* Connection timeouts (NL80211_TIMEOUT_UNSPECIFIED) after disconnect/association timeout
@ 2024-12-04 16:57 James Prestwood
2025-03-03 15:19 ` James Prestwood
0 siblings, 1 reply; 2+ messages in thread
From: James Prestwood @ 2024-12-04 16:57 UTC (permalink / raw)
To: open list:MEDIATEK MT76 WIRELESS LAN DRIVER
Cc: ath10k, ath11k@lists.infradead.org
[-- Attachment #1: Type: text/plain, Size: 4519 bytes --]
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
[-- Attachment #2: connect-loop-trace.txt --]
[-- Type: text/plain, Size: 15943 bytes --]
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
^ permalink raw reply [flat|nested] 2+ messages in thread
* Re: Connection timeouts (NL80211_TIMEOUT_UNSPECIFIED) after disconnect/association timeout
2024-12-04 16:57 Connection timeouts (NL80211_TIMEOUT_UNSPECIFIED) after disconnect/association timeout James Prestwood
@ 2025-03-03 15:19 ` James Prestwood
0 siblings, 0 replies; 2+ messages in thread
From: James Prestwood @ 2025-03-03 15:19 UTC (permalink / raw)
To: open list:MEDIATEK MT76 WIRELESS LAN DRIVER
Cc: ath10k, ath11k@lists.infradead.org
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
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2025-03-03 15:19 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2024-12-04 16:57 Connection timeouts (NL80211_TIMEOUT_UNSPECIFIED) after disconnect/association timeout James Prestwood
2025-03-03 15:19 ` James Prestwood
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).