Problem with EAP Authentication working not every time
Hello! we are using freeradius2 version 2.1.10 on a centos/rhel 5 Server. We authenticate several ubnt clients on ubnt AP's via EAP-PEAP/MSCHAPV2. This works very well, but sometimes the clients got an Access-Reject and i don't know why ;( I set the radius Server to debug mode and get those output: Waking up in 0.7 seconds. Waking up in 2.2 seconds. Waking up in 1.9 seconds. WARNING: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! WARNING: !! EAP session for state 0x69522edb6a233743 did not finish! WARNING: !! Please read http://wiki.freeradius.org/Certificate_Compatibility WARNING: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! Waking up in 0.3 seconds. Ready to process requests. Waking up in 0.9 seconds. [<thread>] # Executing section authorize from file /etc/raddb/sites-enabled/default rlm_sql (sql): Reserving sql socket id: 1 rlm_sql (sql): Released sql socket id: 1 # Executing group from file /etc/raddb/sites-enabled/default Waking up in 0.9 seconds. [<thread>] # Executing section authorize from file /etc/raddb/sites-enabled/default rlm_sql (sql): Reserving sql socket id: 0 rlm_sql (sql): Released sql socket id: 0 # Executing group from file /etc/raddb/sites-enabled/default Waking up in 0.9 seconds. [<thread>] # Executing section authorize from file /etc/raddb/sites-enabled/default # Executing group from file /etc/raddb/sites-enabled/default Waking up in 3.9 seconds. Waking up in 1.9 seconds. Waking up in 0.9 seconds. [<thread>] # Executing section authorize from file /etc/raddb/sites-enabled/default # Executing group from file /etc/raddb/sites-enabled/default rlm_eap: No EAP session matching the State variable. [eap] Either EAP-request timed out OR EAP-response to an unknown EAP-request Login incorrect: [m1588a00@EAP/<via Auth-Type = EAP>] (from client 10.55.0.0/16 port 0 cli 00-27-22-D2-CD-83) # Executing group from file /etc/raddb/sites-enabled/default rlm_sql (sql): Reserving sql socket id: 4 rlm_sql (sql): Released sql socket id: 4 Waking up in 0.9 seconds. The wiki talks about windows clients and decreasing the tunnel MTU. I'm not sure what they mean. How can i get a more detailed debug msg on what is actually wrong. thx for your help Stefan __________________ www.epb.at
On Wed, Aug 8, 2012 at 2:44 PM, stefan novak <lms.brubaker@gmail.com> wrote:
Hello!
we are using freeradius2 version 2.1.10 on a centos/rhel 5 Server. We authenticate several ubnt clients on ubnt AP's via EAP-PEAP/MSCHAPV2. This works very well, but sometimes the clients got an Access-Reject and i don't know why ;(
If it's "sometimes", then it would be wise to compare the debug log of when the client succeeds and when it does not. Also, IIRC RHEL5 has 2.1.12 already, so you should upgrade just in case this is a fixed bug. -- Fajar
If it's "sometimes", then it would be wise to compare the debug log of when the client succeeds and when it does not. Also, IIRC RHEL5 has 2.1.12 already, so you should upgrade just in case this is a fixed bug.
just updated my testserver to 2.1.12. I test now with rad_eap_test utility to eliminate a client failure. the behaviour gets more stranger. the test utility also fails sometimes, but the radius server seams to be ok now? [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 1 [root@wlan-radius rad_eap_test-0.23]# } # server inner-tunnel [peap] Got tunneled reply code 2 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 MS-MPPE-Send-Key = 0x5b1d5157a6d94d87d527c9aab7234a85 MS-MPPE-Recv-Key = 0x942bf481ca97760d330305771e0d2e09 EAP-Message = 0x03090004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "nagios" [peap] Got tunneled reply RADIUS code 2 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 MS-MPPE-Send-Key = 0x5b1d5157a6d94d87d527c9aab7234a85 MS-MPPE-Recv-Key = 0x942bf481ca97760d330305771e0d2e09 EAP-Message = 0x03090004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "nagios" [peap] Tunneled authentication was successful. [peap] SUCCESS ++[eap] returns handled Sending Access-Challenge of id 9 to 172.21.15.1 port 59848 EAP-Message = 0x010a003b19001703010030a46c09beb178741efc835036735026e09d8b1b1b44a88b55fce72fc28133dbf7e6edca8c0a65a6a2a85fd98eeeef2f6e Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc9f5fd31c0ffe486f9e2896c0b298eff Finished request 779. Going to the next request Waking up in 0.1 seconds. rad_recv: Access-Request packet from host 172.21.15.1 port 59848, id=10, length=226 User-Name = "nagios" NAS-IP-Address = 127.0.0.1 Calling-Station-Id = "70-6F-6C-69-73-68" Framed-MTU = 1400 NAS-Port-Type = Wireless-802.11 Connect-Info = "rad_eap_test + eapol_test" EAP-Message = 0x020a006019001703010020fcc074273699ca1e907af0200b96b3eaa01064887cff1a26b692f38602c3a48817030100309381801c8d424b14a2d053af534f137d1f632c69aa0572f0720bec578a1d6a61df79dc279e86b9f81d68dc6c81191e8f State = 0xc9f5fd31c0ffe486f9e2896c0b298eff Message-Authenticator = 0xb3249ed0ca17319a8d00741f734c974b # Executing section authorize from file /etc/raddb/sites-enabled/default +- entering group authorize {...} ++[preprocess] returns ok ++[chap] returns noop ++[mschap] returns noop ++[digest] returns noop [suffix] No '@' in User-Name = "nagios", looking up realm NULL [suffix] No such realm "NULL" ++[suffix] returns noop [eap] EAP packet type response id 10 length 96 [eap] Continuing tunnel setup. ++[eap] returns ok Found Auth-Type = EAP # Executing group from file /etc/raddb/sites-enabled/default +- entering group authenticate {...} [eap] Request found, released from the list [eap] EAP/peap [eap] processing type peap [peap] processing EAP-TLS [peap] eaptls_verify returned 7 [peap] Done initial handshake [peap] eaptls_process returned 7 [peap] EAPTLS_OK [peap] Session established. Decoding tunneled attributes. [peap] Peap state send tlv success [peap] Received EAP-TLV response. [peap] Success [eap] Freeing handler ++[eap] returns ok Login OK: [nagios/<via Auth-Type = EAP>] (from client 172.21.15.1 port 0 cli 70-6F-6C-69-73-68) # Executing section post-auth from file /etc/raddb/sites-enabled/default +- entering group post-auth {...} [sql] expand: %{User-Name} -> nagios [sql] sql_set_user escaped user --> 'nagios' [sql] expand: %{User-Password} -> [sql] ... expanding second conditional [sql] expand: %{Chap-Password} -> [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 ( 'nagios', '', 'Access-Accept', '2012-08-08 10:42:37') rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'nagios', '', 'Access-Accept', '2012-08-08 10:42:37') rlm_sql (sql): Reserving sql socket id: 2 rlm_sql (sql): Released sql socket id: 2 ++[sql] returns ok ++[exec] returns noop Sending Access-Accept of id 10 to 172.21.15.1 port 59848 MS-MPPE-Recv-Key = 0x3a1be0edbc8566fc1b291ff8d09a4892ad61da4dc4a33927088e7c700d478e12 MS-MPPE-Send-Key = 0x39a7512be1ea532b88619cf74533da41e180aeb57c6077287a98c82597f8cfa5 EAP-Message = 0x030a0004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "nagios" Finished request 780. Going to the next request Waking up in 0.1 seconds. -- kind regards, Stefan _______________________ www.epb.at - Your IT Partner in East Austria
Hi,
just updated my testserver to 2.1.12.
I test now with rad_eap_test utility to eliminate a client failure. the behaviour gets more stranger. the test utility also fails sometimes, but the radius server seams to be ok now? [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 1
where the fail? all those are access-accept. byt he way rad_eap_test isnt the best tool to use - use 'eapol_test' instead - comes as part of 'WPA_Supplicant' toolset....and FreeRADIUS has scripts ready to use with it (eg freeradius-server-2.1.12/src/tests from source) alan
On Wed, Aug 8, 2012 at 3:49 PM, alan buxey <A.L.M.Buxey@lboro.ac.uk> wrote:
byt he way rad_eap_test isnt the best tool to use - use 'eapol_test' instead
http://wiki.freeradius.org/EAP-Clients#rad_eap_test says rad_eap_test also uses eapol_test from wpa_supplicant. Shouldn't it produce the same behavior? -- Fajar
http://wiki.freeradius.org/EAP-Clients#rad_eap_test says rad_eap_test also uses eapol_test from wpa_supplicant. Shouldn't it produce the same behavior?
rad_eap_test is only a wrapper script around eapol_test because it
produces much output. Those are all access-accept, aren't they? The second number (reading
from http://wiki.eduroam.cz/rad_eap_test/README) should be latency, not an indication that something failed. CMIIW.
yes, sorry. understand that false.... ok, then it seams that radius server is ok, but the clients are generating false eap packets. i will post debug from those later, but debugging there is limited ;( -- kind regards, Stefan _______________________ www.epb.at - Your IT Partner in East Austria
Hi,
rad_eap_test is only a wrapper script around eapol_test because it produces much output.
yes..and i believe it has a bug or 2
yes, sorry. understand that false.... ok, then it seams that radius server is ok, but the clients are generating false eap packets. i will post debug from those later, but debugging there is limited ;(
when you say clients, you just mean these rad_eap_test requests? I assume you are using NAGIOS...and that occasionally you are getting a WARNING for the RADIUS server? yes? its a bug in rap_eap_test as far as I can see - I moved to a native eapol_test with my NAGIOS because of this bug. rad_eap_test is not maintained as far as i can see. alan
when you say clients, you just mean these rad_eap_test requests? I assume you are using NAGIOS...and that occasionally you are getting a WARNING for the RADIUS server? yes? its a bug in rap_eap_test as far as I can see - I moved to a native eapol_test with my NAGIOS because of this bug. rad_eap_test is not maintained as far as i can see.
no the real clients are Ubiquiti (www.ubnt.com) Nanostation M5 on Ubiquiti Rocket M5 AccessPoints. we encountered the problem that sometimes the rekey'ing from eap not works and disconnects the client. the radius logs then an "access-reject" now i am sure that the ubnt clients maybe the problem. now i am thinking of the next debug steps.... -- kind regards, Stefan _______________________ www.epb.at - Your IT Partner in East Austria
Output from the ubnt client: Aug 7 07:15:18 wpa-supplicant: CTRL-EVENT-EAP-STARTED EAP authentication started Aug 7 07:15:21 wpa-supplicant: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 25 (PEAP) selected Aug 7 07:15:57 pppd[1714]: No response to 5 echo-requests Aug 7 07:15:57 pppd[1714]: Serial link appears to be disconnected. Aug 7 07:15:57 pppd[1714]: Connect time 719.4 minutes. Aug 7 07:15:57 pppd[1714]: Sent 144586850 bytes, received 1342640159 bytes. Aug 7 07:16:06 pppd[1714]: Connection terminated. Aug 7 07:16:06 pppd[1714]: Modem hangup Aug 7 07:16:22 pppd[1714]: Timeout waiting for PADO packets Aug 7 07:16:22 pppd[1714]: Unable to complete PPPoE Discovery Aug 7 07:16:30 dnsmasq[1716]: no servers found in /etc/resolv.conf, will retry Aug 7 07:16:31 wpa-supplicant: CTRL-EVENT-EAP-FAILURE EAP authentication failed Aug 7 07:16:33 wpa-supplicant: Authentication with 00:27:22:4c:9c:1a timed out. Aug 7 07:16:33 wireless: ath0 Sending disassoc to 00:27:22:4c:9c:1a. Reason: Station has left the basic service area and is disassociated (8). Aug 7 07:16:33 wireless: ath0 New Access Point/Cell address:Not-Associated Aug 7 07:16:33 wpa-supplicant: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys -- kind regards, Stefan _______________________ www.epb.at - Your IT Partner in East Austria
I'm not 100% sure but as I know the UBNT equipment has introduced RADIUS client support in firmw. 5.x which is still active and under development... RADIUS MAC authentication was introduced in latest firmware (5.5) so I believe that some things are still not as they should. On 8.8.2012 11:59, stefan novak wrote:
when you say clients, you just mean these rad_eap_test requests? I assume you are using NAGIOS...and that occasionally you are getting a WARNING for the RADIUS server? yes? its a bug in rap_eap_test as far as I can see - I moved to a native eapol_test with my NAGIOS because of this bug. rad_eap_test is not maintained as far as i can see.
no the real clients are Ubiquiti (www.ubnt.com <http://www.ubnt.com>) Nanostation M5 on Ubiquiti Rocket M5 AccessPoints. we encountered the problem that sometimes the rekey'ing from eap not works and disconnects the client. the radius logs then an "access-reject"
now i am sure that the ubnt clients maybe the problem. now i am thinking of the next debug steps....
-- kind regards, Stefan _______________________ www.epb.at <http://www.epb.at> - Your IT Partner in East Austria
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
stefan novak wrote:
just updated my testserver to 2.1.12. I test now with rad_eap_test utility to eliminate a client failure. the behaviour gets more stranger. the test utility also fails sometimes, but the radius server seams to be ok now?
Your method is wrong. You ran the client 5 times. Yet you only looked at the debug output for one authentication. Look at BOTH ends of the RADIUS conversation. Alan DeKok.
On Wed, Aug 8, 2012 at 3:43 PM, stefan novak <lms.brubaker@gmail.com> wrote:
If it's "sometimes", then it would be wise to compare the debug log of when the client succeeds and when it does not. Also, IIRC RHEL5 has 2.1.12 already, so you should upgrade just in case this is a fixed bug.
just updated my testserver to 2.1.12. I test now with rad_eap_test utility to eliminate a client failure. the behaviour gets more stranger. the test utility also fails sometimes,
How did you determine that it fails?
[root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 0 [root@wlan-radius rad_eap_test-0.23]# ./rad_eap_test -H 172.21.15.1 -P 1812 -S testtest -u nagios -p xxxx -m WPA-EAP -e PEAP -2 MSCHAPV2 access-accept; 1
Those are all access-accept, aren't they? The second number (reading from http://wiki.eduroam.cz/rad_eap_test/README) should be latency, not an indication that something failed. CMIIW. -- Fajar
participants (5)
-
alan buxey -
Alan DeKok -
Fajar A. Nugraha -
Marinko Tarlać -
stefan novak