ti 13. elok. 2024 klo 0.49 Simon McVittie (s...@debian.org) kirjoitti:
>
> Control: unmerge 1071456 1077620
> Control: retitle 1077620 autopkgtest-virt-qemu: timed out waiting for 'login
> prompt on serial console'
> Control: reopen 1077620
> Control: tags 1077620 + moreinfo
>
> On Mon, 12 Aug 2024 at 23:17:02 +0300, Martin-Éric Racine wrote:
> > I created a fresh image as follow:
> >
> > sudo autopkgtest-build-qemu unstable /var/tmp/autopkgtest-unstable.img
> >
> > I then tried to launch a test as follow:
> >
> > $ autopkgtest dhcpcd -- qemu --ram-size 2047
> > /var/tmp/autopkgtest-unstable.img
> ...
> > <VirtSubproc>: failure: timed out waiting for 'login prompt on serial
> > console'
>
> I think this must be a different failure mode than the 9pfs bug that
> caused #1071456, then. A similar setup is working well for me, on unstable,
> but I was getting similar timeouts intermittently in the past.
Agreed.
> Adding --debug and/or --show-boot after qemu on the command line might
> provide useful information?
DEBUG
$ autopkgtest dhcpcd -- qemu --debug --ram-size 2047
/var/tmp/autopkgtest-unstable.img
autopkgtest [08:09:22]: starting date and time: 2024-08-13 08:09:22+0300
autopkgtest [08:09:22]: version 5.39
autopkgtest [08:09:22]: host p8h61; command line: /usr/bin/autopkgtest
dhcpcd -- qemu --debug --ram-size 2047
/var/tmp/autopkgtest-unstable.img
autopkgtest-virt-qemu: DBG: Assuming nothing special needs to be done
to set up firmware to boot this machine (boot method: bios)
autopkgtest-virt-qemu: DBG: executing open
autopkgtest-virt-qemu: DBG: qemu architecture: i386
autopkgtest-virt-qemu: DBG: qemu command: qemu-system-i386
autopkgtest-virt-qemu: DBG: find_free_port: trying 10022
autopkgtest-virt-qemu: DBG: find_free_port: 10022 is free
autopkgtest-virt-qemu: DBG: execute-timeout: qemu-img info
--output=json /var/tmp/autopkgtest-unstable.img
autopkgtest-virt-qemu: DBG: Creating temporary overlay image in
/tmp/autopkgtest-qemu.6hxz4sjo/overlay.img
autopkgtest-virt-qemu: DBG: execute-timeout: qemu-img create -f qcow2
-F qcow2 -b /var/tmp/autopkgtest-unstable.img
/tmp/autopkgtest-qemu.6hxz4sjo/overlay.img
autopkgtest-virt-qemu: DBG: Forwarding local port 10022 to VM ssh port 22
autopkgtest-virt-qemu: DBG: full qemu command-line:
['qemu-system-i386', '-m', '2047', '-smp', '1', '-nographic',
'-device', 'virtio-net-pci,netdev=net0', '-netdev',
'user,id=net0,hostfwd=tcp:127.0.0.1:10022-:22', '-object',
'rng-random,filename=/dev/urandom,id=rng0', '-device',
'virtio-rng-pci,rng=rng0,id=rng-device0', '-monitor',
'unix:/tmp/autopkgtest-qemu.6hxz4sjo/monitor,server=on,wait=off',
'-virtfs',
'local,id=autopkgtest,path=/tmp/autopkgtest-qemu.6hxz4sjo/shared,security_model=none,mount_tag=autopkgtest',
'-device', 'virtio-serial', '-chardev',
'socket,path=/tmp/autopkgtest-qemu.6hxz4sjo/hvc0,server=on,wait=off,id=hvc0',
'-device', 'virtconsole,chardev=hvc0', '-chardev',
'socket,path=/tmp/autopkgtest-qemu.6hxz4sjo/hvc1,server=on,wait=off,id=hvc1',
'-device', 'virtconsole,chardev=hvc1', '-serial',
'unix:/tmp/autopkgtest-qemu.6hxz4sjo/ttyS0,server=on,wait=off',
'-serial', 'unix:/tmp/autopkgtest-qemu.6hxz4sjo/ttyS1,server=on,wait=off',
'-drive',
'index=0,file=/tmp/autopkgtest-qemu.6hxz4sjo/overlay.img,format=qcow2,cache=unsafe,if=virtio,discard=unmap']
autopkgtest-virt-qemu: DBG: expect: b' login: '
qemu-system-i386: terminating on signal 15 from pid 51363 (/usr/bin/python3)
autopkgtest-virt-qemu: DBG: cleanup...
<VirtSubproc>: failure: timed out waiting for 'login prompt on serial console'
autopkgtest [08:10:22]: ERROR: testbed failure: unexpected eof from the testbed
SHOW-BOOT
[...kernel boots...]
[ 23.298592] systemd[1]: systemd 256.4-3 running in system mode
(+PAM +AUDIT +SELINUX +APPARMOR +IMA +SMACK +SECCOMP +GCRYPT -GNUTLS
+OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN +IPTC +KMOD
+LIBCRYPTSETUP +LIBCRYPTSETUP_PLUGINS +LIBFDISK +PCRE2 +PWQUALITY
+P11KIT +QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK
-XKBCOMMON +UTMP +SYSVINIT +LIBARCHIVE)
[ 23.301172] systemd[1]: Detected virtualization qemu.
[ 23.302473] systemd[1]: Detected architecture x86.
Welcome to Debian GNU/Linux trixie/sid!
[ 23.324735] systemd[1]: Hostname set to <host>.
[ 27.687764] systemd[1]: Queued start job for default target graphical.target.
[ 28.042777] systemd[1]: Created slice system-autopkgtest.slice -
Slice /system/autopkgtest.
[ OK ] Created slice system-autopkgtest.slice - Slice /system/autopkgtest.
[ 28.076237] systemd[1]: Created slice system-getty.slice - Slice
/system/getty.
[ OK ] Created slice system-getty.slice - Slice /system/getty.
[ 28.091706] systemd[1]: Created slice system-modprobe.slice - Slice
/system/modprobe.
[ OK ] Created slice system-modprobe.slice - Slice /system/modprobe.
[ 28.107356] systemd[1]: Created slice system-serial\x2dgetty.slice
- Slice /system/serial-getty.
[ OK ] Created slice system-serial\x2dget…slice - Slice /system/serial-getty.
[ 28.120775] systemd[1]: Created slice user.slice - User and Session Slice.
[ OK ] Created slice user.slice - User and Session Slice.
[ 28.129581] systemd[1]: Started systemd-ask-password-console.path -
Dispatch Password Requests to Console Directory Watch.
[ OK ] Started systemd-ask-password-conso…equests to Console Directory Watch.
[ 28.135185] systemd[1]: Started systemd-ask-password-wall.path -
Forward Password Requests to Wall Directory Watch.
[ OK ] Started systemd-ask-password-wall.…d Requests to Wall Directory Watch.
[ 28.159271] systemd[1]: Set up automount
proc-sys-fs-binfmt_misc.automount - Arbitrary Executable File Formats
File System Automount Point.
[ OK ] Set up automount proc-sys-fs-binfm…ormats File System Automount Point.
[ 28.164593] systemd[1]: Expecting device dev-hvc0.device - /dev/hvc0...
Expecting device dev-hvc0.device - /dev/hvc0...
[ 28.167542] systemd[1]: Expecting device dev-ttyS0.device - /dev/ttyS0...
Expecting device dev-ttyS0.device - /dev/ttyS0...
[ 28.170836] systemd[1]: Reached target paths.target - Path Units.
[ OK ] Reached target paths.target - Path Units.
[ 28.173624] systemd[1]: Reached target remote-fs.target - Remote
File Systems.
[ OK ] Reached target remote-fs.target - Remote File Systems.
[ 28.176393] systemd[1]: Reached target slices.target - Slice Units.
[ OK ] Reached target slices.target - Slice Units.
[ 28.178986] systemd[1]: Reached target swap.target - Swaps.
[ OK ] Reached target swap.target - Swaps.
[ 28.234599] systemd[1]: Listening on systemd-creds.socket -
Credential Encryption/Decryption.
[ OK ] Listening on systemd-creds.socket - Credential Encryption/Decryption.
[ 28.242812] systemd[1]: Listening on systemd-initctl.socket -
initctl Compatibility Named Pipe.
[ OK ] Listening on systemd-initctl.socke…- initctl Compatibility Named Pipe.
[ 28.250347] systemd[1]: Listening on
systemd-journald-dev-log.socket - Journal Socket (/dev/log).
[ OK ] Listening on systemd-journald-dev-…socket - Journal Socket (/dev/log).
[ 28.257349] systemd[1]: Listening on systemd-journald.socket -
Journal Sockets.
[ OK ] Listening on systemd-journald.socket - Journal Sockets.
[ 28.261731] systemd[1]: systemd-pcrextend.socket - TPM PCR
Measurements was skipped because of an unmet condition check
(ConditionSecurity=measured-uki).
[ 28.263815] systemd[1]: systemd-pcrlock.socket - Make TPM PCR
Policy was skipped because of an unmet condition check
(ConditionSecurity=measured-uki).
[ 28.269696] systemd[1]: Listening on systemd-udevd-control.socket -
udev Control Socket.
[ OK ] Listening on systemd-udevd-control.socket - udev Control Socket.
[ 28.276616] systemd[1]: Listening on systemd-udevd-kernel.socket -
udev Kernel Socket.
[ OK ] Listening on systemd-udevd-kernel.socket - udev Kernel Socket.
[ 28.517295] systemd[1]: Mounting dev-hugepages.mount - Huge Pages
File System...
Mounting dev-hugepages.mount - Huge Pages File System...
[ 28.923612] systemd[1]: Mounting dev-mqueue.mount - POSIX Message
Queue File System...
Mounting dev-mqueue.mount - POSIX Message Queue File System...
[ 29.028752] systemd[1]: Mounting run-lock.mount - Legacy Locks
Directory /run/lock...
Mounting run-lock.mount - Legacy Locks Directory /run/lock...
[ 29.236684] systemd[1]: Mounting sys-kernel-debug.mount - Kernel
Debug File System...
Mounting sys-kernel-debug.mount - Kernel Debug File System...
[ 29.404613] systemd[1]: Mounting sys-kernel-tracing.mount - Kernel
Trace File System...
Mounting sys-kernel-tracing.mount - Kernel Trace File System...
[ 29.584836] systemd[1]: Mounting tmp.mount - Temporary Directory /tmp...
Mounting tmp.mount - Temporary Directory /tmp...
[ 30.076851] systemd[1]: Starting kmod-static-nodes.service - Create
List of Static Device Nodes...
Starting kmod-static-nodes.service…eate List of Static Device Nodes...
[ 30.197191] systemd[1]: Starting modprobe@configfs.service - Load
Kernel Module configfs...
Starting modprobe@configfs.service - Load Kernel Module configfs...
[ 30.362710] systemd[1]: Starting modprobe@drm.service - Load Kernel
Module drm...
Starting modprobe@drm.service - Load Kernel Module drm...
[ 30.526517] systemd[1]: Starting modprobe@efi_pstore.service - Load
Kernel Module efi_pstore...
Starting modprobe@efi_pstore.servi… - Load Kernel Module efi_pstore...
[ 30.662330] systemd[1]: Starting modprobe@fuse.service - Load
Kernel Module fuse...
Starting modprobe@fuse.service - Load Kernel Module fuse...
[ 30.680459] systemd[1]: systemd-fsck-root.service - File System
Check on Root Device was skipped because of an unmet condition check
(ConditionPathExists=!/run/initramfs/fsck-root).
[ 30.708765] systemd[1]: systemd-hibernate-clear.service - Clear
Stale Hibernate Storage Info was skipped because of an unmet condition
check
(ConditionPathExists=/sys/firmware/efi/efivars/HibernateLocation-8cf2644b-4b0b-428f-9387-6d876050dc67).
[ 31.319311] systemd[1]: Starting systemd-journald.service - Journal
Service...
Starting systemd-journald.service - Journal Service...
[ 31.624809] systemd[1]: Starting systemd-modules-load.service -
Load Kernel Modules...
Starting systemd-modules-load.service - Load Kernel Modules...
[ 31.674910] systemd[1]: systemd-pcrmachine.service - TPM PCR
Machine ID Measurement was skipped because of an unmet condition check
(ConditionSecurity=measured-uki).
[ 32.061523] systemd[1]: Starting systemd-remount-fs.service -
Remount Root and Kernel File Systems...
Starting systemd-remount-fs.servic…unt Root and Kernel File Systems...
[ 32.107257] systemd[1]: systemd-tpm2-setup-early.service - Early
TPM SRK Setup was skipped because of an unmet condition check
(ConditionSecurity=measured-uki).
[ 32.184304] ACPI: bus type drm_connector registered
[ 32.337811] systemd[1]: Starting
systemd-udev-load-credentials.service - Load udev Rules from
Credentials...
Starting systemd-udev-load-credent…Load udev Rules from Credentials...
[ 32.473010] systemd[1]: Starting systemd-udev-trigger.service -
Coldplug All udev Devices...
Starting systemd-udev-trigger.service - Coldplug All udev Devices...
[ 34.091330] EXT4-fs (vda1): re-mounted
e02d0b35-b025-4498-90d2-885a755bb73f r/w. Quota mode: none.
[ 34.272090] systemd[1]: Mounted dev-hugepages.mount - Huge Pages File System.
[ OK ] Mounted dev-hugepages.mount - Huge Pages File System.
[ 34.352830] systemd[1]: Mounted dev-mqueue.mount - POSIX Message
Queue File System.
[ OK ] Mounted dev-mqueue.mount - POSIX Message Queue File System.
[ 34.375954] systemd[1]: Mounted run-lock.mount - Legacy Locks
Directory /run/lock.
[ OK ] Mounted run-lock.mount - Legacy Locks Directory /run/lock.
[ 34.399120] systemd[1]: Mounted sys-kernel-debug.mount - Kernel
Debug File System.
[ OK ] Mounted sys-kernel-debug.mount - Kernel Debug File System.
[ 34.422639] systemd[1]: Mounted sys-kernel-tracing.mount - Kernel
Trace File System.
[ OK ] Mounted sys-kernel-tracing.mount - Kernel Trace File System.
[ 34.438417] systemd[1]: Mounted tmp.mount - Temporary Directory /tmp.
[ OK ] Mounted tmp.mount - Temporary Directory /tmp.
[ 34.506772] systemd[1]: Finished kmod-static-nodes.service - Create
List of Static Device Nodes.
[ OK ] Finished kmod-static-nodes.service…Create List of Static Device Nodes.
[ 34.596942] systemd[1]: modprobe@configfs.service: Deactivated successfully.
[ 34.624716] systemd[1]: Finished modprobe@configfs.service - Load
Kernel Module configfs.
[ OK ] Finished modprobe@configfs.service - Load Kernel Module configfs.
[ 34.688717] systemd[1]: modprobe@drm.service: Deactivated successfully.
[ 34.696397] systemd-journald[211]: Collecting audit messages is disabled.
[ 34.716329] systemd[1]: Finished modprobe@drm.service - Load Kernel
Module drm.
[ OK ] Finished modprobe@drm.service - Load Kernel Module drm.
[ 34.766073] systemd[1]: modprobe@efi_pstore.service: Deactivated
successfully.
[ 34.787534] systemd[1]: Finished modprobe@efi_pstore.service - Load
Kernel Module efi_pstore.
[ OK ] Finished modprobe@efi_pstore.service - Load Kernel Module efi_pstore.
[ 34.831297] systemd[1]: modprobe@fuse.service: Deactivated successfully.
[ 34.855336] systemd[1]: Finished modprobe@fuse.service - Load
Kernel Module fuse.
[ OK ] Finished modprobe@fuse.service - Load Kernel Module fuse.
[ 34.892746] systemd[1]: Finished systemd-modules-load.service -
Load Kernel Modules.
[ OK ] Finished systemd-modules-load.service - Load Kernel Modules.
[ 34.934936] systemd[1]: Finished systemd-remount-fs.service -
Remount Root and Kernel File Systems.
[ OK ] Finished systemd-remount-fs.servic…mount Root and Kernel File Systems.
[ 35.283016] systemd[1]: Finished
systemd-udev-load-credentials.service - Load udev Rules from
Credentials.
[ OK ] Finished systemd-udev-load-credent…- Load udev Rules from Credentials.
[ 35.960190] systemd[1]: Mounting sys-fs-fuse-connections.mount -
FUSE Control File System...
Mounting sys-fs-fuse-connections.mount - FUSE Control File System...
[ 36.155479] systemd[1]: Mounting sys-kernel-config.mount - Kernel
Configuration File System...
Mounting sys-kernel-config.mount - Kernel Configuration File System...
[ 36.315805] systemd[1]: systemd-hwdb-update.service - Rebuild
Hardware Database was skipped because no trigger condition checks were
met.
[ 36.364014] systemd[1]: systemd-pstore.service - Platform
Persistent Storage Archival was skipped because of an unmet condition
check (ConditionDirectoryNotEmpty=/sys/fs/pstore).
[ 36.700254] systemd[1]: Starting systemd-random-seed.service -
Load/Save OS Random Seed...
Starting systemd-random-seed.service - Load/Save OS Random Seed...
[ 37.021092] systemd[1]: Starting systemd-sysctl.service - Apply
Kernel Variables...
Starting systemd-sysctl.service - Apply Kernel Variables...
[ 37.436952] systemd[1]: Starting
systemd-tmpfiles-setup-dev-early.service - Create Static Device Nodes
in /dev gracefully...
Starting systemd-tmpfiles-setup-de… Device Nodes in /dev gracefully...
[ 37.535000] systemd[1]: systemd-tpm2-setup.service - TPM SRK Setup
was skipped because of an unmet condition check
(ConditionSecurity=measured-uki).
[ 38.258771] systemd[1]: Started systemd-journald.service - Journal Service.
[ OK ] Started systemd-journald.service - Journal Service.
[ OK ] Mounted sys-fs-fuse-connections.mount - FUSE Control File System.
[ OK ] Mounted sys-kernel-config.mount - Kernel Configuration File System.
[ OK ] Finished systemd-random-seed.service - Load/Save OS Random Seed.
[ OK ] Finished systemd-sysctl.service - Apply Kernel Variables.
Starting systemd-journal-flush.ser…sh Journal to Persistent Storage...
[ OK ] Finished systemd-tmpfiles-setup-de…ic Device Nodes in /dev gracefully.
Starting systemd-sysusers.service - Create System Users...
[ 43.198991] systemd-journald[211]: Received client request to flush
runtime journal.
[ OK ] Finished systemd-sysusers.service - Create System Users.
Starting systemd-tmpfiles-setup-de…eate Static Device Nodes in /dev...
[ OK ] Finished systemd-journal-flush.ser…lush Journal to Persistent Storage.
[ OK ] Finished systemd-tmpfiles-setup-de…Create Static Device Nodes in /dev.
[ OK ] Reached target local-fs-pre.target…Preparation for Local File Systems.
[ OK ] Reached target local-fs.target - Local File Systems.
[ OK ] Listening on systemd-sysext.socket… System Extension Image Management.
Starting apparmor.service - Load AppArmor profiles...
qemu-system-i386: terminating on signal 15 from pid 51545
(/usr/bin/python3)
Starting ldconfig.service - Rebuild Dynamic Linker Cache...
Starting systemd-binfmt.service - Set Up Additional Binary Formats...
Starting systemd-tmpfiles-setup.se…ate System Files and Directories...
Starting systemd-udevd.service - R…ager for Device Events and Files...
[ OK ] Finished systemd-udev-trigger.service - Coldplug All udev Devices.
[ OK ] Finished ldconfig.service - Rebuild Dynamic Linker Cache.
<VirtSubproc>: failure: timed out waiting for 'login prompt on serial console'
autopkgtest [08:13:00]: ERROR: testbed failure: unexpected eof from the testbed
> I wonder whether it's significant that you seem to be using an i386
> user-space on an amd64 kernel. (Intentionally?)
Possible. t64 issue creeping in?
Martin-Éric
