Date: Sat, 28 Mar 2009 23:28:04 +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: <49CEA474.9020302@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
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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?49CEA474.9020302>