| Summary: | tinfoil error handling during server startup suboptimal | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Build System, Metadata & Runtime] BitBake | Reporter: | Richard Purdie <richard.purdie> | ||||||
| Component: | bitbake | Assignee: | Stacy Gaikovaia <stacy.gaikovaia> | ||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||
| Severity: | normal | ||||||||
| Priority: | Medium+ | CC: | bluelightning, poky.bs.watcher, poky.watcher, randy.macleod | ||||||
| Version: | 3.2 | ||||||||
| Target Milestone: | 3.3 M1 | ||||||||
| Hardware: | x86 | ||||||||
| OS: | Multiple | ||||||||
| Whiteboard: | AB-INT | ||||||||
| OS type for building Yocto: | --- | Type of Regression: | --- | ||||||
| Verified: | Documentation change: | No (bug/feature does not impact docs) | |||||||
| Attachments: |
|
||||||||
|
Description
Richard Purdie
2020-07-29 05:57:00 UTC
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. |