For Grml, we run isotovideo back to back for a number of tests.
Every so often one of the invocations fails:

| !!! main: failed to start VM at /usr/lib/os-autoinst/backend/driver.pm line 104

These runs are done in a GitLab CI runner inside docker; it's always
the same runner. Retrying the job often succeeds.

Let me know if you need additional info or anything. I don't know
how to go about debugging this problem.

Logs are below.

Thanks,
Chris


Versions:

libperl5.40:amd64 (5.40.0-8)
os-autoinst (4.6.1731418769.97d9a7fd-1)
ovmf (2024.11-4)
ovmf-ia32 (2024.11-4)
perl (5.40.0-8)
qemu-block-extra (1:9.2.0+ds-5)
qemu-system-common (1:9.2.0+ds-5)
qemu-system-data (1:9.2.0+ds-5)
qemu-system-x86 (1:9.2.0+ds-5)
qemu-utils (1:9.2.0+ds-5)

For a few days this URL should also show the complete job log:
https://gitlab.grml.org/grml/openqa-test/-/jobs/2153/raw

Here's the isotovideo log output from a failing invocation:

D: Running "isotovideo" "--exit-status-from-test-results"
| [2025-01-23T11:17:03.722691Z] [debug] [pid:10882] Current version is unknown [interface v42]
| [2025-01-23T11:17:03.734094Z] [debug] [pid:10882] git hash in '/builds/grml/openqa-test': 75f9fde3d0ff1a78a58aa9a235ca5a568ae29f88
| [2025-01-23T11:17:03.745780Z] [debug] [pid:10882] git url in '/builds/grml/openqa-test': "https://gitlab-ci-token:[MASKED]@gitlab.grml.org/grml/openqa-test.git"
| [2025-01-23T11:17:03.754891Z] [debug] [pid:10882] scheduling boot tests/boot.pm
| [2025-01-23T11:17:03.764775Z] [info] [pid:10889] cmdsrv: daemon reachable under http://*:15223/EwnBiuXjTo/
| [2025-01-23T11:17:03.766607Z] [debug] [pid:10882] git hash in '/builds/grml/openqa-test/needles': 75f9fde3d0ff1a78a58aa9a235ca5a568ae29f88
| [2025-01-23T11:17:03.766769Z] [debug] [pid:10882] git url in '/builds/grml/openqa-test/needles': "UNKNOWN (no .git found)"
| [2025-01-23T11:17:03.766916Z] [debug] [pid:10882] init needles from /builds/grml/openqa-test/needles
| [2025-01-23T11:17:03.768323Z] [info] [pid:10889] Listening at "http://0.0.0.0:15223"
| Web application available at http://0.0.0.0:15223
| [2025-01-23T11:17:03.770610Z] [debug] [pid:10882] loaded 15 needles
| [2025-01-23T11:17:03.961021Z] [debug] [pid:10882] 10882: channel_out 15, channel_in 14
| [2025-01-23T11:17:04.101868Z] [debug] [pid:10899] 10899: cmdpipe 13, rsppipe 16
| [2025-01-23T11:17:04.102117Z] [debug] [pid:10899] started mgmt loop with pid 10899
| [2025-01-23T11:17:04.211067Z] [debug] [pid:10899] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libsvtav1 -crf 50 -preset 7 'video.webm'
| [2025-01-23T11:17:04.257960Z] [debug] [pid:10899] qemu version detected: 9.2.0
| [2025-01-23T11:17:04.260031Z] [debug] [pid:10899] running `/usr/bin/chattr +C /tmp/tmp5eun5hxb/raid`
| [2025-01-23T11:17:04.271448Z] [debug] [pid:10899] Command `/usr/bin/chattr +C /tmp/tmp5eun5hxb/raid` terminated with 1
|   /usr/bin/chattr: Operation not supported while setting flags on /tmp/tmp5eun5hxb/raid
| [2025-01-23T11:17:04.271678Z] [debug] [pid:10899] Configuring storage controllers and block devices
| [2025-01-23T11:17:04.272746Z] [debug] [pid:10899] running `/usr/bin/qemu-img info --output=json /tmp/tmpclqhok01/test.iso`
| [2025-01-23T11:17:04.288922Z] [debug] [pid:10899] running `/usr/bin/qemu-img info --output=json /usr/share/OVMF/OVMF_CODE_4M.fd`
| [2025-01-23T11:17:04.305742Z] [debug] [pid:10899] running `/usr/bin/qemu-img info --output=json /usr/share/OVMF/OVMF_VARS_4M.fd`
| [2025-01-23T11:17:04.323271Z] [debug] [pid:10899] Initializing block device images
| [2025-01-23T11:17:04.323733Z] [debug] [pid:10899] running `/usr/bin/qemu-img create -f qcow2 /tmp/tmp5eun5hxb/raid/hd0 10G`
| [2025-01-23T11:17:04.353485Z] [debug] [pid:10899] Formatting '/tmp/tmp5eun5hxb/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:17:04.353627Z] [debug] [pid:10899] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /tmp/tmpclqhok01/test.iso /tmp/tmp5eun5hxb/raid/cd0-overlay0 976486400`
| [2025-01-23T11:17:04.387591Z] [debug] [pid:10899] Formatting '/tmp/tmp5eun5hxb/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=976486400 backing_file=/tmp/tmpclqhok01/test.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:17:04.387780Z] [debug] [pid:10899] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /usr/share/OVMF/OVMF_CODE_4M.fd /tmp/tmp5eun5hxb/raid/pflash-code-overlay0 3653632`
| [2025-01-23T11:17:04.422869Z] [debug] [pid:10899] Formatting '/tmp/tmp5eun5hxb/raid/pflash-code-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=3653632 backing_file=/usr/share/OVMF/OVMF_CODE_4M.fd backing_fmt=raw lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:17:04.423083Z] [debug] [pid:10899] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /usr/share/OVMF/OVMF_VARS_4M.fd /tmp/tmp5eun5hxb/raid/pflash-vars-overlay0 540672`
| [2025-01-23T11:17:04.460774Z] [debug] [pid:10899] Formatting '/tmp/tmp5eun5hxb/raid/pflash-vars-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=540672 backing_file=/usr/share/OVMF/OVMF_VARS_4M.fd backing_fmt=raw lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:17:04.460934Z] [debug] [pid:10899] init_blockdev_images: Finished creating block devices
| [2025-01-23T11:17:04.462414Z] [debug] [pid:10899] starting: /usr/bin/qemu-system-x86_64 -device VGA,edid=on,xres=1024,yres=768 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.fdtypeA=none -m 1640 -machine q35 -cpu Haswell-v3 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -device qemu-xhci -device usb-tablet -smp 2 -no-shutdown -vnc :90,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/tmp/tmp5eun5hxb/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/tmp/tmp5eun5hxb/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on,discard=unmap -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0 -drive id=pflash-code-overlay0,if=pflash,file=/tmp/tmp5eun5hxb/raid/pflash-code-overlay0,unit=0,readonly=on -drive id=pflash-vars-overlay0,if=pflash,file=/tmp/tmp5eun5hxb/raid/pflash-vars-overlay0,unit=1
| [2025-01-23T11:17:04.468583Z] [debug] [pid:10899] Waiting for 0 attempts
| dmesg: read kernel buffer failed: Operation not permitted
| [2025-01-23T11:17:04.652624Z] [debug] [pid:10899] Waiting for 1 attempts
| [2025-01-23T11:17:04.653001Z] [info] [pid:10899] ::: backend::baseclass::die_handler: Backend process died, backend errors are reported below in the following lines:
|   QEMU terminated before QMP connection could be established. Check for errors below
| [2025-01-23T11:17:04.653422Z] [info] [pid:10899] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
| [2025-01-23T11:17:04.654730Z] [debug] [pid:10899] Passing remaining frames to the video encoder
| [image2pipe @ 0x5567f29ec740] Could not find codec parameters for stream 0 (Video: ppm, none): unspecified size
| Consider increasing the value for the 'analyzeduration' (0) and 'probesize' (5000000) options
| Input #0, image2pipe, from 'fd:':
|   Duration: N/A, bitrate: N/A
|   Stream #0:0: Video: ppm, none, 24 fps, 24 tbr, 24 tbn
| Output #0, webm, to 'video.webm':
| [out#0/webm @ 0x5567f2a022c0] Output file does not contain any stream
| Error opening output file video.webm.
| Error opening output files: Invalid argument
| [2025-01-23T11:17:04.671253Z] [debug] [pid:10899] Waiting for video encoder to finalize the video
| [2025-01-23T11:17:04.671402Z] [debug] [pid:10899] The external video encoder (pid 10907) terminated
| [2025-01-23T11:17:04.671535Z] [debug] [pid:10899] The built-in video encoder (pid 10909) terminated
| [2025-01-23T11:17:04.672873Z] [debug] [pid:10899] QEMU: QEMU emulator version 9.2.0 (Debian 1:9.2.0+ds-5)
| [2025-01-23T11:17:04.672956Z] [debug] [pid:10899] QEMU: Copyright (c) 2003-2024 Fabrice Bellard and the QEMU Project developers
| [2025-01-23T11:17:04.673026Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.pcid [bit 17]
| [2025-01-23T11:17:04.673080Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.tsc-deadline [bit 24]
| [2025-01-23T11:17:04.673124Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.hle [bit 4]
| [2025-01-23T11:17:04.673264Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.invpcid [bit 10]
| [2025-01-23T11:17:04.673318Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.rtm [bit 11]
| [2025-01-23T11:17:04.673372Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EDX.spec-ctrl [bit 26]
| [2025-01-23T11:17:04.673414Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.pcid [bit 17]
| [2025-01-23T11:17:04.673457Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.tsc-deadline [bit 24]
| [2025-01-23T11:17:04.673506Z] [warn] [pid:10899] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.hle [bi
| [2025-01-23T11:17:04.674763Z] [debug] [pid:10899] sending magic and exit
| [2025-01-23T11:17:04.675444Z] [debug] [pid:10882] received magic close
| [2025-01-23T11:17:04.682475Z] [debug] [pid:10882] backend process exited: 0
| [2025-01-23T11:17:04.783289Z] [warn] [pid:10882] !!! main: failed to start VM at /usr/lib/os-autoinst/backend/driver.pm line 104.
|
| [2025-01-23T11:17:04.783847Z] [debug] [pid:10882] stopping command server 10889 because test execution ended through exception
| [2025-01-23T11:17:04.984623Z] [debug] [pid:10882] done with command server
| [2025-01-23T11:17:04.984778Z] [debug] [pid:10882] stopping autotest process 10892
| [2025-01-23T11:17:05.185533Z] [debug] [pid:10882] done with autotest process
| 10882: EXIT 1


And from a successful invocation just before, in the exact same
environment (as its just in the same ci job):

D: Running "isotovideo" "--exit-status-from-test-results"
| [2025-01-23T11:16:50.910190Z] [debug] [pid:10687] Current version is unknown [interface v42]
| [2025-01-23T11:16:50.943668Z] [debug] [pid:10687] git hash in '/builds/grml/openqa-test': 75f9fde3d0ff1a78a58aa9a235ca5a568ae29f88
| [2025-01-23T11:16:50.957401Z] [debug] [pid:10687] git url in '/builds/grml/openqa-test': "https://gitlab-ci-token:[MASKED]@gitlab.grml.org/grml/openqa-test.git"
| [2025-01-23T11:16:50.997751Z] [debug] [pid:10687] scheduling boot tests/boot.pm
| [2025-01-23T11:16:51.009552Z] [info] [pid:10694] cmdsrv: daemon reachable under http://*:15223/sKLhWpPXSJ/
| [2025-01-23T11:16:51.012735Z] [debug] [pid:10687] git hash in '/builds/grml/openqa-test/needles': 75f9fde3d0ff1a78a58aa9a235ca5a568ae29f88
| [2025-01-23T11:16:51.012881Z] [info] [pid:10694] Listening at "http://0.0.0.0:15223"
| [2025-01-23T11:16:51.012967Z] [debug] [pid:10687] git url in '/builds/grml/openqa-test/needles': "UNKNOWN (no .git found)"
| Web application available at http://0.0.0.0:15223
| [2025-01-23T11:16:51.013259Z] [debug] [pid:10687] init needles from /builds/grml/openqa-test/needles
| [2025-01-23T11:16:51.104159Z] [debug] [pid:10687] loaded 15 needles
| [2025-01-23T11:16:51.308636Z] [debug] [pid:10687] 10687: channel_out 15, channel_in 14
| [2025-01-23T11:16:51.439296Z] [debug] [pid:10704] 10704: cmdpipe 13, rsppipe 16
| [2025-01-23T11:16:51.439482Z] [debug] [pid:10704] started mgmt loop with pid 10704
| [2025-01-23T11:16:51.567763Z] [debug] [pid:10704] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libsvtav1 -crf 50 -preset 7 'video.webm'
| [2025-01-23T11:16:51.621648Z] [debug] [pid:10704] qemu version detected: 9.2.0
| [2025-01-23T11:16:51.624528Z] [debug] [pid:10704] running `/usr/bin/chattr +C /tmp/tmpck3ove8k/raid`
| [2025-01-23T11:16:51.637127Z] [debug] [pid:10704] Command `/usr/bin/chattr +C /tmp/tmpck3ove8k/raid` terminated with 1
|   /usr/bin/chattr: Operation not supported while setting flags on /tmp/tmpck3ove8k/raid
| [2025-01-23T11:16:51.637254Z] [debug] [pid:10704] Configuring storage controllers and block devices
| [2025-01-23T11:16:51.638046Z] [debug] [pid:10704] running `/usr/bin/qemu-img info --output=json /tmp/tmpclqhok01/test.iso`
| [2025-01-23T11:16:51.656860Z] [debug] [pid:10704] running `/usr/bin/qemu-img info --output=json /usr/share/OVMF/OVMF_CODE_4M.fd`
| [2025-01-23T11:16:51.676124Z] [debug] [pid:10704] running `/usr/bin/qemu-img info --output=json /usr/share/OVMF/OVMF_VARS_4M.fd`
| [2025-01-23T11:16:51.694541Z] [debug] [pid:10704] Initializing block device images
| [2025-01-23T11:16:51.694943Z] [debug] [pid:10704] running `/usr/bin/qemu-img create -f qcow2 /tmp/tmpck3ove8k/raid/hd0 10G`
| [2025-01-23T11:16:51.723610Z] [debug] [pid:10704] Formatting '/tmp/tmpck3ove8k/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:16:51.723907Z] [debug] [pid:10704] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /tmp/tmpclqhok01/test.iso /tmp/tmpck3ove8k/raid/cd0-overlay0 976486400`
| [2025-01-23T11:16:51.749212Z] [debug] [pid:10704] Formatting '/tmp/tmpck3ove8k/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=976486400 backing_file=/tmp/tmpclqhok01/test.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:16:51.749382Z] [debug] [pid:10704] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /usr/share/OVMF/OVMF_CODE_4M.fd /tmp/tmpck3ove8k/raid/pflash-code-overlay0 3653632`
| [2025-01-23T11:16:51.774486Z] [debug] [pid:10704] Formatting '/tmp/tmpck3ove8k/raid/pflash-code-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=3653632 backing_file=/usr/share/OVMF/OVMF_CODE_4M.fd backing_fmt=raw lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:16:51.774643Z] [debug] [pid:10704] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /usr/share/OVMF/OVMF_VARS_4M.fd /tmp/tmpck3ove8k/raid/pflash-vars-overlay0 540672`
| [2025-01-23T11:16:51.806372Z] [debug] [pid:10704] Formatting '/tmp/tmpck3ove8k/raid/pflash-vars-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=540672 backing_file=/usr/share/OVMF/OVMF_VARS_4M.fd backing_fmt=raw lazy_refcounts=off refcount_bits=16
| [2025-01-23T11:16:51.806525Z] [debug] [pid:10704] init_blockdev_images: Finished creating block devices
| [2025-01-23T11:16:51.808076Z] [debug] [pid:10704] starting: /usr/bin/qemu-system-x86_64 -device VGA,edid=on,xres=1024,yres=768 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.fdtypeA=none -m 1640 -machine q35 -cpu Haswell-v3 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -device qemu-xhci -device usb-tablet -smp 2 -no-shutdown -vnc :90,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/tmp/tmpck3ove8k/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/tmp/tmpck3ove8k/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on,discard=unmap -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0 -drive id=pflash-code-overlay0,if=pflash,file=/tmp/tmpck3ove8k/raid/pflash-code-overlay0,unit=0,readonly=on -drive id=pflash-vars-overlay0,if=pflash,file=/tmp/tmpck3ove8k/raid/pflash-vars-overlay0,unit=1
| [2025-01-23T11:16:51.814647Z] [debug] [pid:10704] Waiting for 0 attempts
| [2025-01-23T11:16:52.816029Z] [debug] [pid:10704] Waiting for 1 attempts
| [2025-01-23T11:16:53.816672Z] [debug] [pid:10704] Finished after 2 attempts
| [2025-01-23T11:16:53.843913Z] [debug] [pid:10704] Establishing VNC connection to localhost:5990
| [2025-01-23T11:16:53.900208Z] [debug] [pid:10704] pointer type 0 0 640 480 -257
| [2025-01-23T11:16:53.900379Z] [debug] [pid:10704] led state 0 1 1 -261
| [2025-01-23T11:16:53.916822Z] [debug] [pid:10704] Start CPU
| [2025-01-23T11:16:53.917248Z] [debug] [pid:10704] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"51788","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":845112,"seconds":1737631013}}
| [2025-01-23T11:16:53.917374Z] [debug] [pid:10704] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"51788","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5990","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":848739,"seconds":1737631013}}
| [2025-01-23T11:16:53.917561Z] [debug] [pid:10704] EVENT {"event":"RESUME","timestamp":{"microseconds":917438,"seconds":1737631013}}
| GOT GO
|
| [2025-01-23T11:16:53.929052Z] [debug] [pid:10704] QEMU: QEMU emulator version 9.2.0 (Debian 1:9.2.0+ds-5)
| [2025-01-23T11:16:53.929151Z] [debug] [pid:10704] QEMU: Copyright (c) 2003-2024 Fabrice Bellard and the QEMU Project developers
| [2025-01-23T11:16:53.929257Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.pcid [bit 17]
| [2025-01-23T11:16:53.929318Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.tsc-deadline [bit 24]
| [2025-01-23T11:16:53.929364Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.hle [bit 4]
| [2025-01-23T11:16:53.929409Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.invpcid [bit 10]
| [2025-01-23T11:16:53.929456Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.rtm [bit 11]
| [2025-01-23T11:16:53.929499Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EDX.spec-ctrl [bit 26]
| [2025-01-23T11:16:53.929541Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.pcid [bit 17]
| [2025-01-23T11:16:53.929585Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.tsc-deadline [bit 24]
| [2025-01-23T11:16:53.929626Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.hle [bi
| [2025-01-23T11:16:53.937694Z] [debug] [pid:10704] QEMU: t 4]
| [2025-01-23T11:16:53.937807Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.invpcid [bit 10]
| [2025-01-23T11:16:53.937945Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EBX.rtm [bit 11]
| [2025-01-23T11:16:53.938Z] [warn] [pid:10704] !!! : qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.07H:EDX.spec-ctrl [bit 26]
| [2025-01-23T11:16:53.940893Z] [debug] [pid:10697] Snapshots are supported
| [2025-01-23T11:16:53.942531Z] [debug] [pid:10697] ||| starting boot tests/boot.pm
| [2025-01-23T11:16:53.945723Z] [debug] [pid:10697] tests/boot.pm:30 called testapi::record_info
| [2025-01-23T11:16:53.946500Z] [debug] [pid:10697] <<< testapi::record_info(title="progress", output="waiting for uefi firmware", result="ok")
| etc ...

Hi Chris,

Chris Hofstaedtler <zeha@debian.org> writes:

I've recently updated os-autoinst, and am likely to update it again
in the near future (assuming that there are not too many more new
dependencies, which is what delayed the last upgrade).

That being the case, it would be nice to know if you're still seeing
this problem with the new version, but please don't waste lots of time
on retesting things, as the current version is liable to be replaced
shortly.  Once I've caught up with upstream, I should have more time to
check what's going on here (and they're likely to be more interested if
the problem exists in a more current version).

Cheers, Phil.

Hello Phil,

* Philip Hands <phil@hands.com> [250219 17:32]:
[..]
[..]

I looked at todays build logs, which used
os-autoinst_4.6.1731418769.97d9a7fd-3 and they still fail in the
same way. On both arm64 and amd64.

Hope this helps,

Chris

Hello Chris,

in the log with QEMU-issues, I saw this line:
`dmesg: read kernel buffer failed: Operation not permitted`

That is caused by the script 'check_qemu_oom', which calls 'dmesg'.
On a regular system, 'dmesg' is not accessible for normal users,
which I reported upstream [1].

Could you try to allow the isotovideo user to access dmesg, and see
whether you get an out-of-memory message for QEMU?

With kind regards,
Roland Clobus

[1] https://github.com/os-autoinst/os-autoinst/issues/2672

Hello Chris,

in the log with QEMU-issues, I saw this line:
`dmesg: read kernel buffer failed: Operation not permitted`

That is caused by the script 'check_qemu_oom', which calls 'dmesg'.
On a regular system, 'dmesg' is not accessible for normal users,
which I reported upstream [1].

Could you try to allow the isotovideo user to access dmesg, and see
whether you get an out-of-memory message for QEMU?

With kind regards,
Roland Clobus

[1] https://github.com/os-autoinst/os-autoinst/issues/2672

Hello Roland,

* Roland Clobus <rclobus@rclobus.nl> [250418 09:03]:

I've changed the sysctl now, and hope this is enough to make it
work. We'll see in the next few days.

Thanks,
Chris

Hello Roland,

* Roland Clobus <rclobus@rclobus.nl> [250418 09:03]:

I've changed the sysctl now, and hope this is enough to make it
work. We'll see in the next few days.

Thanks,
Chris

Hello Roland,

* Roland Clobus <rclobus@rclobus.nl> [250418 09:03]:

I've changed the sysctl now, and hope this is enough to make it
work. We'll see in the next few days.

Thanks,
Chris

* Chris Hofstaedtler <zeha@debian.org> [250418 15:18]:
[..]

Unfortunately dmesg access appears to be restricted by docker too.

I still get this in the log:

| dmesg: read kernel buffer failed: Operation not permitted

Not sure how to work around that. Any ideas?

Chris

Hello Chris,
https://github.com/os-autoinst/os-autoinst/issues/2672

If you change the script 'check_qemu_oom' to use journalctl instead of
dmesg (and add the worker to the group, as mentioned in the bug report),
would you then be able to get a better output?

With kind regards,
Roland Clobus

Hello Chris,
https://github.com/os-autoinst/os-autoinst/issues/2672

If you change the script 'check_qemu_oom' to use journalctl instead of
dmesg (and add the worker to the group, as mentioned in the bug report),
would you then be able to get a better output?

With kind regards,
Roland Clobus