Created attachment 1782501 [details]
nmstateconfig

Created attachment 1782502 [details]
cluster CRs

Note this does not reproduce with rhcos image https://mirror.openshift.com/pub/openshift-v4/dependencies/rhcos/4.7/4.7.7/rhcos-4.7.7-x86_64-live.x86_64.iso.
rhcos was updated in PR: https://github.com/openshift/assisted-service/commit/7487e12585ff3819fb05d48ca4ef6bc92c7931fb#diff-d92a102d43cdea7f87312fbeb3a7892be5648d296003a36c6a0fc5c507c1585f

Hi! I am looking into this. As this is happening with 4.8 but not with 4.7.7 it seems it is a regression from Nmstate or NM. I am trying to reproduce this locally with the nmconnection files, thank you!

(In reply to Fernando F. Mancera from comment #4)
> Hi! I am looking into this. As this is happening with 4.8 but not with 4.7.7
> it seems it is a regression from Nmstate or NM. I am trying to reproduce
> this locally with the nmconnection files, thank you!
assited-service pins nmstate to 1.0.2 https://github.com/openshift/assisted-service/blob/master/Dockerfile.assisted-service#L55

Reproduced on 48.84.202105112120-0

(In reply to nshidlin from comment #5)
> (In reply to Fernando F. Mancera from comment #4)
> > Hi! I am looking into this. As this is happening with 4.8 but not with 4.7.7
> > it seems it is a regression from Nmstate or NM. I am trying to reproduce
> > this locally with the nmconnection files, thank you!
> assited-service pins nmstate to 1.0.2
> https://github.com/openshift/assisted-service/blob/master/Dockerfile.
> assisted-service#L55

Hello!

I've been able to reproduce this issue using the nmconnection files and NetworkManager-1.30. But I've not been able to reproduce this with NetworkManager 1.26. Thomas, Beniamino could you take a look to this? Thank you!

The bond port connections created by nmstate are not activated because
there is already a connection ("Wired Connection") active on those
ethernet devices. The active connection was probably created by
dracut.

Do you have a log of the boot (if possible, captured with "rd.debug"
in the kernel command line and level=TRACE in the [logging] section
of /etc/NetworkManager/NetworkManager.conf)?

Created attachment 1784311 [details]
Boot logs rhcos 48.84.202105062123-0

Created attachment 1784684 [details]
Boot logs rhcos 47.83.202103251640-0

@bgalvani (In reply to Beniamino Galvani from comment #8)
> The bond port connections created by nmstate are not activated because
> there is already a connection ("Wired Connection") active on those
> ethernet devices. The active connection was probably created by
> dracut.
> 
> Do you have a log of the boot (if possible, captured with "rd.debug"
> in the kernel command line and level=TRACE in the [logging] section
> of /etc/NetworkManager/NetworkManager.conf)?

I attached boot logs for both the 4.8 and 4.7 envs

The difference I see between 4.7 and 4.8 log is that in the latter
there is a "Wired Connection" created from the "ip=dhcp,dhcp6" kernel
command line. This connection preempts the "enp0s4" and "enp1s0"
connections that are pre-deployed.

Having those conflicting connections in 4.8 looks like a configuration
error. I don't know why the "Wired Connection" is not present in 4.7;
that doesn't depend on NetworkManager.

I think this needs more investigation from the CoreOS team.

Noteworthy for the NM stack here, 4.7 image contains RHEL 8.3 content while the 4.8 one contains RHEL 8.4 content.

Comparing the 4.7 and 4.8 logs, it looks like both were booting with the same `ip=dhcp,dhcp6` kargs:

```
# 4.7
[    5.861476] dracut-cmdline[453]: dracut-47.83.202103251640-0 dracut-049-95.git20200804.el8_3.4
[    5.862178] dracut-cmdline[453]: Using kernel command line parameters: ip=dhcp,dhcp6 rd.driver.pre=dm_multipath BOOT_IMAGE=/images/pxeboot/vmlinuz random.trust_cpu=on ignition.firstboot ignition.platform.id=metal coreos.live.rootfs_url=https://mirror.openshift.com/pub/openshift-v4/dependencies/rhcos/4.7/4.7.7/rhcos-live-rootfs.x86_64.img

# 4.8
[    4.984415] dracut-cmdline[445]: dracut-48.84.202105062123-0 dracut-049-135.git20210121.el8
[    4.987850] dracut-cmdline[445]: Using kernel command line parameters: ip=dhcp,dhcp6 rd.driver.pre=dm_multipath BOOT_IMAGE=/images/pxeboot/vmlinuz random.trust_cpu=on ignition.firstboot ignition.platform.id=metal coreos.live.rootfs_url=http://assisted-service-assisted-installer.apps.ocp-edge-cluster-assisted-0.qe.lab.redhat.com/api/assisted-install/v1/boot-files?file_type=rootfs.img&openshift_version=4.8
```

So it could be that some behavior may have actually changed in either nm-initrd-generator or in NM running in the initrd.

Digging deeper, I see that:
 * in 4.7 logs, NM seems to immediately enslave the two interfaces to bond0 after activating the connections, skipping the default DHCP ("Wired Connection") for the enslaved interfaces.
 * in 4.8 logs, NM seems to first activate all connections, including the two additional default DHCP "Wired Connection". At that point, it does not proceed to enslave the two interfaces anymore.

Relevant snippets:
```
# 4.7 
[    9.683827] NetworkManager[888]: <info>  [1621408036.1282] policy: auto-activating connection 'enp0s4' (f53b244f-d62c-49b9-afb8-1543616e8240)
[    9.687255] NetworkManager[888]: <info>  [1621408036.1286] policy: auto-activating connection 'enp1s0' (e71b6646-9872-4beb-bf32-f70da6a5b385)
[    9.689757] NetworkManager[888]: <info>  [1621408036.1288] policy: auto-activating connection 'bond0' (cf666337-9b36-4b82-9970-8558d32b2dfa)
[    9.690187] bond0: (slave enp0s4): making interface the new active one
[    9.692116] NetworkManager[888]: <info>  [1621408036.1291] device (enp0s4): Activation: starting connection 'enp0s4' (f53b244f-d62c-49b9-afb8-1543616e8240)
[    9.693365] bond0: (slave enp0s4): Enslaving as an active interface with an up link
[    9.695434] NetworkManager[888]: <info>  [1621408036.1291] device (enp1s0): Activation: starting connection 'enp1s0' (e71b6646-9872-4beb-bf32-f70da6a5b385)
[    9.698883] NetworkManager[888]: <info>  [1621408036.1293] device (bond0): Activation: starting connection 'bond0' (cf666337-9b36-4b82-9970-8558d32b2dfa)
[    9.699295] bond0: (slave enp1s0): Enslaving as a backup interface with an up link

# 4.8
[    8.528237] NetworkManager[895]: <info>  [1621312978.4840] policy: auto-activating connection 'enp0s4' (2c518c81-b725-42dc-991e-b64b426cf5ac)
[    8.530436] NetworkManager[895]: <info>  [1621312978.4843] policy: auto-activating connection 'enp1s0' (43715223-16e0-4180-a6b7-e15fa4700de1)
[    8.532866] NetworkManager[895]: <info>  [1621312978.4845] policy: auto-activating connection 'bond0' (79a0e750-a98f-4140-9eee-25cc62d7ab23)
[    8.535505] NetworkManager[895]: <info>  [1621312978.4849] device (bond0): Activation: starting connection 'bond0' (79a0e750-a98f-4140-9eee-25cc62d7ab23)
[    8.538202] NetworkManager[895]: <info>  [1621312978.4850] policy: auto-activating connection 'Wired Connection' (7305acd5-80fa-4eb9-84da-d7278adaae41)
[    8.540525] NetworkManager[895]: <info>  [1621312978.4852] policy: auto-activating connection 'Wired Connection' (7305acd5-80fa-4eb9-84da-d7278adaae41)
[    8.542661] NetworkManager[895]: <info>  [1621312978.4854] device (enp0s4): Activation: starting connection 'enp0s4' (2c518c81-b725-42dc-991e-b64b426cf5ac)
[    8.545163] NetworkManager[895]: <info>  [1621312978.4855] device (enp1s0): Activation: starting connection 'enp1s0' (43715223-16e0-4180-a6b7-e15fa4700de1)
```

> So it could be that some behavior may have actually changed in either nm-initrd-generator or in NM running in the initrd.

You are right. It wasn't clear from the logs at info level that
connection profiles were the same. I did a git bisect and this change
added in 1.29.10 is the culprit:

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/commit/33b9fa3a3cafa2eddea3bd1774847ce9424f921d

It is fixed in git by:

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/commit/e694f2cec1a0e7bc188776c8573e07a4d57851dc

If I prepare a scratch build with the fix, would somebody be able to test it?

(In reply to Beniamino Galvani from comment #15)
> If I prepare a scratch build with the fix, would somebody be able to test it?

Scratch build of NetworkManager?

Yes.

(In reply to Beniamino Galvani from comment #17)
> Yes.

Yes, but I will need some guidance on how to install it in rhcos

While there may be a legitimate bug in NM that Beniamino has fixed upstream, I think it's piggybacking on top of another (more fundamental) bug.

In your logs we see that dracut only sees network kernel arguments of `ip=dhcp,dhcp6`:

```
[    4.987850] dracut-cmdline[445]: Using kernel command line parameters: ip=dhcp,dhcp6 rd.driver.pre=dm_multipath BOOT_IMAGE=/images/pxeboot/vmlinuz random.trust_cpu=on ignition.firstboot ignition.platform.id=metal coreos.live.rootfs_url=http://assisted-service-assisted-installer.apps.ocp-edge-cluster-assisted-0.qe.lab.redhat.com/api/assisted-install/v1/boot-files?file_type=rootfs.img&openshift_version=4.8
```

But somehow `nm-initrd-generator` (or something else) created 4 nmconnection files:

```
[   20.671708] coreos-teardown-initramfs[1212]: info: propagating initramfs networking config to the real root
[   20.673687] coreos-teardown-initramfs[1212]: '/run/NetworkManager/system-connections/bond0.nmconnection' -> '/sysroot/etc/NetworkManager/system-connections/bond0.nmconnection'
[   20.675617] coreos-teardown-initramfs[1212]: '/run/NetworkManager/system-connections/default_connection.nmconnection' -> '/sysroot/etc/NetworkManager/system-connections/default_connection.nmconnection'
[   20.678389] coreos-teardown-initramfs[1212]: '/run/NetworkManager/system-connections/enp0s4.nmconnection' -> '/sysroot/etc/NetworkManager/system-connections/enp0s4.nmconnection'
[   20.680146] coreos-teardown-initramfs[1212]: '/run/NetworkManager/system-connections/enp1s0.nmconnection' -> '/sysroot/etc/NetworkManager/system-connections/enp1s0.nmconnection'
```

This bug mentions nmstate, but I don't understand how that comes into play here (I need to do some learning), especially this early in the boot.

Can someone tell me what all is the assisted installer doing related to network configuration?

(In reply to Dusty Mabe from comment #19)
> While there may be a legitimate bug in NM that Beniamino has fixed upstream,
> I think it's piggybacking on top of another (more fundamental) bug.
> 
> In your logs we see that dracut only sees network kernel arguments of
> `ip=dhcp,dhcp6`:
> 
> ```
> [    4.987850] dracut-cmdline[445]: Using kernel command line parameters:
> ip=dhcp,dhcp6 rd.driver.pre=dm_multipath BOOT_IMAGE=/images/pxeboot/vmlinuz
> random.trust_cpu=on ignition.firstboot ignition.platform.id=metal
> coreos.live.rootfs_url=http://assisted-service-assisted-installer.apps.ocp-
> edge-cluster-assisted-0.qe.lab.redhat.com/api/assisted-install/v1/boot-
> files?file_type=rootfs.img&openshift_version=4.8
> ```
> 
> But somehow `nm-initrd-generator` (or something else) created 4 nmconnection
> files:
> 
> ```
> [   20.671708] coreos-teardown-initramfs[1212]: info: propagating initramfs
> networking config to the real root
> [   20.673687] coreos-teardown-initramfs[1212]:
> '/run/NetworkManager/system-connections/bond0.nmconnection' ->
> '/sysroot/etc/NetworkManager/system-connections/bond0.nmconnection'
> [   20.675617] coreos-teardown-initramfs[1212]:
> '/run/NetworkManager/system-connections/default_connection.nmconnection' ->
> '/sysroot/etc/NetworkManager/system-connections/default_connection.
> nmconnection'
> [   20.678389] coreos-teardown-initramfs[1212]:
> '/run/NetworkManager/system-connections/enp0s4.nmconnection' ->
> '/sysroot/etc/NetworkManager/system-connections/enp0s4.nmconnection'
> [   20.680146] coreos-teardown-initramfs[1212]:
> '/run/NetworkManager/system-connections/enp1s0.nmconnection' ->
> '/sysroot/etc/NetworkManager/system-connections/enp1s0.nmconnection'
> ```
> 
> This bug mentions nmstate, but I don't understand how that comes into play
> here (I need to do some learning), especially this early in the boot.
> 
> Can someone tell me what all is the assisted installer doing related to
> network configuration?

assisted-installer uses nmstate to generate the nmconnection files and then bakes them into the ISO

> assisted-installer uses nmstate to generate the nmconnection files and then bakes them into the ISO

Can you show me the set of steps they use (with command invocations) on how they do that? There might need to be some tweaks.

(In reply to Dusty Mabe from comment #21)
> > assisted-installer uses nmstate to generate the nmconnection files and then bakes them into the ISO
> 
> Can you show me the set of steps they use (with command invocations) on how
> they do that? There might need to be some tweaks.

@yshnaidm might be a better source for that

we are using 'nmstatectl gc' command to produce nmconnections files. This is done in the preparation step, before nodes are booted. The produced nmconnection files are then updated: the correct interfaces names are set in and autoconnect-priority=1 is added to each nmconnection file. After that those files are set into the ignition of the ISO, so that they are present under /etc/NetworkManager/system-connections before NM is brought up. @nshidlin maybe you can also provide the nmstate yaml that you have used for configuring the static network?

(In reply to yevgeny shnaidman from comment #24)
> we are using 'nmstatectl gc' command to produce nmconnections files. This is
> done in the preparation step, before nodes are booted. The produced
> nmconnection files are then updated: the correct interfaces names are set in
> and autoconnect-priority=1 is added to each nmconnection file. After that
> those files are set into the ignition of the ISO, so that they are present
> under /etc/NetworkManager/system-connections before NM is brought up.
> @nshidlin maybe you can also provide the nmstate yaml that you
> have used for configuring the static network?

All ready attached

(In reply to yevgeny shnaidman from comment #24)

<snip> 

> After that
> those files are set into the ignition of the ISO, so that they are present
> under /etc/NetworkManager/system-connections before NM is brought up.

Can you show me the code that does this part?

(In reply to Dusty Mabe from comment #26)
> (In reply to yevgeny shnaidman from comment #24)
> 
> <snip> 
> 
> > After that
> > those files are set into the ignition of the ISO, so that they are present
> > under /etc/NetworkManager/system-connections before NM is brought up.
> 
> Can you show me the code that does this part?

This is the code that sets the generated nmconnections into the ignition:
https://github.com/openshift/assisted-service/blob/a714f40bf720c30d8e491bdf54e847fb468c0654/internal/ignition/ignition.go#L1281

the ignition format itself is defined here:
https://github.com/openshift/assisted-service/blob/a714f40bf720c30d8e491bdf54e847fb468c0654/internal/ignition/ignition.go#L128

I don't think anything going on in Ignition is the problem. Can you tell me when this code runs? 

https://github.com/openshift/assisted-service/blob/a714f40bf720c30d8e491bdf54e847fb468c0654/internal/constants/scripts.go#L54
https://github.com/openshift/assisted-service/blob/a714f40bf720c30d8e491bdf54e847fb468c0654/internal/constants/scripts.go#L139-L156

If that's running in the initrd on bringup and copying files into `/run/NetworkManager/system-connections` then it's going to cause problems for the logic that we've already baked in.

(In reply to Dusty Mabe from comment #28)
> I don't think anything going on in Ignition is the problem. Can you tell me
> when this code runs? 
> 
> https://github.com/openshift/assisted-service/blob/
> a714f40bf720c30d8e491bdf54e847fb468c0654/internal/constants/scripts.go#L54
> https://github.com/openshift/assisted-service/blob/
> a714f40bf720c30d8e491bdf54e847fb468c0654/internal/constants/scripts.go#L139-
> L156
> 
> If that's running in the initrd on bringup and copying files into
> `/run/NetworkManager/system-connections` then it's going to cause problems
> for the logic that we've already baked in.

yes, this is the scripts that runs in the initrd. it's purpose is to set the correct network interfaces for the current host and copy nmconnection files to the NM runtime dir. We need it in case of running with minimal ISO, since we need to configure the network in order to download the real rootfs.
how does it causes the problem? AFAIK this scripts is executed before NM

(In reply to yevgeny shnaidman from comment #29)

> 
> yes, this is the scripts that runs in the initrd. it's purpose is to set the
> correct network interfaces for the current host and copy nmconnection files
> to the NM runtime dir. We need it in case of running with minimal ISO, since
> we need to configure the network in order to download the real rootfs.
> how does it causes the problem? AFAIK this scripts is executed before NM


It causes the prolem because it doesn't consider the rest of what happens when
networking is requested in the initrd. `nm-initrd-generator` gets run by the 
`network-manager` dracut module [1] during `dracut-cmdline.service`. It creates
the default.nmconnection file, which is the extra file that you don't want.

In the future maybe we (RHCOS) can better support your needs here by allowing you
to copy files in the initrd into a specific directory that we can then pick up
and shepherd the rest of the way into initrd and real root networking configuration.
I opened a ticket to discuss that: https://github.com/coreos/fedora-coreos-tracker/issues/841


For now, the assisted installer service will need to do something like we do for the
coreos-copy-firstboot-network.service. We explicitly run after `dracut-cmdline.service`
and before `dracut-initqueue.service`:

https://github.com/coreos/fedora-coreos-config/blob/08e72dfc25ac3b2d95a8b4fdf8e90ff1de383f71/overlay.d/05core/usr/lib/dracut/modules.d/35coreos-network/coreos-copy-firstboot-network.service#L35-L36

and we delete the files that were created by `nm-initrd-generator`: 

https://github.com/coreos/fedora-coreos-config/blob/08e72dfc25ac3b2d95a8b4fdf8e90ff1de383f71/overlay.d/05core/usr/lib/dracut/modules.d/35coreos-network/coreos-copy-firstboot-network.sh#L21-L23


The assisted installer will need to do the same.

Forgot the reference link: 

[1] https://github.com/dracutdevs/dracut/blob/9355cb8ea5024533210067373657dc337d63ecb9/modules.d/35network-manager/nm-lib.sh#L5

(In reply to Dusty Mabe from comment #30)
> (In reply to yevgeny shnaidman from comment #29)
> 
> > 
> > yes, this is the scripts that runs in the initrd. it's purpose is to set the
> > correct network interfaces for the current host and copy nmconnection files
> > to the NM runtime dir. We need it in case of running with minimal ISO, since
> > we need to configure the network in order to download the real rootfs.
> > how does it causes the problem? AFAIK this scripts is executed before NM
> 
> 
> It causes the prolem because it doesn't consider the rest of what happens
> when
> networking is requested in the initrd. `nm-initrd-generator` gets run by the 
> `network-manager` dracut module [1] during `dracut-cmdline.service`. It
> creates
> the default.nmconnection file, which is the extra file that you don't want.
> 
> In the future maybe we (RHCOS) can better support your needs here by
> allowing you
> to copy files in the initrd into a specific directory that we can then pick
> up
> and shepherd the rest of the way into initrd and real root networking
> configuration.
> I opened a ticket to discuss that:
> https://github.com/coreos/fedora-coreos-tracker/issues/841
> 
> 
> For now, the assisted installer service will need to do something like we do
> for the
> coreos-copy-firstboot-network.service. We explicitly run after
> `dracut-cmdline.service`
> and before `dracut-initqueue.service`:
> 
> https://github.com/coreos/fedora-coreos-config/blob/
> 08e72dfc25ac3b2d95a8b4fdf8e90ff1de383f71/overlay.d/05core/usr/lib/dracut/
> modules.d/35coreos-network/coreos-copy-firstboot-network.service#L35-L36
> 
> and we delete the files that were created by `nm-initrd-generator`: 
> 
> https://github.com/coreos/fedora-coreos-config/blob/
> 08e72dfc25ac3b2d95a8b4fdf8e90ff1de383f71/overlay.d/05core/usr/lib/dracut/
> modules.d/35coreos-network/coreos-copy-firstboot-network.sh#L21-L23
> 
> 
> The assisted installer will need to do the same.

@dustymabe we are especially setting autoconnect-priority property so that NM will ignore the default.nmconnection file for the interfaces that we specify. Or has that implementation been changed?

(In reply to yevgeny shnaidman from comment #32)

> 
> @dustymabe we are especially setting autoconnect-priority
> property so that NM will ignore the default.nmconnection file for the
> interfaces that we specify. Or has that implementation been changed?

I think that might be what the NM fix is about the Beniamino mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1959961#c14

Wouldn't it would be more appropriate to not have the default.nmconnection at all?

(In reply to Dusty Mabe from comment #33)
> (In reply to yevgeny shnaidman from comment #32)
> 
> > 
> > @dustymabe we are especially setting autoconnect-priority
> > property so that NM will ignore the default.nmconnection file for the
> > interfaces that we specify. Or has that implementation been changed?
> 
> I think that might be what the NM fix is about the Beniamino mentioned in
> https://bugzilla.redhat.com/show_bug.cgi?id=1959961#c14
> 
> Wouldn't it would be more appropriate to not have the default.nmconnection
> at all?

Actually , since we have a proper mechanism to prioritize our connections over default, it is easier just to set the priority and not to worry whether default connection was created and to schedule a script to delete it. Also, it allows us/user to pick specific interfaces to handle and let the default configuration take care of the rest

@yevgensm @alazar see https://bugzilla.redhat.com/show_bug.cgi?id=1959961#c35

@

@dustymabe when can we get expect this patch to merged.
Is it possible to have this released as part of 8.4.0?

We'll have to find out that information from the NetworkManager team.

Beniamino, do you know?

Created attachment 1791019 [details]
Reproducer for QE

NMCI test added:
https://gitlab.freedesktop.org/NetworkManager/NetworkManager-ci/-/merge_requests/781

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: NetworkManager security, bug fix, and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2021:4361