NM 1.10 issue connecting to wifi

snap
1

Hi.

I have a snap that among other things allows user to connect to wifi, underneath it’s using libnm to communicate to the snap (it’s a core 20 snap, system is ubuntu 16 itself).

The problem is that wifi connections just fail with those errors (log in reverse):

Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz, 92000 KHz AUTO), (N/A, 2000 mBm), (N/A)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211:  DFS Master region: unset
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: cfg80211: World regulatory domain updated:
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: brcmf_cfg80211_reg_notifier: not a ISO3166 code
Mar 18 15:26:03 srly-t9exdkyzs0elgvn wpa_supplicant[2299]: p2p-dev-wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: audit: type=1107 audit(1616077563.033:3147): pid=1837 uid=100 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_signal"  bus="system" path="/org/freedesktop" interface="org.freedesktop.DBu
exe="/usr/bin/dbus-daemon" sauid=100 hostname=? addr=? terminal=?'
Mar 18 15:26:03 srly-t9exdkyzs0elgvn kernel: audit: type=1107 audit(1616077563.033:3146): pid=1837 uid=100 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_signal"  bus="system" path="/org/freedesktop" interface="org.freedesktop.DBu
exe="/usr/bin/dbus-daemon" sauid=100 hostname=? addr=? terminal=?'
Mar 18 15:26:03 srly-t9exdkyzs0elgvn audit[1837]: USER_AVC pid=1837 uid=100 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_signal"  bus="system" path="/org/freedesktop" interface="org.freedesktop.DBus.ObjectManager" member="Interf
exe="/usr/bin/dbus-daemon" sauid=100 hostname=? addr=? terminal=?'
Mar 18 15:26:03 srly-t9exdkyzs0elgvn audit[1837]: USER_AVC pid=1837 uid=100 auid=4294967295 ses=4294967295 msg='apparmor="DENIED" operation="dbus_signal"  bus="system" path="/org/freedesktop" interface="org.freedesktop.DBus.ObjectManager" member="Interf
exe="/usr/bin/dbus-daemon" sauid=100 hostname=? addr=? terminal=?'
Mar 18 15:26:03 srly-t9exdkyzs0elgvn NetworkManager[1913]: <info>  [1616077563.0261] device (wlan0): supplicant interface state: completed -> disconnected
Mar 18 15:26:03 srly-t9exdkyzs0elgvn NetworkManager[1913]: <warn>  [1616077563.0252] sup-iface[0xc27ce8,wlan0]: connection disconnected (reason -3)
Mar 18 15:26:03 srly-t9exdkyzs0elgvn NetworkManager[1913]: <info>  [1616077563.0190] policy: Device 'wlan0' has no connection; scheduling activate_check in 0 seconds.
Mar 18 15:26:03 srly-t9exdkyzs0elgvn wpa_supplicant[2299]: wlan0: CTRL-EVENT-DISCONNECTED bssid=0c:80:63:1b:5e:8e reason=3 locally_generated=1
Mar 18 15:26:03 srly-t9exdkyzs0elgvn NetworkManager[1913]: <info>  [1616077563.0030] device (wlan0): state change: failed -> disconnected (reason 'none') [120 30 0]
Mar 18 15:26:02 srly-t9exdkyzs0elgvn NetworkManager[1913]: <warn>  [1616077562.8275] device (wlan0): Activation: failed for connection 'KAMI_5G'
Mar 18 15:26:02 srly-t9exdkyzs0elgvn NetworkManager[1913]: <info>  [1616077562.8237] device (wlan0): state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
Mar 18 15:26:02 srly-t9exdkyzs0elgvn NetworkManager[1913]: <info>  [1616077562.8221] dhcp4 (wlan0): state changed timeout -> done
Mar 18 15:26:02 srly-t9exdkyzs0elgvn NetworkManager[1913]: <info>  [1616077562.8219] dhcp4 (wlan0): canceled DHCP transaction
Mar 18 15:26:02 srly-t9exdkyzs0elgvn NetworkManager[1913]: <info>  [1616077562.8117] dhcp4 (wlan0): state changed unknown -> timeout
Mar 18 15:26:02 NetworkManager[1913]: <warn>  [1616077562.8114] dhcp4 (wlan0): request timed out

The first error is this one:
(wlan0): state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]

I tried looking into what happens and called ip route and after that the issue seems to have went away (at least for this particular device).

Any ideas what this might be caused by? Is this related to NM default configuration?

2

Is NM part of your confined snap or are you using the network-manager snap?

3

It’s installed to the image with extra snaps command from 1.10 channel.

4

If the user snap is a core20 snap, better use also the core20-based network-manager snap (include it in the image with --snap network-manager=20/beta - this snap is not yet in 20/stable, although that will happen in the near future).

Also, what happens if you try to create the wifi connection from the command line using nmcli instead of from you snap? Does that work?

5

Sorry, did not see that your reply for a long time. I will try connecting via the command line and report the results.

After I reflashed with the same setup I started getting another error - and mostly for 5 GHz wifi - it would create a connection properly, then it tries to activate it and just times out in 45 seconds.

My plan was to downgrade the libnm I am linking against (and build it myself) since there were no issues when connecting with my app build against core base snap on ubuntu 16.

Is there a timeline for that core 20 based NM snap release?
The reason I did not use it was that it’s precisely in beta, and I did try it and had other issues (I had a custom image with it baked in, and well every other time after reboot ethernet connection only would come up after like 5 minutes).

6

Hm, now I re-read the thread and I missed that this is actually a UC16 system. In that case I would stick to the 1.10 version of NM you are using. Anyway, I’ll wait for your results when you try to connect via the command line.

7

Huh, so it did fail from the command line as well. And here I was thinking it was due to me upgrading my snap to base: core20.
I guess moving to nm 1.10 should have caused the issue. And since it does work in some scenarios I did not notice that.

root@srly-asap2y55ep49job:/# nmcli device wifi connect KAMI_5G password MYPASSWORD
Error: Connection activation failed: (5) IP configuration could not be reserved (no available address, timeout, etc.).

And network manager logs:

Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.8009] keyfile: add connection in-memory (65d86e35-abf8-415b-8113-da83e1b26d66,"KAMI_5G")
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.8155] device (wlan0): Activation: starting connection 'KAMI_5G' (65d86e35-abf8-415b-8113-da83e1b26d66)
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.8682] settings-connection[0x10f8c10,65d86e35-abf8-415b-8113-da83e1b26d66]: write: successfully commited (keyfile: update /var/snap/network-manager/625/conf/system-connections
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.8687] audit: op="connection-add-activate" uuid="65d86e35-abf8-415b-8113-da83e1b26d66" name="KAMI_5G" pid=27922 uid=0 result="success"
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.8992] device (wlan0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9064] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9092] device (wlan0): Activation: (wifi) access point 'KAMI_5G' has security, but secrets are required.
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9096] device (wlan0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9109] sup-iface[0x1160808,wlan0]: wps: type pbc start...
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9337] device (wlan0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9377] device (wlan0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <warn>  [1617984082.9403] device (wlan0): Cannot configure WoWLAN.
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9407] device (wlan0): Activation: (wifi) connection 'KAMI_5G' has security, and secrets exist.  No new secrets needed.
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9414] Config: added 'ssid' value 'KAMI_5G'
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9416] Config: added 'scan_ssid' value '1'
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9418] Config: added 'bgscan' value 'simple:30:-80:86400'
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9419] Config: added 'key_mgmt' value 'WPA-PSK'
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9420] Config: added 'auth_alg' value 'OPEN'
Apr 09 18:01:22 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984082.9422] Config: added 'psk' value '<hidden>'
Apr 09 18:01:23 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984083.0347] device (wlan0): supplicant interface state: inactive -> scanning
Apr 09 18:01:25 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984085.4356] device (wlan0): supplicant interface state: scanning -> associating
Apr 09 18:01:25 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984085.6141] device (wlan0): supplicant interface state: associating -> 4-way handshake
Apr 09 18:01:25 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984085.6379] device (wlan0): supplicant interface state: 4-way handshake -> completed
Apr 09 18:01:25 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984085.6383] device (wlan0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'KAMI_5G'.
Apr 09 18:01:25 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984085.6390] device (wlan0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Apr 09 18:01:25 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984085.6428] dhcp4 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <warn>  [1617984131.0635] dhcp4 (wlan0): request timed out
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984131.0637] dhcp4 (wlan0): state changed unknown -> timeout
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984131.0729] dhcp4 (wlan0): canceled DHCP transaction
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984131.0730] dhcp4 (wlan0): state changed timeout -> done
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984131.0743] device (wlan0): state change: ip-config -> failed (reason 'ip-config-unavailable', sys-iface-state: 'managed')
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <warn>  [1617984131.0776] device (wlan0): Activation: failed for connection 'KAMI_5G'
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984131.0919] device (wlan0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <warn>  [1617984131.1527] sup-iface[0x1160808,wlan0]: connection disconnected (reason -3)
Apr 09 18:02:11 srly-asap2y55ep49job NetworkManager[1901]: <info>  [1617984131.1539] device (wlan0): supplicant interface state: completed -> disconnected
8

dhcp is timing out here - maybe there is some incompatibility/bug between your AP’s dhcp server and NM’s. I would suggest taking a look at tcpdump to try to find out why.

9

Sure I will do it - but it did work with 1.0 without any issues for sure. Also had other people test on different APs and they had the same issues (they did try with older nm and also did not have any issues connecting to their APs).

10

Also why do you not recommend using NM 1.22 on the 16 system? Should it cause any issues? My main snap on that image has base core 20 anyhow.

11

The NM snap is very tied to the underlying UC version, as it does low-level wiring. For instance, DNS handling changed between Ubuntu 16.04/UC16 and Ubuntu 18.04/UC18, so the core16 version of the snap does not work on UC18. See more information about the NM tracks in https://ubuntu.com/core/docs/networkmanager/install

12

Understood, thank you.