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

Summary: wifi connection interrupted several times a day: Received Deauthentication event, reason: 4, from_ap: false
Product: [Fedora] Fedora Reporter: Martin Pitt <mpitt>
Component: iwdAssignee: Lubomir Rintel <lkundrak>
Status: CLOSED EOL QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 33CC: lkundrak
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-11-30 17:52:33 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

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 ?

Comment 2 Ben Cotton 2021-11-04 16:10:25 UTC
This message is a reminder that Fedora 33 is nearing its end of life.
Fedora will stop maintaining and issuing updates for Fedora 33 on 2021-11-30.
It is Fedora's policy to close all bug reports from releases that are no longer
maintained. At that time this bug will be closed as EOL if it remains open with a
Fedora 'version' of '33'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 33 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 3 Ben Cotton 2021-11-30 17:52:33 UTC
Fedora 33 changed to end-of-life (EOL) status on 2021-11-30. Fedora 33 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.