Re: How to triage an "Invalid Key" error message?
Christian Hewitt <[email protected]>
| Newsgroups | dev.linux.lists.iwd |
|---|---|
| Message-ID | <[email protected]> |
> On 18 Jan 2025, at 8:38 pm, KeithG <[email protected]> wrote: > > Christian, > > Is this, perhaps, on devices with the brcmfmac chip? I have seen this > recently with on my Pis with wpa2 and wpa3 APs. The majority of reports are from RPi 4/5 users which have brcmfmac chips, but 85% of our distro installed base runs an RPi board so that mostly reflects our demographics. I’ve also seen reports on Amlogic and Rockchip SoC devices (also using brcmfmac); but to offset theories on it being brcmfmac specific, we’ve also had reports from users with Intel iwlwifi hardware and someone using an RTL8723BS chip. So it’s more likely to be an interaction with common code not driver code. At one point we suspected an issue with WPA3, but that was triaged with RPi developers and we now disable SAE offload which allows boards to connect to mixed WPA2/WPA3 networks, see: https://forum.libreelec.tv/thread/29155-rpi5-network-disappeared https://github.com/LibreELEC/LibreELEC.tv/pull/9477/files In the following forum and GitHub issue threads. There’s lots of assumptions, guesswork, and false conclusions, but among the noise there are some snippets of iwd debug log: https://github.com/LibreELEC/LibreELEC.tv/issues/7166 https://github.com/LibreELEC/LibreELEC.tv/issues/8731 https://github.com/LibreELEC/LibreELEC.tv/issues/8760 https://github.com/LibreELEC/LibreELEC.tv/issues/8762 I’ll need to rig a distro image for greater debug (as per James’ instructions) to see if we can obtain more log output. Christian > This is the journal snippet from one such 'Invalid Key' with wpa3, > though I have also seen it with wpa2: > Jan 04 11:23:57 jackrune iwd[10541]: > src/station.c:station_connect_cb() 3, result: 6 > Jan 04 11:23:57 jackrune iwd[10541]: event: disconnect-info, reason: 0 > Jan 04 11:23:57 jackrune iwd[10541]: src/wiphy.c:wiphy_select_akm() > Network is WPA3-Personal... > Jan 04 11:23:57 jackrune iwd[10541]: event: connect-info, FullMAC > driver: brcmfmac using SAE. Expect EXTERNAL_AUTH > Jan 04 11:23:57 jackrune iwd[10541]: > src/station.c:station_reset_connection_state() 3 > Jan 04 11:23:57 jackrune iwd[10541]: src/station.c:station_roam_state_clear() 3 > Jan 04 11:23:57 jackrune iwd[10541]: event: state, old: connecting, > new: disconnected > Jan 04 11:23:57 jackrune iwd[10541]: event: state, old: disconnected, > new: autoconnect_quick > Jan 04 11:23:57 jackrune iwd[10541]: src/scan.c:scan_periodic_start() > Starting periodic scan for wdev 1 > Jan 04 11:23:57 jackrune iwd[10541]: > src/wiphy.c:wiphy_radio_work_insert() Inserting work item 63 > Jan 04 11:23:57 jackrune iwd[10541]: > src/wiphy.c:wiphy_radio_work_next() Starting work item 63 > Jan 04 11:23:57 jackrune iwd[10541]: src/netdev.c:netdev_link_notify() > event 16 on ifindex 3 > Jan 04 11:23:57 jackrune iwd[10541]: src/scan.c:scan_notify() Scan > notification Trigger Scan(33) > Jan 04 11:23:57 jackrune iwd[10541]: src/netdev.c:netdev_link_notify() > event 16 on ifindex 3 > Jan 04 11:23:57 jackrune iwd[10541]: > src/scan.c:scan_request_triggered() Active scan triggered for wdev 1 > Jan 04 11:23:57 jackrune iwd[10541]: > src/scan.c:scan_periodic_triggered() Periodic scan triggered for wdev > 1 > Jan 04 11:23:57 jackrune iwd[10541]: src/station.c:station_dbus_disconnect() > Jan 04 11:23:57 jackrune iwd[10541]: event: state, old: > autoconnect_full, new: disconnected > Jan 04 11:23:57 jackrune iwd[10541]: src/scan.c:scan_periodic_stop() > Stopping periodic scan for wdev 1 > Jan 04 11:23:57 jackrune iwd[10541]: src/scan.c:scan_cancel() Trying > to cancel scan id 63 for wdev 1 > Jan 04 11:23:57 jackrune iwd[10541]: src/scan.c:scan_cancel() Scan has > been triggered, wait for it to complete > Jan 04 11:23:57 jackrune connmand[9885]: wlan0 {RX} 871 packets 104097 bytes > Jan 04 11:23:57 jackrune connmand[9885]: wlan0 {TX} 167 packets 25045 bytes > Jan 04 11:23:57 jackrune connmand[9885]: wlan0 {update} flags 4099 <UP> > Jan 04 11:23:57 jackrune connmand[9885]: wlan0 {newlink} index 3 > address B8:27:EB:A4:6E:0F mtu 1500 > Jan 04 11:23:57 jackrune connmand[9885]: wlan0 {newlink} index 3 > operstate 2 <DOWN> > Jan 04 11:23:57 jackrune connmand[9885]: Interface wlan0 [ wifi ] > error "invalid-key" > Jan 04 11:23:57 jackrune connmand[9885]: Interface wlan0 [ wifi ] > state is failure > > This is the iwmon snippet of what I think is the same exchange: > < Request: Connect (0x2e) len 148 [ack] 16.707632 > Interface Index: 3 (0x00000003) > Wiphy Frequency: 2412 (0x0000096c) > MAC Address D8:3A:DD:60:A3:0C > SSID: len 7 > 64 65 73 6b 53 41 45 deskSAE > Auth Type: 4 (0x00000004) > External Auth Support: 261 len 0 > Privacy: true > Socket Owns Interface/Connection: true > Cipher Suites Pairwise: > CCMP (00:0f:ac) suite 04 > Cipher Suite Group: CCMP (00:0f:ac) suite 04 > Use MFP: 1 (0x00000001) > AKM Suites: > SAE/PMKSA caching SHA256; RSNA PMKSA caching SHA256/mesh > peering exchange (00:0f:ac) suite 08 > WPA Versions: 4 (0x00000004) > Control Port: true > Information Elements: len 38 > RSN: > Group Data Cipher Suite: len 4 > CCMP (00:0f:ac) suite 04 > Pairwise Cipher Suite: len 4 > CCMP (00:0f:ac) suite 04 > AKM Suite: len 4 > SAE/PMKSA caching SHA256; RSNA PMKSA caching > SHA256/mesh peering exchange (00:0f:ac) suite 08 > RSN capabilities: bits 2 - 3: 1 replay counter per PTKSA > RSN capabilities: bits 4 - 5: 1 replay counter per GTKSA > RSN capabilities: bit 7: Management Frame Protection Capable > 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................ > ac 08 80 00 .... > Extended Capabilities: len 10 > Capability: bit 19: BSS transition > 00 00 08 00 00 00 00 00 00 01 .......... > Tag 262: len 1 > 1a . >> Response: Connect (0x2e) len 4 [0x100] 16.717389 > Status: Success (0) >> Event: External Auth (0x7f) len 56 16.765492 > Wiphy: 0 (0x00000000) > Interface Index: 3 (0x00000003) > AKM Suites: > unknown (08:ac:0f) suite 00 (unknown) > External Auth Action: 260 len 4 > 00 00 00 00 .... > BSSID D8:3A:DD:60:A3:0C > SSID: len 7 > 64 65 73 6b 53 41 45 deskSAE > < Request: Frame (0x3b) len 140 [ack] 16.783162 > Interface Index: 3 (0x00000003) > Frame: len 128 > Frame Type: 0x00b0 > Type: Management (0) > Authentication: > Frame Control: protocol: 00 type: 00 subtype: 11 to: > 00 from: 00 more_frags: 00 > retry: 00 power_mgmt: 00 more_data: 00 protected: > 00 order: 00 > Duration: 0 > Address 1 (RA): D8:3A:DD:60:A3:0C > Address 2 (TA): B8:27:EB:A4:6E:0F > Address 3: D8:3A:DD:60:A3:0C > Fragment Number: 0 > Sequence Number: 0 > Algorithm: SAE (seq: 1, status: 0) > b0 00 00 00 d8 3a dd 60 a3 0c b8 27 eb a4 6e 0f .....:.`...'..n. > d8 3a dd 60 a3 0c 00 00 03 00 01 00 00 00 13 00 .:.`............ > f0 db cc 49 7c ad 4b 75 65 da 78 de 53 11 30 de ...I|.Kue.x.S.0. > fb 47 cf 3e 97 63 99 ff 2a 01 7f a0 e9 9b dd ed .G.>.c..*....... > 13 07 4b 2c 46 8a 61 d0 ee 1d c6 82 60 b5 a9 90 ..K,F.a.....`... > 39 93 63 18 84 24 d2 06 51 26 93 91 2b c2 7c 52 9.c..$..Q&..+.|R > ea 3e 41 38 84 89 4d 41 bf 1a b7 4d 4f b0 fb a4 .>A8..MA...MO... > cc 86 26 c3 5b 84 e7 4e 97 33 be 9f 95 c6 ea 6d ..&.[..N.3.....m >> Event: Frame TX Status (0x3c) len 176 16.791308 > Wiphy: 0 (0x00000000) > Interface Index: 3 (0x00000003) > Wireless Device: 1 (0x0000000000000001) > Frame: len 128 > Frame Type: 0x00b0 > Type: Management (0) > Authentication: > Frame Control: protocol: 00 type: 00 subtype: 11 to: > 00 from: 00 more_frags: 00 > retry: 00 power_mgmt: 00 more_data: 00 protected: > 00 order: 00 > Duration: 0 > Address 1 (RA): D8:3A:DD:60:A3:0C > Address 2 (TA): B8:27:EB:A4:6E:0F > Address 3: D8:3A:DD:60:A3:0C > Fragment Number: 0 > Sequence Number: 0 > Algorithm: SAE (seq: 1, status: 0) > b0 00 00 00 d8 3a dd 60 a3 0c b8 27 eb a4 6e 0f .....:.`...'..n. > d8 3a dd 60 a3 0c 00 00 03 00 01 00 00 00 13 00 .:.`............ > f0 db cc 49 7c ad 4b 75 65 da 78 de 53 11 30 de ...I|.Kue.x.S.0. > fb 47 cf 3e 97 63 99 ff 2a 01 7f a0 e9 9b dd ed .G.>.c..*....... > 13 07 4b 2c 46 8a 61 d0 ee 1d c6 82 60 b5 a9 90 ..K,F.a.....`... > 39 93 63 18 84 24 d2 06 51 26 93 91 2b c2 7c 52 9.c..$..Q&..+.|R > ea 3e 41 38 84 89 4d 41 bf 1a b7 4d 4f b0 fb a4 .>A8..MA...MO... > cc 86 26 c3 5b 84 e7 4e 97 33 be 9f 95 c6 ea 6d ..&.[..N.3.....m > Cookie: 0 (0x0000000000000000) > ACK: true >> Result: Frame (0x3b) len 12 16.791335 > Cookie: 0 (0x0000000000000000) >> Response: Frame (0x3b) len 4 [0x100] 16.791346 > Status: Success (0) >> Event: Frame (0x3b) len 184 16.815917 > Wiphy: 0 (0x00000000) > Interface Index: 3 (0x00000003) > Wireless Device: 1 (0x0000000000000001) > Wiphy Frequency: 2412 (0x0000096c) > Unknown: 290 len 4 > 00 00 00 00 .... > Frame: len 128 > Frame Type: 0x00b0 > Type: Management (0) > Authentication: > Frame Control: protocol: 00 type: 00 subtype: 11 to: > 00 from: 00 more_frags: 00 > retry: 00 power_mgmt: 00 more_data: 00 protected: > 00 order: 00 > Duration: 0 > Address 1 (RA): B8:27:EB:A4:6E:0F > Address 2 (TA): D8:3A:DD:60:A3:0C > Address 3: 00:00:00:00:00:00 > Fragment Number: 0 > Sequence Number: 0 > Algorithm: SAE (seq: 1, status: 0) > b0 00 00 00 b8 27 eb a4 6e 0f d8 3a dd 60 a3 0c .....'..n..:.`.. > 00 00 00 00 00 00 00 00 03 00 01 00 00 00 13 00 ................ > 43 80 d8 95 59 df 2a 68 cd 1f 2f 93 27 21 89 e5 C...Y.*h../.'!.. > 2b 25 63 a4 33 8b 60 3a 2e 63 5e a8 f7 ba 40 f8 +%c.3.`:.c^...@. > 12 22 77 5c a1 9d bc 8b 07 1b 52 c1 ee 1b bc 9f ."w\......R..... > 9e 6c 67 c1 e7 b4 95 bf 07 a6 8a 87 6c dc 15 1d .lg.........l... > 80 71 2e df f1 c6 f2 98 be cb 58 bd 95 ac ce cb .q........X..... > fe a4 2a a0 82 78 b2 79 a0 c2 d4 cb ac 1b 2a 83 ..*..x.y......*. > RX Management Flags: 2 (0x00000002) > < Request: Frame (0x3b) len 76 [ack] 16.822238 > Interface Index: 3 (0x00000003) > Frame: len 64 > Frame Type: 0x00b0 > Type: Management (0) > Authentication: > Frame Control: protocol: 00 type: 00 subtype: 11 to: > 00 from: 00 more_frags: 00 > retry: 00 power_mgmt: 00 more_data: 00 protected: > 00 order: 00 > Duration: 0 > Address 1 (RA): D8:3A:DD:60:A3:0C > Address 2 (TA): B8:27:EB:A4:6E:0F > Address 3: D8:3A:DD:60:A3:0C > Fragment Number: 0 > Sequence Number: 0 > Algorithm: SAE (seq: 2, status: 0) > IEs: len 34 > Error decoding Supported rates IE len 0: Invalid > argument (-22) > b0 00 00 00 d8 3a dd 60 a3 0c b8 27 eb a4 6e 0f .....:.`...'..n. > d8 3a dd 60 a3 0c 00 00 03 00 02 00 00 00 01 00 .:.`............ > b4 69 71 a8 83 ee c4 c3 e1 5e c1 ef 5b 89 cc 18 .iq......^..[... > 6d 37 81 bb e0 9e 60 7b 6e 87 cb be 2b 60 af cf m7....`{n...+`.. >> Event: Frame TX Status (0x3c) len 112 16.828004 > Wiphy: 0 (0x00000000) > Interface Index: 3 (0x00000003) > Wireless Device: 1 (0x0000000000000001) > Frame: len 64 > Frame Type: 0x00b0 > Type: Management (0) > Authentication: > Frame Control: protocol: 00 type: 00 subtype: 11 to: > 00 from: 00 more_frags: 00 > retry: 00 power_mgmt: 00 more_data: 00 protected: > 00 order: 00 > Duration: 0 > Address 1 (RA): D8:3A:DD:60:A3:0C > Address 2 (TA): B8:27:EB:A4:6E:0F > Address 3: D8:3A:DD:60:A3:0C > Fragment Number: 0 > Sequence Number: 0 > Algorithm: SAE (seq: 2, status: 0) > IEs: len 34 > Error decoding Supported rates IE len 0: Invalid > argument (-22) > b0 00 00 00 d8 3a dd 60 a3 0c b8 27 eb a4 6e 0f .....:.`...'..n. > d8 3a dd 60 a3 0c 00 00 03 00 02 00 00 00 01 00 .:.`............ > b4 69 71 a8 83 ee c4 c3 e1 5e c1 ef 5b 89 cc 18 .iq......^..[... > 6d 37 81 bb e0 9e 60 7b 6e 87 cb be 2b 60 af cf m7....`{n...+`.. > Cookie: 0 (0x0000000000000000) > ACK: true >> Result: Frame (0x3b) len 12 16.828029 > Cookie: 0 (0x0000000000000000) >> Response: Frame (0x3b) len 4 [0x100] 16.828042 > Status: Success (0) >> Event: Frame (0x3b) len 120 16.839203 > Wiphy: 0 (0x00000000) > Interface Index: 3 (0x00000003) > Wireless Device: 1 (0x0000000000000001) > Wiphy Frequency: 2412 (0x0000096c) > Unknown: 290 len 4 > 00 00 00 00 .... > Frame: len 64 > Frame Type: 0x00b0 > Type: Management (0) > Authentication: > Frame Control: protocol: 00 type: 00 subtype: 11 to: > 00 from: 00 more_frags: 00 > retry: 00 power_mgmt: 00 more_data: 00 protected: > 00 order: 00 > Duration: 0 > Address 1 (RA): B8:27:EB:A4:6E:0F > Address 2 (TA): D8:3A:DD:60:A3:0C > Address 3: 00:00:00:00:00:00 > Fragment Number: 0 > Sequence Number: 0 > Algorithm: SAE (seq: 2, status: 0) > IEs: len 34 > Error decoding Supported rates IE len 0: Invalid > argument (-22) > b0 00 00 00 b8 27 eb a4 6e 0f d8 3a dd 60 a3 0c .....'..n..:.`.. > 00 00 00 00 00 00 00 00 03 00 02 00 00 00 01 00 ................ > f4 b4 13 37 c0 c2 ca 39 5f 0e ac 44 be d0 d0 04 ...7...9_..D.... > 40 3c 1f cb 94 f8 e2 aa b7 df 65 d5 6a 88 14 7e @<........e.j..~ > RX Management Flags: 2 (0x00000002) > < Request: External Auth (0x7f) len 40 [ack] 16.839539 > Interface Index: 3 (0x00000003) > Status Code: 0 (0x0000) > SSID: len 7 > 64 65 73 6b 53 41 45 deskSAE > BSSID D8:3A:DD:60:A3:0C >> Response: External Auth (0x7f) len 4 [0x100] 16.840308 > Status: Success (0) >> PAE: len 121 16.935734 > Interface Index: 3 > EAPoL: len 121 > Protocol Version: 2 (802.1X-2004) > Type: 3 (Key) > Length: 117 > Descriptor Type: 2 > Key MIC: false > Secure: false > Error: false > Request: false > Encrypted Key Data: false > SMK Message: false > Key Descriptor Version: 0 (00) > Key Type: true > Install: false > Key ACK: true > Key Length: 16 > Key Replay Counter: 1 > Key NONCE > 8c 7a ce cc 0e 1d 4f af 99 42 b6 b9 9c ce 17 e0 .z....O..B...... > ec bf a4 02 f3 36 70 cb 24 b3 3b 97 91 65 1c ed .....6p.$.;..e.. > Key IV > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Key RSC > 00 00 00 00 00 00 00 00 ........ > Key MIC Data > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > Key Data: len 22 > Vendor specific: len 20 > IEEE 802.11 (00:0f:ac) type: 04 > PMKID KDE > 00 0f ac 04 34 5c a4 df d6 8c 75 dd 32 f9 a8 71 > ....4\....u.2..q > 7a 32 ba c4 z2.. > 02 03 00 75 02 00 88 00 10 00 00 00 00 00 00 00 ...u............ > 01 8c 7a ce cc 0e 1d 4f af 99 42 b6 b9 9c ce 17 ..z....O..B..... > e0 ec bf a4 02 f3 36 70 cb 24 b3 3b 97 91 65 1c ......6p.$.;..e. > ed 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ > 00 00 16 dd 14 00 0f ac 04 34 5c a4 df d6 8c 75 .........4\....u > dd 32 f9 a8 71 7a 32 ba c4 .2..qz2.. >> Event: Connect (0x2e) len 156 17.000544 > Wiphy: 0 (0x00000000) > Interface Index: 3 (0x00000003) > MAC Address D8:3A:DD:60:A3:0C > Status Code: 0 (0x0000) > Request IE: len 80 > SSID: deskSAE > 64 65 73 6b 53 41 45 deskSAE > Supported rates: > 1.0(B) 2.0(B) 5.5(B) 11.0(B) 18.0 24.0 36.0 54.0 Mbit/s > 82 84 8b 96 24 30 48 6c ....$0Hl > Extended supported rates: > 6.0 9.0 12.0 48.0 Mbit/s > 0c 12 18 60 ...` > Tag 33: len 2 > 03 14 .. > Tag 36: len 2 > 01 0b .. > RSN: > Group Data Cipher Suite: len 4 > CCMP (00:0f:ac) suite 04 > Pairwise Cipher Suite: len 4 > CCMP (00:0f:ac) suite 04 > AKM Suite: len 4 > SAE/PMKSA caching SHA256; RSNA PMKSA caching > SHA256/mesh peering exchange (00:0f:ac) suite 08 > RSN capabilities: bits 2 - 3: 1 replay counter per PTKSA > RSN capabilities: bits 4 - 5: 1 replay counter per GTKSA > RSN capabilities: bit 7: Management Frame Protection Capable > 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................ > ac 08 80 00 .... > Extended Capabilities: len 8 > Capability: bit 62: Opmode Notification > 00 00 00 00 00 00 00 40 .......@ > Vendor specific: len 9 > Broadcom (00:10:18) type: 02 > 00 10 18 02 00 00 10 00 00 ......... > SSID: > SSID: > Response IE: len 32 > Supported rates: > 1.0(B) 2.0(B) 5.5(B) 11.0(B) 6.0 9.0 12.0 18.0 Mbit/s > 82 84 8b 96 0c 12 18 24 .......$ > Extended supported rates: > 24.0 36.0 48.0 54.0 Mbit/s > 30 48 60 6c 0H`l > Extended Capabilities: len 8 > Capability: bit 2: Extended channel switching > Capability: bit 62: Opmode Notification > 04 00 00 00 00 00 00 40 .......@ > > On Sat, Jan 18, 2025 at 9:52 AM James Prestwood <[email protected]> wrote: >> >> Hi Christian, >> >> On 1/17/25 10:03 PM, Christian Hewitt wrote: >>> Hello folks :) >>> >>> The Kodi focussed distro LibreELEC switched to iwd from >>> wpa_supplicant for our most recent release. It has been an >>> overall positive change, but we continue to see a trickle >>> of end-user reports of an “Invalid Key” error when devices >>> connect to a network. >>> >>> Things we’ve established: >>> >>> * Reverting to wpa_supplicant allows the device to connect >>> * Happens on a range of hardware so is not driver specific >>> * Happens on a range of kernels (tested back to 6.1) >>> * Poor signal strength shows the issue more frequently >>> * Networks with FT enabled show the issue more frequently >>> * Has nothing to do with passphrase length/characters >>> >>> TL/DR: We are reasonably confident the issue is within iwd >>> code and not drivers or kernels. We also use latest or very >>> recent kernels (and in-kernel drivers) and latest ConnMan >>> (we are generally ‘current’ with upstream sources throughout >>> the distro). We suspect a combination of radio properties >>> (influenced by poor signal and features) results in an error >>> which is not handled correctly so you end up in the wrong >>> place in code and trip the ‘Invalid Key’ error instead. >>> >>> Our project team are not able to replicate the issue with >>> our own devices and networks so we are currently reliant >>> on end-user reports. We also lack iwd debugging experience. >>> However, our embedded style distro packaging makes it very >>> simple for users to update and run an image tweaked with >>> iwd patches and/or config to get the output required to >>> triage the issue. >>> >>> So I’d like to understand what needs to be collected or >>> patched etc. to help start the process. >> >> For a start if you could gather debug logs when your users see the >> "Invalid key" message. Tbh I don't see anywhere IWD itself would print >> that, but ELL will signal that if some IWD settings file is using some >> invalid characters, that's about all I can think of at the moment >> without seeing debug logs. Our wiki [1] has some additional info about >> debugging. I'd even be happy to look at any of your locally tracked bug >> reports if there are any, otherwise just send some logs this way and >> we'll take a look. >> >> [1] https://archive.kernel.org/oldwiki/iwd.wiki.kernel.org/debugging.html >> >> Thanks, >> >> James >> >>> >>> Thanks in advance, >>> >>> Christian >>