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

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

[Jan Hendrik Farr]

[-- 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 --]

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

[James Prestwood]

Hi Jan,

On 5/9/25 5:24 AM, Jan Hendrik Farr wrote:
> 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.

Thanks,

James

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

[Jan Hendrik Farr]

On 09 06:12:23, James Prestwood wrote:
> 
> 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

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

[James Prestwood]

Hi,

On 5/9/25 6:45 AM, Jan Hendrik Farr wrote:
> On 09 06:12:23, James Prestwood wrote:
>> 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?

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

>
> Best Regards
> Jan

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

[Jan Hendrik Farr]

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

> 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.

> 
> Thanks,
> 
> James
> 
> > 
> > Best Regards
> > Jan

[-- Attachment #2: trace.dat --]
[-- Type: application/octet-stream, Size: 3158988 bytes --]

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

[Johannes Berg]

On Fri, 2025-05-09 at 17:37 +0200, Jan Hendrik Farr wrote:
> > 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.

I think it tries to connect to a 5 GHz network first.

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.

johannes

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

[Jan Hendrik Farr]

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

> 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

[-- Attachment #2: capture2.tar --]
[-- Type: application/x-tar, Size: 3379200 bytes --]

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

[Jan Hendrik Farr]

On 09 22:42:10, Jan Hendrik Farr wrote:
> > 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

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

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

[Jan Hendrik Farr]

On 12 22:52:13, Jan Hendrik Farr wrote:
> On 09 22:42:10, Jan Hendrik Farr wrote:
> > > 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
> 
> 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.

Did a small experiment by running
echo 'before sleep 10' > /dev/kmsg && sleep 10 && echo 'after sleep 10' > /dev/kmsg

It does take ~10 seconds to complete (checked against smartphone
stopwatch).

dmesg output shows 10 seconds passing:

[326951.572303] before sleep 10
[326961.575732] after sleep 10

demsg -T shows 10 seconds as well:

[Fri May 16 06:35:58 2025] before sleep 10
[Fri May 16 06:36:08 2025] after sleep 10

I assume the incorrect time has something todo with suspend...

But at least the timestamps in the trace seem to be ticking at the
correct rate then. They still don't line up with the packet capture for
me though.

Should the iwlwifi/iwlwifi_dev_tx events roughly match up with frames
sent by the client?

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

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

[Johannes Berg]

On Fri, 2025-05-09 at 22:42 +0200, Jan Hendrik Farr wrote:
> > 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
> 

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

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

[Jan Hendrik Farr]

On 13 09:35:13, Johannes Berg wrote:
> On Fri, 2025-05-09 at 22:42 +0200, Jan Hendrik Farr wrote:
> > > 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
> > 
> 
> 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.

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.

The SAE confirm by the AP (frame 170) is before the SAE confirm by the
STA (frame 174) however. In all cases where the connection actually
works (maybe every 10th attempt or so) this happens to be in the
opposite order (first SAE confirm by the STA, then SAE confirm
by the AP). This is making me think that the order is causing
this issue somewhere in the stack.

The spec [1] seems to allow the SAE confirms to come in any order.
12.4.5.1 says that "[a] party confirms after it has committed and its peer
has committed". So the AP does not have to wait for the confrim from STA
before sending it's own confirm.


[1] https://ieeexplore.ieee.org/stamp/stamp.jsp?tp=&arnumber=7786995

Best Regards
Jan

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

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

[Johannes Berg]

On Tue, 2025-05-13 at 13:29 +0200, Jan Hendrik Farr wrote:
> 
> 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.

> 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

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

[Jan Hendrik Farr]

On 13 13:46:51, Johannes Berg wrote:
> On Tue, 2025-05-13 at 13:29 +0200, Jan Hendrik Farr wrote:
> > 
> > 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.
> 
> > 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

Thanks for the help! I'll test the patch this evening.

> 
> johannes

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

[Denis Kenzior]

Hi Jan,

 >
> 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

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

[Jan Hendrik Farr]

On 13 09:03:54, Denis Kenzior wrote:
> Hi Jan,
> 
> >
> > 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?.

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.

> 
> [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

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

[Jan Hendrik Farr]

On 13 16:19:08, Jan Hendrik Farr wrote:
> On 13 09:03:54, Denis Kenzior wrote:
> > Hi Jan,
> > 
> > >
> > > 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?.
> 
> 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).

Correction frame 879 and 940.

Those other frame number were from another capture I didn't send.

> So maybe the capture device missed them in the second capture? Although
> the RSSIs look good in the 2nd capture.
> 
> > 
> > [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

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

[Johannes Berg]

On Tue, 2025-05-13 at 09:03 -0500, Denis Kenzior wrote:
> Hi Jan,
> 
>  >
> > 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)
> 

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

johannes

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

[Denis Kenzior]

Hi Johannes,

On 5/13/25 9:53 AM, Johannes Berg wrote:
> On Tue, 2025-05-13 at 09:03 -0500, Denis Kenzior wrote:
>> Hi Jan,
>>
>>   >
>>> 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)
>>
> 
> 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.

Regards,
-Denis

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

[Johannes Berg]

On Tue, 2025-05-13 at 10:04 -0500, Denis Kenzior wrote:
> > I think it's expecting a confirm in response, but that was already lost
> > before.
> 
> Sorry, what is 'it' referring to here?

mac80211

> 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

sure

> 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.

By that time iwlwifi has given up on the whole thing and said it was
disconnected, I'm not super surprised that something is mixed up. OTOH,
according to trace-cmd, the frames _are_ going to the firmware and even
ACKed in the log:

 irq/134-iwlwifi-392   [002] 64416.251984: iwlwifi_dbg:          iwl_mvm_rx_tx_cmd_single -- TXQ 1 status SUCCESS (0x00000001)
 irq/134-iwlwifi-392   [002] 64416.251987: iwlwifi_dbg:          iwl_mvm_rx_tx_cmd_single --                            initial_rate 0x8100 retries 0, idx=3 ssn=4 next_reclaimed=0x4 seq_ctl=0x30


so not sure, the PHY context seems correct as well. Don't think this is
the underlying issue here though.

johannes

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

[Jan Hendrik Farr]

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

On 13 13:46:51, Johannes Berg wrote:
> On Tue, 2025-05-13 at 13:29 +0200, Jan Hendrik Farr wrote:
> > 
> > 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.
> 
> > 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

Unfortunately this does not fix it.

Attached another capture (and trace, etc) created with this patch
applied. This one shows the retries of the clients confirm that
you and Denis were discussing.


Best Regards
Jan

> 
> johannes

[-- Attachment #2: capture3.tar --]
[-- Type: application/x-tar, Size: 3358720 bytes --]

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

[Johannes Berg]

On Tue, 2025-05-13 at 18:33 +0200, Jan Hendrik Farr wrote:
> > 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

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

[Jan Hendrik Farr]

On 13 19:07:30, Johannes Berg wrote:
> On Tue, 2025-05-13 at 18:33 +0200, Jan Hendrik Farr wrote:
> > > 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

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.

Best Regards
Jan

> 
> johannes

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

[Johannes Berg]

On Tue, 2025-05-13 at 19:36 +0200, Jan Hendrik Farr wrote:
> > 
> > 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?

Probably scheduling delay in the firmware. Before, to send the second
frame, the client would have create a new schedule and airtime
allocation in the firmware. Now it just keeps the old one so doesn't
have to.

> 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.

johannes

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

[Jan Hendrik Farr]

On 13 19:45:45, Johannes Berg wrote:
> On Tue, 2025-05-13 at 19:36 +0200, Jan Hendrik Farr wrote:
> 
> > 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

Best Regards
Jan

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

[Johannes Berg]

On Thu, 2025-05-15 at 14:36 +0200, Jan Hendrik Farr wrote:
> On 13 19:45:45, Johannes Berg wrote:
> > On Tue, 2025-05-13 at 19:36 +0200, Jan Hendrik Farr wrote:
> > 
> > > 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
> 

Cool, good to know. I still think we shouldn't really do this unpaired
(prepare/complete), but of course almost nothing except iwlwifi cares.
But also iwlwifi shouldn't abort session protection for auth in this
case anyway (or in the unlikely case of WEP shared key auth), unless the
process is suspended/finished.

johannes