https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1192 which fails with: 2020-07-26 13:32:25,274 - oe-selftest - INFO - runtime_test.Postinst.test_postinst_rootfs_and_boot_systemd (subunit.RemotedTestCase) 2020-07-26 13:32:27,651 - oe-selftest - INFO - ... ERROR 2020-07-26 13:32:28,272 - oe-selftest - INFO - 2: 36/37 352/413 (4478.73s) (runtime_test.Postinst.test_postinst_rootfs_and_boot_systemd) 2020-07-26 13:32:28,272 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last): File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/meta/lib/oeqa/core/decorator/__init__.py", line 36, in wrapped_f return func(*args, **kwargs) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/meta/lib/oeqa/selftest/cases/runtime_test.py", line 322, in test_postinst_rootfs_and_boot_systemd self.init_manager_loop("systemd") File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/meta/lib/oeqa/selftest/cases/runtime_test.py", line 273, in init_manager_loop with runqemu('core-image-minimal') as qemu: File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/buildtools/sysroots/x86_64-pokysdk-linux/usr/lib/python3.8/contextlib.py", line 113, in __enter__ return next(self.gen) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/meta/lib/oeqa/utils/commands.py", line 316, in runqemu tinfoil.prepare(config_only=False, quiet=True) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/bitbake/lib/bb/tinfoil.py", line 393, in prepare self.server_connection, ui_module = setup_bitbake(config_params, File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/bitbake/lib/bb/main.py", line 438, in setup_bitbake server = bb.server.process.BitBakeServer(lock, sockname, configuration, featureset) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/bitbake/lib/bb/server/process.py", line 460, in __init__ raise SystemExit(1) SystemExit: 1 tinfoil should really do a better job of logging here as there was logging output but tinfoil didn't display it. Logging onto that worker, we could recover more info, the bitbake-cookerdaemon log file has: --- Starting bitbake server pid 22694 at 2020-07-26 13:30:34.930639 --- Traceback (most recent call last): File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/bitbake/lib/bb/daemonize.py", line 87, in createDaemon function() File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/bitbake/lib/bb/server/process.py", line 476, in _startServer writer.send("r") File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/bitbake/lib/bb/server/process.py", line 666, in send self.writer.send_bytes(obj) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/buildtools/sysroots/x86_64-pokysdk-linux/usr/lib/python3.8/multiprocessing/connection.py", line 200, in send_bytes self._send_bytes(m[offset:offset + size]) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/buildtools/sysroots/x86_64-pokysdk-linux/usr/lib/python3.8/multiprocessing/connection.py", line 411, in _send_bytes self._send(header + buf) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/buildtools/sysroots/x86_64-pokysdk-linux/usr/lib/python3.8/multiprocessing/connection.py", line 368, in _send n = write(self._handle, buf) BrokenPipeError: [Errno 32] Broken pipe --- Starting bitbake server pid 46703 at 2020-07-26 13:32:37.519727 --- Started bitbake server pid 46703 DEBUG: BBCooker starting 1595770357.5207798
Created attachment 4740 [details] A simple test script showing how you can use the tinfoil API from a script
My changes which attempt to reproduce this failure (UI times out in 10 seconds, server waits for 15). This shows a reasonable trace on master, we should re-test with the code from about the 29th July, see if it shows the trace shown in this bug. If so, we can consider the issue resolved by changes in master. diff --git a/bitbake/lib/bb/server/process.py b/bitbake/lib/bb/server/process.py index b27b4aefe0e..8c7b50ccaa9 100644 --- a/bitbake/lib/bb/server/process.py +++ b/bitbake/lib/bb/server/process.py @@ -461,7 +471,7 @@ class BitBakeServer(object): r = ready.poll(5) if not r: bb.note("Bitbake server didn't start within 5 seconds, waiting for 90") - r = ready.poll(90) + r = ready.poll(5) if r: try: r = ready.get() @@ -542,6 +552,7 @@ def execServer(lockfd, readypipeinfd, lockname, sockname, server_timeout, xmlrpc cooker = bb.cooker.BBCooker(featureset, server.register_idle_function) except bb.BBHandledException: return None + time.sleep(15) writer.send("r") writer.close() server.cooker = cooker
Good news, I have figured out where this bug is coming from. First thing: *just* breaking the "r" signaling that the cooker dameon does while starting up does not fully reproduce this issue. Simply making it such that the cooker dameon cannot write an "r" to the pipe in time and as a result the bitbake process thinks the cooker daemon is broken results in the following error: Running command `oe-selftest -r tinfoil.TinfoilTests.test_parse_recipe -j 1` Traceback (most recent call last): File "/home/sgaikova/src/distro/yocto/poky/scripts/oe-selftest", line 60, in <module> ret = main() File "/home/sgaikova/src/distro/yocto/poky/scripts/oe-selftest", line 47, in main results = args.func(logger, args) File "/home/sgaikova/src/distro/yocto/poky/meta/lib/oeqa/selftest/context.py", line 364, in run self._process_args(logger, args) File "/home/sgaikova/src/distro/yocto/poky/meta/lib/oeqa/selftest/context.py", line 213, in _process_args bbvars = get_bb_vars() File "/home/sgaikova/src/distro/yocto/poky/meta/lib/oeqa/utils/commands.py", line 237, in get_bb_vars bbenv = get_bb_env(target, postconfig=postconfig) File "/home/sgaikova/src/distro/yocto/poky/meta/lib/oeqa/utils/commands.py", line 233, in get_bb_env return bitbake("-e", postconfig=postconfig).output File "/home/sgaikova/src/distro/yocto/poky/meta/lib/oeqa/utils/commands.py", line 223, in bitbake return runCmd(cmd, ignore_status, timeout, output_log=output_log, **options) File "/home/sgaikova/src/distro/yocto/poky/meta/lib/oeqa/utils/commands.py", line 201, in runCmd raise AssertionError("Command '%s' returned non-zero exit status %d:\n%s" % (command, result.status, exc_output)) AssertionError: Command 'bitbake -e' returned non-zero exit status 1: NOTE: Bitbake server didn't start within 5 seconds, waiting for 90 ERROR: Unable to start bitbake server (False) ERROR: Server log for this session (/home/sgaikova/src/distro/yocto/poky/build/bitbake-cookerdaemon.log): 2262553 13:12:56.167971 --- Starting bitbake server pid 2262553 at 2020-10-21 13:12:56.167953 --- Running a single test, regardless of if it's tinfoil.TinfoilTests.test_parse_recipe or runtime_test.Postinst.test_postinst_rootfs_and_boot_systemd (listed in original post) will produce the above stack trace. Clearly this looks very different from the build failure. During test setup, the test infastructure will call 'bitbake -e' in order to get information about the environment. That is why we see the error above: the failure above occurs when the test infastructure calls 'bitbake -e' in order to get the envirionment variables necessairy to run. At first I hypothesized after test setup (ie when running the tests themselves), a test may call bitbake a second time, spawning a new bitbake object, and this was where the cooker daemon pipe closing would generate an error would result in the stack trace in the original post. Then I realized that in the specific case where only one test being run, as in the cases described so far, it will call 'bitbake -e' to initialize the test and then re-use the same bitbake object to run the test. To specifically replicate the case where tinfoil, *not the test setup infastructure*, is confused by the SystemExit(1), we need to a) run a multi-test command and 2) artificially introduce the pipe-timeout error only after the first instantiation of the BitBakeServer class. With all that being said, I will attach my reproducer patch, and say that I can produce the following stack trace: 2020-10-21 15:10:15,243 - oe-selftest - INFO - tinfoil.TinfoilTests.test_expand (subunit.RemotedTestCase) 2020-10-21 15:10:15,244 - oe-selftest - INFO - ... ERROR 2020-10-21 15:10:15,244 - oe-selftest - INFO - 0: 2/10 2/10 (5.04s) (tinfoil.TinfoilTests.test_expand) 2020-10-21 15:10:15,244 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last): File "/home/sgaikova/src/distro/yocto/poky/meta/lib/oeqa/selftest/cases/tinfoil.py", line 26, in test_expand tinfoil.prepare(True) File "/home/sgaikova/src/distro/yocto/poky/bitbake/lib/bb/tinfoil.py", line 389, in prepare self.server_connection, ui_module = setup_bitbake(config_params, extrafeatures) File "/home/sgaikova/src/distro/yocto/poky/bitbake/lib/bb/main.py", line 436, in setup_bitbake server = bb.server.process.BitBakeServer(lock, sockname, featureset, configParams.server_timeout, configParams.xmlrpcinterface) File "/home/sgaikova/src/distro/yocto/poky/bitbake/lib/bb/server/process.py", line 512, in __init__ raise SystemExit(1) SystemExit: 1 after calling the command `oe-selftest -r tinfoil.TinfoilTests -j 1`. This is much closer to the error originally reported by the autobuilder; carefully looking at the tests indicates that it is the second one in the TinfoilTests class which fails; as expected.
Created attachment 4741 [details] This is a reproducer patch This is my reproducer patch, relevant to comment #3.
Resolved as of https://git.openembedded.org/bitbake/commit/?h=master-next&id=a2fa7683655a7d39728f831eeb28cec40088a1bd.