* How to triage an "Invalid Key" error message? @ 2025-01-18 6:03 Christian Hewitt 2025-01-18 15:52 ` James Prestwood 0 siblings, 1 reply; 7+ messages in thread From: Christian Hewitt @ 2025-01-18 6:03 UTC (permalink / raw) To: iwd 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. Thanks in advance, Christian ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: How to triage an "Invalid Key" error message? 2025-01-18 6:03 How to triage an "Invalid Key" error message? Christian Hewitt @ 2025-01-18 15:52 ` James Prestwood 2025-01-18 16:38 ` KeithG 0 siblings, 1 reply; 7+ messages in thread From: James Prestwood @ 2025-01-18 15:52 UTC (permalink / raw) To: Christian Hewitt, iwd 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: How to triage an "Invalid Key" error message? 2025-01-18 15:52 ` James Prestwood @ 2025-01-18 16:38 ` KeithG 2025-01-20 15:36 ` Christian Hewitt 0 siblings, 1 reply; 7+ messages in thread From: KeithG @ 2025-01-18 16:38 UTC (permalink / raw) To: James Prestwood; +Cc: Christian Hewitt, iwd Christian, Is this, perhaps, on devices with the brcmfmac chip? I have seen this recently with on my Pis with wpa2 and wpa3 APs. 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 <prestwoj@gmail.com> 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 > ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: How to triage an "Invalid Key" error message? 2025-01-18 16:38 ` KeithG @ 2025-01-20 15:36 ` Christian Hewitt 2025-01-21 13:50 ` James Prestwood 0 siblings, 1 reply; 7+ messages in thread From: Christian Hewitt @ 2025-01-20 15:36 UTC (permalink / raw) To: KeithG; +Cc: James Prestwood, iwd > On 18 Jan 2025, at 8:38 pm, KeithG <ys3al35l@gmail.com> 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 <prestwoj@gmail.com> 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 >> ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: How to triage an "Invalid Key" error message? 2025-01-20 15:36 ` Christian Hewitt @ 2025-01-21 13:50 ` James Prestwood 2025-01-21 14:24 ` Christian Hewitt 0 siblings, 1 reply; 7+ messages in thread From: James Prestwood @ 2025-01-21 13:50 UTC (permalink / raw) To: Christian Hewitt, KeithG; +Cc: iwd Hi Christian, On 1/20/25 7:36 AM, Christian Hewitt wrote: >> On 18 Jan 2025, at 8:38 pm, KeithG <ys3al35l@gmail.com> 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 This one actually has some iwmon logs. Looks like the kernel is sending a failure within ~100ms of the connection which is odd. IWD waits for a successful connect event before starting the 4-way handshake so its not even getting to that point: < Request: Connect (0x2e) len 172 [ack] 5.644853 ... > Event: Connect (0x2e) len 36 5.735838 Wiphy: 0 (0x00000000) Interface Index: 3 (0x00000003) MAC Address 00:00:00:00:00:00 Status Code: 16 (0x0010) There is also a core dump attached, but the back trace isn't of much use. > https://github.com/LibreELEC/LibreELEC.tv/issues/8731 This issue _appears_ as if wpa_supplicant is also running along side IWD. That is generally why you see this log: Mar 16 21:10:35 pineh64-b iwd[1046]: Unexpected connection related event -- is another supplicant running? > https://github.com/LibreELEC/LibreELEC.tv/issues/8760 This seems the same as #7166. > https://github.com/LibreELEC/LibreELEC.tv/issues/8762 Not a whole lot in here, but apparently resolved. > > 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 > So overall the "invalid-key" issue seems to be due to brcmfmac signalling a failure very early on. In a perfect world it would be great if we could capture debug/iwmon logs of both IWD trying to connect and wpa_supplicant, so we can compare the iwmon logs and see what each supplicant is sending to the kernel. The messages _looked_ ok from IWD but if wpa_supplicant works fine there is obviously a difference somewhere. As Keith knows, brcmfmac is kinda a pain to support as its the odd-ball as far as drivers go. IWD doesn't get much contributions from wifi vendors so any odd quirks only get solved by trial and error. Thanks, James ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: How to triage an "Invalid Key" error message? 2025-01-21 13:50 ` James Prestwood @ 2025-01-21 14:24 ` Christian Hewitt 2025-01-21 14:36 ` James Prestwood 0 siblings, 1 reply; 7+ messages in thread From: Christian Hewitt @ 2025-01-21 14:24 UTC (permalink / raw) To: James Prestwood; +Cc: KeithG, iwd > On 21 Jan 2025, at 5:50 pm, James Prestwood <prestwoj@gmail.com> wrote: > > Hi Christian, > > On 1/20/25 7:36 AM, Christian Hewitt wrote: >>> On 18 Jan 2025, at 8:38 pm, KeithG <ys3al35l@gmail.com> 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 > > This one actually has some iwmon logs. Looks like the kernel is sending a failure within ~100ms of the connection which is odd. IWD waits for a successful connect event before starting the 4-way handshake so its not even getting to that point: > > < Request: Connect (0x2e) len 172 [ack] 5.644853 > ... > > Event: Connect (0x2e) len 36 5.735838 > Wiphy: 0 (0x00000000) > Interface Index: 3 (0x00000003) > MAC Address 00:00:00:00:00:00 > Status Code: 16 (0x0010) > > There is also a core dump attached, but the back trace isn't of much use. > >> https://github.com/LibreELEC/LibreELEC.tv/issues/8731 > > This issue _appears_ as if wpa_supplicant is also running along side IWD. That is generally why you see this log: > > Mar 16 21:10:35 pineh64-b iwd[1046]: Unexpected connection related event -- is another supplicant running? 100% guaranteed wpa is not installed at the same time. LibreELEC has embedded style packaging with a read-only filesystem and no package manager. The iwd/wpa selection is baked into the image at distro image creation time and can’t be changed afterwards. >> https://github.com/LibreELEC/LibreELEC.tv/issues/8760 > This seems the same as #7166. >> https://github.com/LibreELEC/LibreELEC.tv/issues/8762 > Not a whole lot in here, but apparently resolved. >> >> 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 >> > So overall the "invalid-key" issue seems to be due to brcmfmac signalling a failure very early on. In a perfect world it would be great if we could capture debug/iwmon logs of both IWD trying to connect and wpa_supplicant, so we can compare the iwmon logs and see what each supplicant is sending to the kernel. The messages _looked_ ok from IWD but if wpa_supplicant works fine there is obviously a difference somewhere. As Keith knows, brcmfmac is kinda a pain to support as its the odd-ball as far as drivers go. IWD doesn't get much contributions from wifi vendors so any odd quirks only get solved by trial and error. It’s been seen on other chips too, but if it’s timing related it could simply be that brcmfmac trips the issue more frequently and that plus distro demographics skews the volume of reports. I’ll prepare some end-user debug instructions around debug/iwmon and then attempt to recruit some affected users in a GitHub thread. Let’s see where things take us. Thx :) Christian ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: How to triage an "Invalid Key" error message? 2025-01-21 14:24 ` Christian Hewitt @ 2025-01-21 14:36 ` James Prestwood 0 siblings, 0 replies; 7+ messages in thread From: James Prestwood @ 2025-01-21 14:36 UTC (permalink / raw) To: Christian Hewitt; +Cc: KeithG, iwd Hi Christian, On 1/21/25 6:24 AM, Christian Hewitt wrote: >> On 21 Jan 2025, at 5:50 pm, James Prestwood <prestwoj@gmail.com> wrote: >> >> Hi Christian, >> >> On 1/20/25 7:36 AM, Christian Hewitt wrote: >>>> On 18 Jan 2025, at 8:38 pm, KeithG <ys3al35l@gmail.com> 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 >> This one actually has some iwmon logs. Looks like the kernel is sending a failure within ~100ms of the connection which is odd. IWD waits for a successful connect event before starting the 4-way handshake so its not even getting to that point: >> >> < Request: Connect (0x2e) len 172 [ack] 5.644853 >> ... >>> Event: Connect (0x2e) len 36 5.735838 >> Wiphy: 0 (0x00000000) >> Interface Index: 3 (0x00000003) >> MAC Address 00:00:00:00:00:00 >> Status Code: 16 (0x0010) >> >> There is also a core dump attached, but the back trace isn't of much use. >> >>> https://github.com/LibreELEC/LibreELEC.tv/issues/8731 >> This issue _appears_ as if wpa_supplicant is also running along side IWD. That is generally why you see this log: >> >> Mar 16 21:10:35 pineh64-b iwd[1046]: Unexpected connection related event -- is another supplicant running? > 100% guaranteed wpa is not installed at the same time. LibreELEC has embedded style packaging with a read-only filesystem and no package manager. The iwd/wpa selection is baked into the image at distro image creation time and can’t be changed afterwards. Ok, this must be some unforeseen interaction/bug between IWD and brcmfmac. Debug logs will help here for sure. > >>> https://github.com/LibreELEC/LibreELEC.tv/issues/8760 >> This seems the same as #7166. >>> https://github.com/LibreELEC/LibreELEC.tv/issues/8762 >> Not a whole lot in here, but apparently resolved. >>> 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 >>> >> So overall the "invalid-key" issue seems to be due to brcmfmac signalling a failure very early on. In a perfect world it would be great if we could capture debug/iwmon logs of both IWD trying to connect and wpa_supplicant, so we can compare the iwmon logs and see what each supplicant is sending to the kernel. The messages _looked_ ok from IWD but if wpa_supplicant works fine there is obviously a difference somewhere. As Keith knows, brcmfmac is kinda a pain to support as its the odd-ball as far as drivers go. IWD doesn't get much contributions from wifi vendors so any odd quirks only get solved by trial and error. > It’s been seen on other chips too, but if it’s timing related it could simply be that brcmfmac trips the issue more frequently and that plus distro demographics skews the volume of reports. > > I’ll prepare some end-user debug instructions around debug/iwmon and then attempt to recruit some affected users in a GitHub thread. Let’s see where things take us. Thx :) Thanks, lets see what comes of that. - James > > Christian > ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2025-01-21 14:36 UTC | newest] Thread overview: 7+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2025-01-18 6:03 How to triage an "Invalid Key" error message? Christian Hewitt 2025-01-18 15:52 ` James Prestwood 2025-01-18 16:38 ` KeithG 2025-01-20 15:36 ` Christian Hewitt 2025-01-21 13:50 ` James Prestwood 2025-01-21 14:24 ` Christian Hewitt 2025-01-21 14:36 ` James Prestwood
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox