nm 1.8.2 problem bring up wifi interface

[Belisko Marek <marek belisko gmail com>]

Hi,

I'm trying to use for my project networkmanager. I've build image
using yocto with nm v1.8.2. On my HW I'm using SDIO wifi chip
(esp8089) which I can operate with wpa_supplicant and simple config
file. When try to use it with networkmanager nmclo device show wlan0
as unavailable. When checked logs it seems that wpa_supplicant cannot
bring interface up because somebody else is trying to do the same.
I've added process name to kernel driver code (can be seen in kernel
messages like: esp_op_add_interface interface 2 requested by -
NetworkManager - 231). When looking through log it seems that nm is
trying to add wireless interface but also wpa_supplicant which then
driver refuse as max interfaces is 2 (also not sure what it means).
Anything else I can check or how to workaround this probem? (when
using raspbian wifi with nm works fine).

/var/log/messages log:
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.1871] NetworkManager (version 1.8.2) is starting... (for
the first time)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.1876] Read config: /etc/NetworkManager/NetworkManager.conf
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.2550] manager[0x141a068]: monitoring kernel firmware
directory '/lib/firmware'.
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.2664] policy: hostname management mode: default
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.2680] dns-mgr[0x1413ac8]: init: dns=default,
rc-manager=symlink
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.2731] rfkill0: found WiFi radio killswitch (at
/sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1/ieee80211/phy0/rfkill0)
(driver eagle_sdio)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.2742] manager[0x141a068]: rfkill: WiFi hardware radio set
enabled
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.2743] manager[0x141a068]: rfkill: WWAN hardware radio set
enabled
Nov 25 22:40:57 rpi daemon.info systemd[1]: Started Network Manager.
Nov 25 22:40:57 rpi daemon.info systemd[1]: Starting Network Manager
Script Dispatcher Service...
Nov 25 22:40:57 rpi daemon.info systemd[1]: Reached target Network.
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.4656] settings: loaded plugin keyfile: (c) 2007 - 2016 Red
Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Nov 25 22:40:57 rpi daemon.info systemd[1]: Started Network Manager
Script Dispatcher Service.
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.8862] settings: hostname: using hostnamed
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.8864] settings: hostname changed from (none) to "rpi"
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.8946] dhcp-init: Using DHCP client 'dhclient'
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.8948] manager: rfkill: WiFi enabled by radio killswitch;
enabled by state file
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.8951] manager: rfkill: WWAN enabled by radio killswitch;
enabled by state file
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.8952] manager: Networking is enabled by state file
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9027] Loaded device plugin: NMBondDeviceFactory (internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9029] Loaded device plugin: NMBridgeDeviceFactory
(internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9030] Loaded device plugin: NMDummyDeviceFactory
(internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9032] Loaded device plugin: NMEthernetDeviceFactory
(internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9033] Loaded device plugin: NMInfinibandDeviceFactory
(internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9034] Loaded device plugin: NMIPTunnelDeviceFactory
(internal)
Nov 25 22:40:57 rpi daemon.info systemd[1]: Startup finished in 4.123s
(kernel) + 5.256s (userspace) = 9.380s.
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9073] Loaded device plugin: NMMacsecDeviceFactory
(internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9075] Loaded device plugin: NMMacvlanDeviceFactory
(internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9076] Loaded device plugin: NMTunDeviceFactory (internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9077] Loaded device plugin: NMVethDeviceFactory (internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9079] Loaded device plugin: NMVlanDeviceFactory (internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9080] Loaded device plugin: NMVxlanDeviceFactory
(internal)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9482] Loaded device plugin: NMWifiFactory
(/usr/lib/NetworkManager/libnm-device-plugin-wifi.so)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9589] device (lo): link connected
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9647] manager: (lo): new Generic device
(/org/freedesktop/NetworkManager/Devices/1)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9677] wifi-nl80211: (wlan0): using nl80211 for WiFi device
control
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9693] device (wlan0): driver supports Access Point (AP)
mode
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9771] manager: (wlan0): new 802.11 WiFi device
(/org/freedesktop/NetworkManager/Devices/2)
Nov 25 22:40:57 rpi kern.info NetworkManager[231]: <info>
[1511649657.9866] device (wlan0): state change: unmanaged ->
unavailable (reason 'managed', internal state 'external')
Nov 25 22:40:58 rpi user.info kernel: [    9.476452] IPv6:
ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov 25 22:40:58 rpi user.warn kernel: [    9.482897]
esp_op_add_interface interface 0 requested by - NetworkManager - 231
Nov 25 22:40:58 rpi user.warn kernel: [    9.490304] esp_op_add_interface STA
Nov 25 22:40:58 rpi user.info kernel: [    9.495224] IPv6:
ADDRCONF(NETDEV_UP): wlan0: link is not ready
Nov 25 22:40:58 rpi kern.info NetworkManager[231]: <info>
[1511649658.0166] device (wlan0): set-hw-addr: set MAC address to
26:2F:1A:C7:05:F4 (scanning)
Nov 25 22:40:58 rpi user.warn kernel: [    9.504764]
esp_op_add_interface interface 2 requested by - NetworkManager - 231
Nov 25 22:40:58 rpi user.warn kernel: [    9.512234]
esp_op_add_interface only support MAX 2 interface
Nov 25 22:40:58 rpi user.warn kernel: [    9.518421]
esp_op_add_interface interface 2 requested by - NetworkManager - 231
Nov 25 22:40:58 rpi user.warn kernel: [    9.525953]
esp_op_add_interface interface 2 already used - NetworkManager -231
Nov 25 22:40:58 rpi kern.err NetworkManager[231]: <error>
[1511649658.0458] platform-linux: do-change-link[2]: failure changing
link: failure 95 (Operation not supported)
Nov 25 22:40:58 rpi daemon.notice dbus[210]: [system] Activating via
systemd: service name='fi.w1.wpa_supplicant1'
unit='wpa_supplicant.service'
Nov 25 22:40:58 rpi daemon.notice dbus[210]: [system] Successfully
activated service 'fi.w1.wpa_supplicant1'
Nov 25 22:40:58 rpi daemon.info wpa_supplicant[269]: Successfully
initialized wpa_supplicant
Nov 25 22:40:58 rpi kern.info NetworkManager[231]: <info>
[1511649658.2930] supplicant: wpa_supplicant running
Nov 25 22:40:58 rpi kern.info NetworkManager[231]: <info>
[1511649658.2933] device (wlan0): supplicant interface state: init ->
starting
Nov 25 22:40:58 rpi user.warn kernel: [    9.803109]
esp_op_add_interface interface 2 requested by - wpa_supplicant - 269
Nov 25 22:40:58 rpi daemon.info wpa_supplicant[269]: Could not set
interface wlan0 flags (UP): Operation not supported
Nov 25 22:40:58 rpi daemon.info wpa_supplicant[269]: nl80211: Could
not set interface 'wlan0' UP
Nov 25 22:40:58 rpi daemon.info wpa_supplicant[269]: nl80211: deinit
ifname=wlan0 disabled_11b_rates=0
Nov 25 22:40:58 rpi user.warn kernel: [    9.810535]
esp_op_add_interface interface 2 already used - wpa_supplicant -269
Nov 25 22:40:58 rpi user.warn kernel: [    9.821740]
esp_op_add_interface interface 2 requested by - wpa_supplicant - 269
Nov 25 22:40:58 rpi user.warn kernel: [    9.829232]
esp_op_add_interface interface 2 already used - wpa_supplicant -269
Nov 25 22:40:58 rpi daemon.info wpa_supplicant[269]: Could not set
interface wlan0 flags (UP): Operation not supported
Nov 25 22:40:58 rpi daemon.info wpa_supplicant[269]: WEXT: Could not
set interface 'wlan0' UP
Nov 25 22:40:58 rpi daemon.info wpa_supplicant[269]: wlan0: Failed to
initialize driver interface
Nov 25 22:40:58 rpi kern.err NetworkManager[231]: <error>
[1511649658.3508] sup-iface[0x145a660,wlan0]: error adding interface:
wpa_supplicant couldn't grab this interface.
Nov 25 22:40:58 rpi kern.info NetworkManager[231]: <info>
[1511649658.3510] device (wlan0): supplicant interface state: starting
-> down
Nov 25 22:40:58 rpi kern.info NetworkManager[231]: <info>
[1511649658.3515] manager: startup complete
Nov 25 22:41:08 rpi kern.warn NetworkManager[231]: <warn>
[1511649668.5258] device (wlan0): re-acquiring supplicant interface
(#1).
Nov 25 22:41:08 rpi user.warn kernel: [   20.020842]
esp_op_add_interface interface 2 requested by - wpa_supplicant - 269
Nov 25 22:41:08 rpi daemon.info wpa_supplicant[269]: Could not set
interface wlan0 flags (UP): Operation not supported
Nov 25 22:41:08 rpi daemon.info wpa_supplicant[269]: nl80211: Could
not set interface 'wlan0' UP
Nov 25 22:41:08 rpi daemon.info wpa_supplicant[269]: nl80211: deinit
ifname=wlan0 disabled_11b_rates=0
Nov 25 22:41:08 rpi user.warn kernel: [   20.028316]
esp_op_add_interface interface 2 already used - wpa_supplicant -269
Nov 25 22:41:08 rpi user.warn kernel: [   20.036895]
esp_op_add_interface interface 2 requested by - wpa_supplicant - 269
Nov 25 22:41:08 rpi user.warn kernel: [   20.044346]
esp_op_add_interface interface 2 already used - wpa_supplicant -269
Nov 25 22:41:08 rpi daemon.info wpa_supplicant[269]: Could not set
interface wlan0 flags (UP): Operation not supported
Nov 25 22:41:08 rpi daemon.info wpa_supplicant[269]: WEXT: Could not
set interface 'wlan0' UP
Nov 25 22:41:08 rpi daemon.info wpa_supplicant[269]: wlan0: Failed to
initialize driver interface
Nov 25 22:41:08 rpi kern.err NetworkManager[231]: <error>
[1511649668.5652] sup-iface[0x145a6c0,wlan0]: error adding interface:
wpa_supplicant couldn't grab this interface.
Nov 25 22:41:08 rpi kern.info NetworkManager[231]: <info>
[1511649668.5654] device (wlan0): supplicant interface state: starting
-> down
Nov 25 22:41:18 rpi kern.warn NetworkManager[231]: <warn>
[1511649678.5348] device (wlan0): re-acquiring supplicant interface
(#2).
Nov 25 22:41:18 rpi user.warn kernel: [   30.029780]
esp_op_add_interface interface 2 requested by - wpa_supplicant - 269
Nov 25 22:41:18 rpi daemon.info wpa_supplicant[269]: Could not set
interface wlan0 flags (UP): Operation not supported
Nov 25 22:41:18 rpi daemon.info wpa_supplicant[269]: nl80211: Could
not set interface 'wlan0' UP
Nov 25 22:41:18 rpi daemon.info wpa_supplicant[269]: nl80211: deinit
ifname=wlan0 disabled_11b_rates=0
Nov 25 22:41:18 rpi user.warn kernel: [   30.037257]
esp_op_add_interface interface 2 already used - wpa_supplicant -269
Nov 25 22:41:18 rpi user.warn kernel: [   30.045852]
esp_op_add_interface interface 2 requested by - wpa_supplicant - 269
Nov 25 22:41:18 rpi user.warn kernel: [   30.053300]
esp_op_add_interface interface 2 already used - wpa_supplicant -269
Nov 25 22:41:18 rpi daemon.info wpa_supplicant[269]: Could not set
interface wlan0 flags (UP): Operation not supported

Thanks and BR,

marek
-- 
as simple and primitive as possible
-------------------------------------------------
Marek Belisko - OPEN-NANDRA
Freelance Developer

Ruska Nova Ves 219 | Presov, 08005 Slovak Republic
Tel: +421 915 052 184
skype: marekwhite
twitter: #opennandra
web: http://open-nandra.com