Re: [OE-core] [PATCH 3/3] testimage.bbclass: capture RuntimeError too

[Richard Purdie <richard.purdie@linuxfoundation.org>]

On Tue, 2025-01-28 at 16:37 +0200, Mikko Rapeli wrote:
> On Tue, Jan 28, 2025 at 01:49:00PM +0000, Richard Purdie wrote:
> > On Tue, 2025-01-28 at 13:04 +0000, Richard Purdie via
> > lists.openembedded.org wrote:
> > > 
> > > Sorry for the delay in looking at this patch. I'm a bit worried about
> > > there being a leaked processes and wanted to understand if there was
> > > other cleanup we should be doing.
> > > 
> > > Instead of this path, would it make sense to move the results.stop()
> > > inside the finally? I'm worried that other forms of exception would
> > > also leak processes.
> > 
> > I've looked more at this and I don't understand how this patch works.
> > 
> > By adding the exception to the exception clause, it will trigger a
> > bb.error() call. The results.stop() call won't happen as results isn't
> > set in this failure.
> > 
> > The only significant difference would therefore be the results =
> > tc.results assignment. Does that really stop processes? If so, should
> > we always be doing that?
> > 
> > I'd like to understand what we need to do to "fix" things so we can
> > handle other exceptions.
> 
> If I remember correctly, I saw this when building meta-arm qemuarm64-secureboot
> kas config which runs oeqa runtime tests with testimage.bbclass during build.
> 
> Without fix 4b3b37156cdf70230bc74c647784da8514c284cf in poky a single failing test
> leaked Cooker processes. Then a rebuild of core-image-base connected to that Cooker
> process and somehow failed to re-generate rootfs which became an empty directory
> inside .wic image. This resulted qemu boot hanging which again throws RuntimeError
> from meta/lib/oeqa/core/target/qemu.py line 52.

Just to be clear, is memory resident bitbake set or not
(BB_SERVER_TIMEOUT) ?


> Example with poky from October 2024 (from old log files which I still had):
> 
> NOTE: Reconnecting to bitbake server...
> ...
> NOTE: recipe core-image-base-1.0-r0: task do_create_image_spdx: Succeeded
> QMP Available for connection at /home/builder/src/base/meta-arm/build/tmp/.ndozl5yn
> QMP connected to QEMU at 10/31/24 13:55:56 and took 0.56 seconds
> QMP released QEMU at 10/31/24 13:55:56 and took 0.19 seconds from connect
> Bitbake still alive (no events for 600s). Active tasks:
> /home/builder/src/base/meta-arm/build/../poky/meta/recipes-core/images/core-image-base.bb:do_testimage
> WARNING: core-image-base-1.0-r0 do_testimage: Target didn't reach login banner in 1000 seconds (10/31/24 14:12:36)
> WARNING: core-image-base-1.0-r0 do_testimage: Last 25 lines of login console (22962):
> [    4.345255] Key type fscrypt-provisioning registered
> [    4.363120] Btrfs loaded, zoned=no, fsverity=no
> [    4.522255] input: QEMU QEMU USB Tablet as /devices/platform/4010000000.pcie/pci0000:00/0000:00:03.0/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input
> /input0
> [    4.528765] hid-generic 0003:0627:0001.0001: input: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:03.0-1/input0
> [    4.636796] Key type encrypted registered
> [    4.644819] printk: legacy console [netcon0] enabled
> [    4.645638] netconsole: network logging started
> [    4.651065] clk: Disabling unused clocks
> [    4.651780] PM: genpd: Disabling unused power domains
> [    4.669045] usb 1-2: new high-speed USB device number 3 using xhci_hcd
> [    4.794967] Freeing unused kernel memory: 1856K
> [    4.803684] Run /init as init process
> [    4.847358] input: QEMU QEMU USB Keyboard as /devices/platform/4010000000.pcie/pci0000:00/0000:00:03.0/usb1/1-2/1-2:1.0/0003:0627:0001.0002/inp
> ut/input1
> [    4.919633] hid-generic 0003:0627:0001.0002: input: USB HID v1.11 Keyboard [QEMU QEMU USB Keyboard] on usb-0000:00:03.0-2/input0
> Starting systemd-udevd version 256.6
> 
> [    7.407191] virtio_net virtio0 enp0s1: renamed from eth0
> [   12.633172] ext3: Unknown parameter 'umask'
> [   12.634318] ext2: Unknown parameter 'umask'
> [   12.634924] ext4: Unknown parameter 'umask'
> [   12.676391] EXT4-fs (vda2): mounted filesystem 41dc66e6-d693-46b3-a5d6-a46998500609 r/w with ordered data mode. Quota mode: disabled.
> [   13.080423] /dev/disk/by-label/root: Can't open blockdev
> [   13.081201] /dev/disk/by-label/root: Can't open blockdev
> ERROR: There's no '/dev' on rootfs.
> 
> WARNING: core-image-base-1.0-r0 do_testimage: Check full boot log: /home/builder/src/base/meta-arm/build/tmp/work/qemuarm64_secureboot-poky-l
> inux/core-image-base/1.0/testimage/qemu_boot_log.20241031135427
> Output from runqemu:
> runqemu - INFO - Received signal: 15
> runqemu - INFO - Cleaning up
> runqemu - INFO - Host uptime: 14098967.33
> 
> tput: No value for $TERM and no -T specified
> WARNING: core-image-base-1.0-r0 do_testimage: Extra log data read: 
> 
> Output from runqemu:
> runqemu - INFO - Received signal: 15
> runqemu - INFO - Cleaning up
> runqemu - INFO - Host uptime: 14098967.33
> 
> tput: No value for $TERM and no -T specified
> 
> Output from runqemu:
> runqemu - INFO - Received signal: 15
> runqemu - INFO - Cleaning up
> runqemu - INFO - Host uptime: 14098967.33
> 
> tput: No value for $TERM and no -T specified
> 
> ERROR: core-image-base-1.0-r0 do_testimage: Error executing a python function in exec_func_python() autogenerated:
> 
> The stack trace of python calls that resulted in this exception/failure was:
> File: 'exec_func_python() autogenerated', lineno: 2, function: <module>
>      0001:
>  *** 0002:do_testimage(d)
>      0003:
> File: '/home/builder/src/base/meta-arm/build/../poky/meta/classes-recipe/testimage.bbclass', lineno: 122, function: do_testimage
>      0118:    dump-guest-memory {"paging":false,"protocol":"file:%s.img"}
>      0119:}
>      0120:
>      0121:python do_testimage() {
>  *** 0122:    testimage_main(d)
>      0123:}
>      0124:
>      0125:addtask testimage
>      0126:do_testimage[nostamp] = "1"
> File: '/home/builder/src/base/meta-arm/build/../poky/meta/classes-recipe/testimage.bbclass', lineno: 364, function: testimage_main
>      0360:    orig_sigterm_handler = signal.signal(signal.SIGTERM, sigterm_exception)
>      0361:    try:
>      0362:        # We need to check if runqemu ends unexpectedly
>      0363:        # or if the worker send us a SIGTERM
>  *** 0364:        tc.target.start(params=d.getVar("TEST_QEMUPARAMS"), runqemuparams=d.getVar("TEST_RUNQEMUPARAMS"))
>      0365:        import threading
>      0366:        try:
>      0367:            threading.Timer(int(d.getVar("TEST_OVERALL_TIMEOUT")), handle_test_timeout, (int(d.getVar("TEST_OVERALL_TIMEOUT")),)).start(
> )
>      0368:        except ValueError:
> File: '/home/builder/src/base/meta-arm/build/../poky/meta/lib/oeqa/core/target/qemu.py', lineno: 91, function: start
>      0087:            except (subprocess.CalledProcessError, subprocess.TimeoutExpired, FileNotFoundError) as err:
>      0088:                msg += "Error running command: %s\n%s\n" % (blcmd, err)
>      0089:            msg += "\n\n===== end: snippet =====\n"
>      0090:
>  *** 0091:            raise RuntimeError("FAILED to start qemu - check the task log and the boot log %s" % (msg))
>      0092:
>      0093:    def stop(self):
>      0094:        self.runner.stop()
> Exception: RuntimeError: FAILED to start qemu - check the task log and the boot log 
> 
> ===== start: snippet =====
> 
> 
> 
> ===== end: snippet =====
> 
> ===== start: snippet =====
> 
> Error running command: ['tail', '-20', '/home/builder/src/base/meta-arm/build/tmp/work/qemuarm64_secureboot-poky-linux/core-image-base/1.0/te
> stimage/qemu_boot_log.20241031135427']
> Command '['tail', '-20', '/home/builder/src/base/meta-arm/build/tmp/work/qemuarm64_secureboot-poky-linux/core-image-base/1.0/testimage/qemu_b
> oot_log.20241031135427']' returned non-zero exit status 1.
> 
> ===== end: snippet =====
> 
> 
> ERROR: Logfile of failure stored in: /home/builder/src/base/meta-arm/build/tmp/work/qemuarm64_secureboot-poky-linux/core-image-base/1.0/temp/
> log.do_testimage.1578012
> NOTE: recipe core-image-base-1.0-r0: task do_testimage: Failed
> ERROR: Task (/home/builder/src/base/meta-arm/build/../poky/meta/recipes-core/images/core-image-base.bb:do_testimage) failed with exit code '1
> '
> NOTE: Tasks Summary: Attempted 7116 tasks of which 7081 didn't need to be rerun and 1 failed.
> 
> Summary: 1 task failed:
>   /home/builder/src/base/meta-arm/build/../poky/meta/recipes-core/images/core-image-base.bb:do_testimage
> 
> 
> Since this exit happens without catching RuntimeError, there is no cleanup
> and Cooker, qemu-system-aarch64 etc processes get leaked again.

Can you point at the "no cleanup"? The code in question has a
try/except/finally clause and the finally should always run. I'm
therefore struggling to work out which cleanup code isn't running.

> If the RuntimeError is captured, then clean up is done and qemu-system-aarch64
> and Cooker processes get killed. Together with
> 4b3b37156cdf70230bc74c647784da8514c284cf in poky
> the failing oeqa runtime test under qemu was handled correctly
> and rebuilds always ended up with same failure, specifically
> from parselogs which is a bit greedy when detecting errors.
> 
> Does this help? If not, I can try to replicate the setup and failures
> again, and try different fixes.

I can't really sed which cleanup code we're missing and I'd like to
understand this before we take the patch as something isn't adding up.

Cheers,

Richard