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

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

One thing you could try easily right off the bat would be to try forcing the default SAE group in IWD's config. I've seen some APs really struggle with group negotiation which is why we added the ability to set this. In your network profile (/var/lib/iwd/ssid.psk) set this:

[Settings]
UseDefaultEccGroup=true

And see if that helps.

Quoted 10 lines · James Prestwood

One thing you could try easily right off the bat would be to try forcing the default SAE group in IWD's config. I've seen some APs really struggle with group negotiation which is why we added the ability to set this. In your network profile (/var/lib/iwd/ssid.psk) set this:

[Settings]
UseDefaultEccGroup=true

And see if that helps.

Thanks for the suggestion. It does not appear to change the behavior I'm seeing. Also I'm pretty convinced that the AP is not at fault here. It is sending the confirm, and the STA fails to ACK that and the confirm never shows up in iwd.

Confirmed that the settings is applied using these logs from iwd:

[SAE]: Using SAE H2E
[SAE]: Using group 19

I assume group 19 is the default group?

Best Regards
Jan

Yep that's it. At least we can take that out of the equation.

And yes, in the PCAP I do see the confirm's being sent but no ACK. We'll have to wait for an iwlwifi person to chime in. I suspect we'll need some iwlwifi debugging enabled to see if the confirm was received at some level in the driver and dropped, or never received at all.

Thanks,

James

Quoted 3 lines

Best Regards
Jan

Quoted 6 lines

Yep that's it. At least we can take that out of the equation.

And yes, in the PCAP I do see the confirm's being sent but no ACK. We'll have to wait for an iwlwifi person to chime in. I suspect we'll need some iwlwifi debugging enabled to see if the confirm was received at some level in the driver and dropped, or never received at all.

I have captured and attached a trace collected using:

trace-cmd record -e iwlwifi -e mac80211 -e cfg80211 -e iwlwifi_msg

At the start of the trace iwd is shutdown. I start it and force it to connect to a 6ghz network. There should be at least two failed connections.

Could you do trace and sniffer at the same time? According to the trace there was no authentication frame from the AP. In the sniffer capture it _is_ there, of course, but I'd like to look at the timing.

Quoted 3 lines

Could you do trace and sniffer at the same time? According to the trace there was no authentication frame from the AP. In the sniffer capture it _is_ there, of course, but I'd like to look at the timing.

Ok, I did another capture.

1. iwd only knows credentials for a single SSID: kepler_test
2. kepler_test is the only SSID broadcasting on 6GHz channel 37 (or any 6GHz channel)
3. I captured 802.11 frames using a second device
4. I did a trace on the client in question
5. I captured dmesg and iwd logs
6. All captures were done simultaneously

All attached to capture2.tar. Contents:
capture2/dmesg2.txt : dmesg
capture2/iwd_log2.txt : iwd log using IWD_SAE_DEBUG=1
capture2/trace2.dat : trace-cmd (iwlwifi, mac80211, cfg80211, iwlwifi_msg)
capture2/iwd_main.conf : iwd config (/etc/iwd/main.conf)
capture2/kepler_test.psk : ssid config for iwd (/var/lib/kepler_test.psk) capture2/capture2.pcapng : the external 802.11 frame capture

I disabled 5Ghz via BandModifier5GHz=0.0 (couldn't disable 2.4GHz as iwd then complains about not being able to disable both)

One note about the client: It's running an Intel N100, so it's probably on the lower end of devices that will be running a modern wifi 6e card. So this increases the chances that the AP will send it's confirm before the client will.

Best Regards
Jan

Quoted 28 lines · Jan Hendrik Farr

Quoted 3 lines

Could you do trace and sniffer at the same time? According to the trace there was no authentication frame from the AP. In the sniffer capture it _is_ there, of course, but I'd like to look at the timing.

Ok, I did another capture.

1. iwd only knows credentials for a single SSID: kepler_test
2. kepler_test is the only SSID broadcasting on 6GHz channel 37 (or any 6GHz channel)
3. I captured 802.11 frames using a second device
4. I did a trace on the client in question
5. I captured dmesg and iwd logs
6. All captures were done simultaneously

All attached to capture2.tar. Contents:
capture2/dmesg2.txt : dmesg
capture2/iwd_log2.txt : iwd log using IWD_SAE_DEBUG=1
capture2/trace2.dat : trace-cmd (iwlwifi, mac80211, cfg80211, iwlwifi_msg)
capture2/iwd_main.conf : iwd config (/etc/iwd/main.conf)
capture2/kepler_test.psk : ssid config for iwd (/var/lib/kepler_test.psk) capture2/capture2.pcapng : the external 802.11 frame capture

I disabled 5Ghz via BandModifier5GHz=0.0 (couldn't disable 2.4GHz as iwd then complains about not being able to disable both)

Quoted 8 lines

One note about the client: It's running an Intel N100, so it's probably on the lower end of devices that will be running a modern wifi 6e card. So this increases the chances that the AP will send it's confirm before the client will.

Best Regards
Jan

I think there is something weird going on with the system time. I tried lining up the times of frames in the packet capture with the iwlwifi/iwlwifi_dev_(rx/tx) events and noticed that it's not possible to get them to line up.

For example time between STA sending commit and sending it's own confirm is 41.85 ms according to the packed capture. But the time between what I think are the corresponding events in the trace is 106.63 ms.

Then I noticed that the time in dmesg -T was running ahead of the correct time even though it was synced at boot. clock source is tsc.

This is making analysis very annoying, but could it also be causing the issue in the first place?

Best Regards
Jan

Quoted 3 lines

Could you do trace and sniffer at the same time? According to the trace there was no authentication frame from the AP. In the sniffer capture it _is_ there, of course, but I'd like to look at the timing.

Ok, I did another capture.

1. iwd only knows credentials for a single SSID: kepler_test
2. kepler_test is the only SSID broadcasting on 6GHz channel 37 (or any 6GHz channel)
3. I captured 802.11 frames using a second device
4. I did a trace on the client in question
5. I captured dmesg and iwd logs
6. All captures were done simultaneously

Quoted 7 lines · Jan Hendrik Farr

Quoted 3 lines

Could you do trace and sniffer at the same time? According to the trace there was no authentication frame from the AP. In the sniffer capture it _is_ there, of course, but I'd like to look at the timing.

Ok, I did another capture.

Quoted 8 lines

1. iwd only knows credentials for a single SSID: kepler_test
2. kepler_test is the only SSID broadcasting on 6GHz channel 37 (or any 6GHz channel)
3. I captured 802.11 frames using a second device
4. I did a trace on the client in question
5. I captured dmesg and iwd logs
6. All captures were done simultaneously

I'm confused now, this all looks fine from a driver perspective.

We send SAE commit, receive SAE commit, send SAE confirm, never receive a response. There's no response in sniffer nor tracing data, so that matches up. There are a couple of retries of the confirm response, but that seems OK.

Seems like maybe iwd builds an SAE confirm that the AP doesn't like, try wpa_supplicant I guess.

johannes

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

There is however no ACK from the client in response to it and it also never shows up in iwd.

Quoted 3 lines · Jan Hendrik Farr

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

Oops, yes, I didn't catch the different seqno and thought it was all retries of a single frame.

Quoted 2 lines

There is however no ACK from the client in response to it and it also never shows up in iwd.

Right. Clearly this is because we actually leave the channel when we get the response to the auth frame.

I guess most cases we have the client much faster than the AP, so this might never be an issue. I guess here you were saying the client wasn't all that fast in responding.

In fact the AP seems to take ~17.1ms from one frame to the other, and the client ~20.4ms, though the client has some propagation delay through the software stack too.

I don't think this is really the right fix, but it might help:
https://p.sipsolutions.net/e852565303ad878b.txt

johannes

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

Hi Jan,

Quoted 4 lines

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

What I also find interesting is that the kernel on the client side reports sending the Authenticate-Confirm 3 times (according to dmesg and trace2.dat), but only a single Confirm from the client is seen in the air trace. I'm guessing the retransmissions (attempt 2 & 3) are lost somehow?.

[64414.164169] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 2/3)
[64415.063575] iwlwifi 0000:00:14.3: Not associated and the session
protection is over already...
[64415.063668] wlan0: Connection to AP 96:2a:6f:b6:d7:9f lost
[64416.215729] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 3/3)

Regards,
-Denis

Quoted 7 lines · Denis Kenzior

Hi Jan,

Quoted 4 lines

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

Quoted 4 lines

What I also find interesting is that the kernel on the client side reports sending the Authenticate-Confirm 3 times (according to dmesg and trace2.dat), but only a single Confirm from the client is seen in the air trace. I'm guessing the retransmissions (attempt 2 & 3) are lost somehow?.

Yes this is weird. On my first capture I did see those additional confirm frames from the client (frame 4007 and 4052 in capture.pcapng).

So maybe the capture device missed them in the second capture? Although the RSSIs look good in the 2nd capture.

Quoted 9 lines

[64414.164169] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 2/3)
[64415.063575] iwlwifi 0000:00:14.3: Not associated and the session
protection is over already...
[64415.063668] wlan0: Connection to AP 96:2a:6f:b6:d7:9f lost
[64416.215729] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 3/3)

Regards,
-Denis

Hi Jan,

Quoted 4 lines

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

What I also find interesting is that the kernel on the client side reports sending the Authenticate-Confirm 3 times (according to dmesg and trace2.dat), but only a single Confirm from the client is seen in the air trace. I'm guessing the retransmissions (attempt 2 & 3) are lost somehow?.

[64414.164169] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 2/3)
[64415.063575] iwlwifi 0000:00:14.3: Not associated and the session protection 
is over already...
[64415.063668] wlan0: Connection to AP 96:2a:6f:b6:d7:9f lost
[64416.215729] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 3/3)

Quoted 12 lines · Denis Kenzior

Hi Jan,

Quoted 4 lines

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

What I also find interesting is that the kernel on the client side reports sending the Authenticate-Confirm 3 times (according to dmesg and trace2.dat), but only a single Confirm from the client is seen in the air trace. I'm guessing the retransmissions (attempt 2 & 3) are lost somehow?.

Quoted 6 lines

[64414.164169] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 2/3)
[64415.063575] iwlwifi 0000:00:14.3: Not associated and the session protection
is over already...
[64415.063668] wlan0: Connection to AP 96:2a:6f:b6:d7:9f lost
[64416.215729] wlan0: send auth to 96:2a:6f:b6:d7:9f (try 3/3)

I think it's expecting a confirm in response, but that was already lost before.

Quoted 2 lines

I think it's expecting a confirm in response, but that was already lost before.

Sorry, what is 'it' referring to here?

iwd sends the Commit and Confirm via CMD_AUTHENTICATE. You can see that Commit frame from the AP was received and then iwd submits a Confirm to the kernel:

May 09 22:10:56 archlinux iwd[31729]: [SAE]: Sending Commit to 96:2a:6f:b6:d7:9f
May 09 22:10:56 archlinux iwd[31729]: [SAE]: Received frame transaction=1 
status=126 state=committed
May 09 22:10:56 archlinux iwd[31729]: [SAE]: Sending Confirm to 

96:2a:6f:b6:d7:9f sc=1

The kernel then transmits the Confirm three times, but attempt 2 and 3 somehow never make it out over the air. I find that strange since they should still go out, regardless whether the Confirm from the AP was lost initially.

Quoted 3 lines · Jan Hendrik Farr

There is a an SAE confirm sent by the AP. It's frame 170 in capture2.pcapng. It's also retried a number of times after that.

Oops, yes, I didn't catch the different seqno and thought it was all retries of a single frame.

Quoted 2 lines

There is however no ACK from the client in response to it and it also never shows up in iwd.

Right. Clearly this is because we actually leave the channel when we get the response to the auth frame.

I guess most cases we have the client much faster than the AP, so this might never be an issue. I guess here you were saying the client wasn't all that fast in responding.

In fact the AP seems to take ~17.1ms from one frame to the other, and the client ~20.4ms, though the client has some propagation delay through the software stack too.

I don't think this is really the right fix, but it might help:
https://p.sipsolutions.net/e852565303ad878b.txt

johannes

Quoted 2 lines

I don't think this is really the right fix, but it might help:
https://p.sipsolutions.net/e852565303ad878b.txt

Unfortunately this does not fix it.

Attached another capture (and trace, etc)

Quoted 6 lines · Jan Hendrik Farr

Quoted 2 lines

I don't think this is really the right fix, but it might help:
https://p.sipsolutions.net/e852565303ad878b.txt

Unfortunately this does not fix it.

Attached another capture (and trace, etc)

Hm. Yeah, I missed the second path that goes there in this case ...

https://p.sipsolutions.net/0c145f72fdec3cf5.txt

johannes

Quoted 4 lines

Hm. Yeah, I missed the second path that goes there in this case ...

https://p.sipsolutions.net/0c145f72fdec3cf5.txt

This work!

Interestingly though, now the order is always:
1. client commit
2. AP commit
3. client confirm
4. AP confirm

It is now only ~5.3 ms between AP commit and client confirm vs ~21.2 ms before.

Do you have an explanation why this patch would change the timing?

So this test doesn't proof that it would work with the order the other way around. Maybe I should try making iwd sleep while generating the commit.

Quoted 2 lines · Jan Hendrik Farr

So this test doesn't proof that it would work with the order the other way around. Maybe I should try making iwd sleep while generating the commit.

I guess you could, right.

Quoted 6 lines · Johannes Berg

Quoted 2 lines · Jan Hendrik Farr

So this test doesn't proof that it would work with the order the other way around. Maybe I should try making iwd sleep while generating the commit.

I guess you could, right.

Just to report back on this:

I added a 20ms delay in iwd's generation of the confirm message and everything is working as expected with your patch applied. Connection is succesful with the following order of frames confirmed by external capture:

1. client sends SAE commit
2. AP sends SAE commit
3. AP sends SAE confirm
4. client sends SAE confirm