Description of problem: I have been using iwd with NetworkManager for a while, mostly to test this new technology and also because in some networks it has faster connection/DHCP than wpa_supplicant. However, for a few months now I got several network interruptions a day. The visible symptom is that wifi goes down, VPN gets torn down with it, and after a few seconds NM re-attempts connecting to my wifi (which usually succeeds). Interruption of video meetings and VPN disconnect are pretty annoying.

At first I suspected some problems with my ISP/router (as I had had some problems with that), but when I looked closer I noticed some journal messages that go along with it:


iwd[739]: Received Deauthentication event, reason: 4, from_ap: false
NetworkManager[737]: <info>  [1610089396.2520] device (wlan0): new IWD device state is disconnected
NetworkManager[737]: <info>  [1610089396.2523] device (wlan0): state change: activated -> failed (reason 'supplicant-disconnect', sys-iface-state: 'managed')
nm-openvpn[1634]: SIGTERM received, sending exit notification to peer
NetworkManager[737]: <warn>  [1610089396.2624] device (wlan0): Activation: failed for connection 'pittinet'
NetworkManager[737]: <info>  [1610089396.2635] manager: NetworkManager state is now CONNECTED_LOCAL
systemd[1]: Starting Network Manager Script Dispatcher Service...
NetworkManager[737]: <info>  [1610089396.2643] vpn-connection[0x557097d12150,5777c2b4-defc-46f1-9858-2b850d51587c,"Brno (BRQ)",0]: VPN plugin: state changed: stopping (5)
NetworkManager[737]: <info>  [1610089396.2657] vpn-connection[0x557097d12150,5777c2b4-defc-46f1-9858-2b850d51587c,"Brno (BRQ)",0]: VPN plugin: state changed: stopped (6)
NetworkManager[737]: <info>  [1610089396.2674] device (tun0): state change: activated -> unmanaged (reason 'connection-assumed', sys-iface-state: 'external')
NetworkManager[737]: <info>  [1610089396.2723] device (wlan0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
systemd[1]: Started Network Manager Script Dispatcher Service.
audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
kernel: audit: type=1130 audit(1610089396.278:262): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
NetworkManager[737]: <info>  [1610089396.2834] dhcp4 (wlan0): canceled DHCP transaction
NetworkManager[737]: <info>  [1610089396.2834] dhcp4 (wlan0): state changed bound -> done
NetworkManager[737]: <info>  [1610089396.2837] dhcp6 (wlan0): canceled DHCP transaction
NetworkManager[737]: <info>  [1610089396.2838] dhcp6 (wlan0): state changed bound -> done
NetworkManager[737]: <info>  [1610089396.2870] policy: auto-activating connection 'pittinet' (fffbd631-2b73-48d7-8a56-ab99cdf546bc)
NetworkManager[737]: <info>  [1610089396.2896] device (wlan0): Activation: starting connection 'pittinet' (fffbd631-2b73-48d7-8a56-ab99cdf546bc)
NetworkManager[737]: <info>  [1610089396.2899] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
NetworkManager[737]: <info>  [1610089396.2904] manager: NetworkManager state is now CONNECTING
NetworkManager[737]: <info>  [1610089396.2910] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
NetworkManager[737]: <info>  [1610089396.3374] device (wlan0): new IWD device state is connecting
nm-openvpn[1634]: write UDP: Network is unreachable (code=101)
kernel: wlan0: authenticate with 44:fe:3b:fb:9d:fe
kernel: wlan0: send auth to 44:fe:3b:fb:9d:fe (try 1/3)
kernel: wlan0: authenticated
kernel: wlan0: associate with 44:fe:3b:fb:9d:fe (try 1/3)
kernel: wlan0: RX AssocResp from 44:fe:3b:fb:9d:fe (capab=0x1411 status=0 aid=2)
kernel: wlan0: associated
kernel: wlan0: Limiting TX power to 23 (23 - 0) dBm as advertised by 44:fe:3b:fb:9d:fe
kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
NetworkManager[737]: <info>  [1610089398.7288] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful.  Connected to 'pittinet'.
NetworkManager[737]: <info>  [1610089398.7295] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
NetworkManager[737]: <info>  [1610089398.7300] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
NetworkManager[737]: <info>  [1610089398.7312] device (wlan0): new IWD device state is connected


My journal goes back to Nov 11, and these "Received Deauthentication event" messages have happened semi-regularly since then. There have been days where everything worked from turning my laptop on in the morning until powering it off in the evening:

Dez 01 05:57:55 donald systemd[1]: Starting Wireless service...
Dez 01 05:57:55 donald iwd[729]: Wireless daemon version 1.9
Dez 01 05:57:55 donald iwd[729]: station: Network configuration is disabled.
Dez 01 05:57:55 donald systemd[1]: Started Wireless service.
Dez 01 05:57:55 donald iwd[729]: Wiphy: 0, Name: phy0
Dez 01 05:57:55 donald iwd[729]:         Permanent Address: a4:4e:31:84:8d:2c
Dez 01 05:57:55 donald iwd[729]:         Bands: 2.4 GHz 5 GHz
Dez 01 05:57:55 donald iwd[729]:         Ciphers: CCMP TKIP
Dez 01 05:57:55 donald iwd[729]:         Supported iftypes: ad-hoc station ap
Dez 01 19:39:23 donald iwd[729]: Terminate
Dez 01 19:39:23 donald iwd[729]: Removing scan context for wdev 2
Dez 01 19:39:23 donald systemd[1]: Stopping Wireless service...
Dez 01 19:39:24 donald iwd[729]: D-Bus disconnected, quitting...
Dez 01 19:39:24 donald systemd[1]: iwd.service: Succeeded.
Dez 01 19:39:24 donald systemd[1]: Stopped Wireless service.

but on most days I get two or three of these interruptions:

Dez 07 05:46:13 donald systemd[1]: Started Wireless service.
Dez 07 11:26:26 donald iwd[732]: Received Deauthentication event, reason: 4, from_ap: false
Dez 07 13:59:22 donald iwd[732]: Received Deauthentication event, reason: 4, from_ap: false

A few days ago it was a *really* bad day:

Jan 04 06:10:09 donald systemd[1]: Starting Wireless service...
Jan 04 09:30:30 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 09:38:25 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 12:01:28 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 12:17:21 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 12:51:31 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 12:53:11 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 12:57:46 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 12:58:11 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 12:59:01 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:02:04 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:02:17 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:03:06 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:03:31 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:10:13 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:16:04 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:16:54 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:17:19 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:21:04 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:21:29 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:21:54 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:22:19 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:23:09 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 20:24:49 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 21:13:17 donald iwd[737]: Received Deauthentication event, reason: 4, from_ap: false
Jan 04 21:13:22 donald iwd[737]: authentication timed out
Jan 04 21:13:44 donald iwd[737]: authentication timed out

This is when I started to look into this more closely.

I switched back to wpasupplicant for comparison, and have now had two complete days without a single interruption. So it seems wpasupplicant handles these events more transparently, without affecting the logical connection? I get several groups of messages like

wpa_supplicant[844]: wlp3s0: WPA: Group rekeying completed with 44:fe:3b:fb:9d:fe [GTK=CCMP]
wpa_supplicant[844]: wlp3s0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-66 noise=9999 txrate=120000
wpa_supplicant[844]: wlp3s0: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-58 noise=9999 txrate=90000

over the day, but there is no log from NM, nor any user-visible interruption of the network connection.



Version-Release number of selected component (if applicable):

iwd-1.10-1.fc33.x86_64
NetworkManager-wifi-1.26.4-1.fc33.x86_64

How reproducible: Occasionally