Authenticated device does not receive and IP, so continuously requests IP allocation
Sophie Loewenthal
sophie.loewenthal at trimbletl.com
Fri Oct 30 13:41:21 CET 2015
Hi,
For a few weeks some devices have had their IP allocation "lost" en
route. They authenticate, and IP is allocated but not received by the
device. Afterwards a device continuously asking for an IP address,
being allocated, and then asking again.
This has happened intermittently with some devices on Vodafone APN. I
did not see devices on other APNs affected.
Please see the three Radius requests in debug mode at the end of this
email in attachments. They are small files of approx 10Kb and were
collected with options to radiusd -xxx
/etc/raddb/users ( with comments and empty lines stripped but willing
to resend if empty lines and # comments are needed )
# grep -v ^# users | grep -v ^$
DEFAULT NAS-IP-Address == 172.200.100.1, Pool-Name := vodafone
DEFAULT NAS-IP-Address == 10.19.255.254, Pool-Name := proximus-carli
DEFAULT NAS-IP-Address == 10.17.255.254, Pool-Name := proximus-mechelen
DEFAULT
Framed-IP-Netmask = 255.255.255.255
O/S and packages
Centos 6.2
freeradius-mysql-2.1.12-1.el6.x86_64
freeradius-utils-2.1.12-1.el6.x86_64
freeradius-2.1.12-1.el6.x86_64
Example from logs:
Thu Oct 29 00:00:15 2015 : Auth: Login OK: [000006156] (from client
vodafone-nas port 594301 cli 31655418538)
Thu Oct 29 00:00:15 2015 : Info: Allocated IP: 10.26.0.61 from
vodafone (did vodafone.exampleapn.com cli 31655418538 port 594301 user
000006156)
Thu Oct 29 00:01:12 2015 : Auth: Login OK: [000006156] (from client
vodafone-nas port 146587 cli 31655418538)
Thu Oct 29 00:01:12 2015 : Info: Allocated IP: 10.26.0.61 from
vodafone (did vodafone.exampleapn.com cli 31655418538 port 146587 user
000006156)
Thu Oct 29 00:02:39 2015 : Auth: Login OK: [000006156] (from client
vodafone-nas port 983132 cli 31655418538)
Thu Oct 29 00:02:39 2015 : Info: Allocated IP: 10.26.0.61 from
vodafone (did vodafone.exampleapn.com cli 31655418538 port 983132 user
000006156)
Thu Oct 29 00:05:01 2015 : Auth: Login OK: [000006156] (from client
vodafone-nas port 928184 cli 31655418538)
Thu Oct 29 00:05:01 2015 : Info: Allocated IP: 10.26.0.61 from
vodafone (did vodafone.exampleapn.com cli 31655418538 port 928184 user
000006156)
Thu Oct 29 00:07:33 2015 : Auth: Login OK: [000006156] (from client
vodafone-nas port 575003 cli 31655418538)
Thu Oct 29 00:07:33 2015 : Info: Allocated IP: 10.26.0.61 from
vodafone (did vodafone.exampleapn.com cli 31655418538 port 575003 user
000006156)
Thu Oct 29 00:08:27 2015 : Auth: Login OK: [000006156] (from client
vodafone-nas port 728168 cli 31655418538)
Thu Oct 29 00:08:27 2015 : Info: Allocated IP: 10.26.0.61 from
vodafone (did vodafone.exampleapn.com cli 31655418538 port 728168 user
000006156)
This happens continuously amounting to 1000s of IP allocations daily.
I do not see Info: Released IP entries for this device. ( there were
some earlier this month. )
I have tcpdump running with : tcpdump -s0 -ni eth0 port 1812 or port
1813 or port 3799 -vw /tmp/rad.pcap
Some questions,
- Could my ippool run out of addresses because the device is
continuously requesting IP addresses?
- Would you offer any improvements on the tcpdump parameters?
- How could I check if Radius really sent the packet back to the client?
- (wireshark/tcpdump question: Is there an expression I could use to
find the radius packet sent back for Info: Allocated IP?
e.g I could radius.User_Name == "00000123" in wireshark to find
User-Name we used for authentication.
Is there any useful info in the attached debugs indicating problems?
Like why the device did not receive an IP.
If not then I can start looking into networks/vpn and vodafone.
Kind regards.
-------------- next part --------------
Fri Oct 30 11:47:45 2015 : Info: [<thread>] # Executing section authorize from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:47:45 2015 : Info: [<thread>] +- entering group authorize {...}
Fri Oct 30 11:47:45 2015 : Info: ++[preprocess] returns ok
Fri Oct 30 11:47:45 2015 : Info: ++[chap] returns noop
Fri Oct 30 11:47:45 2015 : Info: ++[digest] returns noop
Fri Oct 30 11:47:45 2015 : Info: [eap] No EAP-Message, not doing EAP
Fri Oct 30 11:47:45 2015 : Info: ++[eap] returns noop
Fri Oct 30 11:47:45 2015 : Info: [files] users: Matched entry DEFAULT at line 207
Fri Oct 30 11:47:45 2015 : Info: ++[files] returns ok
Fri Oct 30 11:47:45 2015 : Info: [sql] expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:47:45 2015 : Info: [sql] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:47:45 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 14
Fri Oct 30 11:47:45 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:47:45 2015 : Info: [sql] User found in radcheck table
Fri Oct 30 11:47:45 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:47:45 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:47:45 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:47:45 2015 : Info: [sql] User found in group vodafone.exampleapn.com
Fri Oct 30 11:47:45 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:47:45 2015 : Debug: rlm_sql (sql): Released sql socket id: 14
Fri Oct 30 11:47:45 2015 : Info: ++[sql] returns ok
Fri Oct 30 11:47:45 2015 : Info: ++[expiration] returns noop
Fri Oct 30 11:47:45 2015 : Info: ++[logintime] returns noop
Fri Oct 30 11:47:45 2015 : Info: ++[pap] returns updated
Fri Oct 30 11:47:45 2015 : Info: Found Auth-Type = PAP
Fri Oct 30 11:47:45 2015 : Info: # Executing group from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:47:45 2015 : Info: +- entering group PAP {...}
Fri Oct 30 11:47:45 2015 : Info: [pap] login attempt with password ""
Fri Oct 30 11:47:45 2015 : Info: [pap] Using clear text password "5"
Fri Oct 30 11:47:45 2015 : Info: [pap] User authenticated successfully
Fri Oct 30 11:47:45 2015 : Info: ++[pap] returns ok
Fri Oct 30 11:47:45 2015 : Auth: Login OK: [00DELETED] (from client vodafone-nas port 63885 cli 31611709725)
Fri Oct 30 11:47:45 2015 : Info: # Executing section post-auth from file /etc/raddb/sites-enabled/default
Fri Oct 30 11:47:45 2015 : Info: +- entering group post-auth {...}
Fri Oct 30 11:47:45 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 13
Fri Oct 30 11:47:45 2015 : Info: [sqlippool] expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:47:45 2015 : Info: [sqlippool] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:47:45 2015 : Info: [sqlippool] expand: START TRANSACTION -> START TRANSACTION
Fri Oct 30 11:47:45 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:47:45 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:47:45 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:47:45 2015 : Info: [sqlippool] Allocated IP 10.26.0.22 [16001a0a]
Fri Oct 30 11:47:45 2015 : Info: [sqlippool] expand: COMMIT -> COMMIT
Fri Oct 30 11:47:45 2015 : Debug: rlm_sql (sql): Released sql socket id: 13
Fri Oct 30 11:47:45 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 63885 user 00DELETED)
Fri Oct 30 11:47:45 2015 : Info: Allocated IP: 10.26.0.22 from vodafone (did vodafone.exampleapn.com cli 31611709725 port 63885 user 00DELETED)
Fri Oct 30 11:47:45 2015 : Info: ++[sqlippool] returns ok
Fri Oct 30 11:47:45 2015 : Info: [sql] expand: %{User-Name} -> 00DELETED
Fri Oct 30 11:47:45 2015 : Info: [sql] sql_set_user escaped user --> '00DELETED'
Fri Oct 30 11:47:45 2015 : Info: [sql] expand: %{User-Password} -> XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
Fri Oct 30 11:47:45 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:47:45')
Fri Oct 30 11:47:45 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:47:45')
Fri Oct 30 11:47:45 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 12
Fri Oct 30 11:47:45 2015 : Debug: rlm_sql (sql): Released sql socket id: 12
Fri Oct 30 11:47:45 2015 : Info: ++[sql] returns ok
Fri Oct 30 11:47:45 2015 : Info: ++[exec] returns noop
Fri Oct 30 11:47:45 2015 : Info: Finished request 1155.
-------------- next part --------------
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
-------------- next part --------------
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)
More information about the Freeradius-Users
mailing list