Debugging ath device timeouts

[Sam Leffler]

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