Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1915641 - wifi connection interrupted several times a day: Received Deauthentication event, reason: 4, from_ap: false
Summary: wifi connection interrupted several times a day: Received Deauthentication ev...
Keywords:
Status: NEW
Alias: None
Product: Fedora
Classification: Fedora
Component: iwd
Version: 33
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Lubomir Rintel
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-01-13 06:03 UTC by Martin Pitt
Modified: 2021-02-01 10:39 UTC (History)
1 user (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:
Type: Bug
Embargoed:

Attachments (Terms of Use)

Description Martin Pitt 2021-01-13 06:03:11 UTC 
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
Comment 1 Martin Pitt 2021-02-01 10:39:31 UTC 
This may be the same as NetworkManager bug 1861919 ?
Note You need to log in before you can comment on or make changes to this bug.