[Bug 2051407] Re: qemu-net autopkgtest fails: Failed to send exit request: Resource temporarily unavailable

[Nick Rosbrook]

** Changed in: systemd (Ubuntu)
       Status: New => Invalid

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to initramfs-tools in Ubuntu.
https://bugs.launchpad.net/bugs/2051407

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

Status in initramfs-tools package in Ubuntu:
  Invalid
Status in systemd package in Ubuntu:
  Invalid

Bug description:
  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-----------

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/initramfs-tools/+bug/2051407/+subscriptions