Package: os-autoinst Version: 4.6.1731418769.97d9a7fd-1 X-Debbugs-CC: t...@grml.org
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 ...