Skip site navigation (1)Skip section navigation (2)
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>