wifi: iwlwifi: SAE fails when AP sends confirm before STA

[Jan Hendrik Farr <kernel@jfarr.cc>]

[-- Attachment #1: Type: text/plain, Size: 3425 bytes --]

Hello,

I noticed that specifically on the 6GHz band SAE connection fails
on my device most of the time. Connecting over 5GHz works
(even using SAE). So I started to investigate. Here's some of
the details about the devices involved:

STA:

- linux 6.14.5
- iwlwifi (Intel(R) Wi-Fi 6E AX211 160MHz)
- firmware 89.7f71c7f4.0 so-a0-gf-a0-89.ucode
- iwd 3.7

AP:

- Unifi U7 Pro (2nd gen, i.e. U7PROP)
- firmware 8.0.19.16619

I recorded a capture of a failed connection that is attached
(and also one that worked). Here's my understanding so far of what's
going on (starting at frame number 834 in the capture):

1. STA sends commit
2. AP sends ACK
3. AP sends commit
4. STA sends ACK
5. AP sends confirm
- NO ACK from STA!
- iwd logs show this is never received by iwd
6. AP retries confirm
- NO ACK from STA!
- iwd logs show this is never received by iwd
7. AP retries confirm
- NO ACK from STA!
- iwd logs show this is never received by iwd
8. AP retries confirm
- NO ACK from STA!
- iwd logs show this is never received by iwd
9. STA sends confirm
10. AP sends ACK
11. STA sends confirm
12. AP sends ACK
12. STA sends confirm
13. AP sends ACK


Here's iwd logs with IWD_SAE_DEBUG=1:

event: connect-info, ssid: kepler_56, bss: 96:2a:6f:b6:d7:9f, signal: -46, load: 0/255
event: state, old: autoconnect_full, new: connecting
[SAE]: Received frame transaction=1 status=126 state=committed
[SAE]: Sending Confirm to 96:2a:6f:b6:d7:9f sc=1
event: authentication-timeout,
event: connect-failed, status: 1


Here's dmesg from the relevant period:

[32295.061686] wlan0: authenticate with 96:2a:6f:b6:d7:91 (local address=a0:d3:65:93:5c:47)
[32295.063142] wlan0: send auth to 96:2a:6f:b6:d7:91 (try 1/3)
[32295.177571] wlan0: authenticate with 96:2a:6f:b6:d7:91 (local address=a0:d3:65:93:5c:47)
[32295.178025] wlan0: send auth to 96:2a:6f:b6:d7:91 (try 1/3)
[32296.093842] iwlwifi 0000:00:14.3: Not associated and the session protection is over already...
[32296.093940] wlan0: Connection to AP 96:2a:6f:b6:d7:91 lost
[32297.246064] wlan0: send auth to 96:2a:6f:b6:d7:91 (try 2/3)
[32298.166457] iwlwifi 0000:00:14.3: Not associated and the session protection is over already...
[32298.166553] wlan0: Connection to AP 96:2a:6f:b6:d7:91 lost
[32299.293860] wlan0: send auth to 96:2a:6f:b6:d7:91 (try 3/3)
[32300.219460] iwlwifi 0000:00:14.3: Not associated and the session protection is over already...
[32300.219555] wlan0: Connection to AP 96:2a:6f:b6:d7:91 lost
[32301.338987] wlan0: authentication with 96:2a:6f:b6:d7:91 timed out


At first I thought maybe iwd is at fault because its state machine
assumes that it always sends the confirm first. However, from iwd's
perspective this is fine as it's all happening on a single thread in a
synchronous way. So it's always gonna process the AP's confirm
after sending its own confirm. Independent of the actual order.

The fact that the confirm by the AP is not getting acknowledged by the
STA, to me, indicates that this is a problem with the device firmware or
iwlwifi driver. The confirm by the AP also never makes it to userspace
(iwd).


The notable difference with the successful connection (starting at
packet number 4752) is that the confirm by the STA happens to be sent
just before the confirm by the AP. All successful connections I've seen
have this in common. So I think somewhere in the stack (either firmware
or kernel) this order is assumed.


Best Regards
Jan


[-- Attachment #2: capture.pcapng --]
[-- Type: application/octet-stream, Size: 2306416 bytes --]