FS#73495 - wpa_supplicant 2.10 error

Attached to Project: Arch Linux
Opened by Cameron (ElderNoSpace) - Tuesday, 25 January 2022, 10:26 GMT
Last edited by Antonio Rojas (arojas) - Wednesday, 16 February 2022, 17:05 GMT
Task Type Bug Report
Category Packages: Core
Status Closed
Assigned To Antonio Rojas (arojas)
Architecture All
Severity Low
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 11
Private No

Details

Description:

Upgrading to wpa_supplicant 2.10 caused wifi to stop working and gave error CTRL-EVENT-SCAN-FAILED ret=-22 retry=1.
Downgrading back to 2.9 fixed the issue.

Additional info:
wpa_supplicant 2.10

04:00.0 Network controller: Broadcom Inc. and subsidiaries BCM4360 802.11ac Wireless Network Adapter (rev 03)
This task depends upon

Closed by  Antonio Rojas (arojas)
Wednesday, 16 February 2022, 17:05 GMT
Reason for closing:  Fixed
Additional comments about closing:  wpa_supplicant 2.10-2
Comment by Francisco J. Vazquez (Fran) - Tuesday, 25 January 2022, 15:38 GMT
Same here, same adapter (on a MacBook Pro 11,1).
Comment by Przemysław Skweres (przemko) - Wednesday, 26 January 2022, 13:44 GMT
same here on EndevourOS. I can use wifi connected to mobile phone hotspot using the same wifi network but cannot connect to that network directly. Downgrade to ver. 2.9 make my wifi connection works.

System:
Kernel: 5.15.16-1-lts x86_64 bits: 64 compiler: gcc v: 11.1.0
Desktop: GNOME 41.3 tk: GTK 3.24.31 wm: gnome-shell dm: GDM
Distro: Arch Linux
Machine:
Type: Laptop System: Dell product: Inspiron 7577 v: N/A
serial: <superuser required> Chassis: type: 10 serial: <superuser required>
Mobo: Dell model: 0WTYKT v: A00 serial: <superuser required>
UEFI-[Legacy]: Dell v: 1.12.1 date: 12/18/2020
Battery:
ID-1: BAT0 charge: 43.6 Wh (100.0%) condition: 43.6/56.0 Wh (77.8%)
volts: 17.2 min: 15.2 model: Samsung SDI DELL W7NKD7B serial: <filter>
status: Full
CPU:
Info: quad core model: Intel Core i5-7300HQ bits: 64 type: MCP
arch: Kaby Lake rev: 9 cache: L1: 256 KiB L2: 1024 KiB L3: 6 MiB
Speed (MHz): avg: 3332 high: 3376 min/max: 800/3500 cores: 1: 3317
2: 3318 3: 3320 4: 3376 bogomips: 19999
Flags: avx avx2 ht lm nx pae sse sse2 sse3 sse4_1 sse4_2 ssse3 vmx
Graphics:
Device-1: Intel HD Graphics 630 vendor: Dell driver: i915 v: kernel
bus-ID: 00:02.0 chip-ID: 8086:591b
Device-2: NVIDIA GP107M [GeForce GTX 1050 Mobile] vendor: Dell
driver: nvidia v: 495.46 bus-ID: 01:00.0 chip-ID: 10de:1c8d
Display: x11 server: X.Org 1.21.1.3 compositor: gnome-shell driver:
loaded: modesetting,nvidia resolution: 1920x1080~60Hz s-dpi: 96
OpenGL: renderer: Mesa Intel HD Graphics 630 (KBL GT2) v: 4.6 Mesa 21.3.4
direct render: Yes
Audio:
Device-1: Intel CM238 HD Audio vendor: Dell driver: snd_hda_intel v: kernel
Network:
Device-1: Realtek RTL8111/8168/8411 PCI Express Gigabit Ethernet
vendor: Dell driver: N/A port: d000 bus-ID: 3b:00.0 chip-ID: 10ec:8168
Device-2: Intel Wireless 8265 / 8275 driver: iwlwifi v: kernel
bus-ID: 3c:00.0 chip-ID: 8086:24fd
IF: wlan0 state: up mac: <filter>
Comment by BAD+MAD (mat_weiss) - Wednesday, 26 January 2022, 18:20 GMT
Same here.

OS: Arch Linux x86_64
Kernel Release: 5.15.16-1-lts
WM: Xfwm
DE: Xfce
Processor Type: Intel(R) Core(TM) i7-4700MQ CPU @ 2.40GHz
WLAN-CARD-Model: Intel Centrino Wireless-N 135 BGN
WLAN-Router: ASUS Wireless Router GT-AX11000
Comment by Étienne Morice (emorice) - Thursday, 27 January 2022, 05:25 GMT
Same here.

Network controller: Broadcom Inc. and subsidiaries BCM43142 802.11b/g/n
broadcom-wl 6.30.223.271-357 (rev 01)

I had some time to kill so I checked out wpa_supplicant from upstream: http://w1.fi/cvs.html and bisected the bug.
For me the first commits that make it stop working are:
a11804724 MSCS: Add support to send MSCS Request frames
c005283c4 SCS: Sending of SCS Request frames

These introduced in wpa_supplicant/wpa_supplicant.c, in wpas_ext_capab_byte, two new flags:
```
case 6: /* Bits 48-55 */
*pos |= 0x40; /* Bit 54 - SCS */
```
and
```
case 10: /* Bits 80-87 */
*pos |= 0x20; /* Bit 85 - Mirrored SCS */
```

If I comment these out, or set mscs = scs = false at the beginning of the function:
```
diff --git a/wpa_supplicant/wpa_supplicant.c b/wpa_supplicant/wpa_supplicant.c
index d37a994f9..561e5f3ed 100644
--- a/wpa_supplicant/wpa_supplicant.c
+++ b/wpa_supplicant/wpa_supplicant.c
@@ -1883,7 +1883,7 @@ int wpa_supplicant_set_suites(struct wpa_supplicant *wpa_s,

static void wpas_ext_capab_byte(struct wpa_supplicant *wpa_s, u8 *pos, int idx)
{
- bool scs = true, mscs = true;
+ bool scs = false, mscs = false;

*pos = 0x00;
```
I get it to work again. I'm posting from hostap_2_10 with this modification right now.
Also, commenting the rest of the first breaking commit made no difference, so it seems to me that it's really these flags that cause the problem for me and not the rest of code depending on them introduced at the same time.

Now the problem is, I have no idea what these actually do and how they cause the scan to fail.

Most crucially, I don't know at all if wpa_supplicant is doing something wrong here, or if that code is actually correct but these flags are somehow propagated down the stack to components (drivers ?) that cannot handle them yet. So I'm not even sure if this should be fixed upstream here or in other packages.

So I'm stopping here. That was fun to track down, I have a working 2.10 so I'm happy and I hope that will save some time for whoever understands the big picture and can fix this.


Comment by Antonio Rojas (arojas) - Thursday, 27 January 2022, 07:59 GMT
Thanks for the investigation, please post your findings at http://lists.infradead.org/pipermail/hostap/2022-January/040159.html
Comment by Étienne Morice (emorice) - Friday, 28 January 2022, 01:42 GMT
I sent them a mail but it's waiting for mod approval for now.

In the meantime I had a moment to track down what happens down the stack, I'll put it here to remember. The commits that introduced support for SCS and MSCS trigger the use of the extra IE parts in scan. More precisely, commenting out in src/drivers/driver_nl80211_scan.c nl80211_scan_common the lines:
| if (params->extra_ies) {
| wpa_hexdump(MSG_MSGDUMP, "nl80211: Scan extra IEs",
| params->extra_ies, params->extra_ies_len);
| if (nla_put(msg, NL80211_ATTR_IE, params->extra_ies_len,
| params->extra_ies))
| goto fail;
| }
also makes hostap_2_10 work again. After that it's propagated through the wpa_supplicant interface to nl80211, and it ends up in the kernel in net/wireless/nl80211.c where inside nl80211_trigger_scan , it fails the check:
if (ie_len > wiphy->max_scan_ie_len)
return -EINVAL;
I confirmed this with a quick rebuild of cfg80211 and a few printks, adding
if (ie_len > wiphy->max_scan_ie_len) {
+ printk(KERN_DEBUG "nl80211_trigger_scan: EINVAL max_scan_ie_len\n");
+ printk(KERN_DEBUG "nl80211_trigger_scan: ie_len %lu\n", ie_len);
+ printk(KERN_DEBUG "nl80211_trigger_scan: max_scan_ie_len %d\n",
+ wiphy->max_scan_ie_len);
puts the following in dmesg with the versions that fail:
[ 2193.701832] nl80211_trigger_scan: EINVAL max_scan_ie_len
[ 2193.701833] nl80211_trigger_scan: ie_len 13
[ 2193.701836] nl80211_trigger_scan: max_scan_ie_len 0

In comparison non-failing version don't send extra ies and ie_len is 0 too.

As far as I understand the value of max_scan_ie_len depends on the driver below (I guess), so it seems to come down to wpa_supplicant 2.10 trying to pass extra IEs during scan trigger to drivers that don't support them.

Comment by nya (nya) - Friday, 28 January 2022, 18:23 GMT
Similar issues - still distinct. Downgrading to 2.9 resolved the issue.

journalctl -fu wpa_supplicant
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Deauth request to the driver failed
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 3, ignoring for 60 seconds
Jan 28 14:54:58 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=2 duration=20 reason=CONN_FAILED
Jan 28 14:55:06 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-REMOVED 5c:49:79:68:dd:8c 0
Jan 28 14:55:06 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-DSCP-POLICY clear_all
Jan 28 14:56:19 wqed-54 wpa_supplicant[1120]: wlp3s0: Reject scan trigger since one is already pending
Jan 28 14:56:19 wqed-54 wpa_supplicant[1120]: wlp3s0: Failed to initiate AP scan
Jan 28 14:56:20 wqed-54 wpa_supplicant[1120]: wlp3s0: Reject scan trigger since one is already pending
Jan 28 14:56:20 wqed-54 wpa_supplicant[1120]: wlp3s0: Failed to initiate AP scan
Jan 28 14:56:21 wqed-54 wpa_supplicant[1120]: wlp3s0: Reject scan trigger since one is already pending
Jan 28 14:56:21 wqed-54 wpa_supplicant[1120]: wlp3s0: Failed to initiate AP scan
Jan 28 14:56:24 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:25 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:25 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Jan 28 14:56:25 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:25 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:56:25 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Deauth request to the driver failed
Jan 28 14:56:25 wqed-54 wpa_supplicant[1120]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 2, ignoring for 10 seconds
Jan 28 14:56:25 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=1 duration=10 reason=CONN_FAILED
Jan 28 14:56:35 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-REENABLED id=0 ssid="<SSID>"
Jan 28 14:56:35 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:35 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:35 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:56:35 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-REMOVED 5c:49:79:68:dd:8c 0
Jan 28 14:56:35 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:36 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:36 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Jan 28 14:56:36 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:36 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:56:36 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Deauth request to the driver failed
Jan 28 14:56:36 wqed-54 wpa_supplicant[1120]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 3, ignoring for 60 seconds
Jan 28 14:56:36 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=2 duration=20 reason=CONN_FAILED
Jan 28 14:56:43 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-REMOVED 5c:49:79:68:dd:8c 0
Jan 28 14:56:43 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-DSCP-POLICY clear_all
Jan 28 14:56:48 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:49 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:49 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Jan 28 14:56:49 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:49 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:56:49 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Deauth request to the driver failed
Jan 28 14:56:49 wqed-54 wpa_supplicant[1120]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 2, ignoring for 10 seconds
Jan 28 14:56:49 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=1 duration=10 reason=CONN_FAILED
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-REENABLED id=0 ssid="<SSID>"
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-REMOVED 5c:49:79:68:dd:8c 0
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Deauth request to the driver failed
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 3, ignoring for 60 seconds
Jan 28 14:56:59 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=2 duration=20 reason=CONN_FAILED
Jan 28 14:57:10 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-DSCP-POLICY clear_all
Jan 28 14:57:10 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-REMOVED 5c:49:79:68:dd:8c 0
Jan 28 14:57:10 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-DSCP-POLICY clear_all
Jan 28 14:57:13 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:57:14 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:57:14 wqed-54 wpa_supplicant[1120]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Jan 28 14:57:14 wqed-54 wpa_supplicant[1120]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Jan 28 14:57:14 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Jan 28 14:57:14 wqed-54 wpa_supplicant[1120]: wlp3s0: SME: Deauth request to the driver failed
Jan 28 14:57:14 wqed-54 wpa_supplicant[1120]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 2, ignoring for 10 seconds
Jan 28 14:57:14 wqed-54 wpa_supplicant[1120]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=1 duration=10 reason=CONN_FAILED



journalctl -fu NetworkManager
Jan 28 14:57:35 wqed-54 NetworkManager[740]: <info> [1643378255.0334] device (wlp3s0): supplicant interface state: disconnected -> scanning
Jan 28 14:57:38 wqed-54 NetworkManager[740]: <warn> [1643378258.9838] device (wlp3s0): Activation: (wifi) association took too long
Jan 28 14:57:38 wqed-54 NetworkManager[740]: <info> [1643378258.9839] device (wlp3s0): state change: config -> failed (reason 'no-secrets', sys-iface-state: 'managed')
Jan 28 14:57:38 wqed-54 NetworkManager[740]: <info> [1643378258.9853] manager: NetworkManager state is now DISCONNECTED
Jan 28 14:57:39 wqed-54 NetworkManager[740]: <info> [1643378259.0000] device (wlp3s0): set-hw-addr: set MAC address to FE:70:CC:30:CA:63 (scanning)
Jan 28 14:57:39 wqed-54 NetworkManager[740]: <warn> [1643378259.3985] device (wlp3s0): Activation: failed for connection '<SSID>'
Jan 28 14:57:39 wqed-54 NetworkManager[740]: <info> [1643378259.3987] device (wlp3s0): supplicant interface state: scanning -> disconnected
Jan 28 14:57:39 wqed-54 NetworkManager[740]: <info> [1643378259.3988] device (wlp3s0): supplicant interface state: disconnected -> interface_disabled
Jan 28 14:57:39 wqed-54 NetworkManager[740]: <info> [1643378259.3990] device (wlp3s0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Jan 28 14:57:39 wqed-54 NetworkManager[740]: <info> [1643378259.4153] device (wlp3s0): supplicant interface state: interface_disabled -> disconnected
Jan 28 14:57:42 wqed-54 NetworkManager[740]: <info> [1643378262.2968] manager: startup complete
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.5372] device (wlp3s0): Activation: starting connection '<SSID>' (e1e3924b-fa7f-40eb-aa89-53833b1adebc)
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.5373] audit: op="connection-activate" uuid="e1e3924b-fa7f-40eb-aa89-53833b1adebc" name="<SSID>" pid=2810 uid=1000 result="success"
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.5375] device (wlp3s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.5385] manager: NetworkManager state is now CONNECTING
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.5543] device (wlp3s0): set-hw-addr: reset MAC address to 60:67:20:B6:B3:E4 (preserve)
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9510] device (wlp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9515] device (wlp3s0): Activation: (wifi) access point '<SSID>' has security, but secrets are required.
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9515] device (wlp3s0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9521] device (wlp3s0): supplicant interface state: disconnected -> interface_disabled
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9532] device (wlp3s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9535] device (wlp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9538] device (wlp3s0): Activation: (wifi) connection '<SSID>' has security, and secrets exist. No new secrets needed.
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9538] Config: added 'ssid' value '<SSID>'
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9539] Config: added 'scan_ssid' value '1'
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9539] Config: added 'bgscan' value 'simple:30:-70:86400'
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9539] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256 FT-PSK SAE FT-SAE'
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9539] Config: added 'auth_alg' value 'OPEN'
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9539] Config: added 'psk' value '<hidden>'
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9539] Config: added 'ieee80211w' value '0'
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9624] device (wlp3s0): supplicant interface state: interface_disabled -> disconnected
Jan 28 14:57:46 wqed-54 NetworkManager[740]: <info> [1643378266.9798] device (wlp3s0): supplicant interface state: disconnected -> authenticating
Jan 28 14:57:47 wqed-54 NetworkManager[740]: <info> [1643378267.4196] device (wlp3s0): supplicant interface state: authenticating -> associating
Jan 28 14:57:47 wqed-54 NetworkManager[740]: <info> [1643378267.4535] device (wlp3s0): supplicant interface state: associating -> disconnected
Jan 28 14:57:57 wqed-54 NetworkManager[740]: <info> [1643378277.4568] device (wlp3s0): supplicant interface state: disconnected -> scanning
Jan 28 14:57:57 wqed-54 NetworkManager[740]: <info> [1643378277.4986] device (wlp3s0): supplicant interface state: scanning -> authenticating
Jan 28 14:57:57 wqed-54 NetworkManager[740]: <info> [1643378277.5434] device (wlp3s0): supplicant interface state: authenticating -> associating
Jan 28 14:57:57 wqed-54 NetworkManager[740]: <info> [1643378277.5842] device (wlp3s0): supplicant interface state: associating -> authenticating
Jan 28 14:57:58 wqed-54 NetworkManager[740]: <info> [1643378278.0756] device (wlp3s0): supplicant interface state: authenticating -> associating
Jan 28 14:57:58 wqed-54 NetworkManager[740]: <info> [1643378278.1095] device (wlp3s0): supplicant interface state: associating -> disconnected
Jan 28 14:58:08 wqed-54 NetworkManager[740]: <info> [1643378288.1101] device (wlp3s0): supplicant interface state: disconnected -> scanning
Jan 28 14:58:11 wqed-54 NetworkManager[740]: <warn> [1643378291.9830] device (wlp3s0): Activation: (wifi) association took too long
Jan 28 14:58:11 wqed-54 NetworkManager[740]: <info> [1643378291.9832] device (wlp3s0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jan 28 14:58:11 wqed-54 NetworkManager[740]: <warn> [1643378291.9839] device (wlp3s0): Activation: (wifi) asking for new secrets
Jan 28 14:58:11 wqed-54 NetworkManager[740]: <info> [1643378291.9875] device (wlp3s0): supplicant interface state: scanning -> disconnected
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6497] device (wlp3s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6513] device (wlp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6517] device (wlp3s0): Activation: (wifi) connection '<SSID>' has security, and secrets exist. No new secrets needed.
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6518] Config: added 'ssid' value '<SSID>'
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6518] Config: added 'scan_ssid' value '1'
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6518] Config: added 'bgscan' value 'simple:30:-70:86400'
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6518] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256 FT-PSK SAE FT-SAE'
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6518] Config: added 'auth_alg' value 'OPEN'
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6518] Config: added 'psk' value '<hidden>'
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6518] Config: added 'ieee80211w' value '0'
Jan 28 14:58:13 wqed-54 NetworkManager[740]: <info> [1643378293.6882] device (wlp3s0): supplicant interface state: disconnected -> authenticating
Jan 28 14:58:14 wqed-54 NetworkManager[740]: <info> [1643378294.1515] device (wlp3s0): supplicant interface state: authenticating -> associating
Jan 28 14:58:14 wqed-54 NetworkManager[740]: <info> [1643378294.1904] device (wlp3s0): supplicant interface state: associating -> disconnected
Jan 28 14:58:24 wqed-54 NetworkManager[740]: <info> [1643378304.1970] device (wlp3s0): supplicant interface state: disconnected -> scanning
Jan 28 14:58:24 wqed-54 NetworkManager[740]: <info> [1643378304.2386] device (wlp3s0): supplicant interface state: scanning -> authenticating
Jan 28 14:58:24 wqed-54 NetworkManager[740]: <info> [1643378304.2695] device (wlp3s0): supplicant interface state: authenticating -> associating
Jan 28 14:58:24 wqed-54 NetworkManager[740]: <info> [1643378304.3134] device (wlp3s0): supplicant interface state: associating -> authenticating
Jan 28 14:58:24 wqed-54 NetworkManager[740]: <info> [1643378304.7961] device (wlp3s0): supplicant interface state: authenticating -> associating
Jan 28 14:58:24 wqed-54 NetworkManager[740]: <info> [1643378304.8435] device (wlp3s0): supplicant interface state: associating -> disconnected
Jan 28 14:58:34 wqed-54 NetworkManager[740]: <info> [1643378314.8503] device (wlp3s0): supplicant interface state: disconnected -> scanning
Jan 28 14:58:38 wqed-54 NetworkManager[740]: <warn> [1643378318.9833] device (wlp3s0): Activation: (wifi) association took too long
Jan 28 14:58:38 wqed-54 NetworkManager[740]: <info> [1643378318.9834] device (wlp3s0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jan 28 14:58:38 wqed-54 NetworkManager[740]: <warn> [1643378318.9846] device (wlp3s0): Activation: (wifi) asking for new secrets
Jan 28 14:58:38 wqed-54 NetworkManager[740]: <info> [1643378318.9888] device (wlp3s0): supplicant interface state: scanning -> disconnected
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2236] device (wlp3s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2240] device (wlp3s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2243] device (wlp3s0): Activation: (wifi) connection '<SSID>' has security, and secrets exist. No new secrets needed.
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2244] Config: added 'ssid' value '<SSID>'
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2244] Config: added 'scan_ssid' value '1'
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2244] Config: added 'bgscan' value 'simple:30:-70:86400'
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2244] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256 FT-PSK SAE FT-SAE'
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2244] Config: added 'auth_alg' value 'OPEN'
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2245] Config: added 'psk' value '<hidden>'
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2245] Config: added 'ieee80211w' value '0'
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.2565] device (wlp3s0): supplicant interface state: disconnected -> authenticating
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.6884] device (wlp3s0): supplicant interface state: authenticating -> associating
Jan 28 14:58:41 wqed-54 NetworkManager[740]: <info> [1643378321.7222] device (wlp3s0): supplicant interface state: associating -> disconnected

Comment by David Volm (daxxog) - Sunday, 30 January 2022, 13:48 GMT
I am on a MBP with a BCM4331 and the broadcom-wl-dkms driver (version 6.30.223.271-28 at the time of writing).
Downgrading to the previous version (https://github.com/archlinux/svntogit-packages/commit/0cc611ce772916e0700fc337e380c29021e5fe74) fixed my issue.
I also noticed that someone else reported this bug resurfacing (and with similar hardware as mine) in the related redhat bug tracker thread:
https://bugzilla.redhat.com/show_bug.cgi?id=1703745#c83 -- which is also related to this old bug: https://bugs.archlinux.org/task/61119
Comment by loqs (loqs) - Sunday, 30 January 2022, 15:33 GMT
@emorice thank you for working with upstream to fix the issue. Is the attached diff correct?
I took the type to be
drv->capa.max_scan_ie_len <= params->extra_ies_len
should have been
drv->capa.max_scan_ie_len >= params->extra_ies_len
Edit:
Missed your attached diff which flipped arguments instead of comparator.
PKGBUILD.diff.2 merges your fix for the type into the original fix.
   PKGBUILD.diff (3.5 KiB)
   PKGBUILD.diff.2 (3.5 KiB)
Comment by Étienne Morice (emorice) - Sunday, 30 January 2022, 23:11 GMT
@loqs Yes, both diffs seem correct as far as I can see. This builds and fixes the issue as expected on my setup.
Comment by Dylan Bolger (5px) - Sunday, 06 February 2022, 06:25 GMT
Same here on latest Arch Linux. Downgrading to 2.9 has been a workaround.
Comment by Antonio Rojas (arojas) - Saturday, 12 February 2022, 19:15 GMT
Please test 2.10-2
Comment by nya (nya) - Saturday, 12 February 2022, 20:20 GMT
Sorry, still not working for me.

journalctl -fu wpa_supplicant
Feb 12 21:16:18 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:16:18 wqed-54 wpa_supplicant[1131]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Feb 12 21:16:18 wqed-54 wpa_supplicant[1131]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:16:18 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Feb 12 21:16:18 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Deauth request to the driver failed
Feb 12 21:16:18 wqed-54 wpa_supplicant[1131]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 3, ignoring for 60 seconds
Feb 12 21:16:18 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=2 duration=20 reason=CONN_FAILED
Feb 12 21:16:29 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-DSCP-POLICY clear_all
Feb 12 21:16:29 wqed-54 wpa_supplicant[1131]: wlp3s0: PMKSA-CACHE-REMOVED 5c:49:79:68:dd:8c 0
Feb 12 21:16:31 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-DSCP-POLICY clear_all
Feb 12 21:16:51 wqed-54 wpa_supplicant[1131]: wlp3s0: Reject scan trigger since one is already pending
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Deauth request to the driver failed
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 2, ignoring for 10 seconds
Feb 12 21:16:55 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=1 duration=10 reason=CONN_FAILED
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-SSID-REENABLED id=0 ssid="<SSID>"
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: PMKSA-CACHE-REMOVED 5c:49:79:68:dd:8c 0
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Trying to authenticate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: PMKSA-CACHE-ADDED 5c:49:79:68:dd:8c 0
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: Trying to associate with 5c:49:79:68:dd:8c (SSID='<SSID>' freq=5580 MHz)
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-ASSOC-REJECT bssid=5c:49:79:68:dd:8c status_code=40
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: SME: Deauth request to the driver failed
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: BSSID 5c:49:79:68:dd:8c ignore list count incremented to 3, ignoring for 60 seconds
Feb 12 21:17:06 wqed-54 wpa_supplicant[1131]: wlp3s0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="<SSID>" auth_failures=2 duration=20 reason=CONN_FAILED
Comment by Antonio Rojas (arojas) - Saturday, 12 February 2022, 20:31 GMT
@nya please report your issue upstream as it seems to be a different one.
Comment by loqs (loqs) - Saturday, 12 February 2022, 21:11 GMT
@nya is it https://lists.infradead.org/pipermail/hostap/2022-February/040209.html
Comment by Étienne Morice (emorice) - Saturday, 12 February 2022, 21:55 GMT
@arojas 2.10-2 solves the issue as expected for me, thanks !
Comment by Cameron (ElderNoSpace) - Sunday, 13 February 2022, 00:02 GMT
2.10-2 solves the problem for me as well, thanks.
Comment by Antonio Rojas (arojas) - Wednesday, 16 February 2022, 17:04 GMT
Closing this as the original issue is fixed. @nya please follow up with upstream about your issue and open a new ticket when there is some fix we can apply.

Loading...