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
