Hide Forgot
For the Red Hat CoreOS (RHCOS) project, we want to run tests against newly generated RHCOS images using the `kola` (https://github.com/coreos/mantle/kola)est framework. This framework allows us to boot and test new RHCOS images using qemu as an unprivileged user. In this scenario, we are isolating the guest from the host using qemu networking options and how DHCP addresses are handed out. Notably, the DHCP offer does not have any default route provided. When the host comes up, we can see it reach the `network-online.target`, however we can see the `crio.service` fail immediately afterwards because it detects `/proc/net/route` and `/proc/net/ipv6_route` are not populated. (crio.service has `After=network-online.target` in the systemd unit file) If we restart the `crio.service` after login, it starts successfully because the routes have been established. This leads us to believe that NetworkManager is indicating `network-online` earlier than it should, since routing hasn't been established. There is a similar looking problem fixed in `systemd-networkd` that clued us in on this potential problem in NetworkManager: https://github.com/systemd/systemd/pull/8728 To replicate this problem: 1. Checkout the `mantle` repo and build `kola` $ git clone https://github.com/coreos/mantle $ cd mantle/kola $ ./build kola 2. Grab a recent RHCOS build $ curl --compressed -J -L -O https://releases-art-jenkins.cloud.paas.upshift.redhat.com/storage/releases/ootpa/410.8.20190520.0/rhcos-410.8.20190520.0-qemu.qcow2 3. Spawn a `kola` session using `qemu-unpriv` $ kola spawn --qemu-image rhcos-410.8.20190520.0-qemu.qcow2 -p qemu-unpriv --ignition-version v2 4. Observe the failed `crio.service` upon login
Clarification on first comment: Notably that `systemd-networkd` bug means that `wait-online` is never reached, because the route is never considered ready
Could you attach level=TRACE logfile for NetworkManager? See https://cgit.freedesktop.org/NetworkManager/NetworkManager/tree/contrib/fedora/rpm/NetworkManager.conf#n28 Note that if you set ipv4.may-fail=yes (the default) and IPv6 is enabled and completes first, then the connection is considered fully activated (NM doesn't know that it should wait for DHCPv4 as well). Did you try setting ipv4.may-fail=no?
Created attachment 1572902 [details] journal with NM trace enabled
I've uploaded a journal with TRACE enabled in the failure case. I'll try with `ipv4.may-fail=no` next.
I tried to configure the connection to use `ipv4.may-fail=no` in an ifcfg network-script, but it doesn't seem to have taken effect: $ cat /etc/sysconfig/network-scripts/ifcfg-ens4 DEVICE="ens4" BOOTPROTO="dhcp" NM_CONTROLLED="yes" ONBOOT="yes" TYPE="Ethernet" IPV4_FAILURE_FATAL="no" $ nmcli con show NAME UUID TYPE DEVICE System ens4 e27f182b-d125-2c43-5a30-43524d0229ac ethernet ens4 $ nmcli con show "System ens4" | grep fail ipv4.may-fail: yes ipv6.may-fail: yes I'll attach the journal with level=TRACE enabled for this case too
Created attachment 1572925 [details] journal with NM trace enabled; IPV4_FAILURE_FATAL="no"
The thing that delays "network-online.target" is "NetworkManager-wait-online.service". That one is basically reached when NetworkManager logs the message <info> [1558709935.7694] manager: startup complete In the log from comment 6 you see that happens shortly after "ens4" reaches "activated" state. <info> [1558709935.7430] device (ens4): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed') ... which, happens after NM receives DHCP configuration and configures IP addresses and routes. $ zcat journal-raw.txt.gz | sed -n 's/^MESSAGE=//p' | grep 'is starting\|device.*state change:\|startup complete\|platform: signal: route' shows that at that point there is no default route yet. Note that the profile has ipv6.method=ignore. In that case, "ipv6.may-fail" has no effect (because "ignore" method always succeed right away). Hence, once IPv4 is up, the device is fully activated. Do you expect an IPv4 default route there? If you want to wait for the IPv6 configuration, you probably should set "ipv6.method=auto". What do you think? PS: is there a convenient tool how to read the raw journal output? I appreciate getting the full structured logging, but is there a good way to read that? (aside "grep"). Can `journalctl` consume that as input?
(In reply to Thomas Haller from comment #7) > PS: is there a convenient tool how to read the raw journal output? I > appreciate getting the full structured logging, but is there a good way to > read that? (aside "grep"). Can `journalctl` consume that as input? Sorry about the raw journal files. kola provides `journal.txt` and `journal-raw.txt.gz`, but I mistakenly thought the .gz was just a gzipped version of the text file. I'll provide normal journal files going forward. Now that I'm looking at this more carefully with the information you've extracted, this may be an issue with the `crio.service` It originally fails like so: $ journalctl -b | grep crio May 24 16:36:10 localhost.localdomain crio[1135]: time="2019-05-24 16:36:10.717209235Z" level=fatal msg="no default routes found in "/proc/net/route" or "/proc/net/ipv6_route"" May 24 16:36:10 localhost.localdomain systemd[1]: crio.service: Main process exited, code=exited, status=1/FAILURE May 24 16:36:10 localhost.localdomain systemd[1]: crio.service: Failed with result 'exit-code'. When I'm able to get a login prompt on the host and inspect those two files: $ cat /proc/net/route Iface Destination Gateway Flags RefCnt Use Metric Mask MTU Window IRTT ens4 0002000A 00000000 0001 0 0 100 00FFFFFF 0 0 0 $ cat /proc/net/ipv6_route 00000000000000000000000000000001 80 00000000000000000000000000000000 00 00000000000000000000000000000000 00000100 00000001 00000000 00000001 lo fe800000000000000000000000000000 40 00000000000000000000000000000000 00 00000000000000000000000000000000 00000100 00000002 00000000 00000001 ens4 fec00000000000000000000000000000 40 00000000000000000000000000000000 00 00000000000000000000000000000000 00000100 00000001 00000000 004c0001 ens4 00000000000000000000000000000000 00 00000000000000000000000000000000 00 fe800000000000000000000000000002 00000400 00000001 00000000 00450003 ens4 00000000000000000000000000000001 80 00000000000000000000000000000000 00 00000000000000000000000000000000 00000000 00000003 00000000 80200001 lo fe80000000000000505400fffe123456 80 00000000000000000000000000000000 00 00000000000000000000000000000000 00000000 00000003 00000000 80200001 ens4 fec0000000000000505400fffe123456 80 00000000000000000000000000000000 00 00000000000000000000000000000000 00000000 00000002 00000000 80200001 ens4 ff000000000000000000000000000000 08 00000000000000000000000000000000 00 00000000000000000000000000000000 00000100 00000003 00000000 00000001 ens4 00000000000000000000000000000000 00 00000000000000000000000000000000 00 00000000000000000000000000000000 ffffffff 00000001 00000000 00200200 lo $ ip route 10.0.2.0/24 dev ens4 proto kernel scope link src 10.0.2.15 metric 100 $ ip -6 route ::1 dev lo proto kernel metric 256 pref medium fe80::/64 dev ens4 proto kernel metric 256 pref medium fec0::/64 dev ens4 proto kernel metric 256 expires 86154sec pref medium default via fe80::2 dev ens4 proto ra metric 1024 expires 1554sec hoplimit 64 pref medium So there are no default routes present, but there is are routes defined. However if I restart the `crio.service`, it starts successfully, but the routing table hasn't changed. $ sudo systemctl restart crio.service $ journalctl -b | grep "crio\|Open Container" May 24 16:36:10 localhost.localdomain systemd[1]: Starting Open Container Initiative Daemon... May 24 16:36:10 localhost.localdomain crio[1135]: time="2019-05-24 16:36:10.717209235Z" level=fatal msg="no default routes found in "/proc/net/route" or "/proc/net/ipv6_route"" May 24 16:36:10 localhost.localdomain systemd[1]: crio.service: Main process exited, code=exited, status=1/FAILURE May 24 16:36:10 localhost.localdomain systemd[1]: crio.service: Failed with result 'exit-code'. May 24 16:36:10 localhost.localdomain systemd[1]: Failed to start Open Container Initiative Daemon. May 24 16:38:18 localhost.localdomain sudo[1410]: core : TTY=pts/0 ; PWD=/var/home/core ; USER=root ; COMMAND=/bin/systemctl restart crio May 24 16:38:18 localhost.localdomain systemd[1]: Starting Open Container Initiative Daemon... May 24 16:38:18 localhost.localdomain systemd[1]: Started Open Container Initiative Daemon. So why is it starting successfully if the routing table hasn't changed? It doesn't seem likely that `/proc/net/route` or `/proc/net/ipv6_route` wouldn't be populated by the time NetworkManager is online with the message <info> [1558709935.7694] manager: startup complete Let me contact the crio folks and see if they can give me some additional info.
Created attachment 1575393 [details] journal with NM trace enabled; crio debug build used
The crio folks were able to provide me with a version of the crio binary that would dump the contents of /proc/net/route and /proc/net/ipv6_route during startup. I was able to see that the IPv6 routing table changed between reaching `network-online.target` and when the `crio` service successfully started afterwards. I've attached another journal that shows the `crio` service initially failing, then starting successfully after the IPv6 routing table changed. My confusion lies in whether the changes to the routing table should be interpreted as having a valid default route installed, as crio expects. From what I can tell (and I might be spectacularly wrong), the host identifies a default IPv6 route via fe80::2 before `network-online.target` is reached. Additional routes are added afterwards, but the default route is left unchanged. My understanding is that `crio` is using a kubernetes library to decide on the default route; I believe the code is here: https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apimachinery/pkg/util/net/interface.go#L131 I know my use case is a bit contrived, but it seems like there might be a disconnect between what `crio` expects as a default route and what NetworkManager is reporting. I've added one of the crio developers (Mrunal Patel) to this BZ in hopes of spurring some cross-team discussion.
Hi, when DHCPv4 succeeds the connection on ens4 becomes ACTIVATED and we signal the online status. May 30 16:40:55.774207 NetworkManager[1028]: <info> [1559248855.7742] dhcp4 (ens4): state changed unknown -> bound May 30 16:40:55.775515 NetworkManager[1028]: <info> [1559248855.7755] device (ens4): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed') May 30 16:40:55.792243 systemd[1]: Reached target Network is Online. But there isn't any default route because DHCPv4 didn't provide a gateway. May 30 16:40:56.236668 crio[1134]: time="2019-05-30 20:40:56.236635121Z" level=fatal msg="no default routes found in "/proc/net/route" or "/proc/net/ipv6_route"" IPv6 autoconf obtains a default route later: May 30 16:40:57.365597 NetworkManager[1028]: <debug> [1559248857.3655] ndisc-lndp[0x56159d2560e0,"ens4"]: received router advertisement at 4 May 30 16:40:57.365610 NetworkManager[1028]: <debug> [1559248857.3656] ndisc[0x56159d2560e0,"ens4"]: complete-address: using an stable-privacy address May 30 16:40:57.365617 NetworkManager[1028]: <debug> [1559248857.3656] ndisc[0x56159d2560e0,"ens4"]: neighbor discovery configuration changed [dGAR]: May 30 16:40:57.365622 NetworkManager[1028]: <debug> [1559248857.3656] ndisc[0x56159d2560e0,"ens4"]: dhcp-level none May 30 16:40:57.365632 NetworkManager[1028]: <debug> [1559248857.3656] ndisc[0x56159d2560e0,"ens4"]: gateway fe80::2 pref medium exp 1799.9990 May 30 16:41:14.627108 crio[1381]: 00000000000000000000000000000000 00 00000000000000000000000000000000 00 fe800000000000000000000000000002 00000064 00000001 00000000 00000003 ens4 If you need to wait that IPv6 autoconf completes, set ipv6.may-fail=no (or add IPV6_FAILURE_FATAL=yes in the ifcfg file).
Hi Beniamino, thanks for your reply. I've tried my scenario again using `IPV6_FAILURE_FATAL=yes` in the ifcfg file and I'm continuing to see `crio` fail to start for the same reason. From what I can glean from the debug messages from NM, it looks like the IPv6 default route is being added after reaching `network-online.target`. (However, I could be mis-interpreting what I am seeing...) I've attached another journal; I appreciate you continuing to help me with this particular issue. FWIW, here's what my `ifcfg` file looks like: ``` $ cat /etc/sysconfig/network-scripts/ifcfg-ens4 DEVICE="ens4" BOOTPROTO="dhcp" NM_CONTROLLED="yes" ONBOOT="yes" TYPE="Ethernet" IPV4_FAILURE_FATAL="yes" IPV6_FAILURE_FATAL="yes" ```
Created attachment 1579156 [details] journal with NM trace enabled; crio debug build used; IPV6_FAILURE_FATAL=yes
The connection now doesn't have IPv6 enabled (note the method = ignore): <debug> [1560196514.7395] ++ ipv6 [ 0x55f7f1bf0340 ] <debug> [1560196514.7395] ++ ipv6.addresses = ((GPtrArray*) 0x55f7f1c2d3a0) <debug> [1560196514.7395] ++ ipv6.dns = [] <debug> [1560196514.7396] ++ ipv6.dns-search = [] <debug> [1560196514.7396] ++ ipv6.method = 'ignore' <debug> [1560196514.7397] ++ ipv6.routes = ((GPtrArray*) 0x55f7f1c2d340) You should run: nmcli connection modify 'System ens4' ipv6.method auto ipv6.may-fail no to enable IPv6 autoconf and let the connection wait for IPv6.
(In reply to Beniamino Galvani from comment #14) > The connection now doesn't have IPv6 enabled (note the method = ignore): > > <debug> [1560196514.7395] ++ ipv6 [ 0x55f7f1bf0340 ] > <debug> [1560196514.7395] ++ ipv6.addresses = ((GPtrArray*) > 0x55f7f1c2d3a0) > <debug> [1560196514.7395] ++ ipv6.dns = [] > <debug> [1560196514.7396] ++ ipv6.dns-search = [] > <debug> [1560196514.7396] ++ ipv6.method = 'ignore' > <debug> [1560196514.7397] ++ ipv6.routes = ((GPtrArray*) > 0x55f7f1c2d340) > > You should run: > > nmcli connection modify 'System ens4' ipv6.method auto ipv6.may-fail no > > to enable IPv6 autoconf and let the connection wait for IPv6. Huh...not sure how that got disabled. I'll try again with everything properly enabled. Thanks for the pointer!
https://github.com/cri-o/cri-o/issues/2478
Hi Micah, do you have any updates on this?
(In reply to Beniamino Galvani from comment #17) > Hi Micah, > > do you have any updates on this? Unfortunately, I have not been able to return to this BZ and continue investigation. The changes made to RHEL CoreOS, referenced in comment #16, have allowed us to move forward in this specific case. Feel free to close this as you see fit. If it becomes a problem for us again, we will reopen this BZ.
(In reply to Micah Abbott from comment #18) > Feel free to close this as you see fit. If it becomes a problem for us > again, we will reopen this BZ. Okay, thank you.