From: James Prestwood <prestwoj@gmail.com>
To: Owen Garland <garland.owen@gmail.com>
Cc: iwd@lists.linux.dev
Subject: Re: Repeated Deauthentication event, reason: 4
Date: Mon, 6 Jan 2025 05:52:43 -0800 [thread overview]
Message-ID: <b606fe1b-5265-4a96-ac90-a80c1725abb3@gmail.com> (raw)
In-Reply-To: <CAPDaQ_z3GyLsQM86wDXa0UwN9n5p0T4sNmPvSUcgEfpAkqsKQw@mail.gmail.com>
Hi Owen,
On 1/4/25 1:17 AM, Owen Garland wrote:
> Hey, thanks for the quick response!
>
> I'm unsure that the signal strength is the issue, though I can't rule
> it out, as this issue has manifested itself since I've changed OS from
> Manjaro with NetworkManager to Arch with iwd, which has lead me to
> think it's a software issue.
That would make sense. My guess is some difference in the kernel version
or iwlwifi firmware version between Manjaro and Arch. To at least remove
IWD from the equation you could try wpa_supplicant with your current
Arch distro. If you see the same behavior this is likely some regression
with the kernel/iwlwifi.
>
> Here is the logs of the event with debug enabled:
>
> ~ λ journalctl -u iwd | grep -C 15 08:57:34
> Jan 04 08:57:33 titanium iwd[415831]: src/netdev.c:netdev_set_rekey_offload() 7
> Jan 04 08:57:33 titanium iwd[415831]:
> src/netdev.c:netdev_new_group_key_cb() ifindex: 7, err: 0
> Jan 04 08:57:33 titanium iwd[415831]:
> src/netdev.c:try_handshake_complete() ptk_installed: 0, gtk_installed:
> 1, igtk_installed: 1
> Jan 04 08:57:33 titanium iwd[415831]:
> src/netdev.c:netdev_mlme_notify() MLME notification Control Port TX
> Status(139)
> Jan 04 08:57:33 titanium iwd[415831]: src/netdev.c:netdev_set_station_cb()
> Jan 04 08:57:33 titanium iwd[415831]:
> src/netdev.c:try_handshake_complete() ptk_installed: 1, gtk_installed:
> 1, igtk_installed: 1
> Jan 04 08:57:33 titanium iwd[415831]:
> src/netdev.c:try_handshake_complete() nhs->complete: 0
> Jan 04 08:57:33 titanium iwd[415831]:
> src/netdev.c:try_handshake_complete() Invoking handshake_event()
> Jan 04 08:57:33 titanium iwd[415831]:
> src/handshake.c:handshake_state_cache_pmksa() (nil)
> Jan 04 08:57:33 titanium iwd[415831]: src/netdev.c:netdev_connect_ok()
> Jan 04 08:57:33 titanium iwd[415831]:
> src/station.c:station_connect_cb() 7, result: 0
> Jan 04 08:57:33 titanium iwd[415831]: src/station.c:station_connect_ok()
> Jan 04 08:57:33 titanium iwd[415831]: event: state, old: connecting
> (auto), new: connecting (netconfig)
> Jan 04 08:57:33 titanium iwd[415831]:
> src/wiphy.c:wiphy_radio_work_done() Work item 713 done
> Jan 04 08:57:33 titanium iwd[415831]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 7
> Jan 04 08:57:34 titanium iwd[415831]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 7
> Jan 04 08:57:34 titanium iwd[415831]:
> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
> Jan 04 08:57:34 titanium iwd[415831]:
> src/netdev.c:netdev_mlme_notify() MLME notification Deauthenticate(39)
> Jan 04 08:57:34 titanium iwd[415831]: src/netdev.c:netdev_deauthenticate_event()
> Jan 04 08:57:34 titanium iwd[415831]:
> src/netdev.c:netdev_mlme_notify() MLME notification Disconnect(48)
> Jan 04 08:57:34 titanium iwd[415831]: src/netdev.c:netdev_disconnect_event()
> Jan 04 08:57:34 titanium iwd[415831]: Received Deauthentication event,
> reason: 4, from_ap: false
> Jan 04 08:57:34 titanium iwd[415831]: src/station.c:station_disconnect_event() 7
> Jan 04 08:57:34 titanium iwd[415831]: event: disconnect-info, reason: 4
So we get this disconnect immediately after connecting. Was there any
kernel logs here? I'm expecting to see something from iwlwifi like
"connection lost". Unfortunately userspace has no control over this type
of disconnect. The kernel disconnected for some reason and is notifying
userspace. If you do see an improvement with wpa_supplicant using the
same kernel/firmware that would be odd, and would warrant a closer look
at IWD itself.
> Jan 04 08:57:34 titanium iwd[415831]: src/station.c:station_disassociated() 7
> Jan 04 08:57:34 titanium iwd[415831]:
> src/station.c:station_reset_connection_state() 7
> Jan 04 08:57:34 titanium iwd[415831]: src/station.c:station_roam_state_clear() 7
> Jan 04 08:57:34 titanium iwd[415831]: event: state, old: connecting
> (netconfig), new: disconnected
> Jan 04 08:57:34 titanium iwd[415831]: event: state, old: disconnected,
> new: autoconnect_quick
> Jan 04 08:57:34 titanium iwd[415831]:
> src/wiphy.c:wiphy_radio_work_insert() Inserting work item 714
> Jan 04 08:57:34 titanium iwd[415831]:
> src/wiphy.c:wiphy_radio_work_next() Starting work item 714
> Jan 04 08:57:34 titanium iwd[415831]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 7
> Jan 04 08:57:34 titanium iwd[415831]: src/scan.c:scan_notify() Scan
> notification Trigger Scan(33)
> Jan 04 08:57:34 titanium iwd[415831]:
> src/scan.c:scan_request_triggered() Active scan triggered for wdev 6
> Jan 04 08:57:34 titanium iwd[415831]:
> src/station.c:station_quick_scan_triggered() Quick scan triggered for
> wlan0
> Jan 04 08:57:35 titanium iwd[415831]: src/scan.c:scan_notify() Scan
> notification New Scan Results(34)
> Jan 04 08:57:35 titanium iwd[415831]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 7
> Jan 04 08:57:35 titanium iwd[415831]:
> src/station.c:station_print_scan_bss() Processing BSS
> '60:38:e0:3d:f0:b2' with SSID: Tronx_Lower, freq: 2447, rank: 177,
> strength: -7700, data_rate: 21.7, load: 24/255, clients: 1
> Jan 04 08:57:35 titanium iwd[415831]:
> src/station.c:station_print_scan_bss() Processing BSS
> 'c8:78:7d:e6:d3:53' with SSID: Tronx_Middle, freq: 2447, rank: 118,
> strength: -7800, data_rate: 14.4, load: 25/255, clients: 5
> Jan 04 08:57:35 titanium iwd[415831]:
> src/station.c:station_print_scan_bss() Processing BSS
> 'b0:38:29:18:14:0f' with SSID: Omni10_Setup_40F, freq: 2462, rank: 75,
> strength: -8300, data_rate: 11.0
> Jan 04 08:57:35 titanium iwd[415831]:
> src/station.c:station_print_scan_bss() Processing BSS
> '22:d2:cc:07:9c:b5' with SSID: Tronx_Upper, freq: 2422, rank: 75,
> strength: -8300, data_rate: 11.0
> Jan 04 08:57:35 titanium iwd[415831]: src/station.c:station_autoconnect_start()
> Jan 04 08:57:35 titanium iwd[415831]:
> src/station.c:station_autoconnect_next() autoconnect: Trying SSID:
> Tronx_Upper
> Jan 04 08:57:35 titanium iwd[415831]:
> src/station.c:station_autoconnect_next() autoconnect:
> '22:d2:cc:07:9c:b5' freq: 2422, rank: 75, strength: -8300
> Jan 04 08:57:35 titanium iwd[415831]: src/netdev.c:netdev_cqm_rssi_update()
> Jan 04 08:57:35 titanium iwd[415831]:
> src/wiphy.c:wiphy_radio_work_insert() Inserting work item 715
> Jan 04 08:57:35 titanium iwd[415831]: event: connect-info, ssid:
> Tronx_Upper, bss: 22:d2:cc:07:9c:b5, signal: -83, load: 0/255
> Jan 04 08:57:35 titanium iwd[415831]: event: state, old:
> autoconnect_quick, new: connecting (auto)
> Jan 04 08:57:35 titanium iwd[415831]: src/scan.c:scan_cancel() Trying
> to cancel scan id 714 for wdev 6
> Jan 04 08:57:35 titanium iwd[415831]:
> src/wiphy.c:wiphy_radio_work_done() Work item 714 done
>
> Let me know if you need to see anything else :)
>
> Thanks again!
>
> On Sat, Jan 4, 2025 at 12:25 AM James Prestwood <prestwoj@gmail.com> wrote:
>> Hi,
>>
>> On 1/3/25 2:16 PM, Owen Garland wrote:
>>> Hej all,
>>>
>>> I couldn't find an issue tracker so I am trying here. Essentially my
>>> problem is I get deauthenticated from AP's at seemingly random
>>> intervals, with `reason: 4`.
>>>
>>> iwd --version: 3.3
>>> OS: Arch-Linux 6.11.9-arch1-1
>>> Device: Dell XPS 9370
>>> Network controller: Intel Corporation Wireless 8265 / 8275 (rev 78)
>>> Subsystem: Intel Corporation Device 8050
>>> Kernel driver in use: iwlwifi
>>> Kernel modules: iwlwifi
>>> iwconfig:
>>> wlan0 IEEE 802.11 ESSID:"Tronx_Upper"
>>> Mode:Managed Frequency:2.422 GHz Access Point: 22:D2:CC:07:9C:B5
>>> Bit Rate=65 Mb/s Tx-Power=22 dBm
>>> Retry short limit:7 RTS thr:off Fragment thr:off
>>> Power Management:off
>>> Link Quality=31/70 Signal level=-79 dBm
>>> Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
>>> Tx excessive retries:209 Invalid misc:664 Missed beacon:0
>>>
>>> The logs from `journactl -u iwd` show this:
>>>
>>> Jan 03 21:52:09 titanium systemd[1]: Starting Wireless service...
>>> Jan 03 21:52:09 titanium iwd[318201]: Wireless daemon version 3.3
>>> Jan 03 21:52:09 titanium iwd[318201]: Loaded configuration from
>>> /etc/iwd/main.conf
>>> Jan 03 21:52:09 titanium systemd[1]: Started Wireless service.
>>> Jan 03 21:52:09 titanium iwd[318201]: Wiphy: 0, Name: phy0
>>> Jan 03 21:52:09 titanium iwd[318201]: Permanent Address:
>>> 64:5d:86:ed:80:5a
>>> Jan 03 21:52:09 titanium iwd[318201]: 2.4GHz Band:
>>> Jan 03 21:52:09 titanium iwd[318201]: Bitrates (non-HT):
>>> Jan 03 21:52:09 titanium iwd[318201]: 1.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 2.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 5.5 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 11.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 6.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 9.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 12.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 18.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 24.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 36.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 48.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 54.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: HT Capabilities:
>>> Jan 03 21:52:09 titanium iwd[318201]: HT40
>>> Jan 03 21:52:09 titanium iwd[318201]: Short GI for 20Mhz
>>> Jan 03 21:52:09 titanium iwd[318201]: Short GI for 40Mhz
>>> Jan 03 21:52:09 titanium iwd[318201]: HT RX MCS indexes:
>>> Jan 03 21:52:09 titanium iwd[318201]: 0-15
>>> Jan 03 21:52:09 titanium iwd[318201]: 5GHz Band:
>>> Jan 03 21:52:09 titanium iwd[318201]: Bitrates (non-HT):
>>> Jan 03 21:52:09 titanium iwd[318201]: 6.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 9.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 12.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 18.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 24.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 36.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 48.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: 54.0 Mbps
>>> Jan 03 21:52:09 titanium iwd[318201]: HT Capabilities:
>>> Jan 03 21:52:09 titanium iwd[318201]: HT40
>>> Jan 03 21:52:09 titanium iwd[318201]: Short GI for 20Mhz
>>> Jan 03 21:52:09 titanium iwd[318201]: Short GI for 40Mhz
>>> Jan 03 21:52:09 titanium iwd[318201]: HT RX MCS indexes:
>>> Jan 03 21:52:09 titanium iwd[318201]: 0-15
>>> Jan 03 21:52:09 titanium iwd[318201]: VHT Capabilities:
>>> Jan 03 21:52:09 titanium iwd[318201]: Short GI for 80Mhz
>>> Jan 03 21:52:09 titanium iwd[318201]: Max RX
>>> MCS: 0-9 for NSS: 2
>>> Jan 03 21:52:09 titanium iwd[318201]: Max TX
>>> MCS: 0-9 for NSS: 2
>>> Jan 03 21:52:09 titanium iwd[318201]: Ciphers: BIP-CMAC-128
>>> CCMP-128 TKIP
>>> Jan 03 21:52:09 titanium iwd[318201]: Supported iftypes:
>>> ad-hoc station ap p2p-client p2p-go p2p-device
>>> Jan 03 21:52:09 titanium iwd[318201]: event: state, old: disconnected,
>>> new: autoconnect_quick
>>> Jan 03 21:52:09 titanium iwd[318201]: udev interface=wlan0 ifindex=6
>>> Jan 03 21:52:10 titanium iwd[318201]: event: connect-info, ssid:
>>> Tronx_Upper, bss: 22:d2:cc:07:9c:b5, signal: -79, load: 0/255
>>> Jan 03 21:52:10 titanium iwd[318201]: event: state, old:
>>> autoconnect_quick, new: connecting (auto)
>>> Jan 03 21:52:10 titanium iwd[318201]: event: state, old: connecting
>>> (auto), new: connecting (netconfig)
>>> Jan 03 21:52:10 titanium iwd[318201]: event: state, old: connecting
>>> (netconfig), new: connected
>>> Jan 03 21:52:15 titanium iwd[318201]: event: roam-scan,
>>> <truncated>
>>> Jan 03 22:41:53 titanium iwd[318201]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Jan 03 22:41:53 titanium iwd[318201]: event: disconnect-info, reason: 4
>>> Jan 03 22:41:53 titanium iwd[318201]: event: state, old: connected,
>>> new: disconnected
>>> Jan 03 22:41:53 titanium iwd[318201]: event: state, old: disconnected,
>>> new: autoconnect_quick
>>> Jan 03 22:41:54 titanium iwd[318201]: event: state, old:
>>> autoconnect_quick, new: autoconnect_full
>>> Jan 03 22:42:13 titanium iwd[318201]: event: connect-info, ssid:
>>> Tronx_Upper, bss: 22:d2:cc:07:9c:b5, signal: -79, load: 0/255
>>> Jan 03 22:42:13 titanium iwd[318201]: event: state, old:
>>> autoconnect_full, new: connecting (auto)
>>> Jan 03 22:42:17 titanium iwd[318201]: event: state, old: connecting
>>> (auto), new: connecting (netconfig)
>>> Jan 03 22:42:18 titanium iwd[318201]: event: state, old: connecting
>>> (netconfig), new: connected
>>>
>>> This then appears to happen several times, and at seemingly random
>>> intervals. It can be fine for several hours, then there is one
>>> disconnect, or there may be a few disconnects in a short time. As an
>>> example the 28th had this:
>>>
>>> Dec 28 15:40:49 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 15:41:12 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 16:02:27 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 16:13:12 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 16:13:27 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 16:34:55 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 17:02:41 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 17:11:34 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 17:16:38 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 17:20:27 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 17:25:01 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 18:52:40 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 20:21:20 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 20:21:28 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 20:21:46 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>>> Dec 28 21:07:33 titanium iwd[869]: Received Deauthentication event,
>>> reason: 4, from_ap: false
>> Were there any additional kernel/IWD logs at those time? Its probably
>> best to enable IWD debugging with the "-d" flag.
>>
>> This reason code is "Disassociated due to inactivity" and a local
>> disconnect, which we see in our deployments as well. Is your device
>> operating in low RSSI conditions? I see when you connected the RSSI was
>> -79 which is at or at least very quickly approaching unusable connection
>> quality. I suspect this i
>>
>>> My investigations haven't led to much, not having a publicly viewable
>>> issue tracker is certainly not helping. I have found a few other
>>> threads where people have had this issue, however none of the proposed
>>> remedies have made an impact. The one thing I did try was disabling
>>> powersaving by adding this to my config:
>>>
>>> ~ λ cat /etc/modprobe.d/iwlwifi.conf
>>> options iwlmvm power_scheme=1
>>> options iwlwifi power_save=0
>>>
>>> Any suggestions on where to take this, and let me know if I can
>>> provide you with any further information.
>>>
>>> Thanks for making open source software <3
>>>
next prev parent reply other threads:[~2025-01-06 13:52 UTC|newest]
Thread overview: 6+ messages / expand[flat|nested] mbox.gz Atom feed top
2025-01-03 22:16 Repeated Deauthentication event, reason: 4 Owen Garland
2025-01-03 23:25 ` James Prestwood
2025-01-04 9:17 ` Owen Garland
2025-01-06 13:52 ` James Prestwood [this message]
2025-01-06 14:19 ` Owen Garland
2025-01-06 14:32 ` James Prestwood
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=b606fe1b-5265-4a96-ac90-a80c1725abb3@gmail.com \
--to=prestwoj@gmail.com \
--cc=garland.owen@gmail.com \
--cc=iwd@lists.linux.dev \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox