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
iwd-391 [001] 443702.243059: cfg80211_get_bss: phy0, band: 1, freq: 5660.000, e6:55:b8:13:08:28, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [001] 443702.243062: rdev_scan: phy0
iwd-391 [001] 443702.243066: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [001] 443702.244152: drv_return_int: phy0 - 0
iwd-391 [001] 443702.244155: rdev_return_int: phy0, returned: 0
locus_nodelet_m-3180 [002] 443702.396499: api_scan_completed: phy0 aborted:0
kworker/u8:3-1546696 [002] 443702.414460: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
kworker/u8:3-1546696 [002] 443702.414467: cfg80211_get_bss: phy0, band: 1, freq: 5660.000, e6:55:b8:13:08:28, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [001] 443702.414655: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [001] 443702.414656: rdev_return_int: phy0, returned: 0
iwd-391 [001] 443702.414673: cfg80211_get_bss: phy0, band: 1, freq: 5660.000, e6:55:b8:13:04:30, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [001] 443702.414675: rdev_scan: phy0
iwd-391 [001] 443702.414679: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [001] 443702.415075: drv_return_int: phy0 - 0
iwd-391 [001] 443702.415076: rdev_return_int: phy0, returned: 0
<...>-1581103 [001] 443702.449827: rdev_get_tx_power: phy0, wdev(2)
<...>-1581103 [001] 443702.449829: rdev_return_int_int: phy0, function returns: 0, function filled: 21
<idle>-0 [002] 443702.568112: api_scan_completed: phy0 aborted:0
kworker/u8:3-1546696 [001] 443702.586437: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
kworker/u8:3-1546696 [001] 443702.586445: cfg80211_get_bss: phy0, band: 1, freq: 5660.000, e6:55:b8:13:04:30, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [000] 443702.586642: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [000] 443702.586644: rdev_return_int: phy0, returned: 0
iwd-391 [000] 443702.586661: cfg80211_get_bss: phy0, band: 1, freq: 5660.000, e6:55:b8:12:fc:f8, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [000] 443702.586663: rdev_scan: phy0
iwd-391 [000] 443702.586668: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [000] 443702.587074: drv_return_int: phy0 - 0
iwd-391 [000] 443702.587076: rdev_return_int: phy0, returned: 0
<idle>-0 [002] 443702.740116: api_scan_completed: phy0 aborted:0
kworker/u8:3-1546696 [000] 443702.758447: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
kworker/u8:3-1546696 [000] 443702.758457: cfg80211_get_bss: phy0, band: 1, freq: 5660.000, e6:55:b8:12:fc:f8, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [000] 443702.758813: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [000] 443702.758814: rdev_return_int: phy0, returned: 0
iwd-391 [000] 443702.758838: cfg80211_get_bss: phy0, band: 1, freq: 5745.000, e6:55:b8:13:07:0c, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [000] 443702.758840: rdev_scan: phy0
iwd-391 [000] 443702.758846: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [000] 443702.759234: drv_return_int: phy0 - 0
iwd-391 [000] 443702.759236: rdev_return_int: phy0, returned: 0
<...>-1581096 [002] 443702.782533: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5745.000(scan_width: 0) signal: -8600, tsb:443710012133474, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00
<...>-1581096 [002] 443702.782542: cfg80211_return_bss: e6:55:b8:13:08:2c, band: 1, freq: 5745.000
<...>-1581096 [002] 443702.782552: cfg80211_rx_mgmt: wdev(2), freq: 5745.000, sig dbm: -86
<...>-1581096 [002] 443702.782553: cfg80211_return_bool: returned false
<...>-1581096 [002] 443702.786359: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5745.000(scan_width: 0) signal: -8400, tsb:443710015959255, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00
<...>-1581096 [002] 443702.786363: cfg80211_return_bss: e6:55:b8:13:08:2c, band: 1, freq: 5745.000
<...>-1581096 [002] 443702.786371: cfg80211_rx_mgmt: wdev(2), freq: 5745.000, sig dbm: -84
<...>-1581096 [002] 443702.786372: cfg80211_return_bool: returned false
<...>-1564434 [001] 443702.786380: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5745.000(scan_width: 0) signal: -8400, tsb:443710015959255, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00
<...>-1564434 [001] 443702.786383: cfg80211_return_bss: e6:55:b8:13:08:2c, band: 1, freq: 5745.000
<idle>-0 [002] 443702.885337: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5745.000(scan_width: 0) signal: -8600, tsb:443710114935282, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00
<idle>-0 [002] 443702.885342: cfg80211_return_bss: e2:55:b8:13:08:2c, band: 1, freq: 5745.000
<idle>-0 [002] 443702.885353: cfg80211_rx_mgmt: wdev(2), freq: 5745.000, sig dbm: -86
<idle>-0 [002] 443702.885354: cfg80211_return_bool: returned false
<...>-3143 [002] 443702.912278: api_scan_completed: phy0 aborted:0
<...>-1564434 [003] 443702.926446: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
<...>-1564434 [003] 443702.926465: cfg80211_get_bss: phy0, band: 1, freq: 5745.000, e6:55:b8:13:07:0c, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [003] 443702.926671: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [003] 443702.926673: rdev_return_int: phy0, returned: 0
iwd-391 [003] 443702.926692: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:13:08:03, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [003] 443702.926693: rdev_scan: phy0
iwd-391 [003] 443702.926697: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [002] 443702.938222: drv_return_int: phy0 - 0
iwd-391 [002] 443702.938224: rdev_return_int: phy0, returned: 0
locus_nodelet_m-486852 [002] 443703.080131: api_scan_completed: phy0 aborted:0
kworker/u8:3-1546696 [003] 443703.114439: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
kworker/u8:3-1546696 [003] 443703.114450: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:13:08:03, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [000] 443703.114669: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [000] 443703.114672: rdev_return_int: phy0, returned: 0
iwd-391 [000] 443703.114696: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:12:fd:59, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [000] 443703.114699: rdev_scan: phy0
iwd-391 [000] 443703.114704: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [002] 443703.115119: drv_return_int: phy0 - 0
iwd-391 [002] 443703.115121: rdev_return_int: phy0, returned: 0
<idle>-0 [002] 443703.268118: api_scan_completed: phy0 aborted:0
<...>-1564434 [000] 443703.306413: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
<...>-1564434 [000] 443703.306421: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:12:fd:59, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.306638: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [002] 443703.306640: rdev_return_int: phy0, returned: 0
iwd-391 [002] 443703.306661: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:12:fd:56, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.306664: rdev_scan: phy0
iwd-391 [002] 443703.306669: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [002] 443703.307173: drv_return_int: phy0 - 0
iwd-391 [002] 443703.307174: rdev_return_int: phy0, returned: 0
<...>-1581114 [001] 443703.449869: rdev_get_tx_power: phy0, wdev(2)
<...>-1581114 [001] 443703.449871: rdev_return_int_int: phy0, function returns: 0, function filled: 21
<idle>-0 [002] 443703.460100: api_scan_completed: phy0 aborted:0
<...>-1564434 [000] 443703.475100: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
<...>-1564434 [000] 443703.475111: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:12:fd:56, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.475319: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [002] 443703.475320: rdev_return_int: phy0, returned: 0
iwd-391 [002] 443703.475342: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:13:08:27, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.475344: rdev_scan: phy0
iwd-391 [002] 443703.475348: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [002] 443703.477060: drv_return_int: phy0 - 0
iwd-391 [002] 443703.477066: rdev_return_int: phy0, returned: 0
<idle>-0 [002] 443703.628767: api_scan_completed: phy0 aborted:0
<...>-1564434 [000] 443703.646413: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
<...>-1564434 [000] 443703.646425: cfg80211_get_bss: phy0, band: 1, freq: 5580.000, e6:55:b8:13:08:27, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.646718: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [002] 443703.646720: rdev_return_int: phy0, returned: 0
iwd-391 [002] 443703.646744: cfg80211_get_bss: phy0, band: 1, freq: 5680.000, e6:55:b8:13:03:f5, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.646746: rdev_scan: phy0
iwd-391 [002] 443703.646752: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [001] 443703.647626: drv_return_int: phy0 - 0
iwd-391 [001] 443703.647630: rdev_return_int: phy0, returned: 0
<idle>-0 [002] 443703.800194: api_scan_completed: phy0 aborted:0
kworker/u8:3-1546696 [003] 443703.814428: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
kworker/u8:3-1546696 [003] 443703.814436: cfg80211_get_bss: phy0, band: 1, freq: 5680.000, e6:55:b8:13:03:f5, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.814714: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [002] 443703.814716: rdev_return_int: phy0, returned: 0
iwd-391 [002] 443703.814740: cfg80211_get_bss: phy0, band: 1, freq: 5825.000, e6:55:b8:13:07:01, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [002] 443703.814742: rdev_scan: phy0
iwd-391 [002] 443703.814747: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [002] 443703.815269: drv_return_int: phy0 - 0
iwd-391 [002] 443703.815271: rdev_return_int: phy0, returned: 0
<...>-3692 [002] 443703.968177: api_scan_completed: phy0 aborted:0
kworker/u8:3-1546696 [003] 443703.986774: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
kworker/u8:3-1546696 [003] 443703.986783: cfg80211_get_bss: phy0, band: 1, freq: 5825.000, e6:55:b8:13:07:01, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [003] 443703.987012: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [003] 443703.987014: rdev_return_int: phy0, returned: 0
iwd-391 [003] 443703.987031: cfg80211_get_bss: phy0, band: 1, freq: 5765.000, e6:55:b8:12:f9:01, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [003] 443703.987033: rdev_scan: phy0
iwd-391 [003] 443703.987037: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [001] 443703.987419: drv_return_int: phy0 - 0
iwd-391 [001] 443703.987421: rdev_return_int: phy0, returned: 0
<...>-3172 [002] 443704.140472: api_scan_completed: phy0 aborted:0
<...>-1564434 [001] 443704.154412: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
<...>-1564434 [001] 443704.154419: cfg80211_get_bss: phy0, band: 1, freq: 5765.000, e6:55:b8:12:f9:01, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [003] 443704.154617: rdev_set_cqm_rssi_config: phy0, netdev:wlan0(5), rssi_thold: -70, rssi_hyst: 5
iwd-391 [003] 443704.154618: rdev_return_int: phy0, returned: 0
iwd-391 [003] 443704.154640: cfg80211_get_bss: phy0, band: 1, freq: 5240.000, e6:55:b8:13:07:e5, buf: 0x6c, bss_type: 0, privacy: 0
iwd-391 [003] 443704.154643: rdev_scan: phy0
iwd-391 [003] 443704.154648: drv_hw_scan: phy0 vif:wlan0(2)
iwd-391 [003] 443704.155031: drv_return_int: phy0 - 0
iwd-391 [003] 443704.155033: rdev_return_int: phy0, returned: 0
<idle>-0 [002] 443704.188742: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5240.000(scan_width: 0) signal: -8500, tsb:443711418365070, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00
<idle>-0 [002] 443704.188748: cfg80211_return_bss: e6:55:b8:13:07:e5, band: 1, freq: 5240.000
<idle>-0 [002] 443704.188757: cfg80211_rx_mgmt: wdev(2), freq: 5240.000, sig dbm: -85
<idle>-0 [002] 443704.188757: cfg80211_return_bool: returned false
<idle>-0 [002] 443704.189076: cfg80211_inform_bss_frame: phy0, band: 1, freq: 5240.000(scan_width: 0) signal: -8600, tsb:443711418702116, detect_tsf:0, tsf_bssid: 00:00:00:00:00:00
<idle>-0 [002] 443704.189078: cfg80211_return_bss: e2:55:b8:13:07:e5, band: 1, freq: 5240.000
<idle>-0 [002] 443704.189082: cfg80211_rx_mgmt: wdev(2), freq: 5240.000, sig dbm: -86
<idle>-0 [002] 443704.189082: cfg80211_return_bool: returned false
<idle>-0 [002] 443704.308082: api_scan_completed: phy0 aborted:0
<...>-1564434 [003] 443704.322461: cfg80211_scan_done: aborted: false, scan start (TSF): 0, tsf_bssid: 00:00:00:00:00:00
<...>-1564434 [003] 443704.322469: cfg80211_get_bss: phy0, band: 1, freq: 5240.000, e6:55:b8:13:07:e5, buf: 0x6c, bss_type: 0, privacy: 0
<...>-1564434 [003] 443704.322472: cfg80211_return_bss: e6:55:b8:13:07:e5, band: 1, freq: 5240.000
<...>-1542519 [003] 443704.322490: cfg80211_get_bss: phy0, band: 1, freq: 5240.000, e6:55:b8:13:07:e5, buf: 0x6c, bss_type: 0, privacy: 2
<...>-1542519 [003] 443704.322491: cfg80211_return_bss: e6:55:b8:13:07:e5, band: 1, freq: 5240.000
<...>-1542519 [003] 443704.322492: rdev_auth: phy0, netdev:wlan0(5), auth type: 0, bssid: e6:55:b8:13:07:e5
