[SOLVED] New "reason 16" disconnects on linux 5.9.1

Brocellous · 2020-10-21 20:01:26

Since updating to linux 5.9.1 I get regular Wi-Fi disconnects. I am using iwd and systemd-networkd.

The update from 5.8.14 ->5.9.1

[2020-10-17T13:10:48-0600] [PACMAN] Running 'pacman -Syu'
[2020-10-17T13:10:48-0600] [PACMAN] synchronizing package lists
[2020-10-17T13:10:52-0600] [PACMAN] starting full system upgrade
[2020-10-17T13:11:12-0600] [ALPM] running '60-mkinitcpio-remove.hook'...
[2020-10-17T13:11:12-0600] [ALPM] transaction started
[2020-10-17T13:11:12-0600] [ALPM] upgraded alsa-topology-conf (1.2.3-1 -> 1.2.4-1)
[2020-10-17T13:11:12-0600] [ALPM] upgraded alsa-ucm-conf (1.2.3-2 -> 1.2.4-1)
[2020-10-17T13:11:13-0600] [ALPM] upgraded alsa-lib (1.2.3.2-1 -> 1.2.4-1)
[2020-10-17T13:11:13-0600] [ALPM] upgraded alsa-utils (1.2.3-2 -> 1.2.4-1)
[2020-10-17T13:11:13-0600] [ALPM] upgraded linux (5.8.14.arch1-1 -> 5.9.1.arch1-1)
[2020-10-17T13:11:13-0600] [ALPM] upgraded bbswitch (0.8-354 -> 0.8-356)
[2020-10-17T13:11:14-0600] [ALPM] upgraded linux-docs (5.8.14.arch1-1 -> 5.9.1.arch1-1)
[2020-10-17T13:11:16-0600] [ALPM] upgraded linux-headers (5.8.14.arch1-1 -> 5.9.1.arch1-1)
[2020-10-17T13:11:16-0600] [ALPM] upgraded nvidia (455.28-4 -> 455.28-7)
[2020-10-17T13:11:17-0600] [ALPM] transaction completed
[2020-10-17T13:11:17-0600] [ALPM] running '20-paccache.hook'...
[2020-10-17T13:11:17-0600] [ALPM] running '30-systemd-daemon-reload.hook'...
[2020-10-17T13:11:18-0600] [ALPM] running '30-systemd-udev-reload.hook'...
[2020-10-17T13:11:18-0600] [ALPM] running '30-systemd-update.hook'...
[2020-10-17T13:11:18-0600] [ALPM] running '60-depmod.hook'...
[2020-10-17T13:11:24-0600] [ALPM] running '90-mkinitcpio-install.hook'...

My wireless device:

$ lspci -kd::280
02:00.0 Network controller: Intel Corporation Wireless 8265 / 8275 (rev 78)
	Subsystem: Intel Corporation Dual Band Wireless-AC 8265
	Kernel driver in use: iwlwifi
	Kernel modules: iwlwifi

Here is some logging from the last boot on 5.8.14:

$ journalctl -b fc8edd00fee7483eb2ff503a929235fd _KERNEL_DEVICE=+pci:$(lspci -Dd::280 | cut -d ' ' -f1) + _SYSTEMD_UNIT=iwd.service
-- Logs begin at Wed 2020-02-26 10:16:38 MST, end at Wed 2020-10-21 12:10:53 MST. --
Oct 17 12:12:01 archlinux kernel: pci 0000:02:00.0: [8086:24fd] type 00 class 0x028000
Oct 17 12:12:01 archlinux kernel: pci 0000:02:00.0: reg 0x10: [mem 0xedc00000-0xedc01fff 64bit]
Oct 17 12:12:01 archlinux kernel: pci 0000:02:00.0: PME# supported from D0 D3hot D3cold
Oct 17 12:12:03 rxps kernel: iwlwifi 0000:02:00.0: enabling device (0000 -> 0002)
Oct 17 12:12:03 rxps kernel: iwlwifi 0000:02:00.0: Found debug destination: EXTERNAL_DRAM
Oct 17 12:12:03 rxps kernel: iwlwifi 0000:02:00.0: Found debug configuration: 0
Oct 17 12:12:03 rxps kernel: iwlwifi 0000:02:00.0: loaded firmware version 36.79ff3ccf.0 8265-36.ucode op_mode iwlmvm
Oct 17 12:12:03 rxps iwd[332]: Wireless daemon version 1.9
Oct 17 12:12:03 rxps iwd[332]: station: Network configuration is disabled.
Oct 17 12:12:03 rxps kernel: iwlwifi 0000:02:00.0: Detected Intel(R) Dual Band Wireless AC 8265, REV=0x230
Oct 17 12:12:03 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 17 12:12:03 rxps kernel: iwlwifi 0000:02:00.0: Allocated 0x00400000 bytes for firmware monitor.
Oct 17 12:12:04 rxps kernel: iwlwifi 0000:02:00.0: base HW address: cc:2f:71:cd:ca:94
Oct 17 12:12:04 rxps iwd[332]: Received a NEW_INTERFACE for a wiphy id that isn't tracked.  This is most ikely a kernel bug where NEW_WIPHY events that are too large are dropped on the floor.  Attempting a workaround...
Oct 17 12:12:04 rxps iwd[332]: Wiphy: 0, Name: phy0
Oct 17 12:12:04 rxps iwd[332]:         Permanent Address: cc:2f:71:cd:ca:94
Oct 17 12:12:04 rxps iwd[332]:         Bands: 2.4 GHz 5 GHz
Oct 17 12:12:04 rxps iwd[332]:         Ciphers: CCMP TKIP BIP
Oct 17 12:12:04 rxps iwd[332]:         Supported iftypes: ad-hoc station ap p2p-client p2p-go p2p-device
Oct 17 12:12:04 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 17 12:12:04 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 17 12:12:04 rxps kernel: iwlwifi 0000:02:00.0: FW already configured (0) - re-configuring
Oct 17 17:00:02 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 17 17:00:02 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 17 17:00:02 rxps kernel: iwlwifi 0000:02:00.0: FW already configured (0) - re-configuring
Oct 17 17:00:02 rxps iwd[332]: Received Deauthentication event, reason: 3, from_ap: false
Oct 17 17:45:00 rxps iwd[332]: Received Deauthentication event, reason: 4, from_ap: false
Oct 17 18:22:59 rxps iwd[332]: Received Deauthentication event, reason: 4, from_ap: false
Oct 17 18:29:48 rxps iwd[332]: Received Deauthentication event, reason: 4, from_ap: false
Oct 17 18:44:48 rxps iwd[332]: Received Deauthentication event, reason: 4, from_ap: false
Oct 17 19:42:42 rxps iwd[332]: Received Deauthentication event, reason: 4, from_ap: false
Oct 17 19:52:33 rxps iwd[332]: Received Deauthentication event, reason: 2, from_ap: true
Oct 17 22:47:40 rxps iwd[332]: D-Bus disconnected, quitting...
Oct 17 22:47:40 rxps iwd[332]: Removing scan context for wdev 2
Oct 17 22:47:40 rxps iwd[332]: Terminate
Oct 17 22:47:41 rxps iwd[332]: Removing scan context for wdev 3

and the first boot on 5.9.1:

$ journalctl -b 450119f1ba684dd0b0cb48dad4472322 _KERNEL_DEVICE=+pci:$(lspci -Dd::280 | cut -d ' ' -f1) + _SYSTEMD_UNIT=iwd.service
-- Logs begin at Wed 2020-02-26 10:16:38 MST, end at Wed 2020-10-21 12:10:53 MST. --
Oct 18 20:13:39 archlinux kernel: pci 0000:02:00.0: [8086:24fd] type 00 class 0x028000
Oct 18 20:13:39 archlinux kernel: pci 0000:02:00.0: reg 0x10: [mem 0xedc00000-0xedc01fff 64bit]
Oct 18 20:13:39 archlinux kernel: pci 0000:02:00.0: PME# supported from D0 D3hot D3cold
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: enabling device (0000 -> 0002)
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: Found debug destination: EXTERNAL_DRAM
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: Found debug configuration: 0
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: loaded firmware version 36.79ff3ccf.0 8265-36.ucode op_mode iwlmvm
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: Detected Intel(R) Dual Band Wireless AC 8265, REV=0x230
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: Allocated 0x00400000 bytes for firmware monitor.
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: base HW address: cc:2f:71:cd:ca:94
Oct 18 20:13:42 rxps iwd[344]: Wireless daemon version 1.9
Oct 18 20:13:42 rxps iwd[344]: station: Network configuration is disabled.
Oct 18 20:13:42 rxps iwd[344]: Received a NEW_INTERFACE for a wiphy id that isn't tracked.  This is most ikely a kernel bug where NEW_WIPHY events that are too large are dropped on the floor.  Attempting a workaround...
Oct 18 20:13:42 rxps iwd[344]: Wiphy: 0, Name: phy0
Oct 18 20:13:42 rxps iwd[344]:         Permanent Address: cc:2f:71:cd:ca:94
Oct 18 20:13:42 rxps iwd[344]:         Bands: 2.4 GHz 5 GHz
Oct 18 20:13:42 rxps iwd[344]:         Ciphers: CCMP TKIP BIP
Oct 18 20:13:42 rxps iwd[344]:         Supported iftypes: ad-hoc station ap p2p-client p2p-go p2p-device
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: Applying debug destination EXTERNAL_DRAM
Oct 18 20:13:42 rxps kernel: iwlwifi 0000:02:00.0: FW already configured (0) - re-configuring
Oct 18 20:30:39 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 18 21:12:20 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 18 21:30:12 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 18 22:11:24 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 18 22:29:24 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 18 23:11:08 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 18 23:29:08 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 00:10:49 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 00:28:52 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 01:10:33 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 01:28:35 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 02:10:14 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 02:28:19 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 03:09:58 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 03:27:44 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 04:08:46 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 04:26:47 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 05:08:28 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 05:26:33 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 06:08:10 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 06:26:14 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 07:07:49 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 07:25:53 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 07:26:34 rxps iwd[344]: Received Deauthentication event, reason: 4, from_ap: false
Oct 19 08:07:33 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 08:25:38 rxps iwd[344]: Received Deauthentication event, reason: 16, from_ap: true
Oct 19 08:53:01 rxps iwd[344]: D-Bus disconnected, quitting...
Oct 19 08:53:01 rxps iwd[344]: Removing scan context for wdev 2
Oct 19 08:53:01 rxps iwd[344]: Terminate
Oct 19 08:53:02 rxps iwd[344]: Removing scan context for wdev 3

You can see that

Received Deauthentication event, reason: 16, from_ap: true

is suddenly very common.

According to 802-11, Reason Code 16 represents "Group key handshake timeout". Looking at my logs, the NEW_INTERFACE warning from iwd is consistent, and first appears in my first boot of kernel 5.8.1 (w/ iwd 1.8) and never with 5.7.x and below, so I'm not sure it's relevant. It never has any trouble reconnecting, but the disconnects are constant. I get 2 d/c per hour at a regular cadence, every boot since upgrading to 5.9.1. My network has not otherwise changed, I haven't observed these disconnects on other devices, and searching my journal shows I've only gotten a "reason 16" disconnect once before in my recorded journal logs sometime last July. I use this laptop every day.

Is anyone else having this issue with 5.9.1?

Last edited by Brocellous (2020-10-22 01:08:04)

Zod · 2020-10-21 20:27:11

Is it happening while connected to one or more then one routers?

Edit to clarify: Have you been able to test this on more then one router?

And, just to get it out of the way, if it's only one router, have you rebooted the router and tested?

Last edited by Zod (2020-10-21 20:35:15)

Brocellous · 2020-10-21 21:33:23

Only one router. The uptime on my router is a few weeks, so I'll try rebooting it.

EDIT: Still happens

Last edited by Brocellous (2020-10-21 22:36:45)

Zod · 2020-10-21 23:36:17

I've not seen anything that relates to "reason: 16" beyond what you noted.

But I did find something that would seem to be related.

The short version is add this to /etc/iwd/main.conf

[General]
 ControlPortOverNL80211=False

and restart the IWD service.

The longer version is here..
https://lkml.org/lkml/2020/10/14/1101

Last edited by Zod (2020-10-21 23:36:58)

Brocellous · 2020-10-22 01:07:42

Excellent find! I've run this configuration for over an hour now and no disconnects. Solved!

Hopefully the kernel patch will be applied soon as well!

Brocellous · 2020-11-07 02:33:25

The kernel patch was applied in 5.9.4.arch1!

Arch Linux

#1 2020-10-21 20:01:26

[SOLVED] New "reason 16" disconnects on linux 5.9.1

#2 2020-10-21 20:27:11

Re: [SOLVED] New "reason 16" disconnects on linux 5.9.1

#3 2020-10-21 21:33:23

Re: [SOLVED] New "reason 16" disconnects on linux 5.9.1

#4 2020-10-21 23:36:17

Re: [SOLVED] New "reason 16" disconnects on linux 5.9.1

#5 2020-10-22 01:07:42

Re: [SOLVED] New "reason 16" disconnects on linux 5.9.1

#6 2020-11-07 02:33:25

Re: [SOLVED] New "reason 16" disconnects on linux 5.9.1

Board footer