Re: rtw89_8852ce + iwd stuck in (dis-)connect/-auth loop

James Prestwood <prestwoj@xxxxxxxxx> · Thu, 14 Nov 2024 05:05:39 -0800

Hi Philipp,

On 11/14/24 1:04 AM, Philipp Matthias Hahn wrote:
Hello,

I finally switched from `wpa_supplicant` to `iwd` after having regular
issues with connectivity issues, so the following problem is probably
not related to `iwd` at all.

APs:
- FRITZ!Box 7490 one
   - 34:31:C4:27:99:ED (2.4 GHz)
   - 34:31:C4:27:99:EE (5 Ghz)
- FRITZ!Box 7490 two
   - E8:DF:70:4A:46:AB (2.4 GHz)
   - E8:DF:70:4A:46:AC (5 GHz)
- FRITZ!Powerline 1260E
   - F0:B0:14:88:AC:43 (2.4 GHz)
   - F0:B0:14:88:AC:47 (5 GHz)
- FRITZ!Powerline 540E
   - 5C:49:79:E1:C5:94 (2.4 GHz)

Debian-12-Buster
iwd original: 2.3, now: 3.1 self-compiled
Linux 6.10.11
04:00.0 Ethernet controller [0200]: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller [10ec:8168] (rev 15)
         Subsystem: Hewlett-Packard Company RTL8111/8168/8211/8411 PCI Express Gigabit Ethernet Controller [103c:8b7c]
         Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx+
         Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
         Latency: 0, Cache Line Size: 64 bytes
         Interrupt: pin A routed to IRQ 19
         IOMMU group: 16
         Region 0: I/O ports at 3000 [size=256]
         Region 2: Memory at 80804000 (64-bit, non-prefetchable) [size=4K]
         Region 4: Memory at 80800000 (64-bit, non-prefetchable) [size=16K]
         Capabilities: <access denied>
         Kernel driver in use: r8169
         Kernel modules: r8169

After a suspend (to RAM) overnight the connection cannot be
re-established and `iwd` is stuck in a re-connect/-auth loop:
Maybe someone more familiar with this driver specifically can comment, 
but historically on the mailing list I have seen a number of issues 
surrounding suspend/resume with wifi drivers.

Nov 14 09:11:35 phahn iwd[179340]: event: state, old: disconnected, new: autoconnect_quick
Nov 14 09:11:36 phahn iwd[179340]: udev interface=wlan0 ifindex=14
Nov 14 09:11:36 phahn iwd[179340]: event: connect-info, ssid: WBP4a Hahn +491702827535, bss: 34:31:c4:27:99:ee, signal: -78, load: 1/255
Nov 14 09:11:36 phahn iwd[179340]: event: state, old: autoconnect_quick, new: connecting (auto)
Nov 14 09:11:37 phahn iwd[179340]: event: state, old: connecting (auto), new: connected
Nov 14 09:11:46 phahn iwd[179340]: Received Deauthentication event, reason: 4, from_ap: false
Nov 14 09:11:46 phahn iwd[179340]: event: disconnect-info, reason: 4
Nov 14 09:11:46 phahn iwd[179340]: event: state, old: connected, new: disconnected
Nov 14 09:11:46 phahn iwd[179340]: event: state, old: disconnected, new: autoconnect_quick
Nov 14 09:11:47 phahn iwd[179340]: event: connect-info, ssid: WBP4a Hahn +491702827535, bss: f0:b0:14:88:ac:43, signal: -62, load: 23/255
Nov 14 09:11:47 phahn iwd[179340]: event: state, old: autoconnect_quick, new: connecting (auto)
Nov 14 09:11:47 phahn iwd[179340]: event: state, old: connecting (auto), new: connected
Nov 14 09:11:50 phahn iwd[179340]: Received Deauthentication event, reason: 4, from_ap: false
Nov 14 09:11:50 phahn iwd[179340]: event: disconnect-info, reason: 4
Nov 14 09:11:50 phahn iwd[179340]: event: state, old: connected, new: disconnected
Nov 14 09:11:50 phahn iwd[179340]: event: state, old: disconnected, new: autoconnect_quick
Nov 14 09:11:51 phahn iwd[179340]: event: connect-info, ssid: WBP4a Hahn +491702827535, bss: f0:b0:14:88:ac:43, signal: -56, load: 34/255
Nov 14 09:11:51 phahn iwd[179340]: event: state, old: autoconnect_quick, new: connecting (auto)
Nov 14 09:11:51 phahn iwd[179340]: event: state, old: connecting (auto), new: connected
Nov 14 09:11:56 phahn iwd[179340]: Received Deauthentication event, reason: 4, from_ap: false
Nov 14 09:11:56 phahn iwd[179340]: event: disconnect-info, reason: 4
Nov 14 09:11:56 phahn iwd[179340]: event: state, old: connected, new: disconnected
Nov 14 09:11:56 phahn iwd[179340]: event: state, old: disconnected, new: autoconnect_quick
Nov 14 09:11:57 phahn iwd[179340]: event: connect-info, ssid: WBP4a Hahn +491702827535, bss: 5c:49:79:e1:c5:94, signal: -61, load: 27/255
Nov 14 09:11:57 phahn iwd[179340]: event: state, old: autoconnect_quick, new: connecting (auto)
Nov 14 09:11:57 phahn iwd[179340]: event: state, old: connecting (auto), new: connected
Nov 14 09:12:03 phahn iwd[179340]: Received Deauthentication event, reason: 4, from_ap: false
Nov 14 09:12:03 phahn iwd[179340]: event: disconnect-info, reason: 4
Nov 14 09:12:03 phahn iwd[179340]: event: state, old: connected, new: disconnected
Nov 14 09:12:03 phahn iwd[179340]: event: state, old: disconnected, new: autoconnect_quick
Nov 14 09:12:04 phahn iwd[179340]: event: connect-info, ssid: WBP4a Hahn +491702827535, bss: f0:b0:14:88:ac:43, signal: -57, load: 33/255
Nov 14 09:12:04 phahn iwd[179340]: event: state, old: autoconnect_quick, new: connecting (auto)
Nov 14 09:12:04 phahn iwd[179340]: event: state, old: connecting (auto), new: connected
Nov 14 09:12:07 phahn iwd[179340]: Received Deauthentication event, reason: 4, from_ap: false
Nov 14 09:12:07 phahn iwd[179340]: event: disconnect-info, reason: 4
Nov 14 09:12:07 phahn iwd[179340]: event: state, old: connected, new: disconnected
Nov 14 09:12:07 phahn iwd[179340]: event: state, old: disconnected, new: autoconnect_quick
Nov 14 09:12:08 phahn iwd[179340]: event: connect-info, ssid: WBP4a Hahn +491702827535, bss: f0:b0:14:88:ac:43, signal: -55, load: 40/255
Nov 14 09:12:08 phahn iwd[179340]: event: state, old: autoconnect_quick, new: connecting (auto)
Nov 14 09:12:08 phahn iwd[179340]: event: state, old: connecting (auto), new: connected
Nov 14 09:12:16 phahn iwd[179340]: event: state, old: connected, new: disconnecting
Nov 14 09:12:16 phahn iwd[179340]: event: state, old: disconnecting, new: disconnected

Here's the dump of the kernel log:

[87572.028075] wlan0: authenticate with 34:31:c4:27:99:ee (local address=40:1a:58:f6:ca:6f)
[87572.028079] wlan0: send auth to 34:31:c4:27:99:ee (try 1/3)
[87572.031085] wlan0: authenticated
[87572.036527] wlan0: associate with 34:31:c4:27:99:ee (try 1/3)
[87572.039534] wlan0: RX AssocResp from 34:31:c4:27:99:ee (capab=0x1511 status=0 aid=2)
[87572.158153] wlan0: associated
[87572.158264] wlan0: Limiting TX power to 20 (23 - 3) dBm as advertised by 34:31:c4:27:99:ee
[87581.686018] wlan0: Connection to AP 34:31:c4:27:99:ee lost
[87582.508317] wlan0: authenticate with f0:b0:14:88:ac:43 (local address=40:1a:58:f6:ca:6f)
[87582.508323] wlan0: send auth to f0:b0:14:88:ac:43 (try 1/3)
[87582.517681] wlan0: authenticated
[87582.524152] wlan0: associate with f0:b0:14:88:ac:43 (try 1/3)
[87582.530272] wlan0: RX AssocResp from f0:b0:14:88:ac:43 (capab=0x1431 status=0 aid=7)
[87582.646537] wlan0: associated
[87582.646704] wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by f0:b0:14:88:ac:43
[87585.790526] wlan0: Connection to AP f0:b0:14:88:ac:43 lost
[87586.681575] wlan0: authenticate with f0:b0:14:88:ac:43 (local address=40:1a:58:f6:ca:6f)
[87586.681579] wlan0: send auth to f0:b0:14:88:ac:43 (try 1/3)
[87586.684607] wlan0: authenticated
[87586.685919] wlan0: associate with f0:b0:14:88:ac:43 (try 1/3)
[87586.691733] wlan0: RX AssocResp from f0:b0:14:88:ac:43 (capab=0x1431 status=0 aid=7)
[87586.806412] wlan0: associated
[87586.811404] wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by f0:b0:14:88:ac:43
[87591.935894] wlan0: Connection to AP f0:b0:14:88:ac:43 lost
[87592.828319] wlan0: authenticate with 5c:49:79:e1:c5:94 (local address=40:1a:58:f6:ca:6f)
[87592.828324] wlan0: send auth to 5c:49:79:e1:c5:94 (try 1/3)
[87592.831876] wlan0: authenticated
[87592.834046] wlan0: associate with 5c:49:79:e1:c5:94 (try 1/3)
[87592.844654] wlan0: RX AssocResp from 5c:49:79:e1:c5:94 (capab=0x1431 status=0 aid=1)
[87592.962487] wlan0: associated
[87592.962615] wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by 5c:49:79:e1:c5:94
[87598.534139] wlan0: Connection to AP 5c:49:79:e1:c5:94 lost
[87599.413011] wlan0: authenticate with f0:b0:14:88:ac:43 (local address=40:1a:58:f6:ca:6f)
[87599.413015] wlan0: send auth to f0:b0:14:88:ac:43 (try 1/3)
[87599.416010] wlan0: authenticated
[87599.418127] wlan0: associate with f0:b0:14:88:ac:43 (try 1/3)
[87599.428534] wlan0: RX AssocResp from f0:b0:14:88:ac:43 (capab=0x1431 status=0 aid=7)
[87599.542784] wlan0: associated
[87599.542912] wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by f0:b0:14:88:ac:43
[87603.006507] wlan0: Connection to AP f0:b0:14:88:ac:43 lost
[87603.894465] wlan0: authenticate with f0:b0:14:88:ac:43 (local address=40:1a:58:f6:ca:6f)
[87603.894470] wlan0: send auth to f0:b0:14:88:ac:43 (try 1/3)
[87603.897501] wlan0: authenticated
[87603.902232] wlan0: associate with f0:b0:14:88:ac:43 (try 1/3)
[87603.909625] wlan0: RX AssocResp from f0:b0:14:88:ac:43 (capab=0x1431 status=0 aid=7)
[87604.022839] wlan0: associated
[87604.022904] wlan0: Limiting TX power to 20 (20 - 0) dBm as advertised by f0:b0:14:88:ac:43
[87611.261845] wlan0: deauthenticating from f0:b0:14:88:ac:43 by local choice (Reason: 3=DEAUTH_LEAVING)

I have seen that "Limiting TX power to …" before with `wpa_supplicant`,
which also lead to a disconnect there, which triggered me to try `iwd`
now.

Last time unloading `rtw89_8852ce` and re-loading it did get it, but
only after switching Wifi off and on again in NetworkManager.
Seems like a driver issue to me. As you said, I suspect you would see 
the exact same behavior with wpa_supplicant as you see here.

If you need more data, just tell we what you need.

I'm not afraid of compiling my own Linux kernel if that is needed.
I already switched from the regular Debian-12-Buster-Kernel 6.1.115 to
Debian's backports kernel 6.11 as the original kernel did not have the
`rtw89_8852ce` driver; I tried <https://github.com/lwfinger/rtw89> back
then, but did not get it working properly, which prompted me to switch
to the bpo kernel, which was easier.

PS: I'm not subscribed to to both `iwd` and `linux-wireless` lists.

Thanks in advance
Philipp Hahn