Bug 1600823

Since Fedora-Rawhide-20180711.n.0 (it seems), some openQA tests have been failing due to the installed system having no network connection. A few tests seem to fail for each set of tests run; which ones fail seems to be random, this seems like a quasi-random problem.

I managed to hack a bit of debugging into the tests and reproduce the issue, in this test:

https://openqa.stg.fedoraproject.org/tests/328212

At https://openqa.stg.fedoraproject.org/tests/328212#step/_console_avc_crash/7 - just after boot of the installed system - we can see the problem: the ping of an IP that should be reachable (it's actually the 'worker host', the host on which the test VM is running) fails, and `systemctl status NetworkManager.service` shows that it is not running. We capture the whole contents of /var/log from the system - I will upload that as an attachment here, as it will eventually be garbage-collected from the openQA instance. In the journal there, we see this:

Jul 12 17:38:02 localhost.localdomain systemd[1]: network-online.target: Found ordering cycle on NetworkManager-wait-online.service/start
Jul 12 17:38:02 localhost.localdomain systemd[1]: network-online.target: Found dependency on NetworkManager.service/start
Jul 12 17:38:02 localhost.localdomain systemd[1]: network-online.target: Found dependency on basic.target/start
Jul 12 17:38:02 localhost.localdomain systemd[1]: network-online.target: Found dependency on dnf-makecache.timer/start
Jul 12 17:38:02 localhost.localdomain systemd[1]: network-online.target: Found dependency on network-online.target/start
Jul 12 17:38:02 localhost.localdomain systemd[1]: network-online.target: Job NetworkManager-wait-online.service/start deleted to break ordering cycle starting with network-online.target/start

I believe that because NetworkManager.service has 'Also=NetworkManager-wait-online.service', when NetworkManager-wait-online.service/start is deleted, NetworkManager.service/start is also deleted, so NetworkManager.service does not start.

While writing this bug report it occurred to me to look at the logs from a case where the bug did *not* happen, i.e. where the network *did* come up on startup, and lo and behold, we see what looks like basically the same cycle, only represented and broken differently:

Jul 12 17:27:50 localhost.localdomain systemd[1]: dnf-makecache.timer: Found ordering cycle on network-online.target/start
Jul 12 17:27:50 localhost.localdomain systemd[1]: dnf-makecache.timer: Found dependency on network.target/start
Jul 12 17:27:50 localhost.localdomain systemd[1]: dnf-makecache.timer: Found dependency on NetworkManager.service/start
Jul 12 17:27:50 localhost.localdomain systemd[1]: dnf-makecache.timer: Found dependency on basic.target/start
Jul 12 17:27:50 localhost.localdomain systemd[1]: dnf-makecache.timer: Found dependency on dnf-makecache.timer/start
Jul 12 17:27:50 localhost.localdomain systemd[1]: dnf-makecache.timer: Job network-online.target/start deleted to break ordering cycle starting with dnf-makecache.timer/start

so it seems that sometimes systemd decides the cycle is "in" dnf-makecache.timer (and hence disables it, meaning network will work), but at other times decides the cycle is "in" NetworkManager-wait-online.service and hence disables *that* instead.

From older logs I can find it rather looks like the cycle existed before the 20180711.n.0 compose, but for some reason it was never broken by removing NetworkManager-wait-online.service before that compose; I haven't figured out why not yet.

I guess the basic actual *problem* here is that dnf-makecache.timer has these lines:

Wants=network-online.target
After=network-online.target
WantedBy=basic.target

so it wants to start as part of basic.target, but after network-online.target...which AIUI is impossible, those are both systemd special targets and by design, network-online.target comes *after* basic.target. So systemd is faced with an impossible request and has to "pick a choice". Thus, I'm assigning this to dnf.

I believe this showed up in dnf 3.x, because in dnf 2.x, dnf-makecache.timer doesn't have these mutually-exclusive demands, it just has WantedBy=basic.target , but not After=network-online.target . So that at least explains why this only showed up relatively recently, but still, I would've expected it to start being a problem in the first successful compose with DNF 3, which was 20180627.n.0. Oh, well.

Proposing as an F29 Beta blocker as this can unexpectedly cause the network to not come up after installation.