- Freeradius-Users - lists.freeradius.org

Post-Proxy Fail do_not_respond not working
by Peter Lambrechtsen 01 Mar '16

01 Mar '16

I found my last outstanding bug before I deploy my configuration and it's got me stumped. When a Proxy server is down I would like to choose between sending a reject or not sending a response at all. Is there a way that do_not_respond will be honored on 3.0.11 is a post-proxy failure situation? I've tried various ways to have either do_not_respond or update control { &Response-Packet-Type := Do-Not-Respond } But there doesn't seem to be a way to disable the reject and not respond at all when the Proxy fails. Marking home server 222.222.222.1 port 1812 as zombie (it has not responded in 1.000000 seconds). (0) ERROR: Failing proxied request for user "peter", due to lack of any response from home server 222.222.222.1 port 1812 (0) Clearing existing &reply: attributes (0) Found Post-Proxy-Type Fail-Authentication (0) # Executing group from file ./sites-enabled/default (0) Post-Proxy-Type Fail-Authentication { (0) policy do_not_respond { (0) update control { (0) &Response-Packet-Type := Do-Not-Respond (0) } # update control = noop (0) [handled] = handled (0) } # policy do_not_respond = handled (0) } # Post-Proxy-Type Fail-Authentication = handled (0) There was no response configured: rejecting request (0) Using Post-Auth-Type Reject (0) # Executing group from file ./sites-enabled/default (0) Post-Auth-Type REJECT { (0) if (&control:Proxy-To-Realm) { (0) if (&control:Proxy-To-Realm) -> TRUE (0) if (&control:Proxy-To-Realm) { (0) update control { (0) &Response-Packet-Type := Do-Not-Respond (0) } # update control = noop (0) } # if (&control:Proxy-To-Realm) = noop (0) } # Post-Auth-Type REJECT = noop (0) Sent Access-Reject Id 64 from 127.0.0.1:1812 to 127.0.0.1:40320 length 0 (0) Finished request do_not_respond works fine for non-proxied requests, but I can't see how to make it work for proxied requests when the proxy server fails to respond.

2 2

Freeradius + MYSQL, Different NAS device for different user
by Adem Darguner 01 Mar '16

01 Mar '16

Hi Everyone, We are using Freeradius + MYSQL. We are writing NAS information into MYSQL. We are writing radheck information into MYSQL. My question is, Can I make a different NAS device authorization for different users? So, For example, Username "Mike" and we have NAS device Cisco ASA Firewall. Cisco only give approval for user "Mike". But do not allow the user to David. FreeRADIUS + MYSQ do that? Did it support this FreeRadius? How can I do that? Thank you. Regards. -- Adem DARGÜNER Network Engineer

1 0

Force update of TLS cache
by Jonathan Gazeley 01 Mar '16

01 Mar '16

In our EAP-PEAP sessions, the typical conversation length is 10 packets. We have TLS caching enabled, but I noticed the TLS cache is populated during packet 4, which is before processing has started on the tunneled authentication. Is it possible to force an update of the cache entry from the inner-tunnel server e.g. to add attributes that are only available at this stage? I attempted to call an update by doing this in the inner-tunnel server: update control { Cache-TTL := 0 } cache_tls_session This caused authentications to fail with "cache_tls_session (fail)" and no further information is given. Is it possible to do this? Thanks, Jonathan

3 11

Windows PEAP failure in FreeRADIUS 3.1
by Scott Armitage 01 Mar '16

01 Mar '16

Hi, When using FreeRADIUS v3.1 Windows devices fail to authenticate using PEAP. Other OS work fine but Windows fails. If I use a client cert and EAP-TLS windows succeeds. It appears the Windows devices stop responding after the establishment of the PEAP tunnel. Can anyone point out where I am going wrong: Ready to process requests (0) - Received Access-Request Id 248 from 10.53.253.14:32770 to 158.125.161.128:1812 via ens160 length 316 (0) - User-Name = "anon(a)lboro.ac.uk" (0) - Chargeable-User-Identity = 0x00 (0) - Location-Capable = Civix-Location (0) - Calling-Station-Id = "18-cf-5e-12-75-c1" (0) - Called-Station-Id = "b0-aa-77-57-cf-50:wirefree" (0) - NAS-Port = 13 (0) - Cisco-AVPair = "audit-session-id=0a35fd0e000e790756d5a18b" (0) - Acct-Session-Id = "56d5a18b/18:cf:5e:12:75:c1/766789" (0) - NAS-IP-Address = 10.53.253.14 (0) - NAS-IPv6-Address = 2001:630:301:9101::14 (0) - NAS-Identifier = "wism-sport-park-3" (0) - Airespace-Wlan-Id = 3 (0) - Service-Type = Framed-User (0) - Framed-MTU = 1300 (0) - NAS-Port-Type = Wireless-802.11 (0) - Tunnel-Type:0 = VLAN (0) - Tunnel-Medium-Type:0 = IEEE-802 (0) - Tunnel-Private-Group-Id:0 = "1112" (0) - EAP-Message = 0x0202001501616e6f6e406c626f726f2e61632e756b (0) - Message-Authenticator = 0x382df2f62c354bece72daa54ee2d5945 (0) - Running section authorize from file /etc/raddb/sites-enabled/lboro (0) - authorize { (0) - nagios_check { (0) - if (User-Name == "nagios01aa" && "%{client:group}" == "nagios") { (0) - ... (0) - } (0) - } # nagios_check (notfound) (0) - wism_check { (0) - if (User-Name =~ /wism-check/ ) { (0) - ... (0) - } (0) - } # wism_check (notfound) (0) - filter_duff_realms { (0) - if (User-Name =~ /\\.ax\\.uk$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /\\.sc\\.uk$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /\\.ac\\.u$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /lboro$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /lboro\\.co\\.uk$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /ac\\.lboro\\.uk$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /unilboro\\.ac\\.uk$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /\\.a\\.c\\.uk$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /3gppnetwork\\.org$/i) { (0) - ... (0) - } (0) - elsif (User-Name =~ /myabc\\.com$/i) { (0) - ... (0) - } (0) - elsif (User-Name !~ /lboro\\.local$/i && User-Name =~ /\\.local$/i) { (0) - ... (0) - } (0) - elsif (User-Name =~ /lbro\\.ac\\.uk$/i ) { (0) - ... (0) - } (0) - elsif (User-Name =~ /lboro\\.student\\.ac\\.uk$/i ) { (0) - ... (0) - } (0) - } # filter_duff_realms (notfound) (0) - filter_username { (0) - if (!&User-Name) { (0) - ... (0) - } (0) - if (&User-Name =~ / /) { (0) - ... (0) - } (0) - if (&User-Name =~ /@.*@/ ) { (0) - ... (0) - } (0) - if (&User-Name =~ /\.\./ ) { (0) - ... (0) - } (0) - if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (0) - ... (0) - } (0) - if (&User-Name =~ /\.$/) { (0) - ... (0) - } (0) - if (&User-Name =~ /(a)\./) { (0) - ... (0) - } (0) - } # filter_username (notfound) (0) preprocess (ok) (0) operator-name.authorize { (0) if ("%{client:Operator-Name}") { (0) EXPAND %{client:Operator-Name} (0) --> (0) ... (0) } (0) } # operator-name.authorize (ok) (0) cui.authorize { (0) if ("%{client:add_cui}" == 'yes') { (0) EXPAND %{client:add_cui} (0) --> yes (0) update request { (0) &Chargeable-User-Identity := 0x00 (0) } # update request (noop) (0) } # if ("%{client:add_cui}" == 'yes') (noop) (0) } # cui.authorize (noop) (0) suffix - Checking for suffix after "@" (0) suffix - Looking up realm "lboro.ac.uk" for User-Name = "anon(a)lboro.ac.uk" (0) suffix - Found realm "lboro.ac.uk" (0) suffix - Adding Stripped-User-Name = "anon" (0) suffix - Adding Realm = "lboro.ac.uk" (0) suffix - Authentication realm is LOCAL (0) suffix (ok) (0) ntdomain - Request already has destination realm set. Ignoring (0) ntdomain (noop) (0) if ( Called-Station-Id =~ /:eduroam$/ ) { (0) ... (0) } (0) elsif ( Called-Station-Id =~ /.*:YST$/ ) { (0) ... (0) } (0) elsif ( Called-Station-Id =~ /.*:ecb$/ || "%{client:group}" == "ecb" ) { (0) EXPAND %{client:group} (0) --> wireless (0) ... (0) } (0) if ((User-Name =~ /youthsporttrust\\.org$/) || (User-Name =~ /^YOUTHSPORTTRUST\\\\/)) { (0) ... (0) } (0) elsif (User-Name =~ /\(a)ecb\.co\.uk/i && "%{client:shortname}" == "dulcimer" ) { (0) ... (0) } (0) elsif ( Realm == "ECB" || Realm == "ecb.co.uk" ) { (0) ... (0) } (0) elsif (Service-Type == Call-Check && !EAP-Message && User-Name =~ /[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]/) { (0) ... (0) } (0) elsif ( Realm == "lsu.co.uk" ) { (0) ... (0) } (0) elsif (User-Name =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) { (0) ... (0) } (0) else { (0) update request { (0) &Realm := local (0) } # update request (noop) (0) } # else (noop) (0) eap - Peer sent EAP Response (code 2) ID 2 length 21 (0) eap - Peer sent EAP-Identity. Returning 'ok' so we can short-circuit the rest of authorize (0) eap (ok) (0) } # authorize (ok) (0) Using 'Auth-Type = eap' for authenticate {...} (0) Running Auth-Type eap from file /etc/raddb/sites-enabled/lboro (0) authenticate { (0) eap - Peer sent packet with EAP method Identity (1) (0) eap - Calling submodule eap_tls to process data (0) eap_tls - Initiating new EAP-TLS session (0) eap_tls - Setting verify mode to require certificate from client (0) eap - Sending EAP Request (code 1) ID 3 length 6 (0) eap (handled) (0) } # authenticate (handled) (0) Using Post-Auth-Type Challenge (0) Post-Auth-Type sub-section not found. Ignoring. (0) Running Post-Auth-Type Challenge from file /etc/raddb/sites-enabled/lboro (0) Sent Access-Challenge Id 248 from 158.125.161.128:1812 to 10.53.253.14:32770 via ens160 length 0 (0) EAP-Message = 0x010300060d20 (0) Message-Authenticator = 0x00000000000000000000000000000000 (0) State = 0x01015100148ca6ec523c504e518c74e2 (0) Finished request Waking up in 1.9 seconds. (1) - Received Access-Request Id 249 from 10.53.253.14:32770 to 158.125.161.128:1812 via ens160 length 319 (1) - User-Name = "anon(a)lboro.ac.uk" (1) - Chargeable-User-Identity = 0x00 (1) - Location-Capable = Civix-Location (1) - Calling-Station-Id = "18-cf-5e-12-75-c1" (1) - Called-Station-Id = "b0-aa-77-57-cf-50:wirefree" (1) - NAS-Port = 13 (1) - Cisco-AVPair = "audit-session-id=0a35fd0e000e790756d5a18b" (1) - Acct-Session-Id = "56d5a18b/18:cf:5e:12:75:c1/766789" (1) - NAS-IP-Address = 10.53.253.14 (1) - NAS-IPv6-Address = 2001:630:301:9101::14 (1) - NAS-Identifier = "wism-sport-park-3" (1) - Airespace-Wlan-Id = 3 (1) - Service-Type = Framed-User (1) - Framed-MTU = 1300 (1) - NAS-Port-Type = Wireless-802.11 (1) - Tunnel-Type:0 = VLAN (1) - Tunnel-Medium-Type:0 = IEEE-802 (1) - Tunnel-Private-Group-Id:0 = "1112" (1) - EAP-Message = 0x020300060319 (1) - State = 0x01015100148ca6ec523c504e518c74e2 (1) - Message-Authenticator = 0x87079937708aa02274b90e7892aa4815 (1) - Running section authorize from file /etc/raddb/sites-enabled/lboro (1) - authorize { (1) - nagios_check { (1) - if (User-Name == "nagios01aa" && "%{client:group}" == "nagios") { (1) - ... (1) - } (1) - } # nagios_check (notfound) (1) - wism_check { (1) - if (User-Name =~ /wism-check/ ) { (1) - ... (1) - } (1) - } # wism_check (notfound) (1) - filter_duff_realms { (1) - if (User-Name =~ /\\.ax\\.uk$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /\\.sc\\.uk$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /\\.ac\\.u$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /lboro$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /lboro\\.co\\.uk$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /ac\\.lboro\\.uk$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /unilboro\\.ac\\.uk$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /\\.a\\.c\\.uk$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /3gppnetwork\\.org$/i) { (1) - ... (1) - } (1) - elsif (User-Name =~ /myabc\\.com$/i) { (1) - ... (1) - } (1) - elsif (User-Name !~ /lboro\\.local$/i && User-Name =~ /\\.local$/i) { (1) - ... (1) - } (1) - elsif (User-Name =~ /lbro\\.ac\\.uk$/i ) { (1) - ... (1) - } (1) - elsif (User-Name =~ /lboro\\.student\\.ac\\.uk$/i ) { (1) - ... (1) - } (1) - } # filter_duff_realms (notfound) (1) - filter_username { (1) - if (!&User-Name) { (1) - ... (1) - } (1) - if (&User-Name =~ / /) { (1) - ... (1) - } (1) - if (&User-Name =~ /@.*@/ ) { (1) - ... (1) - } (1) - if (&User-Name =~ /\.\./ ) { (1) - ... (1) - } (1) - if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (1) - ... (1) - } (1) - if (&User-Name =~ /\.$/) { (1) - ... (1) - } (1) - if (&User-Name =~ /(a)\./) { (1) - ... (1) - } (1) - } # filter_username (notfound) (1) preprocess (ok) (1) operator-name.authorize { (1) if ("%{client:Operator-Name}") { (1) EXPAND %{client:Operator-Name} (1) --> (1) ... (1) } (1) } # operator-name.authorize (ok) (1) cui.authorize { (1) if ("%{client:add_cui}" == 'yes') { (1) EXPAND %{client:add_cui} (1) --> yes (1) update request { (1) &Chargeable-User-Identity := 0x00 (1) } # update request (noop) (1) } # if ("%{client:add_cui}" == 'yes') (noop) (1) } # cui.authorize (noop) (1) suffix - Checking for suffix after "@" (1) suffix - Looking up realm "lboro.ac.uk" for User-Name = "anon(a)lboro.ac.uk" (1) suffix - Found realm "lboro.ac.uk" (1) suffix - Adding Stripped-User-Name = "anon" (1) suffix - Adding Realm = "lboro.ac.uk" (1) suffix - Authentication realm is LOCAL (1) suffix (ok) (1) ntdomain - Request already has destination realm set. Ignoring (1) ntdomain (noop) (1) if ( Called-Station-Id =~ /:eduroam$/ ) { (1) ... (1) } (1) elsif ( Called-Station-Id =~ /.*:YST$/ ) { (1) ... (1) } (1) elsif ( Called-Station-Id =~ /.*:ecb$/ || "%{client:group}" == "ecb" ) { (1) EXPAND %{client:group} (1) --> wireless (1) ... (1) } (1) if ((User-Name =~ /youthsporttrust\\.org$/) || (User-Name =~ /^YOUTHSPORTTRUST\\\\/)) { (1) ... (1) } (1) elsif (User-Name =~ /\(a)ecb\.co\.uk/i && "%{client:shortname}" == "dulcimer" ) { (1) ... (1) } (1) elsif ( Realm == "ECB" || Realm == "ecb.co.uk" ) { (1) ... (1) } (1) elsif (Service-Type == Call-Check && !EAP-Message && User-Name =~ /[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]/) { (1) ... (1) } (1) elsif ( Realm == "lsu.co.uk" ) { (1) ... (1) } (1) elsif (User-Name =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) { (1) ... (1) } (1) else { (1) update request { (1) &Realm := local (1) } # update request (noop) (1) } # else (noop) (1) eap - Peer sent EAP Response (code 2) ID 3 length 6 (1) eap - Continuing on-going EAP conversation (1) eap (updated) (1) if (Realm != "SportPark") { (1) files (noop) (1) } # if (Realm != "SportPark") (noop) (1) } # authorize (updated) (1) Using 'Auth-Type = eap' for authenticate {...} (1) Running Auth-Type eap from file /etc/raddb/sites-enabled/lboro (1) authenticate { (1) eap - Peer sent packet with EAP method NAK (3) (1) eap - Found mutually acceptable type PEAP (25) (1) eap - Calling submodule eap_peap to process data (1) eap_peap - Initiating new EAP-TLS session (1) eap - Sending EAP Request (code 1) ID 4 length 6 (1) eap (handled) (1) } # authenticate (handled) (1) Using Post-Auth-Type Challenge (1) Post-Auth-Type sub-section not found. Ignoring. (1) Running Post-Auth-Type Challenge from file /etc/raddb/sites-enabled/lboro (1) Sent Access-Challenge Id 249 from 158.125.161.128:1812 to 10.53.253.14:32770 via ens160 length 0 (1) EAP-Message = 0x010400061920 (1) Message-Authenticator = 0x00000000000000000000000000000000 (1) State = 0x020351002306bedc523c504e518c74e2 (1) Finished request Waking up in 1.9 seconds. (2) - Received Access-Request Id 250 from 10.53.253.14:32770 to 158.125.161.128:1812 via ens160 length 491 (2) - User-Name = "anon(a)lboro.ac.uk" (2) - Chargeable-User-Identity = 0x00 (2) - Location-Capable = Civix-Location (2) - Calling-Station-Id = "18-cf-5e-12-75-c1" (2) - Called-Station-Id = "b0-aa-77-57-cf-50:wirefree" (2) - NAS-Port = 13 (2) - Cisco-AVPair = "audit-session-id=0a35fd0e000e790756d5a18b" (2) - Acct-Session-Id = "56d5a18b/18:cf:5e:12:75:c1/766789" (2) - NAS-IP-Address = 10.53.253.14 (2) - NAS-IPv6-Address = 2001:630:301:9101::14 (2) - NAS-Identifier = "wism-sport-park-3" (2) - Airespace-Wlan-Id = 3 (2) - Service-Type = Framed-User (2) - Framed-MTU = 1300 (2) - NAS-Port-Type = Wireless-802.11 (2) - Tunnel-Type:0 = VLAN (2) - Tunnel-Medium-Type:0 = IEEE-802 (2) - Tunnel-Private-Group-Id:0 = "1112" (2) - EAP-Message = 0x020400b21980000000a816030300a30100009f030356d5a1d0b73b3ce7f8e814cc7bd174c70898c308769ae5cbf3b0a4fbd0895733000038c02cc02bc030c02f009f009ec024c023c028c027c00ac009c014c013009d009c003d003c0035002f000a006a0040003800320013000500040100003e000500 (2) - State = 0x020351002306bedc523c504e518c74e2 (2) - Message-Authenticator = 0x25df502901ee50b3554970e162bd935e (2) - Running section authorize from file /etc/raddb/sites-enabled/lboro (2) - authorize { (2) - nagios_check { (2) - if (User-Name == "nagios01aa" && "%{client:group}" == "nagios") { (2) - ... (2) - } (2) - } # nagios_check (notfound) (2) - wism_check { (2) - if (User-Name =~ /wism-check/ ) { (2) - ... (2) - } (2) - } # wism_check (notfound) (2) - filter_duff_realms { (2) - if (User-Name =~ /\\.ax\\.uk$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /\\.sc\\.uk$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /\\.ac\\.u$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /lboro$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /lboro\\.co\\.uk$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /ac\\.lboro\\.uk$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /unilboro\\.ac\\.uk$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /\\.a\\.c\\.uk$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /3gppnetwork\\.org$/i) { (2) - ... (2) - } (2) - elsif (User-Name =~ /myabc\\.com$/i) { (2) - ... (2) - } (2) - elsif (User-Name !~ /lboro\\.local$/i && User-Name =~ /\\.local$/i) { (2) - ... (2) - } (2) - elsif (User-Name =~ /lbro\\.ac\\.uk$/i ) { (2) - ... (2) - } (2) - elsif (User-Name =~ /lboro\\.student\\.ac\\.uk$/i ) { (2) - ... (2) - } (2) - } # filter_duff_realms (notfound) (2) - filter_username { (2) - if (!&User-Name) { (2) - ... (2) - } (2) - if (&User-Name =~ / /) { (2) - ... (2) - } (2) - if (&User-Name =~ /@.*@/ ) { (2) - ... (2) - } (2) - if (&User-Name =~ /\.\./ ) { (2) - ... (2) - } (2) - if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (2) - ... (2) - } (2) - if (&User-Name =~ /\.$/) { (2) - ... (2) - } (2) - if (&User-Name =~ /(a)\./) { (2) - ... (2) - } (2) - } # filter_username (notfound) (2) preprocess (ok) (2) operator-name.authorize { (2) if ("%{client:Operator-Name}") { (2) EXPAND %{client:Operator-Name} (2) --> (2) ... (2) } (2) } # operator-name.authorize (ok) (2) cui.authorize { (2) if ("%{client:add_cui}" == 'yes') { (2) EXPAND %{client:add_cui} (2) --> yes (2) update request { (2) &Chargeable-User-Identity := 0x00 (2) } # update request (noop) (2) } # if ("%{client:add_cui}" == 'yes') (noop) (2) } # cui.authorize (noop) (2) suffix - Checking for suffix after "@" (2) suffix - Looking up realm "lboro.ac.uk" for User-Name = "anon(a)lboro.ac.uk" (2) suffix - Found realm "lboro.ac.uk" (2) suffix - Adding Stripped-User-Name = "anon" (2) suffix - Adding Realm = "lboro.ac.uk" (2) suffix - Authentication realm is LOCAL (2) suffix (ok) (2) ntdomain - Request already has destination realm set. Ignoring (2) ntdomain (noop) (2) if ( Called-Station-Id =~ /:eduroam$/ ) { (2) ... (2) } (2) elsif ( Called-Station-Id =~ /.*:YST$/ ) { (2) ... (2) } (2) elsif ( Called-Station-Id =~ /.*:ecb$/ || "%{client:group}" == "ecb" ) { (2) EXPAND %{client:group} (2) --> wireless (2) ... (2) } (2) if ((User-Name =~ /youthsporttrust\\.org$/) || (User-Name =~ /^YOUTHSPORTTRUST\\\\/)) { (2) ... (2) } (2) elsif (User-Name =~ /\(a)ecb\.co\.uk/i && "%{client:shortname}" == "dulcimer" ) { (2) ... (2) } (2) elsif ( Realm == "ECB" || Realm == "ecb.co.uk" ) { (2) ... (2) } (2) elsif (Service-Type == Call-Check && !EAP-Message && User-Name =~ /[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]/) { (2) ... (2) } (2) elsif ( Realm == "lsu.co.uk" ) { (2) ... (2) } (2) elsif (User-Name =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) { (2) ... (2) } (2) else { (2) update request { (2) &Realm := local (2) } # update request (noop) (2) } # else (noop) (2) eap - Peer sent EAP Response (code 2) ID 4 length 178 (2) eap - Continuing tunnel setup (2) eap (ok) (2) } # authorize (ok) (2) Using 'Auth-Type = eap' for authenticate {...} (2) Running Auth-Type eap from file /etc/raddb/sites-enabled/lboro (2) authenticate { (2) eap - Peer sent packet with EAP method PEAP (25) (2) eap - Calling submodule eap_peap to process data (2) eap_peap - Continuing EAP-TLS (2) eap_peap - Peer indicated complete TLS record size will be 168 bytes (2) eap_peap - Got complete TLS record, with length field (168 bytes) (2) eap_peap - [eap-tls verify] = ok (2) eap_peap - before/accept initialization (2) eap_peap - TLS Accept: before/accept initialization (2) eap_peap - <<< recv handshake [length 163], client_hello (2) eap_peap - TLS Accept: SSLv3 read client hello A (2) eap_peap - >>> send handshake [length 89], server_hello (2) eap_peap - TLS Accept: SSLv3 write server hello A (2) eap_peap - >>> send handshake [length 2457], certificate (2) eap_peap - TLS Accept: SSLv3 write certificate A (2) eap_peap - >>> send handshake [length 331], server_key_exchange (2) eap_peap - TLS Accept: SSLv3 write key exchange A (2) eap_peap - >>> send handshake [length 4], server_hello_done (2) eap_peap - TLS Accept: SSLv3 write server done A (2) eap_peap - TLS Accept: SSLv3 flush data (2) eap_peap - TLS Accept: Need to read more data: SSLv3 read client certificate A (2) eap_peap - TLS Accept: Need to read more data: SSLv3 read client certificate A (2) eap_peap - In TLS handshake phase (2) eap_peap - In TLS accept mode (2) eap_peap - Complete TLS record (2901 bytes) larger than MTU (990 bytes), will fragment (2) eap_peap - Sending first TLS record fragment (990 bytes), 1911 bytes remaining (2) eap_peap - [eap-tls process] = handled (2) eap - Sending EAP Request (code 1) ID 5 length 1000 (2) eap (handled) (2) } # authenticate (handled) (2) Using Post-Auth-Type Challenge (2) Post-Auth-Type sub-section not found. Ignoring. (2) Running Post-Auth-Type Challenge from file /etc/raddb/sites-enabled/lboro (2) Sent Access-Challenge Id 250 from 158.125.161.128:1812 to 10.53.253.14:32770 via ens160 length 0 (2) EAP-Message = 0x010503e819c000000b55160302005902000055030256d5a18b0261059d716b941222cf3855ea00c34b5e728dc7be087afa7d75606d2076d5549bfc2e548e73d1176bbe9daa36dc0d0a1d16dc467e8a51b4989a04fd65c01400000dff01000100000b00040300010216030209990b000995000992000427 (2) Message-Authenticator = 0x00000000000000000000000000000000 (2) State = 0x03015100148ca6ec523c504e518c74e2 (2) Finished request Waking up in 1.9 seconds. (3) - Received Access-Request Id 251 from 10.53.253.14:32770 to 158.125.161.128:1812 via ens160 length 319 (3) - User-Name = "anon(a)lboro.ac.uk" (3) - Chargeable-User-Identity = 0x00 (3) - Location-Capable = Civix-Location (3) - Calling-Station-Id = "18-cf-5e-12-75-c1" (3) - Called-Station-Id = "b0-aa-77-57-cf-50:wirefree" (3) - NAS-Port = 13 (3) - Cisco-AVPair = "audit-session-id=0a35fd0e000e790756d5a18b" (3) - Acct-Session-Id = "56d5a18b/18:cf:5e:12:75:c1/766789" (3) - NAS-IP-Address = 10.53.253.14 (3) - NAS-IPv6-Address = 2001:630:301:9101::14 (3) - NAS-Identifier = "wism-sport-park-3" (3) - Airespace-Wlan-Id = 3 (3) - Service-Type = Framed-User (3) - Framed-MTU = 1300 (3) - NAS-Port-Type = Wireless-802.11 (3) - Tunnel-Type:0 = VLAN (3) - Tunnel-Medium-Type:0 = IEEE-802 (3) - Tunnel-Private-Group-Id:0 = "1112" (3) - EAP-Message = 0x020500061900 (3) - State = 0x03015100148ca6ec523c504e518c74e2 (3) - Message-Authenticator = 0xc2308e039d2d27171a1a80d5fa914f3e (3) - Running section authorize from file /etc/raddb/sites-enabled/lboro (3) - authorize { (3) - nagios_check { (3) - if (User-Name == "nagios01aa" && "%{client:group}" == "nagios") { (3) - ... (3) - } (3) - } # nagios_check (notfound) (3) - wism_check { (3) - if (User-Name =~ /wism-check/ ) { (3) - ... (3) - } (3) - } # wism_check (notfound) (3) - filter_duff_realms { (3) - if (User-Name =~ /\\.ax\\.uk$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /\\.sc\\.uk$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /\\.ac\\.u$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /lboro$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /lboro\\.co\\.uk$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /ac\\.lboro\\.uk$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /unilboro\\.ac\\.uk$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /\\.a\\.c\\.uk$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /3gppnetwork\\.org$/i) { (3) - ... (3) - } (3) - elsif (User-Name =~ /myabc\\.com$/i) { (3) - ... (3) - } (3) - elsif (User-Name !~ /lboro\\.local$/i && User-Name =~ /\\.local$/i) { (3) - ... (3) - } (3) - elsif (User-Name =~ /lbro\\.ac\\.uk$/i ) { (3) - ... (3) - } (3) - elsif (User-Name =~ /lboro\\.student\\.ac\\.uk$/i ) { (3) - ... (3) - } (3) - } # filter_duff_realms (notfound) (3) - filter_username { (3) - if (!&User-Name) { (3) - ... (3) - } (3) - if (&User-Name =~ / /) { (3) - ... (3) - } (3) - if (&User-Name =~ /@.*@/ ) { (3) - ... (3) - } (3) - if (&User-Name =~ /\.\./ ) { (3) - ... (3) - } (3) - if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (3) - ... (3) - } (3) - if (&User-Name =~ /\.$/) { (3) - ... (3) - } (3) - if (&User-Name =~ /(a)\./) { (3) - ... (3) - } (3) - } # filter_username (notfound) (3) preprocess (ok) (3) operator-name.authorize { (3) if ("%{client:Operator-Name}") { (3) EXPAND %{client:Operator-Name} (3) --> (3) ... (3) } (3) } # operator-name.authorize (ok) (3) cui.authorize { (3) if ("%{client:add_cui}" == 'yes') { (3) EXPAND %{client:add_cui} (3) --> yes (3) update request { (3) &Chargeable-User-Identity := 0x00 (3) } # update request (noop) (3) } # if ("%{client:add_cui}" == 'yes') (noop) (3) } # cui.authorize (noop) (3) suffix - Checking for suffix after "@" (3) suffix - Looking up realm "lboro.ac.uk" for User-Name = "anon(a)lboro.ac.uk" (3) suffix - Found realm "lboro.ac.uk" (3) suffix - Adding Stripped-User-Name = "anon" (3) suffix - Adding Realm = "lboro.ac.uk" (3) suffix - Authentication realm is LOCAL (3) suffix (ok) (3) ntdomain - Request already has destination realm set. Ignoring (3) ntdomain (noop) (3) if ( Called-Station-Id =~ /:eduroam$/ ) { (3) ... (3) } (3) elsif ( Called-Station-Id =~ /.*:YST$/ ) { (3) ... (3) } (3) elsif ( Called-Station-Id =~ /.*:ecb$/ || "%{client:group}" == "ecb" ) { (3) EXPAND %{client:group} (3) --> wireless (3) ... (3) } (3) if ((User-Name =~ /youthsporttrust\\.org$/) || (User-Name =~ /^YOUTHSPORTTRUST\\\\/)) { (3) ... (3) } (3) elsif (User-Name =~ /\(a)ecb\.co\.uk/i && "%{client:shortname}" == "dulcimer" ) { (3) ... (3) } (3) elsif ( Realm == "ECB" || Realm == "ecb.co.uk" ) { (3) ... (3) } (3) elsif (Service-Type == Call-Check && !EAP-Message && User-Name =~ /[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]/) { (3) ... (3) } (3) elsif ( Realm == "lsu.co.uk" ) { (3) ... (3) } (3) elsif (User-Name =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) { (3) ... (3) } (3) else { (3) update request { (3) &Realm := local (3) } # update request (noop) (3) } # else (noop) (3) eap - Peer sent EAP Response (code 2) ID 5 length 6 (3) eap - Continuing tunnel setup (3) eap (ok) (3) } # authorize (ok) (3) Using 'Auth-Type = eap' for authenticate {...} (3) Running Auth-Type eap from file /etc/raddb/sites-enabled/lboro (3) authenticate { (3) eap - Peer sent packet with EAP method PEAP (25) (3) eap - Calling submodule eap_peap to process data (3) eap_peap - Continuing EAP-TLS (3) eap_peap - Peer ACKed our handshake fragment (3) eap_peap - [eap-tls verify] = request (3) eap_peap - Sending additional TLS record fragment (994 bytes), 917 bytes remaining (3) eap_peap - [eap-tls process] = handled (3) eap - Sending EAP Request (code 1) ID 6 length 1000 (3) eap (handled) (3) } # authenticate (handled) (3) Using Post-Auth-Type Challenge (3) Post-Auth-Type sub-section not found. Ignoring. (3) Running Post-Auth-Type Challenge from file /etc/raddb/sites-enabled/lboro (3) Sent Access-Challenge Id 251 from 158.125.161.128:1812 to 10.53.253.14:32770 via ens160 length 0 (3) EAP-Message = 0x010603e81940c11f90d2b74ee65a1109bc0009cc59bb16b11c4d981df09929ef3b97d4d9c5040db5321c087b14c214be61a7ff6eb953828ff106bb4180f20d7ba5a7781ef72b286dbe7d9b98dd2c43a67d4e87108d1d22a3253b103f2b5daf5115457e670fcc117461e793aef0eb01f72340aa8042b007 (3) Message-Authenticator = 0x00000000000000000000000000000000 (3) State = 0x040751002306bedc523c504e518c74e2 (3) Finished request Waking up in 1.9 seconds. (4) - Received Access-Request Id 252 from 10.53.253.14:32770 to 158.125.161.128:1812 via ens160 length 319 (4) - User-Name = "anon(a)lboro.ac.uk" (4) - Chargeable-User-Identity = 0x00 (4) - Location-Capable = Civix-Location (4) - Calling-Station-Id = "18-cf-5e-12-75-c1" (4) - Called-Station-Id = "b0-aa-77-57-cf-50:wirefree" (4) - NAS-Port = 13 (4) - Cisco-AVPair = "audit-session-id=0a35fd0e000e790756d5a18b" (4) - Acct-Session-Id = "56d5a18b/18:cf:5e:12:75:c1/766789" (4) - NAS-IP-Address = 10.53.253.14 (4) - NAS-IPv6-Address = 2001:630:301:9101::14 (4) - NAS-Identifier = "wism-sport-park-3" (4) - Airespace-Wlan-Id = 3 (4) - Service-Type = Framed-User (4) - Framed-MTU = 1300 (4) - NAS-Port-Type = Wireless-802.11 (4) - Tunnel-Type:0 = VLAN (4) - Tunnel-Medium-Type:0 = IEEE-802 (4) - Tunnel-Private-Group-Id:0 = "1112" (4) - EAP-Message = 0x020600061900 (4) - State = 0x040751002306bedc523c504e518c74e2 (4) - Message-Authenticator = 0x9e01e0203a757d408a33b0e6da2d6371 (4) - Running section authorize from file /etc/raddb/sites-enabled/lboro (4) - authorize { (4) - nagios_check { (4) - if (User-Name == "nagios01aa" && "%{client:group}" == "nagios") { (4) - ... (4) - } (4) - } # nagios_check (notfound) (4) - wism_check { (4) - if (User-Name =~ /wism-check/ ) { (4) - ... (4) - } (4) - } # wism_check (notfound) (4) - filter_duff_realms { (4) - if (User-Name =~ /\\.ax\\.uk$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /\\.sc\\.uk$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /\\.ac\\.u$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /lboro$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /lboro\\.co\\.uk$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /ac\\.lboro\\.uk$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /unilboro\\.ac\\.uk$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /\\.a\\.c\\.uk$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /3gppnetwork\\.org$/i) { (4) - ... (4) - } (4) - elsif (User-Name =~ /myabc\\.com$/i) { (4) - ... (4) - } (4) - elsif (User-Name !~ /lboro\\.local$/i && User-Name =~ /\\.local$/i) { (4) - ... (4) - } (4) - elsif (User-Name =~ /lbro\\.ac\\.uk$/i ) { (4) - ... (4) - } (4) - elsif (User-Name =~ /lboro\\.student\\.ac\\.uk$/i ) { (4) - ... (4) - } (4) - } # filter_duff_realms (notfound) (4) - filter_username { (4) - if (!&User-Name) { (4) - ... (4) - } (4) - if (&User-Name =~ / /) { (4) - ... (4) - } (4) - if (&User-Name =~ /@.*@/ ) { (4) - ... (4) - } (4) - if (&User-Name =~ /\.\./ ) { (4) - ... (4) - } (4) - if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (4) - ... (4) - } (4) - if (&User-Name =~ /\.$/) { (4) - ... (4) - } (4) - if (&User-Name =~ /(a)\./) { (4) - ... (4) - } (4) - } # filter_username (notfound) (4) preprocess (ok) (4) operator-name.authorize { (4) if ("%{client:Operator-Name}") { (4) EXPAND %{client:Operator-Name} (4) --> (4) ... (4) } (4) } # operator-name.authorize (ok) (4) cui.authorize { (4) if ("%{client:add_cui}" == 'yes') { (4) EXPAND %{client:add_cui} (4) --> yes (4) update request { (4) &Chargeable-User-Identity := 0x00 (4) } # update request (noop) (4) } # if ("%{client:add_cui}" == 'yes') (noop) (4) } # cui.authorize (noop) (4) suffix - Checking for suffix after "@" (4) suffix - Looking up realm "lboro.ac.uk" for User-Name = "anon(a)lboro.ac.uk" (4) suffix - Found realm "lboro.ac.uk" (4) suffix - Adding Stripped-User-Name = "anon" (4) suffix - Adding Realm = "lboro.ac.uk" (4) suffix - Authentication realm is LOCAL (4) suffix (ok) (4) ntdomain - Request already has destination realm set. Ignoring (4) ntdomain (noop) (4) if ( Called-Station-Id =~ /:eduroam$/ ) { (4) ... (4) } (4) elsif ( Called-Station-Id =~ /.*:YST$/ ) { (4) ... (4) } (4) elsif ( Called-Station-Id =~ /.*:ecb$/ || "%{client:group}" == "ecb" ) { (4) EXPAND %{client:group} (4) --> wireless (4) ... (4) } (4) if ((User-Name =~ /youthsporttrust\\.org$/) || (User-Name =~ /^YOUTHSPORTTRUST\\\\/)) { (4) ... (4) } (4) elsif (User-Name =~ /\(a)ecb\.co\.uk/i && "%{client:shortname}" == "dulcimer" ) { (4) ... (4) } (4) elsif ( Realm == "ECB" || Realm == "ecb.co.uk" ) { (4) ... (4) } (4) elsif (Service-Type == Call-Check && !EAP-Message && User-Name =~ /[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]/) { (4) ... (4) } (4) elsif ( Realm == "lsu.co.uk" ) { (4) ... (4) } (4) elsif (User-Name =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) { (4) ... (4) } (4) else { (4) update request { (4) &Realm := local (4) } # update request (noop) (4) } # else (noop) (4) eap - Peer sent EAP Response (code 2) ID 6 length 6 (4) eap - Continuing tunnel setup (4) eap (ok) (4) } # authorize (ok) (4) Using 'Auth-Type = eap' for authenticate {...} (4) Running Auth-Type eap from file /etc/raddb/sites-enabled/lboro (4) authenticate { (4) eap - Peer sent packet with EAP method PEAP (25) (4) eap - Calling submodule eap_peap to process data (4) eap_peap - Continuing EAP-TLS (4) eap_peap - Peer ACKed our handshake fragment (4) eap_peap - [eap-tls verify] = request (4) eap_peap - Sending final TLS record fragment (917 bytes) (4) eap_peap - [eap-tls process] = handled (4) eap - Sending EAP Request (code 1) ID 7 length 923 (4) eap (handled) (4) } # authenticate (handled) (4) Using Post-Auth-Type Challenge (4) Post-Auth-Type sub-section not found. Ignoring. (4) Running Post-Auth-Type Challenge from file /etc/raddb/sites-enabled/lboro (4) Sent Access-Challenge Id 252 from 158.125.161.128:1812 to 10.53.253.14:32770 via ens160 length 0 (4) EAP-Message = 0x0107039b19007d6e67ce70384eded3ef06352db77da33a308201050603551d230481fd3081fa80140cf5aa7d6e67ce70384eded3ef06352db77da33aa181d6a481d33081d0310b3009060355040613024742311730150603550408130e4c65696365737465727368697265311530130603550407130c4c (4) Message-Authenticator = 0x00000000000000000000000000000000 (4) State = 0x05015100148ca6ec523c504e518c74e2 (4) Finished request Waking up in 1.9 seconds. (5) - Received Access-Request Id 253 from 10.53.253.14:32770 to 158.125.161.128:1812 via ens160 length 473 (5) - User-Name = "anon(a)lboro.ac.uk" (5) - Chargeable-User-Identity = 0x00 (5) - Location-Capable = Civix-Location (5) - Calling-Station-Id = "18-cf-5e-12-75-c1" (5) - Called-Station-Id = "b0-aa-77-57-cf-50:wirefree" (5) - NAS-Port = 13 (5) - Cisco-AVPair = "audit-session-id=0a35fd0e000e790756d5a18b" (5) - Acct-Session-Id = "56d5a18b/18:cf:5e:12:75:c1/766789" (5) - NAS-IP-Address = 10.53.253.14 (5) - NAS-IPv6-Address = 2001:630:301:9101::14 (5) - NAS-Identifier = "wism-sport-park-3" (5) - Airespace-Wlan-Id = 3 (5) - Service-Type = Framed-User (5) - Framed-MTU = 1300 (5) - NAS-Port-Type = Wireless-802.11 (5) - Tunnel-Type:0 = VLAN (5) - Tunnel-Medium-Type:0 = IEEE-802 (5) - Tunnel-Private-Group-Id:0 = "1112" (5) - EAP-Message = 0x020700a01980000000961603020046100000424104a1568ed754dd3f72a95e77cd1df1c55abf297742c6079bb39cdecf1f53cf855797776f56e08eacd682c5125da973f5f90ae119460d913d6b4757b78f288010651403020001011603020040fda3db9fe7afd24c7177fcafd292f1419d55de5910015b (5) - State = 0x05015100148ca6ec523c504e518c74e2 (5) - Message-Authenticator = 0xe49aaca6ee4e0e1119ed3410ae02cb7d (5) - Running section authorize from file /etc/raddb/sites-enabled/lboro (5) - authorize { (5) - nagios_check { (5) - if (User-Name == "nagios01aa" && "%{client:group}" == "nagios") { (5) - ... (5) - } (5) - } # nagios_check (notfound) (5) - wism_check { (5) - if (User-Name =~ /wism-check/ ) { (5) - ... (5) - } (5) - } # wism_check (notfound) (5) - filter_duff_realms { (5) - if (User-Name =~ /\\.ax\\.uk$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /\\.sc\\.uk$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /\\.ac\\.u$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /lboro$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /lboro\\.co\\.uk$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /ac\\.lboro\\.uk$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /unilboro\\.ac\\.uk$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /\\.a\\.c\\.uk$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /3gppnetwork\\.org$/i) { (5) - ... (5) - } (5) - elsif (User-Name =~ /myabc\\.com$/i) { (5) - ... (5) - } (5) - elsif (User-Name !~ /lboro\\.local$/i && User-Name =~ /\\.local$/i) { (5) - ... (5) - } (5) - elsif (User-Name =~ /lbro\\.ac\\.uk$/i ) { (5) - ... (5) - } (5) - elsif (User-Name =~ /lboro\\.student\\.ac\\.uk$/i ) { (5) - ... (5) - } (5) - } # filter_duff_realms (notfound) (5) - filter_username { (5) - if (!&User-Name) { (5) - ... (5) - } (5) - if (&User-Name =~ / /) { (5) - ... (5) - } (5) - if (&User-Name =~ /@.*@/ ) { (5) - ... (5) - } (5) - if (&User-Name =~ /\.\./ ) { (5) - ... (5) - } (5) - if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (5) - ... (5) - } (5) - if (&User-Name =~ /\.$/) { (5) - ... (5) - } (5) - if (&User-Name =~ /(a)\./) { (5) - ... (5) - } (5) - } # filter_username (notfound) (5) preprocess (ok) (5) operator-name.authorize { (5) if ("%{client:Operator-Name}") { (5) EXPAND %{client:Operator-Name} (5) --> (5) ... (5) } (5) } # operator-name.authorize (ok) (5) cui.authorize { (5) if ("%{client:add_cui}" == 'yes') { (5) EXPAND %{client:add_cui} (5) --> yes (5) update request { (5) &Chargeable-User-Identity := 0x00 (5) } # update request (noop) (5) } # if ("%{client:add_cui}" == 'yes') (noop) (5) } # cui.authorize (noop) (5) suffix - Checking for suffix after "@" (5) suffix - Looking up realm "lboro.ac.uk" for User-Name = "anon(a)lboro.ac.uk" (5) suffix - Found realm "lboro.ac.uk" (5) suffix - Adding Stripped-User-Name = "anon" (5) suffix - Adding Realm = "lboro.ac.uk" (5) suffix - Authentication realm is LOCAL (5) suffix (ok) (5) ntdomain - Request already has destination realm set. Ignoring (5) ntdomain (noop) (5) if ( Called-Station-Id =~ /:eduroam$/ ) { (5) ... (5) } (5) elsif ( Called-Station-Id =~ /.*:YST$/ ) { (5) ... (5) } (5) elsif ( Called-Station-Id =~ /.*:ecb$/ || "%{client:group}" == "ecb" ) { (5) EXPAND %{client:group} (5) --> wireless (5) ... (5) } (5) if ((User-Name =~ /youthsporttrust\\.org$/) || (User-Name =~ /^YOUTHSPORTTRUST\\\\/)) { (5) ... (5) } (5) elsif (User-Name =~ /\(a)ecb\.co\.uk/i && "%{client:shortname}" == "dulcimer" ) { (5) ... (5) } (5) elsif ( Realm == "ECB" || Realm == "ecb.co.uk" ) { (5) ... (5) } (5) elsif (Service-Type == Call-Check && !EAP-Message && User-Name =~ /[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]/) { (5) ... (5) } (5) elsif ( Realm == "lsu.co.uk" ) { (5) ... (5) } (5) elsif (User-Name =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) { (5) ... (5) } (5) else { (5) update request { (5) &Realm := local (5) } # update request (noop) (5) } # else (noop) (5) eap - Peer sent EAP Response (code 2) ID 7 length 160 (5) eap - Continuing tunnel setup (5) eap (ok) (5) } # authorize (ok) (5) Using 'Auth-Type = eap' for authenticate {...} (5) Running Auth-Type eap from file /etc/raddb/sites-enabled/lboro (5) authenticate { (5) eap - Peer sent packet with EAP method PEAP (25) (5) eap - Calling submodule eap_peap to process data (5) eap_peap - Continuing EAP-TLS (5) eap_peap - Peer indicated complete TLS record size will be 150 bytes (5) eap_peap - Got complete TLS record, with length field (150 bytes) (5) eap_peap - [eap-tls verify] = ok (5) eap_peap - <<< recv handshake [length 70], client_key_exchange (5) eap_peap - TLS Accept: SSLv3 read client key exchange A (5) eap_peap - <<< recv change_cipher_spec [length 1] (5) eap_peap - <<< recv handshake [length 16], finished (5) eap_peap - TLS Accept: SSLv3 read finished A (5) eap_peap - >>> send change_cipher_spec [length 1] (5) eap_peap - TLS Accept: SSLv3 write change cipher spec A (5) eap_peap - >>> send handshake [length 16], finished (5) eap_peap - TLS Accept: SSLv3 write finished A (5) eap_peap - TLS Accept: SSLv3 flush data (5) eap_peap - &TLS-Session-Id = 0x76d5549bfc2e548e73d1176bbe9daa36dc0d0a1d16dc467e8a51b4989a04fd65 (5) eap_peap - &config:TLS-Session-Cache-Action = Write (5) eap_peap - &session-state:TLS-Session-Data = 0x308181020101020203020402c014042076d5549bfc2e548e73d1176bbe9daa36dc0d0a1d16dc467e8a51b4989a04fd650430c180225ce975cca326ffd8557be08a6827c3c8b8f1010231e9160c29a7e8b14285cdd2956228049c70c3494a7d0ed6bda106020456d5a18ba2040202012ca412041046 (5) Running Autz-Type Session-Cache-Write from file /etc/raddb/sites-enabled/tls-cache (5) Autz-Type Session-Cache-Write { (5) update control { (5) &control:Cache-TTL := 0 (5) } # update control (noop) (5) cache_tls_session - Key "v\325T\233\374.T\216s\321\027k\276\235\2526\334\r\n\035\026\334F~\212Q\264\230\232\004\375e" -> slot 6093 (5) cache_tls_session - Reserved connection (0) (5) cache_tls_session - [3] >>> Sending command(s) to 158.125.160.61:6379 (5) cache_tls_session - [3] <<< Returned: success (5) cache_tls_session - Released connection (0) (5) cache_tls_session - No cache entry found for "v\325T\233\374.T\216s\321\027k\276\235\2526\334\r\n\035\026\334F~\212Q\264\230\232\004\375e" (5) cache_tls_session - Creating new cache entry (5) cache_tls_session - &session-state:TLS-Session-Data := &session-state:TLS-Session-Data -> 0x308181020101020203020402c014042076d5549bfc2e548e73d1176bbe9daa36dc0d0a1d16dc467e8a51b4989a04fd650430c180225ce975cca326ffd8557be08a6827c3c8b8f1010231e9160c29a7e8b14285cdd2956228049c70c3494a7d0ed6bda106020456d5a18ba2040202012ca412041046522065617020307832386434353130 (5) cache_tls_session - Key "v\325T\233\374.T\216s\321\027k\276\235\2526\334\r\n\035\026\334F~\212Q\264\230\232\004\375e" -> slot 6093 (5) cache_tls_session - Reserved connection (1) (5) cache_tls_session - [3] >>> Sending command(s) to 158.125.160.61:6379 (5) cache_tls_session - [3] <<< Returned: success (5) cache_tls_session - Released connection (1) (5) cache_tls_session - Committed entry, TTL 3600 seconds (5) cache_tls_session - Removing &control:Cache-TTL (5) cache_tls_session (ok) (5) } # Autz-Type Session-Cache-Write (ok) (5) eap_peap - SSL negotiation finished successfully (5) eap_peap - TLS established with cipher suite: ECDHE-RSA-AES256-SHA SSLv3 Kx=ECDH Au=RSA Enc=AES(256) Mac=SHA1 (5) eap_peap - Sending complete TLS record (75 bytes) (5) eap_peap - [eap-tls process] = handled (5) eap - Sending EAP Request (code 1) ID 8 length 85 (5) eap (handled) (5) } # authenticate (handled) (5) Using Post-Auth-Type Challenge (5) Post-Auth-Type sub-section not found. Ignoring. (5) Running Post-Auth-Type Challenge from file /etc/raddb/sites-enabled/lboro (5) Sent Access-Challenge Id 253 from 158.125.161.128:1812 to 10.53.253.14:32770 via ens160 length 0 (5) EAP-Message = 0x0108005519800000004b1403020001011603020040c4d3afd74b9a05f561d6b102b9650cfbedd82c0fbec9829aedc29f7522df2d1eaf21e1521aee2dbea62ed8ccfd75b59c28289fddff69b2a7b403ed50e789fec1 (5) Message-Authenticator = 0x00000000000000000000000000000000 (5) State = 0x060351002306bedc523c504e518c74e2 (5) Finished request Waking up in 1.9 seconds. (6) - Received Accounting-Request Id 72 from 10.51.2.44:1646 to 158.125.161.128:1813 via ens160 length 127 (6) - Acct-Session-Id = "00001ED6" (6) - Calling-Station-Id = "E8-94-F6-E3-73-EC" (6) - Acct-Authentic = Local (6) - Acct-Status-Type = Start (6) - NAS-Port-Type = Ethernet (6) - NAS-Port = 50002 (6) - NAS-Port-Id = "FastEthernet0/2" (6) - Called-Station-Id = "00-1B-8F-1A-17-82" (6) - Service-Type = Framed-User (6) - NAS-IP-Address = 10.51.2.44 (6) - Acct-Delay-Time = 20 (6) - Running section preacct from file /etc/raddb/sites-enabled/lboro (6) - preacct { (6) preprocess (ok) (6) acct_counters64.preacct { (6) update request { (6) EXPAND %{expr:(&Acct-Input-Gigawords << 32) | &Acct-Input-Octets} (6) WARNING: Can't find &Acct-Input-Gigawords. Using 0 as operand value (6) WARNING: Can't find &Acct-Input-Octets. Using 0 as operand value (6) --> 0 (6) &Acct-Input-Octets64 = 0 (6) EXPAND %{expr:(&Acct-Output-Gigawords << 32) | &Acct-Output-Octets} (6) WARNING: Can't find &Acct-Output-Gigawords. Using 0 as operand value (6) WARNING: Can't find &Acct-Output-Octets. Using 0 as operand value (6) --> 0 (6) &Acct-Output-Octets64 = 0 (6) } # update request (noop) (6) } # acct_counters64.preacct (noop) (6) update request { (6) EXPAND %{expr: %l - %{%{Acct-Session-Time}:-0} - %{%{Acct-Delay-Time}:-0}} (6) --> 1456841080 (6) &FreeRADIUS-Acct-Session-Start-Time = Mar 1 2016 14:04:40 GMT (6) } # update request (noop) (6) acct_unique { (6) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { (6) EXPAND %{string:Class} (6) --> (6) ... (6) } (6) else { (6) update request { (6) EXPAND %{md5:%{User-Name},%{Acct-Multi-Session-ID},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (6) --> 0da3dd9e2370ee8eb568667ef3bea757 (6) &Acct-Unique-Session-Id := 0da3dd9e2370ee8eb568667ef3bea757 (6) } # update request (noop) (6) } # else (noop) (6) } # acct_unique (noop) (6) suffix (noop) (6) ntdomain (noop) (6) files (noop) (6) } # preacct (ok) (6) Running section accounting from file /etc/raddb/sites-enabled/lboro (6) accounting { (6) if (Acct-Session-Time != 0) { (6) ERROR: Condition evaluation failed because the value of an operand could not be determined (6) ... (6) } (6) sql - EXPAND %{tolower:type.%{%{Acct-Status-Type}:-none}.query} (6) sql - --> type.start.query (6) sql - Using query template 'query' (6) sql - Reserved connection (0) (6) sql - EXPAND %{User-Name} (6) sql - --> (6) sql - SQL-User-Name set to '' (6) sql - EXPAND INSERT INTO staffbaseschema.radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Realm}', ''), '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}', NULLIF('%{%{NAS-Port-ID}:-%{NAS-Port}}', ''), '%{NAS-Port-Type}', TO_TIMESTAMP(%{integer:Event-Timestamp}), TO_TIMESTAMP(%{integer:Event-Timestamp}), NULL, 0, '%{Acct-Authentic}', '%{Connect-Info}', NULL, 0, 0, '%{Called-Station-Id}', '%{Calling-Station-Id}', NULL, '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', '')::inet) (6) sql - --> INSERT INTO staffbaseschema.radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('00001ED6', '0da3dd9e2370ee8eb568667ef3bea757', '', NULLIF('', ''), '10.51.2.44', NULLIF('FastEthernet0/2', ''), 'Ethernet', TO_TIMESTAMP(1456841080), TO_TIMESTAMP(1456841080), NULL, 0, 'Local', '', NULL, 0, 0, '00-1B-8F-1A-17-82', 'E8-94-F6-E3-73-EC', NULL, 'Framed-User', '', NULLIF('', '')::inet) (6) sql - Executing query: INSERT INTO staffbaseschema.radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('00001ED6', '0da3dd9e2370ee8eb568667ef3bea757', '', NULLIF('', ''), '10.51.2.44', NULLIF('FastEthernet0/2', ''), 'Ethernet', TO_TIMESTAMP(1456841080), TO_TIMESTAMP(1456841080), NULL, 0, 'Local', '', NULL, 0, 0, '00-1B-8F-1A-17-82', 'E8-94-F6-E3-73-EC', NULL, 'Framed-User', '', NULLIF('', '')::inet) rlm_sql_postgresql - Status: PGRES_COMMAND_OK rlm_sql_postgresql - query affected rows = 1 (6) sql - SQL query returned: success (6) sql - 1 record(s) updated (6) sql - Released connection (0) (6) sql (ok) (6) if (noop) { (6) ... (6) } (6) attr_filter.accounting_response - EXPAND %{User-Name} (6) attr_filter.accounting_response - --> (6) attr_filter.accounting_response - Matched entry DEFAULT at line 12 (6) attr_filter.accounting_response (updated) (6) } # accounting (updated) (6) Sent Accounting-Response Id 72 from 158.125.161.128:1813 to 10.51.2.44:1646 via ens160 length 0 (6) Finished request (6) Cleaning up request packet ID 72 with timestamp +4 Waking up in 1.6 seconds. (7) - Received Access-Request Id 254 from 10.53.253.14:32770 to 158.125.161.128:1812 via ens160 length 319 (7) - User-Name = "anon(a)lboro.ac.uk" (7) - Chargeable-User-Identity = 0x00 (7) - Location-Capable = Civix-Location (7) - Calling-Station-Id = "18-cf-5e-12-75-c1" (7) - Called-Station-Id = "b0-aa-77-57-cf-50:wirefree" (7) - NAS-Port = 13 (7) - Cisco-AVPair = "audit-session-id=0a35fd0e000e790756d5a18b" (7) - Acct-Session-Id = "56d5a18b/18:cf:5e:12:75:c1/766789" (7) - NAS-IP-Address = 10.53.253.14 (7) - NAS-IPv6-Address = 2001:630:301:9101::14 (7) - NAS-Identifier = "wism-sport-park-3" (7) - Airespace-Wlan-Id = 3 (7) - Service-Type = Framed-User (7) - Framed-MTU = 1300 (7) - NAS-Port-Type = Wireless-802.11 (7) - Tunnel-Type:0 = VLAN (7) - Tunnel-Medium-Type:0 = IEEE-802 (7) - Tunnel-Private-Group-Id:0 = "1112" (7) - EAP-Message = 0x020800061900 (7) - State = 0x060351002306bedc523c504e518c74e2 (7) - Message-Authenticator = 0xf70d79e724c5206f4b6e87dbae453927 (7) - Running section authorize from file /etc/raddb/sites-enabled/lboro (7) - authorize { (7) - nagios_check { (7) - if (User-Name == "nagios01aa" && "%{client:group}" == "nagios") { (7) - ... (7) - } (7) - } # nagios_check (notfound) (7) - wism_check { (7) - if (User-Name =~ /wism-check/ ) { (7) - ... (7) - } (7) - } # wism_check (notfound) (7) - filter_duff_realms { (7) - if (User-Name =~ /\\.ax\\.uk$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /\\.sc\\.uk$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /\\.ac\\.u$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /lboro$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /lboro\\.co\\.uk$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /ac\\.lboro\\.uk$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /unilboro\\.ac\\.uk$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /\\.a\\.c\\.uk$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /3gppnetwork\\.org$/i) { (7) - ... (7) - } (7) - elsif (User-Name =~ /myabc\\.com$/i) { (7) - ... (7) - } (7) - elsif (User-Name !~ /lboro\\.local$/i && User-Name =~ /\\.local$/i) { (7) - ... (7) - } (7) - elsif (User-Name =~ /lbro\\.ac\\.uk$/i ) { (7) - ... (7) - } (7) - elsif (User-Name =~ /lboro\\.student\\.ac\\.uk$/i ) { (7) - ... (7) - } (7) - } # filter_duff_realms (notfound) (7) - filter_username { (7) - if (!&User-Name) { (7) - ... (7) - } (7) - if (&User-Name =~ / /) { (7) - ... (7) - } (7) - if (&User-Name =~ /@.*@/ ) { (7) - ... (7) - } (7) - if (&User-Name =~ /\.\./ ) { (7) - ... (7) - } (7) - if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { (7) - ... (7) - } (7) - if (&User-Name =~ /\.$/) { (7) - ... (7) - } (7) - if (&User-Name =~ /(a)\./) { (7) - ... (7) - } (7) - } # filter_username (notfound) (7) preprocess (ok) (7) operator-name.authorize { (7) if ("%{client:Operator-Name}") { (7) EXPAND %{client:Operator-Name} (7) --> (7) ... (7) } (7) } # operator-name.authorize (ok) (7) cui.authorize { (7) if ("%{client:add_cui}" == 'yes') { (7) EXPAND %{client:add_cui} (7) --> yes (7) update request { (7) &Chargeable-User-Identity := 0x00 (7) } # update request (noop) (7) } # if ("%{client:add_cui}" == 'yes') (noop) (7) } # cui.authorize (noop) (7) suffix - Checking for suffix after "@" (7) suffix - Looking up realm "lboro.ac.uk" for User-Name = "anon(a)lboro.ac.uk" (7) suffix - Found realm "lboro.ac.uk" (7) suffix - Adding Stripped-User-Name = "anon" (7) suffix - Adding Realm = "lboro.ac.uk" (7) suffix - Authentication realm is LOCAL (7) suffix (ok) (7) ntdomain - Request already has destination realm set. Ignoring (7) ntdomain (noop) (7) if ( Called-Station-Id =~ /:eduroam$/ ) { (7) ... (7) } (7) elsif ( Called-Station-Id =~ /.*:YST$/ ) { (7) ... (7) } (7) elsif ( Called-Station-Id =~ /.*:ecb$/ || "%{client:group}" == "ecb" ) { (7) EXPAND %{client:group} (7) --> wireless (7) ... (7) } (7) if ((User-Name =~ /youthsporttrust\\.org$/) || (User-Name =~ /^YOUTHSPORTTRUST\\\\/)) { (7) ... (7) } (7) elsif (User-Name =~ /\(a)ecb\.co\.uk/i && "%{client:shortname}" == "dulcimer" ) { (7) ... (7) } (7) elsif ( Realm == "ECB" || Realm == "ecb.co.uk" ) { (7) ... (7) } (7) elsif (Service-Type == Call-Check && !EAP-Message && User-Name =~ /[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]/) { (7) ... (7) } (7) elsif ( Realm == "lsu.co.uk" ) { (7) ... (7) } (7) elsif (User-Name =~ /\\\\?([^@\\\\]+)@?([-[:alnum:]._]*)?$/) { (7) ... (7) } (7) else { (7) update request { (7) &Realm := local (7) } # update request (noop) (7) } # else (noop) (7) eap - Peer sent EAP Response (code 2) ID 8 length 6 (7) eap - Continuing tunnel setup (7) eap (ok) (7) } # authorize (ok) (7) Using 'Auth-Type = eap' for authenticate {...} (7) Running Auth-Type eap from file /etc/raddb/sites-enabled/lboro (7) authenticate { (7) eap - Peer sent packet with EAP method PEAP (25) (7) eap - Calling submodule eap_peap to process data (7) eap_peap - Continuing EAP-TLS (7) eap_peap - Peer ACKed our handshake fragment. handshake is finished (7) eap_peap - [eap-tls verify] = success (7) eap_peap - [eap-tls process] = success (7) eap_peap - Session established. Decoding tunneled data (7) eap_peap - PEAP state TUNNEL ESTABLISHED (7) eap_peap - Sending complete TLS record (53 bytes) (7) eap - Sending EAP Request (code 1) ID 9 length 63 (7) eap (handled) (7) } # authenticate (handled) (7) Using Post-Auth-Type Challenge (7) Post-Auth-Type sub-section not found. Ignoring. (7) Running Post-Auth-Type Challenge from file /etc/raddb/sites-enabled/lboro (7) Sent Access-Challenge Id 254 from 158.125.161.128:1812 to 10.53.253.14:32770 via ens160 length 0 (7) EAP-Message = 0x0109003f198000000035170302003094eda224ed5bd67356b6b9e5e9cb3f4e402a8774515ad7ff767acd2a8960e9fa58e5020503986828312b7c8b944a0e61 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0x07015100148ca6ec523c504e518c74e2 (7) Finished request Waking up in 0.8 seconds. (0) Cleaning up request packet ID 248 with timestamp +3 (1) Cleaning up request packet ID 249 with timestamp +3 (2) Cleaning up request packet ID 250 with timestamp +3 (3) Cleaning up request packet ID 251 with timestamp +3 (4) Cleaning up request packet ID 252 with timestamp +3 (5) Cleaning up request packet ID 253 with timestamp +3 Waking up in 1.0 seconds. (7) Cleaning up request packet ID 254 with timestamp +5 Ready to process requests

2 2

freeradius 3 + mysql configure
by Kiefer, Jonas 29 Feb '16

29 Feb '16

Hello freeradius users, i install a freeradius 3 with mysql and daloradius on ubuntu 14.04 lts. Now i trie to get the radius authentification working with a hp procurve 2530 switch. But the Radius Server does not send any Access-Accept Message. Only Access-Challanges will send tot he switch: Logfile: Fri Feb 26 09:09:12 2016 : Debug: Server was built with: Fri Feb 26 09:09:12 2016 : Debug: accounting : yes Fri Feb 26 09:09:12 2016 : Debug: authentication : yes Fri Feb 26 09:09:12 2016 : Debug: ascend-binary-attributes : yes Fri Feb 26 09:09:12 2016 : Debug: coa : yes Fri Feb 26 09:09:12 2016 : Debug: control-socket : yes Fri Feb 26 09:09:12 2016 : Debug: detail : yes Fri Feb 26 09:09:12 2016 : Debug: dhcp : yes Fri Feb 26 09:09:12 2016 : Debug: dynamic-clients : yes Fri Feb 26 09:09:12 2016 : Debug: osfc2 : no Fri Feb 26 09:09:12 2016 : Debug: proxy : yes Fri Feb 26 09:09:12 2016 : Debug: regex-pcre : no Fri Feb 26 09:09:12 2016 : Debug: regex-posix : yes Fri Feb 26 09:09:12 2016 : Debug: regex-posix-extended : yes Fri Feb 26 09:09:12 2016 : Debug: session-management : yes Fri Feb 26 09:09:12 2016 : Debug: stats : yes Fri Feb 26 09:09:12 2016 : Debug: tcp : yes Fri Feb 26 09:09:12 2016 : Debug: threads : yes Fri Feb 26 09:09:12 2016 : Debug: tls : yes Fri Feb 26 09:09:12 2016 : Debug: unlang : yes Fri Feb 26 09:09:12 2016 : Debug: vmps : yes Fri Feb 26 09:09:12 2016 : Debug: developer : no Fri Feb 26 09:09:12 2016 : Debug: Server core libs: Fri Feb 26 09:09:12 2016 : Debug: freeradius-server : 3.0.10 Fri Feb 26 09:09:12 2016 : Debug: talloc : 2.0.* Fri Feb 26 09:09:12 2016 : Debug: ssl : 1.0.1f release Fri Feb 26 09:09:12 2016 : Debug: Endianness: Fri Feb 26 09:09:12 2016 : Debug: little Fri Feb 26 09:09:12 2016 : Debug: Compilation flags: Fri Feb 26 09:09:12 2016 : Info: Copyright (C) 1999-2015 The FreeRADIUS server project and contributors Fri Feb 26 09:09:12 2016 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Fri Feb 26 09:09:12 2016 : Info: PARTICULAR PURPOSE Fri Feb 26 09:09:12 2016 : Info: You may redistribute copies of FreeRADIUS under the terms of the Fri Feb 26 09:09:12 2016 : Info: GNU General Public License Fri Feb 26 09:09:12 2016 : Info: For more information about these matters, see the file named COPYRIGHT Fri Feb 26 09:09:12 2016 : Info: Starting - reading configuration files ... Fri Feb 26 09:09:12 2016 : Debug: including dictionary file /usr/share/freeradius/dictionary Fri Feb 26 09:09:12 2016 : Debug: including dictionary file /usr/share/freeradius/dictionary.dhcp Fri Feb 26 09:09:12 2016 : Debug: including dictionary file /usr/share/freeradius/dictionary.vqp Fri Feb 26 09:09:12 2016 : Debug: including dictionary file /etc/freeradius/dictionary Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/radiusd.conf Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/proxy.conf Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/clients.conf Fri Feb 26 09:09:12 2016 : Debug: including files in directory /etc/freeradius/mods-enabled/ Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/linelog Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/soh Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/passwd Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/replicate Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/dynamic_clients Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/mschap Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/expr Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/cache_eap Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/files Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/unpack Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/utf8 Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/unix Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/chap Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/detail Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/ntlm_auth Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/preprocess Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/exec Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/sql Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-config/sql/main/sqlite/queries.conf Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/logintime Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/sradutmp Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/digest Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/radutmp Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/eap Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/pap Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/expiration Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/mods-enabled/echo Fri Feb 26 09:09:12 2016 : Debug: including files in directory /etc/freeradius/policy.d/ Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/abfab-tr Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/control Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/cui Fri Feb 26 09:09:12 2016 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Fri Feb 26 09:09:12 2016 : Debug: OPTIMIZING (no == yes) --> FALSE Fri Feb 26 09:09:12 2016 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Fri Feb 26 09:09:12 2016 : Debug: OPTIMIZING (no == yes) --> FALSE Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/dhcp Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/accounting Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/canonicalization Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/debug Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/operator-name Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/filter Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/policy.d/eap Fri Feb 26 09:09:12 2016 : Debug: including files in directory /etc/freeradius/sites-enabled/ Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Fri Feb 26 09:09:12 2016 : Debug: including files in directory /etc/freeradius/sites-enabled/ Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:12 2016 : Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Fri Feb 26 09:09:12 2016 : Debug: main { Fri Feb 26 09:09:12 2016 : Debug: security { Fri Feb 26 09:09:12 2016 : Debug: user = "freerad" Fri Feb 26 09:09:12 2016 : Debug: group = "freerad" Fri Feb 26 09:09:12 2016 : Debug: allow_core_dumps = no Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[462]: The item 'max_attributes' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[480]: The item 'reject_delay' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[500]: The item 'status_server' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: name = "freeradius" Fri Feb 26 09:09:12 2016 : Debug: prefix = "/usr" Fri Feb 26 09:09:12 2016 : Debug: localstatedir = "/var" Fri Feb 26 09:09:12 2016 : Debug: logdir = "/var/log/freeradius" Fri Feb 26 09:09:12 2016 : Debug: run_dir = "/var/run/freeradius" Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[55]: The item 'sysconfdir' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[108]: The item 'libdir' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[119]: The item 'pidfile' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[194]: The item 'max_request_time' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[213]: The item 'cleanup_delay' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[250]: The item 'hostname_lookups' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[372]: The item 'checkrad' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[521]: The item 'proxy_requests' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: main { Fri Feb 26 09:09:12 2016 : Debug: name = "freeradius" Fri Feb 26 09:09:12 2016 : Debug: prefix = "/usr" Fri Feb 26 09:09:12 2016 : Debug: localstatedir = "/var" Fri Feb 26 09:09:12 2016 : Debug: sbindir = "/usr/sbin" Fri Feb 26 09:09:12 2016 : Debug: logdir = "/var/log/freeradius" Fri Feb 26 09:09:12 2016 : Debug: run_dir = "/var/run/freeradius" Fri Feb 26 09:09:12 2016 : Debug: libdir = "/usr/lib/freeradius" Fri Feb 26 09:09:12 2016 : Debug: radacctdir = "/var/log/freeradius/radacct" Fri Feb 26 09:09:12 2016 : Debug: hostname_lookups = no Fri Feb 26 09:09:12 2016 : Debug: max_request_time = 30 Fri Feb 26 09:09:12 2016 : Debug: cleanup_delay = 5 Fri Feb 26 09:09:12 2016 : Debug: max_requests = 16384 Fri Feb 26 09:09:12 2016 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Fri Feb 26 09:09:12 2016 : Debug: checkrad = "/usr/sbin/checkrad" Fri Feb 26 09:09:12 2016 : Debug: debug_level = 0 Fri Feb 26 09:09:12 2016 : Debug: proxy_requests = yes Fri Feb 26 09:09:12 2016 : Debug: log { Fri Feb 26 09:09:12 2016 : Debug: stripped_names = no Fri Feb 26 09:09:12 2016 : Debug: auth = no Fri Feb 26 09:09:12 2016 : Debug: auth_badpass = no Fri Feb 26 09:09:12 2016 : Debug: auth_goodpass = no Fri Feb 26 09:09:12 2016 : Debug: colourise = yes Fri Feb 26 09:09:12 2016 : Debug: msg_denied = "You are already logged in - access denied" Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[268]: The item 'destination' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[285]: The item 'file' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[331]: The item 'syslog_facility' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: resources { Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: security { Fri Feb 26 09:09:12 2016 : Debug: max_attributes = 200 Fri Feb 26 09:09:12 2016 : Debug: reject_delay = 1.000000 Fri Feb 26 09:09:12 2016 : Debug: status_server = yes Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[55]: The item 'sysconfdir' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[74]: The item 'db_dir' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Warning: /etc/freeradius/radiusd.conf[140]: The item 'correct_escapes' is defined, but is unused by the configuration Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: radiusd: #### Loading Realms and Home Servers #### Fri Feb 26 09:09:12 2016 : Debug: proxy server { Fri Feb 26 09:09:12 2016 : Debug: retry_delay = 5 Fri Feb 26 09:09:12 2016 : Debug: retry_count = 3 Fri Feb 26 09:09:12 2016 : Debug: default_fallback = no Fri Feb 26 09:09:12 2016 : Debug: dead_time = 120 Fri Feb 26 09:09:12 2016 : Debug: wake_all_if_all_dead = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: home_server localhost { Fri Feb 26 09:09:12 2016 : Debug: ipaddr = 127.0.0.1 Fri Feb 26 09:09:12 2016 : Debug: port = 1812 Fri Feb 26 09:09:12 2016 : Debug: type = "auth" Fri Feb 26 09:09:12 2016 : Debug: secret = "testing123" Fri Feb 26 09:09:12 2016 : Debug: response_window = 20.000000 Fri Feb 26 09:09:12 2016 : Debug: response_timeouts = 1 Fri Feb 26 09:09:12 2016 : Debug: max_outstanding = 65536 Fri Feb 26 09:09:12 2016 : Debug: zombie_period = 40 Fri Feb 26 09:09:12 2016 : Debug: status_check = "status-server" Fri Feb 26 09:09:12 2016 : Debug: ping_interval = 30 Fri Feb 26 09:09:12 2016 : Debug: check_interval = 30 Fri Feb 26 09:09:12 2016 : Debug: check_timeout = 4 Fri Feb 26 09:09:12 2016 : Debug: num_answers_to_alive = 3 Fri Feb 26 09:09:12 2016 : Debug: revive_interval = 120 Fri Feb 26 09:09:12 2016 : Debug: limit { Fri Feb 26 09:09:12 2016 : Debug: max_connections = 16 Fri Feb 26 09:09:12 2016 : Debug: max_requests = 0 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 0 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: coa { Fri Feb 26 09:09:12 2016 : Debug: irt = 2 Fri Feb 26 09:09:12 2016 : Debug: mrt = 16 Fri Feb 26 09:09:12 2016 : Debug: mrc = 5 Fri Feb 26 09:09:12 2016 : Debug: mrd = 30 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: home_server_pool my_auth_failover { Fri Feb 26 09:09:12 2016 : Debug: type = fail-over Fri Feb 26 09:09:12 2016 : Debug: home_server = localhost Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: realm example.com { Fri Feb 26 09:09:12 2016 : Debug: auth_pool = my_auth_failover Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: realm LOCAL { Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: radiusd: #### Loading Clients #### Fri Feb 26 09:09:12 2016 : Debug: client localhost { Fri Feb 26 09:09:12 2016 : Debug: ipaddr = 127.0.0.1 Fri Feb 26 09:09:12 2016 : Debug: require_message_authenticator = no Fri Feb 26 09:09:12 2016 : Debug: secret = "testing123" Fri Feb 26 09:09:12 2016 : Debug: nas_type = "other" Fri Feb 26 09:09:12 2016 : Debug: proto = "*" Fri Feb 26 09:09:12 2016 : Debug: limit { Fri Feb 26 09:09:12 2016 : Debug: max_connections = 16 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 30 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Fri Feb 26 09:09:12 2016 : Debug: client localhost_ipv6 { Fri Feb 26 09:09:12 2016 : Debug: ipv6addr = ::1 Fri Feb 26 09:09:12 2016 : Debug: require_message_authenticator = no Fri Feb 26 09:09:12 2016 : Debug: secret = "testing123" Fri Feb 26 09:09:12 2016 : Debug: limit { Fri Feb 26 09:09:12 2016 : Debug: max_connections = 16 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 30 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Fri Feb 26 09:09:12 2016 : Info: Debugger not attached Fri Feb 26 09:09:12 2016 : Debug: # Creating Auth-Type = digest Fri Feb 26 09:09:12 2016 : Debug: radiusd: #### Instantiating modules #### Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_linelog.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_linelog, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_linelog Fri Feb 26 09:09:12 2016 : Debug: # Loading module "linelog" from file /etc/freeradius/mods-enabled/linelog Fri Feb 26 09:09:12 2016 : Debug: linelog { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/linelog" Fri Feb 26 09:09:12 2016 : Debug: escape_filenames = no Fri Feb 26 09:09:12 2016 : Debug: syslog_severity = "info" Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: format = "This is a log message for %{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: reference = "messages.%{%{reply:Packet-Type}:-default}" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "log_accounting" from file /etc/freeradius/mods-enabled/linelog Fri Feb 26 09:09:12 2016 : Debug: linelog log_accounting { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/linelog-accounting" Fri Feb 26 09:09:12 2016 : Debug: escape_filenames = no Fri Feb 26 09:09:12 2016 : Debug: syslog_severity = "info" Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: format = "" Fri Feb 26 09:09:12 2016 : Debug: reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_soh.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_soh, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_soh Fri Feb 26 09:09:12 2016 : Debug: # Loading module "soh" from file /etc/freeradius/mods-enabled/soh Fri Feb 26 09:09:12 2016 : Debug: soh { Fri Feb 26 09:09:12 2016 : Debug: dhcp = yes Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_passwd.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_passwd, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_passwd Fri Feb 26 09:09:12 2016 : Debug: # Loading module "etc_passwd" from file /etc/freeradius/mods-enabled/passwd Fri Feb 26 09:09:12 2016 : Debug: passwd etc_passwd { Fri Feb 26 09:09:12 2016 : Debug: filename = "/etc/passwd" Fri Feb 26 09:09:12 2016 : Debug: format = "*User-Name:Crypt-Password:" Fri Feb 26 09:09:12 2016 : Debug: delimiter = ":" Fri Feb 26 09:09:12 2016 : Debug: ignore_nislike = no Fri Feb 26 09:09:12 2016 : Debug: ignore_empty = yes Fri Feb 26 09:09:12 2016 : Debug: allow_multiple_keys = no Fri Feb 26 09:09:12 2016 : Debug: hash_size = 100 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_replicate.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_replicate, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_replicate Fri Feb 26 09:09:12 2016 : Debug: # Loading module "replicate" from file /etc/freeradius/mods-enabled/replicate Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_dynamic_clients.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_dynamic_clients, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_dynamic_clients Fri Feb 26 09:09:12 2016 : Debug: # Loading module "dynamic_clients" from file /etc/freeradius/mods-enabled/dynamic_clients Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_mschap.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_mschap, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_mschap Fri Feb 26 09:09:12 2016 : Debug: # Loading module "mschap" from file /etc/freeradius/mods-enabled/mschap Fri Feb 26 09:09:12 2016 : Debug: mschap { Fri Feb 26 09:09:12 2016 : Debug: use_mppe = yes Fri Feb 26 09:09:12 2016 : Debug: require_encryption = no Fri Feb 26 09:09:12 2016 : Debug: require_strong = no Fri Feb 26 09:09:12 2016 : Debug: with_ntdomain_hack = yes Fri Feb 26 09:09:12 2016 : Debug: passchange { Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: allow_retry = yes Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_expr.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_expr, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_expr Fri Feb 26 09:09:12 2016 : Debug: # Loading module "expr" from file /etc/freeradius/mods-enabled/expr Fri Feb 26 09:09:12 2016 : Debug: expr { Fri Feb 26 09:09:12 2016 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_cache.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_cache, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_cache Fri Feb 26 09:09:12 2016 : Debug: # Loading module "cache_eap" from file /etc/freeradius/mods-enabled/cache_eap Fri Feb 26 09:09:12 2016 : Debug: cache cache_eap { Fri Feb 26 09:09:12 2016 : Debug: driver = "rlm_cache_rbtree" Fri Feb 26 09:09:12 2016 : Debug: key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}" Fri Feb 26 09:09:12 2016 : Debug: ttl = 15 Fri Feb 26 09:09:12 2016 : Debug: max_entries = 0 Fri Feb 26 09:09:12 2016 : Debug: epoch = 0 Fri Feb 26 09:09:12 2016 : Debug: add_stats = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_files.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_files, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_files Fri Feb 26 09:09:12 2016 : Debug: # Loading module "files" from file /etc/freeradius/mods-enabled/files Fri Feb 26 09:09:12 2016 : Debug: files { Fri Feb 26 09:09:12 2016 : Debug: filename = "/etc/freeradius/mods-config/files/authorize" Fri Feb 26 09:09:12 2016 : Debug: acctusersfile = "/etc/freeradius/mods-config/files/accounting" Fri Feb 26 09:09:12 2016 : Debug: preproxy_usersfile = "/etc/freeradius/mods-config/files/pre-proxy" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_unpack.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_unpack, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_unpack Fri Feb 26 09:09:12 2016 : Debug: # Loading module "unpack" from file /etc/freeradius/mods-enabled/unpack Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_detail.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_detail, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_detail Fri Feb 26 09:09:12 2016 : Debug: # Loading module "auth_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: detail auth_log { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" Fri Feb 26 09:09:12 2016 : Debug: header = "%t" Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: locking = no Fri Feb 26 09:09:12 2016 : Debug: escape_filenames = no Fri Feb 26 09:09:12 2016 : Debug: log_packet_header = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "reply_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: detail reply_log { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" Fri Feb 26 09:09:12 2016 : Debug: header = "%t" Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: locking = no Fri Feb 26 09:09:12 2016 : Debug: escape_filenames = no Fri Feb 26 09:09:12 2016 : Debug: log_packet_header = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "pre_proxy_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: detail pre_proxy_log { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" Fri Feb 26 09:09:12 2016 : Debug: header = "%t" Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: locking = no Fri Feb 26 09:09:12 2016 : Debug: escape_filenames = no Fri Feb 26 09:09:12 2016 : Debug: log_packet_header = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "post_proxy_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: detail post_proxy_log { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" Fri Feb 26 09:09:12 2016 : Debug: header = "%t" Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: locking = no Fri Feb 26 09:09:12 2016 : Debug: escape_filenames = no Fri Feb 26 09:09:12 2016 : Debug: log_packet_header = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_utf8.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_utf8, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_utf8 Fri Feb 26 09:09:12 2016 : Debug: # Loading module "utf8" from file /etc/freeradius/mods-enabled/utf8 Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_always.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_always, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_always Fri Feb 26 09:09:12 2016 : Debug: # Loading module "reject" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always reject { Fri Feb 26 09:09:12 2016 : Debug: rcode = "reject" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "fail" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always fail { Fri Feb 26 09:09:12 2016 : Debug: rcode = "fail" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "ok" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always ok { Fri Feb 26 09:09:12 2016 : Debug: rcode = "ok" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "handled" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always handled { Fri Feb 26 09:09:12 2016 : Debug: rcode = "handled" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "invalid" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always invalid { Fri Feb 26 09:09:12 2016 : Debug: rcode = "invalid" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "userlock" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always userlock { Fri Feb 26 09:09:12 2016 : Debug: rcode = "userlock" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "notfound" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always notfound { Fri Feb 26 09:09:12 2016 : Debug: rcode = "notfound" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "noop" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always noop { Fri Feb 26 09:09:12 2016 : Debug: rcode = "noop" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "updated" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: always updated { Fri Feb 26 09:09:12 2016 : Debug: rcode = "updated" Fri Feb 26 09:09:12 2016 : Debug: simulcount = 0 Fri Feb 26 09:09:12 2016 : Debug: mpp = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_unix.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_unix, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_unix Fri Feb 26 09:09:12 2016 : Debug: # Loading module "unix" from file /etc/freeradius/mods-enabled/unix Fri Feb 26 09:09:12 2016 : Debug: unix { Fri Feb 26 09:09:12 2016 : Debug: radwtmp = "/var/log/freeradius/radwtmp" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Creating attribute Unix-Group Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_chap.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_chap, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_chap Fri Feb 26 09:09:12 2016 : Debug: # Loading module "chap" from file /etc/freeradius/mods-enabled/chap Fri Feb 26 09:09:12 2016 : Debug: # Loading module "detail" from file /etc/freeradius/mods-enabled/detail Fri Feb 26 09:09:12 2016 : Debug: detail { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" Fri Feb 26 09:09:12 2016 : Debug: header = "%t" Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: locking = no Fri Feb 26 09:09:12 2016 : Debug: escape_filenames = no Fri Feb 26 09:09:12 2016 : Debug: log_packet_header = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_exec.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_exec, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_exec Fri Feb 26 09:09:12 2016 : Debug: # Loading module "ntlm_auth" from file /etc/freeradius/mods-enabled/ntlm_auth Fri Feb 26 09:09:12 2016 : Debug: exec ntlm_auth { Fri Feb 26 09:09:12 2016 : Debug: wait = yes Fri Feb 26 09:09:12 2016 : Debug: program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" Fri Feb 26 09:09:12 2016 : Debug: shell_escape = yes Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_attr_filter.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_attr_filter, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_attr_filter Fri Feb 26 09:09:12 2016 : Debug: # Loading module "attr_filter.post-proxy" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: attr_filter attr_filter.post-proxy { Fri Feb 26 09:09:12 2016 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/post-proxy" Fri Feb 26 09:09:12 2016 : Debug: key = "%{Realm}" Fri Feb 26 09:09:12 2016 : Debug: relaxed = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "attr_filter.pre-proxy" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: attr_filter attr_filter.pre-proxy { Fri Feb 26 09:09:12 2016 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/pre-proxy" Fri Feb 26 09:09:12 2016 : Debug: key = "%{Realm}" Fri Feb 26 09:09:12 2016 : Debug: relaxed = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "attr_filter.access_reject" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: attr_filter attr_filter.access_reject { Fri Feb 26 09:09:12 2016 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/access_reject" Fri Feb 26 09:09:12 2016 : Debug: key = "%{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: relaxed = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "attr_filter.access_challenge" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: attr_filter attr_filter.access_challenge { Fri Feb 26 09:09:12 2016 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/access_challenge" Fri Feb 26 09:09:12 2016 : Debug: key = "%{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: relaxed = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "attr_filter.accounting_response" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: attr_filter attr_filter.accounting_response { Fri Feb 26 09:09:12 2016 : Debug: filename = "/etc/freeradius/mods-config/attr_filter/accounting_response" Fri Feb 26 09:09:12 2016 : Debug: key = "%{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: relaxed = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_preprocess.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_preprocess, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_preprocess Fri Feb 26 09:09:12 2016 : Debug: # Loading module "preprocess" from file /etc/freeradius/mods-enabled/preprocess Fri Feb 26 09:09:12 2016 : Debug: preprocess { Fri Feb 26 09:09:12 2016 : Debug: huntgroups = "/etc/freeradius/mods-config/preprocess/huntgroups" Fri Feb 26 09:09:12 2016 : Debug: hints = "/etc/freeradius/mods-config/preprocess/hints" Fri Feb 26 09:09:12 2016 : Debug: with_ascend_hack = no Fri Feb 26 09:09:12 2016 : Debug: ascend_channels_per_line = 23 Fri Feb 26 09:09:12 2016 : Debug: with_ntdomain_hack = no Fri Feb 26 09:09:12 2016 : Debug: with_specialix_jetstream_hack = no Fri Feb 26 09:09:12 2016 : Debug: with_cisco_vsa_hack = no Fri Feb 26 09:09:12 2016 : Debug: with_alvarion_vsa_hack = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_realm.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_realm, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_realm Fri Feb 26 09:09:12 2016 : Debug: # Loading module "IPASS" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: realm IPASS { Fri Feb 26 09:09:12 2016 : Debug: format = "prefix" Fri Feb 26 09:09:12 2016 : Debug: delimiter = "/" Fri Feb 26 09:09:12 2016 : Debug: ignore_default = no Fri Feb 26 09:09:12 2016 : Debug: ignore_null = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "suffix" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: realm suffix { Fri Feb 26 09:09:12 2016 : Debug: format = "suffix" Fri Feb 26 09:09:12 2016 : Debug: delimiter = "@" Fri Feb 26 09:09:12 2016 : Debug: ignore_default = no Fri Feb 26 09:09:12 2016 : Debug: ignore_null = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "realmpercent" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: realm realmpercent { Fri Feb 26 09:09:12 2016 : Debug: format = "suffix" Fri Feb 26 09:09:12 2016 : Debug: delimiter = "%" Fri Feb 26 09:09:12 2016 : Debug: ignore_default = no Fri Feb 26 09:09:12 2016 : Debug: ignore_null = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "ntdomain" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: realm ntdomain { Fri Feb 26 09:09:12 2016 : Debug: format = "prefix" Fri Feb 26 09:09:12 2016 : Debug: delimiter = "\\" Fri Feb 26 09:09:12 2016 : Debug: ignore_default = no Fri Feb 26 09:09:12 2016 : Debug: ignore_null = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Loading module "exec" from file /etc/freeradius/mods-enabled/exec Fri Feb 26 09:09:12 2016 : Debug: exec { Fri Feb 26 09:09:12 2016 : Debug: wait = no Fri Feb 26 09:09:12 2016 : Debug: input_pairs = "request" Fri Feb 26 09:09:12 2016 : Debug: shell_escape = yes Fri Feb 26 09:09:12 2016 : Debug: timeout = 10 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_sql.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_sql, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_sql Fri Feb 26 09:09:12 2016 : Debug: # Loading module "sql" from file /etc/freeradius/mods-enabled/sql Fri Feb 26 09:09:12 2016 : Debug: sql { Fri Feb 26 09:09:12 2016 : Debug: driver = "rlm_sql_mysql" Fri Feb 26 09:09:12 2016 : Debug: server = "localhost" Fri Feb 26 09:09:12 2016 : Debug: port = 3306 Fri Feb 26 09:09:12 2016 : Debug: login = "freeradius" Fri Feb 26 09:09:12 2016 : Debug: password = "radius123" Fri Feb 26 09:09:12 2016 : Debug: radius_db = "radius" Fri Feb 26 09:09:12 2016 : Debug: read_groups = yes Fri Feb 26 09:09:12 2016 : Debug: read_profiles = yes Fri Feb 26 09:09:12 2016 : Debug: read_clients = yes Fri Feb 26 09:09:12 2016 : Debug: delete_stale_sessions = yes Fri Feb 26 09:09:12 2016 : Debug: sql_user_name = "%{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: default_user_profile = "" Fri Feb 26 09:09:12 2016 : Debug: client_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" Fri Feb 26 09:09:12 2016 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" Fri Feb 26 09:09:12 2016 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id" Fri Feb 26 09:09:12 2016 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id" Fri Feb 26 09:09:12 2016 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id" Fri Feb 26 09:09:12 2016 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" Fri Feb 26 09:09:12 2016 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-Group}' AND acctstoptime IS NULL" Fri Feb 26 09:09:12 2016 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Fri Feb 26 09:09:12 2016 : Debug: accounting { Fri Feb 26 09:09:12 2016 : Debug: reference = "%{tolower:type.%{Acct-Status-Type}.query}" Fri Feb 26 09:09:12 2016 : Debug: type { Fri Feb 26 09:09:12 2016 : Debug: accounting-on { Fri Feb 26 09:09:12 2016 : Debug: query = "UPDATE radacct SET acctstoptime = %{%{integer:Event-Timestamp}:-date('now')}, acctsessiontime = (%{%{integer:Event-Timestamp}:-strftime('%%s', 'now')} - strftime('%%s', acctstarttime)), acctterminatecause = '%{Acct-Terminate-Cause}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= %{integer:Event-Timestamp}" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: accounting-off { Fri Feb 26 09:09:12 2016 : Debug: query = "UPDATE radacct SET acctstoptime = %{%{integer:Event-Timestamp}:-date('now')}, acctsessiontime = (%{%{integer:Event-Timestamp}:-strftime('%%s', 'now')} - strftime('%%s', acctstarttime)), acctterminatecause = '%{Acct-Terminate-Cause}' WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= %{integer:Event-Timestamp}" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: start { Fri Feb 26 09:09:12 2016 : Debug: query = "INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', %{%{integer:Event-Timestamp}:-date('now')}, %{%{integer:Event-Timestamp}:-date('now')}, NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}')" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: interim-update { Fri Feb 26 09:09:12 2016 : Debug: query = "UPDATE radacct SET acctupdatetime = %{%{integer:Event-Timestamp}:-date('now')}, acctinterval = 0, framedipaddress = '%{Framed-IP-Address}', acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = %{%{Acct-Input-Gigawords}:-0} << 32 | %{%{Acct-Input-Octets}:-0}, acctoutputoctets = %{%{Acct-Output-Gigawords}:-0} << 32 | %{%{Acct-Output-Octets}:-0} WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: stop { Fri Feb 26 09:09:12 2016 : Debug: query = "UPDATE radacct SET acctstoptime = %{%{integer:Event-Timestamp}:-date('now')}, acctsessiontime = %{%{Acct-Session-Time}:-NULL}, acctinputoctets = %{%{Acct-Input-Gigawords}:-0} << 32 | %{%{Acct-Input-Octets}:-0}, acctoutputoctets = %{%{Acct-Output-Gigawords}:-0} << 32 | %{%{Acct-Output-Octets}:-0}, acctterminatecause = '%{Acct-Terminate-Cause}', connectinfo_stop = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: post-auth { Fri Feb 26 09:09:12 2016 : Debug: reference = ".query" Fri Feb 26 09:09:12 2016 : Debug: query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_sql_mysql.so" Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Fri Feb 26 09:09:12 2016 : Debug: Creating attribute SQL-Group Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_logintime.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_logintime, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_logintime Fri Feb 26 09:09:12 2016 : Debug: # Loading module "logintime" from file /etc/freeradius/mods-enabled/logintime Fri Feb 26 09:09:12 2016 : Debug: logintime { Fri Feb 26 09:09:12 2016 : Debug: minimum_timeout = 60 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_radutmp.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_radutmp, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_radutmp Fri Feb 26 09:09:12 2016 : Debug: # Loading module "sradutmp" from file /etc/freeradius/mods-enabled/sradutmp Fri Feb 26 09:09:12 2016 : Debug: radutmp sradutmp { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/sradutmp" Fri Feb 26 09:09:12 2016 : Debug: username = "%{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: case_sensitive = yes Fri Feb 26 09:09:12 2016 : Debug: check_with_nas = yes Fri Feb 26 09:09:12 2016 : Debug: permissions = 420 Fri Feb 26 09:09:12 2016 : Debug: caller_id = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_digest.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_digest, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_digest Fri Feb 26 09:09:12 2016 : Debug: # Loading module "digest" from file /etc/freeradius/mods-enabled/digest Fri Feb 26 09:09:12 2016 : Debug: # Loading module "radutmp" from file /etc/freeradius/mods-enabled/radutmp Fri Feb 26 09:09:12 2016 : Debug: radutmp { Fri Feb 26 09:09:12 2016 : Debug: filename = "/var/log/freeradius/radutmp" Fri Feb 26 09:09:12 2016 : Debug: username = "%{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: case_sensitive = yes Fri Feb 26 09:09:12 2016 : Debug: check_with_nas = yes Fri Feb 26 09:09:12 2016 : Debug: permissions = 384 Fri Feb 26 09:09:12 2016 : Debug: caller_id = yes Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_eap, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_eap Fri Feb 26 09:09:12 2016 : Debug: # Loading module "eap" from file /etc/freeradius/mods-enabled/eap Fri Feb 26 09:09:12 2016 : Debug: eap { Fri Feb 26 09:09:12 2016 : Debug: default_eap_type = "md5" Fri Feb 26 09:09:12 2016 : Debug: timer_expire = 60 Fri Feb 26 09:09:12 2016 : Debug: ignore_unknown_eap_types = no Fri Feb 26 09:09:12 2016 : Debug: cisco_accounting_username_bug = no Fri Feb 26 09:09:12 2016 : Debug: max_sessions = 16384 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_pap.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_pap, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_pap Fri Feb 26 09:09:12 2016 : Debug: # Loading module "pap" from file /etc/freeradius/mods-enabled/pap Fri Feb 26 09:09:12 2016 : Debug: pap { Fri Feb 26 09:09:12 2016 : Debug: normalise = yes Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_expiration.so" Fri Feb 26 09:09:12 2016 : Debug: Loaded rlm_expiration, checking if it's valid Fri Feb 26 09:09:12 2016 : Debug: # Loaded module rlm_expiration Fri Feb 26 09:09:12 2016 : Debug: # Loading module "expiration" from file /etc/freeradius/mods-enabled/expiration Fri Feb 26 09:09:12 2016 : Debug: # Loading module "echo" from file /etc/freeradius/mods-enabled/echo Fri Feb 26 09:09:12 2016 : Debug: exec echo { Fri Feb 26 09:09:12 2016 : Debug: wait = yes Fri Feb 26 09:09:12 2016 : Debug: program = "/bin/echo %{User-Name}" Fri Feb 26 09:09:12 2016 : Debug: input_pairs = "request" Fri Feb 26 09:09:12 2016 : Debug: output_pairs = "reply" Fri Feb 26 09:09:12 2016 : Debug: shell_escape = yes Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: instantiate { Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: modules { Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "linelog" from file /etc/freeradius/mods-enabled/linelog Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "log_accounting" from file /etc/freeradius/mods-enabled/linelog Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "etc_passwd" from file /etc/freeradius/mods-enabled/passwd Fri Feb 26 09:09:12 2016 : Debug: rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "mschap" from file /etc/freeradius/mods-enabled/mschap Fri Feb 26 09:09:12 2016 : Debug: rlm_mschap (mschap): using internal authentication Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "cache_eap" from file /etc/freeradius/mods-enabled/cache_eap Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_cache_rbtree.so" Fri Feb 26 09:09:12 2016 : Debug: rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "files" from file /etc/freeradius/mods-enabled/files Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/files/authorize Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/files/accounting Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/files/pre-proxy Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "auth_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "reply_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "pre_proxy_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "post_proxy_log" from file /etc/freeradius/mods-enabled/detail.log Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "reject" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "fail" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "ok" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "handled" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "invalid" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "userlock" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "notfound" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "noop" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "updated" from file /etc/freeradius/mods-enabled/always Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "detail" from file /etc/freeradius/mods-enabled/detail Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "attr_filter.post-proxy" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/attr_filter/post-proxy Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/attr_filter/pre-proxy Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "attr_filter.access_reject" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/attr_filter/access_reject Fri Feb 26 09:09:12 2016 : Warning: [/etc/freeradius/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". Fri Feb 26 09:09:12 2016 : Warning: [/etc/freeradius/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "attr_filter.access_challenge" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/attr_filter/access_challenge Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "attr_filter.accounting_response" from file /etc/freeradius/mods-enabled/attr_filter Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/attr_filter/accounting_response Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "preprocess" from file /etc/freeradius/mods-enabled/preprocess Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/preprocess/huntgroups Fri Feb 26 09:09:12 2016 : Debug: reading pairlist file /etc/freeradius/mods-config/preprocess/hints Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "IPASS" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "suffix" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "realmpercent" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "ntdomain" from file /etc/freeradius/mods-enabled/realm Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "sql" from file /etc/freeradius/mods-enabled/sql Fri Feb 26 09:09:12 2016 : Info: rlm_sql_mysql: libmysql version: 5.5.47 Fri Feb 26 09:09:12 2016 : Debug: mysql { Fri Feb 26 09:09:12 2016 : Debug: tls { Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: warnings = "auto" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Attempting to connect to database "radius" Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Using local pool section Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): No pool reference found for config item "sql.pool" Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Initialising connection pool Fri Feb 26 09:09:12 2016 : Debug: pool { Fri Feb 26 09:09:12 2016 : Debug: start = 5 Fri Feb 26 09:09:12 2016 : Debug: min = 3 Fri Feb 26 09:09:12 2016 : Debug: max = 32 Fri Feb 26 09:09:12 2016 : Debug: spare = 10 Fri Feb 26 09:09:12 2016 : Debug: uses = 0 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: cleanup_interval = 30 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 60 Fri Feb 26 09:09:12 2016 : Debug: retry_delay = 30 Fri Feb 26 09:09:12 2016 : Debug: spread = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Opening additional connection (0), 1 of 32 pending slots used Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.47-0ubuntu0.14.04.1, protocol version 10 Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Opening additional connection (1), 1 of 31 pending slots used Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.47-0ubuntu0.14.04.1, protocol version 10 Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Opening additional connection (2), 1 of 30 pending slots used Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.47-0ubuntu0.14.04.1, protocol version 10 Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Opening additional connection (3), 1 of 29 pending slots used Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.47-0ubuntu0.14.04.1, protocol version 10 Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Opening additional connection (4), 1 of 28 pending slots used Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.47-0ubuntu0.14.04.1, protocol version 10 Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Adding pool reference 0x1e41e70 to config item "sql.pool" Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Processing generate_sql_clients Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Reserved connection (0) Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Executing select query: SELECT id, nasname, shortname, type, secret, server FROM nas Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Adding client 192.168.6.0/24 () to global clients list Fri Feb 26 09:09:12 2016 : Debug: Adding client 192.168.6.0/24 (192.168.6.0) to prefix tree 24 Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (192.168.6.0): Client "" (sql) added Fri Feb 26 09:09:12 2016 : Debug: rlm_sql (sql): Released connection (0) Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Need 5 more connections to reach 10 spares Fri Feb 26 09:09:12 2016 : Info: rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Fri Feb 26 09:09:12 2016 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.47-0ubuntu0.14.04.1, protocol version 10 Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "logintime" from file /etc/freeradius/mods-enabled/logintime Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "eap" from file /etc/freeradius/mods-enabled/eap Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap_md5.so" Fri Feb 26 09:09:12 2016 : Debug: # Linked to sub-module rlm_eap_md5 Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap_leap.so" Fri Feb 26 09:09:12 2016 : Debug: # Linked to sub-module rlm_eap_leap Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap_gtc.so" Fri Feb 26 09:09:12 2016 : Debug: # Linked to sub-module rlm_eap_gtc Fri Feb 26 09:09:12 2016 : Debug: gtc { Fri Feb 26 09:09:12 2016 : Debug: challenge = "Password: " Fri Feb 26 09:09:12 2016 : Debug: auth_type = "PAP" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap_tls.so" Fri Feb 26 09:09:12 2016 : Debug: # Linked to sub-module rlm_eap_tls Fri Feb 26 09:09:12 2016 : Debug: tls { Fri Feb 26 09:09:12 2016 : Debug: tls = "tls-common" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: tls-config tls-common { Fri Feb 26 09:09:12 2016 : Debug: rsa_key_exchange = no Fri Feb 26 09:09:12 2016 : Debug: dh_key_exchange = yes Fri Feb 26 09:09:12 2016 : Debug: rsa_key_length = 512 Fri Feb 26 09:09:12 2016 : Debug: dh_key_length = 512 Fri Feb 26 09:09:12 2016 : Debug: verify_depth = 0 Fri Feb 26 09:09:12 2016 : Debug: ca_path = "/etc/freeradius/certs" Fri Feb 26 09:09:12 2016 : Debug: pem_file_type = yes Fri Feb 26 09:09:12 2016 : Debug: private_key_file = "/etc/freeradius/certs/server.pem" Fri Feb 26 09:09:12 2016 : Debug: certificate_file = "/etc/freeradius/certs/server.pem" Fri Feb 26 09:09:12 2016 : Debug: ca_file = "/etc/freeradius/certs/ca.pem" Fri Feb 26 09:09:12 2016 : Debug: private_key_password = "whatever" Fri Feb 26 09:09:12 2016 : Debug: dh_file = "/etc/freeradius/certs/dh" Fri Feb 26 09:09:12 2016 : Debug: fragment_size = 1024 Fri Feb 26 09:09:12 2016 : Debug: include_length = yes Fri Feb 26 09:09:12 2016 : Debug: check_crl = no Fri Feb 26 09:09:12 2016 : Debug: check_all_crl = no Fri Feb 26 09:09:12 2016 : Debug: cipher_list = "DEFAULT" Fri Feb 26 09:09:12 2016 : Debug: ecdh_curve = "prime256v1" Fri Feb 26 09:09:12 2016 : Debug: cache { Fri Feb 26 09:09:12 2016 : Debug: enable = yes Fri Feb 26 09:09:12 2016 : Debug: lifetime = 24 Fri Feb 26 09:09:12 2016 : Debug: max_entries = 255 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: verify { Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: ocsp { Fri Feb 26 09:09:12 2016 : Debug: enable = no Fri Feb 26 09:09:12 2016 : Debug: override_cert_url = yes Fri Feb 26 09:09:12 2016 : Debug: url = "http://127.0.0.1/ocsp/" Fri Feb 26 09:09:12 2016 : Debug: use_nonce = yes Fri Feb 26 09:09:12 2016 : Debug: timeout = 0 Fri Feb 26 09:09:12 2016 : Debug: softfail = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap_ttls.so" Fri Feb 26 09:09:12 2016 : Debug: # Linked to sub-module rlm_eap_ttls Fri Feb 26 09:09:12 2016 : Debug: ttls { Fri Feb 26 09:09:12 2016 : Debug: tls = "tls-common" Fri Feb 26 09:09:12 2016 : Debug: default_eap_type = "md5" Fri Feb 26 09:09:12 2016 : Debug: copy_request_to_tunnel = no Fri Feb 26 09:09:12 2016 : Debug: use_tunneled_reply = yes Fri Feb 26 09:09:12 2016 : Debug: virtual_server = "inner-tunnel" Fri Feb 26 09:09:12 2016 : Debug: include_length = yes Fri Feb 26 09:09:12 2016 : Debug: require_client_cert = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: tls: Using cached TLS configuration from previous invocation Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap_peap.so" Fri Feb 26 09:09:12 2016 : Debug: # Linked to sub-module rlm_eap_peap Fri Feb 26 09:09:12 2016 : Debug: peap { Fri Feb 26 09:09:12 2016 : Debug: tls = "tls-common" Fri Feb 26 09:09:12 2016 : Debug: default_eap_type = "mschapv2" Fri Feb 26 09:09:12 2016 : Debug: copy_request_to_tunnel = yes Fri Feb 26 09:09:12 2016 : Debug: use_tunneled_reply = yes Fri Feb 26 09:09:12 2016 : Debug: proxy_tunneled_request_as_eap = yes Fri Feb 26 09:09:12 2016 : Debug: virtual_server = "inner-tunnel" Fri Feb 26 09:09:12 2016 : Debug: soh = no Fri Feb 26 09:09:12 2016 : Debug: require_client_cert = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: tls: Using cached TLS configuration from previous invocation Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/rlm_eap_mschapv2.so" Fri Feb 26 09:09:12 2016 : Debug: # Linked to sub-module rlm_eap_mschapv2 Fri Feb 26 09:09:12 2016 : Debug: mschapv2 { Fri Feb 26 09:09:12 2016 : Debug: with_ntdomain_hack = no Fri Feb 26 09:09:12 2016 : Debug: send_error = no Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "pap" from file /etc/freeradius/mods-enabled/pap Fri Feb 26 09:09:12 2016 : Debug: # Instantiating module "expiration" from file /etc/freeradius/mods-enabled/expiration Fri Feb 26 09:09:12 2016 : Debug: } # modules Fri Feb 26 09:09:12 2016 : Debug: radiusd: #### Loading Virtual Servers #### Fri Feb 26 09:09:12 2016 : Debug: server { # from file /etc/freeradius/radiusd.conf Fri Feb 26 09:09:12 2016 : Debug: } # server Fri Feb 26 09:09:12 2016 : Debug: server default { # from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:12 2016 : Debug: authenticate { Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: pap Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: chap Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: mschap Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: digest Fri Feb 26 09:09:12 2016 : Debug: eap Fri Feb 26 09:09:12 2016 : Debug: } # authenticate Fri Feb 26 09:09:12 2016 : Debug: authorize { Fri Feb 26 09:09:12 2016 : Debug: preprocess Fri Feb 26 09:09:12 2016 : Debug: chap Fri Feb 26 09:09:12 2016 : Debug: mschap Fri Feb 26 09:09:12 2016 : Debug: digest Fri Feb 26 09:09:12 2016 : Debug: suffix Fri Feb 26 09:09:12 2016 : Debug: eap Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Fri Feb 26 09:09:12 2016 : Debug: expiration Fri Feb 26 09:09:12 2016 : Debug: logintime Fri Feb 26 09:09:12 2016 : Debug: pap Fri Feb 26 09:09:12 2016 : Debug: } # authorize Fri Feb 26 09:09:12 2016 : Debug: preacct { Fri Feb 26 09:09:12 2016 : Debug: preprocess Fri Feb 26 09:09:12 2016 : Debug: policy acct_unique { Fri Feb 26 09:09:12 2016 : Debug: if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/) { Fri Feb 26 09:09:12 2016 : Debug: update { Fri Feb 26 09:09:12 2016 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: else { Fri Feb 26 09:09:12 2016 : Debug: update { Fri Feb 26 09:09:12 2016 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}" Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: suffix Fri Feb 26 09:09:12 2016 : Debug: } # preacct Fri Feb 26 09:09:12 2016 : Debug: accounting { Fri Feb 26 09:09:12 2016 : Debug: detail Fri Feb 26 09:09:12 2016 : Debug: unix Fri Feb 26 09:09:12 2016 : Debug: radutmp Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: exec Fri Feb 26 09:09:12 2016 : Debug: attr_filter.accounting_response Fri Feb 26 09:09:12 2016 : Debug: } # accounting Fri Feb 26 09:09:12 2016 : Debug: session { Fri Feb 26 09:09:12 2016 : Debug: radutmp Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: } # session Fri Feb 26 09:09:12 2016 : Debug: post-proxy { Fri Feb 26 09:09:12 2016 : Debug: eap Fri Feb 26 09:09:12 2016 : Debug: } # post-proxy Fri Feb 26 09:09:12 2016 : Debug: post-auth { Fri Feb 26 09:09:12 2016 : Debug: update { Fri Feb 26 09:09:12 2016 : Debug: &reply[*] += &session-state[*] Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: exec Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: attr_filter.access_reject Fri Feb 26 09:09:12 2016 : Debug: eap Fri Feb 26 09:09:12 2016 : Debug: policy remove_reply_message_if_eap { Fri Feb 26 09:09:12 2016 : Debug: if (&reply:EAP-Message && &reply:Reply-Message) { Fri Feb 26 09:09:12 2016 : Debug: update { Fri Feb 26 09:09:12 2016 : Debug: &reply:Reply-Message !* ANY Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: else { Fri Feb 26 09:09:12 2016 : Debug: noop Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } # post-auth Fri Feb 26 09:09:12 2016 : Debug: } # server default Fri Feb 26 09:09:12 2016 : Debug: server inner-tunnel { # from file /etc/freeradius/sites-enabled/inner-tunnel Fri Feb 26 09:09:12 2016 : Debug: authenticate { Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: pap Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: chap Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: mschap Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: eap Fri Feb 26 09:09:12 2016 : Debug: } # authenticate Fri Feb 26 09:09:12 2016 : Debug: authorize { Fri Feb 26 09:09:12 2016 : Debug: chap Fri Feb 26 09:09:12 2016 : Debug: mschap Fri Feb 26 09:09:12 2016 : Debug: suffix Fri Feb 26 09:09:12 2016 : Debug: update { Fri Feb 26 09:09:12 2016 : Debug: &control:Proxy-To-Realm := LOCAL Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: eap Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: expiration Fri Feb 26 09:09:12 2016 : Debug: logintime Fri Feb 26 09:09:12 2016 : Debug: pap Fri Feb 26 09:09:12 2016 : Debug: } # authorize Fri Feb 26 09:09:12 2016 : Debug: session { Fri Feb 26 09:09:12 2016 : Debug: radutmp Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: } # session Fri Feb 26 09:09:12 2016 : Debug: post-proxy { Fri Feb 26 09:09:12 2016 : Debug: eap Fri Feb 26 09:09:12 2016 : Debug: } # post-proxy Fri Feb 26 09:09:12 2016 : Debug: post-auth { Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: group { Fri Feb 26 09:09:12 2016 : Debug: sql Fri Feb 26 09:09:12 2016 : Debug: attr_filter.access_reject Fri Feb 26 09:09:12 2016 : Debug: update { Fri Feb 26 09:09:12 2016 : Debug: &outer.session-state:Module-Failure-Message := &Module-Failure-Message Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } # post-auth Fri Feb 26 09:09:12 2016 : Debug: } # server inner-tunnel Fri Feb 26 09:09:12 2016 : Debug: Created signal pipe. Read end FD 11, write end FD 12 Fri Feb 26 09:09:12 2016 : Debug: radiusd: #### Opening IP addresses and Ports #### Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/proto_auth.so" Fri Feb 26 09:09:12 2016 : Debug: Failed with error: /usr/lib/freeradius/proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: Library file not found Fri Feb 26 09:09:12 2016 : Debug: Loading library using linker search path(s) Fri Feb 26 09:09:12 2016 : Debug: Defaults : /lib:/usr/lib Fri Feb 26 09:09:12 2016 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: listen { Fri Feb 26 09:09:12 2016 : Debug: type = "auth" Fri Feb 26 09:09:12 2016 : Debug: ipaddr = * Fri Feb 26 09:09:12 2016 : Debug: port = 0 Fri Feb 26 09:09:12 2016 : Debug: limit { Fri Feb 26 09:09:12 2016 : Debug: max_connections = 16 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 30 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/proto_acct.so" Fri Feb 26 09:09:12 2016 : Debug: Failed with error: /usr/lib/freeradius/proto_acct.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: Library file not found Fri Feb 26 09:09:12 2016 : Debug: Loading library using linker search path(s) Fri Feb 26 09:09:12 2016 : Debug: Defaults : /lib:/usr/lib Fri Feb 26 09:09:12 2016 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: listen { Fri Feb 26 09:09:12 2016 : Debug: type = "acct" Fri Feb 26 09:09:12 2016 : Debug: ipaddr = * Fri Feb 26 09:09:12 2016 : Debug: port = 0 Fri Feb 26 09:09:12 2016 : Debug: limit { Fri Feb 26 09:09:12 2016 : Debug: max_connections = 16 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 30 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/proto_auth.so" Fri Feb 26 09:09:12 2016 : Debug: Failed with error: /usr/lib/freeradius/proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: Library file not found Fri Feb 26 09:09:12 2016 : Debug: Loading library using linker search path(s) Fri Feb 26 09:09:12 2016 : Debug: Defaults : /lib:/usr/lib Fri Feb 26 09:09:12 2016 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: listen { Fri Feb 26 09:09:12 2016 : Debug: type = "auth" Fri Feb 26 09:09:12 2016 : Debug: ipv6addr = :: Fri Feb 26 09:09:12 2016 : Debug: port = 0 Fri Feb 26 09:09:12 2016 : Debug: limit { Fri Feb 26 09:09:12 2016 : Debug: max_connections = 16 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 30 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/proto_acct.so" Fri Feb 26 09:09:12 2016 : Debug: Failed with error: /usr/lib/freeradius/proto_acct.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: Library file not found Fri Feb 26 09:09:12 2016 : Debug: Loading library using linker search path(s) Fri Feb 26 09:09:12 2016 : Debug: Defaults : /lib:/usr/lib Fri Feb 26 09:09:12 2016 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: listen { Fri Feb 26 09:09:12 2016 : Debug: type = "acct" Fri Feb 26 09:09:12 2016 : Debug: ipv6addr = :: Fri Feb 26 09:09:12 2016 : Debug: port = 0 Fri Feb 26 09:09:12 2016 : Debug: limit { Fri Feb 26 09:09:12 2016 : Debug: max_connections = 16 Fri Feb 26 09:09:12 2016 : Debug: lifetime = 0 Fri Feb 26 09:09:12 2016 : Debug: idle_timeout = 30 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Loading library using absolute path "/usr/lib/freeradius/proto_auth.so" Fri Feb 26 09:09:12 2016 : Debug: Failed with error: /usr/lib/freeradius/proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: Library file not found Fri Feb 26 09:09:12 2016 : Debug: Loading library using linker search path(s) Fri Feb 26 09:09:12 2016 : Debug: Defaults : /lib:/usr/lib Fri Feb 26 09:09:12 2016 : Debug: Failed with error: proto_auth.so: cannot open shared object file: No such file or directory Fri Feb 26 09:09:12 2016 : Debug: listen { Fri Feb 26 09:09:12 2016 : Debug: type = "auth" Fri Feb 26 09:09:12 2016 : Debug: ipaddr = 127.0.0.1 Fri Feb 26 09:09:12 2016 : Debug: port = 18120 Fri Feb 26 09:09:12 2016 : Debug: } Fri Feb 26 09:09:12 2016 : Debug: Listening on auth address * port 1812 bound to server default Fri Feb 26 09:09:12 2016 : Debug: Listening on acct address * port 1813 bound to server default Fri Feb 26 09:09:12 2016 : Debug: Listening on auth address :: port 1812 bound to server default Fri Feb 26 09:09:12 2016 : Debug: Listening on acct address :: port 1813 bound to server default Fri Feb 26 09:09:12 2016 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server inner-tunnel Fri Feb 26 09:09:12 2016 : Debug: Opened new proxy socket 'proxy address * port 52333' Fri Feb 26 09:09:12 2016 : Debug: Listening on proxy address * port 52333 Fri Feb 26 09:09:12 2016 : Debug: Opened new proxy socket 'proxy address :: port 52096' Fri Feb 26 09:09:12 2016 : Debug: Listening on proxy address :: port 52096 Fri Feb 26 09:09:12 2016 : Info: Ready to process requests Fri Feb 26 09:09:20 2016 : Debug: (0) Received Access-Request Id 94 from 192.168.6.211:1812 to 192.168.1.65:1812 length 116 Fri Feb 26 09:09:20 2016 : Debug: (0) User-Name = "test" Fri Feb 26 09:09:20 2016 : Debug: (0) NAS-IP-Address = 211.6.168.192 Fri Feb 26 09:09:20 2016 : Debug: (0) NAS-Identifier = "SWITCH01-TEST" Fri Feb 26 09:09:20 2016 : Debug: (0) NAS-Port-Type = Virtual Fri Feb 26 09:09:20 2016 : Debug: (0) Service-Type = NAS-Prompt-User Fri Feb 26 09:09:20 2016 : Debug: (0) EAP-Message = 0x020000090174657374 Fri Feb 26 09:09:20 2016 : Debug: (0) Message-Authenticator = 0xad23178550d4d9d40cd4ea363c3c6eef Fri Feb 26 09:09:20 2016 : Debug: (0) MS-RAS-Vendor = 184549376 Fri Feb 26 09:09:20 2016 : Debug: (0) Calling-Station-Id = "192.168.14.114" Fri Feb 26 09:09:20 2016 : Debug: (0) session-state: No State attribute Fri Feb 26 09:09:20 2016 : Debug: (0) # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (0) authorize { Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) [preprocess] = ok Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: calling chap (rlm_chap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: returned from chap (rlm_chap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) [chap] = noop Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) [mschap] = noop Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: calling digest (rlm_digest) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: returned from digest (rlm_digest) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) [digest] = noop Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: calling suffix (rlm_realm) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) suffix: Checking for suffix after "@" Fri Feb 26 09:09:20 2016 : Debug: (0) suffix: No '@' in User-Name = "test", looking up realm NULL Fri Feb 26 09:09:20 2016 : Debug: (0) suffix: No such realm "NULL" Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) [suffix] = noop Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) eap: Peer sent EAP Response (code 2) ID 0 length 9 Fri Feb 26 09:09:20 2016 : Debug: (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) [eap] = ok Fri Feb 26 09:09:20 2016 : Debug: (0) } # authorize = ok Fri Feb 26 09:09:20 2016 : Debug: (0) Found Auth-Type = EAP Fri Feb 26 09:09:20 2016 : Debug: (0) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (0) authenticate { Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authenticate]: calling eap (rlm_eap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) eap: Peer sent packet with method EAP Identity (1) Fri Feb 26 09:09:20 2016 : Debug: (0) eap: Calling submodule eap_md5 to process data Fri Feb 26 09:09:20 2016 : Debug: (0) eap_md5: Issuing MD5 Challenge Fri Feb 26 09:09:20 2016 : Debug: (0) eap: Sending EAP Request (code 1) ID 1 length 22 Fri Feb 26 09:09:20 2016 : Debug: (0) eap: EAP session adding &reply:State = 0x49d1e9bb49d0ed66 Fri Feb 26 09:09:20 2016 : Debug: (0) modsingle[authenticate]: returned from eap (rlm_eap) for request 0 Fri Feb 26 09:09:20 2016 : Debug: (0) [eap] = handled Fri Feb 26 09:09:20 2016 : Debug: (0) } # authenticate = handled Fri Feb 26 09:09:20 2016 : Debug: (0) Using Post-Auth-Type Challenge Fri Feb 26 09:09:20 2016 : Debug: (0) Post-Auth-Type sub-section not found. Ignoring. Fri Feb 26 09:09:20 2016 : Debug: (0) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (0) session-state: Nothing to cache Fri Feb 26 09:09:20 2016 : Debug: (0) Sent Access-Challenge Id 94 from 192.168.1.65:1812 to 192.168.6.211:1812 length 0 Fri Feb 26 09:09:20 2016 : Debug: (0) EAP-Message = 0x010100160410cf9fddc333bc02de4f7986fbf39093f9 Fri Feb 26 09:09:20 2016 : Debug: (0) Message-Authenticator = 0x00000000000000000000000000000000 Fri Feb 26 09:09:20 2016 : Debug: (0) State = 0x49d1e9bb49d0ed6604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (0) Finished request Fri Feb 26 09:09:20 2016 : Debug: Waking up in 4.9 seconds. Fri Feb 26 09:09:20 2016 : Debug: (1) Received Access-Request Id 95 from 192.168.6.211:1812 to 192.168.1.65:1812 length 131 Fri Feb 26 09:09:20 2016 : Debug: (1) User-Name = "test" Fri Feb 26 09:09:20 2016 : Debug: (1) NAS-IP-Address = 211.6.168.192 Fri Feb 26 09:09:20 2016 : Debug: (1) NAS-Identifier = "SWITCH01-TEST" Fri Feb 26 09:09:20 2016 : Debug: (1) NAS-Port-Type = Virtual Fri Feb 26 09:09:20 2016 : Debug: (1) Service-Type = NAS-Prompt-User Fri Feb 26 09:09:20 2016 : Debug: (1) State = 0x49d1e9bb49d0ed6604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (1) EAP-Message = 0x020100060319 Fri Feb 26 09:09:20 2016 : Debug: (1) Message-Authenticator = 0xc3f34c4d541be70e121ca7c8c01784c1 Fri Feb 26 09:09:20 2016 : Debug: (1) MS-RAS-Vendor = 184549376 Fri Feb 26 09:09:20 2016 : Debug: (1) Calling-Station-Id = "192.168.14.114" Fri Feb 26 09:09:20 2016 : Debug: (1) session-state: No cached attributes Fri Feb 26 09:09:20 2016 : Debug: (1) # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (1) authorize { Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [preprocess] = ok Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling chap (rlm_chap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from chap (rlm_chap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [chap] = noop Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling mschap (rlm_mschap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from mschap (rlm_mschap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [mschap] = noop Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling digest (rlm_digest) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from digest (rlm_digest) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [digest] = noop Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling suffix (rlm_realm) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) suffix: Checking for suffix after "@" Fri Feb 26 09:09:20 2016 : Debug: (1) suffix: No '@' in User-Name = "test", looking up realm NULL Fri Feb 26 09:09:20 2016 : Debug: (1) suffix: No such realm "NULL" Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from suffix (rlm_realm) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [suffix] = noop Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling eap (rlm_eap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Peer sent EAP Response (code 2) ID 1 length 6 Fri Feb 26 09:09:20 2016 : Debug: (1) eap: No EAP Start, assuming it's an on-going EAP conversation Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from eap (rlm_eap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [eap] = updated Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling sql (rlm_sql) for request 1 Fri Feb 26 09:09:20 2016 : Debug: %{User-Name} Fri Feb 26 09:09:20 2016 : Debug: Parsed xlat tree: Fri Feb 26 09:09:20 2016 : Debug: attribute --> User-Name Fri Feb 26 09:09:20 2016 : Debug: (1) sql: EXPAND %{User-Name} Fri Feb 26 09:09:20 2016 : Debug: (1) sql: --> test Fri Feb 26 09:09:20 2016 : Debug: (1) sql: SQL-User-Name set to 'test' Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: FROM 1 TO 12 MAX 13 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: Examining SQL-User-Name Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: APPENDING SQL-User-Name FROM 0 TO 12 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: TO in 12 out 12 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[0] = User-Name Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[1] = NAS-IP-Address Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[2] = NAS-Identifier Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[3] = NAS-Port-Type Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[4] = Service-Type Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[5] = State Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[6] = EAP-Message Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[7] = Message-Authenticator Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[8] = MS-RAS-Vendor Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[9] = Calling-Station-Id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[10] = Event-Timestamp Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[11] = EAP-Type Fri Feb 26 09:09:20 2016 : Debug: rlm_sql (sql): Reserved connection (1) Fri Feb 26 09:09:20 2016 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: Parsed xlat tree: Fri Feb 26 09:09:20 2016 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Fri Feb 26 09:09:20 2016 : Debug: attribute --> SQL-User-Name Fri Feb 26 09:09:20 2016 : Debug: literal --> ' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'test' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: User found in radcheck table Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Conditional check items matched, merging assignment check items Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Cleartext-Password := "test" Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: FROM 1 TO 1 MAX 2 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: Examining Cleartext-Password Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: APPENDING Cleartext-Password FROM 0 TO 1 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: TO in 1 out 1 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[0] = Auth-Type Fri Feb 26 09:09:20 2016 : Debug: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: Parsed xlat tree: Fri Feb 26 09:09:20 2016 : Debug: literal --> SELECT id, username, attribute, value, op FROM radreply WHERE username = ' Fri Feb 26 09:09:20 2016 : Debug: attribute --> SQL-User-Name Fri Feb 26 09:09:20 2016 : Debug: literal --> ' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: EXPAND SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: --> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Executing select query: SELECT id, username, attribute, value, op FROM radreply WHERE username = 'test' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ... falling-through to group processing Fri Feb 26 09:09:20 2016 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Fri Feb 26 09:09:20 2016 : Debug: Parsed xlat tree: Fri Feb 26 09:09:20 2016 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Fri Feb 26 09:09:20 2016 : Debug: attribute --> SQL-User-Name Fri Feb 26 09:09:20 2016 : Debug: literal --> ' ORDER BY priority Fri Feb 26 09:09:20 2016 : Debug: (1) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Fri Feb 26 09:09:20 2016 : Debug: (1) sql: --> SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'test' ORDER BY priority Fri Feb 26 09:09:20 2016 : Debug: (1) sql: User found in the group table Fri Feb 26 09:09:20 2016 : Debug: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: Parsed xlat tree: Fri Feb 26 09:09:20 2016 : Debug: literal --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = ' Fri Feb 26 09:09:20 2016 : Debug: attribute --> SQL-Group Fri Feb 26 09:09:20 2016 : Debug: literal --> ' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: EXPAND SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{SQL-Group}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: --> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'HP-Procurve-Switch' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Executing select query: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'HP-Procurve-Switch' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Group "HP-Procurve-Switch": Conditional check items matched Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Group "HP-Procurve-Switch": Merging assignment check items Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: FROM 0 TO 2 MAX 2 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: TO in 2 out 2 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[0] = Auth-Type Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: to[1] = Cleartext-Password Fri Feb 26 09:09:20 2016 : Debug: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: Parsed xlat tree: Fri Feb 26 09:09:20 2016 : Debug: literal --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = ' Fri Feb 26 09:09:20 2016 : Debug: attribute --> SQL-Group Fri Feb 26 09:09:20 2016 : Debug: literal --> ' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: EXPAND SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{SQL-Group}' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: --> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'HP-Procurve-Switch' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Executing select query: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'HP-Procurve-Switch' ORDER BY id Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Group "HP-Procurve-Switch": Merging reply items Fri Feb 26 09:09:20 2016 : Debug: (1) sql: Service-Type = Administrative-User Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: FROM 1 TO 0 MAX 1 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: Examining Service-Type Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: APPENDING Service-Type FROM 0 TO 0 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ::: TO in 0 out 0 Fri Feb 26 09:09:20 2016 : Debug: (1) sql: ... falling-through to profile processing Fri Feb 26 09:09:20 2016 : Debug: rlm_sql (sql): Released connection (1) Fri Feb 26 09:09:20 2016 : Info: rlm_sql (sql): Need 4 more connections to reach 10 spares Fri Feb 26 09:09:20 2016 : Info: rlm_sql (sql): Opening additional connection (6), 1 of 26 pending slots used Fri Feb 26 09:09:20 2016 : Debug: rlm_sql_mysql: Starting connect to MySQL server Fri Feb 26 09:09:20 2016 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 5.5.47-0ubuntu0.14.04.1, protocol version 10 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from sql (rlm_sql) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [sql] = ok Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling expiration (rlm_expiration) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from expiration (rlm_expiration) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [expiration] = noop Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling logintime (rlm_logintime) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from logintime (rlm_logintime) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [logintime] = noop Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: calling pap (rlm_pap) for request 1 Fri Feb 26 09:09:20 2016 : WARNING: (1) pap: Auth-Type already set. Not setting to PAP Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authorize]: returned from pap (rlm_pap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [pap] = noop Fri Feb 26 09:09:20 2016 : Debug: (1) } # authorize = updated Fri Feb 26 09:09:20 2016 : Debug: (1) Found Auth-Type = EAP Fri Feb 26 09:09:20 2016 : Debug: (1) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (1) authenticate { Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authenticate]: calling eap (rlm_eap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Expiring EAP session with state 0x49d1e9bb49d0ed66 Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Finished EAP session with state 0x49d1e9bb49d0ed66 Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Previous EAP request found for state 0x49d1e9bb49d0ed66, released from the list Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Peer sent packet with method EAP NAK (3) Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Found mutually acceptable type PEAP (25) Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Calling submodule eap_peap to process data Fri Feb 26 09:09:20 2016 : Debug: (1) eap_peap: Initiating new EAP-TLS session Fri Feb 26 09:09:20 2016 : Debug: (1) eap_peap: Flushing SSL sessions (of #0) Fri Feb 26 09:09:20 2016 : Debug: (1) eap_peap: [eaptls start] = request Fri Feb 26 09:09:20 2016 : Debug: (1) eap: Sending EAP Request (code 1) ID 2 length 6 Fri Feb 26 09:09:20 2016 : Debug: (1) eap: EAP session adding &reply:State = 0x49d1e9bb48d3f066 Fri Feb 26 09:09:20 2016 : Debug: (1) modsingle[authenticate]: returned from eap (rlm_eap) for request 1 Fri Feb 26 09:09:20 2016 : Debug: (1) [eap] = handled Fri Feb 26 09:09:20 2016 : Debug: (1) } # authenticate = handled Fri Feb 26 09:09:20 2016 : Debug: (1) Using Post-Auth-Type Challenge Fri Feb 26 09:09:20 2016 : Debug: (1) Post-Auth-Type sub-section not found. Ignoring. Fri Feb 26 09:09:20 2016 : Debug: (1) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (1) session-state: Nothing to cache Fri Feb 26 09:09:20 2016 : Debug: (1) Sent Access-Challenge Id 95 from 192.168.1.65:1812 to 192.168.6.211:1812 length 0 Fri Feb 26 09:09:20 2016 : Debug: (1) Service-Type = Administrative-User Fri Feb 26 09:09:20 2016 : Debug: (1) EAP-Message = 0x010200061920 Fri Feb 26 09:09:20 2016 : Debug: (1) Message-Authenticator = 0x00000000000000000000000000000000 Fri Feb 26 09:09:20 2016 : Debug: (1) State = 0x49d1e9bb48d3f06604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (1) Finished request Fri Feb 26 09:09:20 2016 : Debug: Waking up in 4.9 seconds. Fri Feb 26 09:09:20 2016 : Debug: (2) Received Access-Request Id 96 from 192.168.6.211:1812 to 192.168.1.65:1812 length 211 Fri Feb 26 09:09:20 2016 : Debug: (2) User-Name = "test" Fri Feb 26 09:09:20 2016 : Debug: (2) NAS-IP-Address = 211.6.168.192 Fri Feb 26 09:09:20 2016 : Debug: (2) NAS-Identifier = "SWITCH01-TEST" Fri Feb 26 09:09:20 2016 : Debug: (2) NAS-Port-Type = Virtual Fri Feb 26 09:09:20 2016 : Debug: (2) Service-Type = NAS-Prompt-User Fri Feb 26 09:09:20 2016 : Debug: (2) State = 0x49d1e9bb48d3f06604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (2) EAP-Message = 0x020200561900160303004b010000470303f469e888bc5f0be285d0034944e649c51126cce388e1c602d6e68b3d32077ec600000c003d0035003c002f000a000901000012000d000e000c060105010401030102010101 Fri Feb 26 09:09:20 2016 : Debug: (2) Message-Authenticator = 0x2ce1bdbb10507e63da3523deaea3b9ac Fri Feb 26 09:09:20 2016 : Debug: (2) MS-RAS-Vendor = 184549376 Fri Feb 26 09:09:20 2016 : Debug: (2) Calling-Station-Id = "192.168.14.114" Fri Feb 26 09:09:20 2016 : Debug: (2) session-state: No cached attributes Fri Feb 26 09:09:20 2016 : Debug: (2) # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (2) authorize { Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) [preprocess] = ok Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: calling chap (rlm_chap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: returned from chap (rlm_chap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) [chap] = noop Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: calling mschap (rlm_mschap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: returned from mschap (rlm_mschap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) [mschap] = noop Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: calling digest (rlm_digest) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: returned from digest (rlm_digest) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) [digest] = noop Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: calling suffix (rlm_realm) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) suffix: Checking for suffix after "@" Fri Feb 26 09:09:20 2016 : Debug: (2) suffix: No '@' in User-Name = "test", looking up realm NULL Fri Feb 26 09:09:20 2016 : Debug: (2) suffix: No such realm "NULL" Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: returned from suffix (rlm_realm) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) [suffix] = noop Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Peer sent EAP Response (code 2) ID 2 length 86 Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Continuing tunnel setup Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) [eap] = ok Fri Feb 26 09:09:20 2016 : Debug: (2) } # authorize = ok Fri Feb 26 09:09:20 2016 : Debug: (2) Found Auth-Type = EAP Fri Feb 26 09:09:20 2016 : Debug: (2) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (2) authenticate { Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authenticate]: calling eap (rlm_eap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Expiring EAP session with state 0x49d1e9bb48d3f066 Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Finished EAP session with state 0x49d1e9bb48d3f066 Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Previous EAP request found for state 0x49d1e9bb48d3f066, released from the list Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Peer sent packet with method EAP PEAP (25) Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Calling submodule eap_peap to process data Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: Continuing EAP-TLS Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: Peer sent flags --- Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: [eaptls verify] = ok Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: Done initial handshake Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: (other): before/accept initialization Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: before/accept initialization Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: <<< TLS 1.2 [length 004b] Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: SSLv3 read client hello A Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: >>> TLS 1.2 [length 004a] Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: SSLv3 write server hello A Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: >>> TLS 1.2 [length 08d3] Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: SSLv3 write certificate A Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: >>> TLS 1.2 [length 0004] Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: SSLv3 write server done A Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: SSLv3 flush data Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: TLS_accept: Need to read more data: SSLv3 read client certificate A Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: In SSL Handshake Phase Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: In SSL Accept mode Fri Feb 26 09:09:20 2016 : Debug: (2) eap_peap: [eaptls process] = handled Fri Feb 26 09:09:20 2016 : Debug: (2) eap: Sending EAP Request (code 1) ID 3 length 1004 Fri Feb 26 09:09:20 2016 : Debug: (2) eap: EAP session adding &reply:State = 0x49d1e9bb4bd2f066 Fri Feb 26 09:09:20 2016 : Debug: (2) modsingle[authenticate]: returned from eap (rlm_eap) for request 2 Fri Feb 26 09:09:20 2016 : Debug: (2) [eap] = handled Fri Feb 26 09:09:20 2016 : Debug: (2) } # authenticate = handled Fri Feb 26 09:09:20 2016 : Debug: (2) Using Post-Auth-Type Challenge Fri Feb 26 09:09:20 2016 : Debug: (2) Post-Auth-Type sub-section not found. Ignoring. Fri Feb 26 09:09:20 2016 : Debug: (2) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (2) session-state: Nothing to cache Fri Feb 26 09:09:20 2016 : Debug: (2) Sent Access-Challenge Id 96 from 192.168.1.65:1812 to 192.168.6.211:1812 length 0 Fri Feb 26 09:09:20 2016 : Debug: (2) EAP-Message = 0x010303ec19c000000930160303004a02000046030354fe36731b467feb5884257e28f240b1ec929d24c9e32152f69a15b29383707a200887f19083730e7634c25242b95cf3766946898850934650cbef5fdc96063735003d0016030308d30b0008cf0008cc0003de308203da308202c2a0030201020201 Fri Feb 26 09:09:20 2016 : Debug: (2) Message-Authenticator = 0x00000000000000000000000000000000 Fri Feb 26 09:09:20 2016 : Debug: (2) State = 0x49d1e9bb4bd2f06604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (2) Finished request Fri Feb 26 09:09:20 2016 : Debug: Waking up in 4.9 seconds. Fri Feb 26 09:09:20 2016 : Debug: (3) Received Access-Request Id 97 from 192.168.6.211:1812 to 192.168.1.65:1812 length 131 Fri Feb 26 09:09:20 2016 : Debug: (3) User-Name = "test" Fri Feb 26 09:09:20 2016 : Debug: (3) NAS-IP-Address = 211.6.168.192 Fri Feb 26 09:09:20 2016 : Debug: (3) NAS-Identifier = "SWITCH01-TEST" Fri Feb 26 09:09:20 2016 : Debug: (3) NAS-Port-Type = Virtual Fri Feb 26 09:09:20 2016 : Debug: (3) Service-Type = NAS-Prompt-User Fri Feb 26 09:09:20 2016 : Debug: (3) State = 0x49d1e9bb4bd2f06604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (3) EAP-Message = 0x020300061900 Fri Feb 26 09:09:20 2016 : Debug: (3) Message-Authenticator = 0x0b12f8d3e8972bbd6ac1b77f1e73f4da Fri Feb 26 09:09:20 2016 : Debug: (3) MS-RAS-Vendor = 184549376 Fri Feb 26 09:09:20 2016 : Debug: (3) Calling-Station-Id = "192.168.14.114" Fri Feb 26 09:09:20 2016 : Debug: (3) session-state: No cached attributes Fri Feb 26 09:09:20 2016 : Debug: (3) # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (3) authorize { Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) [preprocess] = ok Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: calling chap (rlm_chap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: returned from chap (rlm_chap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) [chap] = noop Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: calling mschap (rlm_mschap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: returned from mschap (rlm_mschap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) [mschap] = noop Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: calling digest (rlm_digest) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: returned from digest (rlm_digest) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) [digest] = noop Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: calling suffix (rlm_realm) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) suffix: Checking for suffix after "@" Fri Feb 26 09:09:20 2016 : Debug: (3) suffix: No '@' in User-Name = "test", looking up realm NULL Fri Feb 26 09:09:20 2016 : Debug: (3) suffix: No such realm "NULL" Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: returned from suffix (rlm_realm) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) [suffix] = noop Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: calling eap (rlm_eap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Peer sent EAP Response (code 2) ID 3 length 6 Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Continuing tunnel setup Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authorize]: returned from eap (rlm_eap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) [eap] = ok Fri Feb 26 09:09:20 2016 : Debug: (3) } # authorize = ok Fri Feb 26 09:09:20 2016 : Debug: (3) Found Auth-Type = EAP Fri Feb 26 09:09:20 2016 : Debug: (3) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (3) authenticate { Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authenticate]: calling eap (rlm_eap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Expiring EAP session with state 0x49d1e9bb4bd2f066 Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Finished EAP session with state 0x49d1e9bb4bd2f066 Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Previous EAP request found for state 0x49d1e9bb4bd2f066, released from the list Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Peer sent packet with method EAP PEAP (25) Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Calling submodule eap_peap to process data Fri Feb 26 09:09:20 2016 : Debug: (3) eap_peap: Continuing EAP-TLS Fri Feb 26 09:09:20 2016 : Debug: (3) eap_peap: Peer sent flags --- Fri Feb 26 09:09:20 2016 : Debug: (3) eap_peap: Peer ACKed our handshake fragment Fri Feb 26 09:09:20 2016 : Debug: (3) eap_peap: [eaptls verify] = request Fri Feb 26 09:09:20 2016 : Debug: (3) eap_peap: [eaptls process] = handled Fri Feb 26 09:09:20 2016 : Debug: (3) eap: Sending EAP Request (code 1) ID 4 length 1000 Fri Feb 26 09:09:20 2016 : Debug: (3) eap: EAP session adding &reply:State = 0x49d1e9bb4ad5f066 Fri Feb 26 09:09:20 2016 : Debug: (3) modsingle[authenticate]: returned from eap (rlm_eap) for request 3 Fri Feb 26 09:09:20 2016 : Debug: (3) [eap] = handled Fri Feb 26 09:09:20 2016 : Debug: (3) } # authenticate = handled Fri Feb 26 09:09:20 2016 : Debug: (3) Using Post-Auth-Type Challenge Fri Feb 26 09:09:20 2016 : Debug: (3) Post-Auth-Type sub-section not found. Ignoring. Fri Feb 26 09:09:20 2016 : Debug: (3) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (3) session-state: Nothing to cache Fri Feb 26 09:09:20 2016 : Debug: (3) Sent Access-Challenge Id 97 from 192.168.1.65:1812 to 192.168.6.211:1812 length 0 Fri Feb 26 09:09:20 2016 : Debug: (3) EAP-Message = 0x010403e8194037f46e0cd6a1c7903aa76984aa8740c82df8d7e54ac0028e4acb7016fb031b9e8d801916efbc80b0502432c9edfe776560ac6860c8c92f7dcc0602db1761dd3cdeedc764a04c9323ec69c92a4cae841cb61bfcde2132df31e7d70004e8308204e4308203cca0030201020209008811b646 Fri Feb 26 09:09:20 2016 : Debug: (3) Message-Authenticator = 0x00000000000000000000000000000000 Fri Feb 26 09:09:20 2016 : Debug: (3) State = 0x49d1e9bb4ad5f06604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (3) Finished request Fri Feb 26 09:09:20 2016 : Debug: Waking up in 4.9 seconds. Fri Feb 26 09:09:20 2016 : Debug: (4) Received Access-Request Id 98 from 192.168.6.211:1812 to 192.168.1.65:1812 length 131 Fri Feb 26 09:09:20 2016 : Debug: (4) User-Name = "test" Fri Feb 26 09:09:20 2016 : Debug: (4) NAS-IP-Address = 211.6.168.192 Fri Feb 26 09:09:20 2016 : Debug: (4) NAS-Identifier = "SWITCH01-TEST" Fri Feb 26 09:09:20 2016 : Debug: (4) NAS-Port-Type = Virtual Fri Feb 26 09:09:20 2016 : Debug: (4) Service-Type = NAS-Prompt-User Fri Feb 26 09:09:20 2016 : Debug: (4) State = 0x49d1e9bb4ad5f06604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (4) EAP-Message = 0x020400061900 Fri Feb 26 09:09:20 2016 : Debug: (4) Message-Authenticator = 0x2b99fbc2e77e6ad0efb2e85b90a62f18 Fri Feb 26 09:09:20 2016 : Debug: (4) MS-RAS-Vendor = 184549376 Fri Feb 26 09:09:20 2016 : Debug: (4) Calling-Station-Id = "192.168.14.114" Fri Feb 26 09:09:20 2016 : Debug: (4) session-state: No cached attributes Fri Feb 26 09:09:20 2016 : Debug: (4) # Executing section authorize from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (4) authorize { Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) [preprocess] = ok Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: calling chap (rlm_chap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: returned from chap (rlm_chap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) [chap] = noop Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: calling mschap (rlm_mschap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: returned from mschap (rlm_mschap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) [mschap] = noop Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: calling digest (rlm_digest) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: returned from digest (rlm_digest) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) [digest] = noop Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: calling suffix (rlm_realm) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) suffix: Checking for suffix after "@" Fri Feb 26 09:09:20 2016 : Debug: (4) suffix: No '@' in User-Name = "test", looking up realm NULL Fri Feb 26 09:09:20 2016 : Debug: (4) suffix: No such realm "NULL" Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: returned from suffix (rlm_realm) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) [suffix] = noop Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: calling eap (rlm_eap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Peer sent EAP Response (code 2) ID 4 length 6 Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Continuing tunnel setup Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authorize]: returned from eap (rlm_eap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) [eap] = ok Fri Feb 26 09:09:20 2016 : Debug: (4) } # authorize = ok Fri Feb 26 09:09:20 2016 : Debug: (4) Found Auth-Type = EAP Fri Feb 26 09:09:20 2016 : Debug: (4) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (4) authenticate { Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authenticate]: calling eap (rlm_eap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Expiring EAP session with state 0x49d1e9bb4ad5f066 Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Finished EAP session with state 0x49d1e9bb4ad5f066 Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Previous EAP request found for state 0x49d1e9bb4ad5f066, released from the list Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Peer sent packet with method EAP PEAP (25) Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Calling submodule eap_peap to process data Fri Feb 26 09:09:20 2016 : Debug: (4) eap_peap: Continuing EAP-TLS Fri Feb 26 09:09:20 2016 : Debug: (4) eap_peap: Peer sent flags --- Fri Feb 26 09:09:20 2016 : Debug: (4) eap_peap: Peer ACKed our handshake fragment Fri Feb 26 09:09:20 2016 : Debug: (4) eap_peap: [eaptls verify] = request Fri Feb 26 09:09:20 2016 : Debug: (4) eap_peap: [eaptls process] = handled Fri Feb 26 09:09:20 2016 : Debug: (4) eap: Sending EAP Request (code 1) ID 5 length 370 Fri Feb 26 09:09:20 2016 : Debug: (4) eap: EAP session adding &reply:State = 0x49d1e9bb4dd4f066 Fri Feb 26 09:09:20 2016 : Debug: (4) modsingle[authenticate]: returned from eap (rlm_eap) for request 4 Fri Feb 26 09:09:20 2016 : Debug: (4) [eap] = handled Fri Feb 26 09:09:20 2016 : Debug: (4) } # authenticate = handled Fri Feb 26 09:09:20 2016 : Debug: (4) Using Post-Auth-Type Challenge Fri Feb 26 09:09:20 2016 : Debug: (4) Post-Auth-Type sub-section not found. Ignoring. Fri Feb 26 09:09:20 2016 : Debug: (4) # Executing group from file /etc/freeradius/sites-enabled/default Fri Feb 26 09:09:20 2016 : Debug: (4) session-state: Nothing to cache Fri Feb 26 09:09:20 2016 : Debug: (4) Sent Access-Challenge Id 98 from 192.168.1.65:1812 to 192.168.6.211:1812 length 0 Fri Feb 26 09:09:20 2016 : Debug: (4) EAP-Message = 0x010501721900b646e6d0eb27300f0603551d130101ff040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e6f72672f6578616d706c655f63612e63726c300d06092a864886f70d01010b050003820101004e489dea74691aee9abfa8bd8500 Fri Feb 26 09:09:20 2016 : Debug: (4) Message-Authenticator = 0x00000000000000000000000000000000 Fri Feb 26 09:09:20 2016 : Debug: (4) State = 0x49d1e9bb4dd4f06604270874f25476f7 Fri Feb 26 09:09:20 2016 : Debug: (4) Finished request Fri Feb 26 09:09:20 2016 : Debug: Waking up in 4.9 seconds. Fri Feb 26 09:09:25 2016 : Debug: (0) Cleaning up request packet ID 94 with timestamp +8 Fri Feb 26 09:09:25 2016 : Debug: (1) Cleaning up request packet ID 95 with timestamp +8 Fri Feb 26 09:09:25 2016 : Debug: (2) Cleaning up request packet ID 96 with timestamp +8 Fri Feb 26 09:09:25 2016 : Debug: (3) Cleaning up request packet ID 97 with timestamp +8 Fri Feb 26 09:09:25 2016 : Debug: (4) Cleaning up request packet ID 98 with timestamp +8 Fri Feb 26 09:09:25 2016 : Info: Ready to process requests Can anyone help me? Best regards jonas

3 15

Re: Upgrading FreeRadius / MSSQL
by Richard J Palmer 29 Feb '16

29 Feb '16

Thanks Alan One small further question if I may. FR (using freetds) is currently set against a single mssql server. We are currently setting a second SQL server to allow failover in the case of a server failure. I assume we can run two freetds modules to allow freeradius to failover OK ? I shall be building a test server here the next few days. Should I take the latest .tar from the website or download from git ? Thanks again Richard Palmer | Director | Merula Limited Company Registered in England and Wales No. 3243995 5 Avro Court, Huntingdon, Cambridgeshire, PE29 6XS Phone 01480 222940 | Support 0845 330 0666 Support Email support(a)merula.net > --- Original message --- > Subject: Re: Upgrading FreeRadius / MSSQL > From: <A.L.M.Buxey(a)lboro.ac.uk> > To: FreeRadius users mailing list > <freeradius-users(a)lists.freeradius.org> > Date: Monday, 29/02/2016 10:22 AM > > Hi, > >> >> Taking a look at http://wiki.freeradius.org/modules/Rlm_sql I can >> see that there are 3 possible drivers mentioned for use with mssql - >> We are currently using freetds - however the site mentions: > > I'd say stick with the FreeTDS method if you are happy with it and > your config > is currently using it - the ODBC one adds extra elements/dependencies > into the mix - and you may have extra work to do (not just the local > FR configuration). > > alan > - > List info/subscribe/unsubscribe? See > http://www.freeradius.org/list/users.html

3 2

Upgrading FreeRadius / MSSQL
by Richard J Palmer 29 Feb '16

29 Feb '16

Hi All I am after a little advice if I may as we upgrade our FreeRadius Servers here. For long and complicated reasons the backed database is on a MSSQL Server rather than mysql etc. We are currently using the very old 2.1.x server (which works BUT I know is rather old in the tooth) but moving to the latest 3.1 release. However I have a quick question before I start the process. Taking a look at http://wiki.freeradius.org/modules/Rlm_sql I can see that there are 3 possible drivers mentioned for use with mssql - We are currently using freetds - however the site mentions: rlm_sql_freetds - FreeTDS (mssql) rlm_sql_sybase - Sybase (mssql) rlm_sql_unixodbc - unixODBC (mssql) As possibly suitable - is there a current 'preference' ? If it makes any difference I am hoping to set up failover between two mssql servers - one as primary the other for IF the primary server fails Thanks in advance Richard Palmer

3 2

Re: acct_unique problem
by Viana 28 Feb '16

28 Feb '16

Hello Alan. Thanks for you reply. As you said, I did this modification into sites-available/default file: preacct { "%{NAS-Port}" if (outer.request) { update request { NAS-Port := &NAS-Port } } ... Here is the log file: (0) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (0) preacct { (0) EXPAND %{NAS-Port} (0) --> 0 (0) if (outer.request) { (0) if (outer.request) -> TRUE (0) if (outer.request) { (0) update request { (0) NAS-Port := &NAS-Port -> 0 (0) } # update request = noop (0) } # if (outer.request) = noop The problem is that NAS-Port is 0 (zero) when the request enters preacct, and setting NAS-Port := &NAS-Port inside preacct is taking the zero value. Is it possible to set a temporary variable berfore preacct and use this value inside? Something like this: NAS-Port_temp := &NAS-Port (before preacct) And inside preacct: if (outer.request) { update request { NAS-Port := &NAS-Port_temp } } If it´s possible, where can I set NAS-Port_temp to be used by preacct later? Did you find the solution to this issue for newer versions of FreeRadius? Thanks again! Regards Fabricio --- Este email foi escaneado pelo Avast antivírus. http://www.avast.com

1 0

how to test CHAP authentication with radtest/radclient
by Michael Martinez 28 Feb '16

28 Feb '16

I'm running freeradius-3.0.11. I've got a test user configured in the local unix system, and PAP authentication works. I'm trying to test it with CHAP (for educational purposes). First I run radtest: radtest -t chap test4 testing4 127.0.0.1 0 xxxxx (7) Login incorrect (chap: &control:Cleartext-Password is required for authentication): [test4/<CHAP-Password>] (from client localhost port 0) Then I try radclient: echo "User-Name=test4,Cleartext-Password=testing4,Chap-Password=testing4" | radclient 127.0.0.1 auth hello I tried this latter one with different combinations of "User-Password", "CHAP-Password" and "Cleartext-Password" but they all result in the same error seen below: (11) Found Auth-Type = CHAP (11) # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/default (11) Auth-Type CHAP { (11) chap: ERROR: &control:Cleartext-Password is required for authentication (11) [chap] = fail (11) } # Auth-Type CHAP = fail (11) Failed to authenticate the user (11) Login incorrect (chap: &control:Cleartext-Password is required for authentication): [test4/<CHAP-Password>] (from client localhost port 0) I can't tell whether I'm running the tests incorrectly or I've got the server set up incorrectly (I suspect it's the former.) -- --- Michael Martinez http://www.michael--martinez.com

1 1

PPA stable 3.x plans for Ubuntu 16.04?
by Lovaas,Steven 27 Feb '16

27 Feb '16

I'm looking at upgrading from 2.x to 3, but wonder if a new stable build is coming soon. Are there plans to have the PPA updated soon after the release of 16.04? Thanks! Steve

3 2