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

[Mikko Rapeli <mikko.rapeli@linaro.org>]

Hi,

On Tue, Jan 28, 2025 at 03:10:34PM +0000, Richard Purdie wrote:
> 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) ?

meta-arm builds set:

ci/base.yml:    BB_SERVER_TIMEOUT = "300"

I was building in kas shell.

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

With TESTIMAGE_AUTO = "1" in local.conf, I have seen a lot of failures to kill
Cooker and qemu-system-aarch64 processes. Running tests with slirp networking
over ssh and even pressing ctrl-c multiple times on the build leaves those into
the background. Manual cleanup is needed.

I will setup the builds again to test these out.

Cheers,

-Mikko