upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

olocin · 2019-12-29 13:09:44

Has anyone else experienced this? Has it been reported as a bug somewhere?
(Notice downgrading to previous version fixes the problem.)
This is what I get:

$ nmcli c u zzz
Passwords or encryption keys are required to access the wireless network 'zzz'.
Warning: password for '802-11-wireless-security.psk' not given in 'passwd-file' and nmcli cannot ask without '--ask' option.
Error: Connection activation failed: IP configuration could not be reserved (no available address, timeout, etc.)
Hint: use 'journalctl -xe NM_CONNECTION=...' to get more details.

This is journal:

NetworkManager[620]: <info>  [1577452064.0652] manager: sleep: wake requested (sleeping: yes  enabled: yes)
NetworkManager[620]: <info>  [1577452064.0653] device (wlp4s0): state change: activated -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452064.0766] dhcp4 (wlp4s0): canceled DHCP transaction
NetworkManager[620]: <info>  [1577452064.0767] dhcp4 (wlp4s0): state changed bound -> done
NetworkManager[620]: <info>  [1577452064.0797] device (wlp4s0): set-hw-addr: reset MAC address to ... (unmanage)
NetworkManager[620]: <info>  [1577452064.0902] manager: NetworkManager state is now CONNECTED_GLOBAL
NetworkManager[620]: <info>  [1577452064.0930] manager: NetworkManager state is now DISCONNECTED
NetworkManager[620]: <info>  [1577452064.0945] device (enp0s31f6): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
dbus-daemon[613]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.2' (uid=0 pid=620 comm="/usr/bin/NetworkManager --no-daemon ")
systemd[1]: Starting Network Manager Script Dispatcher Service...
dbus-daemon[613]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
systemd[1]: Started Network Manager Script Dispatcher Service.
kernel: audit: type=1130 audit(1577452064.096:124): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
wpa_supplicant[728]: nl80211: deinit ifname=p2p-dev-wlp4s0 disabled_11b_rates=0
NetworkManager[620]: <info>  [1577452064.2807] device (wlp4s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452064.2892] device (wlp4s0): set-hw-addr: set MAC address to ... (scanning)
NetworkManager[620]: <info>  [1577452064.2964] device (p2p-dev-wlp4s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
wpa_supplicant[728]: nl80211: deinit ifname=wlp4s0 disabled_11b_rates=0
NetworkManager[620]: <info>  [1577452064.4149] sup-iface[...,wlp4s0]: supports 5 scan SSIDs
NetworkManager[620]: <info>  [1577452064.4155] device (wlp4s0): supplicant interface state: starting -> ready
NetworkManager[620]: <info>  [1577452064.4156] device (p2p-dev-wlp4s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452064.4158] device (wlp4s0): state change: unavailable -> disconnected (reason 'supplicant-available', sys-iface-state: 'managed')
wpa_supplicant[728]: wlp4s0: CTRL-EVENT-REGDOM-CHANGE init=DRIVER type=COUNTRY alpha2=IT
NetworkManager[620]: <info>  [1577452067.8142] policy: auto-activating connection 'zzz' (...)
NetworkManager[620]: <info>  [1577452067.8148] device (wlp4s0): Activation: starting connection 'zzz' (...)
NetworkManager[620]: <info>  [1577452067.8149] device (wlp4s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452067.8152] manager: NetworkManager state is now CONNECTING
NetworkManager[620]: <info>  [1577452067.8173] device (wlp4s0): set-hw-addr: set-cloned MAC address to ... (random)
NetworkManager[620]: <info>  [1577452067.8224] device (wlp4s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452067.8241] device (wlp4s0): Activation: (wifi) access point '...' has security, but secrets are required.
NetworkManager[620]: <info>  [1577452067.8242] device (wlp4s0): state change: config -> need-auth (reason 'none', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452067.8545] device (wlp4s0): supplicant interface state: ready -> disconnected
NetworkManager[620]: <info>  [1577452067.8546] device (p2p-dev-wlp4s0): supplicant management interface state: ready -> disconnected
NetworkManager[620]: <info>  [1577452067.8595] device (wlp4s0): supplicant interface state: disconnected -> inactive
NetworkManager[620]: <info>  [1577452067.8595] device (p2p-dev-wlp4s0): supplicant management interface state: disconnected -> inactive
NetworkManager[620]: <info>  [1577452067.8645] device (wlp4s0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452067.8653] device (wlp4s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452067.8661] device (wlp4s0): Activation: (wifi) connection 'zzz' has security, and secrets exist. No new secrets needed.
NetworkManager[620]: <info>  [1577452067.8661] Config: added 'ssid' value 'zzz'
NetworkManager[620]: <info>  [1577452067.8661] Config: added 'scan_ssid' value '1'
NetworkManager[620]: <info>  [1577452067.8662] Config: added 'bgscan' value 'simple:30:-65:300'
NetworkManager[620]: <info>  [1577452067.8662] Config: added 'key_mgmt' value 'WPA-PSK WPA-PSK-SHA256 FT-PSK'
NetworkManager[620]: <info>  [1577452067.8662] Config: added 'psk' value '<hidden>'
NetworkManager[620]: <info>  [1577452067.8787] device (wlp4s0): supplicant interface state: inactive -> scanning
NetworkManager[620]: <info>  [1577452067.8787] device (p2p-dev-wlp4s0): supplicant management interface state: inactive -> scanning
wpa_supplicant[728]: wlp4s0: SME: Trying to authenticate with ... (SSID='zzz' freq=5220 MHz)
kernel: wlp4s0: authenticate with ...
kernel: wlp4s0: send auth to ... (try 1/3)
NetworkManager[620]: <info>  [1577452068.5310] device (wlp4s0): supplicant interface state: scanning -> authenticating
NetworkManager[620]: <info>  [1577452068.5312] device (p2p-dev-wlp4s0): supplicant management interface state: scanning -> authenticating
wpa_supplicant[728]: wlp4s0: Trying to associate with ... (SSID='zzz' freq=5220 MHz)
kernel: wlp4s0: authenticated
kernel: wlp4s0: associate with ... (try 1/3)
NetworkManager[620]: <info>  [1577452068.5470] device (wlp4s0): supplicant interface state: authenticating -> associating
NetworkManager[620]: <info>  [1577452068.5471] device (p2p-dev-wlp4s0): supplicant management interface state: authenticating -> associating
kernel: wlp4s0: RX AssocResp from ... (capab=0x1511 status=0 aid=1)
wpa_supplicant[728]: wlp4s0: Associated with ...
kernel: wlp4s0: associated
wpa_supplicant[728]: wlp4s0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
NetworkManager[620]: <info>  [1577452068.5626] device (wlp4s0): supplicant interface state: associating -> 4-way handshake
NetworkManager[620]: <info>  [1577452068.5627] device (p2p-dev-wlp4s0): supplicant management interface state: associating -> 4-way handshake
wpa_supplicant[728]: wlp4s0: WPA: Key negotiation completed with ... [PTK=CCMP GTK=CCMP]
wpa_supplicant[728]: wlp4s0: CTRL-EVENT-CONNECTED - Connection to ... completed [id=0 id_str=]
kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlp4s0: link becomes ready
wpa_supplicant[728]: wlp4s0: CTRL-EVENT-SIGNAL-CHANGE above=0 signal=-74 noise=9999 txrate=6000
NetworkManager[620]: <info>  [1577452068.5861] device (wlp4s0): supplicant interface state: 4-way handshake -> completed
NetworkManager[620]: <info>  [1577452068.5862] device (wlp4s0): Activation: (wifi) Stage 2 of 5 (Device Configure) successful. Connected to wireless network "zzz"
NetworkManager[620]: <info>  [1577452068.5863] device (p2p-dev-wlp4s0): supplicant management interface state: 4-way handshake -> completed
NetworkManager[620]: <info>  [1577452068.5870] device (wlp4s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
NetworkManager[620]: <info>  [1577452068.5887] dhcp4 (wlp4s0): activation: beginning transaction (timeout in 45 seconds)
NetworkManager[620]: <info>  [1577452068.5980] dhcp4 (wlp4s0): state changed unknown -> fail
kernel: wlp4s0: Limiting TX power to 23 (23 - 0) dBm as advertised by ...

Last edited by olocin (2019-12-30 08:43:45)

seth · 2019-12-29 16:17:44

NetworkManager[620]: <info>  [1577452068.5887] dhcp4 (wlp4s0): activation: beginning transaction (timeout in 45 seconds)
NetworkManager[620]: <info>  [1577452068.5980] dhcp4 (wlp4s0): state changed unknown -> fail

https://bbs.archlinux.org/viewtopic.php?id=251642

And yes, you're no#5 or so…

olocin · 2019-12-30 08:16:39

Thanks.
I don't see the link to the filed bug, can you?

seth · 2019-12-30 08:25:50

There's https://bugs.archlinux.org/task/64880 but it's currently not clear whether this has been actually fixed, because imo the critical line in https://gitlab.freedesktop.org/NetworkM … aster/NEWS is

* DHCP: switch "internal" DHCPv4 plugin from code based on systemd to use nettools'  n-dhcp4 library.

olocin · 2019-12-30 08:37:16

I see.
However, version 1.22.0-1 works fine for me, while the bug says something different.
I switched to dhcpcd as suggested in the bug though, which seems a good idea anyway.
I will now update NM and see if it works.

seth · 2019-12-30 08:42:01

They switched their dhcp implementation and are now poking around to get it under control. From your account, the "fix" to the original bug apparently broke your configuration.
And yes, switching to a more reliable dhcp client (as suggested by me in the linked thread as well as in the bug report) is the sane thing for the time being. You might want to try the internal client every now and then and report upstream if it's broken for you.

olocin · 2019-12-30 08:43:12

Thanks, it now works fine.

Arch Linux

#1 2019-12-29 13:09:44

upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

#2 2019-12-29 16:17:44

Re: upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

#3 2019-12-30 08:16:39

Re: upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

#4 2019-12-30 08:25:50

Re: upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

#5 2019-12-30 08:37:16

Re: upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

#6 2019-12-30 08:42:01

Re: upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

#7 2019-12-30 08:43:12

Re: upgrade to networkmanager-1.22.2-1 breaks wifi [solved]

Board footer