Bug 2083374

So, looking into that last question - it looks like NM connection profiles *can* work that way, but don't 'by default'.

It seems like there are various settings that can be set in an NM connection profile that effectively act as filters. If connection.interface-name is set, the profile will only be applied to a device with that interface name. For profile types that are associated with network adapters, like 802-3-ethernet for ethernet adapters, there's also a mac-address property, and if that's set, the profile will only be applied to a device with that MAC address. The filters are additive, I think - if both properties are set, the profile applies only to a device with the right name *and* the right MAC address.

It seems like the 'default' behaviour of nmcli is to write the device name into the profile. When NM creates a default profile it doesn't write a config file to disk, but if you modify that connection in any way, it writes a config file to disk which has connection.interface-name set (but no mac-address property set).

Looking through some more failures, there appears to be an even more problematic version of this race that can occur in a single boot, with no network config file. It seems like if the interface gets renamed at *just* the right time during NM startup, the rename happens, but NM is confused and does not actually bring up the network. Here's the journal from one such case, with irrelevant entries removed:

May 09 17:23:45 fedora NetworkManager[601]: <info>  [1652131425.9349] NetworkManager (version 1.37.92-1.fc37) is starting... (for the first time)
May 09 17:23:45 fedora NetworkManager[601]: <info>  [1652131425.9355] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 20-connectivity-fedora.conf)
May 09 17:23:45 fedora systemd[1]: Started NetworkManager.service - Network Manager.
May 09 17:23:45 fedora systemd[1]: Reached target network.target - Network.
May 09 17:23:45 fedora NetworkManager[601]: <info>  [1652131425.9517] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
May 09 17:23:45 fedora systemd[1]: Starting NetworkManager-wait-online.service - Network Manager Wait Online...
May 09 17:23:45 fedora NetworkManager[601]: <info>  [1652131425.9885] manager[0x55fc13845020]: monitoring kernel firmware directory '/lib/firmware'.
May 09 17:23:46 fedora systemd[1]: Starting systemd-hostnamed.service - Hostname Service...
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.4882] hostname: hostname: using hostnamed
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.4899] dns-mgr[0x55fc1381a250]: init: dns=systemd-resolved rc-manager=unmanaged (auto), plugin=systemd-resolved
May 09 17:23:46 fedora systemd[1]: Started systemd-hostnamed.service - Hostname Service.
May 09 17:23:46 fedora audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-hostnamed comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.5801] manager[0x55fc13845020]: rfkill: Wi-Fi hardware radio set enabled
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.5802] manager[0x55fc13845020]: rfkill: WWAN hardware radio set enabled
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.5894] Loaded device plugin: NMAtmManager (/usr/lib64/NetworkManager/1.37.92-1.fc37/libnm-device-plugin-adsl.so)
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.5935] Loaded device plugin: NMWifiFactory (/usr/lib64/NetworkManager/1.37.92-1.fc37/libnm-device-plugin-wifi.so)
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.6119] Loaded device plugin: NMBluezManager (/usr/lib64/NetworkManager/1.37.92-1.fc37/libnm-device-plugin-bluetooth.so)
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.6194] Loaded device plugin: NMWwanFactory (/usr/lib64/NetworkManager/1.37.92-1.fc37/libnm-device-plugin-wwan.so)
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.6205] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.6208] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.6210] manager: Networking is enabled by state file
May 09 17:23:46 fedora systemd[1]: Starting NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service...
May 09 17:23:46 fedora kernel: ppdev: user-space parallel port driver
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.6637] settings: Loaded settings plugin: keyfile (internal)
May 09 17:23:46 fedora systemd[1]: Started NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service.
May 09 17:23:46 fedora audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
May 09 17:23:46 fedora kernel: virtio_net virtio1 ens4: renamed from eth0
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.7517] dhcp-init: Using DHCP client 'internal'
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.7519] device (lo): carrier: link connected
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.7530] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.7603] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.7711] settings: (eth0): created default wired connection 'Wired connection 1'
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.7775] device (eth0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.7814] device (eth0): carrier: link connected
May 09 17:23:46 fedora systemd[1]: Listening on systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch.
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.8430] device (eth0): interface index 2 renamed iface from 'eth0' to 'ens4'
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.8692] modem-manager: ModemManager available
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.8719] device (ens4): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
May 09 17:23:46 fedora NetworkManager[601]: <info>  [1652131426.8812] manager: startup complete
May 09 17:23:46 fedora systemd[1]: Finished NetworkManager-wait-online.service - Network Manager Wait Online.
May 09 17:23:46 fedora systemd[1]: Reached target network-online.target - Network is Online.

after that, NetworkManager doesn't do anything, and the network is not up. `ip addr` shows this:

1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: ens4: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
    link/ether 52:54:00:12:34:56 brd ff:ff:ff:ff:ff:ff
    altname enp0s4

and `ip route` shows nothing.

CCing zbyzsek for systemd angle here.

> ISTR with ifcfg profiles connections could be identified by MAC address - whatever the filename was, a configuration that had a 
> `HWADDR=` line would *always* be applied to an interface with that MAC address. e.g. on the openQA server there's an `ifcfg-eth0` 
> which says `HWADDR=52:54:00:57:42:E2` - AIUI, that configuration would be applied to any interface which shows up with the MAC 
> address 52:54:00:57:42:E2, even if it's not called eth0. I guess native NetworkManager configurations don't work the same way? If 
> they did, I'd expect the existing profile to be applied even though the interface name had changed...

Whether a profile is stored in ifcfg or keyfile format makes little difference to NetworkManager.

However, "initscripts" package ships /usr/lib/udev/rename_device, which is called by udev and which reads ifcfg files. If there are ifcfg files that both specify HWADDR and the device name, then udev will rename it. So whether you use ifcfg file or not to store a NetworkManager (and have "initscripts" installed) can make a difference, for how they will be named by udev.

Device naming for ethernet is always done by udev, never NetworkManager.

I think this way of naming interfaces is surprising, and we intentionally did not update /usr/lib/udev/rename_device to also work with keyfiles. Name your interfaces either with .link files or udev rules or by setting the naming policy.


> 1. The system boots for the first time. Its network interface starts out as 'eth0', named by the kernel. NetworkManager starts up
> and creates a connection called 'Wired connection 1' on this interface.
>
> 2. Very shortly after - during the same second - systemd attempts to rename it (always to 'ens4', in openQA) but fails with this 
> error: "fedora systemd-udevd[516]: eth0: Network interface 'eth0' is already up, refusing to rename to 'ens4'."

NetworkManager does not do anything with the device, before udev is finished (renaming it). Here you claim otherwise, but it's not clear that this is really what is happening. Do you have a `level=TRACE` log? Can you pre-deploy a file /etc/NetworkManager/conf.d/99-my.conf with `[logging]\nlevel=TRACE`?

I think you run NetworkManager in initrd? If you don't want that, don't do that. It depends on the kernel command line whether NetworkManager is started. If you run NetworkManager in initrd, it seems kinda necessary that the interface-naming done by udev is the same in initrd and real-root. Did you ensure the latter?



Yes, if a NetworkManager specifies connection.interface-name and/or ethernet.mac-address, then those act as filters (except for /usr/lib/udev/rename_device above). Usually you would not set them both in a profile.

The generated "Wired connection 1" profile is initially stored in /run, but if you modify it, it possibly gets moved to persistent storage (unless you use `nmcli connection modify --temporary ...` or similar). So that's normal. Also, when this happens (moving the profile from /run to /etc), NetworkManager doesn't modify the content of the profile... unless you do it with `nmcli connection modify $NAME $OPTIONS`.


> It seems like the 'default' behaviour of nmcli is to write the device name into the profile. When NM creates a default profile it 
> doesn't write a config file to disk, but if you modify that connection in any way, it writes a config file to disk which has 
> connection.interface-name set (but no mac-address property set).

The only automatism here is that NetworkManager may (depending on configuration) generate this "Wired connection X" profile. There is not much special about it, except that NetworkManager created it (with certain settings). If you don't like it, you can just delete it (NetworkManager will remember in /var/lib/NetworkManager/no-auto-default.state to not create it again). You can also modify it and/or move from /run to /etc. If you don't like that it's tied via connection.interface-name, feel free to clear that field.

"NetworkManager does not do anything with the device, before udev is finished (renaming it). Here you claim otherwise, but it's not clear that this is really what is happening. Do you have a `level=TRACE` log? Can you pre-deploy a file /etc/NetworkManager/conf.d/99-my.conf with `[logging]\nlevel=TRACE`?"

I could, but I can't see any other possible explanation for what's happening. Nothing besides NetworkManager would be putting eth0 in an 'up' state, and the logs clearly suggest this is what is happening.

"I think you run NetworkManager in initrd? If you don't want that, don't do that. It depends on the kernel command line whether NetworkManager is started. If you run NetworkManager in initrd, it seems kinda necessary that the interface-naming done by udev is the same in initrd and real-root. Did you ensure the latter?"

I am not doing that, or at least not intentionally. These tests run on pretty stock base Fedora images produced by virt-install. The kernel command line is logged as:

Command line: BOOT_IMAGE=(hd0,msdos1)/vmlinuz-5.18.0-0.rc5.20220506gitfe27d189e3f42e3.44.fc37.x86_64 root=/dev/mapper/fedora_ibm--p8--kvm--03--guest--02-root ro rd.lvm.lv=fedora_ibm-p8-kvm-03-guest-02/root rhgb quiet

The log messages above are all from the part of the boot process after we have switched to the 'real' system root, they are not from initramfs phase. I'm attaching a full log file from a case of the original type - this test failure: https://openqa.stg.fedoraproject.org/tests/1774143 . Because the network connection is not working, we dump out various useful bits of information via a serial console, and that's what I'm attaching. There are 'headers' dividing the various bits of diagnostic output that look like this:

** IP ADDR **

** IP ROUTE **

** NETWORKMANAGER.SERVICE STATUS **

etc. etc. Any line that looks like "cPu7m-0-" (a short random string ending in -N-) is an artifact of how console commands are run in openQA and can be ignored. It should be obvious from the headers what each bit of output is. "JOURNAL" is journal output from the boot where the test failed, i.e., where the network did not come up; you will note it tries to bring up a "Wired connection 2" on ens4 and that doesn't work. "JOURNAL -1" is journal output from the *previous* boot, where the network was configured; you will see it refers to "Wired connection 1" on eth0, which initially doesn't work (when NM first tries to bring it up with DHCP) but later works (when the openQA test configures it for static IP). You will also note the "eth0: Network interface 'eth0' is already up, refusing to rename to 'ens4'." error in the JOURNAL -1 output but not the JOURNAL output. There is no difference in kernel parameters or anything like that between the two boots.

"You can also modify it and/or move from /run to /etc. If you don't like that it's tied via connection.interface-name, feel free to clear that field."

This is what I've done as a workaround, but this is a problem that could affect anybody using the default tools in a natural way, and which is not very obvious to diagnose. (It would also be problematic if I wanted to write a test that uses two network interfaces with different configurations, I guess, but fortunately ATM I don't have a reason to do that).

Created attachment 1878244 [details]
full logs from a failed openqa test

This is everything relevant the test does:

1. It boots from a base disk image, disk_f37_server_3_x86_64.qcow2 , which is a fairly stock Rawhide Server install built by virt-install using this kickstart: https://pagure.io/fedora-qa/createhdds/blob/main/f/server.ks . qemu is configured to use tap networking via an interface provided by the host system using openvswitch, with no DHCP server available on the virtual network.
2. It runs this command to find the name of the network connection to modify: nmcli --fields NAME con show | head -2 | tail -1 . In the case we're concerned with, this always gives the result "Wired connection 1".
3. It runs this command to configure the connection: nmcli con mod 'Wired connection 1' ipv4.method manual ipv4.addr 172.16.2.105/24 ipv4.gateway 172.16.2.2 ipv4.dns "10.3.163.33, 10.3.163.34"
4. It brings the connection down then up to ensure the configuration is applied: nmcli con down 'Wired connection 1' , nmcli con up 'Wired connection 1'
5. It runs nmcli -t con show 'Wired connection 1' , as a debugging step
6. It installs all available stable updates (since the last time the base image was rebuilt), and the candidate update to be tested
7. It reboots, then tries to use the network again, whereupon it fails as described in this bug

That's everything it does. We don't do anything weird to the boot config, kernel command line, NM configuration or anything else between 5 and 7. There is nothing weird about the base disk image used for testing either.

Since I adjusted step 3 to do this instead:

nmcli con mod 'Wired connection 1' ipv4.method manual ipv4.addr 172.16.2.105/24 ipv4.gateway 172.16.2.2 connection.interface-name '' ipv4.dns "10.3.163.33, 10.3.163.34"

the affected tests have not failed once, which seems to support my reading of what's going on.

The worse case described in comment #2 is even simpler: in that case, we do not use tap networking and there is no reboot involved. Literally all openQA does is boot from the base image, using qemu user networking, and then try to access the network. I'm attaching similar log output from that case. In this case - https://openqa.stg.fedoraproject.org/tests/1774143 - all the test did was boot (network came up successfully on the first boot, see JOURNAL -1 messages), install all updates, reboot, and try to use the network, which failed.

Created attachment 1878245 [details]
full logs from the worse type of failure (no manual connection config involved)

Is it possible to obtain level=TRACE logs of NetworkManager, in particular for the first boot?

See https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/blob/main/contrib/fedora/rpm/NetworkManager.conf#L27 for hints about logging.

Hah, well, it should be, except...to do that I had to re-generate the base image, and it happened to pick up a non-debug kernel since that's what is in Rawhide now (some Rawhide kernels have debugging enabled, some don't). And I think that almost completely stopped the bug happening. I've been re-running the test all day long - I've done well over 100 runs now - and it's only failed once; with the previous base image it would fail about 2 out of 10 times. This supports my theory from the bug description - that we're seeing this problem on Rawhide updates because debug kernels affect the timing, I'm guessing by making the rename happen slower relative to NM starting up.

The one time it failed, I realized I had disabled the logging of the journal from the previous boot again (it's not something we do regularly), so that was missing :( I put it back and have been re-running the test over and over ever since, but haven't got another failure yet.

A new Rawhide kernel build was done today and that one's a debug one, so tomorrow's Rawhide should have that. If this last batch of retries I just fired doesn't get a failure, I can re-generate the base image again tomorrow and try again.

(In reply to Adam Williamson from comment #11)
> A new Rawhide kernel build was done today and that one's a debug one, so
> tomorrow's Rawhide should have that. If this last batch of retries I just
> fired doesn't get a failure, I can re-generate the base image again tomorrow
> and try again.

That's great. Thank you for all your efforts!!

Created attachment 1878691 [details]
journal -1 with trace debugging (first boot, rename to ens4 fails)

Created attachment 1878695 [details]
journal 0 with trace debugging (second boot, rename to ens4 succeeds, bug occurs)

OK, so yeah, I just re-generated the base image, got a debug kernel, and as expected the bug started happening again. Here are the journal outputs with trace debugging enabled, attached separately for ease of reference.

You may note a sort of phantom 'enp1s0' connection in the NetworkManager logs; according to the kernel and `ip addr` output, there is no such interface. I suspect this is because the `virt-install` image creation process somehow leaves a `/etc/NetworkManager/system-connections/enp1s0.nmconnection` file on the disk. I don't think it's related to this bug, though.

> journal -1 with trace debugging (first boot, rename to ens4 fails)

Here NM enumerates devices via udev and eth0 is already there; so NM starts managing it:

  May 11 11:36:02 fedora NetworkManager[667]: <trace> [1652283362.0320] platform-linux: udev-add[eth0,2]: device added
  May 11 11:36:02 fedora NetworkManager[667]: <trace> [1652283362.0336] platform-linux: udev-add[lo,1]: device added

Later, udev tries to rename the interface and fails because NM already brought it up:

  May 11 11:36:02 fedora systemd-udevd[514]: eth0: Network interface 'eth0' is already up, refusing to rename to 'ens4'.

There is something wrong here, as the interface should be reported by udev only after the rename.

Perhaps something changed in udev?

Thanks Beniamino.

The relevant code of NetworkManaer is here:
https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/blob/19a96f64edc8a1f592838f210d681e72b7af68a8/src/libnm-platform/nm-linux-platform.c#L9812

To me this also looks like a udev/libudev bug. Reassigning for investigation.

this looks suspicious to me:

https://github.com/systemd/systemd/commit/d8b50e5df7e01983279e70c6d970fb60d053df97

Thanks a lot for the debugging. I've added a note to the upstream PR that introduced that commit so hopefully the author and Lennart will take a look.

(In reply to Thomas Haller from comment #17)
> this looks suspicious to me:
> 
> https://github.com/systemd/systemd/commit/
> d8b50e5df7e01983279e70c6d970fb60d053df97

I looked again, it does not seem suspicious anymore :)

I don't know what the problem is. Please ignore my earlier comment.

The investigation seems correct. I opened a PR https://github.com/systemd/systemd/pull/23352.

(In reply to Yu Watanabe from comment #20)
> The investigation seems correct. I opened a PR
> https://github.com/systemd/systemd/pull/23352.

Oh, I read that code several times, didn't notice it...
Thanks for the fast fix!

Yep! I can test the fix, I just need to backport the patch and then build a base disk image that has the patched systemd included, then run the test a few times. Should be done this afternoon.

Testing looks good, ran the problematic openQA test 20 times with a base image that includes a systemd build with this fix, passed 20 times. Without this fix it usually fails at least 1 in 5 times. Thanks!

I'll do an official Rawhide build with the fix too, it'll just make life easier for me.

OK, https://koji.fedoraproject.org/koji/taskinfo?taskID=86918751 should fix this. I'll re-open if it turns out we were off-base.