FS#56048 - [wpa_supplicant] Start operation timed out with 1:2.6-11

Attached to Project: Arch Linux
Opened by Frank (jewelux) - Thursday, 19 October 2017, 15:07 GMT
Last edited by Doug Newgard (Scimmia) - Sunday, 29 October 2017, 14:45 GMT
Task Type Bug Report
Category Packages: Core
Status Closed
Assigned To Bartłomiej Piotrowski (Barthalion)
Architecture All
Severity High
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 0
Private No

Details

Description: Since I upgraded to version 1:2.6-11 the wpa_supplicant.service failed to start on boot.
The log shows "Start operation timed out. Terminating." (see below)

Steps to reproduce:
1. only boot the system

Only known workaround:
downgrade to version 1:2.6-8

System configuration:
Dell XPS 13 9350
Intel Dual Band Wireless-8260
Cinnamon + Networkmanager Plugin


Journal with all wpa_supplicant and NM relevant logs:
Okt 19 03:13:45 XXX systemd[1]: Starting Network Manager...
Okt 19 03:13:45 XXX systemd[1]: Starting WPA supplicant...
Okt 19 03:13:45 XXX wpa_supplicant[652]: Successfully initialized wpa_supplicant
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.5997] NetworkManager (version 1.8.4-1, Arch Linux) is starting... (for the first time)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.5997] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 20-connectivity.conf)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6037] manager[0x55f884a99100]: monitoring kernel firmware directory '/usr/lib/firmware'.
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6042] policy: hostname management mode: default
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6043] dns-mgr[0x55f884aa5950]: init: dns=default, rc-manager=resolvconf
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6050] rfkill0: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:1c.4/0000:3a:00.0/ieee80211/phy0/rfkill0) (driver iwlwifi)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6051] manager[0x55f884a99100]: rfkill: WiFi hardware radio set enabled
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6051] manager[0x55f884a99100]: rfkill: WWAN hardware radio set disabled
Okt 19 03:13:45 XXX systemd[1]: Started Network Manager.
Okt 19 03:13:45 XXX dbus[647]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Okt 19 03:13:45 XXX systemd[1]: Starting Network Manager Script Dispatcher Service...
Okt 19 03:13:45 XXX dbus[647]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Okt 19 03:13:45 XXX systemd[1]: Started Network Manager Script Dispatcher Service.
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6193] settings: loaded plugin keyfile: (c) 2007 - 2016 Red Hat, Inc. To report bugs please use the NetworkManager mailing list.
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6257] keyfile: new connection /etc/NetworkManager/system-connections/VPN-Verbindung @Home (ca904ca2-96eb-4042-8835-bd00113371df,"VPN-Verbindung @Home")
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.6312] keyfile: new connection /etc/NetworkManager/system-connections/Kabelgebundene Verbindung 1 (9fa05b25-d0d5-4c9c-a559-29eaa1b36282,"Kabelgebundene Verbindung 1")
Okt 19 03:13:45 XXX dbus[647]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service'
Okt 19 03:13:45 XXX systemd[1]: Starting Hostname Service...
Okt 19 03:13:45 XXX dbus[647]: [system] Successfully activated service 'org.freedesktop.hostname1'
Okt 19 03:13:45 XXX systemd[1]: Started Hostname Service.
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7934] settings: hostname: using hostnamed
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7934] settings: hostname changed from (none) to "XXX"
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7938] dhcp-init: Using DHCP client 'internal'
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7938] manager: rfkill: WiFi enabled by radio killswitch; enabled by state file
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7939] manager: rfkill: WWAN enabled by radio killswitch; disabled by state file
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7939] manager: Networking is enabled by state file
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7940] Loaded device plugin: NMBondDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7940] Loaded device plugin: NMBridgeDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7940] Loaded device plugin: NMDummyDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7941] Loaded device plugin: NMEthernetDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7941] Loaded device plugin: NMInfinibandDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7941] Loaded device plugin: NMIPTunnelDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7942] Loaded device plugin: NMMacsecDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7942] Loaded device plugin: NMMacvlanDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7942] Loaded device plugin: NMTunDeviceFactory (internal)
Okt 19 03:13:45 XXX nm-dispatcher[660]: req:1 'hostname': new request (0 scripts)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7943] Loaded device plugin: NMVethDeviceFactory (internal)
Okt 19 03:13:45 XXX nm-dispatcher[660]: req:1 'hostname': completed: no scripts
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7943] Loaded device plugin: NMVlanDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7943] Loaded device plugin: NMVxlanDeviceFactory (internal)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.7957] Loaded device plugin: NMAtmManager (/usr/lib/NetworkManager/libnm-device-plugin-adsl.so)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8092] Loaded device plugin: NMWwanFactory (/usr/lib/NetworkManager/libnm-device-plugin-wwan.so)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8128] Loaded device plugin: NMBluezManager (/usr/lib/NetworkManager/libnm-device-plugin-bluetooth.so)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8147] Loaded device plugin: NMWifiFactory (/usr/lib/NetworkManager/libnm-device-plugin-wifi.so)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8369] Loaded device plugin: NMTeamFactory (/usr/lib/NetworkManager/libnm-device-plugin-team.so)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8388] device (lo): link connected
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8406] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8415] wifi-nl80211: (wlp58s0): using nl80211 for WiFi device control
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8420] device (wlp58s0): driver supports Access Point (AP) mode
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8442] manager: (wlp58s0): new 802.11 WiFi device (/org/freedesktop/NetworkManager/Devices/2)
Okt 19 03:13:45 XXX NetworkManager[651]: <info> [1508375625.8467] device (wlp58s0): state change: unmanaged -> unavailable (reason 'managed', internal state 'external')
Okt 19 03:13:45 XXX kernel: IPv6: ADDRCONF(NETDEV_UP): wlp58s0: link is not ready
Okt 19 03:13:46 XXX kernel: IPv6: ADDRCONF(NETDEV_UP): wlp58s0: link is not ready
Okt 19 03:13:46 XXX dbus[647]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
Okt 19 03:13:46 XXX systemd[1]: Starting Authorization Manager...
Okt 19 03:13:46 XXX NetworkManager[651]: <info> [1508375626.1058] supplicant: wpa_supplicant running
Okt 19 03:13:46 XXX NetworkManager[651]: <info> [1508375626.1060] device (wlp58s0): supplicant interface state: init -> starting
Okt 19 03:13:46 XXX NetworkManager[651]: <info> [1508375626.1798] sup-iface[0x55f884b43d10,wlp58s0]: supports 5 scan SSIDs
Okt 19 03:13:46 XXX NetworkManager[651]: <info> [1508375626.1816] device (wlp58s0): supplicant interface state: starting -> ready
Okt 19 03:13:46 XXX NetworkManager[651]: <info> [1508375626.1818] device (wlp58s0): state change: unavailable -> disconnected (reason 'supplicant-available', internal state 'managed')
Okt 19 03:13:46 XXX kernel: IPv6: ADDRCONF(NETDEV_UP): wlp58s0: link is not ready
Okt 19 03:13:46 XXX polkitd[671]: Started polkitd version 0.114
Okt 19 03:13:46 XXX polkitd[671]: Loading rules from directory /etc/polkit-1/rules.d
Okt 19 03:13:46 XXX polkitd[671]: Loading rules from directory /usr/share/polkit-1/rules.d
Okt 19 03:13:46 XXX polkitd[671]: Finished loading, compiling and executing 5 rules
Okt 19 03:13:46 XXX dbus[647]: [system] Successfully activated service 'org.freedesktop.PolicyKit1'
Okt 19 03:13:46 XXX systemd[1]: Started Authorization Manager.
Okt 19 03:13:46 XXX polkitd[671]: Acquired the name org.freedesktop.PolicyKit1 on the system bus
Okt 19 03:13:49 XXX NetworkManager[651]: <info> [1508375629.4638] device (wlp58s0): supplicant interface state: ready -> inactive
Okt 19 03:13:49 XXX NetworkManager[651]: <info> [1508375629.4729] manager: startup complete
Okt 19 03:14:13 XXX NetworkManager[651]: <info> [1508375653.7563] device (wlp58s0): supplicant interface state: inactive -> scanning
Okt 19 03:15:15 XXX systemd[1]: wpa_supplicant.service: Start operation timed out. Terminating.
Okt 19 03:15:15 XXX wpa_supplicant[652]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlp58s0/drop_unicast_in_l2_multicast: No such file or directory
Okt 19 03:15:15 XXX wpa_supplicant[652]: nl80211: Failed to set IPv4 unicast in multicast filter
Okt 19 03:15:15 XXX wpa_supplicant[652]: nl80211: Failed to open /proc/sys/net/ipv4/conf/p2p-dev-wlp58s0/drop_unicast_in_l2_multicast: No such file or directory
Okt 19 03:15:15 XXX wpa_supplicant[652]: nl80211: Failed to set IPv4 unicast in multicast filter
Okt 19 03:15:15 XXX wpa_supplicant[652]: nl80211: deinit ifname=p2p-dev-wlp58s0 disabled_11b_rates=0
Okt 19 03:15:15 XXX wpa_supplicant[652]: p2p-dev-wlp58s0: CTRL-EVENT-TERMINATING
Okt 19 03:15:15 XXX wpa_supplicant[652]: nl80211: deinit ifname=wlp58s0 disabled_11b_rates=0
Okt 19 03:15:15 XXX wpa_supplicant[652]: wlp58s0: CTRL-EVENT-TERMINATING
Okt 19 03:15:15 XXX systemd[1]: wpa_supplicant.service: Failed with result 'timeout'.
Okt 19 03:15:15 XXX systemd[1]: Failed to start WPA supplicant.
Okt 19 03:15:15 XXX NetworkManager[651]: <info> [1508375715.7247] supplicant: wpa_supplicant stopped
Okt 19 03:15:15 XXX NetworkManager[651]: <info> [1508375715.7247] device (wlp58s0): supplicant interface state: scanning -> down
Okt 19 03:15:15 XXX NetworkManager[651]: <info> [1508375715.7250] device (wlp58s0): state change: disconnected -> unavailable (reason 'supplicant-failed', internal state 'managed')
Okt 19 03:15:15 XXX systemd[1]: Reached target Network.
Okt 19 03:15:15 XXX systemd[1]: Reached target Network is Online.

Thx for help.
This task depends upon

Closed by  Doug Newgard (Scimmia)
Sunday, 29 October 2017, 14:45 GMT
Reason for closing:  Not a bug
Comment by Frank (jewelux) - Sunday, 29 October 2017, 14:17 GMT
Problem was caused by a old/deprecated service file. After deleting /etc/systemd/system/wpa_supplicant.service the problem is solved.
Task can by closed.

Loading...