From owner-freebsd-mobile@FreeBSD.ORG Tue Feb 21 00:41:17 2006 Return-Path: X-Original-To: freebsd-mobile@freebsd.org Delivered-To: freebsd-mobile@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 6A89816A420 for ; Tue, 21 Feb 2006 00:41:17 +0000 (GMT) (envelope-from peterjderooij@gmail.com) Received: from wproxy.gmail.com (wproxy.gmail.com [64.233.184.206]) by mx1.FreeBSD.org (Postfix) with ESMTP id C85FB43D46 for ; Tue, 21 Feb 2006 00:41:16 +0000 (GMT) (envelope-from peterjderooij@gmail.com) Received: by wproxy.gmail.com with SMTP id i21so1000581wra for ; Mon, 20 Feb 2006 16:41:15 -0800 (PST) DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=beta; d=gmail.com; h=received:message-id:date:from:reply-to:user-agent:x-accept-language:mime-version:to:cc:subject:references:in-reply-to:content-type:content-transfer-encoding:sender; b=oDwZx+lm6+OVpfOTnhXA6PDSKREqGujrebJGtQtLaIxpE89mxOT667qsyQ20+RrWAQb0dlOHLmq5nvpnX/oHdXcV1XefthXcB/m5pM+JGeEw3ySCW00mFusUae3vVaass1EdzrDpS2LDujI7H7FI+KsGr8VedCRN+A/sav2icCM= Received: by 10.64.148.6 with SMTP id v6mr653628qbd; Mon, 20 Feb 2006 16:41:15 -0800 (PST) Received: from ?192.168.0.101? ( [213.78.154.12]) by mx.gmail.com with ESMTP id e16sm3861655qba.2006.02.20.16.41.14; Mon, 20 Feb 2006 16:41:15 -0800 (PST) Message-ID: <43FA61A4.8030406@derooij.org> Date: Tue, 21 Feb 2006 00:41:08 +0000 From: Peter de Rooij User-Agent: Mozilla Thunderbird 1.0.5 (Windows/20050711) X-Accept-Language: en-us, en MIME-Version: 1.0 To: Sam Leffler References: <43F9E6B4.3040309@derooij.org> <43F9F4AD.3070107@errno.com> In-Reply-To: <43F9F4AD.3070107@errno.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Sender: Peter de Rooij Cc: freebsd-mobile@freebsd.org Subject: Re: ral/wpa_supplicant drops after successful WPA negotiation? X-BeenThere: freebsd-mobile@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: peter@derooij.org List-Id: Mobile computing with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 21 Feb 2006 00:41:17 -0000 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 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