Date: Thu, 26 Mar 2009 02:10:56 +0100 From: Daniel Thiele <dthiele@gmx.net> To: Sam Leffler <sam@freebsd.org> Cc: freebsd-current@freebsd.org Subject: Re: Wireless connection (WPA-EAP) stops working after a while Message-ID: <49CAD620.2030106@gmx.net> In-Reply-To: <49CAC1C0.9030506@freebsd.org> References: <49C83038.40300@gmx.net> <49CAC1C0.9030506@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
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<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> 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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?49CAD620.2030106>