reauth-problem with WPA2-tls

2 Jun 2010

      Hello,

I'm using freeradius 2.1.8 with wpa_supplicant 0.7.1, both on
32bit-linux with openssl 1.0.0 or openssl 0.9.8. AP is a Linksys WAP610N.

In eap.conf, the option eap -> tls -> cache -> enable is switched off
and fast_reauth in wpa_supplicant is enabled.

The initial login works fine. But there seems to be a problem to fill
the cache during initial login:

rad_recv: Access-Request packet from host 192.168.1.9 port 2048, id=50,
length=178
        User-Name = "myuser@mydom"
        NAS-Port = 0
        Called-Station-Id = "00-25-....:mywlan"
        Calling-Station-Id = "00-13-..."
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = 0x020800060d00
        State = 0x89d58d3e8edd800104fb11e3a0338e57
        Message-Authenticator = 0xe8f5eca1715e4bd2ecfa23c444efe859
Wed Jun  2 20:29:14 2010 : Info: +- entering group authorize {...}
Wed Jun  2 20:29:14 2010 : Info: ++[preprocess] returns ok
Wed Jun  2 20:29:14 2010 : Info: ++[chap] returns noop
Wed Jun  2 20:29:14 2010 : Info: ++[mschap] returns noop
Wed Jun  2 20:29:14 2010 : Info: [suffix] Looking up realm "mydom" for
User-Name = "myuser@mydom"
Wed Jun  2 20:29:14 2010 : Info: [suffix] No such realm "mydom"
Wed Jun  2 20:29:14 2010 : Info: ++[suffix] returns noop
Wed Jun  2 20:29:14 2010 : Info: [eap] EAP packet type response id 8
length 6
Wed Jun  2 20:29:14 2010 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Jun  2 20:29:14 2010 : Info: ++[eap] returns updated
Wed Jun  2 20:29:14 2010 : Info: ++[unix] returns notfound
Wed Jun  2 20:29:14 2010 : Info: [files] users: Matched entry
myuser@mydom at line 203
Wed Jun  2 20:29:14 2010 : Info: ++[files] returns ok
Wed Jun  2 20:29:14 2010 : Info: ++[expiration] returns noop
Wed Jun  2 20:29:14 2010 : Info: ++[logintime] returns noop
Wed Jun  2 20:29:14 2010 : Info: ++[pap] returns noop
Wed Jun  2 20:29:14 2010 : Info: Found Auth-Type = EAP
Wed Jun  2 20:29:14 2010 : Info: +- entering group authenticate {...}
Wed Jun  2 20:29:14 2010 : Info: [eap] Request found, released from the list
Wed Jun  2 20:29:14 2010 : Info: [eap] EAP/tls
Wed Jun  2 20:29:14 2010 : Info: [eap] processing type tls
Wed Jun  2 20:29:14 2010 : Info: [tls] Authenticate
Wed Jun  2 20:29:14 2010 : Info: [tls] processing EAP-TLS
Wed Jun  2 20:29:14 2010 : Info: [tls] Received TLS ACK
Wed Jun  2 20:29:14 2010 : Info: [tls] ACK handshake is finished
Wed Jun  2 20:29:14 2010 : Info: [tls] eaptls_verify returned 3
Wed Jun  2 20:29:14 2010 : Info: [tls] eaptls_process returned 3
Wed Jun  2 20:29:14 2010 : Info: [tls] Adding user data to cached session
Wed Jun  2 20:29:14 2010 : Info: [tls] Saving response in the cache
Wed Jun  2 20:29:14 2010 : Info: [tls] WARNING: No information to cache:
session caching will be disabled for this session.

If the reconnect takes place, the missing cache-data seems to be the
problem -> the user cannot be authenticated:

rad_recv: Access-Request packet from host 192.168.1.9 port 2048, id=55,
length=237
        User-Name = "myuser@mydom"
        NAS-Port = 0
        Called-Station-Id = "00-25-...:mywlan"
        Calling-Station-Id = "00-13-..."
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = ...df1e94bea7671e5b6cf4571cf262db282b055d78ab191a3
        State = 0x01880c0103840161cd60973c24894f7d
        Message-Authenticator = 0xf8b7771a372c0768720c9bf05de8708b
Wed Jun  2 20:39:18 2010 : Info: +- entering group authorize {...}
Wed Jun  2 20:39:18 2010 : Info: ++[preprocess] returns ok
Wed Jun  2 20:39:18 2010 : Info: ++[chap] returns noop
Wed Jun  2 20:39:18 2010 : Info: ++[mschap] returns noop
Wed Jun  2 20:39:18 2010 : Info: [suffix] Looking up realm "mydom" for
User-Name = "myuser@mydom"
Wed Jun  2 20:39:18 2010 : Info: [suffix] No such realm "mydom"
Wed Jun  2 20:39:18 2010 : Info: ++[suffix] returns noop
Wed Jun  2 20:39:18 2010 : Info: [eap] EAP packet type response id 12
length 65
Wed Jun  2 20:39:18 2010 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Jun  2 20:39:18 2010 : Info: ++[eap] returns updated
Wed Jun  2 20:39:18 2010 : Info: ++[unix] returns notfound
Wed Jun  2 20:39:18 2010 : Info: [files] users: Matched entry
myuser@mydom at line 203
Wed Jun  2 20:39:18 2010 : Info: ++[files] returns ok
Wed Jun  2 20:39:18 2010 : Info: ++[expiration] returns noop
Wed Jun  2 20:39:18 2010 : Info: ++[logintime] returns noop
Wed Jun  2 20:39:18 2010 : Info: ++[pap] returns noop
Wed Jun  2 20:39:18 2010 : Info: Found Auth-Type = EAP
Wed Jun  2 20:39:18 2010 : Info: +- entering group authenticate {...}
Wed Jun  2 20:39:18 2010 : Info: [eap] Request found, released from the list
Wed Jun  2 20:39:18 2010 : Info: [eap] EAP/tls
Wed Jun  2 20:39:18 2010 : Info: [eap] processing type tls
Wed Jun  2 20:39:18 2010 : Info: [tls] Authenticate
Wed Jun  2 20:39:18 2010 : Info: [tls] processing EAP-TLS
Wed Jun  2 20:39:18 2010 : Info: [tls] eaptls_verify returned 7
Wed Jun  2 20:39:18 2010 : Info: [tls] Done initial handshake
Wed Jun  2 20:39:18 2010 : Info: [tls] <<< TLS 1.0 ChangeCipherSpec
[length 0001]
Wed Jun  2 20:39:18 2010 : Info: [tls] <<< TLS 1.0 Handshake [length
0010], Finished
Wed Jun  2 20:39:18 2010 : Info: [tls]     TLS_accept: SSLv3 read finished A
Wed Jun  2 20:39:18 2010 : Info: [tls]     (other): SSL negotiation
finished successfully
Wed Jun  2 20:39:18 2010 : Debug: SSL Connection Established
Wed Jun  2 20:39:18 2010 : Debug: SSL Application Data
Wed Jun  2 20:39:18 2010 : Info: [tls] eaptls_process returned 3
Wed Jun  2 20:39:18 2010 : Info: [tls] Retrieved session data from
cached session
Wed Jun  2 20:39:18 2010 : Info: [tls] WARNING: No information in cached
session!
Wed Jun  2 20:39:18 2010 : Info: [eap] Freeing handler
Wed Jun  2 20:39:18 2010 : Info: ++[eap] returns reject
Wed Jun  2 20:39:18 2010 : Info: Failed to authenticate the user.
Wed Jun  2 20:39:18 2010 : Auth: Login incorrect: [myuser@mydom] (from
client WAP610N port 0 cli 00-13-...)
Wed Jun  2 20:39:18 2010 : Info: Using Post-Auth-Type Reject
Wed Jun  2 20:39:18 2010 : Info: +- entering group REJECT {...}
Wed Jun  2 20:39:18 2010 : Info: [attr_filter.access_reject]    expand:
%{User-Name} -> myuser@mydom
Wed Jun  2 20:39:18 2010 : Debug:  attr_filter: Matched entry DEFAULT at
line 11
Wed Jun  2 20:39:18 2010 : Info: ++[attr_filter.access_reject] returns
updated
Wed Jun  2 20:39:18 2010 : Info: Delaying reject of request 13 for 1 seconds
Wed Jun  2 20:39:18 2010 : Debug: Going to the next request
Wed Jun  2 20:39:18 2010 : Debug: Waking up in 0.9 seconds.
Wed Jun  2 20:39:19 2010 : Info: Sending delayed reject for request 13
Sending Access-Reject of id 55 to 192.168.1.9 port 2048
        EAP-Message = 0x040c0004
        Message-Authenticator = 0x00000000000000000000000000000000

Independently of this incorrect login. the connection between the
supplicant and the AP isn't disconnected or interrupted(!!), but the
reauthentication is done every minute now.

If the cache in eap.conf is disabled, the user can't be authenticated
too, but the error during reauthentication is another
(SSL_GET_PREV_SESSION:session id context uninitialized):

rad_recv: Access-Request packet from host 192.168.1.9 port 2048, id=77,
length=1484
        User-Name = "myuser@mydom"
        NAS-Port = 0
        Called-Station-Id = "00-25-...:mywlan"
        Calling-Station-Id = "00-13-...."
        Framed-MTU = 1400
        NAS-Port-Type = Wireless-802.11
        Connect-Info = "CONNECT 11Mbps 802.11b"
        EAP-Message = ...0170018001900230420447af7318cf8a9
        EAP-Message = ...a3900200a0967a31318e54f7028eb6869963739a506ba
        EAP-Message = ...a35e57c17bbc86639826ba135d40271a953ec8fc6b1748
        EAP-Message = ...ffe48b048b34ca5e97417950e1963592be7aa223ef906e8
        EAP-Message = ...5647e8913e37299de4c889576a3cc2ac565285a27750f
        EAP-Message = ...5cccfedd1b96f38c9897681d78bbf75296a5e559e31c59b
        State = 0xaeafb685afa4bb3f1df61345a8211214
        Message-Authenticator = 0xef86f802b12b474972c47fcd3692ae4f
Wed Jun  2 21:04:16 2010 : Info: +- entering group authorize {...}
Wed Jun  2 21:04:16 2010 : Info: ++[preprocess] returns ok
Wed Jun  2 21:04:16 2010 : Info: ++[chap] returns noop
Wed Jun  2 21:04:16 2010 : Info: ++[mschap] returns noop
Wed Jun  2 21:04:16 2010 : Info: [suffix] Looking up realm "mydom" for
User-Name = "myuser@mydom"
Wed Jun  2 21:04:16 2010 : Info: [suffix] No such realm "mydom"
Wed Jun  2 21:04:16 2010 : Info: ++[suffix] returns noop
Wed Jun  2 21:04:16 2010 : Info: [eap] EAP packet type response id 11
length 253
Wed Jun  2 21:04:16 2010 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Jun  2 21:04:16 2010 : Info: ++[eap] returns updated
Wed Jun  2 21:04:16 2010 : Info: ++[unix] returns notfound
Wed Jun  2 21:04:16 2010 : Info: [files] users: Matched entry
myuser@mydom at line 203
Wed Jun  2 21:04:16 2010 : Info: ++[files] returns ok
Wed Jun  2 21:04:16 2010 : Info: ++[expiration] returns noop
Wed Jun  2 21:04:16 2010 : Info: ++[logintime] returns noop
Wed Jun  2 21:04:16 2010 : Info: ++[pap] returns noop
Wed Jun  2 21:04:16 2010 : Info: Found Auth-Type = EAP
Wed Jun  2 21:04:16 2010 : Info: +- entering group authenticate {...}
Wed Jun  2 21:04:16 2010 : Info: [eap] Request found, released from the list
Wed Jun  2 21:04:16 2010 : Info: [eap] EAP/tls
Wed Jun  2 21:04:16 2010 : Info: [eap] processing type tls
Wed Jun  2 21:04:16 2010 : Info: [tls] Authenticate
Wed Jun  2 21:04:16 2010 : Info: [tls] processing EAP-TLS
Wed Jun  2 21:04:16 2010 : Info: [tls] eaptls_verify returned 7
Wed Jun  2 21:04:16 2010 : Info: [tls] Done initial handshake
Wed Jun  2 21:04:16 2010 : Info: [tls]     (other): before/accept
initialization
Wed Jun  2 21:04:16 2010 : Info: [tls]     TLS_accept: before/accept
initialization
Wed Jun  2 21:04:16 2010 : Info: [tls] <<< TLS 1.0 Handshake [length
050b], ClientHello
Wed Jun  2 21:04:16 2010 : Error:     TLS_accept:error in SSLv3 read
client hello C
Wed Jun  2 21:04:16 2010 : Error: rlm_eap: SSL error error:140D9115:SSL
routines:SSL_GET_PREV_SESSION:session id context uninitialized
Wed Jun  2 21:04:16 2010 : Error: SSL: SSL_read failed in a system call
(-1), TLS session fails.
Wed Jun  2 21:04:16 2010 : Debug: TLS receive handshake failed during
operation

If fast_reauth in wpa_supplicant is disabled, the reauthentication works
fine, but the connection between the AP and the supplicant ist
interrupted for about 20 seconds - much to long :-).

Do you have any idea how to solve this problem?

Thanks for you help,
Andreas

reauth-problem with WPA2-tls

Andreas Hartmann