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 ...

Reply via email to