Fri Oct 30 11:48:33 2015 : Info: [<thread>] # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:48:33 2015 : Info: [<thread>] +- entering group authorize {...}
Fri Oct 30 11:48:33 2015 : Info: ++[preprocess] returns ok
Fri Oct 30 11:48:33 2015 : Info: ++[chap] returns noop
Fri Oct 30 11:48:33 2015 : Info: ++[digest] returns noop
Fri Oct 30 11:48:33 2015 : Info: [eap] No EAP-Message, not doing EAP
Fri Oct 30 11:48:33 2015 : Info: ++[eap] returns noop
Fri Oct 30 11:48:33 2015 : Info: [files] users: Matched entry DEFAULT at line 207
Fri Oct 30 11:48:33 2015 : Info: ++[files] returns ok
Fri Oct 30 11:48:33 2015 : Info: [sql] 	expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:48:33 2015 : Info: [sql] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:48:33 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Fri Oct 30 11:48:33 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:48:33 2015 : Info: [sql] User found in radcheck table
Fri Oct 30 11:48:33 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:48:33 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:48:33 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:48:33 2015 : Info: [sql] User found in group vodafone.exampleapn.com
Fri Oct 30 11:48:33 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:48:33 2015 : Debug: rlm_sql (sql): Released sql socket id: 2
Fri Oct 30 11:48:33 2015 : Info: ++[sql] returns ok
Fri Oct 30 11:48:33 2015 : Info: ++[expiration] returns noop
Fri Oct 30 11:48:33 2015 : Info: ++[logintime] returns noop
Fri Oct 30 11:48:33 2015 : Info: ++[pap] returns updated
Fri Oct 30 11:48:33 2015 : Info: Found Auth-Type = PAP
Fri Oct 30 11:48:33 2015 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:48:33 2015 : Info: +- entering group PAP {...}
Fri Oct 30 11:48:33 2015 : Info: [pap] login attempt with password ""
Fri Oct 30 11:48:33 2015 : Info: [pap] Using clear text password ""
Fri Oct 30 11:48:33 2015 : Info: [pap] User authenticated successfully
Fri Oct 30 11:48:33 2015 : Info: ++[pap] returns ok
Fri Oct 30 11:48:33 2015 : Auth: Login OK: [00DELETED] (from client vodafone-nas port 1307846 cli 31611709725)
Fri Oct 30 11:48:33 2015 : Info: # Executing section post-auth from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:48:33 2015 : Info: +- entering group post-auth {...}
Fri Oct 30 11:48:33 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 1
Fri Oct 30 11:48:33 2015 : Info: [sqlippool] 	expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:48:33 2015 : Info: [sqlippool] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:48:33 2015 : Info: [sqlippool] 	expand: START TRANSACTION -> START TRANSACTION
Fri Oct 30 11:48:33 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:48:33 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:48:33 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:48:33 2015 : Info: [sqlippool] Allocated IP 10.26.0.22 [16001a0a]
Fri Oct 30 11:48:33 2015 : Info: [sqlippool] 	expand: COMMIT -> COMMIT
Fri Oct 30 11:48:33 2015 : Debug: rlm_sql (sql): Released sql socket id: 1
Fri Oct 30 11:48:33 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 1307846 user 00DELETED)
Fri Oct 30 11:48:33 2015 : Info: Allocated IP: 10.26.0.22 from vodafone   (did vodafone.exampleapn.com cli 31611709725 port 1307846 user 00DELETED)
Fri Oct 30 11:48:33 2015 : Info: ++[sqlippool] returns ok
Fri Oct 30 11:48:33 2015 : Info: [sql] 	expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:48:33 2015 : Info: [sql] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:48:33 2015 : Info: [sql] 	expand: %{User-Password} -> 59C4D83C01F0A86496501604BBE8FF68
Fri Oct 30 11:48:33 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:48:33')
Fri Oct 30 11:48:33 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:48:33')
Fri Oct 30 11:48:33 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 0
Fri Oct 30 11:48:33 2015 : Debug: rlm_sql (sql): Released sql socket id: 0
Fri Oct 30 11:48:33 2015 : Info: ++[sql] returns ok
Fri Oct 30 11:48:33 2015 : Info: ++[exec] returns noop
Fri Oct 30 11:48:33 2015 : Info: Finished request 1282.
Fri Oct 30 11:48:33 2015 : Debug: Going to the next request
Fri Oct 30 11:48:33 2015 : Debug: Thread 4 waiting to be assigned a request
Fri Oct 30 11:48:33 2015 : Info: Cleaning up request 1281 ID 203 with timestamp +381
Fri Oct 30 11:48:33 2015 : Debug: Waking up in 0.6 seconds.
Fri Oct 30 11:48:34 2015 : Debug: Waking up in 0.3 seconds.
Fri Oct 30 11:48:34 2015 : Debug: Thread 7 got semaphore
Fri Oct 30 11:48:34 2015 : Debug: Thread 7 handling request 1283, (161 handled so far)
Fri Oct 30 11:48:34 2015 : Info: [<thread>] # Executing section preacct from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:48:34 2015 : Info: [<thread>] +- entering group preacct {...}
Fri Oct 30 11:48:34 2015 : Info: ++[preprocess] returns ok
Fri Oct 30 11:48:34 2015 : Info: [acct_unique] Hashing 'NAS-Port = 860594,Client-IP-Address = 172.200.100.1,NAS-IP-Address = 172.200.100.1,Acct-Session-Id = "3E8C8013443C502A",User-Name = "0000016dd"'
Fri Oct 30 11:48:34 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "69e97430d3eefb9b".
Fri Oct 30 11:48:34 2015 : Info: ++[acct_unique] returns ok
Fri Oct 30 11:48:34 2015 : Info: ++[files] returns noop
Fri Oct 30 11:48:34 2015 : Info: # Executing section accounting from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:48:34 2015 : Info: +- entering group accounting {...}
Fri Oct 30 11:48:34 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 23
Fri Oct 30 11:48:34 2015 : Info: [sqlippool] 	expand: %{User-Name} -> 0000016dd
Fri Oct 30 11:48:34 2015 : Info: [sqlippool] sql_set_user escaped user --> '0000016dd'
Fri Oct 30 11:48:34 2015 : Info: [sqlippool] 	expand: START TRANSACTION -> START TRANSACTION
Fri Oct 30 11:48:34 2015 : Info: [sqlippool] 	expand: UPDATE radippool /* stop-clear */  SET nasipaddress = '', pool_key = 0, callingstationid = '',  expiry_time = NULL, 3GPP_Imsi = '', calledstationid = ''  WHERE nasipaddress = '%{Nas-IP-Address}' AND pool_key = '%{Calling-Station-Id}'  AND username = '%{User-Name}'  AND callingstationid = '%{Calling-Station-Id}'  AND framedipaddress = '%{Framed-IP-Address}' -> UPDATE radippool /* stop-clear */  SET nasipaddress = '', pool_key = 0, callingstationid = '',  expiry_time = NULL, 3GPP_Imsi = '', calledstationid = ''  WHERE nasipaddress = '172.200.100.1' AND pool_key = '31611602387'  AND username = '0000016dd'  AND callingstationid = '31611602387'  AND framedipaddress = '10.26.26.90'
Fri Oct 30 11:48:34 2015 : Info: [sqlippool] 	expand: COMMIT -> COMMIT
Fri Oct 30 11:48:34 2015 : Info: [sqlippool] 	expand: Released IP %{Framed-IP-Address} (did %{Called-Station-Id} cli %{Calling-Station-Id} user %{User-Name}) -> Released IP 10.26.26.90 (did vodafone.exampleapn.com cli 31611602387 user 0000016dd)
Fri Oct 30 11:48:34 2015 : Info: Released IP 10.26.26.90 (did vodafone.exampleapn.com cli 31611602387 user 0000016dd)
Fri Oct 30 11:48:34 2015 : Debug: rlm_sql (sql): Released sql socket id: 23
Fri Oct 30 11:48:34 2015 : Info: ++[sqlippool] returns ok
Fri Oct 30 11:48:34 2015 : Info: [sql] 	expand: %{User-Name} -> 0000016dd
Fri Oct 30 11:48:34 2015 : Info: [sql] sql_set_user escaped user --> '0000016dd'
Fri Oct 30 11:48:34 2015 : Info: [sql] 	expand: %{Acct-Input-Gigawords} -> 
Fri Oct 30 11:48:34 2015 : Info: [sql] 	... expanding second conditional
Fri Oct 30 11:48:34 2015 : Info: [sql] 	expand: %{Acct-Input-Octets} -> 5463
Fri Oct 30 11:48:34 2015 : Info: [sql] 	expand: %{Acct-Output-Gigawords} -> 
Fri Oct 30 11:48:34 2015 : Info: [sql] 	... expanding second conditional
Fri Oct 30 11:48:34 2015 : Info: [sql] 	expand: %{Acct-Output-Octets} -> 2407
Fri Oct 30 11:48:34 2015 : Info: [sql] 	expand: %{Acct-Delay-Time} -> 
Fri Oct 30 11:48:34 2015 : Info: [sql] 	... expanding second conditional
Fri Oct 30 11:48:34 2015 : Info: [sql] 	expand:            UPDATE radacct SET              acctstoptime       = '%S',              acctsessiontime    = '%{Acct-Session-Time}',              acctinputoctets    = '%{%{Acct-Input-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets   = '%{%{Acct-Output-Gigawords}:-0}' << 32 |                                   '%{%{Acct-Output-Octets}:-0}',              acctterminatecause = '%{Acct-Terminate-Cause}',              acctstopdelay      = '%{%{Acct-Delay-Time}:-0}',              connectinfo_stop   = '%{Connect-Info}'           WHERE acctsessionid   = '%{Acct-Session-Id}'           AND username          = '%{SQL-User-Name}'           AND nasipaddress      = '%{NAS-IP-Address}' ->            UPDATE radacct SET              acctstoptime       = '2015-10-30 11:48:34',              acctsessiontime    = '831',              acctinputoctets    = '0' << 32 |                                   '5463',              acctoutputoctets   = '0' << 32 | 
Fri Oct 30 11:48:34 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 22
Fri Oct 30 11:48:34 2015 : Debug: rlm_sql (sql): Released sql socket id: 22
Fri Oct 30 11:48:34 2015 : Info: ++[sql] returns ok
Fri Oct 30 11:48:34 2015 : Info: ++[exec] returns noop
Fri Oct 30 11:48:34 2015 : Info: [attr_filter.accounting_response] 	expand: %{User-Name} -> 0000016dd
Fri Oct 30 11:48:34 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12
Fri Oct 30 11:48:34 2015 : Info: ++[attr_filter.accounting_response] returns updated
Fri Oct 30 11:48:34 2015 : Info: Finished request 1283.
Fri Oct 30 11:48:34 2015 : Debug: Going to the next request
Fri Oct 30 11:48:34 2015 : Debug: Thread 7 waiting to be assigned a request
Fri Oct 30 11:48:34 2015 : Info: Cleaning up request 1273 ID 113 with timestamp +378