EAP session for state problem
Umut Arus
umuta at sabanciuniv.edu
Thu Jul 12 08:55:48 CEST 2012
Hi,
We are using freeradius2-2.1.12-3.el5 on RHEL 5.8 for eduroaming. Sometimes
we are getting "EAP session for state ... did not finish!" warning as you
can see on case 1. We can successfully login after every three or four
tries without error (case 2).
How can I overcome this problem?
PS: I think it is more problem on windows 7.
Case 1:
rad_recv: Access-Request packet from host 10.200.0.2 port 32832, id=203,
length=238
User-Name = "xxx at sabanciuniv.edu.tr"
NAS-IP-Address = 10.200.0.2
NAS-Port = 0
NAS-Identifier = "10.200.0.2"
NAS-Port-Type = Wireless-802.11
Calling-Station-Id = "1C659DA0C84D"
Called-Station-Id = "000B8661DFC4"
Service-Type = Login-User
Framed-MTU = 1100
EAP-Message =
0x020a002401676f6b68616e67756e796f6c40736162616e6369756e69762e6564752e7472
Aruba-Essid-Name = "eduroam"
Aruba-Location-Id = "BM_IT_Net_Sys_3c:02"
Aruba-Attr-10 = 0x424d5f62696e617369
Message-Authenticator = 0x7bde0503caf078e16964c30bb649186a
Thu Jul 12 08:50:06 2012 : Info: server eduroam {
Thu Jul 12 08:50:06 2012 : Info: # Executing section authorize from file
/etc/raddb/sites-enabled/eduroam
Thu Jul 12 08:50:06 2012 : Info: +- entering group authorize {...}
Thu Jul 12 08:50:06 2012 : Info: ++[preprocess] returns ok
Thu Jul 12 08:50:06 2012 : Info: [auth_log] expand:
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d ->
/var/log/radius/radacct/10.200.0.2/auth-detail-20120712
Thu Jul 12 08:50:06 2012 : Info: [auth_log]
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to
/var/log/radius/radacct/10.200.0.2/auth-detail-20120712
Thu Jul 12 08:50:06 2012 : Info: [auth_log] expand: %t -> Thu Jul
12 08:50:06 2012
Thu Jul 12 08:50:06 2012 : Info: ++[auth_log] returns ok
Thu Jul 12 08:50:06 2012 : Info: ++[mschap] returns noop
Thu Jul 12 08:50:06 2012 : Info: [suffix] Looking up realm "
sabanciuniv.edu.tr" for User-Name = "xxx at sabanciuniv.edu.tr"
Thu Jul 12 08:50:06 2012 : Info: [suffix] Found realm "sabanciuniv.edu.tr"
Thu Jul 12 08:50:06 2012 : Info: [suffix] Adding Stripped-User-Name = "xxx"
Thu Jul 12 08:50:06 2012 : Info: [suffix] Adding Realm = "sabanciuniv.edu.tr
"
Thu Jul 12 08:50:06 2012 : Info: [suffix] Authentication realm is LOCAL.
Thu Jul 12 08:50:06 2012 : Info: ++[suffix] returns ok
Thu Jul 12 08:50:06 2012 : Info: [eap] EAP packet type response id 10
length 36
Thu Jul 12 08:50:06 2012 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Thu Jul 12 08:50:06 2012 : Info: ++[eap] returns updated
Thu Jul 12 08:50:06 2012 : Info: ++[files] returns noop
Thu Jul 12 08:50:06 2012 : Info: ++[expiration] returns noop
Thu Jul 12 08:50:06 2012 : Info: ++[logintime] returns noop
Thu Jul 12 08:50:06 2012 : Info: Found Auth-Type = EAP
Thu Jul 12 08:50:06 2012 : Info: # Executing group from file
/etc/raddb/sites-enabled/eduroam
Thu Jul 12 08:50:06 2012 : Info: +- entering group authenticate {...}
Thu Jul 12 08:50:06 2012 : Info: [eap] EAP Identity
Thu Jul 12 08:50:06 2012 : Info: [eap] processing type tls
Thu Jul 12 08:50:06 2012 : Info: [tls] Initiate
Thu Jul 12 08:50:06 2012 : Info: [tls] Start returned 1
Thu Jul 12 08:50:06 2012 : Info: ++[eap] returns handled
Thu Jul 12 08:50:06 2012 : Info: } # server eduroam
Sending Access-Challenge of id 203 to 10.200.0.2 port 32832
EAP-Message = 0x010b00061920
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x470f24c947043df52dda4e1a3d9334ec
Thu Jul 12 08:50:06 2012 : Info: Finished request 61.
Thu Jul 12 08:50:06 2012 : Debug: Going to the next request
Thu Jul 12 08:50:06 2012 : Debug: Waking up in 4.9 seconds.
Thu Jul 12 08:50:11 2012 : Info: Cleaning up request 61 ID 203 with
timestamp +434
Thu Jul 12 08:50:11 2012 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Thu Jul 12 08:50:11 2012 : Debug: WARNING: !! EAP session for state
0x470f24c947043df5 did not finish!
Thu Jul 12 08:50:11 2012 : Debug: WARNING: !! Please read
http://wiki.freeradius.org/Certificate_Compatibility
Thu Jul 12 08:50:11 2012 : Debug: WARNING:
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
Case2:
rad_recv: Access-Request packet from host 10.200.0.2 port 32832, id=215,
length=263
User-Name = "xxx at sabanciuniv.edu.tr"
NAS-IP-Address = 10.200.0.2
NAS-Port = 0
NAS-Identifier = "10.200.0.2"
NAS-Port-Type = Wireless-802.11
Calling-Station-Id = "1C659DA0C84D"
Called-Station-Id = "000B8661DFC4"
Service-Type = Login-User
Framed-MTU = 1100
EAP-Message =
0x0216002b190017030100205cd73791c5a16b72af7729c38c0070ead9b5365d5c59a3cbf94d2d04ab1c88f0
State = 0x933acfe09a2cd6ffa50d9682f870ed3a
Aruba-Essid-Name = "eduroam"
Aruba-Location-Id = "BM_IT_Net_Sys_3c:02"
Aruba-Attr-10 = 0x424d5f62696e617369
Message-Authenticator = 0xee1ce87a79d10bcd3aab616fdf41e564
Thu Jul 12 08:50:20 2012 : Info: server eduroam {
Thu Jul 12 08:50:20 2012 : Info: # Executing section authorize from file
/etc/raddb/sites-enabled/eduroam
Thu Jul 12 08:50:20 2012 : Info: +- entering group authorize {...}
Thu Jul 12 08:50:20 2012 : Info: ++[preprocess] returns ok
Thu Jul 12 08:50:20 2012 : Info: [auth_log] expand:
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d ->
/var/log/radius/radacct/10.200.0.2/auth-detail-20120712
Thu Jul 12 08:50:20 2012 : Info: [auth_log]
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to
/var/log/radius/radacct/10.200.0.2/auth-detail-20120712
Thu Jul 12 08:50:20 2012 : Info: [auth_log] expand: %t -> Thu Jul
12 08:50:20 2012
Thu Jul 12 08:50:20 2012 : Info: ++[auth_log] returns ok
Thu Jul 12 08:50:20 2012 : Info: ++[mschap] returns noop
Thu Jul 12 08:50:20 2012 : Info: [suffix] Looking up realm "
sabanciuniv.edu.tr" for User-Name = "xxx at sabanciuniv.edu.tr"
Thu Jul 12 08:50:20 2012 : Info: [suffix] Found realm "sabanciuniv.edu.tr"
Thu Jul 12 08:50:20 2012 : Info: [suffix] Adding Stripped-User-Name = "xxx"
Thu Jul 12 08:50:20 2012 : Info: [suffix] Adding Realm = "sabanciuniv.edu.tr
"
Thu Jul 12 08:50:20 2012 : Info: [suffix] Authentication realm is LOCAL.
Thu Jul 12 08:50:20 2012 : Info: ++[suffix] returns ok
Thu Jul 12 08:50:20 2012 : Info: [eap] EAP packet type response id 22
length 43
Thu Jul 12 08:50:20 2012 : Info: [eap] Continuing tunnel setup.
Thu Jul 12 08:50:20 2012 : Info: ++[eap] returns ok
Thu Jul 12 08:50:20 2012 : Info: ++[files] returns noop
Thu Jul 12 08:50:20 2012 : Info: ++[expiration] returns noop
Thu Jul 12 08:50:20 2012 : Info: ++[logintime] returns noop
Thu Jul 12 08:50:20 2012 : Info: Found Auth-Type = EAP
Thu Jul 12 08:50:20 2012 : Info: # Executing group from file
/etc/raddb/sites-enabled/eduroam
Thu Jul 12 08:50:20 2012 : Info: +- entering group authenticate {...}
Thu Jul 12 08:50:20 2012 : Info: [eap] Request found, released from the list
Thu Jul 12 08:50:20 2012 : Info: [eap] EAP/peap
Thu Jul 12 08:50:20 2012 : Info: [eap] processing type peap
Thu Jul 12 08:50:20 2012 : Info: [peap] processing EAP-TLS
Thu Jul 12 08:50:20 2012 : Info: [peap] eaptls_verify returned 7
Thu Jul 12 08:50:20 2012 : Info: [peap] Done initial handshake
Thu Jul 12 08:50:20 2012 : Info: [peap] eaptls_process returned 7
Thu Jul 12 08:50:20 2012 : Info: [peap] EAPTLS_OK
Thu Jul 12 08:50:20 2012 : Info: [peap] Session established. Decoding
tunneled attributes.
Thu Jul 12 08:50:20 2012 : Info: [peap] Peap state send tlv success
Thu Jul 12 08:50:20 2012 : Info: [peap] Received EAP-TLV response.
Thu Jul 12 08:50:20 2012 : Info: [peap] Success
Thu Jul 12 08:50:20 2012 : Info: [peap] Using saved attributes from the
original Access-Accept
Cisco-AVPair = "ssid=sunet-staff-wpa2"
User-Name = "xxx"
Thu Jul 12 08:50:20 2012 : Info: [eap] Freeing handler
Thu Jul 12 08:50:20 2012 : Info: ++[eap] returns ok
Thu Jul 12 08:50:20 2012 : Info: # Executing section post-auth from file
/etc/raddb/sites-enabled/eduroam
Thu Jul 12 08:50:20 2012 : Info: +- entering group post-auth {...}
Thu Jul 12 08:50:20 2012 : Info: ++[exec] returns noop
Thu Jul 12 08:50:20 2012 : Info: } # server eduroam
Sending Access-Accept of id 215 to 10.200.0.2 port 32832
Cisco-AVPair = "ssid=sunet-staff-wpa2"
User-Name = "xxx"
MS-MPPE-Recv-Key =
0xaea8b6a844f0e161871649d32f4ead36d6441f8b878fe3e4052b2eb5a2ea7346
MS-MPPE-Send-Key =
0xb17c40cb6eed240c390bbe4ffbbe3ee66d5244b2b6390c3e2fe11844b239e89c
EAP-Message = 0x03160004
Message-Authenticator = 0x00000000000000000000000000000000
Thu Jul 12 08:50:20 2012 : Info: Finished request 72.
Thu Jul 12 08:50:20 2012 : Debug: Going to the next request
Thu Jul 12 08:50:20 2012 : Debug: Waking up in 3.2 seconds.
Thu Jul 12 08:50:23 2012 : Info: Cleaning up request 62 ID 205 with
timestamp +446
Thu Jul 12 08:50:23 2012 : Info: Cleaning up request 63 ID 206 with
timestamp +446
Thu Jul 12 08:50:23 2012 : Info: Cleaning up request 64 ID 207 with
timestamp +446
Thu Jul 12 08:50:23 2012 : Info: Cleaning up request 65 ID 208 with
timestamp +446
Thu Jul 12 08:50:23 2012 : Info: Cleaning up request 66 ID 209 with
timestamp +446
Thu Jul 12 08:50:23 2012 : Info: Cleaning up request 67 ID 210 with
timestamp +446
Thu Jul 12 08:50:23 2012 : Debug: Waking up in 1.6 seconds.
Thu Jul 12 08:50:25 2012 : Info: Cleaning up request 68 ID 211 with
timestamp +448
Thu Jul 12 08:50:25 2012 : Info: Cleaning up request 69 ID 212 with
timestamp +448
Thu Jul 12 08:50:25 2012 : Info: Cleaning up request 70 ID 213 with
timestamp +448
Thu Jul 12 08:50:25 2012 : Info: Cleaning up request 71 ID 214 with
timestamp +448
Thu Jul 12 08:50:25 2012 : Info: Cleaning up request 72 ID 215 with
timestamp +448
Thu Jul 12 08:50:25 2012 : Info: Ready to process requests.
thanks,
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120712/6dbf069e/attachment-0001.html>
More information about the Freeradius-Users
mailing list