Group key negotiation failure with D-link AP leading to unstable connectivity?

Duncan Grove duncan.grove
Sun Aug 1 21:43:50 PDT 2004


Hi,

I'm having stability problems with WPA-PSK on my test system, as 
described below. I think this may be an Access Point problem, but I'm 
not sure - any advice would be appreciated!

Client: Avaya Gold (Hermes I) with wpa_supplicant 0.2.4 + Agere 7.18 
driver + pcmcia-cs 3.2.7 on a Redhat 9.0 base + 2.4.26 kernel.
AP: Dlink DI-784 with the latest firmware (2.36, Feb 2004)

Logs from "wpa_supplicant -D hermes -c/etc/wpa_supplicant.conf -dd" show 
the following behaviour:

1) wpa_supplicant scans for an AP and associates
2) pings to AP do not flow for 3 seconds
3) 4-way handshake for pairwise key succeeds
4) pings to AP flow for 10 seconds (wpa_state=GROUP_HANDSHAKE)
5) group key negotiation times out
6) repeat from step 1

Log of broken operation:

Setting scan request: 0 sec 0 usec
Starting AP scan (broadcast SSID)
Wireless event: cmd=0x8b19 len=12
Received 4096 bytes of scan results (3 BSSes)
Scan results: 3
Selecting BSS from priority group 0
0: 00:80:c8:03:1d:c6 ssid='test' wpa_ie_len=0 rsn_ie_len=0
  skip - no WPA/RSN IE
1: 00:80:c8:03:1d:16 ssid='test' wpa_ie_len=0 rsn_ie_len=0
  skip - no WPA/RSN IE
2: 00:0d:88:c5:40:39 ssid='8021xtst' wpa_ie_len=24 rsn_ie_len=0
  selected
Trying to associate with 00:0d:88:c5:40:39 (SSID='8021xtst' freq=0 MHz)
CTRL_IFACE monitor send - hexdump(len=24): 2f 74 6d 70 2f 77 70 61 5f 63 
74 72 6c 5f 31 38 36 32 39 2d 33 00 a8 60
Cancelling scan request
WPA: using IEEE 802.11i/D3.0
WPA: Own WPA IE - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 
01 00 00 50 f2 02 01 00 00 50 f2 02
wpa_driver_hermes_set_key: alg=none key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_hermes_set_key: alg=none key_idx=1 set_tx=0 seq_len=0 key_len=0
wpa_driver_hermes_set_key: alg=none key_idx=2 set_tx=0 seq_len=0 key_len=0
wpa_driver_hermes_set_key: alg=none key_idx=3 set_tx=0 seq_len=0 key_len=0
wpa_driver_hermes_set_key: alg=none key_idx=0 set_tx=0 seq_len=0 key_len=0
wpa_driver_hermes_set_drop_unencrypted: enabled=1
wpa_driver_hermes_associate
ioctl[SIOCSIWFREQ]: Invalid argument
ioctl[SIOCSIWAP]: Operation not supported
Setting authentication timeout: 5 sec 0 usec
Wireless event: cmd=0x8b1a len=20
Custom wireless event: 
'ASSOCINFO(ReqIEs=dd160050f20101000050f20201000050f20201000050f202)'
Association info event
req_ies - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 
50 f2 02 01 00 00 50 f2 02
assoc_wpa_ie - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 
00 00 50 f2 02 01 00 00 50 f2 02
Wireless event: cmd=0x8b15 len=20
Wireless event: new AP: 00:0d:88:c5:40:39
Association event - clear replay counter
Setting authentication timeout: 10 sec 0 usec
RX ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
EAPOL from 00:0d:88:c5:40:39
RX EAPOL - hexdump(len=99): 01 03 00 5f fe 00 89 00 20 00 00 00 00 00 00 
00 01 23 d4 a6 53 93 b4 6f 9f e5 3f 9f eb 79 5a f0 ba d6 f5 bd ab 34 14 
a5 ed f2 ae e2 8e 5c 99 fb c0 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 00 00 00 00 00 00 
00 00 00 00 00 00 00 00 00 00 00 00
Setting authentication timeout: 10 sec 0 usec
IEEE 802.1X RX: version=1 type=3 length=95
 EAPOL-Key type=254
WPA: RX EAPOL-Key - hexdump(len=99): 01 03 00 5f fe 00 89 00 20 00 00 00 
00 00 00 00 01 23 d4 a6 53 93 b4 6f 9f e5 3f 9f eb 79 5a f0 ba d6 f5 bd 
ab 34 14 a5 ed f2 ae e2 8e 5c 99 fb c0 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 00 00 00 
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
WPA: RX message 1 of 4-Way Handshake from 00:0d:88:c5:40:39 (ver=1)
WPA: Renewed SNonce - hexdump(len=32): 25 5f 88 8d ba bb 83 08 4a 24 11 
aa ba 9b 49 96 cf ec 45 24 32 24 c7 8a ca 22 90 7b ef 60 99 d8
WPA: PMK - hexdump(len=32): d6 a8 54 dc b2 b1 3e 1a 76 66 0b e8 d3 49 a1 
e7 58 7b 6a 99 21 74 57 6d 9c 68 af 0f 9b 4f 10 fd
WPA: PTK - hexdump(len=64): bb 9b 81 85 dd 87 17 fe 61 eb 81 78 2c 4a fa 
dd f8 71 24 4d 00 38 e4 55 93 2a 9b f2 79 62 26 4e 54 96 36 f7 b0 83 db 
f9 93 b4 1b 45 d5 48 04 f9 10 56 6c fa 14 49 07 8a d9 be 14 80 0f 63 f7 8a
WPA: EAPOL-Key MIC - hexdump(len=16): 24 a8 27 17 83 f1 dc 86 b9 08 f7 
99 28 bf b7 4a
WPA: Sending EAPOL-Key 2/4
WPA: TX EAPOL-Key 2/4 - hexdump(len=137): 00 0d 88 c5 40 39 00 02 2d b6 
fa ad 88 8e 01 03 00 77 fe 01 09 00 20 00 00 00 00 00 00 00 01 25 5f 88 
8d ba bb 83 08 4a 24 11 aa ba 9b 49 96 cf ec 45 24 32 24 c7 8a ca 22 90 
7b ef 60 99 d8 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 24 a8 27 17 83 f1 dc 86 b9 08 f7 
99 28 bf b7 4a 00 18 dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50 f2 
02 01 00 00 50 f2 02
RX EAPOL from 00:0d:88:c5:40:39
RX EAPOL - hexdump(len=123): 01 03 00 77 fe 01 c9 00 20 00 00 00 00 00 
00 00 02 23 d4 a6 53 93 b4 6f 9f e5 3f 9f eb 79 5a f0 ba d6 f5 bd ab 34 
14 a5 ed f2 ae e2 8e 5c 99 fb c0 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 f0 88 0e d0 f8 
9c de 67 84 27 9a e2 35 61 c3 60 00 18 dd 16 00 50 f2 01 01 00 00 50 f2 
02 01 00 00 50 f2 02 01 00 00 50 f2 02
IEEE 802.1X RX: version=1 type=3 length=119
 EAPOL-Key type=254
WPA: RX EAPOL-Key - hexdump(len=123): 01 03 00 77 fe 01 c9 00 20 00 00 
00 00 00 00 00 02 23 d4 a6 53 93 b4 6f 9f e5 3f 9f eb 79 5a f0 ba d6 f5 
bd ab 34 14 a5 ed f2 ae e2 8e 5c 99 fb c0 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 f0 88 
0e d0 f8 9c de 67 84 27 9a e2 35 61 c3 60 00 18 dd 16 00 50 f2 01 01 00 
00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02
WPA: RX message 3 of 4-Way Handshake from 00:0d:88:c5:40:39 (ver=1)
WPA: Sending EAPOL-Key 4/4
WPA: TX EAPOL-Key 4/4 - hexdump(len=113): 00 0d 88 c5 40 39 00 02 2d b6 
fa ad 88 8e 01 03 00 5f fe 01 09 00 20 00 00 00 00 00 00 00 02 25 5f 88 
8d ba bb 83 08 4a 24 11 aa ba 9b 49 96 cf ec 45 24 32 24 c7 8a ca 22 90 
7b ef 60 99 d8 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 17 d2 07 68 3d 32 d4 ec bc 3f da 
20 6f c2 88 a6 00 00
WPA: Installing PTK to the driver.
WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
wpa_driver_hermes_set_key: alg=TKIP key_idx=0 set_tx=1 seq_len=6 key_len=32
RX ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           RX 
ctrl_iface - hexdump_ascii(len=4):
    50 49 4e 47                                       PING           
Authentication with 00:0d:88:c5:40:39 timed out.
CTRL_IFACE monitor send - hexdump(len=24): 2f 74 6d 70 2f 77 70 61 5f 63 
74 72 6c 5f 31 38 36 32 39 2d 33 00 a8 60

REPEAT!

After many, many hours of this broken operation the group key 
negotiation finally succeeds (immediately after 
wpa_driver_hermes_set_key above) and everything after that worked fine:

RX EAPOL from 00:0d:88:c5:40:39
IEEE 802.1X RX: version=1 type=3 length=127
 EAPOL-Key type=254
WPA: RX message 1 of Group Key Handshake from 00:0d:88:c5:40:39 (ver=1)
WPA: Group Key - hexdump(len=32): af 5f 55 4f cf 3f 58 11 29 89 19 6c c9 
2c 59 2a cb 0a 88 b5 02 43 e3 2f c9 83 52 91 d6 00 da 77
WPA: Installing GTK to the driver (keyidx=1 tx=0).
WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
wpa_driver_hermes_set_key: alg=TKIP key_idx=1 set_tx=0 seq_len=6 key_len=32
WPA: Sending EAPOL-Key 2/2
WPA: Key negotiation completed with 00:0d:88:c5:40:39
Cancelling authentication timeout

I presume this is what is meant to happen all the time. It seems to me 
like my AP is just not sending message 1 of the Group Key Handshake most 
of the time and this is the source of my problem. Is this correct?

I have also noticed a couple of other problems that may or may not be 
related:

1) If I stop and restart wpa_supplicant, the 4-way handshake gets stuck 
in a rapidly repeating cycle of steps 1 and 2.
2) If I power off/power on the AP, it remains in wpa_supplicants scan 
list, and I need to restart wpa_supplicant.

Oh, and I have one final question: I have been able to find lots of 
dicsussion about how often a WPA rekey happens (eg every minute, every 
day, every 10,000 packets, etc) but I've seen hardly anything on how 
long it takes when it does (for eg if reassociating with a new AP during 
roaming). Is about 3 seconds (what I got above) normal, or very slow?

Regards,
Duncan





More information about the Hostap mailing list