2017-03-29 17:03:33

by Tim Harvey

[permalink] [raw]
Subject: [RESEND] ath9k failure to authenticate WPA2 client mode

Greetings,

(resending plaintext - oops)

I'm seeing failures to authenticate with a WPA2 secured AP using ath9k
based cards on wireless-next:

root@xenial-armhf:~# wpa_passphrase testssid testpass >
/etc/wpa_supplicant/wpa_supplicant.conf

root@xenial-armhf:~# iw reg get
country US: DFS-FCC
(2402 - 2472 @ 40), (N/A, 30), (N/A)
(5170 - 5250 @ 80), (N/A, 17), (N/A)
(5250 - 5330 @ 80), (N/A, 23), (0 ms), DFS
(5490 - 5730 @ 160), (N/A, 23), (0 ms), DFS
(5735 - 5835 @ 80), (N/A, 30), (N/A)
(57240 - 63720 @ 2160), (N/A, 40), (N/A)

root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
/etc/wpa_supplicant/wpa_supplicant.conf
Successfully initialized wpa_supplicant
[ 1882.699010] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
nl80211: send_and_recv->nl_recvms[ 1886.262884] wlan0: authenticate
with 02:1a:11:f2:35:9c
gs failed: -33
wlan0: SME: Trying to authenticate with 02:1a:11:f2:35:9c
(SSID='testssid' freq=2437 MHz)
[ 1886.280755] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
[ 1887.033449] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
[ 1887.993413] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
[ 1888.953390] wlan0: authentication with 02:1a:11:f2:35:9c timed out
wlan0: SME: Trying to authenticat[ 1892.507484] wlan0: authenticate
with 02:1a:11:f2:35:9c
e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
[ 1892.527460] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
[ 1893.993401] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
[ 1894.953419] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
[ 1895.993387] wlan0: authentication with 02:1a:11:f2:35:9c timed out
wlan0: SME: Trying to authenticat[ 1899.997262] wlan0: authenticate
with 02:1a:11:f2:35:9c
e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
[ 1900.017252] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
[ 1901.033259] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
[ 1901.993345] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
[ 1902.953270] wlan0: authentication with 02:1a:11:f2:35:9c timed out
wlan0: SME: Trying to authenticat[ 1907.407446] wlan0: authenticate
with 02:1a:11:f2:35:9c
e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
[ 1907.427370] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
[ 1908.003204] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
[ 1908.953275] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
[ 1909.993254] wlan0: authentication with 02:1a:11:f2:35:9c timed out
wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
auth_failures=1 duration=10 reason=CONN_FAILED
^Cnl80211: deinit ifname=wlan0 disabled_11b_rates=0
wlan0: CTRL-EVENT-TERMINATING

I've tried loading ath9k with nohwcrypt=1 and see the same.

I do not have any trouble with an ath10k card in the same system:

root@xenial-armhf:~# wpa_supplicant -i wlan1 -c
/etc/wpa_supplicant/wpa_supplicant.conf
Successfully initialized wpa_supplicant
[ 593.401846] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
wlan1: SME: Trying to authenticat[ 596.857230] wlan1: authenticate
with 02:1a:11:f1:b9:02
e with 02:1a:11:f1:b9:02 (SSID='testssid' freq=2437 MHz)
[ 596.876749] wlan1: send auth to 02:1a:11:f1:b9:02 (try 1/3)
[ 596.886290] wlan1: authenticated
wlan1: Trying to associate with 02:1a:11:f1:b9:02 (SSID='testssid'
freq=2437 MHz)
[ 596.909012] wlan1: associate with 02:1a:11:f1:b9:02 (try 1/3)
[ 596.922374] wlan1: RX AssocResp from 02:1a:11:f1:b9:02 (capab=0x411
status=0 aid=1)
[ 596.940754] wlan1: associated
[ 596.943954] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
wlan1: Associated with 02:1a:11:f1:b9:02
wlan1: WPA: Key negotiation completed with 02:1a:11:f1:b9:02 [PTK=CCMP GTK=CCMP]
wlan1: CTRL-EVENT-CONNECTED - Connection to 02:1a:11:f1:b9:02
completed [id=0 id_str=]
wlan1: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
^^^^ at this point I can dhcp IP config and all is good

Here's the PCI info for the two cards:

08:00.0 Ethernet controller [0200]: Marvell Technology Group Ltd.
88E8057 PCI-E Gigabit Ethernet Controller [11ab:4380]
09:00.0 Network controller [0280]: Qualcomm Atheros AR9580 Wireless
Network Adapter [168c:0033] (rev 01)

I don't know when ath9k last worked honestly. I usually use them under
OpenWrt which has its own patches against periodic updates of linux
backports. I noticed this first with Ubuntu 16.04 with the Ubuntu 4.4
kernel, saw it still with the Ubuntu 4.8 kernel, then repeated the
issue in wireless-next.

Any ideas?

Regards,

Tim


2017-03-30 08:04:14

by Bastian Bittorf

[permalink] [raw]
Subject: Re: [RESEND] ath9k failure to authenticate WPA2 client mode

* Janusz Dziedzic <[email protected]> [30.03.2017 08:26]:
> On 29 March 2017 at 19:03, Tim Harvey <[email protected]> wrote:
> > I don't know when ath9k last worked honestly. I usually use them under
> > OpenWrt which has its own patches against periodic updates of linux
> > backports. I noticed this first with Ubuntu 16.04 with the Ubuntu 4.4
> > kernel, saw it still with the Ubuntu 4.8 kernel, then repeated the
> > issue in wireless-next.
> >
> > Any ideas?
> >
> Interesting. Are you sure wlan0 is ath9k and wlan1 is ath10k?

an easy check for that is:

# root@box:~ DEV=wlan0; basename $(readlink /sys/class/net/$DEV/device/driver)
iwlwifi

# output is e.g. ath10k_pci or ath9k

bye, bastian

2017-03-30 16:22:25

by Tim Harvey

[permalink] [raw]
Subject: Re: [RESEND] ath9k failure to authenticate WPA2 client mode

On Wed, Mar 29, 2017 at 10:54 PM, Janusz Dziedzic
<[email protected]> wrote:
> On 29 March 2017 at 19:03, Tim Harvey <[email protected]> wrote:
>> Greetings,
>>
>> (resending plaintext - oops)
>>
>> I'm seeing failures to authenticate with a WPA2 secured AP using ath9k
>> based cards on wireless-next:
>>
>> root@xenial-armhf:~# wpa_passphrase testssid testpass >
>> /etc/wpa_supplicant/wpa_supplicant.conf
>>
>> root@xenial-armhf:~# iw reg get
>> country US: DFS-FCC
>> (2402 - 2472 @ 40), (N/A, 30), (N/A)
>> (5170 - 5250 @ 80), (N/A, 17), (N/A)
>> (5250 - 5330 @ 80), (N/A, 23), (0 ms), DFS
>> (5490 - 5730 @ 160), (N/A, 23), (0 ms), DFS
>> (5735 - 5835 @ 80), (N/A, 30), (N/A)
>> (57240 - 63720 @ 2160), (N/A, 40), (N/A)
>>
>> root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
>> /etc/wpa_supplicant/wpa_supplicant.conf
>> Successfully initialized wpa_supplicant
>> [ 1882.699010] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
>> nl80211: send_and_recv->nl_recvms[ 1886.262884] wlan0: authenticate
>> with 02:1a:11:f2:35:9c
>> gs failed: -33
>> wlan0: SME: Trying to authenticate with 02:1a:11:f2:35:9c
>> (SSID='testssid' freq=2437 MHz)
>> [ 1886.280755] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>> [ 1887.033449] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>> [ 1887.993413] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>> [ 1888.953390] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>> wlan0: SME: Trying to authenticat[ 1892.507484] wlan0: authenticate
>> with 02:1a:11:f2:35:9c
>> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
>> [ 1892.527460] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>> [ 1893.993401] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>> [ 1894.953419] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>> [ 1895.993387] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>> wlan0: SME: Trying to authenticat[ 1899.997262] wlan0: authenticate
>> with 02:1a:11:f2:35:9c
>> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
>> [ 1900.017252] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>> [ 1901.033259] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>> [ 1901.993345] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>> [ 1902.953270] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>> wlan0: SME: Trying to authenticat[ 1907.407446] wlan0: authenticate
>> with 02:1a:11:f2:35:9c
>> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
>> [ 1907.427370] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>> [ 1908.003204] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>> [ 1908.953275] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>> [ 1909.993254] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
>> auth_failures=1 duration=10 reason=CONN_FAILED
>> ^Cnl80211: deinit ifname=wlan0 disabled_11b_rates=0
>> wlan0: CTRL-EVENT-TERMINATING
>>
>> I've tried loading ath9k with nohwcrypt=1 and see the same.
>>
>> I do not have any trouble with an ath10k card in the same system:
>>
>> root@xenial-armhf:~# wpa_supplicant -i wlan1 -c
>> /etc/wpa_supplicant/wpa_supplicant.conf
>> Successfully initialized wpa_supplicant
>> [ 593.401846] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
>> wlan1: SME: Trying to authenticat[ 596.857230] wlan1: authenticate
>> with 02:1a:11:f1:b9:02
>> e with 02:1a:11:f1:b9:02 (SSID='testssid' freq=2437 MHz)
>> [ 596.876749] wlan1: send auth to 02:1a:11:f1:b9:02 (try 1/3)
>> [ 596.886290] wlan1: authenticated
>> wlan1: Trying to associate with 02:1a:11:f1:b9:02 (SSID='testssid'
>> freq=2437 MHz)
>> [ 596.909012] wlan1: associate with 02:1a:11:f1:b9:02 (try 1/3)
>> [ 596.922374] wlan1: RX AssocResp from 02:1a:11:f1:b9:02 (capab=0x411
>> status=0 aid=1)
>> [ 596.940754] wlan1: associated
>> [ 596.943954] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
>> wlan1: Associated with 02:1a:11:f1:b9:02
>> wlan1: WPA: Key negotiation completed with 02:1a:11:f1:b9:02 [PTK=CCMP GTK=CCMP]
>> wlan1: CTRL-EVENT-CONNECTED - Connection to 02:1a:11:f1:b9:02
>> completed [id=0 id_str=]
>> wlan1: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
>> ^^^^ at this point I can dhcp IP config and all is good
>>
>> Here's the PCI info for the two cards:
>>
>> 08:00.0 Ethernet controller [0200]: Marvell Technology Group Ltd.
>> 88E8057 PCI-E Gigabit Ethernet Controller [11ab:4380]
>> 09:00.0 Network controller [0280]: Qualcomm Atheros AR9580 Wireless
>> Network Adapter [168c:0033] (rev 01)
>>
>> I don't know when ath9k last worked honestly. I usually use them under
>> OpenWrt which has its own patches against periodic updates of linux
>> backports. I noticed this first with Ubuntu 16.04 with the Ubuntu 4.4
>> kernel, saw it still with the Ubuntu 4.8 kernel, then repeated the
>> issue in wireless-next.
>>
>> Any ideas?
>>
> Interesting. Are you sure wlan0 is ath9k and wlan1 is ath10k?
> ath9k is quite stable - I have AR9462 and works fine with 4.4 and current.
> So, I would suspect some issues with ath10k :)
>
> What if you will modprobe -r ath10k_pci and next run the test?
>

It's ath9k for sure... several different ath9k radios fail the same
way: WLE350NX, WLE200NX, WPEA-127NE, SR710E. I'm surprised as heck as
well. I only put the ath10k radio in to ensure I don't have some
configuration issue (and have since removed it and only test with 1
card at a time). I've also ensured that a variety of radios/drivers
work with the same Ubuntu xenial (16.04) userspace and kernels such as
ath10k, carl9170, iwlwifi.

Is there some userspace configuration issue I may have related to
regdomain on ath9k that perhaps isn't applicable on other drivers?

Note that depending on the kernel version I don't always get the same failure.

Here is Ubuntu 4.8.0-30-generic which is where I originally saw the
issue and started troubleshooting. In this case we auth/assoc and then
immediately get disconnected from the AP:
root@xenial-armhf:~# uname -a
Linux xenial-armhf 4.8.0-30-generic #32~16.04.1-Ubuntu SMP Fri Dec 2
03:46:03 UTC 2016 armv7l armv7l armv7l GNU/Linux
root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
/etc/wpa_supplicant/wpa_supplicant.conf -D nl80211
Successfully initialized wpa_supplicant
[ 240.086690] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
wlan0: SME: Trying to authenticat[ 243.332657] wlan0: authenticate
with 02:1a:11:f9:e9:04
e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
[ 243.354923] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
[ 243.895326] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
[ 244.382493] wlan0: authenticated
^^^^ athenticated
wlan0: Trying to associate with 02:1a:11:f9:e9:04 (SSID='testssid'
freq=2437 MHz)
[ 244.423275] wlan0: associate with 02:1a:11:f9:e9:04 (try 1/3)
[ 245.879282] wlan0: associate with 02:1a:11:f9:e9:04 (try 2/3)
[ 246.462630] wlan0: RX AssocResp from 02:1a:11:f9:e9:04 (capab=0x411
status=0 aid=1)
[ 246.470554] wlan0: associated
^^^^ associated
[ 246.473628] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
wlan0: Associated with 02:1a:11:f9:e9:04
wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
wlan0: CTRL-EVENT-DISCONNECTED bssid=02:1a:11:f9:e9:04 reason=4
locally_generated=1
^^^^ disconnected because of no activity? This was within around 1
second of the association
wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
auth_failures=1 duration=10 reason=WRONG_KEY
^^^^ but we already authenticated???
wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
wlan0: CTRL-EVENT-SSID-REENABLED [ 259.744812] wlan0: authenticate
with 02:1a:11:f9:e9:04
id=0 ssid="testssid"
wlan0: SME: Trying to authenticate with 02:1a:11:f9:e9:04
(SSID='testssid' freq=2437 MHz)
[ 259.766920] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
[ 260.798457] wlan0: authenticated
wlan0: Trying to associate with 02:1a:11:f9:e9:04 (SSID='testssid'
freq=2437 MHz)
[ 260.839297] wlan0: associate with 02:1a:11:f9:e9:04 (try 1/3)
[ 261.879297] wlan0: associate with 02:1a:11:f9:e9:04 (try 2/3)
[ 262.878638] wlan0: RX AssocResp from 02:1a:11:f9:e9:04 (capab=0x411
status=0 aid=1)
[ 262.886553] wlan0: associated
wlan0: Associated with 02:1a:11:f9:e9:04
wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
wlan0: CTRL-EVENT-DISCONNECTED bssid=02:1a:11:f9:e9:04 reason=4
locally_generated=1
wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
auth_failures=2 duration=23 reason=WRONG_KEY
wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
^Cnl80211: deinit ifname=wlan0 disabled_11b_rates=0
wlan0: CTRL-EVENT-TERMINATING

And linux-wireless/master (we never get auuthenticated with ath9k):
root@xenial-armhf:~# uname -a
Linux xenial-armhf 4.11.0-rc2 #579 SMP Thu Mar 30 07:44:08 PDT 2017
armv7l armv7l armv7l GNU/Linux
root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
/etc/wpa_supplicant/wpa_supplicant.conf -D nl80211
Successfully initialized wpa_supplicant
[ 27.312919] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
wlan0: SME: Trying to authenticat[ 30.924677] wlan0: authenticate
with 02:1a:11:f9:e9:04
e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
[ 30.954609] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
[ 32.090557] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
[ 33.129011] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
[ 34.088942] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
wlan0: SME: Trying to authenticat[ 37.670515] wlan0: authenticate
with 02:1a:11:f9:e9:04
e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
[ 37.693822] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
[ 39.128907] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
[ 40.089009] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
[ 41.128974] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
wlan0: SME: Trying to authenticat[ 45.092584] wlan0: authenticate
with 02:1a:11:f9:e9:04
e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
[ 45.115914] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
[ 46.008936] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
[ 46.968911] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
[ 48.008849] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
wlan0: SME: Trying to authenticat[ 52.472625] wlan0: authenticate
with 02:1a:11:f9:e9:04
e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
[ 52.495857] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
[ 53.058850] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
[ 54.008860] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
[ 54.968960] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
auth_failures=1 duration=10 reason=CONN_FAILED
wlan0: CTRL-EVENT-SSID-REENABLED [ 71.862102] wlan0: authenticate
with 02:1a:11:f9:e9:04
id=0 ssid="testssid"
wlan0: SME: Trying to authenticate with 02:1a:11:f9:e9:04
(SSID='testssid' freq=2437 MHz)
[ 71.885021] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
[ 73.128873] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
[ 74.008857] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
[ 74.969026] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
auth_failures=2 duration=23 reason=CONN_FAILED

Regards,

Tim

2017-03-30 23:49:25

by Tim Harvey

[permalink] [raw]
Subject: Re: [RESEND] ath9k failure to authenticate WPA2 client mode

On Thu, Mar 30, 2017 at 9:22 AM, Tim Harvey <[email protected]> wrote:
> On Wed, Mar 29, 2017 at 10:54 PM, Janusz Dziedzic
> <[email protected]> wrote:
>> On 29 March 2017 at 19:03, Tim Harvey <[email protected]> wrote:
>>> Greetings,
>>>
>>> (resending plaintext - oops)
>>>
>>> I'm seeing failures to authenticate with a WPA2 secured AP using ath9k
>>> based cards on wireless-next:
>>>
>>> root@xenial-armhf:~# wpa_passphrase testssid testpass >
>>> /etc/wpa_supplicant/wpa_supplicant.conf
>>>
>>> root@xenial-armhf:~# iw reg get
>>> country US: DFS-FCC
>>> (2402 - 2472 @ 40), (N/A, 30), (N/A)
>>> (5170 - 5250 @ 80), (N/A, 17), (N/A)
>>> (5250 - 5330 @ 80), (N/A, 23), (0 ms), DFS
>>> (5490 - 5730 @ 160), (N/A, 23), (0 ms), DFS
>>> (5735 - 5835 @ 80), (N/A, 30), (N/A)
>>> (57240 - 63720 @ 2160), (N/A, 40), (N/A)
>>>
>>> root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
>>> /etc/wpa_supplicant/wpa_supplicant.conf
>>> Successfully initialized wpa_supplicant
>>> [ 1882.699010] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
>>> nl80211: send_and_recv->nl_recvms[ 1886.262884] wlan0: authenticate
>>> with 02:1a:11:f2:35:9c
>>> gs failed: -33
>>> wlan0: SME: Trying to authenticate with 02:1a:11:f2:35:9c
>>> (SSID='testssid' freq=2437 MHz)
>>> [ 1886.280755] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>>> [ 1887.033449] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>>> [ 1887.993413] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>>> [ 1888.953390] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>>> wlan0: SME: Trying to authenticat[ 1892.507484] wlan0: authenticate
>>> with 02:1a:11:f2:35:9c
>>> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
>>> [ 1892.527460] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>>> [ 1893.993401] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>>> [ 1894.953419] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>>> [ 1895.993387] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>>> wlan0: SME: Trying to authenticat[ 1899.997262] wlan0: authenticate
>>> with 02:1a:11:f2:35:9c
>>> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
>>> [ 1900.017252] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>>> [ 1901.033259] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>>> [ 1901.993345] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>>> [ 1902.953270] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>>> wlan0: SME: Trying to authenticat[ 1907.407446] wlan0: authenticate
>>> with 02:1a:11:f2:35:9c
>>> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
>>> [ 1907.427370] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
>>> [ 1908.003204] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
>>> [ 1908.953275] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
>>> [ 1909.993254] wlan0: authentication with 02:1a:11:f2:35:9c timed out
>>> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
>>> auth_failures=1 duration=10 reason=CONN_FAILED
>>> ^Cnl80211: deinit ifname=wlan0 disabled_11b_rates=0
>>> wlan0: CTRL-EVENT-TERMINATING
>>>
>>> I've tried loading ath9k with nohwcrypt=1 and see the same.
>>>
>>> I do not have any trouble with an ath10k card in the same system:
>>>
>>> root@xenial-armhf:~# wpa_supplicant -i wlan1 -c
>>> /etc/wpa_supplicant/wpa_supplicant.conf
>>> Successfully initialized wpa_supplicant
>>> [ 593.401846] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
>>> wlan1: SME: Trying to authenticat[ 596.857230] wlan1: authenticate
>>> with 02:1a:11:f1:b9:02
>>> e with 02:1a:11:f1:b9:02 (SSID='testssid' freq=2437 MHz)
>>> [ 596.876749] wlan1: send auth to 02:1a:11:f1:b9:02 (try 1/3)
>>> [ 596.886290] wlan1: authenticated
>>> wlan1: Trying to associate with 02:1a:11:f1:b9:02 (SSID='testssid'
>>> freq=2437 MHz)
>>> [ 596.909012] wlan1: associate with 02:1a:11:f1:b9:02 (try 1/3)
>>> [ 596.922374] wlan1: RX AssocResp from 02:1a:11:f1:b9:02 (capab=0x411
>>> status=0 aid=1)
>>> [ 596.940754] wlan1: associated
>>> [ 596.943954] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
>>> wlan1: Associated with 02:1a:11:f1:b9:02
>>> wlan1: WPA: Key negotiation completed with 02:1a:11:f1:b9:02 [PTK=CCMP GTK=CCMP]
>>> wlan1: CTRL-EVENT-CONNECTED - Connection to 02:1a:11:f1:b9:02
>>> completed [id=0 id_str=]
>>> wlan1: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
>>> ^^^^ at this point I can dhcp IP config and all is good
>>>
>>> Here's the PCI info for the two cards:
>>>
>>> 08:00.0 Ethernet controller [0200]: Marvell Technology Group Ltd.
>>> 88E8057 PCI-E Gigabit Ethernet Controller [11ab:4380]
>>> 09:00.0 Network controller [0280]: Qualcomm Atheros AR9580 Wireless
>>> Network Adapter [168c:0033] (rev 01)
>>>
>>> I don't know when ath9k last worked honestly. I usually use them under
>>> OpenWrt which has its own patches against periodic updates of linux
>>> backports. I noticed this first with Ubuntu 16.04 with the Ubuntu 4.4
>>> kernel, saw it still with the Ubuntu 4.8 kernel, then repeated the
>>> issue in wireless-next.
>>>
>>> Any ideas?
>>>
>> Interesting. Are you sure wlan0 is ath9k and wlan1 is ath10k?
>> ath9k is quite stable - I have AR9462 and works fine with 4.4 and current.
>> So, I would suspect some issues with ath10k :)
>>
>> What if you will modprobe -r ath10k_pci and next run the test?
>>
>
> It's ath9k for sure... several different ath9k radios fail the same
> way: WLE350NX, WLE200NX, WPEA-127NE, SR710E. I'm surprised as heck as
> well. I only put the ath10k radio in to ensure I don't have some
> configuration issue (and have since removed it and only test with 1
> card at a time). I've also ensured that a variety of radios/drivers
> work with the same Ubuntu xenial (16.04) userspace and kernels such as
> ath10k, carl9170, iwlwifi.
>
> Is there some userspace configuration issue I may have related to
> regdomain on ath9k that perhaps isn't applicable on other drivers?
>
> Note that depending on the kernel version I don't always get the same failure.
>
> Here is Ubuntu 4.8.0-30-generic which is where I originally saw the
> issue and started troubleshooting. In this case we auth/assoc and then
> immediately get disconnected from the AP:
> root@xenial-armhf:~# uname -a
> Linux xenial-armhf 4.8.0-30-generic #32~16.04.1-Ubuntu SMP Fri Dec 2
> 03:46:03 UTC 2016 armv7l armv7l armv7l GNU/Linux
> root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
> /etc/wpa_supplicant/wpa_supplicant.conf -D nl80211
> Successfully initialized wpa_supplicant
> [ 240.086690] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> wlan0: SME: Trying to authenticat[ 243.332657] wlan0: authenticate
> with 02:1a:11:f9:e9:04
> e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
> [ 243.354923] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
> [ 243.895326] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
> [ 244.382493] wlan0: authenticated
> ^^^^ athenticated
> wlan0: Trying to associate with 02:1a:11:f9:e9:04 (SSID='testssid'
> freq=2437 MHz)
> [ 244.423275] wlan0: associate with 02:1a:11:f9:e9:04 (try 1/3)
> [ 245.879282] wlan0: associate with 02:1a:11:f9:e9:04 (try 2/3)
> [ 246.462630] wlan0: RX AssocResp from 02:1a:11:f9:e9:04 (capab=0x411
> status=0 aid=1)
> [ 246.470554] wlan0: associated
> ^^^^ associated
> [ 246.473628] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
> wlan0: Associated with 02:1a:11:f9:e9:04
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
> wlan0: CTRL-EVENT-DISCONNECTED bssid=02:1a:11:f9:e9:04 reason=4
> locally_generated=1
> ^^^^ disconnected because of no activity? This was within around 1
> second of the association
> wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
> auth_failures=1 duration=10 reason=WRONG_KEY
> ^^^^ but we already authenticated???
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
> wlan0: CTRL-EVENT-SSID-REENABLED [ 259.744812] wlan0: authenticate
> with 02:1a:11:f9:e9:04
> id=0 ssid="testssid"
> wlan0: SME: Trying to authenticate with 02:1a:11:f9:e9:04
> (SSID='testssid' freq=2437 MHz)
> [ 259.766920] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
> [ 260.798457] wlan0: authenticated
> wlan0: Trying to associate with 02:1a:11:f9:e9:04 (SSID='testssid'
> freq=2437 MHz)
> [ 260.839297] wlan0: associate with 02:1a:11:f9:e9:04 (try 1/3)
> [ 261.879297] wlan0: associate with 02:1a:11:f9:e9:04 (try 2/3)
> [ 262.878638] wlan0: RX AssocResp from 02:1a:11:f9:e9:04 (capab=0x411
> status=0 aid=1)
> [ 262.886553] wlan0: associated
> wlan0: Associated with 02:1a:11:f9:e9:04
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
> wlan0: CTRL-EVENT-DISCONNECTED bssid=02:1a:11:f9:e9:04 reason=4
> locally_generated=1
> wlan0: WPA: 4-Way Handshake failed - pre-shared key may be incorrect
> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
> auth_failures=2 duration=23 reason=WRONG_KEY
> wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
> ^Cnl80211: deinit ifname=wlan0 disabled_11b_rates=0
> wlan0: CTRL-EVENT-TERMINATING
>
> And linux-wireless/master (we never get auuthenticated with ath9k):
> root@xenial-armhf:~# uname -a
> Linux xenial-armhf 4.11.0-rc2 #579 SMP Thu Mar 30 07:44:08 PDT 2017
> armv7l armv7l armv7l GNU/Linux
> root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
> /etc/wpa_supplicant/wpa_supplicant.conf -D nl80211
> Successfully initialized wpa_supplicant
> [ 27.312919] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> wlan0: SME: Trying to authenticat[ 30.924677] wlan0: authenticate
> with 02:1a:11:f9:e9:04
> e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
> [ 30.954609] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
> [ 32.090557] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
> [ 33.129011] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
> [ 34.088942] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
> wlan0: SME: Trying to authenticat[ 37.670515] wlan0: authenticate
> with 02:1a:11:f9:e9:04
> e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
> [ 37.693822] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
> [ 39.128907] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
> [ 40.089009] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
> [ 41.128974] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
> wlan0: SME: Trying to authenticat[ 45.092584] wlan0: authenticate
> with 02:1a:11:f9:e9:04
> e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
> [ 45.115914] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
> [ 46.008936] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
> [ 46.968911] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
> [ 48.008849] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
> wlan0: SME: Trying to authenticat[ 52.472625] wlan0: authenticate
> with 02:1a:11:f9:e9:04
> e with 02:1a:11:f9:e9:04 (SSID='testssid' freq=2437 MHz)
> [ 52.495857] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
> [ 53.058850] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
> [ 54.008860] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
> [ 54.968960] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
> auth_failures=1 duration=10 reason=CONN_FAILED
> wlan0: CTRL-EVENT-SSID-REENABLED [ 71.862102] wlan0: authenticate
> with 02:1a:11:f9:e9:04
> id=0 ssid="testssid"
> wlan0: SME: Trying to authenticate with 02:1a:11:f9:e9:04
> (SSID='testssid' freq=2437 MHz)
> [ 71.885021] wlan0: send auth to 02:1a:11:f9:e9:04 (try 1/3)
> [ 73.128873] wlan0: send auth to 02:1a:11:f9:e9:04 (try 2/3)
> [ 74.008857] wlan0: send auth to 02:1a:11:f9:e9:04 (try 3/3)
> [ 74.969026] wlan0: authentication with 02:1a:11:f9:e9:04 timed out
> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
> auth_failures=2 duration=23 reason=CONN_FAILED
>
> Regards,
>
> Tim

This turns out to be caused by interrupts not getting caught. The
target board used here is an IMX6 and its driver and/or PCIe host
controller apparently doesn't support both MSI and legacy interrupts
at the same time thus this breakage occured when the kernel started
enabling MSI by default for IMX6
(3ee803641e76bea76ec730c80dcc64739a9919ff).

Can ath9k can be enhanced to use MSI?

How many other cards/drivers out there don't support MSI?

Tim

2017-03-30 05:54:48

by Janusz Dziedzic

[permalink] [raw]
Subject: Re: [RESEND] ath9k failure to authenticate WPA2 client mode

On 29 March 2017 at 19:03, Tim Harvey <[email protected]> wrote:
> Greetings,
>
> (resending plaintext - oops)
>
> I'm seeing failures to authenticate with a WPA2 secured AP using ath9k
> based cards on wireless-next:
>
> root@xenial-armhf:~# wpa_passphrase testssid testpass >
> /etc/wpa_supplicant/wpa_supplicant.conf
>
> root@xenial-armhf:~# iw reg get
> country US: DFS-FCC
> (2402 - 2472 @ 40), (N/A, 30), (N/A)
> (5170 - 5250 @ 80), (N/A, 17), (N/A)
> (5250 - 5330 @ 80), (N/A, 23), (0 ms), DFS
> (5490 - 5730 @ 160), (N/A, 23), (0 ms), DFS
> (5735 - 5835 @ 80), (N/A, 30), (N/A)
> (57240 - 63720 @ 2160), (N/A, 40), (N/A)
>
> root@xenial-armhf:~# wpa_supplicant -i wlan0 -c
> /etc/wpa_supplicant/wpa_supplicant.conf
> Successfully initialized wpa_supplicant
> [ 1882.699010] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
> nl80211: send_and_recv->nl_recvms[ 1886.262884] wlan0: authenticate
> with 02:1a:11:f2:35:9c
> gs failed: -33
> wlan0: SME: Trying to authenticate with 02:1a:11:f2:35:9c
> (SSID='testssid' freq=2437 MHz)
> [ 1886.280755] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
> [ 1887.033449] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
> [ 1887.993413] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
> [ 1888.953390] wlan0: authentication with 02:1a:11:f2:35:9c timed out
> wlan0: SME: Trying to authenticat[ 1892.507484] wlan0: authenticate
> with 02:1a:11:f2:35:9c
> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
> [ 1892.527460] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
> [ 1893.993401] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
> [ 1894.953419] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
> [ 1895.993387] wlan0: authentication with 02:1a:11:f2:35:9c timed out
> wlan0: SME: Trying to authenticat[ 1899.997262] wlan0: authenticate
> with 02:1a:11:f2:35:9c
> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
> [ 1900.017252] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
> [ 1901.033259] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
> [ 1901.993345] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
> [ 1902.953270] wlan0: authentication with 02:1a:11:f2:35:9c timed out
> wlan0: SME: Trying to authenticat[ 1907.407446] wlan0: authenticate
> with 02:1a:11:f2:35:9c
> e with 02:1a:11:f2:35:9c (SSID='testssid' freq=2437 MHz)
> [ 1907.427370] wlan0: send auth to 02:1a:11:f2:35:9c (try 1/3)
> [ 1908.003204] wlan0: send auth to 02:1a:11:f2:35:9c (try 2/3)
> [ 1908.953275] wlan0: send auth to 02:1a:11:f2:35:9c (try 3/3)
> [ 1909.993254] wlan0: authentication with 02:1a:11:f2:35:9c timed out
> wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="testssid"
> auth_failures=1 duration=10 reason=CONN_FAILED
> ^Cnl80211: deinit ifname=wlan0 disabled_11b_rates=0
> wlan0: CTRL-EVENT-TERMINATING
>
> I've tried loading ath9k with nohwcrypt=1 and see the same.
>
> I do not have any trouble with an ath10k card in the same system:
>
> root@xenial-armhf:~# wpa_supplicant -i wlan1 -c
> /etc/wpa_supplicant/wpa_supplicant.conf
> Successfully initialized wpa_supplicant
> [ 593.401846] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
> wlan1: SME: Trying to authenticat[ 596.857230] wlan1: authenticate
> with 02:1a:11:f1:b9:02
> e with 02:1a:11:f1:b9:02 (SSID='testssid' freq=2437 MHz)
> [ 596.876749] wlan1: send auth to 02:1a:11:f1:b9:02 (try 1/3)
> [ 596.886290] wlan1: authenticated
> wlan1: Trying to associate with 02:1a:11:f1:b9:02 (SSID='testssid'
> freq=2437 MHz)
> [ 596.909012] wlan1: associate with 02:1a:11:f1:b9:02 (try 1/3)
> [ 596.922374] wlan1: RX AssocResp from 02:1a:11:f1:b9:02 (capab=0x411
> status=0 aid=1)
> [ 596.940754] wlan1: associated
> [ 596.943954] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
> wlan1: Associated with 02:1a:11:f1:b9:02
> wlan1: WPA: Key negotiation completed with 02:1a:11:f1:b9:02 [PTK=CCMP GTK=CCMP]
> wlan1: CTRL-EVENT-CONNECTED - Connection to 02:1a:11:f1:b9:02
> completed [id=0 id_str=]
> wlan1: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US
> ^^^^ at this point I can dhcp IP config and all is good
>
> Here's the PCI info for the two cards:
>
> 08:00.0 Ethernet controller [0200]: Marvell Technology Group Ltd.
> 88E8057 PCI-E Gigabit Ethernet Controller [11ab:4380]
> 09:00.0 Network controller [0280]: Qualcomm Atheros AR9580 Wireless
> Network Adapter [168c:0033] (rev 01)
>
> I don't know when ath9k last worked honestly. I usually use them under
> OpenWrt which has its own patches against periodic updates of linux
> backports. I noticed this first with Ubuntu 16.04 with the Ubuntu 4.4
> kernel, saw it still with the Ubuntu 4.8 kernel, then repeated the
> issue in wireless-next.
>
> Any ideas?
>
Interesting. Are you sure wlan0 is ath9k and wlan1 is ath10k?
ath9k is quite stable - I have AR9462 and works fine with 4.4 and current.
So, I would suspect some issues with ath10k :)

What if you will modprobe -r ath10k_pci and next run the test?

BR
Janusz

> Regards,
>
> Tim