14000 2020-08-10 10:10:52 +0000 bitbake lockfile race? 2020-08-25 10:34:52 +0000 1 1 7 Build System, Metadata & Runtime OE-Core core 3.2 x86 Multiple RESOLVED FIXED AB-INT Medium+ normal 3.2 M3 1 richard.purdie richard.purdie dl9pf meta.mr.watcher meta.watcher randy.macleod --- --- No (bug/feature does not impact docs) oldest_to_newest 87904 0 richard.purdie 2020-08-10 10:10:52 +0000 https://autobuilder.yoctoproject.org/typhoon/#/builders/79/builds/1231 2020-08-10 00:14:07,284 - oe-selftest - INFO - setUpClass (kerneldevelopment.KernelDev) [ (subunit.RemotedTestCase) 2020-08-10 00:14:07,574 - oe-selftest - INFO - ... ERROR 2020-08-10 00:14:07,575 - 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/case.py", line 39, in _oeSetUpClass clss.setUpClassMethod() File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/meta/lib/oeqa/selftest/cases/kerneldevelopment.py", line 13, in setUpClass runCmd('bitbake-layers create-layer %s' % cls.layername) File "/home/pokybuild/yocto-worker/oe-selftest-centos/build/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-layers create-layer meta-kerneltest' returned non-zero exit status 1: NOTE: Starting bitbake server... 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/pokybuild/yocto-worker/oe-selftest-centos/build/build-st-47193/bitbake-cookerdaemon.log): --- Starting bitbake server pid 11244 at 2020-08-10 00:12:24.643081 --- 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/pokybuild/yocto-worker/oe-selftest-centos/build/build-st-47193/bitbake-cookerdaemon.log): --- Starting bitbake server pid 11244 at 2020-08-10 00:12:24.643081 --- 2020-08-10 00:14:07,575 - oe-selftest - INFO - oelib.types.TestList.test_list_nosep (subunit.RemotedTestCase) 2020-08-10 00:14:07,576 - oe-selftest - INFO - ... ok 87905 1 richard.purdie 2020-08-10 10:12:03 +0000 Looking at the cookerdaemon log on the failed build it simply has: Running command ['dataStoreConnectorCmd', 0, 'getVar', ('BBLAYERS',), {}] Running command ['dataStoreConnectorVarHistCmd', 0, 'get_variable_items_files', ('BBFILE_COLLECTIONS',), {}] Running command ['clientComplete'] Processing Client Disconnecting Client No timeout, exiting. Exiting --- Starting bitbake server pid 11244 at 2020-08-10 00:12:24.643081 --- --- Starting bitbake server pid 10922 at 2020-08-10 00:14:27.195928 --- Started bitbake server pid 10922 DEBUG: BBCooker starting 1597018467.1970763 DEBUG: BBCooker pyinotify1 1597018467.2043903 DEBUG: BBCooker pyinotify2 1597018467.2048688 DEBUG: BBCooker pyinotify3 1597018467.2095203 87919 2 richard.purdie 2020-08-12 15:09:52 +0000 I was thinking this had to be a lockfile race since there is no real way we should get two "Starting bitbake server" lines line that together unless two servers were racing. I can't see any race in the code. A second theory is the error message is being written but isn't flushed to disk. I'll send a patch to flush the log data to disk more carefully just in case that then adds an error message to the logs and makes what is happening clearer. This was on centos7-ty-1, our infamous race machine. 87921 3 richard.purdie 2020-08-13 02:14:48 +0000 http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=2976f43c22ed2615c2efe63e4b6676639eab5428 was added to potentially help logging 87980 4 dl9pf 2020-08-19 04:56:23 +0000 As a data-point, while duing multiple builds we ended up with this: root@Debian-95-stretch-64-minimal ~ # ps aux | grep -v root | grep python | grep bitbake jansimon 9467 0.0 0.0 155220 28756 pts/17 Tl 13:28 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -c configure virtual/kernel jansimon 16909 0.0 0.4 527168 324300 ? S 09:49 0:06 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhouse jansimon 16910 0.0 0.0 93564 34840 ? S 09:49 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhouse jansimon 16931 0.0 0.0 155480 28648 pts/8 Tl Aug18 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -e jansimon 16938 0.0 0.2 223648 165636 ? S Aug18 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -e jansimon 16939 0.0 0.0 122056 62472 ? S Aug18 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -e jansimon 16945 0.0 0.0 228964 28568 pts/8 Tl Aug18 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -e jansimon 17255 0.0 0.1 249920 125140 ? Sl 09:50 0:03 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake-worker decafbad jansimon 18639 0.0 0.5 534804 334724 ? S Aug06 0:18 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake r jansimon 18640 0.0 0.0 110560 50780 ? S Aug06 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake r jansimon 24683 0.0 0.0 155248 28592 pts/7 Tl Jul22 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhousse jansimon 24690 0.0 0.0 110056 52472 ? S Jul22 0:01 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhousse jansimon 24691 0.0 0.0 105664 45604 ? S Jul22 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhousse jansimon 24693 0.0 0.0 228984 28508 pts/7 Tl Jul22 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhouse jansimon 26274 0.0 0.5 544656 353792 ? S 06:53 0:06 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhouse jansimon 26275 0.0 0.0 123212 63240 ? S 06:53 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake jailhouse jansimon 26593 0.0 0.2 268244 143724 ? Sl 06:54 0:03 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake-worker decafbad jansimon 29700 0.0 0.0 162240 29372 pts/17 Tl 13:27 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -c configure virtual/kernel jansimon 29707 0.8 0.5 553668 347496 ? Sl 13:27 0:09 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -c configure virtual/kernel jansimon 29708 0.0 0.0 109996 50496 ? S 13:27 0:00 python3 /home/jansimon/AGL/external/poky/bitbake/bin/bitbake -c configure virtual/kernel root@Debian-95-stretch-64-minimal ~ # lsof | grep jansimon | grep -v /lib/ | grep /home | grep lock Cooker 16909 jansimon 3u REG 9,2 6 2778696 /home/jansimon/AGL/build-qemux86-64-jailhouse-4/bitbake.lock (deleted) python3 16910 jansimon 3u REG 9,2 6 2778696 /home/jansimon/AGL/build-qemux86-64-jailhouse-4/bitbake.lock (deleted) Cooker 16938 jansimon 3u REG 9,2 6 1978659 /home/jansimon/AGL/build-qemux86-64-jailhouse-2/bitbake.lock (deleted) python3 16939 jansimon 3u REG 9,2 6 1978659 /home/jansimon/AGL/build-qemux86-64-jailhouse-2/bitbake.lock (deleted) Cooker 18639 jansimon 3u REG 9,2 6 13638476 /home/jansimon/AGL/build-qemux86-64-jailhouse/bitbake.lock (deleted) python3 18640 jansimon 3u REG 9,2 6 13638476 /home/jansimon/AGL/build-qemux86-64-jailhouse/bitbake.lock (deleted) Cooker 24690 jansimon 3u REG 9,2 6 13648607 /home/jansimon/AGL/build-qemux86-64-jailhouse/bitbake.lock (deleted) python3 24691 jansimon 3u REG 9,2 6 13648607 /home/jansimon/AGL/build-qemux86-64-jailhouse/bitbake.lock (deleted) Cooker 26274 jansimon 3u REG 9,2 6 1978663 /home/jansimon/AGL/build-qemux86-64-jailhouse-2/bitbake.lock (deleted) python3 26275 jansimon 3u REG 9,2 6 1978663 /home/jansimon/AGL/build-qemux86-64-jailhouse-2/bitbake.lock (deleted) Cooker 29707 jansimon 3u REG 9,2 6 2787782 /home/jansimon/AGL/build-qemux86-64-jailhouse-4/bitbake.lock (deleted) Cooker 29707 29954 Cooker jansimon 3u REG 9,2 6 2787782 /home/jansimon/AGL/build-qemux86-64-jailhouse-4/bitbake.lock (deleted) python3 29708 jansimon 3u REG 9,2 6 2787782 /home/jansimon/AGL/build-qemux86-64-jailhouse-4/bitbake.lock (deleted) Partially these are due to hitting CTRL-C . But some are just normal invocations. 88028 5 richard.purdie 2020-08-25 10:34:52 +0000 We had an autobuilder with two locked up processes. One was waiting on the bb.utils.lock() call in flock() in the "with bb.utils.timeout(3)" code in process.py. The other process was a different server which had hung upon init somewhere. It was very unclear which resource the original hung process had which was stopping the second one from proceeding. The trace for the second did show it as being in libpthreads around pthread_cancel(). The logfile shows the first server process had passed "Exiting"m the second had never printed anything beyond the header. I'm concluding that python doesn't support splitting a python process into two different python processes as its internal state appears to get corrupted and the atexit and Finalize handlers don't work properly. As such the plan is to move the server code to include an execl() call which should hopefully remove some of these issues: http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=7002d67de02206fca0782c3373e915de20a71e9e