Bug 2193422

Summary:	Wired connection does not come back on resume from suspend (NetworkManager 1.43.6 / 1.43.7)
Product:	[Fedora] Fedora	Reporter:	Adam Williamson <awilliam>
Component:	NetworkManager	Assignee:	Beniamino Galvani <bgalvani>
Status:	CLOSED CURRENTRELEASE	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	bgalvani, dcbw, ferferna, gnome-sig, liangwen12year, lkundrak, mclasen, rstrode, ryan, vbubela
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2023-05-18 08:12:08 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Adam Williamson 2023-05-05 15:51:02 UTC

The last couple of days, when I wake my system up in the morning, the network connection does not come up. I have to run `nmcli con up "Wired connection 1"` to make it come back, which works fine.

The first time I saw this was with 1.43.6; I updated to 1.43.7 to see if that fixes it, but it still happened this morning.

Reproducible: Always

Steps to Reproduce:
1. Suspend the system (probably with a VPN connection active on top of the wired connection; I haven't checked if this also happens when the VPN connection is not active)
2. Wake it up again some time later
Actual Results:  
System wakes up, network is not connected.

Expected Results:  
Network should be connected.

Here's a log extract from sleep (23:11:34) to wake (08:12:04) to when I force the connection up with nmcli (08:12:36). Note there's also a wireless connection generating spew; the wired connection is enp88s0.

May 04 23:11:34 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683267094.6218] manager: sleep: sleep requested (sleeping: no  enabled: yes)
May 04 23:11:34 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683267094.6221] device (wlp0s20f3): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
May 04 23:11:34 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683267094.6226] device (wlp0s20f3): set-hw-addr: reset MAC address to E0:D0:45:C4:7A:6B (unmanage)
May 04 23:11:34 xps13a.happyassassin.net NetworkManager[2080]: <warn>  [1683267094.9055] platform-linux: do-change-link[3]: failure 5 (Input/output error)
May 04 23:11:34 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683267094.9058] manager: NetworkManager state is now ASLEEP
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5418] manager: sleep: wake requested (sleeping: yes  enabled: yes)
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5421] device (enp88s0): state change: activated -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5523] dhcp4 (enp88s0): canceled DHCP transaction
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5524] dhcp4 (enp88s0): activation: beginning transaction (timeout in 45 seconds)
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5524] dhcp4 (enp88s0): state changed no lease
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5528] dhcp6 (enp88s0): canceled DHCP transaction
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5528] dhcp6 (enp88s0): activation: beginning transaction (timeout in 45 seconds)
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.5529] dhcp6 (enp88s0): state changed no lease
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.6006] manager: NetworkManager state is now CONNECTED_GLOBAL
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.6350] manager: NetworkManager state is now DISCONNECTED
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.6359] device (enp88s0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 05 08:12:04 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299524.6366] device (wlp0s20f3): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 05 08:12:05 xps13a.happyassassin.net NetworkManager[2080]: <error> [1683299525.1849] device (wlp0s20f3): Couldn't initialize supplicant interface: GDBus.Error:fi.w1.wpa_supplicant1.UnknownError: wpa_supplicant couldn't grab this interface.
May 05 08:12:13 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299533.6249] agent-manager: agent[eb8ef04d2944730b,:1.88/org.gnome.Shell.NetworkAgent/1000]: agent registered
May 05 08:12:15 xps13a.happyassassin.net NetworkManager[2080]: <warn>  [1683299535.1154] device (wlp0s20f3): re-acquiring supplicant interface (#1).
May 05 08:12:15 xps13a.happyassassin.net NetworkManager[2080]: <error> [1683299535.6771] device (wlp0s20f3): Couldn't initialize supplicant interface: GDBus.Error:fi.w1.wpa_supplicant1.UnknownError: wpa_supplicant couldn't grab this interface.
May 05 08:12:26 xps13a.happyassassin.net NetworkManager[2080]: <warn>  [1683299546.1202] device (wlp0s20f3): re-acquiring supplicant interface (#2).
May 05 08:12:26 xps13a.happyassassin.net NetworkManager[2080]: <error> [1683299546.6803] device (wlp0s20f3): Couldn't initialize supplicant interface: GDBus.Error:fi.w1.wpa_supplicant1.UnknownError: wpa_supplicant couldn't grab this interface.
May 05 08:12:37 xps13a.happyassassin.net NetworkManager[2080]: <warn>  [1683299557.1151] device (wlp0s20f3): re-acquiring supplicant interface (#3).
May 05 08:12:37 xps13a.happyassassin.net NetworkManager[2080]: <error> [1683299557.6809] device (wlp0s20f3): Couldn't initialize supplicant interface: GDBus.Error:fi.w1.wpa_supplicant1.UnknownError: wpa_supplicant couldn't grab this interface.
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8001] agent-manager: agent[037c924e8f732ba8,:1.785/nmcli-connect/1000]: agent registered
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8059] device (enp88s0): state change: unavailable -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8066] device (enp88s0): Activation: starting connection 'Wired connection 1' (410be97c-588e-3bc6-93d2-4f11e241da13)
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8067] audit: op="connection-activate" uuid="410be97c-588e-3bc6-93d2-4f11e241da13" name="Wired connection 1" pid=51608 uid=1000 result="success"
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8068] device (enp88s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8071] manager: NetworkManager state is now CONNECTING
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8073] device (enp88s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8379] device (enp88s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 05 08:12:46 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299566.8382] dhcp4 (enp88s0): activation: beginning transaction (timeout in 45 seconds)
May 05 08:12:48 xps13a.happyassassin.net NetworkManager[2080]: <warn>  [1683299568.1151] device (wlp0s20f3): re-acquiring supplicant interface (#4).
May 05 08:12:48 xps13a.happyassassin.net NetworkManager[2080]: <error> [1683299568.6950] device (wlp0s20f3): Couldn't initialize supplicant interface: GDBus.Error:fi.w1.wpa_supplicant1.UnknownError: wpa_supplicant couldn't grab this interface.
May 05 08:12:50 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299570.1425] device (enp88s0): carrier: link connected
May 05 08:12:52 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299572.0159] dhcp6 (enp88s0): activation: beginning transaction (timeout in 45 seconds)
May 05 08:12:52 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299572.0166] policy: set 'Wired connection 1' (enp88s0) as default for IPv6 routing and DNS
May 05 08:12:52 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299572.0198] dhcp6 (enp88s0): state changed new lease
May 05 08:12:52 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299572.9968] dhcp4 (enp88s0): state changed new lease, address=192.168.1.17
May 05 08:12:52 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299572.9971] policy: set 'Wired connection 1' (enp88s0) as default for IPv4 routing and DNS
May 05 08:12:53 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299573.0060] device (enp88s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 05 08:12:53 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299573.0079] device (enp88s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 05 08:12:53 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299573.0081] device (enp88s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 05 08:12:53 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299573.0083] manager: NetworkManager state is now CONNECTED_SITE
May 05 08:12:53 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299573.0085] device (enp88s0): Activation: successful, device activated.
May 05 08:12:53 xps13a.happyassassin.net NetworkManager[2080]: <info>  [1683299573.4027] manager: NetworkManager state is now CONNECTED_GLOBAL

Comment 1 ryan@testtoast.com 2023-05-10 01:02:36 UTC

Also seeing this issue on two systems, desktop wired (Intel X550) and laptop (Thinkpad X1Y4 - Cannon Lake Wifi) with Rawhide (NM 1.43.7) for the last couple of weeks. Requires restarting networkmanager to allow interfaces to come up.

Log below covers sleep -> wake (disconnected) -> NM restart -> connected. enp9s0 is my physically connected X550 card.  "state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')" seems relevant.

May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.7763] manager: sleep: sleep requested (sleeping: no  enabled: yes)
May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.7766] manager: NetworkManager state is now ASLEEP
May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.7767] device (enp9s0): state change: activated -> deactivating (reason 'sleeping', sys-iface-state: 'managed')
May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.8178] device (enp9s0): state change: deactivating -> disconnected (reason 'sleeping', sys-iface-state: 'managed')
May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.8463] dhcp4 (enp9s0): canceled DHCP transaction
May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.8463] dhcp4 (enp9s0): activation: beginning transaction (timeout in 45 seconds)
May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.8463] dhcp4 (enp9s0): state changed no lease
May 10 10:52:14 crackotage NetworkManager[137223]: <info>  [1683672734.8500] device (enp9s0): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
May 10 12:48:57 crackotage NetworkManager[137223]: <info>  [1683679737.6248] manager: sleep: wake requested (sleeping: yes  enabled: yes)
May 10 12:48:57 crackotage NetworkManager[137223]: <info>  [1683679737.6249] device (eno1): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
May 10 12:48:57 crackotage NetworkManager[137223]: <info>  [1683679737.6714] device (eno1): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 10 12:48:57 crackotage NetworkManager[137223]: <info>  [1683679737.6715] device (enp9s0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 10 12:48:57 crackotage NetworkManager[137223]: <info>  [1683679737.6715] manager: NetworkManager state is now CONNECTED_LOCAL
May 10 12:50:48 crackotage systemd[1]: Stopping NetworkManager.service - Network Manager...
░░ Subject: A stop job for unit NetworkManager.service has begun execution
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░
░░ A stop job for unit NetworkManager.service has begun execution.
░░
░░ The job identifier is 5589.
May 10 12:50:48 crackotage NetworkManager[137223]: <info>  [1683679848.3214] caught SIGTERM, shutting down normally.
May 10 12:50:48 crackotage NetworkManager[137223]: <info>  [1683679848.3422] exiting (success)
May 10 12:50:48 crackotage systemd[1]: NetworkManager.service: Deactivated successfully.
░░ Subject: Unit succeeded
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░
░░ The unit NetworkManager.service has successfully entered the 'dead' state.
May 10 12:50:48 crackotage systemd[1]: Stopped NetworkManager.service - Network Manager.
░░ Subject: A stop job for unit NetworkManager.service has finished
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░
░░ A stop job for unit NetworkManager.service has finished.
░░
░░ The job identifier is 5589 and the job result is done.
May 10 12:50:48 crackotage systemd[1]: Starting NetworkManager.service - Network Manager...
░░ Subject: A start job for unit NetworkManager.service has begun execution
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░
░░ A start job for unit NetworkManager.service has begun execution.
░░
░░ The job identifier is 5589.
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3619] NetworkManager (version 1.43.7-1.fc39) is starting... (after a restart, boot:dd800437-849d-44cf-bb3c-5d78c0e120a2)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3619] Read config: /etc/NetworkManager/NetworkManager.conf (run: 15-carrier-timeout.conf) (etc: 10-dns-systemd-resolved.conf)
May 10 12:50:48 crackotage NetworkManager[303149]: <warn>  [1683679848.3619] config: unknown key 'mdns' in section [connection] of file '/etc/NetworkManager/NetworkManager.conf'
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3635] manager[0x55e1f5011b70]: monitoring kernel firmware directory '/lib/firmware'.
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3855] hostname: hostname: using hostnamed
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3855] hostname: static hostname changed from (none) to "crackotage"
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3856] dns-mgr: init: dns=systemd-resolved rc-manager=unmanaged (auto), plugin=systemd-resolved
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3858] manager[0x55e1f5011b70]: rfkill: Wi-Fi hardware radio set enabled
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3859] manager[0x55e1f5011b70]: rfkill: WWAN hardware radio set enabled
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3865] Loaded device plugin: NMWifiFactory (/usr/lib64/NetworkManager/1.43.7-1.fc39/libnm-device-plugin-wifi.so)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3870] Loaded device plugin: NMWwanFactory (/usr/lib64/NetworkManager/1.43.7-1.fc39/libnm-device-plugin-wwan.so)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3871] Loaded device plugin: NMAtmManager (/usr/lib64/NetworkManager/1.43.7-1.fc39/libnm-device-plugin-adsl.so)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3871] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3872] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3872] manager: Networking is enabled by state file
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3872] settings: Loaded settings plugin: keyfile (internal)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3874] settings: Loaded settings plugin: ifcfg-rh ("/usr/lib64/NetworkManager/1.43.7-1.fc39/libnm-settings-plugin-ifcfg-rh.so")
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3885] dhcp: init: Using DHCP client 'internal'
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3885] manager: (lo): new Loopback device (/org/freedesktop/NetworkManager/Devices/1)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3887] device (lo): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3888] device (lo): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3890] device (lo): Activation: starting connection 'lo' (d2389b83-a305-49da-8cb4-69ce6980cf9d)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3893] manager: (eno1): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.3894] device (eno1): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.4610] manager: (enp9s0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/3)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.4611] device (enp9s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7149] manager: (virbr0): new Bridge device (/org/freedesktop/NetworkManager/Devices/4)
May 10 12:50:48 crackotage NetworkManager[303149]: <warn>  [1683679848.7151] device (virbr0): failed to read bridge setting 'vlan_protocol'
May 10 12:50:48 crackotage NetworkManager[303149]: <warn>  [1683679848.7151] device (virbr0): failed to read bridge setting 'vlan_stats_enabled'
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7152] device (virbr0): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7153] device (virbr0): state change: unavailable -> disconnected (reason 'connection-assumed', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7155] device (virbr0): Activation: starting connection 'virbr0' (91e27e98-d999-4d29-a36e-1bb3e2ce87ec)
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7157] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
May 10 12:50:48 crackotage systemd[1]: Started NetworkManager.service - Network Manager.
░░ Subject: A start job for unit NetworkManager.service has finished successfully
░░ Defined-By: systemd
░░ Support: https://lists.freedesktop.org/mailman/listinfo/systemd-devel
░░
░░ A start job for unit NetworkManager.service has finished successfully.
░░
░░ The job identifier is 5589.
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7160] device (lo): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7161] device (lo): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7162] device (lo): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7163] device (virbr0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7163] device (virbr0): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7164] device (virbr0): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7165] device (lo): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7166] device (virbr0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7168] modem-manager: ModemManager available
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7169] device (lo): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7169] device (lo): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7171] device (lo): Activation: successful, device activated.
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7172] device (virbr0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7172] device (virbr0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'external')
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7173] manager: NetworkManager state is now CONNECTED_LOCAL
May 10 12:50:48 crackotage NetworkManager[303149]: <info>  [1683679848.7174] device (virbr0): Activation: successful, device activated.
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.5896] device (enp9s0): carrier: link connected
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.5900] device (enp9s0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.5933] policy: auto-activating connection 'Wired connection 2' (ec2498c7-3f84-3128-8dd3-5e5b1ecc25ca)
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.5939] device (enp9s0): Activation: starting connection 'Wired connection 2' (ec2498c7-3f84-3128-8dd3-5e5b1ecc25ca)
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.5940] device (enp9s0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.5943] manager: NetworkManager state is now CONNECTING
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.5945] device (enp9s0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.6098] device (enp9s0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
May 10 12:50:52 crackotage NetworkManager[303149]: <info>  [1683679852.6122] dhcp4 (enp9s0): activation: beginning transaction (timeout in 45 seconds)
May 10 12:50:57 crackotage NetworkManager[303149]: <info>  [1683679857.7296] policy: set 'Wired connection 2' (enp9s0) as default for IPv6 routing and DNS
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9354] dhcp4 (enp9s0): state changed new lease, address=192.168.1.247
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9362] policy: set 'Wired connection 2' (enp9s0) as default for IPv4 routing and DNS
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9582] device (enp9s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9908] device (enp9s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9908] device (enp9s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9909] manager: NetworkManager state is now CONNECTED_SITE
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9910] device (enp9s0): Activation: successful, device activated.
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9911] manager: NetworkManager state is now CONNECTED_GLOBAL
May 10 12:50:58 crackotage NetworkManager[303149]: <info>  [1683679858.9911] manager: startup complete

Comment 2 Beniamino Galvani 2023-05-10 06:45:22 UTC

(In reply to ryan from comment #1)
> Also seeing this issue on two systems, desktop wired (Intel X550) and laptop
> (Thinkpad X1Y4 - Cannon Lake Wifi) with Rawhide (NM 1.43.7) for the last
> couple of weeks. Requires restarting networkmanager to allow interfaces to
> come up.
> 
> Log below covers sleep -> wake (disconnected) -> NM restart -> connected.
> enp9s0 is my physically connected X550 card.  "state change: unmanaged ->
> unavailable (reason 'connection-assumed', sys-iface-state: 'external')"
> seems relevant.

Right, it is related; the regression was introduced to fix another problem [1]; I'm investigating how to fix it.

[1] https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/commit/5a9a7623c5a4bae2001b30eb99e640e2e3285c3e

Comment 3 ryan@testtoast.com 2023-05-17 20:35:24 UTC

Thanks, I see this a fix for this has now been committed [1], are we able to get it cherry-picked prior to the next NM release, at least for rawhide?

[1] https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/commit/eb9f3b1e3bcbf29eec8eaaac7866265bbad4a80e

Comment 4 Beniamino Galvani 2023-05-17 21:28:12 UTC

I did a build (1.43.8) for rawhide with the fix but at the moment I can't check the status because the build system (koji) is not reachable.

Comment 5 ryan@testtoast.com 2023-05-17 22:47:44 UTC

Oh sorry I see it has been tagged now. Thanks, will be patient!

Comment 6 Beniamino Galvani 2023-05-18 08:12:08 UTC

This should be fixed in NetworkManager-1.43.8-1.fc39 - https://bodhi.fedoraproject.org/updates/FEDORA-2023-2745179b59 . Please reopen if needed.

Comment 7 ryan@testtoast.com 2023-05-18 09:27:23 UTC

Fixed with 1.43.8, thanks!