Fedora Account System
Red Hat Associate
Red Hat Customer
I apologize for the vague report, but it's the best I've got. Recently I've noticed a pattern of openQA jobs apparently failing because the VM just got stuck during early boot: https://openqa.fedoraproject.org/tests/4015548#step/_graphical_wait_login_2/3 https://openqa.fedoraproject.org/tests/4015669#step/_console_wait_login/9 https://openqa.fedoraproject.org/tests/4015881#step/_console_wait_login_2/4 https://openqa.fedoraproject.org/tests/4015721#step/_boot_to_anaconda/5 https://openqa.fedoraproject.org/tests/4015548#step/_graphical_wait_login_2/3 ...etc. There's no obvious rhyme or reason to this, it just...happens sometimes. I don't *think* it's load related. The Fedora version running inside the VM doesn't seem to matter, I've seen it affecting 42, 43 and 44 guests. The boot process seems to just get stuck either before reaching the bootloader (during UEFI firmware init) or shortly after - I don't think I've seen a case where it got beyond the "Booting <bootloader menu entry>" message and actually displayed any boot messages or reached the bootsplash. This is happening on all three x86_64 worker hosts but does not seem to be happening on the aarch64 worker hosts. I *think* it may be happening only to UEFI tests, at least I only see UEFI tests in the list of recent failures that I can find, though I might need to keep an eye out for a while longer to confirm this, as *most* tests are UEFI now, we only have a couple of BIOS tests, so this could just be a sample size thing. I *think* this is happening since I upgraded the worker hosts from Fedora 42 to Fedora 43. That caused qemu to go from 9.2.4-2.fc42 to 10.1.2-1.fc43. Of course there were updates to kernel, glibc etc. as well. Also relevant, I guess, if it's UEFI-only, is that edk2 went from 20250523-16.fc42 to 20250812-24.fc43 . I can't find any relevant messages in the worker hosts' logs when this happens. If there's some debug logging setting I can use to get more info, I can make that happen, please let me know.
sorry, for anyone not familiar with openQA - it's a test framework we use in Fedora. As far as this bug goes, all you really need to know is that the "worker hosts" spin up VMs and run tests in them. Potentially a lot of VMs (up to 60) at the same time, though the load varies. It does not use libvirt, it invokes qemu directly. A typical qemu command for an openQA job - the first failure in the list - looks like this: /usr/bin/qemu-system-x86_64 -device virtio-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 4096 -machine q35,smm=on -cpu host -netdev user,id=qanet0,net=172.16.2.0/24 -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 -enable-kvm -no-shutdown -vnc :120,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 -global driver=cfi.pflash01,property=secure,value=on -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay0-file,filename=/var/lib/openqa/pool/30/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0-overlay0,bootindex=0,serial=hd0 -blockdev driver=file,node-name=hd1-file,filename=/var/lib/openqa/pool/30/raid/hd1,cache.no-flush=on -blockdev driver=qcow2,node-name=hd1,file=hd1-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd1-device,drive=hd1,serial=hd1 -drive id=pflash-code-overlay0,if=pflash,file=/var/lib/openqa/pool/30/raid/pflash-code-overlay0,unit=0,readonly=on -drive id=pflash-vars-overlay0,if=pflash,file=/var/lib/openqa/pool/30/raid/pflash-vars-overlay0,unit=1
There are no known bugs that cause qemu to hang at the moment, at least not that I'm aware of. It'd be useful to get the full qemu stack at the point where it is stuck (eg. using gdb or gstack). With as many symbols as possible. Also make sure all qemu output is getting logged to a file, because that might contain interesting messages. Is qemu running directly on baremetal? Is KVM being used? Is it using nested KVM?
If it's using KVM, then also look for host kernel messages.
Directly on metal, with KVM, no nested KVM. qemu output is logged to the os-autoinst log file, I believe, but there's just nothing interesting there AFAICS. https://openqa.fedoraproject.org/tests/4015721/logfile?filename=autoinst-log.txt is that log from one of the cases where it failed on the very first boot (makes the log less noisy). You can see the early output from qemu like: 2025-11-28T15:21:14.270868Z] [debug] [pid:1783079] QEMU: QEMU emulator version 10.1.2 (qemu-10.1.2-1.fc43) [2025-11-28T15:21:14.270975Z] [debug] [pid:1783079] QEMU: Copyright (c) 2003-2025 Fabrice Bellard and the QEMU Project developers but then after that early stuff I just don't see anything else, no juicy error messages. AFAICS all the later messages are os-autoinst (the openQA test runner) going through the bootloader then noticing the thing it's looking for (the initial anaconda screen) is not appearing, and being sad - that's what all the "no match" and "no change" messages are about. The blob of messages about video encoding is from ffmpeg, os-autoinst uses ffmpeg to compile a video of the test execution from screenshots. I'll see if I can wangle a backtrace, it's a bit tricky as I have to catch a failure live, but I should be able to manage it.
And yeah, as I said I checked the host journal around one of the failures and there just wasn't anything interesting there. I am gonna test both upgrading and downgrading edk2 and see if that makes any difference (though the fact some of the tests at least make it through the bootloader seems to make that a less likely suspect).
If you suspect a UEFI problem, then this suggestion isn't going to help ... But it might be worth running 'qemu-sanity-check' as part of the tests. It simply ensures that the current kernel is able to boot up on the current qemu. We use it in RHEL already: https://gitlab.com/redhat/centos-stream/tests/kernel/kernel-tests/-/tree/main/vm/qemu-sanity-check?ref_type=heads
The problem is it's an intermittent issue. At a rough guess it's affecting maybe 2-3% of tests. Which is enough to be extremely annoying, but a low enough rate that any such test would likely pass. Anyhow, it doesn't seem clearly tied to any particular kernel, as I said. I'm seeing this affect guests running F42, F43 and F44 VMs, with a range of kernels. If there's a *systematic* issue booting a particular kernel on qemu, openQA's gonna notice that pretty quick and the change that triggered the bug will likely be fairly easy to spot. This kinda 'rare but common enough to be a problem' case is much harder to pin down :(
I tried upgrading edk2, it didn't help. I've now got a downgrade deployed and I'll keep an eye out for failures. If that doesn't help, next stop is a downgrade of qemu, then the kernel, I guess.
*Downgrading* edk2 seems like it has helped, though. It's only been a day, but since downgrading to edk2 20250523-18.fc43 on all worker hosts, I don't think I've seen a single case of this. I'll keep monitoring it, but for now let's tentatively re-assign to edk2.
Firmware logfile can be captured this way (libvirt xml, x86_64 only): <serial type='null'> <log file='/path/to/firmware.log' append='off'/> <target type='isa-debug' port='1'> <model name='isa-debugcon'/> </target> <address type='isa' iobase='0x402'/> </serial> Any hardware pattern (such as happening on intel / amd hosts only) ?
Also: edk2 update to 2025-11 just landed in stable, any change in behavior?
I already tried upgrading to a backport of 2025-11, that didn't help. I left the downgrade in place over the weekend and I don't see a single failure of this type on prod or staging, so I'm fairly confident that was it. openQA does not use libvirt, but I'll see if I can figure out how to convert that into qemu commands and wedge it into the openQA runner somehow.
(In reply to Adam Williamson from comment #12) > openQA does not use libvirt, but I'll see if I can figure out how to convert > that into qemu commands and wedge it into the openQA runner somehow. Pretty much just -debugcon file:/path/to/debug.log -global isa-debugcon.iobase=0x402
Thanks. I'll fiddle with that tomorrow as I'll need to futz it a bit so the logs from different runs don't collide...
(In reply to Adam Williamson from comment #12) > openQA does not use libvirt, So the setup is probably different from the default libvirt configuration ... What are the OVMF builds used by openQA?
It's all the official Fedora packaged stuff. You can't really see in the qemu command as it's obscured by overlays, sorry, here's the commands that set up the overlays: [2025-11-28T13:07:21.560555Z] [debug] [pid:1716340] running `/usr/bin/qemu-img create -f qcow2 -F qcow2 -b /usr/share/edk2/ovmf/OVMF_CODE_4M.secboot.qcow2 /var/lib/openqa/pool/30/raid/pflash-code-overlay0 3653632` [2025-11-28T13:07:21.588600Z] [debug] [pid:1716340] Formatting '/var/lib/openqa/pool/30/raid/pflash-code-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=3653632 backing_file=/usr/share/edk2/ovmf/OVMF_CODE_4M.secboot.qcow2 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16 [2025-11-28T13:07:21.588825Z] [debug] [pid:1716340] running `/usr/bin/qemu-img create -f qcow2 -F qcow2 -b /usr/share/edk2/ovmf/OVMF_VARS_4M.secboot.qcow2 /var/lib/openqa/pool/30/raid/pflash-vars-overlay0 540672` [2025-11-28T13:07:21.616953Z] [debug] [pid:1716340] Formatting '/var/lib/openqa/pool/30/raid/pflash-vars-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=540672 backing_file=/usr/share/edk2/ovmf/OVMF_VARS_4M.secboot.qcow2 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16 so we're using /usr/share/edk2/ovmf/OVMF_CODE_4M.secboot.qcow2 and /usr/share/edk2/ovmf/OVMF_VARS_4M.secboot.qcow2 , from the edk2 packages.
Created attachment 2117159 [details] debug log from a good boot with old, non-buggy edk2 20250523
Created attachment 2117160 [details] debug log from a bad boot with new, buggy edk2 20251119
Created attachment 2117161 [details] debug log from a good boot with new, buggy edk2 20251119 OK, managed to get the logs. I've attached three: a good boot with the old, working edk2; a bad boot with the new, buggy edk2; and a good boot with the new, buggy edk2, in case that's useful to see what's different between when the bug happens and when it doesn't.
In the 'bad' boot, we eventually made it past the bootloader to the 'Booting `Fedora Linux foobar` screen, but no further. I happened to be watching the test live, and I noticed that even getting that far was very slow - it took like a minute to reach the Tianocore bootsplash, then maybe another 30 seconds to a minute to reach the bootloader. I hadn't noticed that before.
As a suggestion...I've never found a case where it would have been a *bad* idea to timestamp a logfile. If you can't rely on any absolute time this early, you could still have timestamps on each message relative to the first one...
What happens if you use OVMF_CODE.secboot.fd + OVMF_VARS.secboot.fd? These builds have some features turned off to make the firmware fit into 2M, specifically the new 'log to memory buffer' feature which one candidate for being the root cause is disabled in these builds. Also: apparently virtio-serial is used by openQA, probably for anaconda logging, can you share the exact configuration?
It's in the qemu command I posted above: -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on What we get out on that console in a failed test looks like: BdsDxe: loading Boot0002 "UEFI QEMU QEMU CD-ROM " from PciRoot(0x0)/Pci(0x7,0x0)/Scsi(0x0,0x0) BdsDxe: starting Boot0002 "UEFI QEMU QEMU CD-ROM " from PciRoot(0x0)/Pci(0x7,0x0)/Scsi(0x0,0x0) GRUB version 2.12 ┌────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐││││││││││││││││││││││││││││││││││││││││││││││││││││││││││││││└────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘ Use the ▲ and ▼ keys to select which entry is highlighted. Press enter to boot the selected OS, `e' to edit the commands before booting or `c' for a command-line. Install Fedora eln *Test this media & install Fedora eln Install Fedora eln in FIPS mode Troubleshooting --> The highlighted entry will be executed automatically in 60s. The highlighted entry will be executed automatically in 59s. The highlighted entry will be executed automatically in 58s. Test this media & install Fedora eln *Install Fedora eln Install Fedora eln *Install Fedora eln i.e. a couple of messages and then the grub screen. I can try with the non-4M versions, yeah, but...I feel like when I was initially setting up UEFI or SB support in openQA I tried those and they didn't work, so that's why I wound up with the 4M versions. I might be misremembering, though. I'll try and see what happens.
So far it looks like new edk2 with the 2M OVMF_CODE and OVMF_VARS files is working. I'll leave it this way overnight and see if that holds up.
(In reply to Adam Williamson from comment #20) > and I noticed that even getting that far was very slow - it took > like a minute to reach the Tianocore bootsplash, then maybe another 30 > seconds to a minute to reach the bootloader. I hadn't noticed that before. The logging slows down things ...
(In reply to Adam Williamson from comment #21) > As a suggestion...I've never found a case where it would have been a *bad* > idea to timestamp a logfile. If you can't rely on any absolute time this > early, you could still have timestamps on each message relative to the first > one... Even relative time stamps are hard due to the way edk2 firmware is organized.
(In reply to Adam Williamson from comment #23) > -device virtio-serial -chardev > pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log, > logappend=on Ok, standard virtio console. Makes sense. I've expected to a 'org.fedoraproject.anaconda.log.0' virtserialport is there too.
https://copr.fedorainfracloud.org/coprs/kraxel/edk2.testbuilds/ Can you please: (a) install f42 or f43 builds from the copr repo, and (b) go back to the 4M builds, (c) check if there are any lines prefixed with 'MemDebugLog:' in the firmware log Expected behavior: the cases which used to fail now leave a message in the log file, so that is probably an equally rare event (same 2-3% of the test cases). edk2 changes: https://github.com/kraxel/edk2/commits/devel/logs-deadlock/
Roger, sounds good. Will try and report back later today.
OK, preliminary results: [root@openqa-x86-worker05 tmp][PROD-RDU3]# grep -l "^MemDebugLog" *.log | wc -l 6 [root@openqa-x86-worker05 tmp][PROD-RDU3]# grep -L "^MemDebugLog" *.log | wc -l 102 so, of 108 tests started, 6 have the messages, 102 do not. The ones that have the messages have a *lot* of them, though, for e.g.: [root@openqa-x86-worker05 tmp][PROD-RDU3]# grep "^MemDebugLog" 05643303-fedora-44-updates-workstation-live-iso-x86_64-BuildKojitask-139659340-NOREPORT-kiwi_build | wc -l 2748
After a bit longer: [root@openqa-x86-worker05 tmp][PROD-RDU3]# grep -l "^MemDebugLog" *.log | wc -l 36 [root@openqa-x86-worker05 tmp][PROD-RDU3]# grep -L "^MemDebugLog" *.log | wc -l 197 [root@openqa-x86-worker04 tmp][PROD-RDU3]# grep -l "^MemDebugLog" *.log | wc -l 37 [root@openqa-x86-worker04 tmp][PROD-RDU3]# grep -L "^MemDebugLog" *.log | wc -l 173 so 73 with messages, 370 without, or about 16% failure rate. That's a higher rate than we expected, but my estimate about how common the bug is might just have been off - we run a lot of tests and have automatic retry mechanisms, so it's a bit hard to be precise. Some tests are still timing out, but they may not be hung, just taking too long. It does seem like even with the 'fix', the boot process runs very slowly on jobs that are affected by the problem. I'll try disabling the actual log writing (now we have the numbers) and see if that makes the failures go away...
Unfortunately it seems we still get tests that time out on boot with the COPR edk2 even without the logging enabled, e.g. https://openqa.stg.fedoraproject.org/tests/5647574#step/base_service_manipulation/47 . In that test, we rebooted, then waited 5 minutes for a login screen to appear, and it didn't - as you can see, we only made it to the initial kernel load screen. I can't tell for sure if the system was entirely hung or if it would *eventually* have made it through. I can bump some boot timeouts to find out. But clearly there's still a problem even with the COPR build.
There is a new copr build with the '^MemDebugLog' debug message removed. Can you try if that makes a difference? I suspect it will not, but worth trying, also I don't feel like doing multiple changes at once while trying to find the root cause of this. Trying longer timeouts would be a useful data point too, maybe do that on one of the hosts only if openqa allows that?
Hmm. It actually seems like that *does* make a difference. I've had that one deployed all weekend on staging openQA, with the UEFI firmware set back to the 4M version, and it doesn't look like there have been any failures.
Ok, good. /me goes kick builds.
FEDORA-2025-debcd1b776 (edk2-20251119-3.fc43) has been submitted as an update to Fedora 43. https://bodhi.fedoraproject.org/updates/FEDORA-2025-debcd1b776
FEDORA-2025-d68818f057 (edk2-20250812-19.fc42) has been submitted as an update to Fedora 42. https://bodhi.fedoraproject.org/updates/FEDORA-2025-d68818f057
Thanks. I'll upgrade both deployments to that build, set the UEFI firmwares back to the 4M version on both, and keep an eye out for future failures.
FEDORA-2025-debcd1b776 has been pushed to the Fedora 43 testing repository. Soon you'll be able to install the update with the following command: `sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2025-debcd1b776` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2025-debcd1b776 See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
FEDORA-2025-d68818f057 has been pushed to the Fedora 42 testing repository. Soon you'll be able to install the update with the following command: `sudo dnf upgrade --enablerepo=updates-testing --refresh --advisory=FEDORA-2025-d68818f057` You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2025-d68818f057 See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.
So far things are looking good, thanks.
FEDORA-2025-debcd1b776 (edk2-20251119-3.fc43) has been pushed to the Fedora 43 stable repository. If problem still persists, please make note of it in this bug report.
FEDORA-2025-d68818f057 (edk2-20250812-19.fc42) has been pushed to the Fedora 42 stable repository. If problem still persists, please make note of it in this bug report.