wireless deactivates after sleep / hibernation

[Charlie Brown]

This works here perfectly:

Code: Select all

#!/bin/bash

PATH=/sbin:/usr/sbin:/bin:/usr/bin

case "$1" in
  thaw|resume)
    service network-manager restart && echo "NM restarted" > /home/charlie/test
    ;;
esac

Either the test file is there with the message and I see it restarts.

(And, yes, it doesn't work with "post" for whatever reason)


So, you can do it just service network-manager restart or with i.e. sleep 2 before it or .. stop then start as above in post #7 ...

[VictorRotha]

"does it show up in any of the /var/log/pm-suspend.log logs."

gah, didn't have my admin hat fully in place... It is in the log. Anyway, with all that:

I rejigged the script:

Code: Select all

#!/bin/bash
PATH=/sbin:/usr/sbin:/bin:/usr/bin

case "$1" in
  thaw|resume)
    date >> /tmp/sleeper
    echo "in resume selection" >> /tmp/sleeper
    sleep 10
    service network-manager restart >> /tmp/sleeper 2>&1
    ip address show  dev wlan0 >> /tmp/sleeper
    date >> /tmp/sleeper
    ;;
esac
date >> /tmp/sleeper
echo "now outside case block" >> /tmp/sleeper
sleep 10
ip address show  dev wlan0 >> /tmp/sleeper
date >> /tmp/sleeper 

Rebooted, then tested by closing lid and leaving it closed for 5 mins. It did run, I've posted the pm-suspend.log snippet below. /tmp/sleeper is there, here's the output:

Wed Jan 24 10:38:52 ACDT 2024
now outside case block
2: wlan0: <BROADCAST,MULTICAST> mtu 1500 qdisc noqueue state DOWN group default qlen 1000
link/ether d8:c0:a6:bf:55:03 brd ff:ff:ff:ff:ff:ff
Wed Jan 24 10:39:02 ACDT 2024
Wed Jan 24 10:39:17 ACDT 2024
in resume selection
Stopping network connection manager: NetworkManager.
Starting network connection manager: NetworkManager.
2: wlan0: <BROADCAST,MULTICAST> mtu 1500 qdisc noqueue state DOWN group default qlen 1000
link/ether d8:c0:a6:bf:55:03 brd ff:ff:ff:ff:ff:ff
Wed Jan 24 10:39:27 ACDT 2024
Wed Jan 24 10:39:27 ACDT 2024
now outside case block
2: wlan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
link/ether d8:c0:a6:bf:55:03 brd ff:ff:ff:ff:ff:ff
inet 192.168.0.102/24 brd 192.168.0.255 scope global dynamic noprefixroute wlan0
valid_lft 86395sec preferred_lft 86395sec
inet6 fe80::9537:48bb:f497:378/64 scope link noprefixroute
valid_lft forever preferred_lft forever
Wed Jan 24 10:39:37 ACDT 2024

So it ran twice, somehow. After all that, a few seconds later a message window from network manager pops up: 'Connection WirelessSSID deactivated'. So we are barking up the wrong tree, the deactivation occurs after the hibernation restoration, presumably by NM based on the message.

In syslog, I see (in snips):

Code: Select all

2024-01-24T10:39:17.303331+10:30 phil-envy kernel: [   65.576699] PM: hibernation: hibernation exit

2024-01-24T10:39:31.819179+10:30 phil-envy kernel: [   80.096338] wlan0: authenticated
2024-01-24T10:39:31.883266+10:30 phil-envy wpa_supplicant[2460]: wlan0: CTRL-EVENT-CONNECTED - Connection to 5c:a6:e6:55:27:e5 completed [id=0 id_str=]

2024-01-24T10:40:37.587144+10:30 phil-envy kernel: [  145.862843] wlan0: deauthenticating from 5c:a6:e6:55:27:e5 by local choice (Reason: 3=DEAUTH_LEAVING)
2024-01-24T10:40:37.612366+10:30 phil-envy wpa_supplicant[2460]: wlan0: CTRL-EVENT-DISCONNECTED bssid=5c:a6:e6:55:27:e5 reason=3 locally_generated=1

So, where to from here?

[xaol]

i would assume that you aren't having other spontaneous disconnects, but have seen other situations where turning power management off helped with that. it might be something to try. i usually check it with

Code: Select all

iwconfig

[VictorRotha]

hm, yesterday's post didn't take. Anyway, no intermittent disconnects, only happens with hibernation.

OK so I looked up the kernel message:

Code: Select all

wlan0: deauthenticating from 5c:a6:e6:55:27:e5 by local choice (Reason: 3=DEAUTH_LEAVING)

There are a number of circumstances where this occurs, a long interface name, wireless security type, etc. - none of them relevant here. And disabling IPv6 has no effect.

[xaol]

the deauth and disconnected messages look exactly the same as the ones i get if i manually choose to disconnect from a network from the gui so they may be hard to differentiate from any other cause. i wonder if increasing the sleep time to more that 10 before restarting network-manager would have any effect? it looks like at 10:39:37 the interface was up then at 10:40:37 you got the deauth message. maybe something on the networking side isn't entirely set up that early?

[VictorRotha]

yes, you're right, that deauth message happens as part of the wireless shutdown, but nothing preceding it during these events, other than . I changed the timing and it has no effect. What ever is happening just isn't being recorded that I can see.

[xaol]

you could try changing the wpa_supplicant log level to see if that gets you any extra info but hopefully not too much.

Code: Select all

sudo wpa_cli log_level

should show the current level. on my mx 23 system it is INFO. you can change that to debug with

Code: Select all

sudo wpa_cli log_level debug

another possibly diagnostic option i ran into the other day was the iw command: https://wireless.wiki.kernel.org/en/use ... ntation/iw

When debugging, it can be useful to see the auth/assoc/deauth/disassoc frames, use

iw event -f

Code: Select all

iw event help

shows some other options including adding timestamps. it also has a --debug option, but fair warning that one produces a lot of output.

[VictorRotha]

OK, I shutdown cron/anacron to declutter syslog as the latter always ran after opening the lid. Increased the logging per your suggestion, thanks. I also put in a log entry prior to shutting.

syslog:

Code: Select all

2024-01-30T09:48:42.886938+10:30 phil-envy root: this is a log message - now closing lid w active wifi
2024-01-30T09:48:56.879688+10:30 phil-envy kernel: [76792.965154] atkbd serio0: Unknown key pressed (translated set 2, code 0xd8 on isa0060/serio0).
2024-01-30T09:48:56.879710+10:30 phil-envy kernel: [76792.965166] atkbd serio0: Use 'setkeycodes e058 <keycode>' to make it known.
2024-01-30T09:48:56.880996+10:30 phil-envy kernel: [76792.968502] atkbd serio0: Unknown key released (translated set 2, code 0xd8 on isa0060/serio0).
2024-01-30T09:48:56.881006+10:30 phil-envy kernel: [76792.968511] atkbd serio0: Use 'setkeycodes e058 <keycode>' to make it known.
2024-01-30T09:51:25.279449+10:30 phil-envy dbus-daemon[2285]: [system] Activating service name='org.kde.powerdevil.backlighthelper' requested by ':1.36' (uid=1001 pid=3003 comm="/us
r/lib/x86_64-linux-gnu/libexec/org_kde_powerdev") (using servicehelper)
2024-01-30T09:51:25.302621+10:30 phil-envy dbus-daemon[2285]: [system] Successfully activated service 'org.kde.powerdevil.backlighthelper'
2024-01-30T09:52:32.736133+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 1 BSSID 56:af:97:e5:9d:79 SSID '' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736152+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/1'
2024-01-30T09:52:32.736220+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 2 BSSID 54:af:97:c5:9d:79 SSID 'dattebayo wifi' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736227+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/2'
2024-01-30T09:52:32.736256+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 3 BSSID 56:af:97:e5:9d:77 SSID '' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736262+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/3'
2024-01-30T09:52:32.736287+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 4 BSSID 54:af:97:c5:9d:77 SSID 'dattebayo wifi' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736294+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/4'
2024-01-30T09:52:32.736318+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 5 BSSID 5c:a6:e6:55:27:e3 SSID 'JemimaPuddleDuck' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736324+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/5'
2024-01-30T09:52:32.736348+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 6 BSSID 9c:a2:f4:80:39:81 SSID 'WiFi-803981' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736355+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/6'
2024-01-30T09:52:32.736379+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 7 BSSID 10:27:f5:74:31:24 SSID 'dattebayo wifi_EXT' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736385+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/7'
2024-01-30T09:52:32.736410+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 8 BSSID a6:97:5c:04:1b:0c SSID 'VTECH_5764_1b0c' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736416+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/8'
2024-01-30T09:52:32.736441+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 9 BSSID 10:27:f5:f5:fa:f1 SSID 'WiFi-F5FAF1' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736447+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/9'
2024-01-30T09:52:32.736471+10:30 phil-envy wpa_supplicant[2494]: wlan0: BSS: Remove id 10 BSSID 80:3f:5d:5d:36:27 SSID 'WAVLINK-N' due to wpa_bss_flush_by_age
2024-01-30T09:52:32.736478+10:30 phil-envy wpa_supplicant[2494]: dbus: Unregister BSS object '/fi/w1/wpa_supplicant1/Interfaces/8/BSSs/10'
2024-01-30T09:52:40.278277+10:30 phil-envy dbus-daemon[2285]: [system] Activating service name='org.kde.powerdevil.backlighthelper' requested by ':1.36' (uid=1001 pid=3003 comm="/us
r/lib/x86_64-linux-gnu/libexec/org_kde_powerdev") (using servicehelper)
2024-01-30T09:52:40.306626+10:30 phil-envy dbus-daemon[2285]: [system] Successfully activated service 'org.kde.powerdevil.backlighthelper'
2024-01-30T09:53:55.278404+10:30 phil-envy dbus-daemon[2285]: [system] Activating service name='org.kde.powerdevil.backlighthelper' requested by ':1.36' (uid=1001 pid=3003 comm="/usr/lib/x86_64-linux-gnu/libexec/org_kde_powerdev") (using servicehelper)
2024-01-30T09:53:55.299353+10:30 phil-envy dbus-daemon[2285]: [system] Successfully activated service 'org.kde.powerdevil.backlighthelper'
2024-01-30T10:02:47.843692+10:30 phil-envy kernel: [77623.932086] wlan0: deauthenticating from 5c:a6:e6:55:27:e5 by local choice (Reason: 3=DEAUTH_LEAVING)
2024-01-30T10:02:47.872217+10:30 phil-envy wpa_supplicant[2494]: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
2024-01-30T10:02:47.872231+10:30 phil-envy wpa_supplicant[2494]: nl80211: Delete station 5c:a6:e6:55:27:e5

And here is the iw event log (again at the same time):

Code: Select all

[2024-01-30 10:02:47.872130]: wlan0: del station 5c:a6:e6:55:27:e5
[2024-01-30 10:02:47.872644]: wlan0 (phy #0): deauth d8:c0:a6:bf:55:03 -> 5c:a6:e6:55:27:e5 reason 3: Deauthenticated because sending station is leaving (or has left) the IBSS or ESS

So it is just acknowledging the deauthentication command from the kernel; the deauth cause lies elsewhere... I think the 'unregister BSS object' is just cleanup after the wakeup, this doesn't happen every time.

The only other thing consistently in the log is the unknown keypressed event, which happens before/as the lid shuts - regardless, I can't see this is related to the deauth as the keypress (whatever causes this) is unknown and thus wouldn't have any effect.

BTW, I've used this laptop w ubuntu and fedora on the same wireless AP without this problem. I'm only sitting about 3m away from it. I also just tried it using my phone's wireless AP (in case it is some conflict w my router), same result. A real puzzler.

[xaol]

did the above include your attempt to restart network manager after wake up?

[VictorRotha]

no, will show that below. First, as explained before in the thread, when I go through the close/open lid cycle, the 1st time it deactivates the wireless, the second time it just wakes the wireless up and reconnects by itself. I've attached files with the syslog and iw event log outputs; the files occurred in this order:

wireless-activating-on-open -- this shows the wireless activating itself on lid opening after having deactivated w the previous lid close/opening
wireless-deactivating-on-open -- take2 -- this is the 'normal' deactivation after lid cycle starting from the above active wireless state
wireless-manual-activation-after-take2 -- this is manually activating the wireless directly after the take2 wireless was deactivated

I confirmed that the active/inactive cycle occurs repeated, and regardless of whether I manually activate the wireless. If I manually deactivate the wireless, it remains deactivated through the cycles as one would expect. Forgot to mention that this cycle happens when the system hibernates or sleeps with the activity timeout as well as by the lid closing.