Debugging ath device timeouts

[Uwe Laverenz]

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

> 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".

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).

bye,
Uwe