From owner-freebsd-current@FreeBSD.ORG Thu Mar 26 01:10:36 2009 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 0E1561065672 for ; Thu, 26 Mar 2009 01:10:36 +0000 (UTC) (envelope-from dthiele@gmx.net) Received: from mail.gmx.net (mail.gmx.net [213.165.64.20]) by mx1.freebsd.org (Postfix) with SMTP id 4A4638FC1B for ; Thu, 26 Mar 2009 01:10:34 +0000 (UTC) (envelope-from dthiele@gmx.net) Received: (qmail invoked by alias); 26 Mar 2009 01:10:28 -0000 Received: from p54865167.dip.t-dialin.net (EHLO impala.vnws.lan) [84.134.81.103] by mail.gmx.net (mp043) with SMTP; 26 Mar 2009 02:10:28 +0100 X-Authenticated: #19302822 X-Provags-ID: V01U2FsdGVkX1+MUK06s2iMSA8+Y8Bm88ZxIldne1zE4l705xpHlM 5/04BUIgMzmvBO Message-ID: <49CAD620.2030106@gmx.net> Date: Thu, 26 Mar 2009 02:10:56 +0100 From: Daniel Thiele User-Agent: Thunderbird 2.0.0.21 (X11/20090321) MIME-Version: 1.0 To: Sam Leffler References: <49C83038.40300@gmx.net> <49CAC1C0.9030506@freebsd.org> In-Reply-To: <49CAC1C0.9030506@freebsd.org> X-Enigmail-Version: 0.95.6 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-Y-GMX-Trusted: 0 X-FuHaFi: 0.46 Cc: freebsd-current@freebsd.org Subject: Re: Wireless connection (WPA-EAP) stops working after a while X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 26 Mar 2009 01:10:36 -0000 Sam Leffler wrote: > Daniel Thiele wrote: >> Hi, >> >> I have a problem with my wireless connection. I am running FreeBSD >> 8.0-CURRENT (from Mar 22) with wpa_supplicant v0.6.8 using an Atheros >> based ExpressCard (D-Link DWA-643 via ath(4)) and alternatively a Ralink >> based USB adapter (Linksys WUSB54GC-EU via rum(4)). >> >> At home using the Atheros card together with a FreeBSD (7.1) based >> access point (using rum(4) in hostap mode) and the wpa_supplicant.conf >> (attached at the end of this email) settings for SSID="home" I don't >> have any problems. With a Linksys WRT54GL-DE access point >> running the OpenWRT White Russian 0.9 firmware and OpenVPN over an open >> wireless LAN also works flawlessly. >> >> At the university, however, (SSID="IDA" in the wpa_supplicant.conf at >> the end of this email) the wireless connection only works for about an >> hour. The vague term "wireless connection" in this case means, that the >> WPA connection is opened and associated, then I get an IP address via >> dhclient. There is a message about "OpenSSL: tls_connection_handshake - >> Failed to read possible Application Data >> error:00000000:lib(0):func(0):reason(0)" and "TLS: Unsupported Phase2 >> EAP method 'MSCHAPv2'" but the authentication seems to succeed: > > <...stuff deleted...> >> >> >> Mar 23 14:28:45 impala wpa_supplicant[429]: EAP-MSCHAPV2: Authentication >> succeeded >> Mar 23 14:28:45 impala wpa_supplicant[429]: EAP-TLV: TLV Result - >> Success - EAP-TLV/Phase2 Completed >> Mar 23 14:28:46 impala wpa_supplicant[429]: CTRL-EVENT-EAP-SUCCESS EAP >> authentication completed successfully >> Mar 23 14:28:46 impala wpa_supplicant[429]: WPA: Failed to set PTK to >> the driver. >> Mar 23 14:28:46 impala wpa_supplicant[429]: WPA: Key negotiation >> completed with 00:1b:2f:ef:d3:c9 [PTK=CCMP GTK=TKIP] > > This doesn't look good. For some reason the PTK key was not plumbed; > this means the ioctl that made the request failed. Unfortunately > there's no more information to explain why but typically this is because > the station is no longer associated. But for some reason wpa_supplicant > didn't seem to handle the error properly; it appears it thinks the key > exchange was completed when it was not. A glance at the code looks like > it's ignoring errors; e.g. in contrib/wpa/src/rsn_supp/wpa.c in > wpa_supplicant_process_3_of_4: > > if (key_info & WPA_KEY_INFO_INSTALL) { > wpa_supplicant_install_ptk(sm, key); > } > > (the error return by wpa_supplicant_install_ptk is not checked). This > might be handled some other way but it's not clear why it should proceed. > > >> Mar 23 14:29:01 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS >> Mar 23 14:34:03 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS >> Mar 23 14:39:05 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS >> ----8<-------------------------------------------------------- >> >> ifconfig still lists the connection as "associated": >> >> ----8<-------------------------------------------------------- >> impala# ifconfig wlan0 >> wlan0: flags=8843 metric 0 mtu >> 1500 >> ether 00:21:91:db:15:30 >> media: IEEE 802.11 Wireless Ethernet OFDM/48Mbps mode 11g >> status: associated >> ssid IDA channel 13 (2472 Mhz 11g) bssid 00:1b:2f:ef:d3:c9 >> regdomain ETSI indoor ecm authmode WPA2/802.11i privacy ON >> deftxkey UNDEF TKIP 2:128-bit txpower 20 bmiss 7 scanvalid 450 >> bgscan >> bgscanintvl 300 bgscanidle 250 roam:rssi 7 roam:rate 5 >> protmode CTS >> wme burst roaming MANUAL >> ----8<-------------------------------------------------------- >> >> But dhclient does not accept any new leases: >> >> ----8<-------------------------------------------------------- >> impala# dhclient wlan0 >> DHCPREQUEST on wlan0 to 255.255.255.255 port 67 >> DHCPNAK from 192.168.100.1 >> DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 4 >> DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 10 >> DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 12 >> DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 13 >> DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 8 >> DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 14 >> No DHCPOFFERS received. >> Trying recorded lease 192.168.100.54 >> bound: renewal in 5900 seconds. >> ----8<-------------------------------------------------------- >> >> The site's wireless admin was so kind to provide me with the logs from >> their DHCP server, which seems to offer new leases that somehow don't >> make it through to my machine: >> >> ----8<-------------------------------------------------------- >> DHCPDISCOVER from 00:21:91:db:15:30 (impala) via 192.168.100.1 >> DHCPOFFER on 192.168.100.54 to 00:21:91:db:15:30 (impala) via >> 192.168.100.1 >> ----8<-------------------------------------------------------- >> >> If I audaciously assign myself an IP address (192.168.100.54) and set >> the default route to 192.168.100.1, the wireless connection sill won't >> work. I cannot even ping the router at 192.168.100.1. >> >> >> Next, I tried to rule out the wireless adapter. Both the Atheros >> ExpressCard and the Ralink USB Adapter show the above mentioned >> behavior. So the problem might perhaps be located in FreeBSD's wireless >> stack, wpa_supplicant or dhclient? But I'm not an expert in these areas, >> thus this email. > > It appears this is an issue in wpa_supplicant but it's hard to say. I'd > need to know if the association was broken during the time the key plumb > failed. That should've been reported to wpa_supplicant which should've > logged a msg so I'm guessing no. So we're back to why the key wasn't > plumbed as everything that follows makes sense (i.e. you can't get data > packets through). If you turn on crypto debugging in net80211 you might > get some info from the console msgs; e.g. > > wlandebug crypto > > You should also configure wpa_supplicant debugging so we get more info > from the driver; add > > wpa_supplicant_flags="-sd" > > to your rc.conf file (or start wpa_supplicant by hand). > Thanks, I will try that. >> >> >> What works in the case of the Ralink USB adapter is simply unplugging >> and replugging the device. Then I get another hour of working wireless >> before it breaks again. Since hot-plugging the ExpressCard currently >> does not seem to work I cannot confirm this for the Atheros adapter. > > This sounds like the supplicant is out of sync w/ the ap and you can't > get packets through because you've got the old/wrong key plumbed on the > station. > >> >> I also tried >> >> ----8<-------------------------------------------------------- >> /etc/rc.d/netif restart >> ----8<-------------------------------------------------------- >> >> and >> >> ----8<-------------------------------------------------------- >> ifconfig wlan0 destroy >> ifconfig wlan0 create wlandev rum0 >> ----8<-------------------------------------------------------- >> >> followed by a restart of wpa_suppicant and dhclient, too, but without >> any success. So only re-plugging the device seems to solve or at least >> stall the problem. > > That doesn't make sense. Destroying the vap should be equivalent to > ejecting the device. There should no crypto state kept after a vap is > destroyed. You can verify this for the ath device using athregs > (tools/tools/ath/athregs); athregs -k will dump the contents of the h/w > key cache if the ath driver is built with ATH_DIAGAPI). This is enabled by adding "options ATH_DIAGAPI" to my kernel configuration file, right? > >> >> The output of wpa_supplicant -ddd after the wireless connection stopped >> working can be found at: >> http://www-public.tu-bs.de:8080/~y0023183/FreeBSD/Wireless/wpa_supplicant-ddd.txt >> >> >> >> On a FreeBSD 7.1-STABLE machine with wpa_supplicant v0.5.10 and the >> Ralink USB adapter I did not encounter the problem. > > If I understand correctly the above is for FreeBSD HEAD+0.6.8 so a more > useful comparison is HEAD+0.5.11/0.5.10 which would tell us definitely > if this is a supplicant issue. > Yes, the machine with the borken wireless is a HEAD+0.6.8. I have not tried HEAD+0.5.11, yet. But I will do that on Friday. >> >> >> Now, my question is has anyone else encountered this behavior (WPA-PSK >> working nicely and WPA-EAP only for a limited period of time) and knows >> how to fix this issue? Perhaps it is just a misconfiguration on my >> part. If not, how can I help to further investigate this issue. What can >> I do to provide additional debug information? >> > > I checked the 0.6.9 release that I suggested might have a fix but was > wrong. The change that caught my attention was for hostapd, not > wpa_supplicant. So we're back to isolating whether this is a regression > in the supplicant. The best suggestion I have is to back-rev your HEAD > tree to just before I imported wpa_supplicant 0.6.8. Talk to me > off-line if you need help w/ that. > I already prepared a USB flash drive with a CURRENT from March 3 20:00h. At least i hope that this is what *default release=cvs tag=. date=2009.03.01.20.00.00 in my supfile gave me. A first boot confirmed that I got wpa_supplicant 0.5.11, so I think it worked. BTW. is there a way for normal users to easily check-out a specific SVN revision? The procedure described in the FreeBSD wiki http://wiki.freebsd.org/SubversionPrimer seems to require a valid FreeBSD login name. And I can understand that to efficiently use resources and bandwidth CVSup is used to serve normal users. Maybe I'm just missing something, but it is a little cumbersome to manually look up the SVN revisions at svn-src-head@ to get the corresponding date for the supfile. Anyway, on Friday I will turn on debug output on my HEAD+0.6.8 (or 0.6.9 as of yesterday) machine and also investigate the issue with the prepared USB flash drive and a back-rev'ed HEAD+0.5.11. Daniel