#782973 ifup wlanX fails for x>0 because NetworkManager starts wpa_supplicant on unmanaged interface

Package:
network-manager
Source:
network-manager
Description:
network management framework (daemon and userspace tools)
Submitter:
Chris Bainbridge
Date:
2015-04-19 22:21:07 UTC
Severity:
normal
#782973#5
Date:
2015-04-19 22:16:50 UTC
From:
To:
ifup fails for a wlan interface defined in /etc/network/interfaces
when the interface is not wlan0 with  "wpa_supplicant:
/sbin/wpa_supplicant daemon failed to start"

- wlan5 is defined in /etc/network/interfaces (there is no wlan0)
- NetworkManager is running
- USB wifi inserted and driver loaded
- kernel driver creates network interface on wlan0
- systemd-udevd: renames network interface wlan0 to wlan5
- NetworkManager sets state "unavailable (reason 'managed')"
- NetworkManager starts wpa_supplicant
- NetworkManager sets state "unmanaged (reason 'unmanaged')"
- wpa_supplicant is still running
- `ifup wlan5` will now fail with:
      "wpa_supplicant: /sbin/wpa_supplicant daemon failed to start"
  because wpa_supplicant is already running.
- This does not occur if wlan0 is "unmanaged" by creating a dummy
entry in /etc/network/interfaces
- ifup will work if NetworkManager is stopped and wpa_supplicant is killed

Abbreviated log oddness:

Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): device
state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Apr 19 16:34:38 debian dbus[2894]: [system] Activating via systemd:
service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service'
Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): device
state change: unavailable -> unmanaged (reason 'unmanaged') [20 10 3]

This has been tested with two different wifi devices and the behaviour
is the same.
---
journal:

Apr 19 16:34:37 debian kernel: usb 1-1: reset high-speed USB device
number 2 using xhci_hcd
Apr 19 16:34:37 debian kernel: mt7601u 1-1:1.0: ASIC revision:
76010001 MAC revision: 76010500
Apr 19 16:34:37 debian kernel: mt7601u 1-1:1.0: Warning: unsupported
EEPROM version 0d
Apr 19 16:34:37 debian kernel: mt7601u 1-1:1.0: EEPROM ver:0d fae:00
Apr 19 16:34:38 debian kernel: ieee80211 phy2: Selected rate control
algorithm 'minstrel_ht'
Apr 19 16:34:38 debian kernel: usbcore: registered new interface driver mt7601u
Apr 19 16:34:38 debian kernel: mt7601u 1-1:1.0 wlan5: renamed from wlan0
Apr 19 16:34:38 debian NetworkManager[2871]: <info> rfkill1: found
WiFi radio killswitch (at
/sys/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0/ieee80211/phy2/rfkill1)
(driver mt7601u)
Apr 19 16:34:38 debian systemd[1]: Starting Load/Save RF Kill Switch
Status of rfkill1...
Apr 19 16:34:38 debian systemd[1]: Started Load/Save RF Kill Switch
Status of rfkill1.
Apr 19 16:34:38 debian systemd-udevd[4036]: renamed network interface
wlan0 to wlan5
Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): using
nl80211 for WiFi device control
Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): new
802.11 WiFi device (driver: 'mt7601u' ifindex: 4)
Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): exported
as /org/freedesktop/NetworkManager/Devices/3
Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): device
state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): preparing device
Apr 19 16:34:38 debian dbus[2894]: [system] Activating via systemd:
service name='fi.w1.wpa_supplicant1' unit='wpa_supplicant.service'
Apr 19 16:34:38 debian NetworkManager[2871]: <info> devices added
(path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-1/1-1:1.0/net/wlan5,
iface: wlan5)
Apr 19 16:34:38 debian NetworkManager[2871]: <info> get unmanaged
devices count: 2
Apr 19 16:34:38 debian NetworkManager[2871]: <info> (wlan5): device
state change: unavailable -> unmanaged (reason 'unmanaged') [20 10 3]
Apr 19 16:34:38 debian systemd[1]: Starting WPA supplicant...
Apr 19 16:34:38 debian dbus[2894]: [system] Successfully activated
service 'fi.w1.wpa_supplicant1'
Apr 19 16:34:38 debian systemd[1]: Started WPA supplicant.
Apr 19 16:34:38 debian wpa_supplicant[4056]: Successfully initialized
wpa_supplicant
Apr 19 16:34:38 debian kernel: IPv6: ADDRCONF(NETDEV_UP): wlan5: link
is not ready
Apr 19 16:34:38 debian kernel: IPv6: ADDRCONF(NETDEV_UP): wlan5: link
is not ready
Apr 19 16:34:38 debian NetworkManager[2871]: <info> wpa_supplicant started
--- NetworkManager debug output: NetworkManager[4782]: <debug> [1429479542.305521] [platform/nm-linux-platform.c:1850] event_notification(): netlink event (type 16) for link: wlan0 (5, family 0) NetworkManager[4782]: <debug> [1429479542.305988] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan0 (5, family 0) NetworkManager[4782]: <debug> [1429479542.307262] [nm-rfkill-manager.c:354] handle_uevent(): udev rfkill event: action 'add' device 'rfkill2' NetworkManager[4782]: <info> rfkill2: found WiFi radio killswitch (at /sys/devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3.1/1-3.1:1.0/ieee80211/phy3/rfkill2) (driver mt7601u) NetworkManager[4782]: <debug> [1429479542.307546] [nm-rfkill-manager.c:210] recheck_killswitches(): WiFi rfkill switch rfkill2 state now 1/0 NetworkManager[4782]: <debug> [1429479542.307654] [nm-rfkill-manager.c:210] recheck_killswitches(): WiFi rfkill switch rfkill0 state now 1/0 NetworkManager[4782]: <debug> [1429479542.312108] [platform/nm-linux-platform.c:1850] event_notification(): netlink event (type 16) for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.312179] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.315068] [platform/nm-linux-platform.c:3958] handle_udev_event(): UDEV event: action 'add' subsys 'net' device 'wlan5' (5); seqnum=2168 NetworkManager[4782]: <debug> [1429479542.324323] [platform/nm-platform.c:2565] log_link(): signal: link added: 5: wlan5 <DOWN> mtu 1500 wifi driver 'mt7601u' udi '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3.1/1-3.1:1.0/net/wlan5' NetworkManager[4782]: <debug> [1429479542.324437] [nm-device-wifi.c:228] constructor(): (wlan5): kernel ifindex 5 NetworkManager[4782]: <debug> [1429479542.324573] [platform/wifi/wifi-utils-nl80211.c:799] nl80211_wiphy_info_handler(): Don't know the meaning of NL80211_ATTR_CIPHER_SUITE 0x000fac0a. NetworkManager[4782]: <debug> [1429479542.324589] [platform/wifi/wifi-utils-nl80211.c:799] nl80211_wiphy_info_handler(): Don't know the meaning of NL80211_ATTR_CIPHER_SUITE 0x000fac09. NetworkManager[4782]: <info> (wlan5): using nl80211 for WiFi device control NetworkManager[4782]: <debug> [1429479542.324619] [devices/nm-device.c:6987] nm_device_update_hw_address(): (wlan5): hardware address is 7C:DD:90:73:1F:4C NetworkManager[4782]: <debug> [1429479542.324645] [nm-device-wifi.c:2623] update_initial_hw_address(): (wlan5): read initial MAC address 7C:DD:90:73:1F:4C NetworkManager[4782]: <debug> [1429479542.324714] [platform/nm-linux-platform.c:2099] sysctl_get(): error reading /sys/class/net/wlan5/phys_port_id: Failed to read from file '/sys/class/net/wlan5/phys_port_id': Operation not supported NetworkManager[4782]: <debug> [1429479542.324804] [nm-manager.c:1404] manager_rfkill_update_one_type(): WiFi hw-enabled 1 sw-enabled 1 NetworkManager[4782]: <debug> [1429479542.324815] [nm-device-wifi.c:3230] set_enabled(): (wlan5): device now enabled NetworkManager[4782]: <debug> [1429479542.324823] [nm-device-wifi.c:3236] set_enabled(): (enable): wlan5 blocked by UNMANAGED state NetworkManager[4782]: <info> (wlan5): new 802.11 WiFi device (driver: 'mt7601u' ifindex: 5) NetworkManager[4782]: <info> (wlan5): exported as /org/freedesktop/NetworkManager/Devices/4 NetworkManager[4782]: <debug> [1429479542.324993] [devices/nm-device.c:5093] nm_device_set_ip4_config(): (wlan5): set IP4Config instance (/org/freedesktop/NetworkManager/IP4Config/1) NetworkManager[4782]: <debug> [1429479542.325097] [devices/nm-device.c:5201] nm_device_set_ip6_config(): (wlan5): set IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/1) NetworkManager[4782]: <info> (wlan5): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] NetworkManager[4782]: <debug> [1429479542.325197] [platform/nm-linux-platform.c:2067] _log_dbg_sysctl_get_impl(): sysctl: reading '/proc/sys/net/ipv6/conf/wlan5/accept_ra': '1' NetworkManager[4782]: <debug> [1429479542.325377] [platform/nm-linux-platform.c:2067] _log_dbg_sysctl_get_impl(): sysctl: reading '/proc/sys/net/ipv6/conf/wlan5/accept_ra_defrtr': '1' NetworkManager[4782]: <debug> [1429479542.325585] [platform/nm-linux-platform.c:2067] _log_dbg_sysctl_get_impl(): sysctl: reading '/proc/sys/net/ipv6/conf/wlan5/accept_ra_pinfo': '1' NetworkManager[4782]: <debug> [1429479542.325752] [platform/nm-linux-platform.c:2099] sysctl_get(): error reading /proc/sys/net/ipv6/conf/wlan5/accept_ra_rtr_pref: Failed to open file '/proc/sys/net/ipv6/conf/wlan5/accept_ra_rtr_pref': No such file or directory NetworkManager[4782]: <debug> [1429479542.325943] [platform/nm-linux-platform.c:2067] _log_dbg_sysctl_get_impl(): sysctl: reading '/proc/sys/net/ipv6/conf/wlan5/disable_ipv6': '0' NetworkManager[4782]: <debug> [1429479542.326144] [platform/nm-linux-platform.c:2067] _log_dbg_sysctl_get_impl(): sysctl: reading '/proc/sys/net/ipv6/conf/wlan5/hop_limit': '64' NetworkManager[4782]: <debug> [1429479542.326326] [platform/nm-linux-platform.c:2067] _log_dbg_sysctl_get_impl(): sysctl: reading '/proc/sys/net/ipv6/conf/wlan5/use_tempaddr': '0' NetworkManager[4782]: <debug> [1429479542.326478] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/disable_ipv6' to '1' (current value is '0') NetworkManager[4782]: <debug> [1429479542.326641] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/accept_ra_defrtr' to '0' (current value is '1') NetworkManager[4782]: <debug> [1429479542.326780] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/accept_ra_pinfo' to '0' (current value is '1') NetworkManager[4782]: <debug> [1429479542.326910] [platform/nm-linux-platform.c:2000] sysctl_set(): sysctl: failed to open '/proc/sys/net/ipv6/conf/wlan5/accept_ra_rtr_pref': (2) No such file or directory NetworkManager[4782]: <debug> [1429479542.327104] [platform/nm-linux-platform.c:1965] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/use_tempaddr' to '0' (current value is identical) NetworkManager[4782]: <debug> [1429479542.327224] [devices/nm-device.c:5546] nm_device_bring_up(): (wlan5): bringing up device. NetworkManager[4782]: <debug> [1429479542.327358] [platform/nm-platform.c:806] nm_platform_link_set_up(): link: setting up 'wlan5' (5) NetworkManager[4782]: <debug> [1429479542.327505] [platform/nm-linux-platform.c:2356] link_change_flags(): link: change 5: flags set 'up' (1) NetworkManager[4782]: <debug> [1429479542.327740] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.327937] [platform/nm-platform.c:2565] log_link(): signal: link changed: 5: wlan5 <UP> mtu 1500 wifi driver 'mt7601u' udi '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3.1/1-3.1:1.0/net/wlan5' NetworkManager[4782]: <info> (wlan5): preparing device NetworkManager[4782]: <debug> [1429479542.328275] [devices/nm-device.c:6400] nm_device_remove_pending_action(): (wlan5): remove_pending_action (0): 'autoconf6' not pending (expected) NetworkManager[4782]: <debug> [1429479542.328490] [platform/nm-linux-platform.c:1965] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/disable_ipv6' to '1' (current value is identical) NetworkManager[4782]: <debug> [1429479542.328691] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/accept_ra' to '0' (current value is '1') NetworkManager[4782]: <debug> [1429479542.328853] [platform/nm-linux-platform.c:1965] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/use_tempaddr' to '0' (current value is identical) NetworkManager[4782]: <debug> [1429479542.329016] [devices/nm-device.c:7028] nm_device_set_hw_addr(): (wlan5): no MAC address change needed NetworkManager[4782]: <debug> [1429479542.329206] [NetworkManagerUtils.c:1052] monotonic_timestamp_get(): monotonic timestamp started counting 1.329189747 seconds ago with an offset of 9595.0 seconds to CLOCK_BOOTTIME (local time is 2015-04-19 22:39:02) NetworkManager[4782]: <debug> [1429479542.329333] [devices/nm-device.c:5099] nm_device_set_ip4_config(): (wlan5): clear IP4Config instance (/org/freedesktop/NetworkManager/IP4Config/1) NetworkManager[4782]: <debug> [1429479542.329542] [devices/nm-device.c:5207] nm_device_set_ip6_config(): (wlan5): clear IP6Config instance (/org/freedesktop/NetworkManager/IP6Config/1) NetworkManager[4782]: <debug> [1429479542.329808] [supplicant-manager/nm-supplicant-manager.c:90] nm_supplicant_manager_iface_get(): (wlan5): creating new supplicant interface NetworkManager[4782]: <debug> [1429479542.329958] [supplicant-manager/nm-supplicant-interface.c:881] interface_add(): (wlan5): adding interface to supplicant NetworkManager[4782]: <debug> [1429479542.330156] [devices/nm-device.c:6346] nm_device_add_pending_action(): (wlan5): add_pending_action (1): 'waiting for supplicant' NetworkManager[4782]: <debug> [1429479542.330305] [nm-device-wifi.c:1192] is_available(): (wlan5): not available because supplicant interface not ready NetworkManager[4782]: <debug> [1429479542.330482] [devices/nm-device.c:6709] _set_state_full(): (wlan5): device not yet available for transition to DISCONNECTED NetworkManager[4782]: <debug> [1429479542.330754] [nm-manager.c:1166] system_create_virtual_devices(): creating virtual devices... NetworkManager[4782]: <info> devices added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3.1/1-3.1:1.0/net/wlan5, iface: wlan5) NetworkManager[4782]: <info> get unmanaged devices count: 2 NetworkManager[4782]: <debug> [1429479542.331472] [devices/nm-device.c:5979] nm_device_set_unmanaged(): (wlan5): now unmanaged NetworkManager[4782]: <info> (wlan5): device state change: unavailable -> unmanaged (reason 'unmanaged') [20 10 3] NetworkManager[4782]: <debug> [1429479542.331700] [devices/nm-device.c:5634] nm_device_take_down(): (wlan5): taking down device. NetworkManager[4782]: <debug> [1429479542.331848] [platform/nm-platform.c:824] nm_platform_link_set_down(): link: setting down 'wlan5' (5) NetworkManager[4782]: <debug> [1429479542.332012] [platform/nm-linux-platform.c:2356] link_change_flags(): link: change 5: flags unset 'up' (1) NetworkManager[4782]: <debug> [1429479542.734982] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.735114] [platform/nm-platform.c:2565] log_link(): signal: link changed: 5: wlan5 <DOWN> mtu 1500 wifi driver 'mt7601u' udi '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3.1/1-3.1:1.0/net/wlan5' NetworkManager[4782]: <debug> [1429479542.735203] [platform/nm-linux-platform.c:1965] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/use_tempaddr' to '0' (current value is identical) NetworkManager[4782]: <debug> [1429479542.735262] [platform/nm-linux-platform.c:1965] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/hop_limit' to '64' (current value is identical) NetworkManager[4782]: <debug> [1429479542.735314] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/accept_ra_pinfo' to '1' (current value is '0') NetworkManager[4782]: <debug> [1429479542.735361] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/disable_ipv6' to '0' (current value is '1') NetworkManager[4782]: <debug> [1429479542.735414] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/accept_ra' to '1' (current value is '0') NetworkManager[4782]: <debug> [1429479542.735460] [platform/nm-linux-platform.c:1967] _log_dbg_sysctl_set_impl(): sysctl: setting '/proc/sys/net/ipv6/conf/wlan5/accept_ra_defrtr' to '1' (current value is '0') NetworkManager[4782]: <debug> [1429479542.735643] [platform/nm-linux-platform.c:1850] event_notification(): netlink event (type 16) for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.735699] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.735776] [platform/nm-linux-platform.c:3958] handle_udev_event(): UDEV event: action 'move' subsys 'net' device 'wlan5' (5); seqnum=2175 NetworkManager[4782]: <debug> [1429479542.735907] [platform/nm-platform.c:2565] log_link(): signal: link changed: 5: wlan5 <DOWN> mtu 1500 wifi driver 'mt7601u' udi '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-3/1-3.1/1-3.1:1.0/net/wlan5' NetworkManager[4782]: <debug> [1429479542.736028] [platform/nm-linux-platform.c:1850] event_notification(): netlink event (type 16) for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.736081] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.736129] [platform/nm-linux-platform.c:1850] event_notification(): netlink event (type 16) for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.736176] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.736252] [platform/nm-linux-platform.c:1850] event_notification(): netlink event (type 16) for link: wlan5 (5, family 0) NetworkManager[4782]: <debug> [1429479542.736419] [platform/nm-linux-platform.c:412] get_kernel_object(): get_kernel_object for link: wlan5 (5, family 0)
--- ifup wpa_supplicant error log: Apr 19 16:39:00 debian wpa_supplicant[4087]: Successfully initialized wpa_supplicant Apr 19 16:39:00 debian wpa_supplicant[4087]: ctrl_iface exists and seems to be in use - cannot override it Apr 19 16:39:00 debian wpa_supplicant[4087]: Delete '/run/wpa_supplicant/wlan5' manually if it is not used anymore Apr 19 16:39:00 debian wpa_supplicant[4087]: Failed to initialize control interface '/run/wpa_supplicant'. You may have another wpa_supplicant process already running or the file was left by an unclean termination of wpa_supplicant in which case you will need to manually remove this file before starting wpa_supplicant again.