ral/wpa_supplicant drops after successful WPA negotiation?

[Sam Leffler]

Peter de Rooij wrote:
> I have a weird problem with WPA on FreeBSD 6.0. According to my 
> interpretation of the debug output of wpa_supplicant (below) and 
> according to my AP, WPA keys are successfully negotiated.  However, 
> wpa_supplicant just waits, then times out (authentication time-out) and 
> starts over.
> 
> Short except of wpa_supplicant output (more below):
> ----------------------------------------
> WPA: Installing PTK to the driver.
> WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
> wpa_driver_bsd_set_key: alg=TKIP addr=00:80:c8:05:1e:32 key_idx=0 
> set_tx=1 seq_len=6 key_len=32
> Authentication with 00:80:c8:05:1e:32 timed out.
> Added BSSID 00:80:c8:05:1e:32 into blacklist
> wpa_driver_bsd_disassociate
> ----------------------------------------
> During the wait, ifconfig shows the status as associated, with WPA active.
> 
> In addition, I also get errors
> "ioctl[SIOCS80211, op 20, len 7]: Can't assign requested address"
> 
> I followed the instructions from 
> http://damien.bergamini.free.fr/ral/ral-freebsd.html to set this up.
> 
> I did search for this problem, and found a similar question on this 
> list, but no answers.  (Except the suspicion this is due to the D-Link 
> DI-614+ AP which I also use. This seems weird as the same hardware works 
> under WinXP, and the "error" seems to occur in wpa_supplicant.) See 
> http://lists.freebsd.org/mailman/htdig/freebsd-mobile/2005-December/007474.html 
> 
> 
> Other info:
> - This is on i386 (Pentium 4)
> - the wireless card is Belkin F5D7000uk
> - the AP is D-Link DI614+
> - the same h/w works with WinXP SP2 (though a bit temperamental).
> 
> Help!  This may be something stupid and obivous - I am new to FreeBSD.
> 
> Full wpa_supplicant output follows:
> ----------------------------------------
> $ wpa_supplicant -i ral0 -c /etc/wpa_supplicant.conf -dd
> Initializing interface 'ral0' conf '/etc/wpa_supplicant.conf' driver 
> 'default'
> Configuration file '/etc/wpa_supplicant.conf' -> '/etc/wpa_supplicant.conf'
> Reading configuration file '/etc/wpa_supplicant.conf'
> ctrl_interface_group=0
> eapol_version=1
> ap_scan=1
> fast_reauth=1
> Line: 6 - start of a new network block
> ssid - hexdump_ascii(len=8):
>      45 70 73 69 6c 6f 6e 33                           Epsilon3
> key_mgmt: 0x2
> PSK (ASCII passphrase) - hexdump_ascii(len=9): [REMOVED]
> PSK (from passphrase) - hexdump(len=32): [REMOVED]
> Priority group 0
>    id=0 ssid='Epsilon3'
> Initializing interface (2) 'ral0'
> Own MAC address: 00:11:50:14:e8:0a
> wpa_driver_bsd_set_wpa: enabled=1
> wpa_driver_bsd_set_wpa_internal: wpa=3 privacy=1
> wpa_driver_bsd_del_key: keyidx=0
> wpa_driver_bsd_del_key: keyidx=1
> wpa_driver_bsd_del_key: keyidx=2
> wpa_driver_bsd_del_key: keyidx=3
> wpa_driver_bsd_set_countermeasures: enabled=0
> wpa_driver_bsd_set_drop_unencrypted: enabled=1
> Setting scan request: 0 sec 100000 usec
> Starting AP scan (broadcast SSID)
> Received 0 bytes of scan results (3 BSSes)
> Scan results: 3
> Selecting BSS from priority group 0
> 0: 00:12:bf:07:4b:e1 ssid='belkin54g' wpa_ie_len=26 rsn_ie_len=0
>    skip - SSID mismatch
> 1: 00:0f:66:4c:9c:99 ssid='brunswick' wpa_ie_len=0 rsn_ie_len=0
>    skip - no WPA/RSN IE
> 2: 00:13:10:4f:fa:1c ssid='TOUB' wpa_ie_len=0 rsn_ie_len=0
>    skip - no WPA/RSN IE
> No suitable AP found.
> Setting scan request: 5 sec 0 usec
> Starting AP scan (broadcast SSID)
> Received 0 bytes of scan results (4 BSSes)
> Scan results: 4
> Selecting BSS from priority group 0
> 0: 00:12:bf:07:4b:e1 ssid='belkin54g' wpa_ie_len=26 rsn_ie_len=0
>    skip - SSID mismatch
> 1: 00:0f:66:4c:9c:99 ssid='brunswick' wpa_ie_len=0 rsn_ie_len=0
>    skip - no WPA/RSN IE
> 2: 00:09:5b:ad:1e:60 ssid='Maygang' wpa_ie_len=0 rsn_ie_len=0
>    skip - no WPA/RSN IE
> 3: 00:13:10:4f:fa:1c ssid='TOUB' wpa_ie_len=0 rsn_ie_len=0
>    skip - no WPA/RSN IE
> No suitable AP found.
> Setting scan request: 5 sec 0 usec
> Starting AP scan (broadcast SSID)
> Received 0 bytes of scan results (5 BSSes)
> Scan results: 5
> Selecting BSS from priority group 0
> 0: 00:80:c8:05:1e:32 ssid='Epsilon3' wpa_ie_len=26 rsn_ie_len=0
>    selected
> Trying to associate with 00:80:c8:05:1e:32 (SSID='Epsilon3' freq=2422 MHz)
> Cancelling scan request
> Automatic auth_alg selection: 0x1
> WPA: using IEEE 802.11i/D3.0
> WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2
> WPA: using GTK TKIP
> WPA: using PTK TKIP
> WPA: using KEY_MGMT WPA-PSK
> 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
> No keys have been configured - skip key clearing
> wpa_driver_bsd_set_drop_unencrypted: enabled=1
> wpa_driver_bsd_associate: ssid 'Epsilon3' wpa ie len 24 pairwise 2 group 
> 2 key mgmt 1
> wpa_driver_bsd_associate: set PRIVACY 1
> Setting authentication timeout: 5 sec 0 usec
> Authentication with 00:00:00:00:00:00 timed out.
> Added BSSID 00:00:00:00:00:00 into blacklist
> No keys have been configured - skip key clearing
> Setting scan request: 0 sec 0 usec
> Starting AP scan (broadcast SSID)
> Received 0 bytes of scan results (6 BSSes)
> Scan results: 6
> Selecting BSS from priority group 0
> 0: 00:12:bf:07:4b:e1 ssid='belkin54g' wpa_ie_len=26 rsn_ie_len=0
>    skip - SSID mismatch
> 1: 00:80:c8:05:1e:32 ssid='Epsilon3' wpa_ie_len=26 rsn_ie_len=0
>    selected
> Trying to associate with 00:80:c8:05:1e:32 (SSID='Epsilon3' freq=2422 MHz)
> Cancelling scan request
> Automatic auth_alg selection: 0x1
> WPA: using IEEE 802.11i/D3.0
> WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2
> WPA: using GTK TKIP
> WPA: using PTK TKIP
> WPA: using KEY_MGMT WPA-PSK
> 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
> No keys have been configured - skip key clearing
> wpa_driver_bsd_set_drop_unencrypted: enabled=1
> wpa_driver_bsd_associate: ssid 'Epsilon3' wpa ie len 24 pairwise 2 group 
> 2 key mgmt 1
> wpa_driver_bsd_associate: set PRIVACY 1
> Setting authentication timeout: 5 sec 0 usec
> Association event - clear replay counter
> Associated to a new BSS: BSSID=00:80:c8:05:1e:32
> No keys have been configured - skioctl[SIOCS80211, op 20, len 7]: Can't 
> assign requested address
> ip key clearing
> Associated with 00:80:c8:05:1e:32
> Setting authentication timeout: 10 sec 0 usec
> RX EAPOL from 00:80:c8:05:1e:32
> RX EAPOL - hexdump(len=99): 01 03 00 5f fe 00 89 00 20 00 00 00 00 00 00 
> 00 01 e5 1d 61 82 9d 47 cb 19 47 c3 24 c9 30 d9 5b 6e 82 0f 8b ce 59 e7 
> 6f f1 80 09 af 5b 15 e1 c5 b9 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 e5 1d 61 82 9d 47 cb 19 47 c3 24 c9 30 d9 5b 6e 82 0f 8b 
> ce 59 e7 6f f1 80 09 af 5b 15 e1 c5 b9 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:80:c8:05:1e:32 (ver=1)
> WPA: Renewed SNonce - hexdump(len=32): 6d c2 57 80 5d 2c 67 a0 e5 f6 31 
> 1a f8 62 53 0b a7 a8 0b 1b c3 8d 1c b4 42 e8 73 35 8e ca 89 ae
> WPA: PMK - hexdump(len=32): [REMOVED]
> WPA: PTK - hexdump(len=64): [REMOVED]
> WPA: EAPOL-Key MIC - hexdump(len=16): a0 ae e7 5e 58 ba ac f0 29 0b c6 
> c3 69 b6 a0 21
> WPA: Sending EAPOL-Key 2/4
> WPA: TX EAPOL-Key 2/4 - hexdump(len=137): 00 80 c8 05 1e 32 00 11 50 14 
> e8 0a 88 8e 01 03 00 77 fe 01 09 00 20 00 00 00 00 00 00 00 01 6d c2 57 
> 80 5d 2c 67 a0 e5 f6 31 1a f8 62 53 0b a7 a8 0b 1b c3 8d 1c b4 42 e8 73 
> 35 8e ca 89 ae 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 a0 ae e7 5e 58 ba ac f0 29 0b c6 
> c3 69 b6 a0 21 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:80:c8:05:1e:32
> RX EAPOL - hexdump(len=125): 01 03 00 79 fe 01 c9 00 20 00 00 00 00 00 
> 00 00 02 e5 1d 61 82 9d 47 cb 19 47 c3 24 c9 30 d9 5b 6e 82 0f 8b ce 59 
> e7 6f f1 80 09 af 5b 15 e1 c5 b9 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 64 8f cd 41 a6 
> 30 31 5e dd 9e c7 47 d0 ba e9 27 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
> IEEE 802.1X RX: version=1 type=3 length=121
>   EAPOL-Key type=254
> WPA: RX EAPOL-Key - hexdump(len=125): 01 03 00 79 fe 01 c9 00 20 00 00 
> 00 00 00 00 00 02 e5 1d 61 82 9d 47 cb 19 47 c3 24 c9 30 d9 5b 6e 82 0f 
> 8b ce 59 e7 6f f1 80 09 af 5b 15 e1 c5 b9 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 64 8f 
> cd 41 a6 30 31 5e dd 9e c7 47 d0 ba e9 27 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
> WPA: RX message 3 of 4-Way Handshake from 00:80:c8:05:1e:32 (ver=1)
> WPA: IE KeyData - hexdump(len=26): 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
> WPA: Sending EAPOL-Key 4/4
> WPA: TX EAPOL-Key 4/4 - hexdump(len=113): 00 80 c8 05 1e 32 00 11 50 14 
> e8 0a 88 8e 01 03 00 5f fe 01 09 00 20 00 00 00 00 00 00 00 02 6d c2 57 
> 80 5d 2c 67 a0 e5 f6 31 1a f8 62 53 0b a7 a8 0b 1b c3 8d 1c b4 42 e8 73 
> 35 8e ca 89 ae 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 80 c5 b9 ad 56 a8 90 99 df 68 db 
> 4b b1 9b eb b7 00 00
> WPA: Installing PTK to the driver.
> WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
> wpa_driver_bsd_set_key: alg=TKIP addr=00:80:c8:05:1e:32 key_idx=0 
> set_tx=1 seq_len=6 key_len=32
> Authentication with 00:80:c8:05:1e:32 timed out.
> Added BSSID 00:80:c8:05:1e:32 into blacklist
> wpa_driver_bsd_disassociate
> wpa_driver_bsd_del_key: keyidx=0
> wpa_driver_bsd_del_key: keyidx=1
> wpa_driver_bsd_del_key: keyidx=2
> wpa_driver_bsd_del_key: keyidx=3
> wpa_driver_bsd_del_key: addr=00:80:c8:05:1e:32 keyidx=0
> Setting scan request: 0 sec 0 usec
> Starting AP scan (broadcast SSID)
> ----------------------------------------
> etc...

This sort of looks like the race I fixed in HEAD recently that caused 
the timer used to identify unanswered mgt frame transmits to trigger 
unexpectedly.  If you enable state transition msgs in the 802.11 layer 
you can see:

wlandebug -i ral0 scan

If you see a spurious state transition from RUN->SCAN then it's the 
problem.  The fix is in RELENG_6 and will appear in 6.1.  You can pull 
it directly as rev 1.26.2.5 of sys/net80211/ieee80211_output.c.

	Sam