problem with wpa_supplicant and hostapd handoff using cached PMK

[Gan Hock Lai]

two APs were setup using hostapd-0.2.5,
hostap-driver-0.2.5. the client was setup using
wpa_suppicant-0.2.5 as well. the client was set to
manual scan and roaming mode (iwpriv wlan0
host_roaming 2). pre-authentication was executed and
the PMKSA was cached in both AP and client. i forced
the client to handoff by the command iwconfig wlan0 ap
<new_ap_mac> . however, the client using the old PMKID
and sent in the association request frame. as the
result, full authentication was executed.
in another case, i forced the handoff process by
turned of the associated AP and forced reassociation
process using wpa_cli. the client bind the new PMKID
together with associate request frame, and as expected
new AP was able to match with the cached PMK.
surprisingly, it skipped to do just 4-way handshake
but performed full authentication.

here is the AP log:
(end of pre-auth)
Received 189 bytes from RADIUS server
Received RADIUS message
RADIUS packet matching with station 00:09:5b:0d:29:18
MS-MPPE-Send-Key (len=32): cc 94 fc 29 cd ee 51 be 13
51 5a a7 42 11 b0 eb a0 3e 88 bd a5 20 37 70 5c 96 88
91 0b 41 65 46
MS-MPPE-Recv-Key (len=32): e3 92 a5 22 67 e4 42 6d f9
46 d4 d6 ce 90 ad fa 36 22 45 bb a6 d6 8d 49 59 4b c2
f3 bc 23 4f de
wlan0: STA 00:09:5b:0d:29:18 WPA: added PMKSA cache
entry
RSN: added PMKID - hexdump(len=16): 6f 09 06 ce 2c 2c
14 21 0f 6a 16 9f b6 c7 3a c2
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.1X: decapsulated
EAP packet (code=3 id=6 len=4) from RADIUS server: EAP
Success
IEEE 802.1X: 00:09:5b:0d:29:18 BE_AUTH entering state
SUCCESS
IEEE 802.1X: Sending EAP Packet to 00:09:5b:0d:29:18
(identifier 6)
IEEE 802.1X: 00:09:5b:0d:29:18 REAUTH_TIMER entering
state INITIALIZE
IEEE 802.1X: 00:09:5b:0d:29:18 AUTH_PAE entering state
AUTHENTICATED
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.1X:
authenticated
wlan0: STA 00:09:5b:0d:29:18 WPA: pre-authentication
succeeded
wlan0: STA 00:09:5b:0d:29:18 WPA: added PMKSA cache
entry
RSN: added PMKID - hexdump(len=16): 6f 09 06 ce 2c 2c
14 21 0f 6a 16 9f b6 c7 3a c2
Received 30 bytes management frame
MGMT
mgmt::auth
authentication: STA=00:09:5b:0d:29:18 auth_alg=0
auth_transaction=1 status_code=0 wep=0
  New STA
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.11:
authentication OK (open system)
wlan0: STA 00:09:5b:0d:29:18 WPA: event 0 notification
authentication reply: STA=00:09:5b:0d:29:18 auth_alg=0
auth_transaction=2 resp=0
Received 30 bytes management frame
MGMT (TX callback) ACK
mgmt::auth cb
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.11:
authenticated
Received 83 bytes management frame
MGMT
mgmt::assoc_req
association request: STA=00:09:5b:0d:29:18
capab_info=0x11 listen_interval=10
RSN IE: STA PMKID - hexdump(len=16): 6f 09 06 ce 2c 2c
14 21 0f 6a 16 9f b6 c7 3a c2
wlan0: STA 00:09:5b:0d:29:18 WPA: PMKID found from
PMKSA cache
  new AID 1
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.11: association
OK (aid 1)
Received 36 bytes management frame
MGMT (TX callback) ACK
mgmt::assoc_resp cb
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.11: associated
(aid 1)
wlan0: STA 00:09:5b:0d:29:18 WPA: event 1 notification
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.1X: start
authentication
IEEE 802.1X: 00:09:5b:0d:29:18 AUTH_PAE entering state
INITIALIZE
IEEE 802.1X: 00:09:5b:0d:29:18 AUTH_PAE entering state
INITIALIZE
wlan0: STA 00:09:5b:0d:29:18 WPA: start authentication
WPA: 00:09:5b:0d:29:18 WPA_PTK entering state
INITIALIZE
WPA: 00:09:5b:0d:29:18 WPA_PTK_GROUP entering state
IDLE
WPA: 00:09:5b:0d:29:18 WPA_PTK entering state
AUTHENTICATION
WPA: 00:09:5b:0d:29:18 WPA_PTK entering state
AUTHENTICATION2
Wireless event: cmd=0x8c03 len=20
IEEE 802.1X: 00:09:5b:0d:29:18 AUTH_PAE entering state
DISCONNECTED
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.1X:
unauthorizing port
IEEE 802.1X: 00:09:5b:0d:29:18 BE_AUTH entering state
IDLE
IEEE 802.1X: 00:09:5b:0d:29:18 REAUTH_TIMER entering
state INITIALIZE
IEEE 802.1X: 00:09:5b:0d:29:18 AUTH_PAE entering state
CONNECTING
IEEE 802.1X: Sending EAP Request-Identity to
00:09:5b:0d:29:18 (identifier 0)
IEEE 802.1X: 00:09:5b:0d:29:18 REAUTH_TIMER entering
state INITIALIZE
IEEE 802.1X: 00:09:5b:0d:29:18 REAUTH_TIMER entering
state INITIALIZE
Received 46 bytes management frame
DATA (TX callback) ACK
IEEE 802.1X: 00:09:5b:0d:29:18 TX status - version=1
type=0 length=10 - ack=1
Received 50 bytes management frame
DATA
IEEE 802.1X: 18 bytes from 00:09:5b:0d:29:18
   IEEE 802.1X: version=1 type=0 length=14
   EAP: code=2 identifier=0 length=14 (response)
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.1X: received EAP
packet (code=2 id=0 len=14) from STA: EAP
Response-Identity (1)
(full auth starts)

things work fine when client reassociate with the same
AP, here is the log:

mgmt::assoc_req
association request: STA=00:09:5b:0d:29:18
capab_info=0x11 listen_interval=10
RSN IE: STA PMKID - hexdump(len=16): a0 49 f9 6a 91 45
61 74 03 40 50 06 10 68 e2 31
wlan0: STA 00:09:5b:0d:29:18 WPA: PMKID found from
PMKSA cache
  old AID 1
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.11: association
OK (aid 1)
Received 36 bytes management frame
MGMT (TX callback) ACK
mgmt::assoc_resp cb
wlan0: STA 00:09:5b:0d:29:18 IEEE 802.11: associated
(aid 1)
wlan0: STA 00:09:5b:0d:29:18 WPA: event 1 notification
wlan0: STA 00:09:5b:0d:29:18 WPA: PMK from PMKSA cache
- skip IEEE 802.1X/EAP
wlan0: STA 00:09:5b:0d:29:18 WPA: event 4 notification
wlan0: STA 00:09:5b:0d:29:18 WPA: PMK from PMKSA cache
- skip IEEE 802.1X/EAP
WPA: 00:09:5b:0d:29:18 WPA_PTK entering state
AUTHENTICATION2
WPA: 00:09:5b:0d:29:18 WPA_PTK entering state INITPMK
WPA: 00:09:5b:0d:29:18 WPA_PTK entering state PTKSTART
wlan0: STA 00:09:5b:0d:29:18 WPA: sending 1/4 msg of
4-Way Handshake 

regards,
Gan Hock Lai

__________________________________________________
Do You Yahoo!?
Tired of spam?  Yahoo! Mail has the best spam protection around 
http://mail.yahoo.com