On Wed, Mar 29, 2017 at 10:54 PM, Janusz Dziedzic
[off-list ref] wrote:

On 29 March 2017 at 19:03, Tim Harvey [off-list ref] wrote:

quoted

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