Fri Oct 30 11:50:18 2015 : Debug: Thread 8 handling request 1648, (206 handled so far)
Fri Oct 30 11:50:18 2015 : Info: [<thread>] # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:50:18 2015 : Info: [<thread>] +- entering group authorize {...}
Fri Oct 30 11:50:18 2015 : Info: ++[preprocess] returns ok
Fri Oct 30 11:50:18 2015 : Info: ++[chap] returns noop
Fri Oct 30 11:50:18 2015 : Info: ++[digest] returns noop
Fri Oct 30 11:50:18 2015 : Info: [eap] No EAP-Message, not doing EAP
Fri Oct 30 11:50:18 2015 : Info: ++[eap] returns noop
Fri Oct 30 11:50:18 2015 : Info: [files] users: Matched entry DEFAULT at line 207
Fri Oct 30 11:50:18 2015 : Info: ++[files] returns ok
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:50:18 2015 : Info: [sql] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:50:18 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 14
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '00DELETED'           ORDER BY id
Fri Oct 30 11:50:18 2015 : Info: [sql] User found in radcheck table
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '00DELETED'           ORDER BY id
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '00DELETED'           ORDER BY priority
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = 'vodafone.exampleapn.com'           ORDER BY id
Fri Oct 30 11:50:18 2015 : Info: [sql] User found in group vodafone.exampleapn.com
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = 'vodafone.exampleapn.com'           ORDER BY id
Fri Oct 30 11:50:18 2015 : Debug: rlm_sql (sql): Released sql socket id: 14
Fri Oct 30 11:50:18 2015 : Info: ++[sql] returns ok
Fri Oct 30 11:50:18 2015 : Info: ++[expiration] returns noop
Fri Oct 30 11:50:18 2015 : Info: ++[logintime] returns noop
Fri Oct 30 11:50:18 2015 : Info: ++[pap] returns updated
Fri Oct 30 11:50:18 2015 : Info: Found Auth-Type = PAP
Fri Oct 30 11:50:18 2015 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:50:18 2015 : Info: +- entering group PAP {...}
Fri Oct 30 11:50:18 2015 : Info: [pap] login attempt with password "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"
Fri Oct 30 11:50:18 2015 : Info: [pap] Using clear text password "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"
Fri Oct 30 11:50:18 2015 : Info: [pap] User authenticated successfully
Fri Oct 30 11:50:18 2015 : Info: ++[pap] returns ok
Fri Oct 30 11:50:18 2015 : Auth: Login OK: [00DELETED] (from client vodafone-nas port 515582 cli 31611709725)
Fri Oct 30 11:50:18 2015 : Info: # Executing section post-auth from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:50:18 2015 : Info: +- entering group post-auth {...}
Fri Oct 30 11:50:18 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 13
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] 	expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] 	expand: START TRANSACTION -> START TRANSACTION
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] 	expand: UPDATE radippool /* allocate-clear */  SET nasipaddress = '', pool_key = 0,  callingstationid = '', calledstationid = '',  expiry_time = NULL, 3GPP_Imsi = ''  WHERE pool_key = '%{Calling-Station-Id}' -> UPDATE radippool /* allocate-clear */  SET nasipaddress = '', pool_key = 0,  callingstationid = '', calledstationid = '',  expiry_time = NULL, 3GPP_Imsi = ''  WHERE pool_key = '31611709725'
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] 	expand: SELECT framedipaddress FROM radippool   WHERE pool_name = '%{control:Pool-Name}'   AND username = '%{User-Name}' LIMIT 1 -> SELECT framedipaddress FROM radippool   WHERE pool_name = 'vodafone'   AND username = '00DELETED' LIMIT 1
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] 	expand: UPDATE radippool /* allocate-update */  SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{Calling-Station-Id}',  callingstationid = '%{Calling-Station-Id}',  expiry_time = NOW() + INTERVAL 3600 SECOND,  3GPP_Imsi = '%{3GPP-IMSI}', calledstationid = '%{Called-Station-Id}'  WHERE framedipaddress = '10.26.0.22' AND username = '%{User-Name}' -> UPDATE radippool /* allocate-update */  SET nasipaddress = '172.200.100.1', pool_key = '31611709725',  callingstationid = '31611709725',  expiry_time = NOW() + INTERVAL 3600 SECOND,  3GPP_Imsi = '204044870889430', calledstationid = 'vodafone.exampleapn.com'  WHERE framedipaddress = '10.26.0.22' AND username = '00DELETED'
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] Allocated IP 10.26.0.22 [16001a0a]
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] 	expand: COMMIT -> COMMIT
Fri Oct 30 11:50:18 2015 : Debug: rlm_sql (sql): Released sql socket id: 13
Fri Oct 30 11:50:18 2015 : Info: [sqlippool] 	expand: Allocated IP: %{reply:Framed-IP-Address} from %{control:Pool-Name}   (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name}) -> Allocated IP: 10.26.0.22 from vodafone   (did vodafone.exampleapn.com cli 31611709725 port 515582 user 00DELETED)
Fri Oct 30 11:50:18 2015 : Info: Allocated IP: 10.26.0.22 from vodafone   (did vodafone.exampleapn.com cli 31611709725 port 515582 user 00DELETED)
Fri Oct 30 11:50:18 2015 : Info: ++[sqlippool] returns ok
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:50:18 2015 : Info: [sql] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: %{User-Password} -> XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Fri Oct 30 11:50:18 2015 : Info: [sql] 	expand: INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '%{User-Name}',                           '%{%{User-Password}:-%{Chap-Password}}',                           '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '00DELETED',                           'XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX',                           'Access-Accept', '2015-10-30 11:50:18')
Fri Oct 30 11:50:18 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth                           (username, pass, reply, authdate)                           VALUES (                           '00DELETED',                           'XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX',                           'Access-Accept', '2015-10-30 11:50:18')
Fri Oct 30 11:50:18 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 12
Fri Oct 30 11:50:18 2015 : Debug: rlm_sql (sql): Released sql socket id: 12
Fri Oct 30 11:50:18 2015 : Info: ++[sql] returns ok
Fri Oct 30 11:50:18 2015 : Info: ++[exec] returns noop
Fri Oct 30 11:50:18 2015 : Info: Finished request 1648.
Fri Oct 30 11:50:18 2015 : Debug: Going to the next request
Fri Oct 30 11:50:18 2015 : Debug: Thread 8 waiting to be assigned a request
Fri Oct 30 11:50:18 2015 : Info: Sending delayed reject for request 1646
Fri Oct 30 11:50:18 2015 : Debug: Waking up in 0.2 seconds.
Fri Oct 30 11:50:18 2015 : Info: Sending duplicate reply to client vodafone-nas port 25088 - ID: 137
Fri Oct 30 11:50:18 2015 : Debug: Waking up in 0.2 seconds.
Fri Oct 30 11:50:18 2015 : Info: Cleaning up request 1627 ID 194 with timestamp +482
Fri Oct 30 11:50:18 2015 : Debug: Waking up in 0.1 seconds.
Fri Oct 30 11:50:19 2015 : Info: Cleaning up request 1630 ID 188 with timestamp +483
Fri Oct 30 11:50:19 2015 : Info: Cleaning up request 1647 ID 173 with timestamp +487
Fri Oct 30 11:50:19 2015 : Debug: Waking up in 0.4 seconds.
Fri Oct 30 11:50:19 2015 : Debug: Waking up in 0.3 seconds.
Fri Oct 30 11:50:19 2015 : Debug: Thread 4 got semaphore
Fri Oct 30 11:50:19 2015 : Debug: Thread 4 handling request 1649, (207 handled so far)