Jouni,
I'm having a problem authenticating with my AP using WPA-PSK TKIP and the bcm43xx-mac80211 driver.
The system works fine with bcm43xx-softmac - thus I know my wpa_supplicant.conf file is OK.
I have turned on full (-ddd) debugging of wpa_supplicant. In my log, I see the following sequence of
outputs for both the good and the bad examples:
logger: State: ASSOCIATED -> 4WAY_HANDSHAKE
logger: WPA: RX message 1 of 4-Way Handshake from 00:14:bf:85:49:fa (ver=1)
logger: WPA: Renewed SNonce - hexdump(len=32): 5e ca e4 8d 31 e3 05 5b e4 1f b0 80 56 94 14 fa 51 23
81 d6 2d a5 5f 68 3c 02 fe ef 04 56 3e 6e
logger: WPA: PMK - hexdump(len=32): [REMOVED]
logger: WPA: PTK - hexdump(len=64): [REMOVED]
logger: WPA: WPA IE for msg 2/4 - hexdump(len=24): dd 16 00 50 f2 01 01 00 00 50 f2 02 01 00 00 50
f2 02 01 0000 50 f2 02
logger: WPA: Sending EAPOL-Key 2/4
At this point, the two cases diverge. The bad example has a 4 second delay, then I get the following:
kernel: eth1: RX deauthentication from 00:14:bf:85:49:fa (reason=15)
kernel: eth1: deauthenticated
logger: WPA: TX EAPOL-Key - hexdump(len=123): 01 03 00 77 fe 01 09 00 20 00 00 00 00 00 00 00 16 5e
ca e4 8d 31 e3 05 5b e4 1f b0 80 56 94 14 fa 51 23 81 d6 2d a5 5f 68 3c 02 fe ef 04 56 3e 6e 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 09 9d 33 23 c2 dc 6b ca 26 19 5f d9 a4 1b 85 11 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
logger: EAPOL: startWhen --> 0
logger: EAPOL: SUPP_PAE entering state CONNECTING
logger: EAPOL: txStart
logger: WPA: drop TX EAPOL in non-IEEE 802.1X mode (type=1 len=0)
logger: RTM_NEWLINK: operstate=0 ifi_flags=0x1023 ([UP])
logger: Wireless event: cmd=0x8b15 len=24
logger: Wireless event: new AP: 00:00:00:00:00:00
From here, the process repeats over and over without success.
With the driver that works, the output continues with:
logger: WPA: TX EAPOL-Key - hexdump(len=123): 01 03 00 77 fe 01 09 00 20 00 00 00 00 00 00 00 0e fd
80 70 69 ec e0 6d 0d 4b ec 66 c3 0d 8a 46 82 11 6e a8 e8 97 be 20 5a 19 4f a3 99 c5 4e 39 e4 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 fe 58 da 6c 96 95 93 66 96 d5 46 a3 e0 18 32 bd 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
logger: RX EAPOL from 00:14:bf:85:49:fa
logger: RX EAPOL - hexdump(len=125): 01 03 00 79 fe 01 c9 00 20 00 00 00 00 00 00 00 0f 57 6f 04 92
27 6b 80 c0 19 de 3c 7f e8 22 2b e0 ce 47 09 1e 68 fc bf 4a 1e 3d ca 4d d3 21 b3 dd 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 33 bb 6b 6a 3d 36 6a 41 32 ab d0 7a 51 a1 b5 cf 00 1a dd 18 00 50
f2 01 01 00 00 50 f2 02 01 00 00 50 f2 02 01 00 00 50 f2 02 00 00
logger: IEEE 802.1X RX: version=1 type=3 length=121
From here if finishes the authentication and communication is established.
Do you know why the supplicant waits the 4 seconds between the "sending key 2/4" message and the
actual transmission of it? Do you think that is important, or is it a false lead? I would appreciate
any debugging leads you might offer.
I'm using wpa_supplicant 0.5.7 and running 2.6.21-rc5 on an openSUSE 10.2 distribution.
Thanks,
Larry
On Mon, Apr 09, 2007 at 04:52:09PM -0500, Larry Finger wrote:
> logger: WPA: Sending EAPOL-Key 2/4
>
> At this point, the two cases diverge. The bad example has a 4 second delay,
> then I get the following:
>
> kernel: eth1: RX deauthentication from 00:14:bf:85:49:fa (reason=15)
> kernel: eth1: deauthenticated
> logger: WPA: TX EAPOL-Key - hexdump(len=123): 01 03 00 77 fe 01 09 00 20 00
> Do you know why the supplicant waits the 4 seconds between the "sending key
> 2/4" message and the actual transmission of it? Do you think that is
> important, or is it a false lead? I would appreciate any debugging leads
> you might offer.
This looks very odd.. There is not really any blocking operations in
wpa_supplicant between the places that print "WPA: Sending EAPOL-Key
2/4" and "WPA: TX EAPOL-Key"... How do you generate these syslog
messages? Could there be something buffering the TX EAPOL-Key message
and the delay would actually happen only after that? This could be
caused by send() getting blocked by something and the receiption of
deauthentication triggering unblocking somehow..
--
Jouni Malinen PGP id EFC895FA