Subject: Re: regression after partial vmlocking merge (was: ath(4)
To: None <current-users@NetBSD.org>
From: Jukka Salmi <j+nbsd@2007.salmi.ch>
List: current-users
Date: 08/07/2007 14:20:32
David Young --> current-users (2007-08-06 11:41:42 -0500):
> Are the client and the AP both little-endian?  ISTR somebody fixed an
> endianness bug in hostapd and/or wpa_supplicant.

Yes, both are i386. That bug was fixed two months ago; after that
wpa_supplicant still worked fine for me.


> I suggest looking very closely at what hostapd and wpa_supplicant can
> tell you about the disconnections.

I'm trying to reproduce the problem while running hostapd (on 4.0_BETA2)
and wpa_supplicant (on -current as of yesterday) with -dd, without
success so far.

Some minutes ago a client (unfortunately running wpa_supplicant
_without_ -dd) lost connectivity while hostapd on the AP was running
with -dd. IIUC hostapd disconnects the client because of repeated
timeouts while rekeying:

Checking STA 00:0e:9b:a2:8d:9c inactivity:
  Station has been active
ath0: WPA rekeying GTK
WPA: group state machine entering state SETKEYS
GMK - hexdump(len=32): d8 c6 ba e5 b3 b8 0d d7 34 0c 22 ba 86 1b 84 bc 4c ca 17 9d c3 56 16 6e 62 c9 c5 ca 44 47 4e bd
GTK - hexdump(len=32): 2b b9 f5 23 39 2d e7 b5 45 40 89 b4 dd 07 22 da ac 91 5f a1 34 cf 71 7b 85 d6 56 2a 92 ad 47 bc
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA 00:0e:9b:a2:8d:9c WPA: sending 1/2 msg of Group Key Handshake
Plaintext EAPOL-Key Key Data - hexdump(len=32): 2b b9 f5 23 39 2d e7 b5 45 40 89 b4 dd 07 22 da ac 91 5f a1 34 cf 71 7b 85 d6 56 2a 92 ad 47 bc
ath0: STA 00:0e:9b:a2:8d:9c WPA: EAPOL-Key timeout
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA 00:0e:9b:a2:8d:9c WPA: sending 1/2 msg of Group Key Handshake
Plaintext EAPOL-Key Key Data - hexdump(len=32): 2b b9 f5 23 39 2d e7 b5 45 40 89 b4 dd 07 22 da ac 91 5f a1 34 cf 71 7b 85 d6 56 2a 92 ad 47 bc
ath0: STA 00:0e:9b:a2:8d:9c WPA: EAPOL-Key timeout
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA 00:0e:9b:a2:8d:9c WPA: sending 1/2 msg of Group Key Handshake
Plaintext EAPOL-Key Key Data - hexdump(len=32): 2b b9 f5 23 39 2d e7 b5 45 40 89 b4 dd 07 22 da ac 91 5f a1 34 cf 71 7b 85 d6 56 2a 92 ad 47 bc
ath0: STA 00:0e:9b:a2:8d:9c WPA: EAPOL-Key timeout
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA 00:0e:9b:a2:8d:9c WPA: sending 1/2 msg of Group Key Handshake
Plaintext EAPOL-Key Key Data - hexdump(len=32): 2b b9 f5 23 39 2d e7 b5 45 40 89 b4 dd 07 22 da ac 91 5f a1 34 cf 71 7b 85 d6 56 2a 92 ad 47 bc
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state KEYERROR
WPA: group state machine entering state SETKEYSDONE
bsd_set_key: alg=TKIP addr=00:00:00:00:00:00 key_idx=2
WPA: 00:0e:9b:a2:8d:9c WPA_PTK entering state DISCONNECT
bsd_sta_deauth: addr=00:0e:9b:a2:8d:9c reason_code=2
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state IDLE
WPA: 00:0e:9b:a2:8d:9c WPA_PTK entering state DISCONNECTED
WPA: 00:0e:9b:a2:8d:9c WPA_PTK entering state INITIALIZE
bsd_del_key: addr=00:0e:9b:a2:8d:9c key_idx=0
hostapd: ioctl[SIOCS80211, op 20, len 7]: No such file or directory
ath0: STA 00:0e:9b:a2:8d:9c IEEE 802.1X: unauthorizing port
bsd_set_sta_authorized: addr=00:0e:9b:a2:8d:9c authorized=0
hostapd: ioctl[SIOCS80211, op 21, len 42]: Invalid argument
ath0: STA 00:0e:9b:a2:8d:9c IEEE 802.11: deauthenticated due to local deauth request
ath0: STA 00:0e:9b:a2:8d:9c IEEE 802.11: deassociated

(Full hostapd log is [1]available.)

Some minutes later - after wpa_supplicant and hostapd were both
restarted - rekeying worked fine:

ath0: WPA rekeying GTK
WPA: group state machine entering state SETKEYS
GMK - hexdump(len=32): 8e d8 85 7f 57 8f c1 8b 90 cd 70 dc 7d 37 5b d3 72 17 69 3c 51 73 6d bc f9 53 c2 8a 82 f5 1e 2e
GTK - hexdump(len=32): b3 7c 9a 9f 26 51 03 dd 27 6f 49 f6 f5 d9 75 91 b1 3d 23 8f 79 e4 f7 43 f5 52 20 99 99 02 bd 8d
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state REKEYNEGOTIATING
ath0: STA 00:0e:9b:a2:8d:9c WPA: sending 1/2 msg of Group Key Handshake
Plaintext EAPOL-Key Key Data - hexdump(len=32): b3 7c 9a 9f 26 51 03 dd 27 6f 49 f6 f5 d9 75 91 b1 3d 23 8f 79 e4 f7 43 f5 52 20 99 99 02 bd 8d
IEEE 802.1X: 99 bytes from 00:0e:9b:a2:8d:9c
   IEEE 802.1X: version=1 type=3 length=95
ath0: STA 00:0e:9b:a2:8d:9c WPA: received EAPOL-Key frame (2/2 Group)
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state REKEYESTABLISHED
ath0: STA 00:0e:9b:a2:8d:9c WPA: group key handshake completed (WPA)
WPA: group state machine entering state SETKEYSDONE
bsd_set_key: alg=TKIP addr=00:00:00:00:00:00 key_idx=2
WPA: 00:0e:9b:a2:8d:9c WPA_PTK_GROUP entering state IDLE
Checking STA 00:0e:9b:a2:8d:9c inactivity:
  Station has been active

Hmm, any hints what could cause these timeouts?


> Does a statistic shown by 'ifconfig
> -v ath0' increase with the disconnections?

Yes, `rx deauthentication' does.


Regards, Jukka

[1] http://salmi.ch/~jukka/nbsd/hostapd.log

-- 
bashian roulette:
$ ((RANDOM%6)) || rm -rf ~