From owner-freebsd-mobile@FreeBSD.ORG Mon Jan 23 14:52:43 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 AEC7316A420 for ; Mon, 23 Jan 2006 14:52:42 +0000 (GMT) (envelope-from uwe@laverenz.de) Received: from natsmtp00.rzone.de (natsmtp00.rzone.de [81.169.145.165]) by mx1.FreeBSD.org (Postfix) with ESMTP id 1E81F43D6A for ; Mon, 23 Jan 2006 14:52:23 +0000 (GMT) (envelope-from uwe@laverenz.de) Received: from athena.laverenz.de (p5480C002.dip.t-dialin.net [84.128.192.2]) by post.webmailer.de (8.13.1/8.13.1) with ESMTP id k0NEqLiU029853 for ; Mon, 23 Jan 2006 15:52:21 +0100 (MET) Received: from localhost (localhost.localdomain [127.0.0.1]) by athena.laverenz.de (Postfix) with ESMTP id 0611FE379FDD for ; Mon, 23 Jan 2006 15:52:21 +0100 (CET) Received: from athena.laverenz.de ([127.0.0.1]) by localhost (athena [127.0.0.1]) (amavisd-new, port 10024) with LMTP id 17549-05 for ; Mon, 23 Jan 2006 15:52:19 +0100 (CET) Received: by athena.laverenz.de (Postfix, from userid 2000) id 8B512E379FD0; Mon, 23 Jan 2006 15:52:19 +0100 (CET) Date: Mon, 23 Jan 2006 15:52:19 +0100 From: Uwe Laverenz To: freebsd-mobile@freebsd.org Message-ID: <20060123145219.GF17465@laverenz.de> Mail-Followup-To: freebsd-mobile@freebsd.org References: <20060123041139.GB69091@geoff.deadheaven.com> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20060123041139.GB69091@geoff.deadheaven.com> Organization: private site Sender: uwe@laverenz.de User-Agent: Mutt/1.5.9i X-Virus-Scanned: by amavisd-new-20030616-p10 (Debian) at laverenz.de 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 14:52:43 -0000 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