Connection timeouts (NL80211_TIMEOUT_UNSPECIFIED) after disconnect/association timeout

[James Prestwood]

Still seeing this, and I think I've uncovered a bit more info. I'm going 
to add some additional debugging to confirm, but it appears for some 
reason the kernel's BSS list does not contain the BSS (or in some cases 
any BSS's) we are trying to connect to. I'll go over the sequence of 
events again:

1. Client gets deauthenticated for whatever reason

Feb 27 22:43:58 kernel: wlan0: deauthenticated from **:**:**:22:60:7c 
(Reason: 6=CLASS2_FRAME_FROM_NONAUTH_STA)

2. Client issues a scan to reconnect, note that it clearly sees the 
following BSS's after scanning:

Feb 27 22:43:58 iwd[457]: src/station.c:station_print_scan_bss() 
Processing BSS '**:**:**:22:40:92' with SSID: <redacted>, freq: 5300, 
rank: 1702, strength: -5900, data_rate: 173.3, snr: 40, load: 21/255
Feb 27 22:43:58 iwd[457]: src/station.c:station_print_scan_bss() 
Processing BSS '**:**:**:1c:10:98' with SSID: <redacted>, freq: 5500, 
rank: 1418, strength: -6300, data_rate: 144.4, snr: 33, load: 37/255

3. Client tries to connect to **:**:**:22:40:92

Feb 27 22:43:58 iwd[457]: event: connect-info, ssid: <redacted>, bss: 
**:**:**:22:40:92, signal: -59, load: 21/255
Feb 27 22:43:58 iwd[457]: event: state, old: autoconnect_quick, new: 
connecting (auto)

4. Based on the IWD logging it appears the kernel has no BSS record, and 
tries to issue a scan (the scan was definitely not from IWD), but 
apparently comes up with nothing:

Feb 27 22:43:58 iwd[457]: src/scan.c:scan_notify() Scan notification 
Trigger Scan(33)
Feb 27 22:43:59 iwd[457]: src/scan.c:scan_notify() Scan notification New 
Scan Results(34)
Feb 27 22:43:59 iwd[457]: src/netdev.c:netdev_mlme_notify() MLME 
notification Connect(46)
Feb 27 22:43:59 iwd[457]: src/netdev.c:netdev_connect_event()
Feb 27 22:43:59 iwd[457]: src/netdev.c:netdev_connect_event() aborting 
and ignore_connect_event not set, proceed
Feb 27 22:43:59 iwd[457]: event: connect-timeout, reason: 0

The timeout reason 0 is NL80211_TIMEOUT_UNSPECIFIED.

5. IWD proceeds to the next BSS, which the kernel also needs to scan 
for, but succeeds:

Feb 27 22:43:59 iwd[457]: event: connect-info, ssid: <redacted>, 
bss: **:**:**:1c:10:98, signal: -63, load: 37/255
Feb 27 22:43:59 iwd[457]: src/station.c:station_try_next_bss() 
Attempting to connect to next BSS **:**:**:1c:10:98
Feb 27 22:43:59 iwd[457]: src/netdev.c:netdev_link_notify() event 16 on 
ifindex 5
Feb 27 22:43:59 iwd[457]: src/scan.c:scan_notify() Scan notification 
Trigger Scan(33)
Feb 27 22:43:59 iwd[457]: src/scan.c:scan_notify() Scan notification New 
Scan Results(34)
Feb 27 22:43:59 iwd[457]: src/netdev.c:netdev_link_notify() event 16 on 
ifindex 5
Feb 27 22:43:59 iwd[457]: src/netdev.c:netdev_mlme_notify() MLME 
notification New Station(19)
Feb 27 22:43:59 kernel: wlan0: authenticate with **:**:**:1c:10:98 
(local address=**:**:**:a2:a4:58)
Feb 27 22:43:59 kernel: wlan0: send auth to **:**:**:1c:10:98 (try 1/3)

So it would appear to me that despite the original scan that IWD issued 
which clearly showed both BSS's the kernel's BSS list did not contain 
those entries. In both cases above the kernel needed to scan for the 
requested BSS. Anything we can do on the supplicant side? I figured an 
explicit scan by the supplicant would surely populate the kernel's BSS 
list, but apparently in some cases it does not?

Thanks,

James

On 12/4/24 8:57 AM, James Prestwood wrote:
> Hi,
>
> I noticed this behavior where in some cases if the client gets 
> disconnect or fails to roam due to an association timeout the next 
> connection attempt will fail with a timeout of 
> NL80211_TIMEOUT_UNSPECIFIED as the reason. Briefly looking at the 
> kernel code in nl80211/sme.c:cfg80211_conn_do_work() this appears to 
> be the default value passed in, so its hitting one of the cases that 
> aren't auth/assoc related. There are no kernel logs when this happens. 
> The supplicant fails multiple times continuing to iterate BSS's until 
> it finally is able to connect a few seconds later. In some _very_ rare 
> cases I have seen the client never able to reconnect to any BSS's, it 
> just loops over all BSS with the same NL80211_TIMEOUT_UNSPECIFIED 
> error indefinitely until a customer notices and reboots the client.
>
> I see this behavior on kernel 6.2 and 6.8 (that's all our clients run 
> at the moment) and on both ath10k and ath11k drivers. I'm not able to 
> get this to happen with mac80211_hwsim fwiw. Prior to switching to 6.2 
> (and 6.8) we were on 5.15 and I never saw this happen.
>
> Below are some logs from the kernel and IWD. Lots of irrelevant lines 
> have been removed to be more concise.
>
> tl;dr
>
> 1. Got an association timeout attempting to roam, disconnected
>
> 2. Scanned (~1 second), plenty of available BSS's
>
> 3. Failed to connect to 4 different BSS's in a row with 
> NL80211_TIMEOUT_UNSPECIFIED ("reason: 0")
>
> 4. Failed to connect to the next BSS with an auth timeout (no issue 
> here, this just happens sometimes)
>
> 5. Finally able to connect to another BSS (oddly, the original BSS we 
> were roaming away from)
>
>
> Dec 04 11:42:34 iwd[391]: event: roam-info, bss: **:**:**:13:06:ea, 
> signal: -87, load: 63/255
> Dec 04 11:42:34 iwd[391]: event: state, old: connected, new: ft-roaming
> Dec 04 11:42:34 kernel: wlan0: disconnect from AP **:**:**:13:07:b6 
> for new assoc to **:**:**:13:06:ea
> Dec 04 11:42:34 kernel: wlan0: associate with **:**:**:13:06:ea (try 1/3)
> Dec 04 11:42:34 kernel: wlan0: associate with **:**:**:13:06:ea (try 2/3)
> Dec 04 11:42:34 kernel: wlan0: associate with **:**:**:13:06:ea (try 3/3)
> Dec 04 11:42:34 kernel: wlan0: association with **:**:**:13:06:ea 
> timed out
> Dec 04 11:42:34 iwd[391]: src/netdev.c:netdev_associate_event()
> Dec 04 11:42:34 iwd[391]: event: association-timeout,
> Dec 04 11:42:34 iwd[391]: event: state, old: ft-roaming, new: 
> disconnected
> Dec 04 11:42:34 iwd[391]: event: state, old: disconnected, new: 
> autoconnect_quick
> Dec 04 11:42:34 iwd[391]: src/station.c:station_quick_scan_triggered() 
> Quick scan triggered for wlan0
> Dec 04 11:42:35 iwd[391]: src/scan.c:scan_notify() Scan notification 
> New Scan Results(34)
> Dec 04 11:42:35 iwd[391]: src/netdev.c:netdev_link_notify() event 16 
> on ifindex 5
> Dec 04 11:42:35 iwd[391]: event: connect-info, ssid: <redacted>, bss: 
> **:**:**:12:fc:f8, signal: -56, load: 65/255
> Dec 04 11:42:35 iwd[391]: event: state, old: autoconnect_quick, new: 
> connecting (auto)
> Dec 04 11:42:35 iwd[391]: event: connect-timeout, reason: 0
> Dec 04 11:42:35 iwd[391]: event: connect-info, ssid: <redacted>, bss: 
> **:**:**:12:fd:56, signal: -62, load: 69/255
> Dec 04 11:42:36 iwd[391]: event: connect-timeout, reason: 0
> Dec 04 11:42:36 iwd[391]: event: connect-info, ssid: <redacted>, bss: 
> **:**:**:13:08:33, signal: -60, load: 53/255
> Dec 04 11:42:36 iwd[391]: event: connect-timeout, reason: 0
> Dec 04 11:42:36 iwd[391]: event: connect-info, ssid: <redacted>, bss: 
> **:**:**:12:fd:34, signal: -67, load: 43/255
> Dec 04 11:42:36 iwd[391]: event: connect-timeout, reason: 0
> Dec 04 11:42:36 kernel: wlan0: authenticate with **:**:**:13:07:b6
> Dec 04 11:42:36 iwd[391]: event: connect-failed, status: 1
> Dec 04 11:42:36 iwd[391]: event: connect-info, ssid: <redacted>, bss: 
> **:**:**:13:07:b6, signal: -70, load: 28/255
> Dec 04 11:42:36 iwd[391]: src/station.c:station_try_next_bss() 
> Attempting to connect to next BSS **:**:**:13:07:b6
> Dec 04 11:42:36 kernel: wlan0: send auth to **:**:**:13:07:b6 (try 1/3)
> Dec 04 11:42:36 kernel: wlan0: send auth to **:**:**:13:07:b6 (try 2/3)
> Dec 04 11:42:36 kernel: wlan0: authenticated
> Dec 04 11:42:36 kernel: wlan0: associate with **:**:**:13:07:b6 (try 1/3)
> Dec 04 11:42:36 kernel: wlan0: RX AssocResp from **:**:**:13:07:b6 
> (capab=0x1511 status=0 aid=3)
>
>
> While writing this email I also saw it happen live while I had a 
> mac80211/cfg80211 trace running. In this recent case it failed on 12 
> consecutive BSS's with the unspecified timeout. That trace log is 
> attached, maybe could shed more light on this.
>
> Thanks,
>
> James