15651 2024-11-19 15:12:32 +0000 strace ptest shows multiple levels of breakage 2026-03-31 17:47:44 +0000 1 1 10 QA/Testing Package Testing (ptest) ptest unspecified x86 Multiple NEW Medium+ normal 6.1 M1 1 richard.purdie randy.macleod randy.macleod --- --- No (bug/feature does not impact docs) oldest_to_newest 100207 0 richard.purdie 2024-11-19 15:12:32 +0000 https://valkyrie.yoctoproject.org/#/builders/73/builds/401 The build is hanging. Looking at the testimage task log, it is 6GB in size. The reason why is the tar output collection is being printed into the log as binary data: https://valkyrie.yocto.io/pub/shared-failure-data/log.do_testimage.2400954 So firstly we need to fix that. Secondly a test fails: https://valkyrie.yocto.io/pub/shared-failure-data/ptest-runner.log and finally, there is a lot of noise in dmesg from the test run including an OOM: https://valkyrie.yocto.io/pub/shared-failure-data/qemu_boot_log.20241118102253 not sure if the OOM is related to the test failure or not. There is the question of why the task finished but cooker is still running too. 100208 1 richard.purdie 2024-11-19 15:15:07 +0000 bitbake-cookerdaemon shows nothing interesting, pings are succeeding. The console output shows the core-image-ptest-strace did finish and the log output is shown but somehow bitbake never marked the task as completed. 100209 2 richard.purdie 2024-11-19 15:17:35 +0000 Nothing significant in the host dmesg. 100210 3 richard.purdie 2024-11-19 15:27:51 +0000 bitbake-worker is looping in worker_flush writing 64kb at a time: mmap(NULL, 2218389504, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d93c00000 munmap(0x712c8b400000, 2218455040) = 0 futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xb47bd8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997040}) write(1, "aa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\x"..., 2218387790) = 65536 mmap(NULL, 2218323968, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d0f800000 munmap(0x712d93c00000, 2218389504) = 0 futex(0xb47b80, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xb47bdc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999996730}) write(1, "aa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\x"..., 2218322254) = 65536 mmap(NULL, 2218258432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712c8b400000 munmap(0x712d0f800000, 2218323968) = 0 futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xb47b80, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=673516, tv_nsec=134260404}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1) = 0 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999996940}) write(1, "aa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\xaa\\x"..., 2218256718) = 65536 mmap(NULL, 2218192896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d93c00000 (gdb) py-bt Traceback (most recent call first): File "/srv/pokybuild/yocto-worker/qemux86-64-ptest/build/bitbake/bin/bitbake-worker", line 108, in worker_flush worker_queue_int = worker_queue_int[written:] File "/usr/lib/python3.12/threading.py", line 1010, in run self._target(*self._args, **self._kwargs) File "/usr/lib/python3.12/threading.py", line 1073, in _bootstrap_inner self.run() File "/usr/lib/python3.12/threading.py", line 1030, in _bootstrap self._bootstrap_inner() 100212 4 richard.purdie 2024-11-19 15:59:53 +0000 The delay is around the mmap, which corresponds to: worker_queue_int = worker_queue_int[written:] in the worker code. 100213 5 richard.purdie 2024-11-19 16:01:20 +0000 With timestamps: 17:00:53.877740 munmap(0x712d9aa00000, 2101735424) = 0 17:00:54.056454 futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1) = 1 17:00:54.056501 futex(0xb47bdc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) 17:00:54.056618 futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0 17:00:54.056650 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997460}) 17:00:54.056734 write(1, "UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU"..., 2101668174) = 65536 17:00:54.056850 mmap(NULL, 2101604352, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d9aa00000 17:00:55.085339 munmap(0x712d1d400000, 2101669888) = 0 17:00:55.263597 futex(0xb47b80, FUTEX_WAKE_PRIVATE, 1) = 1 17:00:55.263668 futex(0xb47bd8, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) 17:00:55.263727 futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0 17:00:55.263787 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997420}) 17:00:55.263887 write(1, "UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU"..., 2101602638) = 65536 17:00:55.264014 mmap(NULL, 2101538816, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d1d400000 17:00:56.283010 munmap(0x712d9aa00000, 2101604352) = 0 17:00:56.461363 futex(0xb47b84, FUTEX_WAKE_PRIVATE, 1) = 1 17:00:56.461436 futex(0xb47bdc, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) 17:00:56.461495 futex(0xb47be0, FUTEX_WAKE_PRIVATE, 1) = 0 17:00:56.461555 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999996780}) 17:00:56.461656 write(1, "UUUUUUUUUUUUUUUUUUUUUUUUUUUUUUUU"..., 2101537102) = 65536 17:00:56.461736 mmap(NULL, 2101473280, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x712d9aa00000 17:00:57.500454 munmap(0x712d1d400000, 2101538816) = 0 17:00:57.677700 futex(0xb47b80, FUTEX_WAKE_PRIVATE, 1) = 1 17:00:57.677770 futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1) = 1 17:00:57.677826 futex(0xb47b84, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=675735, tv_nsec=3601111}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable) 17:00:57.677904 futex(0xb47b88, FUTEX_WAKE_PRIVATE, 1) = 0 17:00:57.677962 pselect6(2, NULL, [1], NULL, {tv_sec=1, tv_nsec=0}, NULL) = 1 (out [1], left {tv_sec=0, tv_nsec=999997310} 100222 6 richard.purdie 2024-11-20 15:13:49 +0000 For the record, strace ptest creates a 43GB sparse file which is why the data transfer is huge when saving artefact data. 100224 7 richard.purdie 2024-11-20 22:20:04 +0000 Summary of issues found: https://lists.openembedded.org/g/openembedded-core/message/207476 100237 8 randy.macleod 2024-11-21 15:37:24 +0000 For the strace issue which is all that remains thanks to Richard.