dot1x PEAPoMSChapv2 timers

14 Dec 2017

      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 !~ /@(.+)\.(.+)$/))  {
Wed Dec 13 16:39:52 2017 : Debug: (72)           if ((&User-Name =~ /@/) &&
(&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)  =
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 !~ /@(.+)\.(.+)$/))  {
Wed Dec 13 16:39:52 2017 : Debug: (73)           if ((&User-Name =~ /@/) &&
(&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)  =
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 !~ /@(.+)\.(.+)$/))  {
Wed Dec 13 16:39:54 2017 : Debug: (74)           if ((&User-Name =~ /@/) &&
(&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)  =
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

3＠D4rkn3ss DuMb

Matthew Newton

tags

participants (2)