Bug 29899

Summary: stopping NM doesn't stop old wpa_supplicant
Product: Sisyphus Reporter: Ivan Zakharyaschev <imz>
Component: NetworkManagerAssignee: Mikhail Efremov <sem>
Status: CLOSED WORKSFORME QA Contact: qa-sisyphus
Severity: normal    
Priority: P3 CC: sem
Version: unstable   
Hardware: all   
OS: Linux   

Description Ivan Zakharyaschev 2014-03-20 12:31:24 MSK 
# rpm -q NetworkManager wpa_supplicant 
NetworkManager-0.9.8.8-alt2.M70P.2
wpa_supplicant-2.0-alt2
# 

(In p7, Simply Linux.)

After various manipulations with the network driver, I wanted to restart NetworkManager to set up the wireless interface. (It is configured as an access point in NetworkManager's configuration files.)

But even after I issued "service NetworkManager stop" or "... restart", the old wpa_supplicant process wasn't stopped, and it was unable to perform authentcation in the network.

I had to manually kill wpa_supplicant, only after that and "service NetworkManager start", connections were made possible.

Here are probably the logs from the old wpa_supplicant:

мар 20 11:49:37 host-17.localdomain systemd[1]: Stopping Network Manager...
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Interface wlp7s0.IPv4 no longer relevant for mDNS.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Leaving mDNS multicast group on interface wlp7s0.IPv4 with address 10.42.0.1.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Withdrawing address record for fe80::226:5eff:fe4d:2b2e on wlp7s0.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Withdrawing address record for 10.42.0.1 on wlp7s0.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Joining mDNS multicast group on interface wlp7s0.IPv4 with address 10.42.0.1.
мар 20 11:49:37 host-17.localdomain kernel: IPv6: ADDRCONF(NETDEV_UP): wlp7s0: link is not ready
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: New relevant interface wlp7s0.IPv4 for mDNS.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Registering new address record for 10.42.0.1 on wlp7s0.IPv4.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Withdrawing address record for 10.42.0.1 on wlp7s0.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Leaving mDNS multicast group on interface wlp7s0.IPv4 with address 10.42.0.1.
мар 20 11:49:37 host-17.localdomain avahi-daemon[1521]: Interface wlp7s0.IPv4 no longer relevant for mDNS.
мар 20 11:49:37 host-17.localdomain dbus-daemon[1539]: dbus[1539]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
мар 20 11:49:37 host-17.localdomain dbus[1539]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
мар 20 11:49:37 host-17.localdomain systemd[1]: Starting Network Manager Script Dispatcher Service...
мар 20 11:49:38 host-17.localdomain dbus-daemon[1539]: dbus[1539]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
мар 20 11:49:38 host-17.localdomain dbus[1539]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
мар 20 11:49:38 host-17.localdomain systemd[1]: Started Network Manager Script Dispatcher Service.
мар 20 11:49:38 host-17.localdomain systemd[1]: Stopped Network Manager.
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Successfully initialized wpa_supplicant
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: wlp7s0: Failed to start AP functionality
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: rfkill: WLAN hard blocked
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Using interface wlp7s0 with hwaddr 00:26:5e:4d:2b:2e and ssid "inki"
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: wlp7s0: CTRL-EVENT-CONNECTED - Connection to 00:26:5e:4d:2b:2e completed [id=0 id_str=]
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: wlp7s0: Could not connect to kernel driver
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Using interface wlp7s0 with hwaddr 00:26:5e:4d:2b:2e and ssid "inki"
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: wlp7s0: CTRL-EVENT-CONNECTED - Connection to 00:26:5e:4d:2b:2e completed [id=0 id_str=]
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: wlp7s0: Could not connect to kernel driver
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not read interface wlp7s0 flags: No such device
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not read interface wlp7s0 flags: No such device
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not read interface wlp7s0 flags: No such device
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Using interface wlp7s0 with hwaddr 00:26:5e:4d:2b:2e and ssid "inki"
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: wlp7s0: CTRL-EVENT-CONNECTED - Connection to 00:26:5e:4d:2b:2e completed [id=0 id_str=]
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station d4:6e:5c:fa:37:02 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station d4:6e:5c:fa:37:02 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station d4:6e:5c:fa:37:02 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station d4:6e:5c:fa:37:02 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Using interface wlp7s0 with hwaddr 00:26:5e:4d:2b:2e and ssid "inki"
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: wlp7s0: CTRL-EVENT-CONNECTED - Connection to 00:26:5e:4d:2b:2e completed [id=0 id_str=]
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).
мар 20 11:49:47 host-17.localdomain wpa_supplicant[3187]: Could not set station 44:91:db:9a:f2:d5 flags for kernel driver (errno=100).


And here are the logs after killing it manually and restarting NetworkManager.

мар 20 11:49:53 host-17.localdomain systemd[1]: Starting Network Manager...
мар 20 11:49:53 host-17.localdomain NetworkManager-prestart[16229]: Setting network parameters: [ DONE ]
мар 20 11:49:54 host-17.localdomain systemd[1]: Started Network Manager.
мар 20 11:49:54 host-17.localdomain kernel: IPv6: ADDRCONF(NETDEV_UP): wlp7s0: link is not ready
мар 20 11:49:54 host-17.localdomain dbus-daemon[1539]: dbus[1539]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service'
мар 20 11:49:54 host-17.localdomain dbus[1539]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service'
мар 20 11:49:54 host-17.localdomain systemd[1]: Starting WPA supplicant...
мар 20 11:49:55 host-17.localdomain dbus-daemon[1539]: dbus[1539]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
мар 20 11:49:55 host-17.localdomain dbus[1539]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
мар 20 11:49:55 host-17.localdomain systemd[1]: Started WPA supplicant.
мар 20 11:49:55 host-17.localdomain avahi-daemon[1521]: Withdrawing address record for fe80::21f:16ff:fee7:a9bd on enp0s10.
мар 20 11:49:56 host-17.localdomain dbus-daemon[1539]: dbus[1539]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
мар 20 11:49:56 host-17.localdomain dbus[1539]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
мар 20 11:49:56 host-17.localdomain systemd[1]: Starting Network Manager Script Dispatcher Service...
мар 20 11:49:56 host-17.localdomain dbus-daemon[1539]: dbus[1539]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
мар 20 11:49:56 host-17.localdomain dbus[1539]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
мар 20 11:49:56 host-17.localdomain systemd[1]: Started Network Manager Script Dispatcher Service.
мар 20 11:49:56 host-17.localdomain nm-dispatcher.action[16307]: masked
мар 20 11:49:56 host-17.localdomain avahi-daemon[1521]: Registering new address record for fe80::21f:16ff:fee7:a9bd on enp0s10.*.
мар 20 11:49:57 host-17.localdomain kernel: IPv6: ADDRCONF(NETDEV_UP): wlp7s0: link is not ready

NetworkManager should stop the old wpa_supplicant on "service NetworkManager stop".
Comment 1 Ivan Zakharyaschev 2014-03-20 12:35:19 MSK 
The messages from wpa_supplicant appear to be from мар 20 11:49:47, but actually they are from much earlier AFAIU -- these messages come from the initial boot of the system several hours earlier.

For some reasons, they were printed to the journal only when I killed wpa_supplicant.
Comment 2 Mikhail Efremov 2014-03-20 21:29:05 MSK 
(В ответ на комментарий №0)
> NetworkManager should stop the old wpa_supplicant on "service NetworkManager
> stop".

No, it should not. NM withdraw the configuration from wpa_supplicant when it disconnects the interface. But from some point of time NM do not deconfigure interfaces on exit, may be it is the cause. In case of sysvinit I've added workaround in the init script and deconfigure all interfaces before NM is stopped (see NM_STOP_ONEXIT option in the /etc/sysconfig/NetworkManager), but in case of systemd this can't be done so easely (there is no something like ExecStopPre).
Please try to disconnect manually before restaring NetworkManager.service, does it help?
Comment 3 Mikhail Efremov 2022-08-30 15:51:35 MSK 
I hope it works nowaday.