From owner-freebsd-mobile@FreeBSD.ORG Mon Jan 23 17:55:01 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 C426616A423 for ; Mon, 23 Jan 2006 17:55:01 +0000 (GMT) (envelope-from sam@errno.com) Received: from ebb.errno.com (ebb.errno.com [69.12.149.25]) by mx1.FreeBSD.org (Postfix) with ESMTP id 091FF43D48 for ; Mon, 23 Jan 2006 17:55:00 +0000 (GMT) (envelope-from sam@errno.com) Received: from [10.0.0.248] (trouble.errno.com [10.0.0.248]) (authenticated bits=0) by ebb.errno.com (8.12.9/8.12.6) with ESMTP id k0NHsxo7050935 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Mon, 23 Jan 2006 09:55:00 -0800 (PST) (envelope-from sam@errno.com) Message-ID: <43D518D9.6030208@errno.com> Date: Mon, 23 Jan 2006 09:56:41 -0800 From: Sam Leffler User-Agent: Mozilla Thunderbird 1.0.7 (X11/20051227) X-Accept-Language: en-us, en MIME-Version: 1.0 To: Uwe Laverenz References: <20060123041139.GB69091@geoff.deadheaven.com> <20060123145219.GF17465@laverenz.de> In-Reply-To: <20060123145219.GF17465@laverenz.de> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Cc: freebsd-mobile@freebsd.org Subject: Re: Debugging ath device timeouts X-BeenThere: freebsd-mobile@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Mobile computing with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 23 Jan 2006 17:55:01 -0000 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