Bug 1888348

Created attachment 1721526 [details]
System logs with NM trace enabled

> Nmstate fail complaining about lossing bond ports.

The logfile shows a lot of things happening, I don't see what is considered wrong there.

the last step of the reproducer script is one nmstatectl call, which "fails". But the bug report doesn't explain *why* it fails. What means "loosing bond ports"? Because at timestamp 1602686937.7269 we see that the bond ports are about to activate. 

Then, at timestamp "1602686937.9038" there is another activation request for bond0 (although bond0 is already about to be re-activated due to the bridge's connection.autoconnect-slave settinngs).

but even after that, the bond ports are again about to re-activate (e.g. at 1602686938.4919).


Until at 1602686938.5156, nmstate gives up and tears everthing down.


I think nmstate should simply have waited longer, and it would have reached the expected configuration. By "longer", I don't mean a long time. nmstate aborted after less than 2 seconds.

Also, the reproducer script (and afterwards the nmstate call) perform the activations in a manner that result in multiple activations. E.g. nmstate calling connection-activate for bond1 results in the dummy devices to be re-activated. Although, they were already activated. This is related to the email thread "bulk profile activation?". But regardless, I think nmstate just didn't wait long enough before giving up. Back to my earlier question: how did nmstate determine that something is wrong and abort?

(In reply to Thomas Haller from comment #3)
> > Nmstate fail complaining about lossing bond ports.
> 
> The logfile shows a lot of things happening, I don't see what is considered
> wrong there.
> 
> the last step of the reproducer script is one nmstatectl call, which
> "fails". But the bug report doesn't explain *why* it fails. What means
> "loosing bond ports"? Because at timestamp 1602686937.7269 we see that the
> bond ports are about to activate. 

Losing bond port means, dummy_98/_99 is not set as bond port but still exists
in `ip link`.

> 
> Then, at timestamp "1602686937.9038" there is another activation request for
> bond0 (although bond0 is already about to be re-activated due to the
> bridge's connection.autoconnect-slave settinngs).

I don't know how NM internally is doing.

Nmstate after activation on newly created bridge, then wait it finish.
Then activate the bond.

> 
> but even after that, the bond ports are again about to re-activate (e.g. at
> 1602686938.4919).
> 
> 
> Until at 1602686938.5156, nmstate gives up and tears everthing down.
> 
> 
> I think nmstate should simply have waited longer, and it would have reached
> the expected configuration. By "longer", I don't mean a long time. nmstate
> aborted after less than 2 seconds.

Actually, after profile been marked as activated by NM. Nmstate will verify
the state every seconds and retry 5 times.

So nmstate only fail after 5 seconds.

> 
> Also, the reproducer script (and afterwards the nmstate call) perform the
> activations in a manner that result in multiple activations. E.g. nmstate
> calling connection-activate for bond1 results in the dummy devices to be
> re-activated. Although, they were already activated. This is related to the
> email thread "bulk profile activation?". But regardless, I think nmstate
> just didn't wait long enough before giving up. Back to my earlier question:
> how did nmstate determine that something is wrong and abort?

Nmstate detemine something is wrong by verify the state after NM applied the 
configure. We retried 5 times with 1 second interval.

If you need a server to debug yourself, I can ask RHV to perpare one.

The log you see does not have verification state in nmstate as the reproduce script use `--no-verify`.

I tried to wait longer, the dummy interface is still not changed to be bond port.

In the logfile from comment 1, nmstate only gives 1.3 seconds before aborting.

See:

[1602686937.3058] audit: op="checkpoint-create" arg="/org/freedesktop/NetworkManager/Checkpoint/1" pid=1819111 uid=0 result="success"
[1602686937.3131] audit: op="connection-update" uuid="fd5a3119-59de-4e1b-a623-205aeff957db" name="bond1" args="bond.options,connection.master,connection.lldp,connection.slave-type,ipv6.met>
[1602686937.3158] audit: op="connection-add" uuid="9fd8cab8-2a89-474f-9d37-918a9fde8afa" name="C18_nm_network2" pid=1819111 uid=0 result="success"
[1602686937.3447] audit: op="connection-activate" uuid="9fd8cab8-2a89-474f-9d37-918a9fde8afa" name="C18_nm_network2" pid=1819111 uid=0 result="success"
[1602686937.7329] audit: op="device-managed" arg="managed" pid=1819111 uid=0 result="success"
[1602686937.9038] audit: op="connection-activate" uuid="fd5a3119-59de-4e1b-a623-205aeff957db" name="bond1" pid=1819111 uid=0 result="success"
[1602686938.4954] audit: op="device-delete" interface="br-int" ifindex=9 pid=1819111 uid=0 result="success"
[1602686938.5156] audit: op="checkpoint-destroy" arg="/org/freedesktop/NetworkManager/Checkpoint/1" pid=1819111 uid=0 result="success"

nmstate was not waiting long enough. It is not clear whether the activation would have proceeded correctly, if nmstate had waited longer. But there is no reason to assume that it wouldn't.


> Actually, after profile been marked as activated by NM. Nmstate will verify
> the state every seconds and retry 5 times.
> 
> So nmstate only fail after 5 seconds.

Such a retry is not visible in the logfile from comment 1.


> I tried to wait longer, the dummy interface is still not changed to be bond port.

Is there a log of that?


Why did nmstate decide to abort at (around) timestamp 1602686938.5? At that point, the activation seemed right on track.

Created attachment 1735478 [details]
Reproduce script

Version reproducer works in VM.

Created attachment 1735479 [details]
System logs with NM trace enabled

New log

Hi Thomas,

I have reproduced this problem locally in my RHEL 8.3 VM.

Reproducer: for x in `seq 1 100`; do sudo ./bug.sh || break; done

The failure in new log is both `dummy_98` and `dummy_99` are not assigned to bond1.

The log shows both `dummy_98` and 99 been marked as activated before `bond1` been marked as activated.

I made some notes on this logs at http://people.redhat.com/fge/bz_1888348/nm_log_notes.md

The same problem is also reproducable on NetworkManager-1.30.0-0.2.el8.x86_64.

And in the new log, nmstate has waited 5 seconds(keep rechecking whether bond1 has dummy_98 and 99 as port) before rollback.

Hi Michael,

we would be able to backport this to 8.3.0.2, we still have a (small) time window to include this fix.

Would that be alright?

(In reply to Antonio Cardace from comment #16)
> Hi Michael,
> 
> we would be able to backport this to 8.3.0.2, we still have a (small) time
> window to include this fix.
> 
> Would that be alright?

Hi Antonio,
Yes, this will be great for us! Thank you very much.

Fixed on master:

https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/commit/8180b0180beba0c492bf172a32069c77e501f884

Setting OtherQA and marking verified as RHV team was the only one that was able to verify the fix. Even VM with a lot of CPU load is not showing issue with reproducer suggested in comment #9.

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 and libnma 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:1574