Authenticated device does not receive and IP, so continuously requests IP allocation
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.
On Oct 30, 2015, at 8:41 AM, Sophie Loewenthal <sophie.loewenthal@trimbletl.com> wrote:
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.
There are a few steps between authentication and the device receiving the IP. Is FreeRADIUS *sending* the correct IP? If so, the problem is the NAS. Nothing you do to FreeRADIUS will help. If not, then you can fix FreeRADIUS.
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.
Then it's probably the vodafone APN which is dropping the IP.
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
And not "radiusd -X", which is suggested in the FAQ, "man" page, web pages, and daily on this list. Which means you can't see what's in the Access-Request, or what's in the Access-Accept. That information is *critical* to solving the problem. PLEASE follow the documentation. Alan DeKok.
Thank-you for your help. Yes, FreeRADIUS did send the correct IP address for this APN. My suspicions has been their NAS or mobile network somewhere along the way. From man page: '-X Debugging mode. Equivalent to "-sfxx -l stdout". When trying to understand how the server works, ALWAYS run it with "radiusd -X".' If -X is the same as '-sfxx -l stdout' then would '-sfxx -l myradius.log' produce the same results as -X? On 30-Oct-15 1:49 PM, Alan DeKok wrote:
On Oct 30, 2015, at 8:41 AM, Sophie Loewenthal <sophie.loewenthal@trimbletl.com> wrote:
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.
There are a few steps between authentication and the device receiving the IP.
Is FreeRADIUS *sending* the correct IP? If so, the problem is the NAS. Nothing you do to FreeRADIUS will help.
If not, then you can fix FreeRADIUS.
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. Then it's probably the vodafone APN which is dropping the IP.
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 And not "radiusd -X", which is suggested in the FAQ, "man" page, web pages, and daily on this list.
Which means you can't see what's in the Access-Request, or what's in the Access-Accept. That information is *critical* to solving the problem.
PLEASE follow the documentation.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Fri, Oct 30, 2015 at 03:08:55PM +0100, Sophie Loewenthal wrote:
If -X is the same as '-sfxx -l stdout' then would '-sfxx -l myradius.log' produce the same results as -X?
Essentially, yes. -X is single-threaded -sfxx -l stdout is multi-threaded You may want to look at radmin when debugging packets on a running server. (I put some notes here, but I'm sure it's on the FreeRADIUS wiki somewhere as well http://notes.asd.me.uk/2014/09/16/debugging-freeradius-packets-with-radmin/ ) Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
On Oct 30, 2015, at 10:08 AM, Sophie Loewenthal <sophie.loewenthal@trimbletl.com> wrote:
Yes, FreeRADIUS did send the correct IP address for this APN. My suspicions has been their NAS or mobile network somewhere along the way.
From man page: '-X Debugging mode. Equivalent to "-sfxx -l stdout". When trying to understand how the server works, ALWAYS run it with "radiusd -X".'
If -X is the same as '-sfxx -l stdout' then would '-sfxx -l myradius.log' produce the same results as -X?
Yes. Alan DeKok.
Good morning, Below output was produced by running with '-sfxx -l myradius.log' I did see Access-Accept below The device did not receive an IP address. Thanks, S. Going to the next request Waking up in 0.9 seconds. Sending delayed reject for request 177598 Cleaning up request 177597 ID 219 with timestamp +131514 Waking up in 4.9 seconds. # Executing section authorize from file /etc/raddb/sites-enabled/default +- entering group authorize {...} ++[preprocess] returns ok ++[chap] returns noop ++[digest] returns noop [eap] No EAP-Message, not doing EAP ++[eap] returns noop [files] users: Matched entry DEFAULT at line 207 ++[files] returns ok [sql] expand: %{User-Name} -> 010101010 [sql] sql_set_user escaped user --> '010101010' rlm_sql (sql): Reserving sql socket id: 23 [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 = '010101010' ORDER BY id [sql] User found in radcheck table [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 = '010101010' ORDER BY id [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '010101010' ORDER BY priority [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.example.com' ORDER BY id [sql] User found in group vodafone.example.com [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.example.com' ORDER BY id rlm_sql (sql): Released sql socket id: 23 ++[sql] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated Found Auth-Type = PAP # Executing group from file /etc/raddb/sites-enabled/default +- entering group PAP {...} [pap] login attempt with password "XXXXXXXXXXXXXXXXXXXXXXXXXXXXX" [pap] Using clear text password "XXXXXXXXXXXXXXXXXXXXXXXXXXXXX" [pap] User authenticated successfully ++[pap] returns ok Login OK: [010101010] (from client vodafone-nas port 556657 cli 31655425447) # Executing section post-auth from file /etc/raddb/sites-enabled/default +- entering group post-auth {...} rlm_sql (sql): Reserving sql socket id: 22 [sqlippool] expand: %{User-Name} -> 010101010 [sqlippool] sql_set_user escaped user --> '010101010' [sqlippool] expand: START TRANSACTION -> START TRANSACTION [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 = '31655425447' [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 = '010101010' LIMIT 1 [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.16' AND username = '%{User-Name}' -> UPDATE radippool /* allocate-update */ SET nasipaddress = '172.200.100.1', pool_key = '31655425447', callingstationid = '31655425447', expiry_time = NOW() + INTERVAL 3600 SECOND, 3GPP_Imsi = '204045650449471', calledstationid = 'vodafone.example.com' WHERE framedipaddress = '10.26.0.16' AND username = '010101010' [sqlippool] Allocated IP 10.26.0.16 [10001a0a] [sqlippool] expand: COMMIT -> COMMIT rlm_sql (sql): Released sql socket id: 22 [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.16 from vodafone (did vodafone.example.com cli 31655425447 port 556657 user 010101010) Allocated IP: 10.26.0.16 from vodafone (did vodafone.example.com cli 31655425447 port 556657 user 010101010) ++[sqlippool] returns ok [sql] expand: %{User-Name} -> 010101010 [sql] sql_set_user escaped user --> '010101010' [sql] expand: %{User-Password} -> XXXXXXXXXXXXXXXXXXXXXXXXXXXXX [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 ( '010101010', 'XXXXXXXXXXXXXXXXXXXXXXXXXXXXX', 'Access-Accept', '2015-11-01 03:23:00') rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '010101010', 'XXXXXXXXXXXXXXXXXXXXXXXXXXXXX', 'Access-Accept', '2015-11-01 03:23:00') rlm_sql (sql): Reserving sql socket id: 21 rlm_sql (sql): Released sql socket id: 21 ++[sql] returns ok ++[exec] returns noop Finished request 177599. Going to the next request On 30-Oct-15 1:49 PM, Alan DeKok wrote:
On Oct 30, 2015, at 8:41 AM, Sophie Loewenthal <sophie.loewenthal@example.com> wrote:
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.
There are a few steps between authentication and the device receiving the IP.
Is FreeRADIUS *sending* the correct IP? If so, the problem is the NAS. Nothing you do to FreeRADIUS will help.
If not, then you can fix FreeRADIUS.
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. Then it's probably the vodafone APN which is dropping the IP.
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 And not "radiusd -X", which is suggested in the FAQ, "man" page, web pages, and daily on this list.
Which means you can't see what's in the Access-Request, or what's in the Access-Accept. That information is *critical* to solving the problem.
PLEASE follow the documentation.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (3)
-
Alan DeKok -
Matthew Newton -
Sophie Loewenthal