Bug 1372854

The Fedora QA team uses an automated test system called openQA:

https://openqa.fedoraproject.org/

what openQA basically does is run virtual machines - using qemu user-mode networking - and then...test stuff in them. Most of the tests are installer tests.

Every so often, a test which uses a network repository will fail because the network was not correctly brought up. anaconda fails to configure the network repository, and when openQA tries to send some log files out from the VM (by uploading them to a web server it runs for this purpose), it cannot reach the network either.

I've been debugging this by creating a special openQA test which simply boots the installer, tries to upload a log file (to see if the network is working), and dumps out a bunch of diagnostic info via the serial console if it hits the bug. I've been running this test over and over, 8 runs at a time. It seems like we hit the failure approximately once in every 30 or 40 runs of the test.

From the diagnostic info we got out, it seems like what happens is that NetworkManager tries to configure the interface via DHCP, but decides the DHCP request failed after a 45 second timeout.

We tried a couple of variations on the test. First we modified the test so NetworkManager uses its internal DHCP client rather than dhclient (by using an anaconda updates.img which adds an NM config file to specify that setting). I tried ~100 runs with that configuration and did not get a single failure.

Second we modified the test to boot to dracut's emergency shell, rather than anaconda, and run 'dhclient ens4' directly from the shell. Again I tried ~100 runs of that, and it successfully brought up the network every time.

So it seems like this only happens with NM+dhclient. Finally, we got a failed run with as much diagnostic info as we could:

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

all the info is in the serial console log:

https://openqa.stg.fedoraproject.org/tests/37112/file/serial0.txt

under IP ADDR is the output of 'ip addr'. Under ROUTE is the output of 'route'. From these you can see that the interface has no IPv4 address and there is no default route. Under JOURNAL is the output of 'journalctl --no-pager', and under SYSLOG is the contents of /tmp/syslog , where some messages which don't appear to reach the journal show up.

Crucially, in /tmp/syslog , we can see that there is actually what looks like a perfectly successful dhclient session:

22:17:15,711 INFO dhclient: Created duid "\000\004\307\326\2422\011\036N\246\217N\251 \030\353\023\313".
22:17:15,711 INFO dhclient: DHCPDISCOVER on ens4 to 255.255.255.255 port 67 interval 3 (xid=0x6ad3f212)
22:17:15,712 INFO dhclient: DHCPREQUEST on ens4 to 255.255.255.255 port 67 (xid=0x6ad3f212)
22:17:15,712 INFO dhclient: DHCPOFFER from 10.0.2.2
22:17:15,712 INFO dhclient: DHCPACK from 10.0.2.2 (xid=0x6ad3f212)
22:17:15,721 INFO dhclient: bound to 10.0.2.15 -- renewal in 38317 seconds.

This is indeed right where NM ran dhclient - you can see that from the journal NM logs:

Sep 02 22:17:15 localhost NetworkManager[1600]: <debug> [1472854635.4244] dhcp4 (ens4): running: /sbin/dhclient -d -q -sf /usr/libexec/nm-dhcp-helper -pf /var/run/dhclient-ens4.pid -lf /var/lib/NetworkManager/dhclient-a84395a1-4721-30e0-9fbb-e422b26ac329-ens4.lease -cf /var/lib/NetworkManager/dhclient-ens4.conf ens4
Sep 02 22:17:15 localhost NetworkManager[1600]: <info>  [1472854635.4387] dhcp4 (ens4): dhclient started with pid 1681

however, it seems like NM never realizes that dhclient worked, and instead it gives up and kills the dhclient process 45 seconds later:

Sep 02 22:18:00 localhost NetworkManager[1600]: [0;1;39m<warn>  [1472854680.5422] dhcp4 (ens4): request timed out[0m
Sep 02 22:18:00 localhost NetworkManager[1600]: <info>  [1472854680.5428] dhcp4 (ens4): state changed unknown -> timeout
Sep 02 22:18:00 localhost NetworkManager[1600]: <debug> [1472854680.5428] device[0x56481bc0f9e0] (ens4): new DHCPv4 client state 2
Sep 02 22:18:00 localhost NetworkManager[1600]: <debug> [1472854680.5428] device[0x56481bc0f9e0] (ens4): DHCPv4 failed: timeout 1, num tries left 3
Sep 02 22:18:00 localhost NetworkManager[1600]: <debug> [1472854680.5428] device[0x56481bc0f9e0] (ens4): remove_pending_action (0): 'dhcp4'
Sep 02 22:18:00 localhost NetworkManager[1600]: <info>  [1472854680.5428] manager: startup complete
Sep 02 22:18:00 localhost NetworkManager[1600]: <debug> [1472854680.5444] kill child process 'dhcp-client-ens4' (1681): waiting up to 500 milliseconds for process to terminate normally after sending SIGTERM (15)...
Sep 02 22:18:00 localhost NetworkManager[1600]: <debug> [1472854680.5528] kill child process 'dhcp-client-ens4' (1681): after sending SIGTERM (15), process 1681 exited by signal 15 (8416 usec elapsed)
Sep 02 22:18:00 localhost NetworkManager[1600]: <info>  [1472854680.5533] dhcp4 (ens4): canceled DHCP transaction, DHCP client pid 1681
Sep 02 22:18:00 localhost NetworkManager[1600]: <info>  [1472854680.5533] dhcp4 (ens4): state changed timeout -> done

so the problem is somewhere in NM's communication with its dhclient process, I guess. thaller is looking into this at present.

This bug seems to occur in both Fedora 25 and Fedora Rawhide tests. The failures have been occurring for some time now, certainly we have failures with the git20160621.072358da snapshot. I don't believe we've actually hit this failure with the final 1.4.0 yet, but it's only been in Rawhide a few days and is not in F25 yet, so that may just be blind luck. I'll run my reproducer test on a recent Rawhide image and confirm whether I can trigger the bug there too.