Date: Mon, 23 Jan 2006 09:56:41 -0800 From: Sam Leffler <sam@errno.com> To: Uwe Laverenz <uwe@laverenz.de> Cc: freebsd-mobile@freebsd.org Subject: Re: Debugging ath device timeouts Message-ID: <43D518D9.6030208@errno.com> In-Reply-To: <20060123145219.GF17465@laverenz.de> References: <20060123041139.GB69091@geoff.deadheaven.com> <20060123145219.GF17465@laverenz.de>
next in thread | previous in thread | raw e-mail | index | archive | help
Uwe Laverenz wrote: > On Sun, Jan 22, 2006 at 08:11:39PM -0800, David F. Severski wrote: > > >>80211stats, I'm at a loss as to where I should be looking to try to track >>down this problem. Search through the archives for this error don't seem >>to point at a consistent area within the stack to look for a culprit. > > > Several people with different chipsets/drivers (iwi, ath, ral...) seem > to have this problem: > > http://www.freebsd.org/cgi/query-pr.cgi?pr=kern/88793 A device timeout in ath means a frame was submitted to the hardware for transmit but no interrupt was received for 5 seconds. I cannot comment on the other drivers but I find it unlikely that the issue is common. The PR has no useful information. > > >>Any suggestions as to what could be causing this error? > > > I guess it could be a bug in wpa_supplicant, I started the following > session with "wpa_supplicant -i iwi0 -c /etc/wpa_supplicant.conf -d": > > --- log --- > [...] > WPA: RX message 1 of Group Key Handshake from 00:13:49:12:02:29 (ver=1) > WPA: Group Key - hexdump(len=32): [REMOVED] > WPA: Installing GTK to the driver (keyidx=1 tx=0). > WPA: RSC - hexdump(len=6): 00 00 00 00 00 00 > wpa_driver_bsd_set_key: alg=TKIP addr=ff:ff:ff:ff:ff:ff key_idx=1 > set_tx=0 seq_l en=6 key_len=32 > WPA: Sending EAPOL-Key 2/2 > WPA: Key negotiation completed with 00:13:49:12:02:29 [PTK=TKIP > GTK=TKIP] > Cancelling authentication timeout > EAPOL: External notification - portValid=1 > EAPOL: External notification - EAP success=1 > EAPOL: SUPP_PAE entering state AUTHENTICATING > EAPOL: SUPP_BE entering state SUCCESS > EAPOL: SUPP_PAE entering state AUTHENTICATED > EAPOL: SUPP_BE entering state IDLE > > [...several minutes connection ok...] > > RX EAPOL from 00:13:49:12:02:29 > EAPOL: Ignoring WPA EAPOL-Key frame in EAPOL state machines > IEEE 802.1X RX: version=1 type=3 length=127 > EAPOL-Key type=254 > WPA: RX message 1 of Group Key Handshake from 00:13:49:12:02:29 (ver=1) > WPA: Group Key - hexdump(len=32): [REMOVED] > WPA: Installing GTK to the driver (keyidx=1 tx=0). > WPA: RSC - hexdump(len=6): 00 00 00 00 00 00 > wpa_driver_bsd_set_key: alg=TKIP addr=ff:ff:ff:ff:ff:ff key_idx=1 > set_tx=0 seq_len=6 key_len=32 > WPA: Sending EAPOL-Key 2/2 > WPA: Group rekeying completed with 00:13:49:12:02:29 [GTK=TKIP] > > [...connection still ok...] > > RX EAPOL from 00:13:49:12:02:29 > EAPOL: Ignoring WPA EAPOL-Key frame in EAPOL state machines > IEEE 802.1X RX: version=1 type=3 length=95 > EAPOL-Key type=254 > WPA: RX message 1 of 4-Way Handshake from 00:13:49:12:02:29 (ver=1) > WPA: Renewed SNonce - hexdump(len=32): d3 d6 43 c2 48 d3 a4 1b a7 fd ee > 55 49 c2 c6 b9 8c 24 1d 8c 33 b5 fe ea 23 cc ff 23 71 8e 54 7b > WPA: PMK - hexdump(len=32): [REMOVED] > WPA: PTK - hexdump(len=64): [REMOVED] > WPA: EAPOL-Key MIC - hexdump(len=16): 34 01 ba 96 f7 c1 40 08 0d 00 ec > f0 3a d9 38 b7 > WPA: Sending EAPOL-Key 2/4 > RX EAPOL from 00:13:49:12:02:29 > EAPOL: Ignoring WPA EAPOL-Key frame in EAPOL state machines > IEEE 802.1X RX: version=1 type=3 length=119 > EAPOL-Key type=254 > WPA: RX message 3 of 4-Way Handshake from 00:13:49:12:02:29 (ver=1) > WPA: IE KeyData - 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 > WPA: Sending EAPOL-Key 4/4 > 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:13:49:12:02:29 key_idx=0 > set_tx=1 seq_len=6 key_len=32 > Received 0 bytes of scan results (1 BSSes) > Scan results: 1 > Selecting BSS from priority group 10 > 0: 00:13:49:12:02:29 ssid='Nostromo' wpa_ie_len=24 rsn_ie_len=0 > selected > Already associated with the selected AP. > > [...connection down...] > > --- log --- > > At this point you often get the connection up again with a restart of > wpa_supplicant or a "killall -1 wpa_supplicant". The iwi driver has issues unrelated to ath. Comparing the two is unlikely to help. If you provide a complete wpa supplicant log (privately) I can try to understand what you're seeing. From the snippet above it appears wpa_supplicant was notified that the sta associated/reassociated after it had completed re-keying. This likely means that iwi driver is out of sync w/ wpa_supplicant and/or is not properly dispatching events through the net80211 layer to wpa_supplicant. > > It looks like wpa_supplicant thinks everything is fine with the > connection when it's not?! This behaviour is reproduceable with two > different Access Points (Linksys WRT54G, Zywall 5). I could do some > additional tests with a Dlink wireless card (ath-chipset). iwi is totally different from ath. Trying to infer a problem in one using the other is likely to just confuse the matter. If you've got an iwi problem stick with it. Sam
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?43D518D9.6030208>