new association fails during group rekeying

Thu Aug 5 19:35:54 EDT 2010

Hello all,

I'm seeing an issue where a station that tries to associate during a 
WPA group rekeying process gets EAPOL-Key timeouts and eventually 
disassociates. Is this an issue with hostapd, or is the client 
misbehaving by barging in on the rekeying process like this? I don't
know enough about the state machine to say.

Anyway, here are the hostapd logs (hostapd v0.7.1, 2.6.30 linux kernel, 
ath 231x). You'll see three clients in there: MAC1 and MAC2 are already 
authenticated and get rekeyed no problem, while MAC3 appears during the 
rekeying and never manages to associate, even after this exchange.

Thanks in advance,

-Alan

------------------------------------------------------------------------

hostapd.conf:

  driver=madwifi
  interface=ath0
  wpa_passphrase=********
  wpa=2
  wpa_pairwise=CCMP
  ssid=********

------------------------------------------------------------------------

ath0: WPA rekeying GTK
WPA: group state machine entering state SETKEYS (VLAN-ID 0)
GMK - hexdump(len=32): [REMOVED]
GTK - hexdump(len=16): [REMOVED]
WPA: {{MAC1}} WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA {{MAC1}} WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
TX EAPOL - hexdump(len=145): 00 08 dc 15 4f b3 00 15 6d f0 fa 05 88 8e 02 03 00 7f 02 13 82 00 10 00 00 00 00 00 00 00 06 40 62 cb 92 b2 d5 02 30 98 e9 5e bc dd 63 c3 b5 23 25 da 4e 70 90 bf 2e 05 96 f5 03 2a 07 3a 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 13 b6 27 ed 25 43 29 6f 58 ed d5 1b 93 1b ab 8f 00 20 49 34 eb 98 b2 73 3b 32 15 c7 56 a1 d1 79 cb b2 c9 ef 0e 0d a6 7a 6c c9 71 2c 74 b2 8d 1f f8 c1
WPA: {{MAC2}} WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA {{MAC2}} WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
TX EAPOL - hexdump(len=145): 00 05 4e 4b 37 40 00 15 6d f0 fa 05 88 8e 02 03 00 7f 02 13 82 00 10 00 00 00 00 00 00 00 03 40 62 cb 92 b2 d5 02 30 98 e9 5e bc dd 63 c3 b5 23 25 da 4e 70 90 bf 2e 05 96 f5 03 2a 07 3a 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2d 9a 26 66 8e 7e a9 c0 c0 e7 04 f6 51 39 7b 96 00 20 e8 8a 17 75 44 42 65 b9 1a 72 97 67 ea 87 c9 2f be ec b5 75 7d f2 0c f5 8d b1 ec 31 89 da a2 b9
WPA: {{MAC3}} WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA {{MAC3}} WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
TX EAPOL - hexdump(len=145): 00 08 dc 15 34 7f 00 15 6d f0 fa 05 88 8e 02 03 00 7f 02 13 82 00 10 00 00 00 00 00 00 00 06 40 62 cb 92 b2 d5 02 30 98 e9 5e bc dd 63 c3 b5 23 25 da 4e 70 90 bf 2e 05 96 f5 03 2a 07 3a 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 e7 12 ce 34 e8 cb 51 d4 0d 55 15 4d fe 16 d2 17 00 20 33 cc 0c c3 25 bb 20 54 9c 37 7b 3b a0 d1 74 49 ab 9e b9 a2 7b 2b 03 0c 8b 3e 1a 30 f3 7c f4 bd
wpa_group_setkeys: GKeyDoneStations=3
IEEE 802.1X: 99 bytes from {{MAC1}}
   IEEE 802.1X: version=1 type=3 length=95
ath0: STA {{MAC1}} WPA: received EAPOL-Key frame (2/2 Group)
WPA: {{MAC1}} WPA_PTK_GROUP entering state REKEYESTABLISHED
ath0: STA {{MAC1}} WPA: group key handshake completed (RSN)
WPA: {{MAC1}} WPA_PTK_GROUP entering state IDLE
IEEE 802.1X: 99 bytes from {{MAC2}}
   IEEE 802.1X: version=1 type=3 length=95
ath0: STA {{MAC2}} WPA: received EAPOL-Key frame (2/2 Group)
WPA: {{MAC2}} WPA_PTK_GROUP entering state REKEYESTABLISHED
ath0: STA {{MAC2}} WPA: group key handshake completed (RSN)
WPA: {{MAC2}} WPA_PTK_GROUP entering state IDLE
ath0: STA {{MAC3}} WPA: EAPOL-Key timeout
WPA: {{MAC3}} WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA {{MAC3}} WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
TX EAPOL - hexdump(len=145): 00 08 dc 15 34 7f 00 15 6d f0 fa 05 88 8e 02 03 00 7f 02 13 82 00 10 00 00 00 00 00 00 00 07 40 62 cb 92 b2 d5 02 30 98 e9 5e bc dd 63 c3 b5 23 25 da 4e 70 90 bf 2e 05 96 f5 03 2a 07 3a 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 85 80 2b 69 6f b5 34 63 95 39 dc e2 75 df 8f 9d 00 20 33 cc 0c c3 25 bb 20 54 9c 37 7b 3b a0 d1 74 49 ab 9e b9 a2 7b 2b 03 0c 8b 3e 1a 30 f3 7c f4 bd
ath0: STA {{MAC3}} WPA: EAPOL-Key timeout
WPA: {{MAC3}} WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA {{MAC3}} WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
TX EAPOL - hexdump(len=145): 00 08 dc 15 34 7f 00 15 6d f0 fa 05 88 8e 02 03 00 7f 02 13 82 00 10 00 00 00 00 00 00 00 08 40 62 cb 92 b2 d5 02 30 98 e9 5e bc dd 63 c3 b5 23 25 da 4e 70 90 bf 2e 05 96 f5 03 2a 07 3a 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c1 e8 5a a4 a3 25 8a 8b 55 bc 11 83 c4 63 01 de 00 20 33 cc 0c c3 25 bb 20 54 9c 37 7b 3b a0 d1 74 49 ab 9e b9 a2 7b 2b 03 0c 8b 3e 1a 30 f3 7c f4 bd
ath0: STA {{MAC3}} WPA: EAPOL-Key timeout
WPA: {{MAC3}} WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA {{MAC3}} WPA: sending 1/2 msg of Group Key Handshake
WPA: Send EAPOL(version=2 secure=1 mic=1 ack=1 install=0 pairwise=0 kde_len=24 keyidx=2 encr=1)
Plaintext EAPOL-Key Key Data - hexdump(len=32): [REMOVED]
TX EAPOL - hexdump(len=145): 00 08 dc 15 34 7f 00 15 6d f0 fa 05 88 8e 02 03 00 7f 02 13 82 00 10 00 00 00 00 00 00 00 09 40 62 cb 92 b2 d5 02 30 98 e9 5e bc dd 63 c3 b5 23 25 da 4e 70 90 bf 2e 05 96 f5 03 2a 07 3a 21 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3f 9b 9b 7f f3 c7 2d ef 4d 39 59 3c af 1f bb 8e 00 20 33 cc 0c c3 25 bb 20 54 9c 37 7b 3b a0 d1 74 49 ab 9e b9 a2 7b 2b 03 0c 8b 3e 1a 30 f3 7c f4 bd
ath0: STA {{MAC3}} WPA: EAPOL-Key timeout
WPA: {{MAC3}} WPA_PTK_GROUP entering state REKEYNEGOTIATING
WPA: {{MAC3}} WPA_PTK_GROUP entering state KEYERROR
WPA: group state machine entering state SETKEYSDONE (VLAN-ID 0)
madwifi_set_key: alg=3 addr=00:00:00:00:00:00 key_idx=2
WPA: {{MAC3}} WPA_PTK entering state DISCONNECT
hostapd_wpa_auth_disconnect: WPA authenticator requests disconnect: STA {{MAC3}} reason 2
madwifi_sta_deauth: addr={{MAC3}} reason_code=2
WPA: {{MAC3}} WPA_PTK_GROUP entering state IDLE
WPA: {{MAC3}} WPA_PTK entering state DISCONNECTED
WPA: {{MAC3}} WPA_PTK entering state INITIALIZE
madwifi_del_key: addr={{MAC3}} key_idx=0
madwifi_set_sta_authorized: addr={{MAC3}} authorized=0
ioctl[IEEE80211_IOCTL_SETMLME]: No such file or directory
madwifi_set_sta_authorized: Failed to unauthorize STA {{MAC3}}
ath0: STA {{MAC3}} IEEE 802.1X: unauthorizing port
ath0: STA {{MAC3}} IEEE 802.11: deauthenticated due to local deauth request
Wireless event: cmd=0x8c02 len=103
Custom wireless event: 'STA-TRAFFIC-STAT
mac={{MAC3}}
rx_packets=19
rx_bytes=3542
tx_packets=33
tx_bytes=4007
'
Wireless event: cmd=0x8c04 len=20
ath0: STA {{MAC3}} IEEE 802.11: disassociated
Disassociation notification for unknown STA {{MAC3}}