[SOLVED] Deauthentication by local choice with iwd & connman

Nimlot · 2021-08-17 17:13:20

I set up iwd with connman based on this guide in the Arch Wiki. Recently, the WiFi disconnects at seemingly random intervals. Whenever it does, I see this in my dmesg output:

[20169.242505] wlan0: deauthenticating from **:**:**:**:**:** by local choice (Reason: 3=DEAUTH_LEAVING)

I can generally reconnect immediately (but manually) in connmanctl.

From searching online, I suspect the problem is that I have two different processes (iwd and ???) competing to manage the network connection. I uninstalled wpa_supplicant, but that did not fix the problem.

Any help is much appreciated!

Last edited by Nimlot (2021-09-04 22:35:01)

seth · 2021-08-17 22:05:13

find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f

Nimlot · 2021-08-20 18:12:27

acpid.service                            | multi-user.target.wants
autorandr.service                        | sleep.target.wants
bluetooth.service                        | bluetooth.target.wants
bumblebeed.service                       | graphical.target.wants
connman_iwd.service                      | multi-user.target.wants
dbus-org.bluez.service                   | system
dirmngr.socket                           | sockets.target.wants
display-manager.service                  | system
getty@tty1.service                       | getty.target.wants
getty@tty2.service                       | getty.target.wants
gpg-agent-browser.socket                 | sockets.target.wants
gpg-agent-extra.socket                   | sockets.target.wants
gpg-agent.socket                         | sockets.target.wants
gpg-agent-ssh.socket                     | sockets.target.wants
logid.service                            | multi-user.target.wants
ntpd.service                             | multi-user.target.wants
p11-kit-server.socket                    | sockets.target.wants
pipewire.socket                          | sockets.target.wants
pulseaudio.socket                        | sockets.target.wants
remote-fs.target                         | multi-user.target.wants
tlp.service                              | multi-user.target.wants
xdg-user-dirs-update.service             | default.target.wants

I don't see anything that stands out as likely to compete with connman/iwd.

Last edited by Nimlot (2021-08-20 18:13:06)

seth · 2021-08-20 21:26:26

Nope. Please chck/post the system journal.
Notably look for interface errors, possibly in relation w/ TLP.

You can, but technically do not have to obfuscate the AP MAC (it's not a secret, your AP is yelling it into the world)

Nimlot · 2021-08-24 18:53:26

Aug 24 11:48:52 zen iwd[74521]: wiphy_estimate_data_rate() failed
Aug 24 11:50:32 zen iwd[74521]: wiphy_estimate_data_rate() failed
Aug 24 11:50:49 zen connmand[76679]: wlan0 {RX} 1949655 packets 1344728803 bytes
Aug 24 11:50:49 zen connmand[76679]: wlan0 {TX} 2101293 packets 1387259845 bytes
Aug 24 11:50:49 zen connmand[76679]: wlan0 {update} flags 4099 <UP>
Aug 24 11:50:49 zen connman-vpnd[494]: wlan0 {update} flags 4099 <UP>
Aug 24 11:50:49 zen connman-vpnd[494]: wlan0 {newlink} index 14 address 5C:E0:C5:93:6F:34 mtu 1500
Aug 24 11:50:49 zen connman-vpnd[494]: wlan0 {newlink} index 14 operstate 2 <DOWN>
Aug 24 11:50:49 zen kernel: wlan0: deauthenticating from 3c:36:e4:69:f5:00 by local choice (Reason: 3=DEAUTH_LEAVING)
Aug 24 11:50:49 zen connmand[76679]: wlan0 {newlink} index 14 address 5C:E0:C5:93:6F:34 mtu 1500
Aug 24 11:50:49 zen connmand[76679]: wlan0 {newlink} index 14 operstate 2 <DOWN>
Aug 24 11:50:50 zen connmand[76679]: wlan0 {del} address 192.168.1.66/24 label wlan0
Aug 24 11:50:50 zen connmand[76679]: wlan0 {del} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
Aug 24 11:50:50 zen connmand[76679]: wlan0 {del} address 2600:1700:e1c0:c420::3d/64 label (null)
Aug 24 11:50:50 zen connmand[76679]: wlan0 {del} route 2600:1700:e1c0:c420:: gw :: scope 0 <UNIVERSE>
Aug 24 11:50:50 zen connmand[76679]: wlan0 {del} route fe80:: gw :: scope 0 <UNIVERSE>
Aug 24 11:50:50 zen connmand[76679]: wlan0 {del} address 2600:1700:e1c0:c420:5ee0:c5ff:fe93:6f34/64 label (null)
Aug 24 11:50:51 zen ntpd[439]: Deleting interface #276 wlan0, fe80::5ee0:c5ff:fe93:6f34%14#123, interface stats: received=0, sent=0, dropped=0, active_time=260 secs
Aug 24 11:50:51 zen ntpd[439]: Deleting interface #278 wlan0, 2600:1700:e1c0:c420:5ee0:c5ff:fe93:6f34#123, interface stats: received=2, sent=2, dropped=0, active_time=258 secs
Aug 24 11:50:51 zen ntpd[439]: 2600:3c00::2:b401 local addr 2600:1700:e1c0:c420:5ee0:c5ff:fe93:6f34 -> <null>
Aug 24 11:50:51 zen ntpd[439]: Deleting interface #279 wlan0, 192.168.1.66#123, interface stats: received=6, sent=6, dropped=0, active_time=255 secs
Aug 24 11:50:51 zen ntpd[439]: 50.205.57.38 local addr 192.168.1.66 -> <null>
Aug 24 11:50:51 zen ntpd[439]: 47.190.36.235 local addr 192.168.1.66 -> <null>
Aug 24 11:50:51 zen ntpd[439]: 91.217.155.60 local addr 192.168.1.66 -> <null>
Aug 24 11:50:51 zen ntpd[439]: Deleting interface #280 wlan0, 2600:1700:e1c0:c420::3d#123, interface stats: received=0, sent=0, dropped=0, active_time=255 secs
Aug 24 11:51:21 zen iwd[74521]: wiphy_estimate_data_rate() failed
Aug 24 11:52:11 zen iwd[74521]: wiphy_estimate_data_rate() failed
Aug 24 11:52:11 zen iwd[74521]: authentication timed out
Aug 24 11:52:11 zen iwd[74521]: authentication timed out
Aug 24 11:52:12 zen iwd[74521]: authentication timed out
Aug 24 11:52:12 zen iwd[74521]: authentication timed out
Aug 24 11:52:13 zen iwd[74521]: authentication timed out
Aug 24 11:52:13 zen kernel: wlan0: authenticate with 04:18:d6:4f:67:e3
Aug 24 11:52:13 zen kernel: wlan0: send auth to 04:18:d6:4f:67:e3 (try 1/3)
Aug 24 11:52:13 zen kernel: wlan0: send auth to 04:18:d6:4f:67:e3 (try 2/3)
Aug 24 11:52:13 zen kernel: wlan0: send auth to 04:18:d6:4f:67:e3 (try 3/3)
Aug 24 11:52:13 zen kernel: wlan0: authentication with 04:18:d6:4f:67:e3 timed out
Aug 24 11:52:13 zen iwd[74521]: authentication timed out
Aug 24 11:52:14 zen iwd[74521]: authentication timed out
Aug 24 11:52:14 zen iwd[74521]: authentication timed out

seth · 2021-08-24 20:42:20

So there's a VPN, that goes down and then the NIC does. Also this happens within a second of bringing the NIC up.
=> Does this happen w/o the VPN?

Nimlot · 2021-08-25 16:09:47

It happens even with the connman-vpn service stopped. Likewise with ntpd.

Here's the journal from when both were stopped (I manually made connman reconnect each time it disconnected):

Aug 25 09:04:35 zen kernel: wlan0: authenticate with 3c:36:e4:69:f5:00
Aug 25 09:04:35 zen kernel: wlan0: send auth to 3c:36:e4:69:f5:00 (try 1/3)
Aug 25 09:04:35 zen kernel: wlan0: authenticated
Aug 25 09:04:35 zen kernel: wlan0: associate with 3c:36:e4:69:f5:00 (try 1/3)
Aug 25 09:04:35 zen kernel: wlan0: RX AssocResp from 3c:36:e4:69:f5:00 (capab=0x1411 status=0 aid=3)
Aug 25 09:04:35 zen connmand[341]: wlan0 {RX} 388116 packets 412402315 bytes
Aug 25 09:04:35 zen connmand[341]: wlan0 {TX} 168188 packets 45380718 bytes
Aug 25 09:04:35 zen connmand[341]: wlan0 {update} flags 69635 <UP,LOWER_UP>
Aug 25 09:04:35 zen connmand[341]: wlan0 {newlink} index 3 address 5C:E0:C5:93:6F:34 mtu 1500
Aug 25 09:04:35 zen connmand[341]: wlan0 {newlink} index 3 operstate 5 <DORMANT>
Aug 25 09:04:35 zen kernel: wlan0: associated
Aug 25 09:04:35 zen connmand[341]: wlan0 {add} route fe80:: gw :: scope 0 <UNIVERSE>
Aug 25 09:04:35 zen connmand[341]: wlan0 {RX} 388118 packets 412402619 bytes
Aug 25 09:04:35 zen connmand[341]: wlan0 {TX} 168190 packets 45381006 bytes
Aug 25 09:04:35 zen connmand[341]: wlan0 {update} flags 69699 <UP,RUNNING,LOWER_UP>
Aug 25 09:04:35 zen connmand[341]: wlan0 {newlink} index 3 address 5C:E0:C5:93:6F:34 mtu 1500
Aug 25 09:04:35 zen connmand[341]: wlan0 {newlink} index 3 operstate 6 <UP>
Aug 25 09:04:35 zen kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Aug 25 09:04:40 zen connmand[341]: wlan0 {add} route 2600:1700:e1c0:c420:: gw :: scope 0 <UNIVERSE>
Aug 25 09:04:41 zen connmand[341]: wlan0 {add} address 2600:1700:e1c0:c420:5ee0:c5ff:fe93:6f34/64 label (null) family 10
Aug 25 09:04:42 zen connmand[341]: wlan0 {add} address 192.168.1.66/24 label wlan0 family 2
Aug 25 09:04:42 zen connmand[341]: wlan0 {add} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
Aug 25 09:04:42 zen connmand[341]: wlan0 {add} route 192.168.1.254 gw 0.0.0.0 scope 253 <LINK>
Aug 25 09:04:42 zen connmand[341]: wlan0 {add} route 0.0.0.0 gw 192.168.1.254 scope 0 <UNIVERSE>
Aug 25 09:04:42 zen geoclue[1458]: Failed to query location: Error resolving “location.services.mozilla.com”: Name or service not known
Aug 25 09:04:42 zen connmand[341]: wlan0 {add} route 82.165.8.211 gw 192.168.1.254 scope 0 <UNIVERSE>
Aug 25 09:04:43 zen connmand[341]: wlan0 {add} address 2600:1700:e1c0:c420::39/64 label (null) family 10

Probably coincidental, but it seems to disconnect more often in the morning or when Zoom is running.

Also just confirming that I've checked my router for problems; none of my other devices disconnect (and my current workaround is to tether my phone).

Last edited by Nimlot (2021-08-25 16:13:56)

seth · 2021-08-25 16:15:42

The journal segment does not indicate any kind of network issues, beyond

Aug 25 09:04:42 zen geoclue[1458]: Failed to query location: Error resolving “location.services.mozilla.com”: Name or service not known

which could be down to DNS. Notably there's no deauth.

Can you ping "8.8.8.8" when it breaks away?
Also please paste a complete journal from a boot where this happened (sudo journalctl -b, you can use the tip in the first link below to pipe it into ix.io) for context.

Nimlot · 2021-08-25 22:30:06

Here's a complete journal, with a disconnect event happening at 15:23: http://ix.io/3wXU

Pinging 8.8.8.8 while disconnected gives me:

ping: connect: Network is unreachable

seth · 2021-08-26 06:50:03

Aug 25 15:21:59 zen systemd-sleep[2575]: Entering sleep state 'suspend'...
…
Aug 25 15:22:09 zen kernel: wlan0: deauthenticating from 3c:36:e4:69:f5:00 by local choice (Reason: 3=DEAUTH_LEAVING)
…
Aug 25 15:22:09 zen iwd[368]: Received Deauthentication event, reason: 3, from_ap: false

This is normal.

Aug 25 15:22:09 zen kernel: ACPI: Waking up from system sleep state S3
…
Aug 25 15:22:09 zen systemd-sleep[2575]: System returned from sleep state.
Aug 25 15:22:09 zen kernel: wlan0: authenticate with 3c:36:e4:69:f5:00
Aug 25 15:22:09 zen kernel: PM: suspend exit
…
Aug 25 15:22:09 zen kernel: wlan0: associated
…
Aug 25 15:22:09 zen systemd[1]: Stopped target Suspend.
Aug 25 15:22:09 zen systemd-logind[377]: Operation 'sleep' finished.
…
Aug 25 15:22:18 zen ntpd[420]: new interface(s) found: waking up resolver
…
Aug 25 15:23:22 zen connmand[369]: wlan0 {update} flags 4099 <UP>
Aug 25 15:23:22 zen kernel: wlan0: deauthenticating from 3c:36:e4:69:f5:00 by local choice (Reason: 3=DEAUTH_LEAVING)
Aug 25 15:23:22 zen connmand[369]: wlan0 {newlink} index 3 address 5C:E0:C5:93:6F:34 mtu 1500
Aug 25 15:23:22 zen connmand[369]: wlan0 {newlink} index 3 operstate 2 <DOWN>

This is fishy.

So you sleep S3 and resume *immediately* (is that an intentional sleep cycle?) and ~1m later disconnect from the network.
My guess would be that the insta-wake S3 is causing this and my guess is also that this isn't an intended S3?

Nimlot · 2021-08-26 17:32:12

I deliberately had the machine sleep and then woke it, in case the disconnect problem was only happening after a sleep.

Last edited by Nimlot (2021-08-26 17:33:17)

seth · 2021-08-27 06:29:27

From the context:
2.4GHz connection?
Could be bluetooth interference, in particular "Logitech Wireless Mouse MX Master 3" (do you have a wired rodent for testing?)
Also check the rfkill state when you disconnect (maybe the wifi gets accidentally blocked)

Nimlot · 2021-09-04 22:34:34

So I updated my system and also removed some nearby access points from connman that shouldn't be registered, and now the connection seems to be stable.

Thanks for all the help anyways!

Last edited by Nimlot (2021-09-04 22:35:18)

nbd · 2021-09-04 23:03:07

Didn't you notice this? :

Aug 25 15:22:09 zen audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Aug 25 15:22:09 zen iwd[368]: Received Deauthentication event, reason: 3, from_ap: false

Seems like rfkill resets your connection when started within systemd service.

seth · 2021-09-06 22:20:45

He's suspending the system a this point - neither systemd-rfkill nor deauth are unexpected at *this* point.

man systemd-rfkill wrote:

DESCRIPTION
systemd-rfkill.service is a service that restores the RF kill switch state at early boot and saves it on each change. On disk, the RF kill switch state is stored in /var/lib/systemd/rfkill/.

Aug 25 15:22:09 zen systemd-logind[377]: Operation 'sleep' finished.

He's leaving S3

Aug 25 15:22:14 zen systemd[1]: systemd-rfkill.service: Deactivated successfully.
Aug 25 15:22:14 zen audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Aug 25 15:22:14 zen kernel: audit: type=1131 audit(1629930134.443:117): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

systemd-rfkill restores the state

Aug 25 15:22:16 zen connmand[369]: wlan0 {add} address 192.168.1.66/24 label wlan0 family 2
Aug 25 15:22:16 zen connmand[369]: wlan0 {add} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
Aug 25 15:22:16 zen connmand[369]: wlan0 {add} route 192.168.1.254 gw 0.0.0.0 scope 253 <LINK>
Aug 25 15:22:16 zen connmand[369]: wlan0 {add} route 0.0.0.0 gw 192.168.1.254 scope 0 <UNIVERSE>
Aug 25 15:22:16 zen connmand[369]: wlan0 {add} route 82.165.8.211 gw 192.168.1.254 scope 0 <UNIVERSE>
Aug 25 15:22:17 zen connmand[369]: wlan0 {del} route 82.165.8.211 gw 192.168.1.254 scope 0 <UNIVERSE>

He reconnected to the AP

Aug 25 15:23:22 zen connmand[369]: wlan0 {RX} 8567 packets 6798809 bytes
Aug 25 15:23:22 zen connmand[369]: wlan0 {TX} 12473 packets 10461919 bytes
Aug 25 15:23:22 zen connmand[369]: wlan0 {update} flags 4099 <UP>
Aug 25 15:23:22 zen kernel: wlan0: deauthenticating from 3c:36:e4:69:f5:00 by local choice (Reason: 3=DEAUTH_LEAVING)
Aug 25 15:23:22 zen connmand[369]: wlan0 {newlink} index 3 address 5C:E0:C5:93:6F:34 mtu 1500
Aug 25 15:23:22 zen connmand[369]: wlan0 {newlink} index 3 operstate 2 <DOWN>
Aug 25 15:23:22 zen connmand[369]: wlan0 {del} address 192.168.1.66/24 label wlan0
Aug 25 15:23:22 zen connmand[369]: wlan0 {del} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
Aug 25 15:23:22 zen connmand[369]: wlan0 {del} address 2600:1700:e1c0:c420::2b/64 label (null)
Aug 25 15:23:22 zen connmand[369]: wlan0 {del} route 2600:1700:e1c0:c420:: gw :: scope 0 <UNIVERSE>
Aug 25 15:23:22 zen connmand[369]: wlan0 {del} route fe80:: gw :: scope 0 <UNIVERSE>
Aug 25 15:23:22 zen connmand[369]: wlan0 {del} address 2600:1700:e1c0:c420:5ee0:c5ff:fe93:6f34/64 label (null)

And loses it ~60 seconds later.

nbd · 2021-09-07 02:09:17

seth, you are right. Sorry for the noise.

usualrise · 2022-12-24 02:59:46

Does it gets solved? I am getting the same error.

seth · 2022-12-24 07:56:40

The OP wrote:

So I updated my system and also removed some nearby access points from connman that shouldn't be registered, and now the connection seems to be stable.

Unless you're facing an interference issue as well, open a new thread and post the output of

find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f

and your system journal

sudo journalctl -b | curl -F 'file=@-' 0x0.st

Edit: or continue in https://bbs.archlinux.org/viewtopic.php?id=282270 …

Last edited by seth (2022-12-24 07:59:27)

Arch Linux

#1 2021-08-17 17:13:20

[SOLVED] Deauthentication by local choice with iwd & connman

#2 2021-08-17 22:05:13

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#3 2021-08-20 18:12:27

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#4 2021-08-20 21:26:26

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#5 2021-08-24 18:53:26

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#6 2021-08-24 20:42:20

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#7 2021-08-25 16:09:47

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#8 2021-08-25 16:15:42

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#9 2021-08-25 22:30:06

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#10 2021-08-26 06:50:03

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#11 2021-08-26 17:32:12

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#12 2021-08-27 06:29:27

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#13 2021-09-04 22:34:34

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#14 2021-09-04 23:03:07

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#15 2021-09-06 22:20:45

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#16 2021-09-07 02:09:17

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#17 2022-12-24 02:59:46

Re: [SOLVED] Deauthentication by local choice with iwd & connman

#18 2022-12-24 07:56:40

Re: [SOLVED] Deauthentication by local choice with iwd & connman

Board footer