NetworkManager Configs Being Ignored?

dedline · April 30, 2021, 6:01pm

Hello;

My device recently stopped respecting my NetworkManager configs and I don’t know why

I leverage a compatible USB WiFi Adapter. But instead of acting as an AP, it decides to establish a connection to the local WiFi… but that’s not his job, that’s the on-board WiFi’s job.

My NM Configs:

balena-hotspot (USB WiFi AP Config that is not being respected!)

id=QVNTRA
uuid=714d42f9-629b-4e94-b2c7-62a87fcf445f
type=wifi
interface-name=wlp1s0u1u3
permissions=

[wifi]
mac-address-blacklist=
mode=ap
ssid=QVNTRA

[wifi-security]
key-mgmt=wpa-psk
psk=*************

[ipv4]
address1=192.168.4.1/24
dns-search=
method=shared

[ipv6]
addr-gen-mode=stable-privacy
dns-search=
method=ignore

rhlh-wifi (Backup WiFi for on-board WiFi module to leverage):

[connection]
id=balena-wifi
type=wifi

[wifi]
hidden=true
mode=infrastructure
ssid=CenturyLink1456_EXT

[ipv4]
method=auto

[ipv6]
addr-gen-mode=stable-privacy
method=auto

[wifi-security]
auth-alg=open
key-mgmt=wpa-psk
psk=*************

Journalctl -fn 100 -u NetworkManager (output):

Apr 30 17:21:20 d9858b6 NetworkManager[1459]: <info>  [1619803280.3626] device (wlp1s0u1u3): supplicant interface state: authenticating -> disconnected
Apr 30 17:21:20 d9858b6 NetworkManager[1459]: <info>  [1619803280.8638] device (wlp1s0u1u3): supplicant interface state: disconnected -> scanning
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.3795] device (wlp1s0u1u3): supplicant interface state: scanning -> authenticating
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.4066] device (wlp1s0u1u3): supplicant interface state: authenticating -> associating
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.4750] device (wlp1s0u1u3): supplicant interface state: associating -> associated
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.4751] device (wlp1s0u1u3): DHCPv4 lease renewal requested
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.4989] dhcp4 (wlp1s0u1u3): canceled DHCP transaction
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.4990] dhcp4 (wlp1s0u1u3): state changed bound -> done
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.5009] dhcp4 (wlp1s0u1u3): activation: beginning transaction (no timeout)
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.5446] device (wlp1s0u1u3): supplicant interface state: associated -> 4way_handshake
Apr 30 17:21:34 d9858b6 NetworkManager[1459]: <info>  [1619803294.5510] device (wlp1s0u1u3): supplicant interface state: 4way_handshake -> completed
Apr 30 17:21:35 d9858b6 NetworkManager[1459]: <warn>  [1619803295.5563] device (wlan0): link timed out.
Apr 30 17:21:35 d9858b6 NetworkManager[1459]: <info>  [1619803295.5581] device (wlan0): state change: activated -> failed (reason 'ssid-not-found', sys-iface-state: 'managed')
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <info>  [1619803296.1139] device (wlan0): set-hw-addr: set MAC address to 86:6F:1E:6D:05:B2 (scanning)
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <info>  [1619803296.1490] dns-mgr: Writing DNS information to /sbin/resolvconf
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <warn>  [1619803296.1759] device (wlan0): Activation: failed for connection 'balena-wifi'
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <info>  [1619803296.1811] device (wlan0): supplicant interface state: scanning -> disconnected
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <info>  [1619803296.1816] device (wlan0): supplicant interface state: disconnected -> scanning
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <info>  [1619803296.1854] device (wlan0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <info>  [1619803296.2109] dhcp4 (wlan0): canceled DHCP transaction
Apr 30 17:21:36 d9858b6 NetworkManager[1459]: <info>  [1619803296.2112] dhcp4 (wlan0): state changed bound -> done
Apr 30 17:21:38 d9858b6 NetworkManager[1459]: <info>  [1619803298.9618] device (wlan0): supplicant interface state: scanning -> disconnected
Apr 30 17:21:38 d9858b6 NetworkManager[1459]: <info>  [1619803298.9684] policy: auto-activating connection 'balena-wifi' (c32b5cec-34cd-3163-ae0f-36efc76067c9)
Apr 30 17:21:38 d9858b6 NetworkManager[1459]: <info>  [1619803298.9700] device (wlan0): Activation: starting connection 'balena-wifi' (c32b5cec-34cd-3163-ae0f-36efc76067c9)
Apr 30 17:21:38 d9858b6 NetworkManager[1459]: <info>  [1619803298.9703] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5337] device (wlan0): set-hw-addr: reset MAC address to DC:A6:32:82:CF:F1 (preserve)
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5460] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5480] device (wlan0): Activation: (wifi) access point 'balena-wifi' has security, but secrets are required.
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5481] device (wlan0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5538] device (wlan0): supplicant interface state: disconnected -> inactive
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5588] device (wlan0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5599] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5612] device (wlan0): Activation: (wifi) connection 'balena-wifi' has security, and secrets exist.  No new secrets needed.
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5613] Config: added 'ssid' value 'CenturyLink1456_EXT'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5618] Config: added 'scan_ssid' value '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5619] Config: added 'bgscan' value 'simple:30:-70:86400'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5623] Config: added 'key_mgmt' value 'WPA-PSK'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5626] Config: added 'auth_alg' value 'OPEN'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.5627] Config: added 'psk' value '<hidden>'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.6256] device (wlan0): supplicant interface state: inactive -> scanning
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9302] dhcp4 (wlp1s0u1u3): option dhcp_lease_time      => '86400'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9303] dhcp4 (wlp1s0u1u3): option domain_name          => 'Home'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9303] dhcp4 (wlp1s0u1u3): option domain_name_servers  => '192.168.0.1 205.171.3.26'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9304] dhcp4 (wlp1s0u1u3): option expiry               => '1619889699'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9304] dhcp4 (wlp1s0u1u3): option ip_address           => '192.168.0.121'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9305] dhcp4 (wlp1s0u1u3): option requested_broadcast_address => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9305] dhcp4 (wlp1s0u1u3): option requested_domain_name => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9305] dhcp4 (wlp1s0u1u3): option requested_domain_name_servers => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9306] dhcp4 (wlp1s0u1u3): option requested_domain_search => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9306] dhcp4 (wlp1s0u1u3): option requested_host_name  => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9307] dhcp4 (wlp1s0u1u3): option requested_interface_mtu => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9307] dhcp4 (wlp1s0u1u3): option requested_ms_classless_static_routes => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9308] dhcp4 (wlp1s0u1u3): option requested_nis_domain => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9308] dhcp4 (wlp1s0u1u3): option requested_nis_servers => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9309] dhcp4 (wlp1s0u1u3): option requested_ntp_servers => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9309] dhcp4 (wlp1s0u1u3): option requested_rfc3442_classless_static_routes => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9309] dhcp4 (wlp1s0u1u3): option requested_root_path  => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9310] dhcp4 (wlp1s0u1u3): option requested_routers    => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9310] dhcp4 (wlp1s0u1u3): option requested_static_routes => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9311] dhcp4 (wlp1s0u1u3): option requested_subnet_mask => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9311] dhcp4 (wlp1s0u1u3): option requested_time_offset => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9311] dhcp4 (wlp1s0u1u3): option requested_wpad       => '1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9312] dhcp4 (wlp1s0u1u3): option routers              => '192.168.0.1'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9312] dhcp4 (wlp1s0u1u3): option subnet_mask          => '255.255.255.0'
Apr 30 17:21:39 d9858b6 NetworkManager[1459]: <info>  [1619803299.9313] dhcp4 (wlp1s0u1u3): state changed unknown -> bound
Apr 30 17:21:42 d9858b6 NetworkManager[1459]: <info>  [1619803302.4427] device (wlan0): supplicant interface state: scanning -> associating
Apr 30 17:21:45 d9858b6 NetworkManager[1459]: <info>  [1619803305.4766] device (wlan0): supplicant interface state: associating -> completed
Apr 30 17:21:45 d9858b6 NetworkManager[1459]: <info>  [1619803305.4767] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "CenturyLink1456_EXT"
Apr 30 17:21:45 d9858b6 NetworkManager[1459]: <info>  [1619803305.4780] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:45 d9858b6 NetworkManager[1459]: <info>  [1619803305.4838] dhcp4 (wlan0): activation: beginning transaction (no timeout)
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2257] dhcp4 (wlan0): option dhcp_lease_time      => '86400'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2258] dhcp4 (wlan0): option domain_name          => 'Home'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2258] dhcp4 (wlan0): option domain_name_servers  => '192.168.0.1 205.171.3.26'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2259] dhcp4 (wlan0): option expiry               => '1619889708'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2259] dhcp4 (wlan0): option ip_address           => '192.168.0.107'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2260] dhcp4 (wlan0): option requested_broadcast_address => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2260] dhcp4 (wlan0): option requested_domain_name => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2261] dhcp4 (wlan0): option requested_domain_name_servers => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2261] dhcp4 (wlan0): option requested_domain_search => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2262] dhcp4 (wlan0): option requested_host_name  => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2262] dhcp4 (wlan0): option requested_interface_mtu => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2262] dhcp4 (wlan0): option requested_ms_classless_static_routes => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2263] dhcp4 (wlan0): option requested_nis_domain => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2263] dhcp4 (wlan0): option requested_nis_servers => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2264] dhcp4 (wlan0): option requested_ntp_servers => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2264] dhcp4 (wlan0): option requested_rfc3442_classless_static_routes => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2265] dhcp4 (wlan0): option requested_root_path  => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2265] dhcp4 (wlan0): option requested_routers    => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2266] dhcp4 (wlan0): option requested_static_routes => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2266] dhcp4 (wlan0): option requested_subnet_mask => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2267] dhcp4 (wlan0): option requested_time_offset => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2268] dhcp4 (wlan0): option requested_wpad       => '1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2268] dhcp4 (wlan0): option routers              => '192.168.0.1'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2268] dhcp4 (wlan0): option subnet_mask          => '255.255.255.0'
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2269] dhcp4 (wlan0): state changed unknown -> bound
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2345] device (wlan0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2433] device (wlan0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2443] device (wlan0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2526] dns-mgr: Writing DNS information to /sbin/resolvconf
Apr 30 17:21:48 d9858b6 NetworkManager[1459]: <info>  [1619803308.2727] device (wlan0): Activation: successful, device activated.

This started hapenning when I plugged my WiFi USB Adapter into an Intel NUC for testing and then replugged it into my Raspberry Pi 4. Now he does want to do his job.

Anyone have a way for me to remediate this remotely and permanently? The device is at the client site. I am okay providing support access if needed!

klutchell · April 30, 2021, 6:28pm

How dare the NetworkManager not respect your config like that! Can you confirm the version of balenaOS you are running on your Raspberry Pi 4?

In your NetworkManager logs I don’t see any reference to balena-hotspot being discovered and loaded at all, can you grep the earlier logs to see if there is any mention of the config not being loaded?

journalctl -u NetworkManager --no-pager | grep balena-hotspot
journalctl -u NetworkManager --no-pager | grep QVNTRA

dedline · April 30, 2021, 6:43pm

HOST OS VERSION = balenaOS 2.69.1+rev1

It’s ignoring my configs

dedline · May 1, 2021, 11:56pm

Bump. I have proactively enabled ‘Support Access’ to expedite any help here.

Any other Balena users have this same issue?

markcorbinuk · May 3, 2021, 12:45pm

Please could you post the full UUID of your device. Thanks.

dedline · May 3, 2021, 1:44pm

Hi Mark;

UUID == d9858b6d659422cb2e233588395cb61c

dedline · May 4, 2021, 12:45pm

Lol, did you guys knock my device offline?

markcorbinuk · May 4, 2021, 2:41pm

Hello @dedline
We didn’t knock your device offline as far as I am aware. I have asked one of my colleagues to take a look at your device. We will get back to you when we have investigated further.

majorz · May 5, 2021, 10:51am

Hi, I checked your device now and I see a couple of issues.

Firstly the WiFi connection profiles are duplicated for some unknown reason to me:

root@d9858b6:/etc/NetworkManager/system-connections# ls -al
total 7
drwxr-xr-x 2 root root 1024 May  5 00:32 .
drwxr-xr-x 7 root root 1024 Mar  9  2018 ..
-rw------- 1 root root  339 May  5 00:32 balena-hotspot
-rw------- 1 root root  339 May  5 00:32 balena-hotspot.nmconnection
-rw------- 1 root root  166 May  5 00:32 cellular
-rw------- 1 root root  232 May  5 00:32 rhlh-wifi
-rw------- 1 root root  232 May  5 00:32 rhlh-wifi.nmconnection

See how there is a rhlh-wifi and a rhlh-wifi.nmconnection files with the same content. And then there are two balena-wifi profiles listed by NetworkManager:

root@d9858b6:/etc/NetworkManager/system-connections# nmcli c
NAME                UUID                                  TYPE      DEVICE      
Wired connection 1  b9630612-f9f5-3cb6-af01-5f2de3681894  ethernet  eth0        
balena-wifi         8c275c4d-6236-3ec2-89b6-66b0bb3ab4d2  wifi      wlan1       
balena-wifi         c32b5cec-34cd-3163-ae0f-36efc76067c9  wifi      wlp1s0u1u3  
supervisor0         3934805a-2b38-4205-ae2e-d4d71bf2b6fd  bridge    supervisor0 
QVNTRA              714d42f9-629b-4e94-b2c7-62a87fcf445f  wifi      --          
cellular            d811a35a-70fc-3716-84e1-a3578d10cc1e  gsm       --

That explains why the two interfaces are connected to the same network.

The second issue is that the rhlh-wifi connection profile does not bind to specific interface name as the other one does: the balena-hotspot contains interface-name=wlp1s0u1u3, but rhlh-wifi does not.

There an issue with that though as the primary interface may appear as wlan0 or wlan1. Currently it is wlan1. This is because the AP dongle was enumerated initially as wlan0 and then renamed to wlan1 by the kernel:

root@d9858b6:/etc/NetworkManager/system-connections# dmesg|grep wlan0
[    9.720545] rt2800usb 1-1.3:1.0 wlp1s0u1u3: renamed from wlan0

To solve all of this I would suggest having two rhlh-wifi connection profiles - rhlh-wifi-wlan0 and rhlh-wifi-wlan1. One that binds to wlan0 and one that binds to wlan1. The rest of the content could be the same. This way you will have all of the connection profiles bound to particular interface names and this type of issue would no longer occur.

Please let me know if you have any questions.

Thanks,
Zahari

dedline · May 5, 2021, 10:02pm

Zahari;

Thank you very much for the tutelage on NetworkManager. Everything that you wrote makes a lot of sense to me and I am moving to implement. I was going to remove the ‘rhlh-wifi’ as a last resort, but your solution allows me to resolve conflict and maintain the WiFi as our Ethernet fail-over.

Big cheers