- Freeradius-Users - lists.freeradius.org

FreeRADIUS w/ LDAP and EAP-TLS
by Andrew Meyer 15 Dec '17

15 Dec '17

So yesterday after complicating my configuration I decided to completely start over. I rebuilt the server and got everything work up to the EAP-TLS. While it is clear that it says no "known good" password found, I was able to auth to LDAP prior to turning on EAP-TLS. So I suspect there is something else that I am missing. I am using the certificates that came w/ FreeRADIUS in the /etc/raddb/certs/ folder. I will be generating my own or applying ones from FreeIPA once I get this working. I followed this: http://deployingradius.com/documents/configuration/eap.html https://wiki.alpinelinux.org/wiki/FreeRadius_EAP-TLS_configuration Here is the output from debug: (2) control:Auth-Type := LDAP (2) } # update = noop (2) } # if ((ok || updated) && User-Password) = noop (2) [expiration] = noop (2) [logintime] = noop (2) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (2) pap: WARNING: Authentication will fail unless a "known good" password is available (2) [pap] = noop (2) } # authorize = ok (2) Found Auth-Type = LDAP (2) # Executing group from file /etc/raddb/sites-enabled/default (2) Auth-Type LDAP { rlm_ldap (ldap): Reserved connection (6) (2) ldap: Login attempt by "andrew.meyer" (2) ldap: Using user DN from request "uid=andrew.meyer,cn=users,cn=accounts,dc=meyer,dc=local" (2) ldap: Waiting for bind result... (2) ldap: Bind successful (2) ldap: Bind as user "uid=andrew.meyer,cn=users,cn=accounts,dc=meyer,dc=local" was successful rlm_ldap (ldap): Released connection (6) (2) [ldap] = ok (2) } # Auth-Type LDAP = ok (2) # Executing section post-auth from file /etc/raddb/sites-enabled/default (2) post-auth { (2) update { (2) No attributes updated (2) } # update = noop (2) [exec] = noop (2) policy remove_reply_message_if_eap { (2) if (&reply:EAP-Message && &reply:Reply-Message) { (2) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (2) else { (2) [noop] = noop (2) } # else = noop (2) } # policy remove_reply_message_if_eap = noop (2) } # post-auth = noop (2) Sent Access-Accept Id 16 from 10.150.10.45:1812 to 10.150.1.250:53618 length 0 (2) Finished request Waking up in 1.0 seconds. (1) Cleaning up request packet ID 15 with timestamp +68 Waking up in 3.9 seconds. (2) Cleaning up request packet ID 16 with timestamp +72 Ready to process requests

2 1

linelog module and logs on multiple lines
by Jérôme BERTHIER 15 Dec '17

15 Dec '17

Hello I used to write specific logs using linelog module : Access-Request = "%S\nPacket-Type = %{reply:Packet-Type} \n\tUser-Name = %{User-Name} \n\tCalling-Station-Id = %{Calling-station-Id} \n\tNAS-IP-Address = %{NAS-IP-Address} \n\tNAS-Port = %{NAS-Port} \n\tCalled-Station-Id = %{Called-Station-Id} \n\tClient-IP-Address = %{Client-IP-Address}" Since an upgrade to freeradius 3.0.13, the log is written on one single line and the characters \n\t are not interpreted. Is it related to the new behavior with "correct_escapes = true" ? Is there any trick to write logs on multiple lines ? Regards, -- Jérôme BERTHIER

2 2

Python Module with FreeRADIUS 3.0.15
by Gary Gwin 14 Dec '17

14 Dec '17

Trying to implement just the basic Python example as documented is not working with the FreeRADIUS 3.0.15 build on Unbuntu 14.04. After enabling and running "freeradius -X", FreeRADIUS exits with only this: # Instantiating module "python" from file /etc/freeradius/mods-enabled/python Python version: 2.7.6 (default, Oct 26 2016, 20:33:43) [GCC 4.8.4] Other than enabling the the python module, the only other change was to enable the python_path and uncomment the "func_authorize = authorize" line in mods-available/python. The example.pyc is not created. Everything was working swimmingly under FreeRADIUS 3.0.12. Any ideas? Thanks, Gary

3 5

Re: winbindd_priv dont exist
by Alan Buxey 14 Dec '17

14 Dec '17

Hi Hi, yes i do it, and the administrator is administrator Then why are you using 'administraor' ?? alan

2 1

groupname not coming in the radacct table
by J E H A N Z A I B 14 Dec '17

14 Dec '17

Hi folks, I am running *FreeRADIUS 3.0.13 *and missing the groupname in the radacct table. Apart from groupname everything else seems to be working fine. Any idea how can i add it ? I dont think i can add into the account insert insert query. but i tried it and its empty there as well. i tried in /etc/raddb/mods-config/sql/main/mysql/queries.conf

2 7

Outer User-Name is not anonymized
by Vieri 14 Dec '17

14 Dec '17

Hi, I'd like to know why FR thinks that the outer User-Name is not anonymized when a Windows client connects with supposedly anonymized identity (blank or 'anon'). Is it because the domain part is always passed even if the user is blank? Does it all rely on the filter_inner_identity function in policy.d? If that's the case then this function expects @ as the user/domain seperator. Windows clients send \ as the seperator. So I guess I can either ignore the warning or change the function. (8) Received Access-Request Id 0 from 10.215.147.140:49154 to 10.215.144.91:1812 length 147 (8) NAS-IP-Address = 10.215.147.140 (8) NAS-Port-Type = Ethernet (8) NAS-Port = 43 (8) User-Name = "DOMAIN\\" (8) State = 0x8f4c1991884500fd085fc9de274e79da (8) Calling-Station-Id = "DC-4A-3E-06-11-46" [...] (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "DOMAIN\", looking up realm NULL (8) suffix: No such realm "NULL" (8) [suffix] = noop (8) ntdomain: Checking for prefix before "\" (8) ntdomain: Looking up realm "DOMAIN" for User-Name = "DOMAIN\" (8) ntdomain: No such realm "DOMAIN" (8) [ntdomain] = noop (8) [expiration] = noop (8) [logintime] = noop (8) } # authorize = updated (8) Found Auth-Type = eap (8) # Executing group from file /etc/raddb/sites-enabled/default (8) authenticate { (8) eap: Expiring EAP session with state 0x052a3c3004232630 (8) eap: Finished EAP session with state 0x8f4c1991884500fd (8) eap: Previous EAP request found for state 0x8f4c1991884500fd, released from the list (8) eap: Peer sent packet with method EAP PEAP (25) (8) eap: Calling submodule eap_peap to process data (8) eap_peap: Continuing EAP-TLS (8) eap_peap: [eaptls verify] = ok (8) eap_peap: Done initial handshake (8) eap_peap: [eaptls process] = ok (8) eap_peap: Session established. Decoding tunneled attributes (8) eap_peap: PEAP state phase2 (8) eap_peap: EAP method MSCHAPv2 (26) (8) eap_peap: Got tunneled request (8) eap_peap: EAP-Message = 0x020900061a03 (8) eap_peap: Setting User-Name to DOMAIN\adminpc (8) eap_peap: Sending tunneled request to inner-tunnel (8) eap_peap: EAP-Message = 0x020900061a03 (8) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (8) eap_peap: User-Name = "DOMAIN\\adminpc" (8) eap_peap: State = 0x052a3c3004232630e22377547b424230 (8) Virtual server inner-tunnel received request (8) EAP-Message = 0x020900061a03 (8) FreeRADIUS-Proxied-To = 127.0.0.1 (8) User-Name = "DOMAIN\\adminpc" (8) State = 0x052a3c3004232630e22377547b424230 (8) WARNING: Outer User-Name is not anonymized. User privacy is compromised. Thanks, Vieri

2 1

dot1x PEAPoMSChapv2 timers
by 3＠D4rkn3ss DuMb 14 Dec '17

14 Dec '17

Dear list, First, I must say that FreeRadius is in my humble opinion, the best open source project out there: top dev team, well documented, proactive mailing list, and above all, you can find it anywhere inside the security vendors solutions ... and that's a few of the advantages. I had to get that out of my chest before anything ... so Thank you for all the devs out there, for the idea and for making such a beautiful, stable and strong product ! I really hope that I would be able to contribute one day, even if its for the documentation since I m not good at coding :) Here come worries: I have setup inside 4 different companies a 802.1X solution (of course based on FreeRadius) and everything is working like a charm, (FreeRADIUS v 3.0.14) but in one of the secondary server (the main and the backup is linked through UCARP VRRP) which is currently serving around 400 supplicants, it is dropping the clients (randomly) after a timeout. below the setup (simple enough): FreeRADIUS authenticates the client (supplicants) to the AD, then verifies if its MAC address is authorized to connect or not. I suspect that is related to the following: Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: EXPAND --nt-response=%{%{mschap:NT-Response}:-00} Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: --> --nt-response= ebe1377d01d09cbe0bfda9256149732ec2b94b30d4cbc327 Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.4 seconds. Wed Dec 13 16:39:53 2017 : Debug: Waking up in 0.7 seconds. Wed Dec 13 16:39:53 2017 : Debug: Waking up in 1.1 seconds. But I am not sure. If the above is however correct, does it mean that it is waiting for the AD to reply or is it just misbehaving ? Please find below the full log for your reference. Wed Dec 13 16:37:53 2017 : Debug: (57) Cleaning up request packet ID 238 with timestamp +1892 Wed Dec 13 16:37:53 2017 : Debug: (58) Cleaning up request packet ID 239 with timestamp +1892 Wed Dec 13 16:37:53 2017 : Debug: (59) Cleaning up request packet ID 240 with timestamp +1892 Wed Dec 13 16:37:53 2017 : Debug: (60) Cleaning up request packet ID 241 with timestamp +1892 Wed Dec 13 16:37:53 2017 : Debug: (61) Cleaning up request packet ID 242 with timestamp +1892 Wed Dec 13 16:37:53 2017 : Debug: Waking up in 2.6 seconds. Wed Dec 13 16:37:55 2017 : Debug: (62) Cleaning up request packet ID 243 with timestamp +1892 Wed Dec 13 16:37:55 2017 : Debug: (63) Cleaning up request packet ID 244 with timestamp +1894 Wed Dec 13 16:37:55 2017 : Debug: (64) Cleaning up request packet ID 245 with timestamp +1894 Wed Dec 13 16:37:55 2017 : Info: Ready to process requests Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.3 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 4 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 4 handling request 66, (14 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (66) Received Access-Request Id 246 from 10.100.100.114:1645 to 192.168.10.13:1812 length 182 Wed Dec 13 16:39:52 2017 : Debug: (66) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (66) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (66) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (66) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (66) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (66) EAP-Message = 0x02e4001b01686f73742f6473696231303930322e62636d2e696e74 Wed Dec 13 16:39:52 2017 : Debug: (66) Message-Authenticator = 0x04fc640c7390637c2393ca8d33dd9bc1 Wed Dec 13 16:39:52 2017 : Debug: (66) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (66) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (66) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (66) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (66) session-state: No State attribute Wed Dec 13 16:39:52 2017 : Debug: (66) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (66) authorize { Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (66) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (66) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (66) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (66) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (66) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (66) update request { Wed Dec 13 16:39:52 2017 : Debug: (66) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (66) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (66) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (66) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (66) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (66) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (66) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (66) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (66) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (66) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (66) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (66) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (11): Hit idle_timeout, was idle for 124 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (18): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (20): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (19): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (16): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (14): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (13): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (17): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): You probably need to lower "min" Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (12): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): You probably need to lower "min" Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Closing connection (15): Hit idle_timeout, was idle for 122 seconds Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): You probably need to lower "min" Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Socket destructor called, closing socket Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): 0 of 0 connections in use. You may need to increase "spare" Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Opening additional connection (21), 1 of 32 pending slots used Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 10.1.23-MariaDB-9+deb9u1, protocol version 10 Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (66) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (66) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (66) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Info: Need 2 more connections to reach min connections (3) Wed Dec 13 16:39:52 2017 : Info: rlm_sql (sql): Opening additional connection (22), 1 of 31 pending slots used Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server Wed Dec 13 16:39:52 2017 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 10.1.23-MariaDB-9+deb9u1, protocol version 10 Wed Dec 13 16:39:52 2017 : Debug: (66) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (66) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (66) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (66) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (66) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (66) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (66) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (66) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (66) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (66) else { Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (66) eap: Peer sent EAP Response (code 2) ID 228 length 27 Wed Dec 13 16:39:52 2017 : Debug: (66) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (66) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (66) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (66) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (66) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (66) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (66) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (66) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (66) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (66) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (66) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (66) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (66) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (66) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (66) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (66) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (66) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (66) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (66) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (66) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (66) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (66) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (66) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (66) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (66) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (66) eap: Peer sent packet with method EAP Identity (1) Wed Dec 13 16:39:52 2017 : Debug: (66) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (66) eap_peap: Initiating new EAP-TLS session Wed Dec 13 16:39:52 2017 : Debug: (66) eap_peap: [eaptls start] = request Wed Dec 13 16:39:52 2017 : Debug: (66) eap: Sending EAP Request (code 1) ID 229 length 6 Wed Dec 13 16:39:52 2017 : Debug: (66) eap: EAP session adding &reply:State = 0xb2f1dd18b214c4f8 Wed Dec 13 16:39:52 2017 : Debug: (66) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (66) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (66) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (66) Using Post-Auth-Type Challenge Wed Dec 13 16:39:52 2017 : Debug: (66) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:52 2017 : Debug: (66) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (66) session-state: Nothing to cache Wed Dec 13 16:39:52 2017 : Debug: (66) Sent Access-Challenge Id 246 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:52 2017 : Debug: (66) EAP-Message = 0x01e500061920 Wed Dec 13 16:39:52 2017 : Debug: (66) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (66) State = 0xb2f1dd18b214c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (66) Finished request Wed Dec 13 16:39:52 2017 : Debug: Thread 4 waiting to be assigned a request Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.3 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 3 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 3 handling request 67, (14 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (67) Received Access-Request Id 247 from 10.100.100.114:1645 to 192.168.10.13:1812 length 314 Wed Dec 13 16:39:52 2017 : Debug: (67) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (67) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (67) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (67) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (67) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (67) EAP-Message = 0x02e5008d198000000083160301007e0100007a03015a312da838e7eb1277eaaa0fe2229f41baff2203ce5cf8f0da422f16716293f02090ca41f41126a4070993bf7e66c7af11671f312c47dfa47f49044b66fb877aad0018002f00350005000ac013c014c009c00a003200380013000401000019000a00 Wed Dec 13 16:39:52 2017 : Debug: (67) Message-Authenticator = 0xf634b9f7b146caf2075346e7d611b0df Wed Dec 13 16:39:52 2017 : Debug: (67) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (67) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (67) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (67) State = 0xb2f1dd18b214c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (67) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (67) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (67) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (67) authorize { Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (67) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (67) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (67) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (67) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (67) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (67) update request { Wed Dec 13 16:39:52 2017 : Debug: (67) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (67) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (67) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (67) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (67) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (67) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (67) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (67) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (67) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (67) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (67) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (67) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (67) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (67) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (67) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (67) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (67) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (67) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (67) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (67) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (67) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (67) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (67) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (67) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (67) else { Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Peer sent EAP Response (code 2) ID 229 length 141 Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Continuing tunnel setup Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (67) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (67) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (67) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (67) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (67) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (67) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (67) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (67) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (67) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (67) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (67) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (67) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (67) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (67) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (67) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (67) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (67) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (67) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (67) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (67) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (67) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (67) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (67) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (67) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Expiring EAP session with state 0xb2f1dd18b214c4f8 Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Finished EAP session with state 0xb2f1dd18b214c4f8 Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Previous EAP request found for state 0xb2f1dd18b214c4f8, released from the list Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: Peer sent flags --L Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: Peer indicated complete TLS record size will be 131 bytes Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: Got complete TLS record (131 bytes) Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: [eaptls verify] = length included Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: (other): before SSL initialization Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: TLS_accept: before SSL initialization Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: TLS_accept: before SSL initialization Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: <<< recv TLS 1.2 [length 007e] Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: TLS_accept: SSLv3/TLS read client hello Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: >>> send TLS 1.0 Handshake [length 0055], ServerHello Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: TLS_accept: SSLv3/TLS write server hello Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: >>> send TLS 1.0 Handshake [length 08da], Certificate Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: TLS_accept: SSLv3/TLS write certificate Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: >>> send TLS 1.0 Handshake [length 0004], ServerHelloDone Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: TLS_accept: SSLv3/TLS write server done Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: TLS_accept: Need to read more data: SSLv3/TLS write server done Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: In SSL Handshake Phase Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: In SSL Accept mode Wed Dec 13 16:39:52 2017 : Debug: (67) eap_peap: [eaptls process] = handled Wed Dec 13 16:39:52 2017 : Debug: (67) eap: Sending EAP Request (code 1) ID 230 length 1014 Wed Dec 13 16:39:52 2017 : Debug: (67) eap: EAP session adding &reply:State = 0xb2f1dd18b317c4f8 Wed Dec 13 16:39:52 2017 : Debug: (67) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (67) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (67) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (67) Using Post-Auth-Type Challenge Wed Dec 13 16:39:52 2017 : Debug: (67) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:52 2017 : Debug: (67) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (67) session-state: Nothing to cache Wed Dec 13 16:39:52 2017 : Debug: (67) Sent Access-Challenge Id 247 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:52 2017 : Debug: (67) EAP-Message = 0x01e603f619c0000009421603010055020000510301689a651941a5eb17ffc97c35e3d98edfef8bb6c4bc562ac4d3a5af00efaa4ca52095db7d9e2523aae891c1d018e9ed1044ea85ec6edaec542ec57336414956fad0002f000009ff010001000017000016030108da0b0008d60008d30003e2308203de Wed Dec 13 16:39:52 2017 : Debug: (67) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (67) State = 0xb2f1dd18b317c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (67) Finished request Wed Dec 13 16:39:52 2017 : Debug: Thread 3 waiting to be assigned a request Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.3 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 2 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 2 handling request 68, (14 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (68) Received Access-Request Id 248 from 10.100.100.114:1645 to 192.168.10.13:1812 length 179 Wed Dec 13 16:39:52 2017 : Debug: (68) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (68) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (68) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (68) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (68) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (68) EAP-Message = 0x02e600061900 Wed Dec 13 16:39:52 2017 : Debug: (68) Message-Authenticator = 0x089978e5410c85c595afe9a72f4c9187 Wed Dec 13 16:39:52 2017 : Debug: (68) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (68) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (68) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (68) State = 0xb2f1dd18b317c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (68) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (68) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (68) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (68) authorize { Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (68) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (68) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (68) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (68) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (68) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (68) update request { Wed Dec 13 16:39:52 2017 : Debug: (68) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (68) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (68) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (68) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (68) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (68) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (68) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (68) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (68) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (68) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (68) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (68) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (68) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (68) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (68) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (68) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (68) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (68) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (68) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (68) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (68) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (68) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (68) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (68) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (68) else { Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Peer sent EAP Response (code 2) ID 230 length 6 Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Continuing tunnel setup Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (68) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (68) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (68) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (68) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (68) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (68) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (68) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (68) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (68) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (68) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (68) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (68) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (68) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (68) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (68) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (68) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (68) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (68) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (68) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (68) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (68) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (68) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (68) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (68) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Expiring EAP session with state 0xb2f1dd18b317c4f8 Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Finished EAP session with state 0xb2f1dd18b317c4f8 Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Previous EAP request found for state 0xb2f1dd18b317c4f8, released from the list Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (68) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:52 2017 : Debug: (68) eap_peap: Peer sent flags --- Wed Dec 13 16:39:52 2017 : Debug: (68) eap_peap: Peer ACKed our handshake fragment Wed Dec 13 16:39:52 2017 : Debug: (68) eap_peap: [eaptls verify] = request Wed Dec 13 16:39:52 2017 : Debug: (68) eap_peap: [eaptls process] = handled Wed Dec 13 16:39:52 2017 : Debug: (68) eap: Sending EAP Request (code 1) ID 231 length 1010 Wed Dec 13 16:39:52 2017 : Debug: (68) eap: EAP session adding &reply:State = 0xb2f1dd18b016c4f8 Wed Dec 13 16:39:52 2017 : Debug: (68) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (68) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (68) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (68) Using Post-Auth-Type Challenge Wed Dec 13 16:39:52 2017 : Debug: (68) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:52 2017 : Debug: (68) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (68) session-state: Nothing to cache Wed Dec 13 16:39:52 2017 : Debug: (68) Sent Access-Challenge Id 248 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:52 2017 : Debug: (68) EAP-Message = 0x01e703f219402fd0040cc7a2836a3d5a9474629f257654ef4ae2e1aa2252a7cf7ad7ba7b88669dcd3e1d83545f01725b22bcf9611db89530220d34b7613c31723b148c10d512e6c3fc3b03a5fd663feb73996729bcb9317599a1532f494c64ceb1d42978530004eb308204e7308203cfa0030201020209 Wed Dec 13 16:39:52 2017 : Debug: (68) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (68) State = 0xb2f1dd18b016c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (68) Finished request Wed Dec 13 16:39:52 2017 : Debug: Thread 2 waiting to be assigned a request Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.2 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 1 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 1 handling request 69, (14 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (69) Received Access-Request Id 249 from 10.100.100.114:1645 to 192.168.10.13:1812 length 179 Wed Dec 13 16:39:52 2017 : Debug: (69) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (69) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (69) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (69) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (69) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (69) EAP-Message = 0x02e700061900 Wed Dec 13 16:39:52 2017 : Debug: (69) Message-Authenticator = 0xf29aeea458cb4107726abd1c6e709dad Wed Dec 13 16:39:52 2017 : Debug: (69) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (69) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (69) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (69) State = 0xb2f1dd18b016c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (69) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (69) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (69) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (69) authorize { Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (69) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (69) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (69) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (69) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (69) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (69) update request { Wed Dec 13 16:39:52 2017 : Debug: (69) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (69) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (69) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (69) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (69) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (69) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (69) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (69) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (69) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (69) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (69) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (69) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (69) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (69) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (69) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (69) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (69) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (69) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (69) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (69) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (69) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (69) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (69) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (69) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (69) else { Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Peer sent EAP Response (code 2) ID 231 length 6 Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Continuing tunnel setup Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (69) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (69) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (69) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (69) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (69) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (69) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (69) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (69) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (69) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (69) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (69) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (69) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (69) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (69) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (69) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (69) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (69) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (69) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (69) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (69) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (69) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (69) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (69) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (69) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Expiring EAP session with state 0xb2f1dd18b016c4f8 Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Finished EAP session with state 0xb2f1dd18b016c4f8 Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Previous EAP request found for state 0xb2f1dd18b016c4f8, released from the list Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (69) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:52 2017 : Debug: (69) eap_peap: Peer sent flags --- Wed Dec 13 16:39:52 2017 : Debug: (69) eap_peap: Peer ACKed our handshake fragment Wed Dec 13 16:39:52 2017 : Debug: (69) eap_peap: [eaptls verify] = request Wed Dec 13 16:39:52 2017 : Debug: (69) eap_peap: [eaptls process] = handled Wed Dec 13 16:39:52 2017 : Debug: (69) eap: Sending EAP Request (code 1) ID 232 length 368 Wed Dec 13 16:39:52 2017 : Debug: (69) eap: EAP session adding &reply:State = 0xb2f1dd18b119c4f8 Wed Dec 13 16:39:52 2017 : Debug: (69) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (69) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (69) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (69) Using Post-Auth-Type Challenge Wed Dec 13 16:39:52 2017 : Debug: (69) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:52 2017 : Debug: (69) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (69) session-state: Nothing to cache Wed Dec 13 16:39:52 2017 : Debug: (69) Sent Access-Challenge Id 249 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:52 2017 : Debug: (69) EAP-Message = 0x01e80170190024b44b9e300f0603551d130101ff040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e6f72672f6578616d706c655f63612e63726c300d06092a864886f70d01010b0500038201010008f415e3691f090f70e2a03127503e0d Wed Dec 13 16:39:52 2017 : Debug: (69) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (69) State = 0xb2f1dd18b119c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (69) Finished request Wed Dec 13 16:39:52 2017 : Debug: Thread 1 waiting to be assigned a request Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.2 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 5 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 5 handling request 70, (15 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (70) Received Access-Request Id 250 from 10.100.100.114:1645 to 192.168.10.13:1812 length 511 Wed Dec 13 16:39:52 2017 : Debug: (70) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (70) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (70) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (70) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (70) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (70) EAP-Message = 0x02e801501980000001461603010106100001020100eaef314b15e9bd4de9194789038a3fe2d488a349d02e6fe56721aa3d6ef8c0c66a59aed00c5e3df4fd312b0dcca1f0fc3a93d89bd3134b0905fa518d3622ce610ba422e9965aaa9d4b87a8180efb7d567874f40bc9276ed0750387c4f997f721e9e5 Wed Dec 13 16:39:52 2017 : Debug: (70) Message-Authenticator = 0x27e98b94cc274bf7fdad3396f2e191fe Wed Dec 13 16:39:52 2017 : Debug: (70) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (70) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (70) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (70) State = 0xb2f1dd18b119c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (70) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (70) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (70) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (70) authorize { Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (70) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (70) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (70) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (70) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (70) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (70) update request { Wed Dec 13 16:39:52 2017 : Debug: (70) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (70) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (70) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (70) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (70) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (70) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (70) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (70) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (70) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (70) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (70) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (70) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (70) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (70) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (70) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (70) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (70) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (70) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (70) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (70) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (70) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (70) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (70) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (70) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (70) else { Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Peer sent EAP Response (code 2) ID 232 length 336 Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Continuing tunnel setup Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (70) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (70) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (70) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (70) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (70) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (70) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (70) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (70) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (70) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (70) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (70) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (70) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (70) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (70) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (70) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (70) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (70) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (70) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (70) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (70) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (70) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (70) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (70) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (70) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Expiring EAP session with state 0xb2f1dd18b119c4f8 Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Finished EAP session with state 0xb2f1dd18b119c4f8 Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Previous EAP request found for state 0xb2f1dd18b119c4f8, released from the list Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: Peer sent flags --L Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: Peer indicated complete TLS record size will be 326 bytes Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: Got complete TLS record (326 bytes) Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: [eaptls verify] = length included Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: TLS_accept: SSLv3/TLS write server done Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: <<< recv TLS 1.0 Handshake [length 0106], ClientKeyExchange Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: TLS_accept: SSLv3/TLS read client key exchange Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: TLS_accept: SSLv3/TLS read change cipher spec Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: <<< recv TLS 1.0 Handshake [length 0010], Finished Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: TLS_accept: SSLv3/TLS read finished Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: >>> send TLS 1.0 ChangeCipherSpec [length 0001] Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: TLS_accept: SSLv3/TLS write change cipher spec Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: >>> send TLS 1.0 Handshake [length 0010], Finished Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: TLS_accept: SSLv3/TLS write finished Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: (other): SSL negotiation finished successfully Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: SSL Connection Established Wed Dec 13 16:39:52 2017 : Debug: (70) eap_peap: [eaptls process] = handled Wed Dec 13 16:39:52 2017 : Debug: (70) eap: Sending EAP Request (code 1) ID 233 length 65 Wed Dec 13 16:39:52 2017 : Debug: (70) eap: EAP session adding &reply:State = 0xb2f1dd18b618c4f8 Wed Dec 13 16:39:52 2017 : Debug: (70) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (70) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (70) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (70) Using Post-Auth-Type Challenge Wed Dec 13 16:39:52 2017 : Debug: (70) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:52 2017 : Debug: (70) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (70) session-state: Nothing to cache Wed Dec 13 16:39:52 2017 : Debug: (70) Sent Access-Challenge Id 250 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:52 2017 : Debug: (70) EAP-Message = 0x01e900411900140301000101160301003066ffee845b52179f6faf0d91732f48ea0af013c1bf71f9d0b802f57d679e6aaac945e788b62aa2e358c26dbfedfa283c Wed Dec 13 16:39:52 2017 : Debug: (70) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (70) State = 0xb2f1dd18b618c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (70) Finished request Wed Dec 13 16:39:52 2017 : Debug: Thread 5 waiting to be assigned a request Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.2 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 4 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 4 handling request 71, (15 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (71) Received Access-Request Id 251 from 10.100.100.114:1645 to 192.168.10.13:1812 length 179 Wed Dec 13 16:39:52 2017 : Debug: (71) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (71) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (71) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (71) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (71) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (71) EAP-Message = 0x02e900061900 Wed Dec 13 16:39:52 2017 : Debug: (71) Message-Authenticator = 0xd779fd84efcfda5554cca7b2bf28828b Wed Dec 13 16:39:52 2017 : Debug: (71) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (71) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (71) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (71) State = 0xb2f1dd18b618c4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (71) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (71) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (71) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (71) authorize { Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (71) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (71) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (71) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (71) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (71) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (71) update request { Wed Dec 13 16:39:52 2017 : Debug: (71) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (71) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (71) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (71) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (71) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (71) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (71) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (71) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (71) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (71) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (71) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (71) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (71) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (71) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (71) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (71) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (71) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (71) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (71) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (71) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (71) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (71) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (71) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (71) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (71) else { Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Peer sent EAP Response (code 2) ID 233 length 6 Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Continuing tunnel setup Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (71) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (71) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (71) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (71) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (71) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (71) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (71) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (71) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (71) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (71) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (71) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (71) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (71) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (71) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (71) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (71) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (71) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (71) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (71) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (71) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (71) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (71) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (71) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (71) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Expiring EAP session with state 0xb2f1dd18b618c4f8 Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Finished EAP session with state 0xb2f1dd18b618c4f8 Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Previous EAP request found for state 0xb2f1dd18b618c4f8, released from the list Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (71) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:52 2017 : Debug: (71) eap_peap: Peer sent flags --- Wed Dec 13 16:39:52 2017 : Debug: (71) eap_peap: Peer ACKed our handshake fragment. handshake is finished Wed Dec 13 16:39:52 2017 : Debug: (71) eap_peap: [eaptls verify] = success Wed Dec 13 16:39:52 2017 : Debug: (71) eap_peap: [eaptls process] = success Wed Dec 13 16:39:52 2017 : Debug: (71) eap_peap: Session established. Decoding tunneled attributes Wed Dec 13 16:39:52 2017 : Debug: (71) eap_peap: PEAP state TUNNEL ESTABLISHED Wed Dec 13 16:39:52 2017 : Debug: (71) eap: Sending EAP Request (code 1) ID 234 length 43 Wed Dec 13 16:39:52 2017 : Debug: (71) eap: EAP session adding &reply:State = 0xb2f1dd18b71bc4f8 Wed Dec 13 16:39:52 2017 : Debug: (71) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (71) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (71) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (71) Using Post-Auth-Type Challenge Wed Dec 13 16:39:52 2017 : Debug: (71) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:52 2017 : Debug: (71) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (71) session-state: Nothing to cache Wed Dec 13 16:39:52 2017 : Debug: (71) Sent Access-Challenge Id 251 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:52 2017 : Debug: (71) EAP-Message = 0x01ea002b19001703010020041b240740ab5e4a795f0b3d392eed72516bbce615dc6c9699f88d3989a8a6d2 Wed Dec 13 16:39:52 2017 : Debug: (71) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (71) State = 0xb2f1dd18b71bc4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (71) Finished request Wed Dec 13 16:39:52 2017 : Debug: Thread 4 waiting to be assigned a request Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.2 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 3 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 3 handling request 72, (15 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (72) Received Access-Request Id 252 from 10.100.100.114:1645 to 192.168.10.13:1812 length 232 Wed Dec 13 16:39:52 2017 : Debug: (72) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (72) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (72) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (72) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (72) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (72) EAP-Message = 0x02ea003b19001703010030689c2c40650b330b047d146fb0ae29c039a839ef95960137b24edc752e5f8c40d5af2ae1204f4ae5557ab0c8011a8112 Wed Dec 13 16:39:52 2017 : Debug: (72) Message-Authenticator = 0xea42077a165451293384643a255be922 Wed Dec 13 16:39:52 2017 : Debug: (72) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (72) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (72) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (72) State = 0xb2f1dd18b71bc4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (72) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (72) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (72) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (72) authorize { Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (72) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (72) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (72) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (72) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (72) update request { Wed Dec 13 16:39:52 2017 : Debug: (72) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (72) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (72) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (72) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (72) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (72) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (72) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (72) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (72) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (72) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (72) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (72) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (72) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (72) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (72) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (72) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (72) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (72) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (72) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (72) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (72) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (72) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (72) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (72) else { Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Peer sent EAP Response (code 2) ID 234 length 59 Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Continuing tunnel setup Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (72) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (72) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (72) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (72) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (72) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (72) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (72) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (72) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (72) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (72) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (72) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (72) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (72) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (72) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (72) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (72) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (72) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (72) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (72) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (72) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (72) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (72) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (72) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Expiring EAP session with state 0xb2f1dd18b71bc4f8 Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Finished EAP session with state 0xb2f1dd18b71bc4f8 Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Previous EAP request found for state 0xb2f1dd18b71bc4f8, released from the list Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Peer sent flags --- Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: [eaptls verify] = ok Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Done initial handshake Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: [eaptls process] = ok Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Session established. Decoding tunneled attributes Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: PEAP state WAITING FOR INNER IDENTITY Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Identity - host/ test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Got inner identity 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Setting default EAP type for tunneled EAP session Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Got tunneled request Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: EAP-Message = 0x02ea001b01686f73742f6473696231303930322e62636d2e696e74 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Setting User-Name to host/ test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Sending tunneled request to inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: EAP-Message = 0x02ea001b01686f73742f6473696231303930322e62636d2e696e74 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: User-Name = "host/ test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (72) Virtual server inner-tunnel received request Wed Dec 13 16:39:52 2017 : Debug: (72) EAP-Message = 0x02ea001b01686f73742f6473696231303930322e62636d2e696e74 Wed Dec 13 16:39:52 2017 : Debug: (72) FreeRADIUS-Proxied-To = 127.0.0.1 Wed Dec 13 16:39:52 2017 : Debug: (72) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : WARNING: (72) Outer and inner identities are the same. User privacy is compromised. Wed Dec 13 16:39:52 2017 : Debug: (72) server inner-tunnel { Wed Dec 13 16:39:52 2017 : Debug: (72) session-state: No State attribute Wed Dec 13 16:39:52 2017 : Debug: (72) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (72) authorize { Wed Dec 13 16:39:52 2017 : Debug: (72) policy filter_username { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ / /) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ / /) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /@[^@]*@/ ) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /\.\./ ) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /\.\./ ) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (72) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Wed Dec 13 16:39:52 2017 : Debug: (72) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /\.$/) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /\.$/) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /(a)\./) { Wed Dec 13 16:39:52 2017 : Debug: (72) if (&User-Name =~ /(a)\./) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (72) } # if (&User-Name) = notfound Wed Dec 13 16:39:52 2017 : Debug: (72) } # policy filter_username = notfound Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling chap (rlm_chap) Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from chap (rlm_chap) Wed Dec 13 16:39:52 2017 : Debug: (72) [chap] = noop Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (72) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (72) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (72) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (72) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (72) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (72) update control { Wed Dec 13 16:39:52 2017 : Debug: (72) &Proxy-To-Realm := LOCAL Wed Dec 13 16:39:52 2017 : Debug: (72) } # update control = noop Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Peer sent EAP Response (code 2) ID 234 length 27 Wed Dec 13 16:39:52 2017 : Debug: (72) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (72) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (72) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (72) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (72) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Peer sent packet with method EAP Identity (1) Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Calling submodule eap_mschapv2 to process data Wed Dec 13 16:39:52 2017 : Debug: (72) eap_mschapv2: Issuing Challenge Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Sending EAP Request (code 1) ID 235 length 34 Wed Dec 13 16:39:52 2017 : Debug: (72) eap: EAP session adding &reply:State = 0x3ca0b9d33c4ba3ba Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (72) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (72) } # server inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (72) Virtual server sending reply Wed Dec 13 16:39:52 2017 : Debug: (72) EAP-Message = 0x01eb00221a01eb001d1052a3468f574dc93d234f72b77c6b138742434d312d414141 Wed Dec 13 16:39:52 2017 : Debug: (72) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (72) State = 0x3ca0b9d33c4ba3ba9fc0b7509ba338f8 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Got tunneled reply code 11 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: EAP-Message = 0x01eb00221a01eb001d1052a3468f574dc93d234f72b77c6b138742434d312d414141 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: State = 0x3ca0b9d33c4ba3ba9fc0b7509ba338f8 Wed Dec 13 16:39:52 2017 : Debug: (72) eap_peap: Got tunneled Access-Challenge Wed Dec 13 16:39:52 2017 : Debug: (72) eap: Sending EAP Request (code 1) ID 235 length 75 Wed Dec 13 16:39:52 2017 : Debug: (72) eap: EAP session adding &reply:State = 0xb2f1dd18b41ac4f8 Wed Dec 13 16:39:52 2017 : Debug: (72) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (72) [eap] = handled Wed Dec 13 16:39:52 2017 : Debug: (72) } # authenticate = handled Wed Dec 13 16:39:52 2017 : Debug: (72) Using Post-Auth-Type Challenge Wed Dec 13 16:39:52 2017 : Debug: (72) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:52 2017 : Debug: (72) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (72) session-state: Nothing to cache Wed Dec 13 16:39:52 2017 : Debug: (72) Sent Access-Challenge Id 252 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:52 2017 : Debug: (72) EAP-Message = 0x01eb004b190017030100406acf1842608e54febcaf1c28c2339d3f5a8cefa941e6b09e8008ef1e1bb7e4d0e36236d2d0cf0d67af1cce5cb411976a832ae019c26b7400d63e2a01da3cfca4 Wed Dec 13 16:39:52 2017 : Debug: (72) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:52 2017 : Debug: (72) State = 0xb2f1dd18b41ac4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (72) Finished request Wed Dec 13 16:39:52 2017 : Debug: Thread 3 waiting to be assigned a request Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.2 seconds. Wed Dec 13 16:39:52 2017 : Debug: Thread 2 got semaphore Wed Dec 13 16:39:52 2017 : Debug: Thread 2 handling request 73, (15 handled so far) Wed Dec 13 16:39:52 2017 : Debug: (73) Received Access-Request Id 253 from 10.100.100.114:1645 to 192.168.10.13:1812 length 296 Wed Dec 13 16:39:52 2017 : Debug: (73) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (73) Service-Type = Framed-User Wed Dec 13 16:39:52 2017 : Debug: (73) Framed-MTU = 1500 Wed Dec 13 16:39:52 2017 : Debug: (73) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:52 2017 : Debug: (73) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (73) EAP-Message = 0x02eb007b1900170301007024943779732cbeccdd8a64918bca94bb276c68b7b533d798f3eb3c2d3c9d8c344de4bf9c16e8072b7b673448e07427a8f291765dc0cc5713db3f8d1a4dfb5395c77f2a8d1868a61111ec694643d1f36dc94977dfe6b0ae5848e082fddf9c85dbd0f04c699536605a573fff57 Wed Dec 13 16:39:52 2017 : Debug: (73) Message-Authenticator = 0x5f483d7b99ab18d1e0b8abce47b0d2e7 Wed Dec 13 16:39:52 2017 : Debug: (73) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:52 2017 : Debug: (73) NAS-Port = 50003 Wed Dec 13 16:39:52 2017 : Debug: (73) NAS-Port-Type = Ethernet Wed Dec 13 16:39:52 2017 : Debug: (73) State = 0xb2f1dd18b41ac4f89bc17b18e7fb770d Wed Dec 13 16:39:52 2017 : Debug: (73) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:52 2017 : Debug: (73) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (73) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (73) authorize { Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:52 2017 : Debug: (73) [preprocess] = ok Wed Dec 13 16:39:52 2017 : Debug: (73) policy rewrite_calling_station_id { Wed Dec 13 16:39:52 2017 : Debug: (73) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (73) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:52 2017 : Debug: (73) update request { Wed Dec 13 16:39:52 2017 : Debug: (73) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:52 2017 : Debug: (73) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (73) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:52 2017 : Debug: (73) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:52 2017 : Debug: (73) } # update request = noop Wed Dec 13 16:39:52 2017 : Debug: (73) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:52 2017 : Debug: (73) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (73) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:52 2017 : Debug: (73) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (73) EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (73) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (73) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (73) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (73) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:52 2017 : Debug: (73) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (73) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:52 2017 : Debug: (73) --> 1 Wed Dec 13 16:39:52 2017 : Debug: (73) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (73) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:52 2017 : Debug: (73) [ok] = ok Wed Dec 13 16:39:52 2017 : Debug: (73) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:52 2017 : Debug: (73) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:52 2017 : Debug: (73) if (!EAP-Message) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (73) else { Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Peer sent EAP Response (code 2) ID 235 length 123 Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Continuing tunnel setup Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (73) [eap] = ok Wed Dec 13 16:39:52 2017 : Debug: (73) } # else = ok Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (73) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (73) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (73) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (73) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (73) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (73) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (73) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (73) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (73) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (73) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (73) } # authorize = ok Wed Dec 13 16:39:52 2017 : Debug: (73) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (73) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:52 2017 : Debug: (73) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Expiring EAP session with state 0x3ca0b9d33c4ba3ba Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Finished EAP session with state 0xb2f1dd18b41ac4f8 Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Previous EAP request found for state 0xb2f1dd18b41ac4f8, released from the list Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: Peer sent flags --- Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: [eaptls verify] = ok Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: Done initial handshake Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: [eaptls process] = ok Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: Session established. Decoding tunneled attributes Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: PEAP state phase2 Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: EAP method MSCHAPv2 (26) Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: Got tunneled request Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: EAP-Message = 0x02eb00511a02eb004c31f906c233e692c49eeecb392c3e6f33cc0000000000000000ebe1377d01d09cbe0bfda9256149732ec2b94b30d4cbc32700686f73742f6473696231303930322e62636d2e696e74 Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: Setting User-Name to host/ test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: Sending tunneled request to inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: EAP-Message = 0x02eb00511a02eb004c31f906c233e692c49eeecb392c3e6f33cc0000000000000000ebe1377d01d09cbe0bfda9256149732ec2b94b30d4cbc32700686f73742f6473696231303930322e62636d2e696e74 Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: User-Name = "host/ test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (73) eap_peap: State = 0x3ca0b9d33c4ba3ba9fc0b7509ba338f8 Wed Dec 13 16:39:52 2017 : Debug: (73) Virtual server inner-tunnel received request Wed Dec 13 16:39:52 2017 : Debug: (73) EAP-Message = 0x02eb00511a02eb004c31f906c233e692c49eeecb392c3e6f33cc0000000000000000ebe1377d01d09cbe0bfda9256149732ec2b94b30d4cbc32700686f73742f6473696231303930322e62636d2e696e74 Wed Dec 13 16:39:52 2017 : Debug: (73) FreeRADIUS-Proxied-To = 127.0.0.1 Wed Dec 13 16:39:52 2017 : Debug: (73) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:52 2017 : Debug: (73) State = 0x3ca0b9d33c4ba3ba9fc0b7509ba338f8 Wed Dec 13 16:39:52 2017 : WARNING: (73) Outer and inner identities are the same. User privacy is compromised. Wed Dec 13 16:39:52 2017 : Debug: (73) server inner-tunnel { Wed Dec 13 16:39:52 2017 : Debug: (73) session-state: No cached attributes Wed Dec 13 16:39:52 2017 : Debug: (73) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (73) authorize { Wed Dec 13 16:39:52 2017 : Debug: (73) policy filter_username { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name) -> TRUE Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ / /) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ / /) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /@[^@]*@/ ) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /\.\./ ) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /\.\./ ) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (73) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Wed Dec 13 16:39:52 2017 : Debug: (73) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /\.$/) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /\.$/) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /(a)\./) { Wed Dec 13 16:39:52 2017 : Debug: (73) if (&User-Name =~ /(a)\./) -> FALSE Wed Dec 13 16:39:52 2017 : Debug: (73) } # if (&User-Name) = notfound Wed Dec 13 16:39:52 2017 : Debug: (73) } # policy filter_username = notfound Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling chap (rlm_chap) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from chap (rlm_chap) Wed Dec 13 16:39:52 2017 : Debug: (73) [chap] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (73) [mschap] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (73) suffix: Checking for suffix after "@" Wed Dec 13 16:39:52 2017 : Debug: (73) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:52 2017 : Debug: (73) suffix: No such realm "NULL" Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:52 2017 : Debug: (73) [suffix] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) update control { Wed Dec 13 16:39:52 2017 : Debug: (73) &Proxy-To-Realm := LOCAL Wed Dec 13 16:39:52 2017 : Debug: (73) } # update control = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Peer sent EAP Response (code 2) ID 235 length 81 Wed Dec 13 16:39:52 2017 : Debug: (73) eap: No EAP Start, assuming it's an on-going EAP conversation Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (73) [eap] = updated Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling files (rlm_files) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from files (rlm_files) Wed Dec 13 16:39:52 2017 : Debug: (73) [files] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:52 2017 : Debug: (73) sql: EXPAND %{User-Name} Wed Dec 13 16:39:52 2017 : Debug: (73) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (73) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:52 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:52 2017 : Debug: (73) sql: ... falling-through to group processing Wed Dec 13 16:39:52 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:52 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:52 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:52 2017 : Debug: (73) sql: User not found in any groups Wed Dec 13 16:39:52 2017 : Debug: (73) sql: ... falling-through to profile processing Wed Dec 13 16:39:52 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:52 2017 : Debug: (73) [sql] = notfound Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling expiration (rlm_expiration) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from expiration (rlm_expiration) Wed Dec 13 16:39:52 2017 : Debug: (73) [expiration] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling logintime (rlm_logintime) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from logintime (rlm_logintime) Wed Dec 13 16:39:52 2017 : Debug: (73) [logintime] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: calling pap (rlm_pap) Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authorize]: returned from pap (rlm_pap) Wed Dec 13 16:39:52 2017 : Debug: (73) [pap] = noop Wed Dec 13 16:39:52 2017 : Debug: (73) } # authorize = updated Wed Dec 13 16:39:52 2017 : Debug: (73) Found Auth-Type = eap Wed Dec 13 16:39:52 2017 : Debug: (73) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (73) authenticate { Wed Dec 13 16:39:52 2017 : Debug: (73) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Expiring EAP session with state 0x3ca0b9d33c4ba3ba Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Finished EAP session with state 0x3ca0b9d33c4ba3ba Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Previous EAP request found for state 0x3ca0b9d33c4ba3ba, released from the list Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Peer sent packet with method EAP MSCHAPv2 (26) Wed Dec 13 16:39:52 2017 : Debug: (73) eap: Calling submodule eap_mschapv2 to process data Wed Dec 13 16:39:52 2017 : Debug: (73) eap_mschapv2: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:52 2017 : Debug: (73) eap_mschapv2: Auth-Type MS-CHAP { Wed Dec 13 16:39:52 2017 : Debug: (73) eap_mschapv2: modsingle[authenticate]: calling mschap (rlm_mschap) Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: Creating challenge hash with username: host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: Client is using MS-CHAPv2 Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: Executing: /usr/bin/ntlm_auth --request-nt-key --username=%{%{mschap:User-Name}:-00} --domain=%{mschap:NT-Domain} --challenge=%{%{mschap:Challenge}:-00} --nt-response=%{%{mschap:NT-Response}:-00} : Wed Dec 13 16:39:52 2017 : Debug: --username=%{%{mschap:User-Name}:-00} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> --username= Wed Dec 13 16:39:52 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:52 2017 : Debug: xlat --> mschap Wed Dec 13 16:39:52 2017 : Debug: { Wed Dec 13 16:39:52 2017 : Debug: literal --> User-Name Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:52 2017 : Debug: literal --> 00 Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: EXPAND --username=%{%{mschap:User-Name}:-00} Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: --> --username=test0LAB$ Wed Dec 13 16:39:52 2017 : Debug: --domain=%{mschap:NT-Domain} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> --domain= Wed Dec 13 16:39:52 2017 : Debug: xlat --> mschap Wed Dec 13 16:39:52 2017 : Debug: { Wed Dec 13 16:39:52 2017 : Debug: literal --> NT-Domain Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: EXPAND --domain=%{mschap:NT-Domain} Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: --> --domain=bcm Wed Dec 13 16:39:52 2017 : Debug: --challenge=%{%{mschap:Challenge}:-00} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> --challenge= Wed Dec 13 16:39:52 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:52 2017 : Debug: xlat --> mschap Wed Dec 13 16:39:52 2017 : Debug: { Wed Dec 13 16:39:52 2017 : Debug: literal --> Challenge Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:52 2017 : Debug: literal --> 00 Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: Creating challenge hash with username: host/test0LAB.ar0s.is Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: EXPAND --challenge=%{%{mschap:Challenge}:-00} Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: --> --challenge=63e591e3006dd7d0 Wed Dec 13 16:39:52 2017 : Debug: --nt-response=%{%{mschap:NT-Response}:-00} Wed Dec 13 16:39:52 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:52 2017 : Debug: literal --> --nt-response= Wed Dec 13 16:39:52 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:52 2017 : Debug: xlat --> mschap Wed Dec 13 16:39:52 2017 : Debug: { Wed Dec 13 16:39:52 2017 : Debug: literal --> NT-Response Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:52 2017 : Debug: literal --> 00 Wed Dec 13 16:39:52 2017 : Debug: } Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: EXPAND --nt-response=%{%{mschap:NT-Response}:-00} Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: --> --nt-response=ebe1377d01d09cbe0bfda9256149732ec2b94b30d4cbc327 Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.4 seconds. Wed Dec 13 16:39:53 2017 : Debug: Waking up in 0.7 seconds. Wed Dec 13 16:39:53 2017 : Debug: Waking up in 1.1 seconds. Wed Dec 13 16:39:54 2017 : Debug: (73) mschap: Program returned code (0) and output 'NT_KEY: 584702B9B75800AE1371683946584AFD' Wed Dec 13 16:39:54 2017 : Debug: (73) mschap: Adding MS-CHAPv2 MPPE keys Wed Dec 13 16:39:54 2017 : Debug: (73) modsingle[authenticate]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:54 2017 : Debug: (73) [mschap] = ok Wed Dec 13 16:39:54 2017 : Debug: (73) } # Auth-Type MS-CHAP = ok Wed Dec 13 16:39:54 2017 : Debug: (73) MSCHAP Success Wed Dec 13 16:39:54 2017 : Debug: (73) eap: Sending EAP Request (code 1) ID 236 length 51 Wed Dec 13 16:39:54 2017 : Debug: (73) eap: EAP session adding &reply:State = 0x3ca0b9d33d4ca3ba Wed Dec 13 16:39:54 2017 : Debug: (73) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (73) [eap] = handled Wed Dec 13 16:39:54 2017 : Debug: (73) } # authenticate = handled Wed Dec 13 16:39:54 2017 : Debug: (73) } # server inner-tunnel Wed Dec 13 16:39:54 2017 : Debug: (73) Virtual server sending reply Wed Dec 13 16:39:54 2017 : Debug: (73) EAP-Message = 0x01ec00331a03eb002e533d34334334373134324538463945383132394130334642334630343834463744463442334434443741 Wed Dec 13 16:39:54 2017 : Debug: (73) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:54 2017 : Debug: (73) State = 0x3ca0b9d33d4ca3ba9fc0b7509ba338f8 Wed Dec 13 16:39:54 2017 : Debug: (73) eap_peap: Got tunneled reply code 11 Wed Dec 13 16:39:54 2017 : Debug: (73) eap_peap: EAP-Message = 0x01ec00331a03eb002e533d34334334373134324538463945383132394130334642334630343834463744463442334434443741 Wed Dec 13 16:39:54 2017 : Debug: (73) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:54 2017 : Debug: (73) eap_peap: State = 0x3ca0b9d33d4ca3ba9fc0b7509ba338f8 Wed Dec 13 16:39:54 2017 : Debug: (73) eap_peap: Got tunneled Access-Challenge Wed Dec 13 16:39:54 2017 : Debug: (73) eap: Sending EAP Request (code 1) ID 236 length 91 Wed Dec 13 16:39:54 2017 : Debug: (73) eap: EAP session adding &reply:State = 0xb2f1dd18b51dc4f8 Wed Dec 13 16:39:54 2017 : Debug: (73) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (73) [eap] = handled Wed Dec 13 16:39:54 2017 : Debug: (73) } # authenticate = handled Wed Dec 13 16:39:54 2017 : Debug: (73) Using Post-Auth-Type Challenge Wed Dec 13 16:39:54 2017 : Debug: (73) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:54 2017 : Debug: (73) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (73) session-state: Nothing to cache Wed Dec 13 16:39:54 2017 : Debug: (73) Sent Access-Challenge Id 253 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:54 2017 : Debug: (73) EAP-Message = 0x01ec005b19001703010050ec0d00019ade8da0742a0d81bb3c3e31564132c3ed189a52b0b2faecc6f34ecab77828ae9cc6c5d72c3d27d53308e21105347667f8a2d36a6ada60f2ff085720b46eac17213a3d5b3e62c9f1c34b84fb Wed Dec 13 16:39:54 2017 : Debug: (73) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:54 2017 : Debug: (73) State = 0xb2f1dd18b51dc4f89bc17b18e7fb770d Wed Dec 13 16:39:54 2017 : Debug: (73) Finished request Wed Dec 13 16:39:54 2017 : Debug: Thread 2 waiting to be assigned a request Wed Dec 13 16:39:54 2017 : Debug: Waking up in 0.3 seconds. Wed Dec 13 16:39:54 2017 : Debug: Thread 1 got semaphore Wed Dec 13 16:39:54 2017 : Debug: Thread 1 handling request 74, (15 handled so far) Wed Dec 13 16:39:54 2017 : Debug: (74) Received Access-Request Id 254 from 10.100.100.114:1645 to 192.168.10.13:1812 length 216 Wed Dec 13 16:39:54 2017 : Debug: (74) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (74) Service-Type = Framed-User Wed Dec 13 16:39:54 2017 : Debug: (74) Framed-MTU = 1500 Wed Dec 13 16:39:54 2017 : Debug: (74) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:54 2017 : Debug: (74) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:54 2017 : Debug: (74) EAP-Message = 0x02ec002b1900170301002035bcea1c20157015f360ebbf7e0ab18d057df2669d46a249b81807f87274acd6 Wed Dec 13 16:39:54 2017 : Debug: (74) Message-Authenticator = 0xa22e7fc4c1ea4bac087829bba98ffe67 Wed Dec 13 16:39:54 2017 : Debug: (74) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:54 2017 : Debug: (74) NAS-Port = 50003 Wed Dec 13 16:39:54 2017 : Debug: (74) NAS-Port-Type = Ethernet Wed Dec 13 16:39:54 2017 : Debug: (74) State = 0xb2f1dd18b51dc4f89bc17b18e7fb770d Wed Dec 13 16:39:54 2017 : Debug: (74) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:54 2017 : Debug: (74) session-state: No cached attributes Wed Dec 13 16:39:54 2017 : Debug: (74) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (74) authorize { Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:54 2017 : Debug: (74) [preprocess] = ok Wed Dec 13 16:39:54 2017 : Debug: (74) policy rewrite_calling_station_id { Wed Dec 13 16:39:54 2017 : Debug: (74) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:54 2017 : Debug: (74) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:54 2017 : Debug: (74) update request { Wed Dec 13 16:39:54 2017 : Debug: (74) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:54 2017 : Debug: (74) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:54 2017 : Debug: (74) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:54 2017 : Debug: (74) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:54 2017 : Debug: (74) } # update request = noop Wed Dec 13 16:39:54 2017 : Debug: (74) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:54 2017 : Debug: (74) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:54 2017 : Debug: (74) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:54 2017 : Debug: (74) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (74) EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (74) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (74) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:54 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (74) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (74) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (74) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:54 2017 : Info: Need 1 more connections to reach min connections (3) Wed Dec 13 16:39:54 2017 : Info: rlm_sql (sql): Opening additional connection (23), 1 of 30 pending slots used Wed Dec 13 16:39:54 2017 : Debug: rlm_sql_mysql: Starting connect to MySQL server Wed Dec 13 16:39:54 2017 : Debug: rlm_sql_mysql: Connected to database 'radius' on Localhost via UNIX socket, server version 10.1.23-MariaDB-9+deb9u1, protocol version 10 Wed Dec 13 16:39:54 2017 : Debug: (74) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:54 2017 : Debug: (74) --> 1 Wed Dec 13 16:39:54 2017 : Debug: (74) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:54 2017 : Debug: (74) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (74) [ok] = ok Wed Dec 13 16:39:54 2017 : Debug: (74) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:54 2017 : Debug: (74) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:54 2017 : Debug: (74) if (!EAP-Message) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (74) else { Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Peer sent EAP Response (code 2) ID 236 length 43 Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Continuing tunnel setup Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) [eap] = ok Wed Dec 13 16:39:54 2017 : Debug: (74) } # else = ok Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:54 2017 : Debug: (74) [mschap] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (74) suffix: Checking for suffix after "@" Wed Dec 13 16:39:54 2017 : Debug: (74) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:54 2017 : Debug: (74) suffix: No such realm "NULL" Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (74) [suffix] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (74) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:54 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:54 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: ... falling-through to group processing Wed Dec 13 16:39:54 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:54 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: User not found in any groups Wed Dec 13 16:39:54 2017 : Debug: (74) sql: ... falling-through to profile processing Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: (74) [sql] = notfound Wed Dec 13 16:39:54 2017 : Debug: (74) } # authorize = ok Wed Dec 13 16:39:54 2017 : Debug: (74) Found Auth-Type = eap Wed Dec 13 16:39:54 2017 : Debug: (74) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (74) authenticate { Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Expiring EAP session with state 0x3ca0b9d33d4ca3ba Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Finished EAP session with state 0xb2f1dd18b51dc4f8 Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Previous EAP request found for state 0xb2f1dd18b51dc4f8, released from the list Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Peer sent flags --- Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: [eaptls verify] = ok Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Done initial handshake Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: [eaptls process] = ok Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Session established. Decoding tunneled attributes Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: PEAP state phase2 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: EAP method MSCHAPv2 (26) Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Got tunneled request Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: EAP-Message = 0x02ec00061a03 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Setting User-Name to host/ test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Sending tunneled request to inner-tunnel Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: EAP-Message = 0x02ec00061a03 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: User-Name = "host/ test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: State = 0x3ca0b9d33d4ca3ba9fc0b7509ba338f8 Wed Dec 13 16:39:54 2017 : Debug: (74) Virtual server inner-tunnel received request Wed Dec 13 16:39:54 2017 : Debug: (74) EAP-Message = 0x02ec00061a03 Wed Dec 13 16:39:54 2017 : Debug: (74) FreeRADIUS-Proxied-To = 127.0.0.1 Wed Dec 13 16:39:54 2017 : Debug: (74) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (74) State = 0x3ca0b9d33d4ca3ba9fc0b7509ba338f8 Wed Dec 13 16:39:54 2017 : WARNING: (74) Outer and inner identities are the same. User privacy is compromised. Wed Dec 13 16:39:54 2017 : Debug: (74) server inner-tunnel { Wed Dec 13 16:39:54 2017 : Debug: (74) session-state: No cached attributes Wed Dec 13 16:39:54 2017 : Debug: (74) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:54 2017 : Debug: (74) authorize { Wed Dec 13 16:39:54 2017 : Debug: (74) policy filter_username { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name) -> TRUE Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ / /) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ / /) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /@[^@]*@/ ) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /@[^@]*@/ ) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /\.\./ ) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /\.\./ ) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (74) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) { Wed Dec 13 16:39:54 2017 : Debug: (74) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /\.$/) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /\.$/) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /(a)\./) { Wed Dec 13 16:39:54 2017 : Debug: (74) if (&User-Name =~ /(a)\./) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (74) } # if (&User-Name) = notfound Wed Dec 13 16:39:54 2017 : Debug: (74) } # policy filter_username = notfound Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling chap (rlm_chap) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from chap (rlm_chap) Wed Dec 13 16:39:54 2017 : Debug: (74) [chap] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:54 2017 : Debug: (74) [mschap] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (74) suffix: Checking for suffix after "@" Wed Dec 13 16:39:54 2017 : Debug: (74) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:54 2017 : Debug: (74) suffix: No such realm "NULL" Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (74) [suffix] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) update control { Wed Dec 13 16:39:54 2017 : Debug: (74) &Proxy-To-Realm := LOCAL Wed Dec 13 16:39:54 2017 : Debug: (74) } # update control = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Peer sent EAP Response (code 2) ID 236 length 6 Wed Dec 13 16:39:54 2017 : Debug: (74) eap: No EAP Start, assuming it's an on-going EAP conversation Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) [eap] = updated Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling files (rlm_files) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from files (rlm_files) Wed Dec 13 16:39:54 2017 : Debug: (74) [files] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (74) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:54 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:54 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (74) sql: ... falling-through to group processing Wed Dec 13 16:39:54 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:54 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (74) sql: User not found in any groups Wed Dec 13 16:39:54 2017 : Debug: (74) sql: ... falling-through to profile processing Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: (74) [sql] = notfound Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling expiration (rlm_expiration) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from expiration (rlm_expiration) Wed Dec 13 16:39:54 2017 : Debug: (74) [expiration] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling logintime (rlm_logintime) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from logintime (rlm_logintime) Wed Dec 13 16:39:54 2017 : Debug: (74) [logintime] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: calling pap (rlm_pap) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authorize]: returned from pap (rlm_pap) Wed Dec 13 16:39:54 2017 : Debug: (74) [pap] = noop Wed Dec 13 16:39:54 2017 : Debug: (74) } # authorize = updated Wed Dec 13 16:39:54 2017 : Debug: (74) Found Auth-Type = eap Wed Dec 13 16:39:54 2017 : Debug: (74) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:54 2017 : Debug: (74) authenticate { Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Expiring EAP session with state 0x3ca0b9d33d4ca3ba Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Finished EAP session with state 0x3ca0b9d33d4ca3ba Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Previous EAP request found for state 0x3ca0b9d33d4ca3ba, released from the list Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Peer sent packet with method EAP MSCHAPv2 (26) Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Calling submodule eap_mschapv2 to process data Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Sending EAP Success (code 3) ID 236 length 4 Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Freeing handler Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) [eap] = ok Wed Dec 13 16:39:54 2017 : Debug: (74) } # authenticate = ok Wed Dec 13 16:39:54 2017 : Debug: (74) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Wed Dec 13 16:39:54 2017 : Debug: (74) post-auth { Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[post-auth]: calling sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: .query Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> .query Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND .query Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> .query Wed Dec 13 16:39:54 2017 : Debug: (74) sql: Using query template 'query' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (23) Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (74) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:54 2017 : Debug: literal --> ', ' Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Password Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: attribute --> CHAP-Password Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> ', ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> Packet-Type Wed Dec 13 16:39:54 2017 : Debug: literal --> ', ' Wed Dec 13 16:39:54 2017 : Debug: percent --> S Wed Dec 13 16:39:54 2017 : Debug: literal --> ') Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'host/test0LAB.ar0s.is', '', 'Access-Accept', '2017-12-13 16:39:54') Wed Dec 13 16:39:54 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (74) sql: EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (74) sql: --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (74) sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'host/ test0LAB.ar0s.is', '', 'Access-Accept', '2017-12-13 16:39:54') Wed Dec 13 16:39:54 2017 : Debug: (74) sql: SQL query returned: success Wed Dec 13 16:39:54 2017 : Debug: (74) sql: 1 record(s) updated Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (23) Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[post-auth]: returned from sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: (74) [sql] = ok Wed Dec 13 16:39:54 2017 : Debug: (74) } # post-auth = ok Wed Dec 13 16:39:54 2017 : Debug: (74) } # server inner-tunnel Wed Dec 13 16:39:54 2017 : Debug: (74) Virtual server sending reply Wed Dec 13 16:39:54 2017 : Debug: (74) MS-MPPE-Encryption-Policy = Encryption-Required Wed Dec 13 16:39:54 2017 : Debug: (74) MS-MPPE-Encryption-Types = 4 Wed Dec 13 16:39:54 2017 : Debug: (74) MS-MPPE-Send-Key = 0x0bbbbcb711397d7d94139ac68e30f327 Wed Dec 13 16:39:54 2017 : Debug: (74) MS-MPPE-Recv-Key = 0xd29604f012f5e1bc9243a10fb015a25f Wed Dec 13 16:39:54 2017 : Debug: (74) EAP-Message = 0x03ec0004 Wed Dec 13 16:39:54 2017 : Debug: (74) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:54 2017 : Debug: (74) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Got tunneled reply code 2 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: MS-MPPE-Encryption-Policy = Encryption-Required Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: MS-MPPE-Encryption-Types = 4 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: MS-MPPE-Send-Key = 0x0bbbbcb711397d7d94139ac68e30f327 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: MS-MPPE-Recv-Key = 0xd29604f012f5e1bc9243a10fb015a25f Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: EAP-Message = 0x03ec0004 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: User-Name = "host/ test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Tunneled authentication was successful Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: SUCCESS Wed Dec 13 16:39:54 2017 : Debug: (74) eap_peap: Saving tunneled attributes for later Wed Dec 13 16:39:54 2017 : Debug: (74) eap: Sending EAP Request (code 1) ID 237 length 43 Wed Dec 13 16:39:54 2017 : Debug: (74) eap: EAP session adding &reply:State = 0xb2f1dd18ba1cc4f8 Wed Dec 13 16:39:54 2017 : Debug: (74) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (74) [eap] = handled Wed Dec 13 16:39:54 2017 : Debug: (74) } # authenticate = handled Wed Dec 13 16:39:54 2017 : Debug: (74) Using Post-Auth-Type Challenge Wed Dec 13 16:39:54 2017 : Debug: (74) Post-Auth-Type sub-section not found. Ignoring. Wed Dec 13 16:39:54 2017 : Debug: (74) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (74) session-state: Nothing to cache Wed Dec 13 16:39:54 2017 : Debug: (74) Sent Access-Challenge Id 254 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:54 2017 : Debug: (74) EAP-Message = 0x01ed002b19001703010020a333bff49a369b991e3c207ffcdcd4bee4f75d063a4eae7d320066a6b81b2996 Wed Dec 13 16:39:54 2017 : Debug: (74) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:54 2017 : Debug: (74) State = 0xb2f1dd18ba1cc4f89bc17b18e7fb770d Wed Dec 13 16:39:54 2017 : Debug: (74) Finished request Wed Dec 13 16:39:54 2017 : Debug: Thread 1 waiting to be assigned a request Wed Dec 13 16:39:54 2017 : Debug: Waking up in 0.2 seconds. Wed Dec 13 16:39:54 2017 : Debug: Thread 5 got semaphore Wed Dec 13 16:39:54 2017 : Debug: Thread 5 handling request 75, (16 handled so far) Wed Dec 13 16:39:54 2017 : Debug: (75) Received Access-Request Id 255 from 10.100.100.114:1645 to 192.168.10.13:1812 length 216 Wed Dec 13 16:39:54 2017 : Debug: (75) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (75) Service-Type = Framed-User Wed Dec 13 16:39:54 2017 : Debug: (75) Framed-MTU = 1500 Wed Dec 13 16:39:54 2017 : Debug: (75) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:54 2017 : Debug: (75) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:54 2017 : Debug: (75) EAP-Message = 0x02ed002b19001703010020d602362d206fc7a360005419706fbaa69f2e4afd12d32893f4e89f7412bf6609 Wed Dec 13 16:39:54 2017 : Debug: (75) Message-Authenticator = 0x7765ff294336d01528246a5ccffad687 Wed Dec 13 16:39:54 2017 : Debug: (75) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:54 2017 : Debug: (75) NAS-Port = 50003 Wed Dec 13 16:39:54 2017 : Debug: (75) NAS-Port-Type = Ethernet Wed Dec 13 16:39:54 2017 : Debug: (75) State = 0xb2f1dd18ba1cc4f89bc17b18e7fb770d Wed Dec 13 16:39:54 2017 : Debug: (75) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:54 2017 : Debug: (75) session-state: No cached attributes Wed Dec 13 16:39:54 2017 : Debug: (75) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (75) authorize { Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:54 2017 : Debug: (75) [preprocess] = ok Wed Dec 13 16:39:54 2017 : Debug: (75) policy rewrite_calling_station_id { Wed Dec 13 16:39:54 2017 : Debug: (75) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:54 2017 : Debug: (75) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) -> TRUE Wed Dec 13 16:39:54 2017 : Debug: (75) if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) { Wed Dec 13 16:39:54 2017 : Debug: (75) update request { Wed Dec 13 16:39:54 2017 : Debug: (75) EXPAND %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} Wed Dec 13 16:39:54 2017 : Debug: (75) --> A4-04-19-10-D2-2F Wed Dec 13 16:39:54 2017 : Debug: (75) Calling-Station-Id := A4-04-19-10-D2-2F Wed Dec 13 16:39:54 2017 : Debug: (75) Overwriting value "A4-04-19-10-D2-2F" with "A4-04-19-10-D2-2F" Wed Dec 13 16:39:54 2017 : Debug: (75) } # update request = noop Wed Dec 13 16:39:54 2017 : Debug: (75) } # if (Calling-Station-Id =~ /([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})[-:.]?([0-9a-f]{2})[-:]?([0-9a-f]{2})/i) = noop Wed Dec 13 16:39:54 2017 : Debug: (75) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:54 2017 : Debug: (75) } # policy rewrite_calling_station_id = noop Wed Dec 13 16:39:54 2017 : Debug: (75) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (75) EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (75) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (75) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:54 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (75) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (75) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (75) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:54 2017 : Debug: (75) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:54 2017 : Debug: (75) --> 1 Wed Dec 13 16:39:54 2017 : Debug: (75) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:54 2017 : Debug: (75) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: calling ok (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: returned from ok (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (75) [ok] = ok Wed Dec 13 16:39:54 2017 : Debug: (75) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:54 2017 : Debug: (75) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:54 2017 : Debug: (75) if (!EAP-Message) { Wed Dec 13 16:39:54 2017 : Debug: (75) if (!EAP-Message) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (75) else { Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: calling eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Peer sent EAP Response (code 2) ID 237 length 43 Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Continuing tunnel setup Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (75) [eap] = ok Wed Dec 13 16:39:54 2017 : Debug: (75) } # else = ok Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: calling mschap (rlm_mschap) Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: returned from mschap (rlm_mschap) Wed Dec 13 16:39:54 2017 : Debug: (75) [mschap] = noop Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: calling suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (75) suffix: Checking for suffix after "@" Wed Dec 13 16:39:54 2017 : Debug: (75) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:54 2017 : Debug: (75) suffix: No such realm "NULL" Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: returned from suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (75) [suffix] = noop Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: calling sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (75) sql: EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (75) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (75) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (21) Wed Dec 13 16:39:54 2017 : Debug: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:54 2017 : Debug: literal --> ' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (75) sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (75) sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (75) sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'host/ test0LAB.ar0s.is' ORDER BY id Wed Dec 13 16:39:54 2017 : Debug: (75) sql: ... falling-through to group processing Wed Dec 13 16:39:54 2017 : Debug: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> SELECT groupname FROM radusergroup WHERE username = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> SQL-User-Name Wed Dec 13 16:39:54 2017 : Debug: literal --> ' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (75) sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (75) sql: --> SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (75) sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'host/test0LAB.ar0s.is' ORDER BY priority Wed Dec 13 16:39:54 2017 : Debug: (75) sql: User not found in any groups Wed Dec 13 16:39:54 2017 : Debug: (75) sql: ... falling-through to profile processing Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (21) Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authorize]: returned from sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: (75) [sql] = notfound Wed Dec 13 16:39:54 2017 : Debug: (75) } # authorize = ok Wed Dec 13 16:39:54 2017 : Debug: (75) Found Auth-Type = eap Wed Dec 13 16:39:54 2017 : Debug: (75) # Executing group from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (75) authenticate { Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authenticate]: calling eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Expiring EAP session with state 0xb2f1dd18ba1cc4f8 Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Finished EAP session with state 0xb2f1dd18ba1cc4f8 Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Previous EAP request found for state 0xb2f1dd18ba1cc4f8, released from the list Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Peer sent packet with method EAP PEAP (25) Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Calling submodule eap_peap to process data Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Continuing EAP-TLS Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Peer sent flags --- Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: [eaptls verify] = ok Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Done initial handshake Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: [eaptls process] = ok Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Session established. Decoding tunneled attributes Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: PEAP state send tlv success Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Received EAP-TLV response Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Success Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Using saved attributes from the original Access-Accept Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: User-Name = "host/ test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: caching User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (75) eap_peap: Failed to find 'persist_dir' in TLS configuration. Session will not be cached on disk. Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Sending EAP Success (code 3) ID 237 length 4 Wed Dec 13 16:39:54 2017 : Debug: (75) eap: Freeing handler Wed Dec 13 16:39:54 2017 : Debug: tls: Freeing cached session VPs Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[authenticate]: returned from eap (rlm_eap) Wed Dec 13 16:39:54 2017 : Debug: (75) [eap] = ok Wed Dec 13 16:39:54 2017 : Debug: (75) } # authenticate = ok Wed Dec 13 16:39:54 2017 : Debug: (75) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (75) post-auth { Wed Dec 13 16:39:54 2017 : Debug: (75) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0){ Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (75) EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (75) --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (75) SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (23) Wed Dec 13 16:39:54 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (75) EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (75) --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (75) Executing select query: SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='A4-04-19-10-D2-2F' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (23) Wed Dec 13 16:39:54 2017 : Debug: (75) EXPAND %{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'} Wed Dec 13 16:39:54 2017 : Debug: (75) --> 1 Wed Dec 13 16:39:54 2017 : Debug: (75) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) -> TRUE Wed Dec 13 16:39:54 2017 : Debug: (75) if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) { Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[post-auth]: calling ok (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[post-auth]: returned from ok (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (75) [ok] = ok Wed Dec 13 16:39:54 2017 : Debug: (75) } # if ("%{sql:SELECT COUNT(macaddress) FROM radmac WHERE macaddress ='%{Calling-Station-Id}'}" > 0) = ok Wed Dec 13 16:39:54 2017 : Debug: (75) ... skipping else: Preceding "if" was taken Wed Dec 13 16:39:54 2017 : Debug: (75) update { Wed Dec 13 16:39:54 2017 : Debug: (75) No attributes updated Wed Dec 13 16:39:54 2017 : Debug: (75) } # update = noop Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[post-auth]: calling exec (rlm_exec) Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[post-auth]: returned from exec (rlm_exec) Wed Dec 13 16:39:54 2017 : Debug: (75) [exec] = noop Wed Dec 13 16:39:54 2017 : Debug: (75) policy remove_reply_message_if_eap { Wed Dec 13 16:39:54 2017 : Debug: (75) if (&reply:EAP-Message && &reply:Reply-Message) { Wed Dec 13 16:39:54 2017 : Debug: (75) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (75) else { Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[post-auth]: calling noop (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (75) modsingle[post-auth]: returned from noop (rlm_always) Wed Dec 13 16:39:54 2017 : Debug: (75) [noop] = noop Wed Dec 13 16:39:54 2017 : Debug: (75) } # else = noop Wed Dec 13 16:39:54 2017 : Debug: (75) } # policy remove_reply_message_if_eap = noop Wed Dec 13 16:39:54 2017 : Debug: (75) } # post-auth = ok Wed Dec 13 16:39:54 2017 : Debug: (75) Sent Access-Accept Id 255 from 192.168.10.13:1812 to 10.100.100.114:1645 length 0 Wed Dec 13 16:39:54 2017 : Debug: (75) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (75) MS-MPPE-Recv-Key = 0x486fb959688d8e906b557ec62c85361250d02c1d6fc453b68af967fcda89a2b6 Wed Dec 13 16:39:54 2017 : Debug: (75) MS-MPPE-Send-Key = 0xe3def073214fa616aa59e9f3d67826d872b2872340cc925164c2fb01f4f575b8 Wed Dec 13 16:39:54 2017 : Debug: (75) EAP-Message = 0x03ed0004 Wed Dec 13 16:39:54 2017 : Debug: (75) Message-Authenticator = 0x00000000000000000000000000000000 Wed Dec 13 16:39:54 2017 : Debug: (75) Finished request Wed Dec 13 16:39:54 2017 : Debug: Thread 5 waiting to be assigned a request Wed Dec 13 16:39:54 2017 : Debug: Waking up in 0.2 seconds. Wed Dec 13 16:39:54 2017 : Debug: Thread 4 got semaphore Wed Dec 13 16:39:54 2017 : Debug: Thread 4 handling request 76, (16 handled so far) Wed Dec 13 16:39:54 2017 : Debug: (76) Received Accounting-Request Id 89 from 10.100.100.114:1646 to 192.168.10.13:1813 length 276 Wed Dec 13 16:39:54 2017 : Debug: (76) Called-Station-Id = "00-19-55-9F-DA-03" Wed Dec 13 16:39:54 2017 : Debug: (76) Calling-Station-Id = "A4-04-19-10-D2-2F" Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Session-Id = "0.0.0.0 host/ test0LAB.ar0s.is 06/15/93 19:39:08 00F30000" Wed Dec 13 16:39:54 2017 : Debug: (76) Framed-IP-Address = 1.133.138.32 Wed Dec 13 16:39:54 2017 : Debug: (76) Cisco-AVPair = "connect-progress=Auth Open" Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Session-Time = 31683 Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Input-Octets = 494380646 Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Output-Octets = 818956336 Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Input-Packets = 659213 Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Output-Packets = 1746529 Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Authentic = RADIUS Wed Dec 13 16:39:54 2017 : Debug: (76) User-Name = "host/test0LAB.ar0s.is" Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Status-Type = Interim-Update Wed Dec 13 16:39:54 2017 : Debug: (76) Cisco-NAS-Port = "FastEthernet0/3" Wed Dec 13 16:39:54 2017 : Debug: (76) NAS-Port = 50003 Wed Dec 13 16:39:54 2017 : Debug: (76) NAS-Port-Type = Ethernet Wed Dec 13 16:39:54 2017 : Debug: (76) Service-Type = Framed-User Wed Dec 13 16:39:54 2017 : Debug: (76) NAS-IP-Address = 10.100.100.114 Wed Dec 13 16:39:54 2017 : Debug: (76) Acct-Delay-Time = 0 Wed Dec 13 16:39:54 2017 : Debug: (76) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (76) preacct { Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[preacct]: calling preprocess (rlm_preprocess) Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[preacct]: returned from preprocess (rlm_preprocess) Wed Dec 13 16:39:54 2017 : Debug: (76) [preprocess] = ok Wed Dec 13 16:39:54 2017 : Debug: (76) policy acct_unique { Wed Dec 13 16:39:54 2017 : Debug: (76) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { Wed Dec 13 16:39:54 2017 : Debug: (76) EXPAND %{string:Class} Wed Dec 13 16:39:54 2017 : Debug: (76) --> Wed Dec 13 16:39:54 2017 : Debug: (76) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE Wed Dec 13 16:39:54 2017 : Debug: (76) else { Wed Dec 13 16:39:54 2017 : Debug: (76) update request { Wed Dec 13 16:39:54 2017 : Debug: (76) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Wed Dec 13 16:39:54 2017 : Debug: (76) --> b801a6e08d003be6367ecacee87e40d5 Wed Dec 13 16:39:54 2017 : Debug: (76) &Acct-Unique-Session-Id := b801a6e08d003be6367ecacee87e40d5 Wed Dec 13 16:39:54 2017 : Debug: (76) } # update request = noop Wed Dec 13 16:39:54 2017 : Debug: (76) } # else = noop Wed Dec 13 16:39:54 2017 : Debug: (76) } # policy acct_unique = noop Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[preacct]: calling suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (76) suffix: Checking for suffix after "@" Wed Dec 13 16:39:54 2017 : Debug: (76) suffix: No '@' in User-Name = "host/ test0LAB.ar0s.is", looking up realm NULL Wed Dec 13 16:39:54 2017 : Debug: (76) suffix: No such realm "NULL" Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[preacct]: returned from suffix (rlm_realm) Wed Dec 13 16:39:54 2017 : Debug: (76) [suffix] = noop Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[preacct]: calling files (rlm_files) Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[preacct]: returned from files (rlm_files) Wed Dec 13 16:39:54 2017 : Debug: (76) [files] = noop Wed Dec 13 16:39:54 2017 : Debug: (76) } # preacct = ok Wed Dec 13 16:39:54 2017 : Debug: (76) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default Wed Dec 13 16:39:54 2017 : Debug: (76) accounting { Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: calling detail (rlm_detail) Wed Dec 13 16:39:54 2017 : Debug: /mnt/DATA/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> /mnt/DATA/radius/radacct/ Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: attribute --> Packet-Src-IP-Address Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: attribute --> Packet-Src-IPv6-Address Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> /detail- Wed Dec 13 16:39:54 2017 : Debug: percent --> Y Wed Dec 13 16:39:54 2017 : Debug: percent --> m Wed Dec 13 16:39:54 2017 : Debug: percent --> d Wed Dec 13 16:39:54 2017 : Debug: (76) detail: EXPAND /mnt/DATA/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d Wed Dec 13 16:39:54 2017 : Debug: (76) detail: --> /mnt/DATA/radius/radacct/10.100.100.114/detail-20171213 Wed Dec 13 16:39:54 2017 : Debug: (76) detail: /mnt/DATA/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /mnt/DATA/radius/radacct/10.100.100.114/detail-20171213 Wed Dec 13 16:39:54 2017 : Debug: %t Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: percent --> t Wed Dec 13 16:39:54 2017 : Debug: (76) detail: EXPAND %t Wed Dec 13 16:39:54 2017 : Debug: (76) detail: --> Wed Dec 13 16:39:54 2017 Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: returned from detail (rlm_detail) Wed Dec 13 16:39:54 2017 : Debug: (76) [detail] = ok Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: calling unix (rlm_unix) Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: returned from unix (rlm_unix) Wed Dec 13 16:39:54 2017 : Debug: (76) [unix] = noop Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: calling sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: %{tolower:type.%{Acct-Status-Type}.query} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: xlat --> tolower Wed Dec 13 16:39:54 2017 : Debug: { Wed Dec 13 16:39:54 2017 : Debug: literal --> type. Wed Dec 13 16:39:54 2017 : Debug: attribute --> Acct-Status-Type Wed Dec 13 16:39:54 2017 : Debug: literal --> .query Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: (76) sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} Wed Dec 13 16:39:54 2017 : Debug: (76) sql: --> type.interim-update.query Wed Dec 13 16:39:54 2017 : Debug: (76) sql: Using query template 'query' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Reserved connection (22) Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (76) sql: EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (76) sql: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (76) sql: SQL-User-Name set to 'host/ test0LAB.ar0s.is' Wed Dec 13 16:39:54 2017 : Debug: 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}' Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> UPDATE radacct SET acctupdatetime = Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: xlat --> integer Wed Dec 13 16:39:54 2017 : Debug: { Wed Dec 13 16:39:54 2017 : Debug: literal --> Event-Timestamp Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: literal --> date('now') Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> , acctinterval = 0, framedipaddress = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> Framed-IP-Address Wed Dec 13 16:39:54 2017 : Debug: literal --> ', acctsessiontime = Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: attribute --> Acct-Session-Time Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: literal --> NULL Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> , acctinputoctets = Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: attribute --> Acct-Input-Gigawords Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: literal --> 0 Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> << 32 | Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: attribute --> Acct-Input-Octets Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: literal --> 0 Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> , acctoutputoctets = Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: attribute --> Acct-Output-Gigawords Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: literal --> 0 Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> << 32 | Wed Dec 13 16:39:54 2017 : Debug: XLAT-IF { Wed Dec 13 16:39:54 2017 : Debug: attribute --> Acct-Output-Octets Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: XLAT-ELSE { Wed Dec 13 16:39:54 2017 : Debug: literal --> 0 Wed Dec 13 16:39:54 2017 : Debug: } Wed Dec 13 16:39:54 2017 : Debug: literal --> WHERE AcctUniqueId = ' Wed Dec 13 16:39:54 2017 : Debug: attribute --> Acct-Unique-Session-Id Wed Dec 13 16:39:54 2017 : Debug: literal --> ' Wed Dec 13 16:39:54 2017 : Debug: (76) sql: EXPAND 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}' Wed Dec 13 16:39:54 2017 : Debug: (76) sql: --> UPDATE radacct SET acctupdatetime = 1513172394, acctinterval = 0, framedipaddress = '1.133.138.32', acctsessiontime = 31683, acctinputoctets = 0 << 32 | 494380646, acctoutputoctets = 0 << 32 | 818956336 WHERE AcctUniqueId = 'b801a6e08d003be6367ecacee87e40d5' Wed Dec 13 16:39:54 2017 : Debug: /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: literal --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (76) sql: EXPAND /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (76) sql: --> /mnt/DATA/radius/sqllog.sql Wed Dec 13 16:39:54 2017 : Debug: (76) sql: Executing query: UPDATE radacct SET acctupdatetime = 1513172394, acctinterval = 0, framedipaddress = '1.133.138.32', acctsessiontime = 31683, acctinputoctets = 0 << 32 | 494380646, acctoutputoctets = 0 << 32 | 818956336 WHERE AcctUniqueId = 'b801a6e08d003be6367ecacee87e40d5' Wed Dec 13 16:39:54 2017 : Debug: rlm_sql_mysql: Rows matched: 1 Changed: 1 Warnings: 1 Wed Dec 13 16:39:54 2017 : Debug: (76) sql: SQL query returned: success Wed Dec 13 16:39:54 2017 : Debug: (76) sql: 1 record(s) updated Wed Dec 13 16:39:54 2017 : Debug: rlm_sql (sql): Released connection (22) Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: returned from sql (rlm_sql) Wed Dec 13 16:39:54 2017 : Debug: (76) [sql] = ok Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: calling exec (rlm_exec) Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: returned from exec (rlm_exec) Wed Dec 13 16:39:54 2017 : Debug: (76) [exec] = noop Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) Wed Dec 13 16:39:54 2017 : Debug: %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: Parsed xlat tree: Wed Dec 13 16:39:54 2017 : Debug: attribute --> User-Name Wed Dec 13 16:39:54 2017 : Debug: (76) attr_filter.accounting_response: EXPAND %{User-Name} Wed Dec 13 16:39:54 2017 : Debug: (76) attr_filter.accounting_response: --> host/test0LAB.ar0s.is Wed Dec 13 16:39:54 2017 : Debug: (76) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Wed Dec 13 16:39:54 2017 : Debug: (76) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) Wed Dec 13 16:39:54 2017 : Debug: (76) [attr_filter.accounting_response] = updated Wed Dec 13 16:39:54 2017 : Debug: (76) } # accounting = updated Wed Dec 13 16:39:54 2017 : Debug: (76) Sent Accounting-Response Id 89 from 192.168.10.13:1813 to 10.100.100.114:1646 length 0 Wed Dec 13 16:39:54 2017 : Debug: (76) Finished request Wed Dec 13 16:39:54 2017 : Debug: Thread 4 waiting to be assigned a request Wed Dec 13 16:39:54 2017 : Debug: (76) Cleaning up request packet ID 89 with timestamp +2018 Wed Dec 13 16:39:54 2017 : Debug: Waking up in 0.5 seconds. Wed Dec 13 16:39:55 2017 : Debug: Waking up in 2.2 seconds. Wed Dec 13 16:39:57 2017 : Debug: (66) Cleaning up request packet ID 246 with timestamp +2016 Wed Dec 13 16:39:57 2017 : Debug: (67) Cleaning up request packet ID 247 with timestamp +2016 Wed Dec 13 16:39:57 2017 : Debug: (68) Cleaning up request packet ID 248 with timestamp +2016 Wed Dec 13 16:39:57 2017 : Debug: (69) Cleaning up request packet ID 249 with timestamp +2016 Wed Dec 13 16:39:57 2017 : Debug: (70) Cleaning up request packet ID 250 with timestamp +2016 Wed Dec 13 16:39:57 2017 : Debug: (71) Cleaning up request packet ID 251 with timestamp +2016 Wed Dec 13 16:39:57 2017 : Debug: (72) Cleaning up request packet ID 252 with timestamp +2016 Wed Dec 13 16:39:57 2017 : Debug: Waking up in 1.7 seconds. Wed Dec 13 16:39:59 2017 : Debug: (73) Cleaning up request packet ID 253 with timestamp +2016 Wed Dec 13 16:39:59 2017 : Debug: (74) Cleaning up request packet ID 254 with timestamp +2018 Wed Dec 13 16:39:59 2017 : Debug: (75) Cleaning up request packet ID 255 with timestamp +2018 Wed Dec 13 16:39:59 2017 : Info: Ready to process requests Regards

2 1

dot1x PEAPoMSChapv2 timers
by 3＠D4rkn3ss DuMb 14 Dec '17

14 Dec '17

Dear list, First, I must say that FreeRadius is in my humble opinion, the best open source project out there: top dev team, well documented, proactive mailing list, and above all, you can find it anywhere inside the security vendors solutions ... and that's a few of the advantages. I had to get that out of my chest before anything ... so Thank you for all the devs out there, for the idea and for making such a beautiful, stable and strong product ! I really hope that I would be able to contribute one day, even if its for the documentation since I m not good at coding :) Here come worries: I have setup inside 4 different companies a 802.1X solution (of course based on FreeRadius) and everything is working like a charm, (FreeRADIUS v 3.0.14) but in one of the secondary server (the main and the backup is linked through UCARP VRRP) which is currently serving around 400 supplicants, it is dropping the clients (randomly) after a timeout. below the setup (simple enough): FreeRADIUS authenticates the client (supplicants) to the AD, then verifies if its MAC address is authorized to connect or not. I suspect that is related to the following: Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: EXPAND --nt-response=%{%{mschap:NT-Response}:-00} Wed Dec 13 16:39:52 2017 : Debug: (73) mschap: --> --nt-response=ebe1377d01d09cbe0bfda9256149732ec2b94b30d4cbc327 Wed Dec 13 16:39:52 2017 : Debug: Waking up in 0.4 seconds. Wed Dec 13 16:39:53 2017 : Debug: Waking up in 0.7 seconds. Wed Dec 13 16:39:53 2017 : Debug: Waking up in 1.1 seconds. But I am not sure. If the above is however correct, does it mean that it is waiting for the AD to reply or is it just misbehaving ? Please find enclosed the full log for your reference. Regards

1 0

Re: winbindd_priv dont exist
by Carlos Bordon 13 Dec '17

13 Dec '17

i dont have other ldap, if i change the port or the ip of the AD i see it in debug, but no take this options..i dont known ________________________________ De: Freeradius-Users <freeradius-users-bounces+cgermanb=live.com.ar(a)lists.freeradius.org> en nombre de Alan DeKok <aland(a)deployingradius.com> Enviado: martes, 12 de diciembre de 2017 02:30 p.m. Para: FreeRadius users mailing list Asunto: Re: winbindd_priv dont exist On Dec 12, 2017, at 12:27 PM, Carlos Bordon <cgermanb(a)live.com.ar> wrote: > They are uncomment this options but nothing happend , try restarting too You need to restart the server after that configuration change. If you still see the same error, then you're editing one file, and the server is reading another one. Read the debug output to see which file is used for the LDAP module. Then, edit that file. Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html Support & Services<http://www.freeradius.org/list/users.html> www.freeradius.org The world's leading RADIUS server. The project includes a GPL AAA server, BSD licensed client and PAM and Apache modules. Full support is available from NetworkRADIUS.

3 13

Re: FreeRadius - Pass LDAP Group (Attribute?) to RSSO?
by Matthew Stavert 13 Dec '17

13 Dec '17

> *What, exactly do you need to do? Write that down, first. e.g.* I need to identify the group the user is in once they are authenticated, and then pass the users's group to the Dynamic RSSO group on the Fortigate using the Class attribute I believe. A picture is worth 1000 words...or something like that: [image: Inline image 2] The user names are being passed from freeradius, but the user's are not there. To pass the user's LDAP group, I believe I need to identify which group they are a part of in freeradius, and put that in CLASS. > * If they're a member of LDAP group X, send class Y.* >etc. Yes, this is what I need to do. If member of student, send Class=students, If member of admins send class=admins, if member of staff, send class=staff. Would I have to identify some of this in the LDAP module, or is free radius Version 3, smart enough to identity what group the user is a part of in LDAP? If it is, I imagine I can just move to implementing in unlang. If not...can you provide me with some guidance where I would start identifying or how I would identify what gorup the user was a part of in free radius, and what file that would go in? >*Then... implement that in unlang.* What conf file and area would be the best place to put the unlang if statements, IE: if User-Name is a member of students then Class = students if User-Name is a member staff then Class = Staff etc. >*And upgrade to v3. It will be infinitely easier to do this (and debug it), than in 2.1.1.* I will be upgrading to version 3 today, and getting this all going on the newest server. >Alan DeKok. -- ______________________________________________________________________________ *Matthew Stavert* - CIPS I.S.P, ITSM, ITIL Certified, Google APPS Certified, MCE - Microsoft Certified Educator, MTA Certified - Microsoft Technology Associate Information Systems Analyst - Systems Integration Specialist Northern Lights School Division No. 69 CIPS: Canada's Only Legally Recognized Professional Designation http://www.cips.ca Office: 780-826-3145 Cell : 780-207-1146

2 1