balenaOS 2.68 wifi reconnect issues

Product support balenaOS
1

BalenaOS Version 2.68.1+rev1 / Supervisor 12.9.3

Our BalenaOS device connects via wifi to another device to retrieve data. The other device can sometimes be power cycled or otherwise disconnect from wifi, and when it comes back online our BalenaOS device fails to reconnect.

Some additional data points:

  • This issue has only been seen after upgrading to BalenaOS 2.68, and not on other devices running 2.50 and earlier. The connection configuration is the same across both versions. The version of NetworkManager changed from 1.20.2 to 1.28.0 somewhere along the way
  • The BalenaOS device still “sees” the other device’s wifi but will not reconnect automatically. By “see” I mean the access point shows up in the list if you run nmcli device wifi in the terminal on the host OS
  • There are no issues reconnecting via the command line, but that isn’t a workable solution for our fleet. Running nmcli device wifi connect <SSID> works just fine to force a re connection.
  • The other device has a ~10s boot up cycle and the wifi will occasionally fail to authenticate, and then succeed on retry.

Any help or understanding what might have changed between versions would be appreciated.
ConorB

3

Hi, there could be some indications in the NetworkManager log on why it does not reconnect. Can you please grab those when this happens again and attach them here so that I can take a look at them - you may grab those with journalctl -u NetworkManager. The problem does not necessary has to do with NetworkManager as it could be in wpa_supplicant, the WiFi drivers and so on. Also is the other device that serves as access point to the balena device the same across deployments?
Thanks,
Zahari

4

Thanks @majorz. I’m pasting a log sequence below with some annotations. The issue can be reliably reproduced (happens every time in the same way). The other device is the same across deployments, and we don’t have any control around how the wifi works on that device.

-- Reboot --
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9760] NetworkManager (version 1.28.0) is starting... (for the first time)
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9760] Read config: /etc/NetworkManager/NetworkManager.conf (etc: os-networkmanager.conf)
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9773] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9828] manager[0x55d186410080]: monitoring kernel firmware directory '/lib/firmware'.
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9847] hostname: hostname: using hostnamed
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9847] hostname: hostname changed from (none) to "25e052a"
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9850] dns-mgr[0x55d1863fa270]: init: dns=default,systemd-resolved rc-manager=resolvconf (auto)
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9857] rfkill1: found Wi-Fi radio killswitch (at /sys/devices/pci0000:00/0000:00:14.3/ieee80211/phy0/rfkill1) (driver iwlwifi)
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9858] manager[0x55d186410080]: rfkill: Wi-Fi hardware radio set enabled
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9858] manager[0x55d186410080]: rfkill: WWAN hardware radio set enabled
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9922] Loaded device plugin: NMWwanFactory (/usr/lib/NetworkManager/1.28.0/libnm-device-plugin-wwan.so)
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9935] Loaded device plugin: NMAtmManager (/usr/lib/NetworkManager/1.28.0/libnm-device-plugin-adsl.so)
Jul 29 22:45:20 25e052a NetworkManager[1069]: <info>  [1627598720.9988] Loaded device plugin: NMWifiFactory (/usr/lib/NetworkManager/1.28.0/libnm-device-plugin-wifi.so)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0034] Loaded device plugin: NMBluezManager (/usr/lib/NetworkManager/1.28.0/libnm-device-plugin-bluetooth.so)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0037] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0037] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0039] manager: Networking is enabled by state file
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0040] dhcp-init: Using DHCP client 'internal'
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0062] settings: Loaded settings plugin: keyfile (internal)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0155] device (lo): carrier: link connected
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0158] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0166] manager: (eno1): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0180] settings: (eno1): created default wired connection 'Wired connection 1'
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.0188] device (eno1): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.2000] manager: (resin-dns): new Bridge device (/org/freedesktop/NetworkManager/Devices/3)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.2007] manager: (sit0): new IPTunnel device (/org/freedesktop/NetworkManager/Devices/4)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.2010] device (wlp0s20f3): driver supports Access Point (AP) mode
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.2015] manager: (wlp0s20f3): new 802.11 Wi-Fi device (/org/freedesktop/NetworkManager/Devices/5)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.2021] device (wlp0s20f3): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.4031] modem-manager: ModemManager available
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.4287] device (wlp0s20f3): supplicant interface state: internal-starting -> disconnected
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.4287] device (wlp0s20f3): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6509] manager: (supervisor0): new Bridge device (/org/freedesktop/NetworkManager/Devices/6)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6711] device (supervisor0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <warn>  [1627598721.6727] device (supervisor0): failed to read bridge setting 'vlan_protocol'
Jul 29 22:45:21 25e052a NetworkManager[1069]: <warn>  [1627598721.6728] device (supervisor0): failed to read bridge setting 'vlan_stats_enabled'
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6740] device (supervisor0): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6748] device (supervisor0): Activation: starting connection 'supervisor0' (1591b819-5c06-41eb-860e-66bf61bdd71c)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6753] manager: (balena0): new Bridge device (/org/freedesktop/NetworkManager/Devices/7)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6759] device (supervisor0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6762] device (supervisor0): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6766] device (supervisor0): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6769] device (supervisor0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6784] device (supervisor0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6787] device (supervisor0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6793] manager: NetworkManager state is now CONNECTED_LOCAL
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6807] policy: set-hostname: set hostname to '25e052a' (from system configuration)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6808] device (supervisor0): Activation: successful, device activated.
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.6929] manager: (br-6702f10e2a1a): new Bridge device (/org/freedesktop/NetworkManager/Devices/8)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.7798] manager: (veth6d8093e): new Veth device (/org/freedesktop/NetworkManager/Devices/9)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.7817] manager: (veth6bc9930): new Veth device (/org/freedesktop/NetworkManager/Devices/10)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.8393] manager: (veth1162b03): new Veth device (/org/freedesktop/NetworkManager/Devices/11)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.8408] manager: (veth286f5f9): new Veth device (/org/freedesktop/NetworkManager/Devices/12)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.9002] manager: (vethe3d5475): new Veth device (/org/freedesktop/NetworkManager/Devices/13)
Jul 29 22:45:21 25e052a NetworkManager[1069]: <info>  [1627598721.9011] manager: (vethc458127): new Veth device (/org/freedesktop/NetworkManager/Devices/14)
Jul 29 22:45:22 25e052a NetworkManager[1069]: <info>  [1627598722.3165] device (veth286f5f9): carrier: link connected
Jul 29 22:45:22 25e052a NetworkManager[1069]: <info>  [1627598722.3168] device (veth6bc9930): carrier: link connected
Jul 29 22:45:22 25e052a NetworkManager[1069]: <info>  [1627598722.3170] device (br-6702f10e2a1a): carrier: link connected
Jul 29 22:45:22 25e052a NetworkManager[1069]: <info>  [1627598722.3347] device (vethc458127): carrier: link connected
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7921] device (eno1): carrier: link connected
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7926] device (eno1): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7937] policy: auto-activating connection 'Wired connection 1' (f1bdf79d-590f-323f-966c-81453b7b6ee7)
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7944] device (eno1): Activation: starting connection 'Wired connection 1' (f1bdf79d-590f-323f-966c-81453b7b6ee7)
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7946] device (eno1): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7950] manager: NetworkManager state is now CONNECTING
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7953] device (eno1): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7959] device (eno1): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Jul 29 22:45:25 25e052a NetworkManager[1069]: <info>  [1627598725.7964] dhcp4 (eno1): activation: beginning transaction (no timeout)
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8414] dhcp4 (eno1): option dhcp_lease_time      => '86400'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8414] dhcp4 (eno1): option domain_name          => 'localdomain'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8414] dhcp4 (eno1): option domain_name_servers  => '192.168.2.1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8414] dhcp4 (eno1): option expiry               => '1627685127'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option host_name            => '25e052a'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option ip_address           => '192.168.2.167'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option next_server          => '192.168.2.1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_broadcast_address => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_domain_name => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_domain_name_servers => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_domain_search => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_host_name  => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_interface_mtu => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_ms_classless_static_routes => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_nis_domain => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_nis_servers => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_ntp_servers => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_rfc3442_classless_static_routes => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_root_path  => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_routers    => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_static_routes => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_subnet_mask => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_time_offset => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option requested_wpad       => '1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8415] dhcp4 (eno1): option routers              => '192.168.2.1'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8416] dhcp4 (eno1): option subnet_mask          => '255.255.255.0'
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8416] dhcp4 (eno1): state changed unknown -> bound
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8425] device (eno1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8438] device (eno1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8440] device (eno1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8444] manager: NetworkManager state is now CONNECTED_LOCAL
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8452] manager: NetworkManager state is now CONNECTED_SITE
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8453] policy: set 'Wired connection 1' (eno1) as default for IPv4 routing and DNS
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8456] dns-mgr: Writing DNS information to /sbin/resolvconf
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8523] device (eno1): Activation: successful, device activated.
Jul 29 22:45:27 25e052a NetworkManager[1069]: <info>  [1627598727.8529] manager: startup complete
Jul 29 22:45:28 25e052a NetworkManager[1069]: <info>  [1627598728.0209] manager: NetworkManager state is now CONNECTED_GLOBAL
Jul 29 22:45:33 25e052a NetworkManager[1069]: <info>  [1627598733.4245] manager: (resin-vpn): new Tun device (/org/freedesktop/NetworkManager/Devices/15)
(TURNED ON EXTERNAL DEVICE)
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0434] policy: auto-activating connection 'REDACTED-cz65' (059a20da-4cf3-47f8-a96a-094d3b003d65)
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0438] device (wlp0s20f3): Activation: starting connection 'REDACTED-cz65' (059a20da-4cf3-47f8-a96a-094d3b003d65)
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0439] device (wlp0s20f3): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0445] device (wlp0s20f3): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0448] device (wlp0s20f3): Activation: (wifi) access point 'REDACTED-cz65' has security, but secrets are required.
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0448] device (wlp0s20f3): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0464] device (wlp0s20f3): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0467] device (wlp0s20f3): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0470] device (wlp0s20f3): Activation: (wifi) connection 'REDACTED-cz65' has security, and secrets exist.  No new secrets needed.
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0470] Config: added 'ssid' value 'REDACTED-cz65'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0470] Config: added 'scan_ssid' value '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0470] Config: added 'bgscan' value 'simple:30:-70:86400'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0470] Config: added 'key_mgmt' value 'WPA-PSK'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0471] Config: added 'auth_alg' value 'OPEN'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0471] Config: added 'psk' value '<hidden>'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0608] device (wlp0s20f3): supplicant interface state: disconnected -> authenticating
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.0971] device (wlp0s20f3): supplicant interface state: authenticating -> associating
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1055] device (wlp0s20f3): supplicant interface state: associating -> 4way_handshake
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1197] device (wlp0s20f3): supplicant interface state: 4way_handshake -> completed
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1197] device (wlp0s20f3): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "REDACTED-cz65"
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1198] device (wlp0s20f3): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1202] dhcp4 (wlp0s20f3): activation: beginning transaction (no timeout)
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option dhcp_lease_time      => '86400'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option expiry               => '1627700652'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option host_name            => '25e052a'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option ip_address           => '192.168.10.57'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option next_server          => '192.168.10.1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option requested_broadcast_address => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option requested_domain_name => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option requested_domain_name_servers => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option requested_domain_search => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option requested_host_name  => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option requested_interface_mtu => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1317] dhcp4 (wlp0s20f3): option requested_ms_classless_static_routes => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_nis_domain => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_nis_servers => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_ntp_servers => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_rfc3442_classless_static_routes => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_root_path  => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_routers    => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_static_routes => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_subnet_mask => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_time_offset => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option requested_wpad       => '1'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): option subnet_mask          => '255.255.255.0'
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1318] dhcp4 (wlp0s20f3): state changed unknown -> bound
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1329] device (wlp0s20f3): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1428] device (wlp0s20f3): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1430] device (wlp0s20f3): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Jul 30 03:04:12 25e052a NetworkManager[1069]: <info>  [1627614252.1449] device (wlp0s20f3): Activation: successful, device activated.
(TURNED OFF EXTERNAL DEVICE)
Jul 30 03:08:14 25e052a NetworkManager[1069]: <info>  [1627614494.0906] device (wlp0s20f3): supplicant interface state: completed -> disconnected
Jul 30 03:08:14 25e052a NetworkManager[1069]: <info>  [1627614494.1837] device (wlp0s20f3): supplicant interface state: disconnected -> scanning
Jul 30 03:08:28 25e052a NetworkManager[1069]: <warn>  [1627614508.9994] device (wlp0s20f3): link timed out.
Jul 30 03:08:29 25e052a NetworkManager[1069]: <info>  [1627614509.0008] device (wlp0s20f3): state change: activated -> failed (reason 'ssid-not-found', sys-iface-state: 'managed')
Jul 30 03:08:29 25e052a NetworkManager[1069]: <warn>  [1627614509.0049] device (wlp0s20f3): Activation: failed for connection 'REDACTED-cz65'
Jul 30 03:08:29 25e052a NetworkManager[1069]: <info>  [1627614509.0055] device (wlp0s20f3): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Jul 30 03:08:29 25e052a NetworkManager[1069]: <info>  [1627614509.0183] dhcp4 (wlp0s20f3): canceled DHCP transaction
Jul 30 03:08:29 25e052a NetworkManager[1069]: <info>  [1627614509.0184] dhcp4 (wlp0s20f3): state changed bound -> done
(TURNED ON EXTERNAL DEVICE)
(NO NEW MESSAGES AFTER 10 MINUTES OF LEAVING THE DEVICE ON)
(INITIATE MANUAL RECONNECT BY ISSUING COMMAND `nmcli device wifi connect REDACTED-cz65` ON HOST OS)
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.3888] audit: op="connection-update" uuid="059a20da-4cf3-47f8-a96a-094d3b003d65" name="REDACTED-cz65" args="802-11-wireless-security.psk,connection.timestamp,802-11-wireless.seen-bssids" pid=206419 uid=0 result="success"
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.3917] device (wlp0s20f3): Activation: starting connection 'REDACTED-cz65' (059a20da-4cf3-47f8-a96a-094d3b003d65)
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.3919] audit: op="connection-activate" uuid="059a20da-4cf3-47f8-a96a-094d3b003d65" name="REDACTED-cz65" pid=206419 uid=0 result="success"
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.3923] device (wlp0s20f3): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.3947] device (wlp0s20f3): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.3958] device (wlp0s20f3): Activation: (wifi) access point 'REDACTED-cz65' has security, but secrets are required.
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.3959] device (wlp0s20f3): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4046] device (wlp0s20f3): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4056] device (wlp0s20f3): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4067] device (wlp0s20f3): Activation: (wifi) connection 'REDACTED-cz65' has security, and secrets exist.  No new secrets needed.
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4068] Config: added 'ssid' value 'REDACTED-cz65'
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4069] Config: added 'scan_ssid' value '1'
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4069] Config: added 'bgscan' value 'simple:30:-70:86400'
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4070] Config: added 'key_mgmt' value 'WPA-PSK'
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4070] Config: added 'auth_alg' value 'OPEN'
Jul 30 03:18:32 25e052a NetworkManager[1069]: <info>  [1627615112.4071] Config: added 'psk' value '<hidden>'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0258] device (wlp0s20f3): supplicant interface state: scanning -> authenticating
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0640] device (wlp0s20f3): supplicant interface state: authenticating -> associating
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0725] device (wlp0s20f3): supplicant interface state: associating -> 4way_handshake
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0820] device (wlp0s20f3): supplicant interface state: 4way_handshake -> completed
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0821] device (wlp0s20f3): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "REDACTED-cz65"
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0825] device (wlp0s20f3): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0836] dhcp4 (wlp0s20f3): activation: beginning transaction (no timeout)
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0968] dhcp4 (wlp0s20f3): option dhcp_lease_time      => '86400'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0969] dhcp4 (wlp0s20f3): option expiry               => '1627701514'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0969] dhcp4 (wlp0s20f3): option host_name            => '25e052a'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0969] dhcp4 (wlp0s20f3): option ip_address           => '192.168.10.57'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0969] dhcp4 (wlp0s20f3): option next_server          => '192.168.10.1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0970] dhcp4 (wlp0s20f3): option requested_broadcast_address => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0970] dhcp4 (wlp0s20f3): option requested_domain_name => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0970] dhcp4 (wlp0s20f3): option requested_domain_name_servers => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0970] dhcp4 (wlp0s20f3): option requested_domain_search => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0971] dhcp4 (wlp0s20f3): option requested_host_name  => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0971] dhcp4 (wlp0s20f3): option requested_interface_mtu => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0971] dhcp4 (wlp0s20f3): option requested_ms_classless_static_routes => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0972] dhcp4 (wlp0s20f3): option requested_nis_domain => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0972] dhcp4 (wlp0s20f3): option requested_nis_servers => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0972] dhcp4 (wlp0s20f3): option requested_ntp_servers => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0972] dhcp4 (wlp0s20f3): option requested_rfc3442_classless_static_routes => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0973] dhcp4 (wlp0s20f3): option requested_root_path  => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0973] dhcp4 (wlp0s20f3): option requested_routers    => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0973] dhcp4 (wlp0s20f3): option requested_static_routes => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0973] dhcp4 (wlp0s20f3): option requested_subnet_mask => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0974] dhcp4 (wlp0s20f3): option requested_time_offset => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0974] dhcp4 (wlp0s20f3): option requested_wpad       => '1'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0974] dhcp4 (wlp0s20f3): option subnet_mask          => '255.255.255.0'
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.0974] dhcp4 (wlp0s20f3): state changed unknown -> bound
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.1003] device (wlp0s20f3): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.1311] device (wlp0s20f3): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.1316] device (wlp0s20f3): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Jul 30 03:18:34 25e052a NetworkManager[1069]: <info>  [1627615114.1356] device (wlp0s20f3): Activation: successful, device activated.

Regards,
ConorB

5

Thanks for posting the logs here. I looked into them but no concrete indications are found there. What is the specific device type you are using - I see it is not a Raspberry Pi judging from the naming convention of the interfaces? I will do some local tests here to see whether I can reproduce something similar.

6

This is with the Intel NUC. The device we are connecting to (REDACTED-cz65) is 3rd party hardware that I’m not inclined to post about publicly, but can share privately if necessary.

Regards,
ConorB

7

I think it is a NUC kernel issue - most probably with the iwlwifi driver/firmware. Can you please do the same procedure and paste me the output of dmesg? There are plenty of differences between NUC devices and that will help us to narrow down the problem a bit more. You may also send it in a private message here to me.

8

I will post dmesg output shortly.

As a data point, if I add an explicit call to RequestScan() and then GetAllAccessPoints() the NUC seems to recognize the other device again. I leaned heavily on what @mhazley did in this post → Scanning for SSID's at Runtime - #8 by mhazley

9

That’s a nice find actually. For some reason the routine scanning when the device is not connected to a network does not occur and it needs extra nudge. A team member is just finishing some drivers/firmware reorganization and updates that should also affect to iwlwifi driver, so I may provide you an image to check out once he is ready. Also we may bump the NetworkManager version to latest stable for you to try out as well. Let me follow up with you on Monday once I get all the relevant information.

10

This is the PR I will be awaiting for to get finished to produce new build for you to test with: linux-firmware: upgrade 20190815 -> 20210511 by jakogut · Pull Request #2240 · balena-os/meta-balena · GitHub
It looks like it still need some polishing to be done for it to be completed but it is actively worked on.

14

Many thanks. On my end we implemented a function that is called periodically by our main loop. In that function we scan the wifi connections as mentioned in the previously referenced post. If we find the SSID that we are interested in and the connection is not active, we explicitly call NetworkManager ActivateConnection() method. That seems to be doing the trick as a workaround.

Thanks again for your guidance on this.

Regards,
ConorB

20

Hello @cbrady sorry for the late answer on this.

Last month we made a PR to try to solve this. Did you try to test a new OS version where the PR is included? Thanks!