EAP session for state problem

12 Jul 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@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@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@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@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,

EAP session for state problem

Umut Arus