[Pkg-utopia-maintainers] Bug#782973: ifup wlanX fails for x>0 because NetworkManager starts wpa_supplicant on unmanaged interface
Chris Bainbridge
chris.bainbridge at gmail.com
Sun Apr 19 22:16:50 UTC 2015
Package: network-manager
Version: 0.9.10.0-7
Severity: normal
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.
More information about the Pkg-utopia-maintainers
mailing list