Re: ral/wpa_supplicant drops after successful WPA negotiation?

Sam Leffler wrote:
> 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
> 

Thanks!
Alas, I don't think that's it.
I did "sysctl net.wlan.0.debug=0xFFFFFFFF" - I guess that is the 
slegdehammer approach in absence of wlandebug (couldn't find that - I 
optimistically installed only X-User).

The following seem to be the transitions (output of dmesg | grep 
newstate | sort | uniq):
ral0: ieee80211_newstate: ASSOC -> RUN
ral0: ieee80211_newstate: AUTH -> ASSOC
ral0: ieee80211_newstate: INIT -> INIT
ral0: ieee80211_newstate: INIT -> SCAN
ral0: ieee80211_newstate: RUN -> INIT
ral0: ieee80211_newstate: SCAN -> AUTH
ral0: ieee80211_newstate: SCAN -> SCAN

And here's an excerpt of dmesg | grep ral0:
----------------------------------------
ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 3
ral0: received probe_resp from 00:80:c8:05:1e:32 rssi 42
ral0: ieee80211_setup_node 0xc2059c00<00:80:c8:05:1e:32> in scan table
[00:80:c8:05:1e:32] new probe_resp on chan 3 (bss chan 3) "Epsilon3"
[00:80:c8:05:1e:32] caps 0x51 bintval 1000 erp 0x0
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
[00:80:c8:05:1e:32] beacon on chan 3 (bss chan 3) "Epsilon3"
ral0: ieee80211_cancel_scan: end active scan
ral0: ral0: notify scan done
ral0: ieee80211_find_node_with_ssid 0xc2059c00<00:80:c8:05:1e:32> refcnt 2
ral0: _ieee80211_free_node 0xc205b400<00:11:50:14:e8:0a> in <gone> table
ral0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0
ral0: ieee80211_newstate: SCAN -> AUTH
ral0: ieee80211_ref_node (ieee80211_send_mgmt:1063) 
0xc2059c00<00:80:c8:05:1e:32> refcnt 3
[00:80:c8:05:1e:32] send auth on channel 3
ral0: received auth from 00:80:c8:05:1e:32 rssi 43
ral0: [00:80:c8:05:1e:32] recv auth frame with algorithm 0 seq 2
ral0: ieee80211_newstate: AUTH -> ASSOC
ral0: ieee80211_ref_node (ieee80211_send_mgmt:1063) 
0xc2059c00<00:80:c8:05:1e:32> refcnt 4
[00:80:c8:05:1e:32] send assoc_req on channel 3
[ral0:00:80:c8:05:1e:32] discard duplicate frame, seqno <1188,1188> 
fragno <0,0> tid 0
ral0: received assoc_resp from 00:80:c8:05:1e:32 rssi 43
ral0: [00:80:c8:05:1e:32] assoc success: long preamble, long slot time
ral0: ieee80211_newstate: ASSOC -> RUN
ral0: associated with 00:80:c8:05:1e:32 ssid "Epsilon3" channel 3 start 1Mb
ral0: link state changed to UP
[ral0:00:80:c8:05:1e:32] discard duplicate frame, seqno <1189,1189> 
fragno <0,0> tid 0
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 44
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: ieee80211_crypto_newkey: no h/w support for cipher TKIP, falling 
back to s/w
ral0: ieee80211_crypto_newkey: no h/w support for TKIP MIC, falling back 
to s/w
ral0: ieee80211_crypto_setkey: TKIP keyix 0 flags 0x33 mac 
00:80:c8:05:1e:32 rsc 0 tsc 0 len 16
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
[ral0:00:90:4b:f6:27:5e] discard frame, not to bss
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: received beacon from 00:80:c8:05:1e:32 rssi 43
ral0: ieee80211_newstate: RUN -> INIT
ral0: ieee80211_ref_node (ieee80211_send_mgmt:1063) 
0xc2059c00<00:80:c8:05:1e:32> refcnt 3
ral0: [00:80:c8:05:1e:32] send station disassociate (reason 8)
[00:80:c8:05:1e:32] send disassoc on channel 3
ral0: _ieee80211_crypto_delkey: TKIP keyix 0 flags 0x33 rsc 0 tsc 1 len 16
ral0: link state changed to DOWN
ral0: ieee80211_node_table_reset scan table
ral0: ieee80211_free_allnodes_locked: free all nodes in scan table
----------------------------------------
etc...

Anything wrong with this (the beacons from my AP?)

Cheers, Peter
--
Peter de Rooij <[email protected]>
_______________________________________________
[email protected] mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-mobile
To unsubscribe, send any mail to "[email protected]"