You are not logged in.

#1 2021-06-10 11:32:12

zegkljan
Member
Registered: 2017-12-30
Posts: 45

wpa_supplicant service does not stop

The first symptom of my problem was that my PC was not shutting down - it hung on a black screen with cursor blinking in the top left corner. To troubleshoot the issue I removed the quiet kernel parameter to see what is going on. I discovered that the system hangs on stopping Network Manager and WPA supplicant. This was consistent with the fact that if I performed a power off before the PC (laptop, actually) connected to wifi, the shutdown went normally. So, to test the theory further, I wanted to manually stop wpa_supplicant.service. However, when I do this

systemctl stop wpa_supplicant.service

the stopping does not complete, it hangs and does not return the control over the console. If I display the status of the service from another console, it shows as deactivating. Manually killing the wpa_supplicant process also does nothing. The only way I figured to get out of this situation is to issue the Alt+SysRq+B shortcut to force reboot the system. The wpa_supplicant logs for that particular boot when I attempted to stop the service look like this:

... previous boot(s)
-- Boot 6c988d3d745f437598652cf42ffba0b1 --
čen 10 10:56:26 eddie systemd[1]: Starting WPA supplicant...
čen 10 10:56:26 eddie systemd[1]: Started WPA supplicant.
čen 10 10:56:26 eddie wpa_supplicant[523]: Successfully initialized wpa_supplicant
čen 10 10:56:27 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 10:56:27 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 10:56:27 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 10:56:28 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 10:56:33 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 10:56:33 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 10:56:36 eddie wpa_supplicant[523]: wlan1: SME: Trying to authenticate with 70:4f:57:37:19:65 (SSID='wigfi2.4' freq=2412 MHz)
čen 10 10:56:37 eddie wpa_supplicant[523]: wlan1: Trying to associate with 70:4f:57:37:19:65 (SSID='wigfi2.4' freq=2412 MHz)
čen 10 10:56:37 eddie wpa_supplicant[523]: RRM: Ignoring radio measurement request: Not associated
čen 10 10:56:37 eddie wpa_supplicant[523]: wlan1: Associated with 70:4f:57:37:19:65
čen 10 10:56:37 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
čen 10 10:56:37 eddie wpa_supplicant[523]: wlan1: WPA: Key negotiation completed with 70:4f:57:37:19:65 [PTK=CCMP GTK=CCMP]
čen 10 10:56:37 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-CONNECTED - Connection to 70:4f:57:37:19:65 completed [id=0 id_str=]
čen 10 10:56:37 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-SIGNAL-CHANGE above=1 signal=-59 noise=-112 txrate=162000
čen 10 10:57:03 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 10:57:03 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 11:01:23 eddie wpa_supplicant[523]: wlan1: WPA: Group rekeying completed with 70:4f:57:37:19:65 [GTK=CCMP]
čen 10 11:10:26 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-DISCONNECTED bssid=70:4f:57:37:19:65 reason=3 locally_generated=1
čen 10 11:10:26 eddie wpa_supplicant[523]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
čen 10 11:10:27 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 11:10:27 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 11:10:28 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-REGDOM-CHANGE init=BEACON_HINT type=UNKNOWN
čen 10 11:10:42 eddie systemd[1]: Stopping WPA supplicant...
čen 10 11:10:42 eddie wpa_supplicant[523]: nl80211: deinit ifname=wlan1 disabled_11b_rates=0
čen 10 11:10:42 eddie wpa_supplicant[523]: wlan1: CTRL-EVENT-TERMINATING
čen 10 11:10:42 eddie wpa_supplicant[523]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0
čen 10 11:12:12 eddie systemd[1]: wpa_supplicant.service: State 'stop-sigterm' timed out. Killing.
čen 10 11:12:12 eddie systemd[1]: wpa_supplicant.service: Killing process 523 (wpa_supplicant) with signal SIGKILL.
čen 10 11:13:42 eddie systemd[1]: wpa_supplicant.service: Processes still around after SIGKILL. Ignoring.
čen 10 11:15:12 eddie systemd[1]: wpa_supplicant.service: State 'final-sigterm' timed out. Killing.
čen 10 11:15:12 eddie systemd[1]: wpa_supplicant.service: Killing process 523 (wpa_supplicant) with signal SIGKILL.
čen 10 11:16:42 eddie systemd[1]: wpa_supplicant.service: Processes still around after final SIGKILL. Entering failed mode.
čen 10 11:16:42 eddie systemd[1]: wpa_supplicant.service: Failed with result 'timeout'.
čen 10 11:16:42 eddie systemd[1]: wpa_supplicant.service: Unit process 523 (wpa_supplicant) remains running after unit stopped.
čen 10 11:16:42 eddie systemd[1]: Stopped WPA supplicant.
-- Boot 7a7d6f9e7ea64a43ba8b8b95c8f8621e --
... following boot(s)

The log shows "Stopped WPA supplicant" but that is actually not the case, the process is still there. When the system shutdown fails, I think what is happening is that it "stops" the service like this but the process is still hanging there, causing the shutdown process to hang as well. But I don't know, I'm not very knowledgeable in these areas.

Another weird thing is that the wpa_supplicant.service is not enabled but is started anyway, even if NetworkManager.service is disabled. I cannot see it in systemctl list-dependencies either.

What could be the the problem? How is it possible that a service is started without it being neither enabled or wanted by another service? How can I make the service work as expected (i.e. stop it when I or the system tells it to stop)?

I'd be happy to provide additional info if instructed.

Offline

#2 2021-06-10 12:27:16

V1del
Forum Moderator
Registered: 2012-10-16
Posts: 12,992

Re: wpa_supplicant service does not stop

Services can be started by invocation through other services which is e.g. what NetworkManager does, it calls wpa_supplicant itself. In general this reads like classic multiple networking services fighting for the interface. What's your output for

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

Offline

#3 2021-06-10 12:39:58

zegkljan
Member
Registered: 2017-12-30
Posts: 45

Re: wpa_supplicant service does not stop

V1del wrote:

Services can be started by invocation through other services which is e.g. what NetworkManager does, it calls wpa_supplicant itself.

I have written, I found wpa_supplicant started just after reboot even when NetworkManager is disabled and not started.

V1del wrote:

In general this reads like classic multiple networking services fighting for the interface. What's your output for

find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
$ find /etc/systemd -type l -exec test -f {} \; -print | awk -F'/' '{ printf ("%-40s | %s\n", $(NF-0), $(NF-1)) }' | sort -f
bluetooth.service                        | bluetooth.target.wants
cups.path                                | multi-user.target.wants
cups.service                             | printer.target.wants
cups.socket                              | sockets.target.wants
dbus-org.bluez.service                   | system
dbus-org.freedesktop.nm-dispatcher.service | system
dbus-org.freedesktop.resolve1.service    | system
dbus-org.freedesktop.timesync1.service   | system
dirmngr.socket                           | sockets.target.wants
display-manager.service                  | system
docker.service                           | multi-user.target.wants
foldingathome.service                    | multi-user.target.wants
getty@tty1.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
NetworkManager.service                   | multi-user.target.wants
NetworkManager-wait-online.service       | network-online.target.wants
p11-kit-server.socket                    | sockets.target.wants
paccache.timer                           | timers.target.wants
pipewire-media-session.service           | pipewire.service.wants
pipewire-pulse.socket                    | sockets.target.wants
pipewire.socket                          | sockets.target.wants
reflector.timer                          | timers.target.wants
remote-fs.target                         | multi-user.target.wants
sshd.socket                              | sockets.target.wants
systemd-resolved.service                 | multi-user.target.wants
systemd-timesyncd.service                | sysinit.target.wants
xdg-user-dirs-update.service             | default.target.wants

Offline

#4 2021-06-10 13:34:41

seth
Member
Registered: 2012-09-03
Posts: 21,074

Re: wpa_supplicant service does not stop

Please post a complete system journal from a boot where wpa_supplicant is started despite NM being disablded.

Offline

#5 2021-06-10 14:56:29

zegkljan
Member
Registered: 2017-12-30
Posts: 45

Re: wpa_supplicant service does not stop

It's rather long, so here: http://ix.io/3pt5

Offline

#6 2021-06-10 15:04:12

seth
Member
Registered: 2012-09-03
Posts: 21,074

Re: wpa_supplicant service does not stop

Invoked by geoclue (which is invoked by gnome-shell)

Jun 10 16:50:27 eddie dbus-daemon[414]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service' requested by ':1.29' (uid=971 pid=989 comm="/usr/lib/geoclue ")
Jun 10 16:50:27 eddie systemd[1]: Starting WPA supplicant...
Jun 10 16:50:27 eddie dbus-daemon[414]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
Jun 10 16:50:27 eddie systemd[1]: Started WPA supplicant.
Jun 10 16:50:27 eddie audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=wpa_supplicant comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Jun 10 16:50:27 eddie wpa_supplicant[1000]: Successfully initialized wpa_supplicant
Jun 10 16:50:27 eddie systemd[1]: Reached target Network.

Most likely because wifi is enabled in /etc/geoclue/geoclue.conf - there's no effort to stop it in this journal, but I guess you need to stop geoclue first.

Offline

#7 2021-06-11 05:56:32

zegkljan
Member
Registered: 2017-12-30
Posts: 45

Re: wpa_supplicant service does not stop

Nice catch. I have disabled wifi in /etc/geoclue/geoclue.conf and wpa_supplicant.service is not starting anymore. However, the original problem remains - when I actually start NetworkManager.service, which in turn starts wpa_supplicant.service, I am unable to stop it. A manual attempt to do this (systemctl stop wpa_supplicant.service) looks like this:

čen 11 07:39:28 eddie systemd[1]: Stopping WPA supplicant...
čen 11 07:40:58 eddie systemd[1]: wpa_supplicant.service: State 'stop-sigterm' timed out. Killing.
čen 11 07:40:58 eddie systemd[1]: wpa_supplicant.service: Killing process 2183 (wpa_supplicant) with signal SIGKILL.
čen 11 07:42:28 eddie systemd[1]: wpa_supplicant.service: Processes still around after SIGKILL. Ignoring.
čen 11 07:43:58 eddie systemd[1]: wpa_supplicant.service: State 'final-sigterm' timed out. Killing.
čen 11 07:43:58 eddie systemd[1]: wpa_supplicant.service: Killing process 2183 (wpa_supplicant) with signal SIGKILL.
čen 11 07:45:29 eddie systemd[1]: wpa_supplicant.service: Processes still around after final SIGKILL. Entering failed mode.
čen 11 07:45:29 eddie systemd[1]: wpa_supplicant.service: Failed with result 'timeout'.
čen 11 07:45:29 eddie systemd[1]: wpa_supplicant.service: Unit process 2183 (wpa_supplicant) remains running after unit stopped.
čen 11 07:45:29 eddie systemd[1]: Stopped WPA supplicant.

And indeed, the process is still happily running.

By the way, basically the same thing happens with NetworkManager.service too:

čen 11 07:36:29 eddie systemd[1]: Stopping Network Manager...
čen 11 07:36:29 eddie NetworkManager[2173]: <info>  [1623389789.9189] caught SIGTERM, shutting down normally.
čen 11 07:36:29 eddie NetworkManager[2173]: <info>  [1623389789.9224] device (wlan0): state change: disconnected -> unmanaged (reason 'unmanaged', sys-iface-state: 'managed')
čen 11 07:36:29 eddie NetworkManager[2173]: <info>  [1623389789.9876] device (wlan0): set-hw-addr: reset MAC address to 04:CE:14:07:43:2B (unmanage)
čen 11 07:36:30 eddie NetworkManager[2173]: <info>  [1623389790.0768] device (p2p-dev-wlan0): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
čen 11 07:36:30 eddie NetworkManager[2173]: <info>  [1623389790.0786] device (wlan1): state change: disconnected -> unmanaged (reason 'unmanaged', sys-iface-state: 'managed')
čen 11 07:36:30 eddie NetworkManager[2173]: <info>  [1623389790.1635] device (wlan1): set-hw-addr: reset MAC address to 6C:0B:84:26:73:D7 (unmanage)
čen 11 07:38:00 eddie systemd[1]: NetworkManager.service: State 'stop-sigterm' timed out. Killing.
čen 11 07:38:00 eddie systemd[1]: NetworkManager.service: Killing process 2173 (NetworkManager) with signal SIGKILL.
čen 11 07:39:30 eddie systemd[1]: NetworkManager.service: Processes still around after SIGKILL. Ignoring.
čen 11 07:41:00 eddie systemd[1]: NetworkManager.service: State 'final-sigterm' timed out. Killing.
čen 11 07:41:00 eddie systemd[1]: NetworkManager.service: Killing process 2173 (NetworkManager) with signal SIGKILL.
čen 11 07:42:30 eddie systemd[1]: NetworkManager.service: Processes still around after final SIGKILL. Entering failed mode.
čen 11 07:42:30 eddie systemd[1]: NetworkManager.service: Failed with result 'timeout'.
čen 11 07:42:30 eddie systemd[1]: NetworkManager.service: Unit process 2173 (NetworkManager) remains running after unit stopped.
čen 11 07:42:30 eddie systemd[1]: Stopped Network Manager.
čen 11 07:42:30 eddie systemd[1]: NetworkManager.service: Consumed 1.762s CPU time.

The system refuses to shut down too (my very original problem).

Offline

#8 2021-06-11 06:49:18

seth
Member
Registered: 2012-09-03
Posts: 21,074

Re: wpa_supplicant service does not stop

Does it meet the PID wpa_supplicant.service thinks it has?

What's its state?

ps aux | grep wpa

Offline

#9 2021-06-11 08:19:21

zegkljan
Member
Registered: 2017-12-30
Posts: 45

Re: wpa_supplicant service does not stop

Yes it does. The log:

čen 11 08:58:59 eddie systemd[1]: Stopping WPA supplicant...
čen 11 08:58:59 eddie wpa_supplicant[2029]: wlan1: CTRL-EVENT-DISCONNECTED bssid=70:4f:57:37:19:65 reason=3 locally_generated=1
čen 11 08:58:59 eddie wpa_supplicant[2029]: nl80211: deinit ifname=wlan1 disabled_11b_rates=0
čen 11 08:58:59 eddie wpa_supplicant[2029]: wlan1: CTRL-EVENT-TERMINATING
čen 11 08:58:59 eddie wpa_supplicant[2029]: nl80211: deinit ifname=p2p-dev-wlan0 disabled_11b_rates=0
čen 11 09:00:29 eddie systemd[1]: wpa_supplicant.service: State 'stop-sigterm' timed out. Killing.
čen 11 09:00:29 eddie systemd[1]: wpa_supplicant.service: Killing process 2029 (wpa_supplicant) with signal SIGKILL.
čen 11 09:01:59 eddie systemd[1]: wpa_supplicant.service: Processes still around after SIGKILL. Ignoring.
čen 11 09:03:29 eddie systemd[1]: wpa_supplicant.service: State 'final-sigterm' timed out. Killing.
čen 11 09:03:29 eddie systemd[1]: wpa_supplicant.service: Killing process 2029 (wpa_supplicant) with signal SIGKILL.
čen 11 09:05:00 eddie systemd[1]: wpa_supplicant.service: Processes still around after final SIGKILL. Entering failed mode.
čen 11 09:05:00 eddie systemd[1]: wpa_supplicant.service: Failed with result 'timeout'.
čen 11 09:05:00 eddie systemd[1]: wpa_supplicant.service: Unit process 2029 (wpa_supplicant) remains running after unit stopped.
čen 11 09:05:00 eddie systemd[1]: Stopped WPA supplicant.

ps aux | grep wpa

root        2029  0.0  0.1  15364  9600 ?        Ds   07:50   0:00 /usr/bin/wpa_supplicant -u -s -O /run/wpa_supplicant
zegkljan    6491  0.0  0.7 974280 63060 pts/0    S+   08:58   0:00 journalctl -fu wpa_supplicant.service
zegkljan    9810  0.0  0.0   8936  2328 pts/1    S+   10:13   0:00 grep --color=auto wpa

Out of curiosity, I tried to start wpa_supplicant.service again from this state and this is the log:

čen 11 10:14:34 eddie systemd[1]: wpa_supplicant.service: Found left-over process 2029 (wpa_supplicant) in control group while starting unit. Ignoring.
čen 11 10:14:34 eddie systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
čen 11 10:14:34 eddie systemd[1]: Starting WPA supplicant...
čen 11 10:14:34 eddie wpa_supplicant[10039]: dbus: Could not request service name: already registered
čen 11 10:14:34 eddie wpa_supplicant[10039]: Failed to initialize wpa_supplicant
čen 11 10:14:34 eddie systemd[1]: wpa_supplicant.service: Main process exited, code=exited, status=255/EXCEPTION

Offline

#10 2021-06-11 13:26:56

seth
Member
Registered: 2012-09-03
Posts: 21,074

Re: wpa_supplicant service does not stop

It's likely waiting for some I/O ("D" state) - you could strace it to see where it's hanging around or check the dmesg for IO errors.

Does the wifi NIC work? Can you ping an IP over it? (Before trying to take it down)?
Is it in the "D" state before the attempt to terminate it?

Offline

Board footer

Powered by FluxBB