[SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

jewetux · 2017-10-29 01:51:06

Since I updated wpa_supplicant from 1:2.6-8 to 1:2.6-11 I'm not able to run wpa_supplicant.service anymore. The service fails with result 'timeout'.

The symptoms are the same mentioned under deauthenticating wlan0 (Reason: 3=DEAUTH_LEAVING).

The OP could solved it by changing some lines in /etc/dbus-1/system.d/wpa_supplicant.conf.
But I think in my case the cause is a different problem, because I use the same file version ships with the wpa_supplicant package. Furthermore the wpa_supplicant.conf file comes with 1:2.6-11 looks like the one published with 1:2.6-8. So it doesn't changed by the update. Why and what lines should I change in wpa_supplicant.conf? I'don't know.

Another thing I should mention: This problem only exits with my main Arch Linux installation that is installed on the internal SSD drive. I've got a second (Arch Linux) test installation which is installed on a USB stick with nearly the same environment (and the same wpa_supplicant.conf file). On the USB system I have no problem to run wpa_supplicant.service in version 1:2.6-11.

Journal of the corrupted system installed on internal SSD (journal filtered by the word 'supplicant'):

systemd[1]: Starting WPA supplicant...
wpa_supplicant[555]: Successfully initialized wpa_supplicant
NetworkManager[554]: <info> [1509229839.3233] supplicant: wpa_supplicant running
NetworkManager[554]: <info> [1509229839.4110] device (wlp58s0): supplicant interface state: starting -> ready
NetworkManager[554]: <info> [1509229839.4112] device (wlp58s0): state change: unavailable -> disconnected (reason 'supplicant-available', internal state 'managed')
NetworkManager[554]: <info> [1509229842.6654] device (wlp58s0): supplicant interface state: ready -> inactive
NetworkManager[554]: <info> [1509229842.8320] device (wlp58s0): supplicant interface state: inactive -> disconnected
NetworkManager[554]: <info> [1509229842.8442] device (wlp58s0): supplicant interface state: disconnected -> inactive
NetworkManager[554]: <info> [1509229842.8506] device (wlp58s0): supplicant interface state: inactive -> scanning
wpa_supplicant[555]: wlp58s0: SME: Trying to authenticate with MAC (SSID='SSID' freq=5500 MHz)
NetworkManager[554]: <info> [1509229844.2071] device (wlp58s0): supplicant interface state: scanning -> authenticating
wpa_supplicant[555]: wlp58s0: Trying to associate with MAC (SSID='SSID' freq=5500 MHz)
wpa_supplicant[555]: wlp58s0: Associated with MAC
wpa_supplicant[555]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
NetworkManager[554]: <info> [1509229844.2482] device (wlp58s0): supplicant interface state: associating -> 4-way handshake
wpa_supplicant[555]: wlp58s0: WPA: Key negotiation completed with MAC [PTK=CCMP GTK=CCMP]
wpa_supplicant[555]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to MAC completed [id=0 id_str=]3
NetworkManager[554]: <info> [1509229844.3076] device (wlp58s0): supplicant interface state: 4-way handshake -> completed
systemd[1]: wpa_supplicant.service: Start operation timed out. Terminating.
wpa_supplicant[555]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlp58s0/drop_unicast_in_l2_multicast: No such file or directory
wpa_supplicant[555]: nl80211: Failed to set IPv4 unicast in multicast filter
wpa_supplicant[555]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlp58s0/drop_unicast_in_l2_multicast: No such file or directory
wpa_supplicant[555]: nl80211: Failed to set IPv4 unicast in multicast filter
wpa_supplicant[555]: nl80211: deinit ifname=p2p-dev-wlp58s0 disabled_11b_rates=0
wpa_supplicant[555]: p2p-dev-wlp58s0: CTRL-EVENT-TERMINATING
wpa_supplicant[555]: wlp58s0: CTRL-EVENT-DISCONNECTED bssid=MAC reason=3 locally_generated=1
wpa_supplicant[555]: nl80211: deinit ifname=wlp58s0 disabled_11b_rates=0
wpa_supplicant[555]: wlp58s0: CTRL-EVENT-TERMINATING
systemd[1]: wpa_supplicant.service: Failed with result 'timeout'.
NetworkManager[554]: <info> [1509229928.7855] supplicant: wpa_supplicant stopped
NetworkManager[554]: <info> [1509229928.7856] device (wlp58s0): supplicant interface state: completed -> down
systemd[1]: Failed to start WPA supplicant.
NetworkManager[554]: <info> [1509229928.7859] device (wlp58s0): state change: activated -> unavailable (reason 'supplicant-failed', internal state 'managed')

Journal of the working system installed on USB stick (journal filtered by the word 'supplicant'):

dbus[430]: [system] Activating via systemd: service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service'
systemd[1]: Starting WPA supplicant...
dbus[430]: [system] Successfully activated service 'fi.w1.wpa_supplicant1'
wpa_supplicant[481]: Successfully initialized wpa_supplicant
systemd[1]: Started WPA supplicant.
NetworkManager[434]: <info> [1509230694.9981] supplicant: wpa_supplicant running
NetworkManager[434]: <info> [1509230694.9983] device (wlp58s0): supplicant interface state: init -> starting
NetworkManager[434]: <info> [1509230695.1243] device (wlp58s0): supplicant interface state: starting -> ready
NetworkManager[434]: <info> [1509230695.1244] device (wlp58s0): state change: unavailable -> disconnected (reason 'supplicant-available', internal state 'managed')
NetworkManager[434]: <info> [1509230698.4234] device (wlp58s0): supplicant interface state: ready -> inactive
NetworkManager[434]: <info> [1509230698.5655] device (wlp58s0): supplicant interface state: inactive -> disconnected
NetworkManager[434]: <info> [1509230698.5825] device (wlp58s0): supplicant interface state: disconnected -> inactive
NetworkManager[434]: <info> [1509230698.5890] device (wlp58s0): supplicant interface state: inactive -> scanning
wpa_supplicant[481]: wlp58s0: SME: Trying to authenticate with MAC (SSID='SSID' freq=5500 MHz)
NetworkManager[434]: <info> [1509230699.6959] device (wlp58s0): supplicant interface state: scanning -> authenticating
wpa_supplicant[481]: wlp58s0: Trying to associate with MAC (SSID='SSID' freq=5500 MHz)
NetworkManager[434]: <info> [1509230699.7096] device (wlp58s0): supplicant interface state: authenticating -> associating
wpa_supplicant[481]: wlp58s0: Associated with MAC
wpa_supplicant[481]: wlp58s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
NetworkManager[434]: <info> [1509230699.7385] device (wlp58s0): supplicant interface state: associating -> 4-way handshake
wpa_supplicant[481]: wlp58s0: WPA: Key negotiation completed with MAC [PTK=CCMP GTK=CCMP]
wpa_supplicant[481]: wlp58s0: CTRL-EVENT-CONNECTED - Connection to MAC completed [id=0 id_str=]
NetworkManager[434]: <info> [1509230699.7681] device (wlp58s0): supplicant interface state: 4-way handshake -> completed

You can see that the dbus of the corrupted (internal) installation doesn't try to activate wpa_supplicant.service.
How can I find out what is preventing dbus by activating wpa_supplicant?

Thx for any help.

Last edited by jewetux (2017-10-29 14:13:24)

sm-Fifteen · 2017-10-29 03:55:56

Just to be sure, what unit file does systemd use?

systemctl status wpa-supplicant

And what are the contents of that file?

jewetux · 2017-10-29 13:03:52

Hallo, thx for your answer.

$ systemctl status wpa_supplicant
● wpa_supplicant.service - WPA supplicant
Loaded: loaded (/etc/systemd/system/wpa_supplicant.service; enabled; vendor preset: disabled)
Active: failed (Result: timeout) since Sun 2017-10-29 13:46:27 CET; 36s ago
Process: 2152 ExecStart=/usr/bin/wpa_supplicant -u (code=exited, status=0/SUCCESS)
Main PID: 2152 (code=exited, status=0/SUCCESS)
Okt 29 13:46:27 User wpa_supplicant[2152]: nl80211: Failed to set IPv4 unicast in multicast filter
Okt 29 13:46:27 User wpa_supplicant[2152]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlp58s0/drop_unicast
Okt 29 13:46:27 User wpa_supplicant[2152]: nl80211: Failed to set IPv4 unicast in multicast filter
Okt 29 13:46:27 User wpa_supplicant[2152]: nl80211: deinit ifname=p2p-dev-wlp58s0 disabled_11b_rates=0
Okt 29 13:46:27 User wpa_supplicant[2152]: p2p-dev-wlp58s0: CTRL-EVENT-TERMINATING
Okt 29 13:46:27 User wpa_supplicant[2152]: wlp58s0: CTRL-EVENT-DISCONNECTED bssid=MAC reason=3 locally_ge
Okt 29 13:46:27 User wpa_supplicant[2152]: nl80211: deinit ifname=wlp58s0 disabled_11b_rates=0
Okt 29 13:46:27 User wpa_supplicant[2152]: wlp58s0: CTRL-EVENT-TERMINATING
Okt 29 13:46:27 User systemd[1]: wpa_supplicant.service: Failed with result 'timeout'.
Okt 29 13:46:27 User systemd[1]: Failed to start WPA supplicant.

$ cat /etc/dbus-1/system.d/wpa_supplicant.conf
<!DOCTYPE busconfig PUBLIC
"-//freedesktop//DTD D-BUS Bus Configuration 1.0//EN"
"http://www.freedesktop.org/standards/db … config.dtd">
<busconfig>
<policy user="root">
<allow own="fi.epitest.hostap.WPASupplicant"/>
<allow send_destination="fi.epitest.hostap.WPASupplicant"/>
<allow send_interface="fi.epitest.hostap.WPASupplicant"/>
<allow own="fi.w1.wpa_supplicant1"/>
<allow send_destination="fi.w1.wpa_supplicant1"/>
<allow send_interface="fi.w1.wpa_supplicant1"/>
<allow receive_sender="fi.w1.wpa_supplicant1" receive_type="signal"/>
</policy>
<policy context="default">
<deny own="fi.epitest.hostap.WPASupplicant"/>
<deny send_destination="fi.epitest.hostap.WPASupplicant"/>
<deny own="fi.w1.wpa_supplicant1"/>
<deny send_destination="fi.w1.wpa_supplicant1"/>
<deny receive_sender="fi.w1.wpa_supplicant1" receive_type="signal"/>
</policy>
</busconfig>

I don't use a custom /etc/wpa_supplicant/wpa_supplicant.conf.

Btw. It is only wpa_supplicant.service that doesn't work. If I stop NM and run wpa_supplicant+dhcpcd I've got a stable network connection.

$ cat /etc/NetworkManager/NetworkManager.conf
[main]
plugins=keyfile
dns=default
dhcp=dhclient
#dhcp=internal
#dhcp=dhcpcd

You can see that I tested with different dhcp clients. Same result. It doesn't work.

progandy · 2017-10-29 13:14:35

You seem to have a modified wpa_supplicant.service in /etc. What are its contents? Compare it to the original and maybe remove/update the one in /etc. Don' forget to restart or refresh systemd (systemctl daemon-reload)

/usr/lib/systemd/system/wpa_supplicant.service
/etc/systemd/system/wpa_supplicant.service

Last edited by progandy (2017-10-29 13:17:31)

jewetux · 2017-10-29 13:34:56

Hi, here is the content of both service files:

$ cat /usr/lib/systemd/system/wpa_supplicant.service
[Unit]
Description=WPA supplicant
Before=network.target
Wants=network.target
[Service]
Type=dbus
BusName=fi.w1.wpa_supplicant1
ExecStart=/usr/bin/wpa_supplicant -u
[Install]
WantedBy=multi-user.target
Alias=dbus-fi.w1.wpa_supplicant1.service

cat /etc/systemd/system/wpa_supplicant.service
[Unit]
Description=WPA supplicant
Before=network.target
Wants=network.target
After=dbus.service
[Service]
Type=dbus
BusName=fi.epitest.hostap.WPASupplicant
ExecStart=/usr/bin/wpa_supplicant -u
[Install]
WantedBy=multi-user.target
Alias=dbus-fi.epitest.hostap.WPASupplicant.service

Should both look the same way? So replace the /etc service file by the /usr file?

progandy · 2017-10-29 13:47:59

Should both look the same way? So replace the /etc service file by the /usr file?

The unit in /etc has the old dbus name, that is why it times out. That is the same issue as sm-Fifteen in the thread you linked in your first post.
You don't need the copy in /etc, since you don't have any custom changes in it. Delete the service in /etc, and then daemon-reload systemd to detect the change. Afterwards systemd should use the unit in /usr/lib.

Last edited by progandy (2017-10-29 13:50:56)

jewetux · 2017-10-29 14:12:53

Thx, after deleting /etc/systemd/system/wpa_supplicant.service and a reboot there are no failures anymore. Problem is solved.

Last edited by jewetux (2017-10-29 14:13:56)

Arch Linux

#1 2017-10-29 01:51:06

[SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

#2 2017-10-29 03:55:56

Re: [SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

#3 2017-10-29 13:03:52

Re: [SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

#4 2017-10-29 13:14:35

Re: [SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

#5 2017-10-29 13:34:56

Re: [SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

#6 2017-10-29 13:47:59

Re: [SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

#7 2017-10-29 14:12:53

Re: [SOLVED] wpa_supplicant 1:2.6-11: Service failed with result 'timeout'

Board footer