[PATCH 1/3] uki.bbclass: fix debug print logging level

[PATCH 1/3] uki.bbclass: fix debug print logging level

[Mikko Rapeli]

Missing/unknown log level triggers a warning.

Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
---
 meta/classes-recipe/uki.bbclass | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/meta/classes-recipe/uki.bbclass b/meta/classes-recipe/uki.bbclass
index d4f25c7fd2..441e4a7f8e 100644
--- a/meta/classes-recipe/uki.bbclass
+++ b/meta/classes-recipe/uki.bbclass
@@ -189,7 +189,7 @@ python do_uki() {
     ukify_cmd += " %s" % (output)
 
     # Run the ukify command
-    bb.debug("uki: running command: %s" % (ukify_cmd))
+    bb.debug(2, "uki: running command: %s" % (ukify_cmd))
     bb.process.run(ukify_cmd, shell=True)
 }
 addtask uki after do_rootfs before do_deploy do_image_complete do_image_wic
-- 
2.34.1

[PATCH 2/3] oeqa runtime uki.py: add tests

[Mikko Rapeli]

If Unified Kernel Image was enabled via IMAGE_CLASSES, then
target should also boot the same uki at runtime.

Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
---
 meta/lib/oeqa/runtime/cases/uki.py | 16 ++++++++++++++++
 1 file changed, 16 insertions(+)
 create mode 100644 meta/lib/oeqa/runtime/cases/uki.py

diff --git a/meta/lib/oeqa/runtime/cases/uki.py b/meta/lib/oeqa/runtime/cases/uki.py
new file mode 100644
index 0000000000..77bc5b9791
--- /dev/null
+++ b/meta/lib/oeqa/runtime/cases/uki.py
@@ -0,0 +1,16 @@
+# SPDX-License-Identifier: MIT
+#
+
+from oeqa.runtime.case import OERuntimeTestCase
+from oeqa.core.decorator.data import skipIfNotInDataVar
+
+class UkiTest(OERuntimeTestCase):
+
+    @skipIfNotInDataVar('IMAGE_CLASSES', 'uki', 'Test case uki is for images which use uki.bbclass')
+    def test_uki(self):
+        uki_filename = self.td.get('UKI_FILENAME')
+        status, output = self.target.run('ls /boot/EFI/Linux/%s' % uki_filename)
+        self.assertEqual(status, 0, output)
+
+        status, output = self.target.run('echo $( cat /sys/firmware/efi/efivars/LoaderEntrySelected-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f  ) | grep %s' % uki_filename)
+        self.assertEqual(status, 0, output)
-- 
2.34.1

[PATCH 3/3] testimage.bbclass: capture RuntimeError too

[Mikko Rapeli]

runqemu can fail with RuntimeError exception. Non-cought exception
causes cooker process leaks which bind to successive bitbake command
line calls and that can cause really odd errors to users, e.g. when
build/tmp is wiped and cooker processes expect files to be there.

Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
---
 meta/classes-recipe/testimage.bbclass | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/meta/classes-recipe/testimage.bbclass b/meta/classes-recipe/testimage.bbclass
index 19075ce1f3..a9b031093a 100644
--- a/meta/classes-recipe/testimage.bbclass
+++ b/meta/classes-recipe/testimage.bbclass
@@ -371,7 +371,7 @@ def testimage_main(d):
         complete = True
         if results.hasAnyFailingTest():
             run_failed_tests_post_actions(d, tc)
-    except (KeyboardInterrupt, BlockingIOError) as err:
+    except (KeyboardInterrupt, BlockingIOError, RuntimeError) as err:
         if isinstance(err, KeyboardInterrupt):
             bb.error('testimage interrupted, shutting down...')
         else:
-- 
2.34.1

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

[Richard Purdie]

On Mon, 2024-11-11 at 13:16 +0000, Mikko Rapeli via lists.openembedded.org wrote:
> runqemu can fail with RuntimeError exception. Non-cought exception
> causes cooker process leaks which bind to successive bitbake command
> line calls and that can cause really odd errors to users, e.g. when
> build/tmp is wiped and cooker processes expect files to be there.
> 
> Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
> ---
>  meta/classes-recipe/testimage.bbclass | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/meta/classes-recipe/testimage.bbclass b/meta/classes-recipe/testimage.bbclass
> index 19075ce1f3..a9b031093a 100644
> --- a/meta/classes-recipe/testimage.bbclass
> +++ b/meta/classes-recipe/testimage.bbclass
> @@ -371,7 +371,7 @@ def testimage_main(d):
>          complete = True
>          if results.hasAnyFailingTest():
>              run_failed_tests_post_actions(d, tc)
> -    except (KeyboardInterrupt, BlockingIOError) as err:
> +    except (KeyboardInterrupt, BlockingIOError, RuntimeError) as err:
>          if isinstance(err, KeyboardInterrupt):
>              bb.error('testimage interrupted, shutting down...')
>          else:
> 

During review it is hard to understand what the real issue is from this
description. I don't like the sound of processes leaking and if that is
happening, adding another exception to this list doesn't feel correct.
I was going to ask for a better explanation but looking at the code,
perhaps this error handling path just needs rewriting/improving with
more of the code in the finally, conditionally?

I just want to make sure we fix the real bug here.

Cheers,

Richard 

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

[Mikko Rapeli]

Hi,

On Tue, Nov 12, 2024 at 11:25:51AM +0000, Richard Purdie wrote:
> On Mon, 2024-11-11 at 13:16 +0000, Mikko Rapeli via lists.openembedded.org wrote:
> > runqemu can fail with RuntimeError exception. Non-cought exception
> > causes cooker process leaks which bind to successive bitbake command
> > line calls and that can cause really odd errors to users, e.g. when
> > build/tmp is wiped and cooker processes expect files to be there.
> > 
> > Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
> > ---
> > �meta/classes-recipe/testimage.bbclass | 2 +-
> > �1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/meta/classes-recipe/testimage.bbclass b/meta/classes-recipe/testimage.bbclass
> > index 19075ce1f3..a9b031093a 100644
> > --- a/meta/classes-recipe/testimage.bbclass
> > +++ b/meta/classes-recipe/testimage.bbclass
> > @@ -371,7 +371,7 @@ def testimage_main(d):
> > �������� complete = True
> > �������� if results.hasAnyFailingTest():
> > ������������ run_failed_tests_post_actions(d, tc)
> > -��� except (KeyboardInterrupt, BlockingIOError) as err:
> > +��� except (KeyboardInterrupt, BlockingIOError, RuntimeError) as err:
> > �������� if isinstance(err, KeyboardInterrupt):
> > ������������ bb.error('testimage interrupted, shutting down...')
> > �������� else:
> > 
> 
> During review it is hard to understand what the real issue is from this
> description. I don't like the sound of processes leaking and if that is
> happening, adding another exception to this list doesn't feel correct.
> I was going to ask for a better explanation but looking at the code,
> perhaps this error handling path just needs rewriting/improving with
> more of the code in the finally, conditionally?
> 
> I just want to make sure we fix the real bug here.

Sorry for being unclear. I thought the backtrace would be too verbose.

The bug happens when runqemu startup fails:

poky/meta/lib/oeqa/targetcontrol.py:            raise RuntimeError("%s - FAILED to start qemu - check the task log and the boot log" % self.pn)

cooker processes do leak when the exceptions are not cought.
Maybe these are not strictly related but it happens for me. It
can be that cleanup happens but just slowly, and when I run
other bitbake commands right after failure they connect to these
leaked cooker processes which then behave badly, for example when
build/tmp was already wiped.

Here is a failure log from one of my builds from meta-arm with other
changes on top which are the root cause for missing rootfs file:

ERROR: core-image-base-1.0-r0 do_testimage: Invalid rootfs /home/builder/src/base/meta-arm/build/tmp/deploy/images/qemuarm64-secureboot/core-image-base-qemuarm64-secureboot.rootfs.wic.qcow2
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/testimage/qemu_boot_log.20241031142321']
Command '['tail', '-20', '/home/builder/src/base/meta-arm/build/tmp/work/qemuarm64_secureboot-poky-linux/core-image-base/1.0/testimage/qemu_boot_log.20241031142321']' 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.1779338
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 7084 tasks of which 7054 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

Cheers,

-Mikko

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

[Richard Purdie]

On Mon, 2024-11-18 at 10:00 +0200, Mikko Rapeli wrote:
> On Tue, Nov 12, 2024 at 11:25:51AM +0000, Richard Purdie wrote:
> > On Mon, 2024-11-11 at 13:16 +0000, Mikko Rapeli via lists.openembedded.org wrote:
> > > runqemu can fail with RuntimeError exception. Non-cought exception
> > > causes cooker process leaks which bind to successive bitbake command
> > > line calls and that can cause really odd errors to users, e.g. when
> > > build/tmp is wiped and cooker processes expect files to be there.
> > > 
> > > Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
> > > ---
> > >  meta/classes-recipe/testimage.bbclass | 2 +-
> > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > > 
> > > diff --git a/meta/classes-recipe/testimage.bbclass b/meta/classes-recipe/testimage.bbclass
> > > index 19075ce1f3..a9b031093a 100644
> > > --- a/meta/classes-recipe/testimage.bbclass
> > > +++ b/meta/classes-recipe/testimage.bbclass
> > > @@ -371,7 +371,7 @@ def testimage_main(d):
> > >          complete = True
> > >          if results.hasAnyFailingTest():
> > >              run_failed_tests_post_actions(d, tc)
> > > -    except (KeyboardInterrupt, BlockingIOError) as err:
> > > +    except (KeyboardInterrupt, BlockingIOError, RuntimeError) as err:
> > >          if isinstance(err, KeyboardInterrupt):
> > >              bb.error('testimage interrupted, shutting down...')
> > >          else:
> > > 
> > 
> > During review it is hard to understand what the real issue is from this
> > description. I don't like the sound of processes leaking and if that is
> > happening, adding another exception to this list doesn't feel correct.
> > I was going to ask for a better explanation but looking at the code,
> > perhaps this error handling path just needs rewriting/improving with
> > more of the code in the finally, conditionally?
> > 
> > I just want to make sure we fix the real bug here.
> 
> Sorry for being unclear. I thought the backtrace would be too verbose.
> 
> The bug happens when runqemu startup fails:
> 
> poky/meta/lib/oeqa/targetcontrol.py:            raise RuntimeError("%s - FAILED to start qemu - check the task log and the boot log" % self.pn)
> 
> cooker processes do leak when the exceptions are not cought.
> Maybe these are not strictly related but it happens for me. It
> can be that cleanup happens but just slowly, and when I run
> other bitbake commands right after failure they connect to these
> leaked cooker processes which then behave badly, for example when
> build/tmp was already wiped.
> 

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.

Cheers,

Richard

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

[Richard Purdie]

On Tue, 2025-01-28 at 13:04 +0000, Richard Purdie via
lists.openembedded.org wrote:
> On Mon, 2024-11-18 at 10:00 +0200, Mikko Rapeli wrote:
> > On Tue, Nov 12, 2024 at 11:25:51AM +0000, Richard Purdie wrote:
> > > On Mon, 2024-11-11 at 13:16 +0000, Mikko Rapeli via
> > > lists.openembedded.org wrote:
> > > > runqemu can fail with RuntimeError exception. Non-cought
> > > > exception
> > > > causes cooker process leaks which bind to successive bitbake
> > > > command
> > > > line calls and that can cause really odd errors to users, e.g.
> > > > when
> > > > build/tmp is wiped and cooker processes expect files to be
> > > > there.
> > > > 
> > > > Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
> > > > ---
> > > >  meta/classes-recipe/testimage.bbclass | 2 +-
> > > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > > > 
> > > > diff --git a/meta/classes-recipe/testimage.bbclass
> > > > b/meta/classes-recipe/testimage.bbclass
> > > > index 19075ce1f3..a9b031093a 100644
> > > > --- a/meta/classes-recipe/testimage.bbclass
> > > > +++ b/meta/classes-recipe/testimage.bbclass
> > > > @@ -371,7 +371,7 @@ def testimage_main(d):
> > > >          complete = True
> > > >          if results.hasAnyFailingTest():
> > > >              run_failed_tests_post_actions(d, tc)
> > > > -    except (KeyboardInterrupt, BlockingIOError) as err:
> > > > +    except (KeyboardInterrupt, BlockingIOError, RuntimeError)
> > > > as err:
> > > >          if isinstance(err, KeyboardInterrupt):
> > > >              bb.error('testimage interrupted, shutting
> > > > down...')
> > > >          else:
> > > > 
> > > 
> > > During review it is hard to understand what the real issue is
> > > from this
> > > description. I don't like the sound of processes leaking and if
> > > that is
> > > happening, adding another exception to this list doesn't feel
> > > correct.
> > > I was going to ask for a better explanation but looking at the
> > > code,
> > > perhaps this error handling path just needs rewriting/improving
> > > with
> > > more of the code in the finally, conditionally?
> > > 
> > > I just want to make sure we fix the real bug here.
> > 
> > Sorry for being unclear. I thought the backtrace would be too
> > verbose.
> > 
> > The bug happens when runqemu startup fails:
> > 
> > poky/meta/lib/oeqa/targetcontrol.py:            raise
> > RuntimeError("%s - FAILED to start qemu - check the task log and
> > the boot log" % self.pn)
> > 
> > cooker processes do leak when the exceptions are not cought.
> > Maybe these are not strictly related but it happens for me. It
> > can be that cleanup happens but just slowly, and when I run
> > other bitbake commands right after failure they connect to these
> > leaked cooker processes which then behave badly, for example when
> > build/tmp was already wiped.
> > 
> 
> 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.

Cheers,

Richard

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

[Mikko Rapeli]

Hi,

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:
> > On Mon, 2024-11-18 at 10:00 +0200, Mikko Rapeli wrote:
> > > On Tue, Nov 12, 2024 at 11:25:51AM +0000, Richard Purdie wrote:
> > > > On Mon, 2024-11-11 at 13:16 +0000, Mikko Rapeli via
> > > > lists.openembedded.org wrote:
> > > > > runqemu can fail with RuntimeError exception. Non-cought
> > > > > exception
> > > > > causes cooker process leaks which bind to successive bitbake
> > > > > command
> > > > > line calls and that can cause really odd errors to users, e.g.
> > > > > when
> > > > > build/tmp is wiped and cooker processes expect files to be
> > > > > there.
> > > > > 
> > > > > Signed-off-by: Mikko Rapeli <mikko.rapeli@linaro.org>
> > > > > ---
> > > > > �meta/classes-recipe/testimage.bbclass | 2 +-
> > > > > �1 file changed, 1 insertion(+), 1 deletion(-)
> > > > > 
> > > > > diff --git a/meta/classes-recipe/testimage.bbclass
> > > > > b/meta/classes-recipe/testimage.bbclass
> > > > > index 19075ce1f3..a9b031093a 100644
> > > > > --- a/meta/classes-recipe/testimage.bbclass
> > > > > +++ b/meta/classes-recipe/testimage.bbclass
> > > > > @@ -371,7 +371,7 @@ def testimage_main(d):
> > > > > �������� complete = True
> > > > > �������� if results.hasAnyFailingTest():
> > > > > ������������ run_failed_tests_post_actions(d, tc)
> > > > > -��� except (KeyboardInterrupt, BlockingIOError) as err:
> > > > > +��� except (KeyboardInterrupt, BlockingIOError, RuntimeError)
> > > > > as err:
> > > > > �������� if isinstance(err, KeyboardInterrupt):
> > > > > ������������ bb.error('testimage interrupted, shutting
> > > > > down...')
> > > > > �������� else:
> > > > > 
> > > > 
> > > > During review it is hard to understand what the real issue is
> > > > from this
> > > > description. I don't like the sound of processes leaking and if
> > > > that is
> > > > happening, adding another exception to this list doesn't feel
> > > > correct.
> > > > I was going to ask for a better explanation but looking at the
> > > > code,
> > > > perhaps this error handling path just needs rewriting/improving
> > > > with
> > > > more of the code in the finally, conditionally?
> > > > 
> > > > I just want to make sure we fix the real bug here.
> > > 
> > > Sorry for being unclear. I thought the backtrace would be too
> > > verbose.
> > > 
> > > The bug happens when runqemu startup fails:
> > > 
> > > poky/meta/lib/oeqa/targetcontrol.py:����������� raise
> > > RuntimeError("%s - FAILED to start qemu - check the task log and
> > > the boot log" % self.pn)
> > > 
> > > cooker processes do leak when the exceptions are not cought.
> > > Maybe these are not strictly related but it happens for me. It
> > > can be that cleanup happens but just slowly, and when I run
> > > other bitbake commands right after failure they connect to these
> > > leaked cooker processes which then behave badly, for example when
> > > build/tmp was already wiped.
> > > 
> > 
> > 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.

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.

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.

Cheers,

-Mikko

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

[Richard Purdie]

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

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

[Mikko Rapeli]

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