13993 2020-07-29 05:57:00 +0000 tinfoil error handling during server startup suboptimal 2020-10-26 08:26:08 +0000 1 1 7 Build System, Metadata & Runtime BitBake bitbake 3.2 x86 Multiple RESOLVED FIXED AB-INT Medium+ normal 3.3 M1 1 richard.purdie stacy.gaikovaia bluelightning poky.bs.watcher poky.watcher randy.macleod --- --- No (bug/feature does not impact docs) oldest_to_newest 87849 0 richard.purdie 2020-07-29 05:57:00 +0000 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 88435 1 4740 richard.purdie 2020-10-20 06:21:57 +0000 Created attachment 4740 A simple test script showing how you can use the tinfoil API from a script 88436 2 richard.purdie 2020-10-20 06:23:51 +0000 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 88449 3 stacy.gaikovaia 2020-10-21 12:24:11 +0000 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. 88450 4 4741 stacy.gaikovaia 2020-10-21 12:25:37 +0000 Created attachment 4741 This is a reproducer patch This is my reproducer patch, relevant to comment #3. 88486 5 stacy.gaikovaia 2020-10-26 08:26:08 +0000 Resolved as of https://git.openembedded.org/bitbake/commit/?h=master-next&id=a2fa7683655a7d39728f831eeb28cec40088a1bd. 4740 2020-10-20 06:21:57 +0000 2020-10-20 06:21:57 +0000 A simple test script showing how you can use the tinfoil API from a script tinfoil-test.py text/x-python 1036 richard.purdie IyEvdXNyL2Jpbi9lbnYgcHl0aG9uMwoKaW1wb3J0IHN5cwppbXBvcnQgb3MKaW1wb3J0IGFyZ3Bh cnNlCmltcG9ydCBnbG9iCmltcG9ydCByZQppbXBvcnQgY29uZmlncGFyc2VyCmltcG9ydCBzdWJw cm9jZXNzCmltcG9ydCBsb2dnaW5nCgpiYXNlcGF0aCA9ICcnCndvcmtzcGFjZSA9IHt9CmNvbmZp ZyA9IE5vbmUKY29udGV4dCA9IE5vbmUKCgpiYXNlcGF0aCA9IG9zLnBhdGguYWJzcGF0aChvcy5w YXRoLmRpcm5hbWUoX19maWxlX18pICsgJy8uLi8uLicpCmJpdGJha2VwYXRoID0gTm9uZQppZiBv cy5wYXRoLmV4aXN0cyhiYXNlcGF0aCArICcvYml0YmFrZS9saWIvYmInKToKICAgIGJpdGJha2Vw YXRoID0gYmFzZXBhdGggKyAnL2JpdGJha2UnCmVsc2U6CiAgICAjIGxvb2sgZm9yIGJpdGJha2Uv YmluIGRpciBpbiBQQVRICiAgICBmb3IgcHRoIGluIG9zLmVudmlyb25bJ1BBVEgnXS5zcGxpdCgn OicpOgogICAgICAgIGlmIG9zLnBhdGguZXhpc3RzKG9zLnBhdGguam9pbihwdGgsICcuLi9saWIv YmInKSk6CiAgICAgICAgICAgIGJpdGJha2VwYXRoID0gb3MucGF0aC5hYnNwYXRoKG9zLnBhdGgu am9pbihwdGgsICcuLicpKQogICAgICAgICAgICBicmVhawoKaWYgYml0YmFrZXBhdGg6CiAgICBz eXMucGF0aC5pbnNlcnQoMCwgYml0YmFrZXBhdGggKyAnL2xpYicpCgoKCmltcG9ydCBiYi50aW5m b2lsCgp3aXRoIGJiLnRpbmZvaWwuVGluZm9pbCgpIGFzIHRpbmZvaWw6CiAgICAgICAgdGluZm9p bC5wcmVwYXJlKGNvbmZpZ19vbmx5PUZhbHNlLCBxdWlldD0yKQogICAgICAgIHRlc3RyZWNpcGUg PSAnbWRhZG0nCiAgICAgICAgYmVzdCA9IHRpbmZvaWwuZmluZF9iZXN0X3Byb3ZpZGVyKHRlc3Ry ZWNpcGUpCiAgICAgICAgaWYgbm90IGJlc3Q6CiAgICAgICAgICAgIHNlbGYuZmFpbCgnVW5hYmxl IHRvIGZpbmQgcmVjaXBlIHByb3ZpZGluZyAlcycgJSB0ZXN0cmVjaXBlKQogICAgICAgIHJkID0g dGluZm9pbC5wYXJzZV9yZWNpcGVfZmlsZShiZXN0WzNdKQogICAgICAgIHByaW50KHJkLmdldFZh cignUE4nKSkKCg== 4741 2020-10-21 12:25:37 +0000 2020-10-21 12:25:37 +0000 This is a reproducer patch reproducer.patch text/plain 1744 stacy.gaikovaia ZGlmZiAtLWdpdCBhL2JpdGJha2UvbGliL2JiL3NlcnZlci9wcm9jZXNzLnB5IGIvYml0YmFrZS9s aWIvYmIvc2VydmVyL3Byb2Nlc3MucHkKaW5kZXggYjI3YjRhZWZlMC4uOTdmODFjNDU4ZiAxMDA2 NDQKLS0tIGEvYml0YmFrZS9saWIvYmIvc2VydmVyL3Byb2Nlc3MucHkKKysrIGIvYml0YmFrZS9s aWIvYmIvc2VydmVyL3Byb2Nlc3MucHkKQEAgLTI5LDYgKzI5LDcgQEAgaW1wb3J0IHBpY2tsZQog aW1wb3J0IGJiLnNlcnZlci54bWxycGNzZXJ2ZXIKIGZyb20gYmIgaW1wb3J0IGRhZW1vbml6ZQog ZnJvbSBtdWx0aXByb2Nlc3NpbmcgaW1wb3J0IHF1ZXVlcworZnJvbSBpdGVydG9vbHMgaW1wb3J0 IGNvdW50CiAKIGxvZ2dlciA9IGxvZ2dpbmcuZ2V0TG9nZ2VyKCdCaXRCYWtlJykKIApAQCAtNDM4 LDkgKzQzOSwxMSBAQCBzdGFydF9sb2dfZm9ybWF0ID0gJy0tLSBTdGFydGluZyBiaXRiYWtlIHNl cnZlciBwaWQgJXMgYXQgJXMgLS0tJwogc3RhcnRfbG9nX2RhdGV0aW1lX2Zvcm1hdCA9ICclWS0l bS0lZCAlSDolTTolUy4lZicKIAogY2xhc3MgQml0QmFrZVNlcnZlcihvYmplY3QpOgorICAgIF9p ZHMgPSBjb3VudCgwKQogCiAgICAgZGVmIF9faW5pdF9fKHNlbGYsIGxvY2ssIHNvY2tuYW1lLCBm ZWF0dXJlc2V0LCBzZXJ2ZXJfdGltZW91dCwgeG1scnBjaW50ZXJmYWNlKToKLQorICAgICAgICBz ZWxmLmlkcyA9IG5leHQoc2VsZi5faWRzKQorICAgICAgICBzZXJ2ZXJsb2cocmVwcihzZWxmLl9p ZHMpKQogICAgICAgICBzZWxmLnNlcnZlcl90aW1lb3V0ID0gc2VydmVyX3RpbWVvdXQKICAgICAg ICAgc2VsZi54bWxycGNpbnRlcmZhY2UgPSB4bWxycGNpbnRlcmZhY2UKICAgICAgICAgc2VsZi5m ZWF0dXJlc2V0ID0gZmVhdHVyZXNldApAQCAtNDYwLDggKzQ2MywxMiBAQCBjbGFzcyBCaXRCYWtl U2VydmVyKG9iamVjdCk6CiAgICAgICAgIHJlYWR5ID0gQ29ubmVjdGlvblJlYWRlcihzZWxmLnJl YWR5cGlwZSkKICAgICAgICAgciA9IHJlYWR5LnBvbGwoNSkKICAgICAgICAgaWYgbm90IHI6Cisg ICAgICAgICAgICBwcmludChzdHIoc2VsZi5faWRzKSkKICAgICAgICAgICAgIGJiLm5vdGUoIkJp dGJha2Ugc2VydmVyIGRpZG4ndCBzdGFydCB3aXRoaW4gNSBzZWNvbmRzLCB3YWl0aW5nIGZvciA5 MCIpCi0gICAgICAgICAgICByID0gcmVhZHkucG9sbCg5MCkKKyAgICAgICAgICAgIGlmIChzdHIo c2VsZi5faWRzKSA9PSAiY291bnQoMSkiKToKKyAgICAgICAgICAgICAgICByID0gcmVhZHkucG9s bCgyMCkKKyAgICAgICAgICAgIGVsc2U6CisgICAgICAgICAgICAgICAgcHJpbnQoIkhlbGxvLCBJ J20gYnJva2VuIikKICAgICAgICAgaWYgcjoKICAgICAgICAgICAgIHRyeToKICAgICAgICAgICAg ICAgICByID0gcmVhZHkuZ2V0KCkKQEAgLTU0Miw2ICs1NDksNyBAQCBkZWYgZXhlY1NlcnZlcihs b2NrZmQsIHJlYWR5cGlwZWluZmQsIGxvY2tuYW1lLCBzb2NrbmFtZSwgc2VydmVyX3RpbWVvdXQs IHhtbHJwYwogICAgICAgICAgICAgY29va2VyID0gYmIuY29va2VyLkJCQ29va2VyKGZlYXR1cmVz ZXQsIHNlcnZlci5yZWdpc3Rlcl9pZGxlX2Z1bmN0aW9uKQogICAgICAgICBleGNlcHQgYmIuQkJI YW5kbGVkRXhjZXB0aW9uOgogICAgICAgICAgICAgcmV0dXJuIE5vbmUKKyAgICAgICAgdGltZS5z bGVlcCgxNSkKICAgICAgICAgd3JpdGVyLnNlbmQoInIiKQogICAgICAgICB3cml0ZXIuY2xvc2Uo KQogICAgICAgICBzZXJ2ZXIuY29va2VyID0gY29va2VyCg==