qemu-net autopkgtest fails: Failed to send exit request: Resource temporarily unavailable

[dann frazier]

This log shows initramfs-tools' qemu-net test failing on arm64. Here's the relevant portion:

https://autopkgtest.ubuntu.com/results/autopkgtest-mantic/mantic/arm64/i/initramfs-tools/20240119_214255_431f3@/log.gz

[...]
5482s no valid interfaces found
5482s exiting due to oneshot
5482s no interfaces have a carrier
5482s exiting due to oneshot
5482s dhcpcd exited
5482s dhcpcd_fork_cb: truncated read 0 (expected 4)
5492s [ 839.627776] virtio_net virtio1 lan0: renamed from eth0 (while UP)
5492s [ 839.806177] virtio_net virtio2 lan1: renamed from eth1 (while UP)
5544s no such user dhcpcd
5544s dhcpcd-10.0.2 starting
5544s dev: loaded udev
5557s DUID 00:03:00:01:52:54:00:65:43:21
5557s lan0: IAID 00:65:43:21
5557s lan1: IAID 00:12:34:56
5557s lan1: soliciting a DHCP lease
5558s lan1: offered 10.0.2.15 from 10.0.2.2
5558s lan1: probing address 10.0.2.15/24
5558s lan0: soliciting a DHCP lease
5558s lan0: offered 10.0.3.15 from 10.0.3.2
5558s lan0: probing address 10.0.3.15/24
5567s lan1: leased 10.0.2.15 for 86400 seconds
5567s lan1: adding route to 10.0.2.0/24
5567s lan1: adding default route via 10.0.2.2
5569s lan1: Setting hostname: goulash
5571s exiting due to oneshot
5579s dhcpcd exited
5579s dhcpcd_fork_cb: truncated read 0 (expected 4)
5590s Begin: Running /scripts/init-bottom ... Failed to send exit request: Resource temporarily unavailable
5658s done.
5661s /init: line 386: can't open /root/dev/console: no such file
5661s [ 1009.213600] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00000100

I compared this to this successful test log:
https://autopkgtest.ubuntu.com/results/autopkgtest-mantic/mantic/arm64/i/initramfs-tools/20240116_053535_e8fd8@/log.gz

They test output looks about the same, up until:

5590s Begin: Running /scripts/init-bottom ... Failed to send exit request: Resource temporarily unavailable.

I believe that error message is coming from /usr/share/initramfs-tools/scripts/init-bottom/udev. That file does this:

---------START---------
#!/bin/sh -e

... usual boilerplate ...

# Stop udevd, we'll miss a few events while we run init, but we catch up
udevadm control --exit

# move the /dev tmpfs to the rootfs; fall back to util-linux mount that does
# not understand -o move
mount -n -o move /dev "${rootmnt:?}/dev" || mount -n --move /dev "${rootmnt}/dev"
---------END---------

`udevadm control --exit` tries to send an exit request to udev over a control socket. "Resource temporarily unavailable" means that it received an -EAGAIN when it tried to do so. udev_ctrl_send() doesn't check for an -EAGAIN, so this is fatal. Since the script is `set -e`, it fails to continue and therefore /dev never gets moved over.

Observations:

  - The QEMU instance in the failed test ran much slower than the successful one. The successful one made it to userspace in about 6 seconds, where the failed one took 63.

  - Not all QEMU instance boots in this run took that long - the others took 30-45s. So it's not like the QEMU version or guest kernel are always slow.

  - The failed instance emits "Failed to wait for daemon to reply: Connection timed out" early on. I'm guessing that this is from the `udevadm` calls in init-top/udev - likely the `udevadm settle`, since it is the only one with a `|| true` to ignore errors. Perhaps this is an early sign that something is wrong with systemd-udevd. Here's that snippet:

-----------START-----------
[ 63.075129] Run /init as init process
Loading, please wait...
Starting systemd-udevd version 253.5-1ubuntu6.1
[ 233.675459] hrtimer: interrupt took 10193008 ns
Failed to wait for daemon to reply: Connection timed out
Begin: Loading essential drivers ... [ 576.182017] raid6: neonx8 gen() 210 MB/s
[ 576.261515] raid6: neonx4 gen() 244 MB/s

-----------END-----------

[Benjamin Drung (bdrung)]

This failure is gone.