We got this error a few time during the last weeks, always during oe-selftest-ubuntu and always on ubuntu2204-vk-1 so far. 644 2025-02-13 21:24:13,049 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last): 645 File "/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/meta/lib/oeqa/selftest/cases/devtool.py", line 397, in test_devtool_add 646 bb_vars = get_bb_vars(['D', 'bindir'], pn) 647 File "/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/meta/lib/oeqa/utils/commands.py", line 250, in get_bb_vars 648 bbenv = get_bb_env(target, postconfig=postconfig) 649 File "/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/meta/lib/oeqa/utils/commands.py", line 244, in get_bb_env 650 return bitbake("-e %s" % target, postconfig=postconfig).output 651 File "/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/meta/lib/oeqa/utils/commands.py", line 236, in bitbake 652 return runCmd(cmd, ignore_status, timeout, output_log=output_log, **options) 653 File "/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/meta/lib/oeqa/utils/commands.py", line 214, in runCmd 654 raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output)) 655 AssertionError: Command 'bitbake -e pv' returned non-zero exit status 1: 656 NOTE: Reconnecting to bitbake server... 657 Loading cache...ERROR: Executing event: bitbake-server might have died or been forcibly stopped, ie. OOM killed
oe-selftest-ubuntu ubuntu2204-vk-1 master-next completed at 2025-02-13T23:29:32Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/969/steps/14/logs/stdio oe-selftest-ubuntu ubuntu2204-vk-1 mathieu/master-next completed at 2025-02-17T11:03:51Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/982/steps/14/logs/stdio oe-selftest-ubuntu ubuntu2204-vk-1 master-next completed at 2025-02-18T13:23:43Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/991/steps/14/logs/stdio oe-selftest-ubuntu ubuntu2204-vk-1 master-next completed at 2025-02-19T11:47:27Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/1003/steps/14/logs/stdio oe-selftest-ubuntu ubuntu2204-vk-1 mathieu/master-next completed at 2025-02-19T19:33:27Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/1007/steps/14/logs/stdio oe-selftest-ubuntu ubuntu2204-vk-1 mathieu/master-next completed at 2025-02-25T11:55:46Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/1040/steps/14/logs/stdio
oe-selftest-ubuntu ubuntu2204-vk-1 mathieu/master-next completed at 2025-02-26T11:17:24Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/1047/steps/14/logs/stdio
Randy to run the IO test script that runs top and other stuff.
I did some investigation and I can note that: * there is nothing in dmesg * journalctl does show ubuntu2204-vk-1 systemd-networkd[1913]: tap1: Gained carrier ubuntu2204-vk-1 systemd-networkd[1913]: tap1: Lost carrier type messages around the times when we see these failures which means qemu is being stopped/started * there is nothing in the bitbake-cookerdaemon log at the time of problems. I added extra flush calls, I switched the code to create separate log files per server pid, I added extra exception handling code and nothing shows anything further in the logs, it is as if the bitbake server is SIGKILL'd * When the new server does start, the logs show WARNING: removing existing socket file '/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/ build-st-164284/bitbake.sock' messages which means the shutdown was unclean * Michael tried making the builbot worker version the same as the other workers with no change * Michael rebooted that system and upgraded the kernel, no change.
I added an auditd syscall intercept for kill syscalls. I then share the logs for a failure below from https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/1074 Bitbake server cooker daemon log that hangs: 552802 16:47:03.836461 --- Starting bitbake server pid 552802 at 2025-02-28 16:47:03.836446 --- [....] 552802 17:06:43.459213 Command Completed (socket: True) auditd intercepts for kill syscall ---- time->Fri Feb 28 17:06:47 2025 type=PROCTITLE msg=audit(1740762407.201:3713): proctitle="/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/build-st-552482/tmp/sysroots-components/x86_64/pseudo-native/usr/bin/pseudo" type=OBJ_PID msg=audit(1740762407.201:3713): opid=2021315 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="pseudo" type=SYSCALL msg=audit(1740762407.201:3713): arch=c000003e syscall=62 success=yes exit=0 a0=1ed7c3 a1=a a2=30 a3=5 items=0 ppid=2021315 pid=2021320 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) ses=4294967295 comm=" pseudo" exe="/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/build-st-552482/tmp/sysroots-components/x86_64/pseudo-native/usr/bin/pseudo" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:06:47 2025 type=PROCTITLE msg=audit(1740762407.289:3714): proctitle=707974686F6E33002F7372762F706F6B796275696C642F796F63746F2D776F726B65722F6F652D73656C66746573742D7562756E74752F6275696C642F736372697074732F6F652D73656C6674657374002D61002D2D736B69702D74657374730064697374726F646174612E446 97374726F646174612E746573745F63686563 type=OBJ_PID msg=audit(1740762407.289:3714): opid=2015430 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="qemu-system-x86" type=SYSCALL msg=audit(1740762407.289:3714): arch=c000003e syscall=62 success=yes exit=0 a0=1ec0c6 a1=f a2=562705a73b40 a3=56270586f0d9 items=0 ppid=552429 pid=552458 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) se s=4294967295 comm="KnottyUI" exe="/usr/bin/python3.10" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:06:47 2025 type=PROCTITLE msg=audit(1740762407.289:3715): proctitle=707974686F6E33002F7372762F706F6B796275696C642F796F63746F2D776F726B65722F6F652D73656C66746573742D7562756E74752F6275696C642F736372697074732F6F652D73656C6674657374002D61002D2D736B69702D74657374730064697374726F646174612E446 97374726F646174612E746573745F63686563 type=OBJ_PID msg=audit(1740762407.289:3715): opid=2015299 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="KnottyUI" type=SYSCALL msg=audit(1740762407.289:3715): arch=c000003e syscall=62 success=yes exit=0 a0=1ec043 a1=9 a2=562705a73b40 a3=56270586f0d9 items=0 ppid=552429 pid=552458 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) se s=4294967295 comm="KnottyUI" exe="/usr/bin/python3.10" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:06:47 2025 type=PROCTITLE msg=audit(1740762407.289:3716): proctitle=707974686F6E33002F7372762F706F6B796275696C642F796F63746F2D776F726B65722F6F652D73656C66746573742D7562756E74752F6275696C642F736372697074732F6F652D73656C6674657374002D61002D2D736B69702D74657374730064697374726F646174612E44697374726F646174612E746573745F63686563 type=OBJ_PID msg=audit(1740762407.289:3716): opid=2015430 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="qemu-system-x86" type=OBJ_PID msg=audit(1740762407.289:3716): opid=2015294 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="sh" type=OBJ_PID msg=audit(1740762407.289:3716): opid=2015298 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="python3" type=SYSCALL msg=audit(1740762407.289:3716): arch=c000003e syscall=62 success=yes exit=0 a0=ffe13fc2 a1=f a2=562705a73b40 a3=5627058c3b32 items=0 ppid=552429 pid=552458 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) ses=4294967295 comm="KnottyUI" exe="/usr/bin/python3.10" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:06:47 2025 type=PROCTITLE msg=audit(1740762407.289:3717): proctitle=707974686F6E33002F7372762F706F6B796275696C642F796F63746F2D776F726B65722F6F652D73656C66746573742D7562756E74752F6275696C642F736372697074732F72756E71656D7500736E617073686F74006B766D0071656D757838362D3634002F7372762F706F6B796275696C642F796F63746F2D776F726B6572 type=OBJ_PID msg=audit(1740762407.289:3717): opid=2015430 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="qemu-system-x86" type=SYSCALL msg=audit(1740762407.289:3717): arch=c000003e syscall=62 success=yes exit=0 a0=1ec0c6 a1=f a2=555d37429b40 a3=555d372250d9 items=0 ppid=1 pid=2015298 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) ses=4294967295 comm="python3" exe="/usr/bin/python3.10" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:06:52 2025 type=PROCTITLE msg=audit(1740762412.289:3718): proctitle=707974686F6E33002F7372762F706F6B796275696C642F796F63746F2D776F726B65722F6F652D73656C66746573742D7562756E74752F6275696C642F736372697074732F72756E71656D7500736E617073686F74006B766D0071656D757838362D3634002F7372762F706F6B796275696C642F796F63746F2D776F726B6572 type=OBJ_PID msg=audit(1740762412.289:3718): opid=2015430 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="qemu-system-x86" type=SYSCALL msg=audit(1740762412.289:3718): arch=c000003e syscall=62 success=yes exit=0 a0=1ec0c6 a1=9 a2=555d37429b40 a3=555d372250d9 items=0 ppid=1 pid=2015298 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) ses=4294967295 comm="python3" exe="/usr/bin/python3.10" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:06:54 2025 type=PROCTITLE msg=audit(1740762414.629:3719): proctitle=2F7372762F706F6B796275696C642F6275696C64626F742D76656E762F62696E2F707974686F6E33002F7372762F706F6B796275696C642F796F63746F2D776F726B65722F6F652D73656C66746573742D7562756E74752F6275696C642F62697462616B652F62696E2F62697462616B652D776F726B65720064656361666261 type=SYSCALL msg=audit(1740762414.629:3719): arch=c000003e syscall=62 success=no exit=-3 a0=1eb7ab a1=0 a2=0 a3=7fb920a16f60 items=0 ppid=2013089 pid=2025693 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) ses=4294967295 comm=576F726B6572202846616B65726F6F exe="/usr/bin/python3.10" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:06:54 2025 type=PROCTITLE msg=audit(1740762414.637:3720): proctitle="/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/build-st-552454/tmp/sysroots-components/x86_64/pseudo-native/usr/bin/pseudo" type=OBJ_PID msg=audit(1740762414.637:3720): opid=2025694 oauid=-1 ouid=6000 oses=-1 obj=unconfined ocomm="pseudo" type=SYSCALL msg=audit(1740762414.637:3720): arch=c000003e syscall=62 success=yes exit=0 a0=1ee8de a1=a a2=30 a3=5 items=0 ppid=2025694 pid=2025695 auid=4294967295 uid=6000 gid=6000 euid=6000 suid=6000 fsuid=6000 egid=6000 sgid=6000 fsgid=6000 tty=(none) ses=4294967295 comm="pseudo" exe="/srv/pokybuild/yocto-worker/oe-selftest-ubuntu/build/build-st-552454/tmp/sysroots-components/x86_64/pseudo-native/usr/bin/pseudo" subj=unconfined key="teste_kill" ---- time->Fri Feb 28 17:07:04 2025 type=PROCTITLE msg=audit(1740762424.881:3721): proctitle=2F62696E2F7368002F7573722F6C69622F706F73746669782F7362696E2F706F73746669782D7363726970740072656C6F6164 type=OBJ_PID msg=audit(1740762424.881:3721): opid=3906 oauid=-1 ouid=0 oses=-1 obj=unconfined ocomm="master" type=SYSCALL msg=audit(1740762424.881:3721): arch=c000003e syscall=62 success=yes exit=0 a0=f42 a1=1 a2=55c9d7d39359 a3=7f39e9829ac0 items=0 ppid=2028253 pid=2028290 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="postfix-script" exe="/usr/bin/dash" subj=unconfined key="teste_kill" New bitbake cookerdaemon log: 2081331 17:07:44.744732 --- Starting bitbake server pid 2081331 at 2025-02-28 17:07:44.744716 ---
After a lot of debugging, mostly with print statements to narrow down where the hang happens, I've tracked it to the: bb.event.fire(bb.event.CacheLoadProgress(current_progress, cachesize), databuilder.data) call in cache.py in MulticonfigCache:progress() Commenting that line out seems to let the builds pass. Why? No idea. There are hung bitbake server processes left behind, they're hanging in: File "/usr/lib/python3.10/threading.py", line 1567, in _shutdown lock.acquire() so some thread is trying to exit but the idle loop is still active and running on another thread.
oe-selftest-ubuntu ubuntu2204-vk-1 master completed at 2025-03-02T02:37:23Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/1087/steps/14/logs/stdio oe-selftest-ubuntu ubuntu2204-vk-1 master completed at 2025-03-03T02:55:17Z https://autobuilder.yoctoproject.org/valkyrie/#/builders/54/builds/1102/steps/14/logs/stdio
https://git.yoctoproject.org/poky/commit/?id=054875b222c3f93a3dec6d99ddc09d918774af7b