json encoding (Freeradius 3.0.13)
Hi All, i am trying to implement cisco Device sensor (http://www.cisco.com/c/en/us/td/docs/switches/lan/catalyst3750/software/rele...) that allow to have endpoint data like DHCP, LLDP in the radius accounting packet. I am able to receive these specific attributes but when i want to send them to my api (PacketFence) through rlm_rest module , it looks that these attributes are not well encoded. You can see in the raddebug trace this attribute Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" received from the cisco switch which is encoded to that "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+" and i am not able to decode it. On my side i did some test with a perl json encoding code and the encoding string is suppose to be \\0007\\000\\r\\001\\017\\003\\006,.\/\\037!y\\371\\374+ Do i miss something in the Freeradius configuration in order to make it work ? Thanks, Regards Fabrice Here my raddebug trace: Tue Nov 22 15:19:40 2016 : Debug: (0) Received Accounting-Request Id 77 from 172.20.135.3:2940 to 172.20.135.1:1813 length 555 Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dc-profile-name=HP-Device" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dc-device-name=MSFT 5.0" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dc-device-class-tag=HP-Device" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dc-certainty-metric=10" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dc-opaque=\000\000\000\002\000\000\000\000\000\000\000" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dc-protocol-map=9" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dhcp-option=\000<\000\010MSFT 5.0" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "dhcp-option=\000\014\000\tinverse-8" Tue Nov 22 15:19:40 2016 : Debug: (0) User-Name = "101f74b2f6a5" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "audit-session-id=AC158904000001485B34CE42" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "vlan-id=138" Tue Nov 22 15:19:40 2016 : Debug: (0) Cisco-AVPair = "method=mab" Tue Nov 22 15:19:40 2016 : Debug: (0) Called-Station-Id = "DC-A5-F4-34-55-08" Tue Nov 22 15:19:40 2016 : Debug: (0) Calling-Station-Id = "10-1F-74-B2-F6-A5" Tue Nov 22 15:19:40 2016 : Debug: (0) NAS-IP-Address = 172.20.135.77 Tue Nov 22 15:19:40 2016 : Debug: (0) NAS-Port-Id = "GigabitEthernet1/0/8" Tue Nov 22 15:19:40 2016 : Debug: (0) NAS-Port-Type = Ethernet Tue Nov 22 15:19:40 2016 : Debug: (0) NAS-Port = 50108 Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Session-Id = "000003B1" Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Terminate-Cause = Lost-Carrier Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Status-Type = Stop Tue Nov 22 15:19:40 2016 : Debug: (0) Event-Timestamp = "nov 22 2016 15:26:16 EST" Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Session-Time = 1133 Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Input-Octets = 97158148 Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Output-Octets = 166844207 Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Input-Packets = 744486 Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Output-Packets = 1682264 Tue Nov 22 15:19:40 2016 : Debug: (0) Acct-Delay-Time = 0 Tue Nov 22 15:19:40 2016 : Debug: (0) Proxy-State = 0x313339 Tue Nov 22 15:19:40 2016 : Debug: (0) # Executing section preacct from file raddb//sites-enabled/packetfence Tue Nov 22 15:19:40 2016 : Debug: (0) preacct { Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: calling preprocess (rlm_preprocess) Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: returned from preprocess (rlm_preprocess) Tue Nov 22 15:19:40 2016 : Debug: (0) [preprocess] = ok Tue Nov 22 15:19:40 2016 : Debug: (0) policy rewrite_called_station_id { Tue Nov 22 15:19:40 2016 : Debug: (0) if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) -> TRUE Tue Nov 22 15:19:40 2016 : Debug: (0) if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) update request { Tue Nov 22 15:19:40 2016 : Debug: (0) &Called-Station-Id !* ANY Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} Tue Nov 22 15:19:40 2016 : Debug: (0) --> dc:a5:f4:34:55:08 Tue Nov 22 15:19:40 2016 : Debug: (0) &Called-Station-Id := dc:a5:f4:34:55:08 Tue Nov 22 15:19:40 2016 : Debug: (0) } # update request = noop Tue Nov 22 15:19:40 2016 : Debug: (0) if ("%{8}") { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{8} Tue Nov 22 15:19:40 2016 : Debug: (0) --> Tue Nov 22 15:19:40 2016 : Debug: (0) if ("%{8}") -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) { Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) elsif (Aruba-Essid-Name) { Tue Nov 22 15:19:40 2016 : Debug: (0) elsif (Aruba-Essid-Name) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{Cisco-AVPair} Tue Nov 22 15:19:40 2016 : Debug: (0) --> dc-profile-name=HP-Device Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: calling updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: returned from updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) [updated] = updated Tue Nov 22 15:19:40 2016 : Debug: (0) } # if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) = updated Tue Nov 22 15:19:40 2016 : Debug: (0) ... skipping else: Preceding "if" was taken Tue Nov 22 15:19:40 2016 : Debug: (0) } # policy rewrite_called_station_id = updated Tue Nov 22 15:19:40 2016 : Debug: (0) policy acct_unique { Tue Nov 22 15:19:40 2016 : Debug: (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{string:Class} Tue Nov 22 15:19:40 2016 : Debug: (0) --> Tue Nov 22 15:19:40 2016 : Debug: (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) else { Tue Nov 22 15:19:40 2016 : Debug: (0) update request { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Tue Nov 22 15:19:40 2016 : Debug: (0) --> ddbfe7a1d200b1fb1576b92057e0bcc6 Tue Nov 22 15:19:40 2016 : Debug: (0) &Acct-Unique-Session-Id := ddbfe7a1d200b1fb1576b92057e0bcc6 Tue Nov 22 15:19:40 2016 : Debug: (0) } # update request = noop Tue Nov 22 15:19:40 2016 : Debug: (0) } # else = noop Tue Nov 22 15:19:40 2016 : Debug: (0) } # policy acct_unique = noop Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: calling suffix (rlm_realm) Tue Nov 22 15:19:40 2016 : Debug: (0) suffix: Checking for suffix after "@" Tue Nov 22 15:19:40 2016 : Debug: (0) suffix: No '@' in User-Name = "101f74b2f6a5", skipping NULL due to config. Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: returned from suffix (rlm_realm) Tue Nov 22 15:19:40 2016 : Debug: (0) [suffix] = noop Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: calling ntdomain (rlm_realm) Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Checking for prefix before "\" Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: No '\' in User-Name = "101f74b2f6a5", looking up realm NULL Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Found realm "null" Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Adding Stripped-User-Name = "101f74b2f6a5" Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Adding Realm = "null" Tue Nov 22 15:19:40 2016 : Debug: (0) ntdomain: Accounting realm is LOCAL Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: returned from ntdomain (rlm_realm) Tue Nov 22 15:19:40 2016 : Debug: (0) [ntdomain] = ok Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: calling files (rlm_files) Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[preacct]: returned from files (rlm_files) Tue Nov 22 15:19:40 2016 : Debug: (0) [files] = noop Tue Nov 22 15:19:40 2016 : Debug: (0) } # preacct = updated Tue Nov 22 15:19:40 2016 : Debug: (0) # Executing section accounting from file raddb//sites-enabled/packetfence Tue Nov 22 15:19:40 2016 : Debug: (0) accounting { Tue Nov 22 15:19:40 2016 : Debug: (0) policy set_calling_station_id { Tue Nov 22 15:19:40 2016 : Debug: (0) if (&User-Name && (&User-Name =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) if (&User-Name && (&User-Name =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) -> TRUE Tue Nov 22 15:19:40 2016 : Debug: (0) if (&User-Name && (&User-Name =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) update request { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} Tue Nov 22 15:19:40 2016 : Debug: (0) --> 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) &User-Name := 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) Overwriting value "101f74b2f6a5" with "10:1f:74:b2:f6:a5" Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} Tue Nov 22 15:19:40 2016 : Debug: (0) --> 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) &Calling-Station-Id = 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) Refusing to overwrite (use :=) Tue Nov 22 15:19:40 2016 : Debug: (0) } # update request = noop Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: calling updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: returned from updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) [updated] = updated Tue Nov 22 15:19:40 2016 : Debug: (0) } # if (&User-Name && (&User-Name =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) = updated Tue Nov 22 15:19:40 2016 : Debug: (0) ... skipping else: Preceding "if" was taken Tue Nov 22 15:19:40 2016 : Debug: (0) } # policy set_calling_station_id = updated Tue Nov 22 15:19:40 2016 : Debug: (0) policy rewrite_calling_station_id { Tue Nov 22 15:19:40 2016 : Debug: (0) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) -> TRUE Tue Nov 22 15:19:40 2016 : Debug: (0) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) update request { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} Tue Nov 22 15:19:40 2016 : Debug: (0) --> 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) &Calling-Station-Id := 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) Overwriting value "10-1F-74-B2-F6-A5" with "10:1f:74:b2:f6:a5" Tue Nov 22 15:19:40 2016 : Debug: (0) } # update request = noop Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: calling updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: returned from updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) [updated] = updated Tue Nov 22 15:19:40 2016 : Debug: (0) } # if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) = updated Tue Nov 22 15:19:40 2016 : Debug: (0) ... skipping else: Preceding "if" was taken Tue Nov 22 15:19:40 2016 : Debug: (0) } # policy rewrite_calling_station_id = updated Tue Nov 22 15:19:40 2016 : Debug: (0) policy rewrite_called_station_id { Tue Nov 22 15:19:40 2016 : Debug: (0) if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) -> TRUE Tue Nov 22 15:19:40 2016 : Debug: (0) if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) { Tue Nov 22 15:19:40 2016 : Debug: (0) update request { Tue Nov 22 15:19:40 2016 : Debug: (0) &Called-Station-Id !* ANY Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{tolower:%{1}:%{2}:%{3}:%{4}:%{5}:%{6}} Tue Nov 22 15:19:40 2016 : Debug: (0) --> dc:a5:f4:34:55:08 Tue Nov 22 15:19:40 2016 : Debug: (0) &Called-Station-Id := dc:a5:f4:34:55:08 Tue Nov 22 15:19:40 2016 : Debug: (0) } # update request = noop Tue Nov 22 15:19:40 2016 : Debug: (0) if ("%{8}") { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{8} Tue Nov 22 15:19:40 2016 : Debug: (0) --> Tue Nov 22 15:19:40 2016 : Debug: (0) if ("%{8}") -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) { Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Colubris-AVPair) && "%{Colubris-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) elsif (Aruba-Essid-Name) { Tue Nov 22 15:19:40 2016 : Debug: (0) elsif (Aruba-Essid-Name) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{Cisco-AVPair} Tue Nov 22 15:19:40 2016 : Debug: (0) --> dc-profile-name=HP-Device Tue Nov 22 15:19:40 2016 : Debug: (0) elsif ( (Cisco-AVPair) && "%{Cisco-AVPair}" =~ /^ssid=(.*)$/i) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: calling updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: returned from updated (rlm_always) Tue Nov 22 15:19:40 2016 : Debug: (0) [updated] = updated Tue Nov 22 15:19:40 2016 : Debug: (0) } # if ((&Called-Station-Id) && (&Called-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})(:(.+))?$/i)) = updated Tue Nov 22 15:19:40 2016 : Debug: (0) ... skipping else: Preceding "if" was taken Tue Nov 22 15:19:40 2016 : Debug: (0) } # policy rewrite_called_station_id = updated Tue Nov 22 15:19:40 2016 : Debug: (0) update { Tue Nov 22 15:19:40 2016 : Debug: (0) EXPAND %{Packet-Src-IP-Address} Tue Nov 22 15:19:40 2016 : Debug: (0) --> 172.20.135.3 Tue Nov 22 15:19:40 2016 : Debug: (0) &request:FreeRADIUS-Client-IP-Address := 172.20.135.3 Tue Nov 22 15:19:40 2016 : Debug: (0) &control:PacketFence-RPC-Server = 127.0.0.1 Tue Nov 22 15:19:40 2016 : Debug: (0) &control:PacketFence-RPC-Port = 7070 Tue Nov 22 15:19:40 2016 : Debug: (0) &control:PacketFence-RPC-User = packet Tue Nov 22 15:19:40 2016 : Debug: (0) &control:PacketFence-RPC-Pass = fence Tue Nov 22 15:19:40 2016 : Debug: (0) &control:PacketFence-RPC-Proto = http Tue Nov 22 15:19:40 2016 : Debug: (0) } # update = noop Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: calling sql (rlm_sql) Tue Nov 22 15:19:40 2016 : Debug: %{tolower:type.%{Acct-Status-Type}.query} Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: xlat --> tolower Tue Nov 22 15:19:40 2016 : Debug: { Tue Nov 22 15:19:40 2016 : Debug: literal --> type. Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Status-Type Tue Nov 22 15:19:40 2016 : Debug: literal --> .query Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: (0) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} Tue Nov 22 15:19:40 2016 : Debug: (0) sql: --> type.stop.query Tue Nov 22 15:19:40 2016 : Debug: (0) sql: Using query template 'query' Tue Nov 22 15:19:40 2016 : Debug: rlm_sql (sql): Reserved connection (1) Tue Nov 22 15:19:40 2016 : Debug: %{User-Name} Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: attribute --> User-Name Tue Nov 22 15:19:40 2016 : Debug: (0) sql: EXPAND %{User-Name} Tue Nov 22 15:19:40 2016 : Debug: (0) sql: --> 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) sql: SQL-User-Name set to '10:1f:74:b2:f6:a5' Tue Nov 22 15:19:40 2016 : Debug: CALL acct_stop ( FROM_UNIXTIME(%{integer:Event-Timestamp}), '%{Framed-IP-Address}', %{%{Acct-Session-Time}:-NULL}, '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Acct-Unique-Session-Id}', '%{Acct-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', '%{Acct-Authentic}', '%{Connect-Info}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Acct-Terminate-Cause}', '%{Acct-Status-Type}') Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: literal --> CALL acct_stop ( FROM_UNIXTIME( Tue Nov 22 15:19:40 2016 : Debug: xlat --> integer Tue Nov 22 15:19:40 2016 : Debug: { Tue Nov 22 15:19:40 2016 : Debug: literal --> Event-Timestamp Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: literal --> ), ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Framed-IP-Address Tue Nov 22 15:19:40 2016 : Debug: literal --> ', Tue Nov 22 15:19:40 2016 : Debug: if { Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Session-Time Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: else { Tue Nov 22 15:19:40 2016 : Debug: literal --> NULL Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: literal --> , ' Tue Nov 22 15:19:40 2016 : Debug: if { Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Input-Gigawords Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: else { Tue Nov 22 15:19:40 2016 : Debug: literal --> 0 Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: literal --> ' << 32 | ' Tue Nov 22 15:19:40 2016 : Debug: if { Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Input-Octets Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: else { Tue Nov 22 15:19:40 2016 : Debug: literal --> 0 Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: if { Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Output-Gigawords Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: else { Tue Nov 22 15:19:40 2016 : Debug: literal --> 0 Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: literal --> ' << 32 | ' Tue Nov 22 15:19:40 2016 : Debug: if { Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Output-Octets Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: else { Tue Nov 22 15:19:40 2016 : Debug: literal --> 0 Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Unique-Session-Id Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Session-Id Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> SQL-User-Name Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Realm Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> NAS-IP-Address Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: if { Tue Nov 22 15:19:40 2016 : Debug: attribute --> NAS-Port-Id Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: else { Tue Nov 22 15:19:40 2016 : Debug: attribute --> NAS-Port Tue Nov 22 15:19:40 2016 : Debug: } Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> NAS-Port-Type Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Authentic Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Connect-Info Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Called-Station-Id Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Calling-Station-Id Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Service-Type Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Framed-Protocol Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Terminate-Cause Tue Nov 22 15:19:40 2016 : Debug: literal --> ', ' Tue Nov 22 15:19:40 2016 : Debug: attribute --> Acct-Status-Type Tue Nov 22 15:19:40 2016 : Debug: literal --> ') Tue Nov 22 15:19:40 2016 : Debug: (0) sql: EXPAND CALL acct_stop ( FROM_UNIXTIME(%{integer:Event-Timestamp}), '%{Framed-IP-Address}', %{%{Acct-Session-Time}:-NULL}, '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Acct-Unique-Session-Id}', '%{Acct-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', '%{Acct-Authentic}', '%{Connect-Info}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Acct-Terminate-Cause}', '%{Acct-Status-Type}') Tue Nov 22 15:19:40 2016 : Debug: (0) sql: --> CALL acct_stop ( FROM_UNIXTIME(1479846376), '', 1133, '0' << 32 | '97158148', '0' << 32 | '166844207', 'ddbfe7a1d200b1fb1576b92057e0bcc6', '000003B1', '10:1f:74:b2:f6:a5', 'null', '172.20.135.77', 'GigabitEthernet1/0/8', 'Ethernet', '', '', 'dc:a5:f4:34:55:08', '10:1f:74:b2:f6:a5', '', '', 'Lost-Carrier', 'Stop') Tue Nov 22 15:19:40 2016 : Debug: (0) sql: Executing query: CALL acct_stop ( FROM_UNIXTIME(1479846376), '', 1133, '0' << 32 | '97158148', '0' << 32 | '166844207', 'ddbfe7a1d200b1fb1576b92057e0bcc6', '000003B1', '10:1f:74:b2:f6:a5', 'null', '172.20.135.77', 'GigabitEthernet1/0/8', 'Ethernet', '', '', 'dc:a5:f4:34:55:08', '10:1f:74:b2:f6:a5', '', '', 'Lost-Carrier', 'Stop') Tue Nov 22 15:19:40 2016 : Debug: (0) sql: SQL query returned: success Tue Nov 22 15:19:40 2016 : Debug: (0) sql: 1 record(s) updated Tue Nov 22 15:19:40 2016 : Debug: rlm_sql (sql): Released connection (1) Tue Nov 22 15:19:40 2016 : Info: rlm_sql (sql): Need 4 more connections to reach 10 spares Tue Nov 22 15:19:40 2016 : Info: rlm_sql (sql): Opening additional connection (6), 1 of 58 pending slots used Tue Nov 22 15:19:40 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Tue Nov 22 15:19:40 2016 : Debug: rlm_sql_mysql: Connected to database 'pf' on 127.0.0.1 via TCP/IP, server version 5.5.50-MariaDB, protocol version 10 Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: returned from sql (rlm_sql) Tue Nov 22 15:19:40 2016 : Debug: (0) [sql] = ok Tue Nov 22 15:19:40 2016 : Debug: (0) if (noop) { Tue Nov 22 15:19:40 2016 : Debug: (0) if (noop) -> FALSE Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Tue Nov 22 15:19:40 2016 : Debug: %{User-Name} Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: attribute --> User-Name Tue Nov 22 15:19:40 2016 : Debug: (0) attr_filter.accounting_response: EXPAND %{User-Name} Tue Nov 22 15:19:40 2016 : Debug: (0) attr_filter.accounting_response: --> 10:1f:74:b2:f6:a5 Tue Nov 22 15:19:40 2016 : Debug: (0) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Tue Nov 22 15:19:40 2016 : Debug: (0) [attr_filter.accounting_response] = updated Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: calling rest (rlm_rest) Tue Nov 22 15:19:40 2016 : Debug: rlm_rest (rest): Reserved connection (0) Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Expanding URI components Tue Nov 22 15:19:40 2016 : Debug: http://127.0.0.1:7070 Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: literal --> http://127.0.0.1:7070 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND http://127.0.0.1:7070 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: --> http://127.0.0.1:7070 Tue Nov 22 15:19:40 2016 : Debug: //radius/rest/accounting Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: literal --> //radius/rest/accounting Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND //radius/rest/accounting Tue Nov 22 15:19:40 2016 : Debug: (0) rest: --> //radius/rest/accounting Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Sending HTTP POST to "http://127.0.0.1:7070//radius/rest/accounting" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Adding custom headers: Tue Nov 22 15:19:40 2016 : Debug: (0) rest: X-FreeRADIUS-Section: accounting Tue Nov 22 15:19:40 2016 : Debug: (0) rest: X-FreeRADIUS-Server: packetfence Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Request body content-type will be "application/json" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "User-Name" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 17 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "10:1f:74:b2:f6:a5" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "NAS-IP-Address" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : ipaddr Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 13 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "172.20.135.77" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "NAS-Port" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 5 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 50108 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Called-Station-Id" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 17 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dc:a5:f4:34:55:08" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Calling-Station-Id" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 17 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "10:1f:74:b2:f6:a5" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Proxy-State" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : octets Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 8 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "0x313339" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "NAS-Port-Type" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 2 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 15 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Status-Type" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 1 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 2 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Delay-Time" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 1 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 0 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Input-Octets" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 8 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 97158148 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Output-Octets" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 9 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 166844207 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Session-Id" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 8 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "000003B1" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Session-Time" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 4 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 1133 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Input-Packets" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 6 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 744486 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Output-Packets" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 7 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 1682264 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Terminate-Cause" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : integer Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 1 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : 2 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Event-Timestamp" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : date Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 24 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "nov 22 2016 15:26:16 EST" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "NAS-Port-Id" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: JSON Data: {"User-Name":{"type":"string","value":["10:1f:74:b2:f6:a5"]},"NAS-IP-Address":{"type":"ipaddr","value":["172.20.135.77"]},"NAS-Port":{"type":"integer","value":[50108]},"Called-Station-Id":{"type":"string","value":["dc:a5:f4:34:55:08"]},"Calling-Station-Id":{"type":"string","value":["10:1f:74:b2:f6:a5"]},"Proxy-State":{"type":"octets","value":["0x313339"]},"NAS-Port-Type":{"type":"integer","value":[15]},"Acct-Status-Type":{"type":"integer","value":[2]},"Acct-Delay-Time":{"type":"integer","value":[0]},"Acct-Input-Octets":{"type":"integer","value":[97158148]},"Acct-Output-Octets":{"type":"integer","value":[166844207]},"Acct-Session-Id":{"type":"string","value":["000003B1"]},"Acct-Session-Time":{"type":"integer","value":[1133]},"Acct-Input-Packets":{"type":"integer","value":[744486]},"Acct-Output-Packets":{"type":"integer","value":[1682264]},"Acct-Terminate-Cause":{"type":"integer","value":[2]},"Event-Timestamp":{"type":"date","value":["nov 22 2016 15:26:16 EST"]},"NAS-Port-Id":{"type":"string","value":[ Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Returning 1015 bytes of JSON data (buffer full or chunk exceeded) Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 22 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "GigabitEthernet1\/0\/8" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Cisco-AVPair" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 25 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dc-profile-name=HP-Device" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 23 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dc-device-name=MSFT 5.0" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 29 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dc-device-class-tag=HP-Device" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 22 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dc-certainty-metric=10" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 82 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dc-opaque=\u0000\u0000\u0000\u0002\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 17 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dc-protocol-map=9" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 84 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 35 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dhcp-option=\u0000<\u0000\bMSFT 5.0" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 37 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "dhcp-option=\u0000\f\u0000\tinverse-8" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 41 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "audit-session-id=AC158904000001485B34CE42" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 11 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "vlan-id=138" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 10 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "method=mab" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Stripped-User-Name" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 12 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "101f74b2f6a5" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Realm" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 4 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "null" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "Acct-Unique-Session-Id" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 32 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "ddbfe7a1d200b1fb1576b92057e0bcc6" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Encoding attribute "FreeRADIUS-Client-IP-Address" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : ipaddr Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 12 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "172.20.135.3" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: JSON Data: "GigabitEthernet1\/0\/8"]},"Cisco-AVPair":{"type":"string","value":["dc-profile-name=HP-Device","dc-device-name=MSFT 5.0","dc-device-class-tag=HP-Device","dc-certainty-metric=10","dc-opaque=\u0000\u0000\u0000\u0002\u0000\u0000\u0000\u0000\u0000\u0000\u0000\u0000","dc-protocol-map=9","dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+","dhcp-option=\u0000<\u0000\bMSFT 5.0","dhcp-option=\u0000\f\u0000\tinverse-8","audit-session-id=AC158904000001485B34CE42","vlan-id=138","method=mab"]},"Stripped-User-Name":{"type":"string","value":["101f74b2f6a5"]},"Realm":{"type":"string","value":["null"]},"Acct-Unique-Session-Id":{"type":"string","value":["ddbfe7a1d200b1fb1576b92057e0bcc6"]},"FreeRADIUS-Client-IP-Address":{"type":"ipaddr","value":["172.20.135.3"]}} Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Returning 791 bytes of JSON data Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Processing response header Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Status : 100 (Continue) Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Continuing... Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Processing response header Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Status : 200 (OK) Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : json (application/json) Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Parsing attribute "Reply-Message" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 13 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "Accounting ok" Tue Nov 22 15:19:40 2016 : Debug: Accounting ok Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: literal --> Accounting ok Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND Accounting ok Tue Nov 22 15:19:40 2016 : Debug: (0) rest: --> Accounting ok Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Reply-Message := "Accounting ok" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Parsing attribute "reply:PacketFence-Authorization-Status" Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Type : string Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Length : 5 Tue Nov 22 15:19:40 2016 : Debug: (0) rest: Value : "allow" Tue Nov 22 15:19:40 2016 : Debug: allow Tue Nov 22 15:19:40 2016 : Debug: Parsed xlat tree: Tue Nov 22 15:19:40 2016 : Debug: literal --> allow Tue Nov 22 15:19:40 2016 : Debug: (0) rest: EXPAND allow Tue Nov 22 15:19:40 2016 : Debug: (0) rest: --> allow Tue Nov 22 15:19:40 2016 : Debug: (0) rest: PacketFence-Authorization-Status := "allow" Tue Nov 22 15:19:40 2016 : Debug: rlm_rest (rest): Released connection (0) Tue Nov 22 15:19:40 2016 : Info: rlm_rest (rest): Need 5 more connections to reach 10 spares Tue Nov 22 15:19:40 2016 : Info: rlm_rest (rest): Opening additional connection (5), 1 of 59 pending slots used Tue Nov 22 15:19:40 2016 : Debug: rlm_rest (rest): Connecting to "http://127.0.0.1:7070/" Tue Nov 22 15:19:40 2016 : Debug: (0) modsingle[accounting]: returned from rest (rlm_rest) Tue Nov 22 15:19:40 2016 : Debug: (0) [rest] = updated Tue Nov 22 15:19:40 2016 : Debug: (0) } # accounting = updated Tue Nov 22 15:19:40 2016 : Debug: (0) Sent Accounting-Response Id 77 from 172.20.135.1:1813 to 172.20.135.3:2940 length 0 Tue Nov 22 15:19:40 2016 : Debug: (0) Reply-Message = "Accounting ok" Tue Nov 22 15:19:40 2016 : Debug: (0) PacketFence-Authorization-Status = "allow" Tue Nov 22 15:19:40 2016 : Debug: (0) Proxy-State = 0x313339 Tue Nov 22 15:19:40 2016 : Debug: (0) Finished request Tue Nov 22 15:19:40 2016 : Debug: (0) Cleaning up request packet ID 77 with timestamp +20 Tue Nov 22 15:19:40 2016 : Info: Ready to process requests -- Fabrice Durand fdurand@inverse.ca :: +1.514.447.4918 (x135) :: www.inverse.ca Inverse inc. :: Leaders behind SOGo (http://www.sogo.nu) and PacketFence (http://packetfence.org)
On Nov 22, 2016, at 3:39 PM, Fabrice Durand <fdurand@inverse.ca> wrote:
i am trying to implement cisco Device sensor (http://www.cisco.com/c/en/us/td/docs/switches/lan/catalyst3750/software/rele...) that allow to have endpoint data like DHCP, LLDP in the radius accounting packet.
I am able to receive these specific attributes but when i want to send them to my api (PacketFence) through rlm_rest module , it looks that these attributes are not well encoded.
The issue is that Cisco is stupid. The Cisco-AVPair attribute is *supposed* to be a printable string. Being a large corporation, Cisco decided to also put binary data in there. Which is a stupid idea.
You can see in the raddebug trace this attribute Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" received from the cisco switch which is encoded to that "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+" and i am not able to decode it.
Hmm... jscon_encode_xlat() in rlm_rest.
On my side i did some test with a perl json encoding code and the encoding string is suppose to be \\0007\\000\\r\\001\\017\\003\\006,.\/\\037!y\\371\\374+
Probably...
Do i miss something in the Freeradius configuration in order to make it work ?
Nope. It should just work. Maybe Arran knows what's up... Alan DeKok.
On Nov 22, 2016, at 3:39 PM, Fabrice Durand <fdurand@inverse.ca> wrote:
i am trying to implement cisco Device sensor (http://www.cisco.com/c/en/us/td/docs/switches/lan/catalyst3750/software/rele...) that allow to have endpoint data like DHCP, LLDP in the radius accounting packet.
I am able to receive these specific attributes but when i want to send them to my api (PacketFence) through rlm_rest module , it looks that these attributes are not well encoded.
You can see in the raddebug trace this attribute Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" received from the cisco switch which is encoded to that "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+"
The json spec says that binary data is \uXXXX where "XXXX" is 4 hex digits. So the above *mostly* looks OK. Except for the FFFFF issue... which is a sign problem. Fixing that should be as simple as making the data unsigned...
and i am not able to decode it.
On my side i did some test with a perl json encoding code and the encoding string is suppose to be \\0007\\000\\r\\001\\017\\003\\006,.\/\\037!y\\371\\374+
Which doesn't follow the json spec. Alan DeKok.
Thanks for the commit Alan, i will make a try and let you know. Regard Fabrice Le 2016-11-22 à 16:27, Alan DeKok a écrit :
On Nov 22, 2016, at 3:39 PM, Fabrice Durand <fdurand@inverse.ca> wrote:
i am trying to implement cisco Device sensor (http://www.cisco.com/c/en/us/td/docs/switches/lan/catalyst3750/software/rele...) that allow to have endpoint data like DHCP, LLDP in the radius accounting packet.
I am able to receive these specific attributes but when i want to send them to my api (PacketFence) through rlm_rest module , it looks that these attributes are not well encoded.
You can see in the raddebug trace this attribute Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" received from the cisco switch which is encoded to that "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+" The json spec says that binary data is \uXXXX where "XXXX" is 4 hex digits. So the above *mostly* looks OK. Except for the FFFFF issue... which is a sign problem.
Fixing that should be as simple as making the data unsigned...
and i am not able to decode it.
On my side i did some test with a perl json encoding code and the encoding string is suppose to be \\0007\\000\\r\\001\\017\\003\\006,.\/\\037!y\\371\\374+ Which doesn't follow the json spec.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Ok so i tested with the patch and it looks to be the same. Wed Nov 23 08:40:39 2016 : Debug: (1) Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" Wed Nov 23 08:40:39 2016 : Debug: (1) rest: Value : "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+" I also noticed in the code that the function vp_prints_value_json is use instead of jsonquote_xlat so i did the following patch: diff --git a/src/lib/print.c b/src/lib/print.c index 5e3a353..0bf128d 100644 --- a/src/lib/print.c +++ b/src/lib/print.c @@ -583,7 +583,7 @@ size_t vp_prints_value_json(char *out, size_t outlen, VALUE_PAIR const *vp) freespace--; break; default: - len = snprintf(out, freespace, "u%04X", *q); + len = snprintf(out, freespace, "u%04X", (uint32_t) *q); if (is_truncated(len, freespace)) return (outlen - freespace) + len; out += len; freespace -= len; diff --git a/src/modules/rlm_rest/rlm_rest.c b/src/modules/rlm_rest/rlm_rest.c index ac00171..7278a58 100644 --- a/src/modules/rlm_rest/rlm_rest.c +++ b/src/modules/rlm_rest/rlm_rest.c @@ -174,7 +174,7 @@ static ssize_t jsonquote_xlat(UNUSED void *instance, UNUSED REQUEST *request, break; case '\n': - *out++ = 'b'; + *out++ = 'n'; freespace--; break; Regards Fabrice Le 2016-11-22 à 16:27, Alan DeKok a écrit :
On Nov 22, 2016, at 3:39 PM, Fabrice Durand <fdurand@inverse.ca> wrote:
i am trying to implement cisco Device sensor (http://www.cisco.com/c/en/us/td/docs/switches/lan/catalyst3750/software/rele...) that allow to have endpoint data like DHCP, LLDP in the radius accounting packet.
I am able to receive these specific attributes but when i want to send them to my api (PacketFence) through rlm_rest module , it looks that these attributes are not well encoded.
You can see in the raddebug trace this attribute Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+" received from the cisco switch which is encoded to that "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+" The json spec says that binary data is \uXXXX where "XXXX" is 4 hex digits. So the above *mostly* looks OK. Except for the FFFFF issue... which is a sign problem.
Fixing that should be as simple as making the data unsigned...
and i am not able to decode it.
On my side i did some test with a perl json encoding code and the encoding string is suppose to be \\0007\\000\\r\\001\\017\\003\\006,.\/\\037!y\\371\\374+ Which doesn't follow the json spec.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Fabrice Durand fdurand@inverse.ca :: +1.514.447.4918 (x135) :: www.inverse.ca Inverse inc. :: Leaders behind SOGo (http://www.sogo.nu) and PacketFence (http://packetfence.org)
On Nov 23, 2016, at 8:56 AM, Fabrice Durand <fdurand@inverse.ca> wrote:
Ok so i tested with the patch and it looks to be the same.
Wed Nov 23 08:40:39 2016 : Debug: (1) Cisco-AVPair = "dhcp-option=\0007\000\r\001\017\003\006,./\037!y\371\374+"
Wed Nov 23 08:40:39 2016 : Debug: (1) rest: Value : "dhcp-option=\u00007\u0000\r\u0001\u000F\u0003\u0006,.\/\u001F!y\uFFFFFFF9\uFFFFFFFC+"
I also noticed in the code that the function vp_prints_value_json is use instead of jsonquote_xlat so i did the following patch:
OK. I've pushed the patches, thanks. Alan DeKok.
participants (3)
-
Alan DeKok -
Durand fabrice -
Fabrice Durand