[Bug 580753] Re: ath9k module causing MIC challenge failures

Wed May 26 22:15:18 UTC 2010

Continuing to test 2.6.34-999-generic. Had a client generate a MIC
failure after several hours of continuous connectivity.

Most interesting is cross-correlating the logs between the access point
(in this case an Apple AirPort) and the client that caused the MIC
failure.

Access point:

May 26 13:10:01	Severity:5	Disassociated with station 1c:4b:d6:a3:82:31
May 26 13:10:01	Severity:5	Rotated TKIP group key.
May 26 13:10:02	Severity:5	Associated with station 1c:4b:d6:a3:82:31
May 26 13:10:02	Severity:5	Installed unicast CCMP key for supplicant 1c:4b:d6:a3:82:31
May 26 13:10:02	Severity:1	MIC integrity error (reported from STA) src_addr=1c:4b:d6:a3:82:31

Client:

May 26 13:10:01 asd-laptop avahi-daemon[637]: last message repeated 2 times
May 26 13:10:01 asd-laptop kernel: [13398.500221] No probe response from AP 00:1b:63:2b:46:75 after 500ms, disconnecting.
May 26 13:10:01 asd-laptop wpa_supplicant[671]: CTRL-EVENT-DISCONNECTED - Disconnect event - remove keys
May 26 13:10:01 asd-laptop kernel: [13398.560196] cfg80211: All devices are disconnected, going to restore regulatory settings
May 26 13:10:01 asd-laptop kernel: [13398.560222] cfg80211: Restoring regulatory settings
May 26 13:10:01 asd-laptop kernel: [13398.560242] cfg80211: Calling CRDA to update world regulatory domain
May 26 13:10:01 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  completed -> disconnected
May 26 13:10:01 asd-laptop kernel: [13398.571339] cfg80211: World regulatory domain updated:
May 26 13:10:01 asd-laptop kernel: [13398.571354]     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 26 13:10:01 asd-laptop kernel: [13398.571370]     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:01 asd-laptop kernel: [13398.571384]     (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:01 asd-laptop kernel: [13398.571397]     (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:01 asd-laptop kernel: [13398.571411]     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:01 asd-laptop kernel: [13398.571424]     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:01 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  disconnected -> scanning
May 26 13:10:02 asd-laptop wpa_supplicant[671]: Trying to associate with 00:1b:63:2b:46:75 (SSID='ittesting' freq=2452 MHz)
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  scanning -> associating
May 26 13:10:02 asd-laptop kernel: [13399.798514] wlan1: authenticate with 00:1b:63:2b:46:75 (try 1)
May 26 13:10:02 asd-laptop kernel: [13399.808652] wlan1: authenticated
May 26 13:10:02 asd-laptop kernel: [13399.808712] wlan1: associate with 00:1b:63:2b:46:75 (try 1)
May 26 13:10:02 asd-laptop kernel: [13399.812547] wlan1: RX AssocResp from 00:1b:63:2b:46:75 (capab=0x431 status=0 aid=1)
May 26 13:10:02 asd-laptop kernel: [13399.812559] wlan1: associated
May 26 13:10:02 asd-laptop wpa_supplicant[671]: Associated with 00:1b:63:2b:46:75
May 26 13:10:02 asd-laptop kernel: [13399.822750] cfg80211: Calling CRDA for country: US
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  associating -> associated
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  associated -> 4-way handshake
May 26 13:10:02 asd-laptop kernel: [13399.829306] cfg80211: Received country IE:
May 26 13:10:02 asd-laptop kernel: [13399.829318] cfg80211: Regulatory domain: US
May 26 13:10:02 asd-laptop kernel: [13399.829324]     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 26 13:10:02 asd-laptop kernel: [13399.829335]     (2402000 KHz - 2472000 KHz @ 40000 KHz), (10000 mBi, 2700 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829342] cfg80211: CRDA thinks this should applied:
May 26 13:10:02 asd-laptop kernel: [13399.829348] cfg80211: Regulatory domain: US
May 26 13:10:02 asd-laptop kernel: [13399.829354]     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 26 13:10:02 asd-laptop kernel: [13399.829364]     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829373]     (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829383]     (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829392]     (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829401]     (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829411]     (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829417] cfg80211: We intersect both of these and get:
May 26 13:10:02 asd-laptop kernel: [13399.829423] cfg80211: Regulatory domain: 98
May 26 13:10:02 asd-laptop kernel: [13399.829428]     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 26 13:10:02 asd-laptop kernel: [13399.829438]     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
May 26 13:10:02 asd-laptop kernel: [13399.829459] cfg80211: Current regulatory domain updated by AP to: US
May 26 13:10:02 asd-laptop kernel: [13399.829468]     (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
May 26 13:10:02 asd-laptop kernel: [13399.829478]     (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  4-way handshake -> group handshake
May 26 13:10:02 asd-laptop wpa_supplicant[671]: WPA: Key negotiation completed with 00:1b:63:2b:46:75 [PTK=CCMP GTK=TKIP]
May 26 13:10:02 asd-laptop wpa_supplicant[671]: CTRL-EVENT-CONNECTED - Connection to 00:1b:63:2b:46:75 completed (reauth) [id=0 id_str=]
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  group handshake -> completed
May 26 13:10:02 asd-laptop wpa_supplicant[671]: Michael MIC failure detected
May 26 13:10:02 asd-laptop wpa_supplicant[671]: WPA: Sending EAPOL-Key Request (error=1 pairwise=0 ptk_set=1 len=99)
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  completed -> 4-way handshake
May 26 13:10:02 asd-laptop wpa_supplicant[671]: WPA: Key negotiation completed with 00:1b:63:2b:46:75 [PTK=CCMP GTK=TKIP]
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  4-way handshake -> group handshake
May 26 13:10:02 asd-laptop NetworkManager: <info>  (wlan1): supplicant connection state:  group handshake -> completed

It appears the kernel (mistakenly?) thinks the access point is
unavailable and forces the disconnect. The access point and client both
disconnect. The client then reconnects, the access point does not report
a group TKIP key rotation, but the client reports completing the group
handshake and then both devices report the MIC failure.

Then, though the access point should still be in MIC countermeasure mode
for 60 seconds, NetworkManager and wpa_supplicant are still happily
chatting away.

** Attachment added: "Apple AirPort log"
   http://launchpadlibrarian.net/49166686/ectest_10%20Log.txt

-- 
ath9k module causing MIC challenge failures
https://bugs.launchpad.net/bugs/580753
You received this bug notification because you are a member of Kernel
Bugs, which is subscribed to linux in ubuntu.