- Freeradius-Users - lists.freeradius.org

Should I be worried about these error messages?
by Alex Sharaz 23 Nov '16

23 Nov '16

I'm seeing a fair number of error messages of the form Error: Couldn't open /var/cache/freeradius/tlscache/e60f73c400b6462028a381a46f584d59f25f392c59d217981221a60eba9b3345.vps for reading: No such file or directory on our 3.0.12 servers with eap caching enabled.Would you see this if the cache entry has expired or is it something else? Rgds Alex

2 1

json encoding (Freeradius 3.0.13)
by Fabrice Durand 23 Nov '16

23 Nov '16

Hi All, i am trying to implement cisco Device sensor (http://www.cisco.com/c/en/us/td/docs/switches/lan/catalyst3750/software/rel…) 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(a)inverse.ca :: +1.514.447.4918 (x135) :: www.inverse.ca Inverse inc. :: Leaders behind SOGo (http://www.sogo.nu) and PacketFence (http://packetfence.org)

3 5

authentication-failed
by Ejaz 23 Nov '16

23 Nov '16

Hello, Please help As per the attached error it was not bringing the users data, when we cross checked our database with quries.conf which is below. We found on the oracle database table only a "username" as attached where as in queries.conf ""SQL-User-Name" Therefore, if replace in my quries.conf from ""SQL-User-Name" with "User-Name" that should work. I appreciate your Usual support. Here is the query.conf file. queries.conf allocate_begin = "commit" start_begin = "commit" alive_begin = "commit" stop_begin = "commit" on_begin = "commit" off_begin = "commit" allocate_find = "\ SELECT framedipaddress \ FROM ${ippool_table} \ WHERE pool_name = '%{control:Pool-Name}' \ AND expiry_time < current_timestamp \ AND rownum <= 1 \ ORDER BY \ (username <> '%{SQL-User-Name}'), \ (callingstationid <> '%{Calling-Station- Id}'), \ expiry_time \ FOR UPDATE" pool_check = "\ SELECT id \ FROM (\ SELECT id \ FROM ${ippool_table} \ WHERE pool_name='%{control:Pool-Name}'\ ) \ WHERE ROWNUM = 1" allocate_update = "\ UPDATE ${ippool_table} \ SET \ nasipaddress = '%{NAS-IP-Address}', \ pool_key = '${pool_key}', \ callingstationid = '%{Calling-Station-Id}', \ username = '%{SQL-User-Name}', \ expiry_time = current_timestamp + INTERVAL '${lease_duration}' second(1) \ WHERE framedipaddress = '%I'" allocate_clear = "\ UPDATE ${ippool_table} \ SET \ nasipaddress = '', \ pool_key = 0, \ callingstationid = '', \ expiry_time = current_timestamp - INTERVAL '1' second(1) \ WHERE pool_key = '${pool_key}'" start_update = "\ UPDATE ${ippool_table} \ SET \ expiry_time = current_timestamp + INTERVAL '${lease_duration}' second(1) \ WHERE nasipaddress = '%{NAS-IP-Address}' \ AND pool_key = '${pool_key}'" stop_clear = "\ UPDATE ${ippool_table} \ SET \ nasipaddress = '', \ pool_key = 0, \ callingstationid = '', \ expiry_time = current_timestamp - INTERVAL '1' second(1) \ WHERE nasipaddress = '%{Nas-IP-Address}' \ AND pool_key = '${pool_key}' \ AND username = '%{SQL-User-Name}' \ AND callingstationid = '%{Calling-Station-Id}'" alive_update = "\ UPDATE ${ippool_table} \ SET \ expiry_time = current_timestamp + INTERVAL '${lease_duration}' second(1) \ WHERE nasipaddress = '%{Nas-IP-Address}' \ AND pool_key = '${pool_key}' \ AND framedipaddress = '%{Framed-IP-Address}' \ AND username = '%{SQL-User-Name}' \ AND callingstationid = '%{Calling-Station-Id}'" on_clear = "\ UPDATE ${ippool_table} \ SET \ nasipaddress = '', \ pool_key = 0, \ callingstationid = '', \ expiry_time = current_timestamp - INTERVAL '1' second(1) \ WHERE nasipaddress = '%{Nas-IP-Address}'" off_clear = "\ UPDATE ${ippool_table} \ SET \ nasipaddress = '', \ pool_key = 0, \ callingstationid = '', \ expiry_time = current_timestamp - INTERVAL '1' second(1) \ WHERE nasipaddress = '%{Nas-IP-Address}'" Thanks, Mohammed Ejaz Asst. Operation Director of Systems. Cyberia SAUDI ARABIA P.O.Box: 301079, Riyadh 11372 Phone: (+966) 11 464 7114 Ext. 140 Mobile: (+966) 562311787 Fax: (+966) 11 465 4735 Website: http://www.cyberia.net.sa

4 6

EAP-MD5 Deprecation
by David Teston 23 Nov '16

23 Nov '16

Hi All, I've been using the apt repo package of FreeRadius (version 2.x) on Ubuntu 16.04. Recently, I switched to the GitHub repo version 3.1.x. I want to use "radtest -t eap-md5 ..." for testing which is supported in 2.x at /usr/bin/radtest, but 3.1.x uses a different radtest client (/usr/local/bin/radtest) which doesn't have support for eap-md5. Why is eap-md5 not there anymore? Does anyone know how to get this to work, short of copying the file? Additionally, all of my passwords are MD5 hashed. Thanks in advance, David -- David Teston PINES System Administrator dteston(a)georgialibraries.org

7 12

Status of pam_radius_auth
by Michael Weissenbacher 22 Nov '16

22 Nov '16

Dear List! I wanted to ask about the status of the pam_radius_auth Module found at http://freeradius.org/pam_radius_auth/ Does this have it's own mailing list? Bugtracker? It it currently unmaintained? The reason i am asking is because i found a few issues and would like to submit patches and/or find people who are willing to test them. Unfortunately it seems that the module didn't have much activity in recent years. Also, most distros (at least Debian, Ubuntu and Gentoo) still package the old version 1.3.17 and not 1.4.0. And please point me to the right place, in case it's not here :-) thanks, Michael

2 1

Building FR 4.0 on Ubuntu 16.04.1
by Alex Sharaz 21 Nov '16

21 Nov '16

Trying to build FR 4.0 on This flavour of Ubuntu and I get root@prodn2:/usr/local/src/freeradius-server-4.0.x# make scripts/boiler.mk:628: src/modules/rlm_lua/rlm_lua.mk: No such file or directory scripts/boiler.mk:628: src/modules/rlm_lua/libfreeradius-lua.mk: No such file or directory make: *** No rule to make target 'src/modules/rlm_lua/libfreeradius-lua.mk'. Stop. What do I need to install to get a bit further? A

3 6

missing is missing --is-lightweight?
by Peter Lambrechtsen 21 Nov '16

21 Nov '16

Noticed something pretty minor but thought I might point it out. When building on Debian on 3.0.x checking for rusers... /usr/bin/rusers /freeradius/freeradius-server/missing: Unknown `--is-lightweight' option Try `/freeradius/freeradius-server/missing --help' for more information configure: WARNING: 'missing' script is too old or missing checking for locate... /usr/bin/locate In the aclocal.m4 is pointing to the script. # Use eval to expand $SHELL if eval "$MISSING --is-lightweight"; then am_missing_run="$MISSING " else am_missing_run= AC_MSG_WARN(['missing' script is too old or missing]) fi Meh no biggie.. but if anyone was poking around aclocal or missing it might be worth sorting.

2 1

Re: Freeradius-Users Digest, Vol 139, Issue 55
by firing neurons 19 Nov '16

19 Nov '16

I read in mods-available/cache that "The module can cache a fixed set of attributes per key. It can be listed in "authorize", "post-auth", "pre-proxy" and "post-proxy". " This means that I can't update cache inside accounting section and read it back later? Message: 8 Date: Fri, 18 Nov 2016 17:01:42 -0500 From: Arran Cudbard-Bell <a.cudbardb(a)freeradius.org> To: FreeRadius users mailing list <freeradius-users(a)lists.freeradius.org> Subject: Re: Store a attribute in session-state list till the next interim update? Message-ID: <5F646959-9FB0-4F1B-96CF-E9FDB746CD6A(a)freeradius.org> Content-Type: text/plain; charset="utf-8" > On Nov 18, 2016, at 4:35 PM, firing neurons <firingneurons(a)mail.com> wrote: > > Hi, > > I want to store a Tmp-String-0 attribute in session-state list and > retrive it and use it in a conditional in the next interim update. Can > this be done? Yes, with the cache module. -Arran

1 0

LDAP Group Default
by Albert K 19 Nov '16

19 Nov '16

Hi, I have want to the login user to be authorized according to their user grouping in Microsoft AD and also a catch all default. At the moment I am testing with two DEFAULT. Is it possible to do a Catch all DEFAULT. My example below only catch non hod group. Any help would be much appreciated. Thank you. /users DEFAULT Ldap-Group == "cn=hod,cn=users,dc=smartoptz,dc=com" Tunnel-Type = VLAN, Tunnel-Medium-Type = IEEE-802, Tunnel-Private-Group-Id = "30" DEFAULT Ldap-Group != "cn=hod,cn=users,dc=smartoptz,dc=com" Tunnel-Type = VLAN, Tunnel-Medium-Type = IEEE-802, Tunnel-Private-Group-Id = "40"

5 7

How is User-Name getting into reply?
by Brian Candler 19 Nov '16

19 Nov '16

I don't understand how a User-Name attribute is being added into the *reply* when using EAP. To replicate this, I have the default 3.0.12 config with the "steve" user uncommented, and with radtest it behaves as expected: no User-Name in the reply. But if I exercise this account using eapol_test, I see the outer User-Name attribute is in the Access-Accept: (29) Sent Access-Accept Id 10 from 127.0.0.1:1812 to 127.0.0.1:38985 length 0 (29) MS-MPPE-Recv-Key = 0xb581e1ac47471ad3952989c90595a23d8b851827abebc4089ef09574e9d69246 (29) MS-MPPE-Send-Key = 0x244f2954e441937015fa8aa44a36fc94d3c473fbb86ae9498b93f3524b126d37 (29) EAP-Message = 0x030a0004 (29) Message-Authenticator = 0x00000000000000000000000000000000 (29) User-Name = "anonymous" << HERE And if I uncomment these sections from inner-tunnel: update { &outer.session-state: += &reply: } update outer.session-state { MS-MPPE-Encryption-Policy !* ANY MS-MPPE-Encryption-Types !* ANY MS-MPPE-Send-Key !* ANY MS-MPPE-Recv-Key !* ANY Message-Authenticator !* ANY EAP-Message !* ANY Proxy-State !* ANY } then the reply has *two* User-Name attributes: (10) Sent Access-Accept Id 10 from 127.0.0.1:1812 to 127.0.0.1:53750 length 0 (10) MS-MPPE-Recv-Key = 0x0bd13ceb1f41f1cd7acbc81339d64f6a5411d5c507153eacefe6f7b51201956c (10) MS-MPPE-Send-Key = 0x619ca77357791b4b88a270e610dd8716cce3faebd7973dc07b18aa2cb625611a (10) EAP-Message = 0x030a0004 (10) Message-Authenticator = 0x00000000000000000000000000000000 (10) User-Name = "anonymous" << HERE (10) Service-Type += Framed-User (10) Framed-Protocol += PPP (10) Framed-IP-Address += 172.16.3.33 (10) Framed-IP-Netmask += 255.255.255.0 (10) Framed-Routing += Broadcast-Listen (10) Framed-Filter-Id += "std.ppp" (10) Framed-MTU += 1500 (10) Framed-Compression += Van-Jacobson-TCP-IP (10) User-Name += "steve" << HERE Any clues as to what's going on here? RFC2865 (section 5.44) says that an Access-Accept may only contain 0 or 1 User-Name attributes. I could filter them both out, but I'd like to understand how they are getting there in the first place. Thanks, Brian.

2 1