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

Sat Mar 28 15:27:28 PDT 2009

Hi Sam,

I ran tests with both a CURRENT from March 26 + (the manually updated)
wpa_supplicant 0.6.9 and an older CURRENT from March 1 2000h +
wpa_supplicant 0.5.11. I included the logs below. Unfortunately, in both
cases I get the "WPA: Failed to set PTK to the driver" error and the
wireless adapter stops working.

FreeBSD: CURRENT from March 26 (manually updated wpa_supplicant)
wpa_supplicant 0.6.9 (running with wpa_supplicant_flags="-sd")
wlandebug crypto

Via dmesg:
----8<----------------------------------------------------------
wlan0: link state changed to UP
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x4), reseting
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x4), reseting
wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x3 keyix 4
wlan0: ieee80211_crypto_newkey: unable to setup cipher AES-CCM
wlan0: ieee80211_crypto_newkey: cipher 1 flags 0x6 keyix 1
wlan0: ieee80211_crypto_setkey: TKIP keyix 1 flags 0x106 mac 
ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16
ath0: bb hang detected (0x4), reseting
ath0: bb hang detected (0x4), reseting
----8<----------------------------------------------------------

 From /var/log/messages:
----8<----------------------------------------------------------
Mar 27 13:28:55 impala kernel: wlan0: Ethernet address: 00:21:91:db:15:30
Mar 27 13:28:55 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 13:28:55 impala wpa_supplicant[426]: Trying to associate with 
00:1b:2f:ef:d3:c9 (SSID='IDA' freq=2472 MHz)
Mar 27 13:28:55 impala kernel: wlan0: link state changed to UP
Mar 27 13:28:55 impala wpa_supplicant[426]: Associated with 
00:1b:2f:ef:d3:c9
Mar 27 13:28:55 impala wpa_supplicant[426]: CTRL-EVENT-EAP-STARTED EAP 
authentication started
Mar 27 13:28:55 impala wpa_supplicant[426]: TLS: Unsupported Phase2 EAP 
method 'MSCHAPv2'
Mar 27 13:28:55 impala wpa_supplicant[426]: CTRL-EVENT-EAP-METHOD EAP 
vendor 0 method 25 (PEAP) selected
Mar 27 13:28:55 impala wpa_supplicant[426]: OpenSSL: 
tls_connection_handshake - Failed to read possible Application Data 
error:00000000:lib(0):func(0):reason(0)
Mar 27 13:28:55 impala wpa_supplicant[426]: EAP-MSCHAPV2: Authentication 
succeeded
Mar 27 13:28:55 impala wpa_supplicant[426]: EAP-TLV: TLV Result - 
Success - EAP-TLV/Phase2 Completed
Mar 27 13:28:55 impala wpa_supplicant[426]: CTRL-EVENT-EAP-SUCCESS EAP 
authentication completed successfully
Mar 27 13:28:55 impala wpa_supplicant[426]: WPA: Key negotiation 
completed with 00:1b:2f:ef:d3:c9 [PTK=CCMP GTK=TKIP]
Mar 27 13:28:55 impala wpa_supplicant[426]: CTRL-EVENT-CONNECTED - 
Connection to 00:1b:2f:ef:d3:c9 completed (auth) [id=3 id_str=]
Mar 27 13:29:01 impala dhclient: New IP Address (wlan0): 192.168.100.54
Mar 27 13:29:01 impala dhclient: New Subnet Mask (wlan0): 255.255.255.0
Mar 27 13:29:01 impala dhclient: New Broadcast Address (wlan0): 
192.168.100.255
Mar 27 13:29:01 impala dhclient: New Routers (wlan0): 192.168.100.1
Mar 27 13:32:43 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 27 13:33:57 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 13:34:50 impala kernel: ath0: bb hang detected (0x4), reseting
Mar 27 13:38:59 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 13:39:20 impala su: dthiele to root on /dev/pts/3
Mar 27 13:39:38 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 27 13:44:03 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 13:44:28 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 27 13:49:06 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 13:49:29 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 27 13:54:08 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 13:54:27 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 27 13:59:11 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 13:59:33 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 27 14:04:13 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:09:15 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:09:27 impala kernel: ath0: bb hang detected (0x80), reseting
Mar 27 14:14:17 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:16:32 impala kernel: ath0: bb hang detected (0x4), reseting
Mar 27 14:19:19 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:24:21 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:28:59 impala wpa_supplicant[426]: CTRL-EVENT-EAP-STARTED EAP 
authentication started
Mar 27 14:28:59 impala wpa_supplicant[426]: CTRL-EVENT-EAP-METHOD EAP 
vendor 0 method 25 (PEAP) selected
Mar 27 14:29:00 impala wpa_supplicant[426]: OpenSSL: 
tls_connection_handshake - Failed to read possible Application Data 
error:00000000:lib(0):func(0):reason(0)
Mar 27 14:29:00 impala wpa_supplicant[426]: EAP-MSCHAPV2: Authentication 
succeeded
Mar 27 14:29:00 impala wpa_supplicant[426]: EAP-TLV: TLV Result - 
Success - EAP-TLV/Phase2 Completed
Mar 27 14:29:00 impala wpa_supplicant[426]: CTRL-EVENT-EAP-SUCCESS EAP 
authentication completed successfully
Mar 27 14:29:01 impala kernel: wlan0: ieee80211_crypto_newkey: cipher 3 
flags 0x3 keyix 4
Mar 27 14:29:01 impala kernel:
Mar 27 14:29:01 impala kernel: wlan0: ieee80211_crypto_newkey: unable to 
setup cipher AES-CCM
Mar 27 14:29:01 impala kernel:
Mar 27 14:29:01 impala kernel: wlan0: ieee80211_crypto_newkey: cipher 1 
flags 0x6 keyix 1
Mar 27 14:29:01 impala kernel: wlan0: ieee80211_crypto_setkey: TKIP 
keyix 1 flags 0x106 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16
Mar 27 14:29:01 impala wpa_supplicant[426]: WPA: Failed to set PTK to 
the driver.
Mar 27 14:29:01 impala wpa_supplicant[426]: WPA: Key negotiation 
completed with 00:1b:2f:ef:d3:c9 [PTK=CCMP GTK=TKIP]
Mar 27 14:29:23 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:34:26 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:39:28 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:49:32 impala last message repeated 2 times
Mar 27 14:54:34 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 14:55:10 impala kernel: ath0: bb hang detected (0x4), reseting
Mar 27 14:59:36 impala wpa_supplicant[426]: CTRL-EVENT-SCAN-RESULTS
Mar 27 15:00:30 impala kernel: ath0: bb hang detected (0x4), reseting
----8<----------------------------------------------------------

FreeBSD: CURRENT from March 1 (2000h)
wpa_supplicant 0.5.11 (running with wpa_supplicant_flags="-sd")
wlandebug crypto
(This is the same hardware as above. I just changed the hostname)

Via dmesg:
----8<----------------------------------------------------------
wlan0: Ethernet address: 00:21:91:db:15:30
wlan0: link state changed to UP
wlan0: link state changed to DOWN
wlan0: Ethernet address: 00:21:91:db:15:30
wlan0: Ethernet address: 00:21:91:db:15:30
wlan0: link state changed to UP
wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 
len 0
wlan0: _ieee80211_crypto_delkey: TKIP keyix 1 flags 0x106 rsc 1096785 
tsc 1 len 16
wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 
len 0
wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 
len 0
wlan0: _ieee80211_crypto_delkey: AES-CCM keyix 4 flags 0x103 rsc 28882 
tsc 19125 len 16
wlan0: link state changed to DOWN
wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 
len 0
wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 
len 0
wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 
len 0
wlan0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 
len 0
wlan0: link state changed to UP
wlan0: [00:1b:2f:ef:d3:b9] key id 1 is not set (decap)
wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x3 keyix 65535
wlan0: ieee80211_crypto_setkey: AES-CCM keyix 4 flags 0x103 mac 
00:1b:2f:ef:d3:b9 rsc 0 tsc 0 len 16
wlan0: ieee80211_crypto_newkey: cipher 1 flags 0x6 keyix 1
wlan0: ieee80211_crypto_setkey: TKIP keyix 1 flags 0x106 mac 
ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16
wlan0: [00:1b:2f:ef:d3:b9] AES-CCM replay detected <rsc 0, csc 0, keyix 
4 rxkeyix 4>
ath0: bb hang detected (0x80), reseting
wlan0: ieee80211_crypto_newkey: cipher 3 flags 0x3 keyix 4
wlan0: ieee80211_crypto_newkey: unable to setup cipher AES-CCM
wlan0: ieee80211_crypto_newkey: cipher 1 flags 0x6 keyix 1
wlan0: ieee80211_crypto_setkey: TKIP keyix 1 flags 0x106 mac 
ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16
ath0: bb hang detected (0x80), reseting
ath0: bb hang detected (0x80), reseting
----8<----------------------------------------------------------

 From /var/log/messages:
----8<----------------------------------------------------------
Mar 27 15:22:32 edward kernel: wlan0: Ethernet address: 00:21:91:db:15:30
Mar 27 15:22:35 edward wpa_supplicant[2815]: Trying to associate with 
00:1b:2f:ef:d3:b9 (SSID='IDA' freq=2442 MHz)
Mar 27 15:22:35 edward kernel: wlan0: link state changed to UP
Mar 27 15:22:35 edward wpa_supplicant[2815]: Associated with 
00:1b:2f:ef:d3:b9
Mar 27 15:22:35 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-STARTED EAP 
authentication started
Mar 27 15:22:35 edward wpa_supplicant[2815]: EAP-PEAP: Unsupported 
Phase2 method 'MSCHAPv2'
Mar 27 15:22:35 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-METHOD EAP 
vendor 0 method 25 (PEAP) selected
Mar 27 15:22:35 edward wpa_supplicant[2815]: OpenSSL: 
tls_connection_handshake - Failed to read possible Application Data 
error:00000000:lib(0):func(0):reason(0)
Mar 27 15:22:35 edward wpa_supplicant[2815]: EAP-MSCHAPV2: 
Authentication succeeded
Mar 27 15:22:35 edward wpa_supplicant[2815]: EAP-TLV: TLV Result - 
Success - EAP-TLV/Phase2 Completed
Mar 27 15:22:35 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-SUCCESS EAP 
authentication completed successfully
Mar 27 15:22:35 edward wpa_supplicant[2815]: WPA: Key negotiation 
completed with 00:1b:2f:ef:d3:b9 [PTK=CCMP GTK=TKIP]
Mar 27 15:22:35 edward wpa_supplicant[2815]: CTRL-EVENT-CONNECTED - 
Connection to 00:1b:2f:ef:d3:b9 completed (auth) [id=3 id_str=]
Mar 27 15:22:46 edward dhclient: New IP Address (wlan0): 192.168.100.54
Mar 27 15:22:46 edward dhclient: New Subnet Mask (wlan0): 255.255.255.0
Mar 27 15:22:46 edward dhclient: New Broadcast Address (wlan0): 
192.168.100.255
Mar 27 15:22:46 edward dhclient: New Routers (wlan0): 192.168.100.1
Mar 27 15:22:51 edward dhclient: New IP Address (wlan0): 192.168.100.54
Mar 27 15:22:51 edward dhclient: New Subnet Mask (wlan0): 255.255.255.0
Mar 27 15:22:51 edward dhclient: New Broadcast Address (wlan0): 
192.168.100.255
Mar 27 15:22:51 edward dhclient: New Routers (wlan0): 192.168.100.1
Mar 27 16:14:58 edward kernel: wlan0: _ieee80211_crypto_delkey: NONE 
keyix 65535 flags 0x3 rsc 0 tsc 0 en 0
Mar 27 16:14:58 edward kernel: wlan0: _ieee80211_crypto_delkey: TKIP 
keyix 1 flags0x106 rsc 1096785 tc 1 len 16
Mar 27 16:14:58 edward kernel: wlan0: _ieee80211_crypto_delkey: NONE 
keyix 65535 lags 0x3 rsc 0 tc 0 len 0
Mar 27 16:14:58 edward kernel: wlan0: _ieee80211_crypto_delkey: NONE 
keyix 65535 flags 0x3 rsc 0 tc 0 len 0
Mar 27 16:14:58 edward wpa_supplicant[2815]: Trying to associate with 
00:1e:2a:f9:0a:64 (SSID='IDA' freq=2472 MHz)
Mar 27 16:14:58 edward kernel: wlan0: _ieee80211_crypto_delkey: AES-CCM 
keyix 4 flags 0x103 rsc 28882 tsc 19125 len16
Mar 27 16:14:58 edward kernel: wlan0: link state changed to DOWN
Mar 27 16:14:59 edward kernel: wlan0: _ieee80211_crypto_delkey: NONE 
keyix 65535 flags 0x3 rsc 0 tsc 0 len 0
Mar 27 16:14:59 edward last message repeated 3 times
Mar 27 16:14:58 edward wpa_supplicant[2815]: CTRL-EVENT-DISCONNECTED - 
Disconnect event - remove keys
Mar 27 16:15:09 edward wpa_supplicant[2815]: Authentication with 
00:00:00:00:00:00 timed out.
Mar 27 16:15:21 edward wpa_supplicant[2815]: Authentication with 
00:1e:2a:f9:0a:64 timed out.
Mar 27 16:15:21 edward wpa_supplicant[2815]: Trying to associate with 
00:1b:2f:ef:d3:b9 (SSID='IDA' freq=2442 MHz)
Mar 27 16:15:21 edward kernel: wlan0: link state changed to UP
Mar 27 16:15:21 edward wpa_supplicant[2815]: Associated with 
00:1b:2f:ef:d3:b9
Mar 27 16:15:21 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-STARTED EAP 
authentication started
Mar 27 16:15:21 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-METHOD EAP 
vendor 0 method 25 (PEAP) selected
Mar 27 16:15:22 edward kernel: wlan0: [00:1b:2f:ef:d3:b9] key id 1 is 
not set (decap)
Mar 27 16:15:22 edward wpa_supplicant[2815]: EAP-TLV: TLV Result - 
Success - EAP-TLV/Phase2 Completed
Mar 27 16:15:22 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-SUCCESS EAP 
authentication completed successfully
Mar 27 16:15:22 edward kernel: wlan0: ieee80211_crypto_newkey: cipher 3 
flags 0x3 keyix 65535
Mar 27 16:15:22 edward kernel: wlan0: ieee80211_crypto_setkey: AES-CCM 
keyix 4 flags 0x103 mac 00:1b:2f:ef:d3:b9 rsc 0 tsc 0 len 16
Mar 27 16:15:23 edward kernel: wlan0: ieee80211_crypto_newkey: cipher 1 
flags 0x6 keyix 1
Mar 27 16:15:23 edward kernel: wlan0: ieee80211_crypto_setkey: TKIP 
keyix 1 flags 0x106 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16
Mar 27 16:15:22 edward wpa_supplicant[2815]: WPA: Key negotiation 
completed with 00:1b:2f:ef:d3:b9 [PTK=CCMP GTK=TKIP]
Mar 27 16:15:22 edward wpa_supplicant[2815]: CTRL-EVENT-CONNECTED - 
Connection to 00:1b:2f:ef:d3:b9 completed (reauth) [id=3 id_str=]
Mar 27 16:15:23 edward kernel: wlan0: [00:1b:2f:ef:d3:b9] AES-CCM replay 
detected <rsc 0, csc 0, keyix 4 rxkeyix 4>
Mar 27 16:15:24 edward dhclient: New IP Address (wlan0): 192.168.100.54
Mar 27 16:15:24 edward dhclient: New Subnet Mask (wlan0): 255.255.255.0
Mar 27 16:15:24 edward dhclient: New Broadcast Address (wlan0): 
192.168.100.255
Mar 27 16:15:24 edward dhclient: New Routers (wlan0): 192.168.100.1
Mar 27 16:15:24 edward dhclient: New IP Address (wlan0): 192.168.100.54
Mar 27 16:15:24 edward dhclient: New Subnet Mask (wlan0): 255.255.255.0
Mar 27 16:15:24 edward dhclient: New Broadcast Address (wlan0): 
192.168.100.255
Mar 27 16:15:24 edward dhclient: New Routers (wlan0): 192.168.100.1
Mar 27 17:00:09 edward dhclient[3024]: connection closed
Mar 27 17:00:09 edward dhclient[3024]: exiting.
Mar 27 17:01:00 edward dhclient: New IP Address (wlan0): 192.168.100.54
Mar 27 17:01:00 edward dhclient: New Subnet Mask (wlan0): 255.255.255.0
Mar 27 17:01:00 edward dhclient: New Broadcast Address (wlan0): 
192.168.100.255
Mar 27 17:01:00 edward dhclient: New Routers (wlan0): 192.168.100.1
Mar 27 17:09:38 edward kernel: ath0: bb hang detected (0x80), reseting
Mar 27 17:15:22 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-STARTED EAP 
authentication started
Mar 27 17:15:22 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-METHOD EAP 
vendor 0 method 25 (PEAP) selected
Mar 27 17:15:23 edward wpa_supplicant[2815]: OpenSSL: 
tls_connection_handshake - Failed to read possible Application Data 
error:00000000:lib(0):func(0):reason(0)
Mar 27 17:15:23 edward wpa_supplicant[2815]: EAP-MSCHAPV2: 
Authentication succeeded
Mar 27 17:15:23 edward wpa_supplicant[2815]: EAP-TLV: TLV Result - 
Success - EAP-TLV/Phase2 Completed
Mar 27 17:15:23 edward wpa_supplicant[2815]: CTRL-EVENT-EAP-SUCCESS EAP 
authentication completed successfully
Mar 27 17:15:23 edward kernel: wlan0: ieee80211_crypto_newkey: cipher 3 
flags 0x3 keyix
Mar 27 17:15:23 edward kernel:
Mar 27 17:15:23 edward kernel: wlan0: ieee80211_crypto_newkey: unable to 
setup cipher AES-CCM
Mar 27 17:15:23 edward wpa_supplicant[2815]: WPA: Failed to set PTK to 
the driver.
Mar 27 17:15:23 edward kernel: wlan0: ieee80211_crypto_newkey: cipher 
flags 0x6 keyix
Mar 27 17:15:23 edward kernel: 1
Mar 27 17:15:23 edward kernel: wlan0: ieee80211_crypto_setkey: TKIP 
keyix 1 flags 0x106 mac ff:ff:ff:ff:ff:ff rsc 0 tsc 0 len 16
Mar 27 17:15:23 edward wpa_supplicant[2815]: WPA: Key negotiation 
completed with 00:1b:2f:ef:d3:b9 [PTK=CCMP GTK=TKIP]
Mar 27 17:16:05 edward kernel: ath0: bb hang detected (0x80), reseting
Mar 27 17:18:57 edward kernel: ath0: bb hang detected (0x80), reseting
----8<----------------------------------------------------------

Is there a way to get further information out of wpa_supplicant? Maybe
by manually adding some extra logging? Or is it now time to start
looking into the related drivers and infrastructure, too?

IIRC I did not have this problem on a 7.1-STABLE + wpa_supplicant 0.5.10
and I still have that notebook. Unfortunately I can only use the
built-in ipw and an external rum adapter on that machine. Maybe I could
use that notebook to get some relevant information, too? Alternatively
I could install a 7-STABLE on my current notebook to have access to the
ath card, if that would help.

Regards,
Daniel