Wireless connection (WPA-EAP) stops working after a while

From: Daniel Thiele <dthiele_at_gmx.net>
Date: Tue, 24 Mar 2009 01:58:32 +0100
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:

----8<--------------------------------------------------------
Mar 23 13:27:31 impala wpa_supplicant[429]: Authentication with
00:1b:2f:ef:d3:c9 timed out.
Mar 23 13:27:33 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:27:33 impala wpa_supplicant[429]: Trying to associate with
00:1b:2f:ef:d3:c9 (SSID='IDA' freq=2472 MHz)
Mar 23 13:27:43 impala wpa_supplicant[429]: Authentication with
00:1b:2f:ef:d3:c9 timed out.
Mar 23 13:27:43 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:27:43 impala wpa_supplicant[429]: Trying to associate with
00:1b:2f:ef:d3:b9 (SSID='IDA' freq=2442 MHz)
Mar 23 13:27:53 impala wpa_supplicant[429]: Authentication with
00:1b:2f:ef:d3:b9 timed out.
Mar 23 13:27:56 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:27:56 impala wpa_supplicant[429]: Trying to associate with
00:1b:2f:ef:d3:b9 (SSID='IDA' freq=2442 MHz)
Mar 23 13:28:06 impala wpa_supplicant[429]: Authentication with
00:1b:2f:ef:d3:b9 timed out.
Mar 23 13:28:08 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:28:08 impala wpa_supplicant[429]: Trying to associate with
00:1e:2a:f9:0a:64 (SSID='IDA' freq=2472 MHz)
Mar 23 13:28:18 impala wpa_supplicant[429]: Authentication with
00:1e:2a:f9:0a:64 timed out.
Mar 23 13:28:20 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:28:20 impala wpa_supplicant[429]: Trying to associate with
00:1e:2a:f9:0a:64 (SSID='IDA' freq=2472 MHz)
Mar 23 13:28:30 impala wpa_supplicant[429]: Authentication with
00:1e:2a:f9:0a:64 timed out.
Mar 23 13:28:32 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:28:32 impala wpa_supplicant[429]: Trying to associate with
00:1b:2f:ef:d3:c9 (SSID='IDA' freq=2472 MHz)
Mar 23 13:28:32 impala wpa_supplicant[429]: Associated with
00:1b:2f:ef:d3:c9
Mar 23 13:28:32 impala kernel: wlan0: link state changed to UP
Mar 23 13:28:32 impala wpa_supplicant[429]: CTRL-EVENT-EAP-STARTED EAP
authentication started
Mar 23 13:28:32 impala wpa_supplicant[429]: TLS: Unsupported Phase2 EAP
method 'MSCHAPv2'
Mar 23 13:28:32 impala wpa_supplicant[429]: CTRL-EVENT-EAP-METHOD EAP
vendor 0 method 25 (PEAP) selected
Mar 23 13:28:32 impala wpa_supplicant[429]: OpenSSL:
tls_connection_handshake - Failed to read possible Application Data
error:00000000:lib(0):func(0):reason(0)
Mar 23 13:28:32 impala wpa_supplicant[429]: EAP-MSCHAPV2: Authentication
succeeded
Mar 23 13:28:32 impala wpa_supplicant[429]: EAP-TLV: TLV Result -
Success - EAP-TLV/Phase2 Completed
Mar 23 13:28:32 impala wpa_supplicant[429]: CTRL-EVENT-EAP-SUCCESS EAP
authentication completed successfully
Mar 23 13:28:32 impala wpa_supplicant[429]: WPA: Key negotiation
completed with 00:1b:2f:ef:d3:c9 [PTK=CCMP GTK=TKIP]
Mar 23 13:28:32 impala wpa_supplicant[429]: CTRL-EVENT-CONNECTED -
Connection to 00:1b:2f:ef:d3:c9 completed (auth) [id=3 id_str=]
Mar 23 13:28:40 impala dhclient: New IP Address (wlan0): 192.168.100.54
Mar 23 13:28:40 impala dhclient: New Subnet Mask (wlan0): 255.255.255.0
Mar 23 13:28:40 impala dhclient: New Broadcast Address (wlan0):
192.168.100.255
Mar 23 13:28:40 impala dhclient: New Routers (wlan0): 192.168.100.1
Mar 23 13:28:46 impala su: dthiele to root on /dev/pts/1
Mar 23 13:29:08 impala kernel: ath0: bb hang detected (0x80), reseting

[unrelated logs]

Mar 23 13:33:34 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:35:27 impala kernel: ath0: bb hang detected (0x4), reseting
Mar 23 13:38:36 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:41:48 impala kernel: ath0: mac hang detected (0x8000)
Mar 23 13:43:38 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:48:41 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:53:43 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 13:57:23 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 23 13:58:45 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 14:03:47 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 14:08:50 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 14:13:55 impala wpa_supplicant[429]: CTRL-EVENT-SCAN-RESULTS
Mar 23 14:23:59 impala last message repeated 2 times
Mar 23 14:26:11 impala kernel: ath0: bb hang detected (0x80), reseting
----8<--------------------------------------------------------

After a while (in most cases this happened after roughly an hour)
I get these messages:

----8<--------------------------------------------------------
Mar 23 14:28:45 impala wpa_supplicant[429]: CTRL-EVENT-EAP-STARTED EAP
authentication started
Mar 23 14:28:45 impala wpa_supplicant[429]: CTRL-EVENT-EAP-METHOD EAP
vendor 0 method 25 (PEAP) selected
Mar 23 14:28:45 impala wpa_supplicant[429]: OpenSSL:
tls_connection_handshake - Failed to read possible Application Data
error:00000000:lib(0):func(0):reason(0)
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]
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.


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.

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.

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.


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?


Best regards,

Daniel Thiele



Additioinal information:

impala# uname -a
FreeBSD impala.vnws.lan 8.0-CURRENT FreeBSD 8.0-CURRENT #2: Sun Mar 22
00:34:38 CET 2009
dthiele_at_impala.vnws.lan:/usr/obj/usr/src/sys/kernel_8Xv0  i386
(Kernel and world are in sync)


impala# kldstat -v | grep wlan
                  236 wlan
                  235 wlan_wep
                  234 wlan_tkip
                  233 wlan_ccmp
                  232 wlan_amrr
                  237 wlan_sta


impala# wpa_supplicant -v
wpa_supplicant v0.6.8
Copyright (c) 2003-2009, Jouni Malinen <j_at_w1.fi> and contributors


impala# cat /etc/wpa_supplicant.conf
ctrl_interface=/var/run/wpa_supplicant
ctrl_interface_group=wheel

ap_scan=1
fast_reauth=1

# This is the working setup I am using at home.
# The AP is a ThinkPad R40 running FreeBSD-7.1-STABLE with a rum(4)
# wireless adapter in hostap mode.
network={
          ssid="SuperCollider"
          scan_ssid=1
          mode=0
          proto=WPA
          key_mgmt=WPA-PSK
          psk="[REMOVED]"
          pairwise=CCMP
          priority=10
}

# This is the "partially-working" setup at the university
network={
          ssid="IDA"
          mode=0
          proto=WPA2
          key_mgmt=WPA-EAP
          eap=PEAP
          identity="[REMOVED]"
          anonymous_identity="[REMOVED]"
          password="[REMOVED]"
          ca_cert="[REMOVED]"
          phase2="autH=msCHAPv2"
          priority=2
}


impala# cat /etc/dhclient.conf
timeout 60;
retry 60;
interface "wlan0" {
         prepend domain-name-servers [REMOVED], 217.237.150.188;
         request subnet-mask, broadcast-address, time-offset, routers, 
domain-name;
}


impala# grep wlan /etc/rc.conf
wlans_ath0=wlan0
ifconfig_wlan0="WPA DHCP"
Received on Tue Mar 24 2009 - 00:24:40 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:44 UTC