Re: Repeated Deauthentication event, reason: 4

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.

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
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 <[email protected]> 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
> >