11746 2017-07-03 06:50:48 +0000 oe-selftest: capture self.logger output messages in parallel test case with -j 2026-08-06 15:26:05 +0000 1 1 10 QA/Testing Runtime Testing general unspecified x86 Multiple NEW Medium enhancement 6.99 1 patrick.ohly unassigned joshuagloe juan.m.cruz.alcaraz leonardo.sandoval.gonzalez randy.macleod richard.purdie ross.burton --- --- No (bug/feature does not impact docs) oldest_to_newest 74703 0 patrick.ohly 2017-07-03 06:50:48 +0000 Currently output can be produced by a test in several ways: - bb.note/debug/... - self.logger.info/debug/warn/... - print() Using bb is not recommended (not always available?). self.logger has the advantage of providing structured output with time stamps and was recommended by alimon as the mechanism one should use. However, messages printed that way do not end up in the <system-out> node of the XML file produces by unittest-xml-reporting (tested on Debian with unittest-xml-reporting installed via "sudo pip3 install"). print() output gets captured in the XML, but does not get printed on the console while the test runs, which defeats the purpose of informing the user about test execution (in particular in long-running tests). So self.logger looks like the best choice, but it needs to be enhanced so that the output also gets captured. See https://stackoverflow.com/questions/7472863/pydev-unittesting-how-to-capture-text-logged-to-a-logging-logger-in-captured-o 78584 1 joshuagloe 2017-12-07 15:15:08 +0000 This may have been implemented already in recent logger changes from Richard. Need to test and check whether the issue is resolved. 91385 2 richard.purdie 2021-09-10 16:26:07 +0000 The differences are perhaps best shown with: class TestLogging(OESelftestTestCase): def test_logoutput_success(self): self.logger.debug("Test debug message") self.logger.info("Test info message") self.logger.warn("Test warn message") print("Stdout message") def atest_logoutput_fail(self): self.logger.debug("Test debug message") self.logger.info("Test info message") self.logger.warn("Test warn message") print("Stdout message") self.assertTrue(False) $ oe-selftest -r bblogging.TestLogging.test_logoutput_success 2021-09-10 16:33:08,711 - oe-selftest - INFO - Adding layer libraries: 2021-09-10 16:33:08,711 - oe-selftest - INFO - /media/build1/poky/meta-poky/lib 2021-09-10 16:33:08,712 - oe-selftest - INFO - /media/build1/poky/meta/lib 2021-09-10 16:33:08,712 - oe-selftest - INFO - /media/build1/poky/meta-yocto-bsp/lib 2021-09-10 16:33:08,712 - oe-selftest - INFO - /media/build1/poky/meta-selftest/lib 2021-09-10 16:33:08,713 - oe-selftest - INFO - Running bitbake -e to test the configuration is valid/parsable 2021-09-10 16:33:12,719 - oe-selftest - INFO - Adding: "include selftest.inc" in /media/build1/poky/build-st/conf/local.conf 2021-09-10 16:33:12,720 - oe-selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf 2021-09-10 16:33:12,720 - oe-selftest - INFO - test_logoutput_success (bblogging.TestLogging) 2021-09-10 16:33:12,729 - oe-selftest - INFO - Test info message 2021-09-10 16:33:12,730 - oe-selftest - WARNING - Test warn message 2021-09-10 16:33:12,730 - oe-selftest - INFO - ... ok 2021-09-10 16:33:12,912 - oe-selftest - INFO - ---------------------------------------------------------------------- 2021-09-10 16:33:12,913 - oe-selftest - INFO - Ran 1 test in 2.332s 2021-09-10 16:33:12,913 - oe-selftest - INFO - OK 2021-09-10 16:33:15,626 - oe-selftest - INFO - RESULTS: 2021-09-10 16:33:15,626 - oe-selftest - INFO - RESULTS - bblogging.TestLogging.test_logoutput_success: PASSED (0.01s) 2021-09-10 16:33:15,929 - oe-selftest - INFO - SUMMARY: 2021-09-10 16:33:15,929 - oe-selftest - INFO - oe-selftest () - Ran 1 test in 2.334s 2021-09-10 16:33:15,930 - oe-selftest - INFO - oe-selftest - OK - All required tests passed (successes=1, skipped=0, failures=0, errors=0) $ oe-selftest -r bblogging.TestLogging.test_logoutput_success -j 1 2021-09-10 16:44:10,307 - oe-selftest - INFO - Adding layer libraries: 2021-09-10 16:44:10,307 - oe-selftest - INFO - /media/build1/poky/meta-poky/lib 2021-09-10 16:44:10,308 - oe-selftest - INFO - /media/build1/poky/meta/lib 2021-09-10 16:44:10,308 - oe-selftest - INFO - /media/build1/poky/meta-yocto-bsp/lib 2021-09-10 16:44:10,308 - oe-selftest - INFO - /media/build1/poky/meta-selftest/lib 2021-09-10 16:44:10,309 - oe-selftest - INFO - Running bitbake -e to test the configuration is valid/parsable 2021-09-10 16:44:14,580 - oe-selftest - INFO - bblogging.TestLogging.test_logoutput_success (subunit.RemotedTestCase) 2021-09-10 16:44:14,580 - oe-selftest - INFO - ... ok 2021-09-10 16:44:14,581 - oe-selftest - INFO - 0: 1/1 1/1 (0.01s) (bblogging.TestLogging.test_logoutput_success) 2021-09-10 16:44:14,780 - oe-selftest - INFO - ---------------------------------------------------------------------- 2021-09-10 16:44:14,780 - oe-selftest - INFO - Ran 1 test in 2.381s 2021-09-10 16:44:14,780 - oe-selftest - INFO - OK 2021-09-10 16:44:17,649 - oe-selftest - INFO - RESULTS: 2021-09-10 16:44:17,650 - oe-selftest - INFO - RESULTS - bblogging.TestLogging.test_logoutput_success: PASSED (0.01s) 2021-09-10 16:44:17,954 - oe-selftest - INFO - SUMMARY: 2021-09-10 16:44:17,954 - oe-selftest - INFO - oe-selftest () - Ran 1 test in 2.585s 2021-09-10 16:44:17,954 - oe-selftest - INFO - oe-selftest - OK - All required tests passed (successes=1, skipped=0, failures=0, errors=0) so in the success case, the logger output is "lost". In the failure case: $ oe-selftest -r bblogging.TestLogging.test_logoutput_fail 2021-09-10 17:20:47,622 - oe-selftest - INFO - Adding layer libraries: 2021-09-10 17:20:47,623 - oe-selftest - INFO - /media/build1/poky/meta-poky/lib 2021-09-10 17:20:47,623 - oe-selftest - INFO - /media/build1/poky/meta/lib 2021-09-10 17:20:47,623 - oe-selftest - INFO - /media/build1/poky/meta-yocto-bsp/lib 2021-09-10 17:20:47,623 - oe-selftest - INFO - /media/build1/poky/meta-selftest/lib 2021-09-10 17:20:47,626 - oe-selftest - INFO - Running bitbake -e to test the configuration is valid/parsable 2021-09-10 17:20:51,857 - oe-selftest - INFO - Adding: "include selftest.inc" in /media/build1/poky/build-st/conf/local.conf 2021-09-10 17:20:51,858 - oe-selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf 2021-09-10 17:20:51,858 - oe-selftest - INFO - test_logoutput_fail (bblogging.TestLogging) 2021-09-10 17:20:51,868 - oe-selftest - INFO - Test info message 2021-09-10 17:20:51,868 - oe-selftest - WARNING - Test warn message 2021-09-10 17:20:51,869 - oe-selftest - INFO - ... FAIL Stdout: Stdout message 2021-09-10 17:20:51,869 - oe-selftest - INFO - Traceback (most recent call last): File "/media/build1/poky/meta/lib/oeqa/selftest/cases/bblogging.py", line 118, in test_logoutput_fail self.assertTrue(False) AssertionError: False is not true Stdout: Stdout message 2021-09-10 17:20:51,869 - oe-selftest - INFO - ====================================================================== 2021-09-10 17:20:51,869 - oe-selftest - INFO - FAIL: test_logoutput_fail (bblogging.TestLogging) 2021-09-10 17:20:51,870 - oe-selftest - INFO - ---------------------------------------------------------------------- 2021-09-10 17:20:51,870 - oe-selftest - INFO - Traceback (most recent call last): File "/media/build1/poky/meta/lib/oeqa/selftest/cases/bblogging.py", line 118, in test_logoutput_fail self.assertTrue(False) AssertionError: False is not true Stdout: Stdout message 2021-09-10 17:20:51,870 - oe-selftest - INFO - ---------------------------------------------------------------------- 2021-09-10 17:20:51,870 - oe-selftest - INFO - Ran 1 test in 2.299s 2021-09-10 17:20:51,870 - oe-selftest - INFO - FAILED 2021-09-10 17:20:51,870 - oe-selftest - INFO - (failures=1) 2021-09-10 17:20:55,026 - oe-selftest - INFO - RESULTS: 2021-09-10 17:20:55,026 - oe-selftest - INFO - RESULTS - bblogging.TestLogging.test_logoutput_fail: FAILED (0.01s) 2021-09-10 17:20:55,334 - oe-selftest - INFO - SUMMARY: 2021-09-10 17:20:55,334 - oe-selftest - INFO - oe-selftest () - Ran 1 test in 2.300s 2021-09-10 17:20:55,334 - oe-selftest - INFO - oe-selftest - FAIL - Required tests failed (successes=0, skipped=0, failures=1, errors=0) oe-selftest -r bblogging.TestLogging.test_logoutput_fail -j 1 2021-09-10 17:21:47,089 - oe-selftest - INFO - Adding layer libraries: 2021-09-10 17:21:47,089 - oe-selftest - INFO - /media/build1/poky/meta-poky/lib 2021-09-10 17:21:47,089 - oe-selftest - INFO - /media/build1/poky/meta/lib 2021-09-10 17:21:47,089 - oe-selftest - INFO - /media/build1/poky/meta-yocto-bsp/lib 2021-09-10 17:21:47,090 - oe-selftest - INFO - /media/build1/poky/meta-selftest/lib 2021-09-10 17:21:47,091 - oe-selftest - INFO - Running bitbake -e to test the configuration is valid/parsable 2021-09-10 17:21:51,488 - oe-selftest - INFO - bblogging.TestLogging.test_logoutput_fail (subunit.RemotedTestCase) 2021-09-10 17:21:51,489 - oe-selftest - INFO - ... FAIL Stderr: 2021-09-10 17:21:51,479 - oe-selftest - INFO - Adding: "include selftest.inc" in /media/build1/poky/build-st-53338/conf/local.conf 2021-09-10 17:21:51,480 - oe-selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf 2021-09-10 17:21:51,486 - oe-selftest - INFO - Test info message 2021-09-10 17:21:51,486 - oe-selftest - WARNING - Test warn message Stdout message 2021-09-10 17:21:51,489 - oe-selftest - INFO - 0: 1/1 1/1 (0.01s) (bblogging.TestLogging.test_logoutput_fail) 2021-09-10 17:21:51,490 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last): File "/media/build1/poky/meta/lib/oeqa/selftest/cases/bblogging.py", line 118, in test_logoutput_fail self.assertTrue(False) File "/usr/lib/python3.8/unittest/case.py", line 765, in assertTrue raise self.failureException(msg) AssertionError: False is not true Stderr: 2021-09-10 17:21:51,479 - oe-selftest - INFO - Adding: "include selftest.inc" in /media/build1/poky/build-st-53338/conf/local.conf 2021-09-10 17:21:51,480 - oe-selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf 2021-09-10 17:21:51,486 - oe-selftest - INFO - Test info message 2021-09-10 17:21:51,486 - oe-selftest - WARNING - Test warn message Stdout message 2021-09-10 17:21:51,490 - oe-selftest - INFO - ====================================================================== 2021-09-10 17:21:51,490 - oe-selftest - INFO - FAIL: bblogging.TestLogging.test_logoutput_fail (subunit.RemotedTestCase) 2021-09-10 17:21:51,491 - oe-selftest - INFO - ---------------------------------------------------------------------- 2021-09-10 17:21:51,491 - oe-selftest - INFO - testtools.testresult.real._StringException: Traceback (most recent call last): File "/media/build1/poky/meta/lib/oeqa/selftest/cases/bblogging.py", line 118, in test_logoutput_fail self.assertTrue(False) File "/usr/lib/python3.8/unittest/case.py", line 765, in assertTrue raise self.failureException(msg) AssertionError: False is not true Stderr: 2021-09-10 17:21:51,479 - oe-selftest - INFO - Adding: "include selftest.inc" in /media/build1/poky/build-st-53338/conf/local.conf 2021-09-10 17:21:51,480 - oe-selftest - INFO - Adding: "include bblayers.inc" in bblayers.conf 2021-09-10 17:21:51,486 - oe-selftest - INFO - Test info message 2021-09-10 17:21:51,486 - oe-selftest - WARNING - Test warn message Stdout message 2021-09-10 17:21:51,491 - oe-selftest - INFO - ---------------------------------------------------------------------- 2021-09-10 17:21:51,491 - oe-selftest - INFO - Ran 1 test in 2.193s 2021-09-10 17:21:51,491 - oe-selftest - INFO - FAILED 2021-09-10 17:21:51,491 - oe-selftest - INFO - (failures=1) 2021-09-10 17:21:54,960 - oe-selftest - INFO - RESULTS: 2021-09-10 17:21:54,961 - oe-selftest - INFO - RESULTS - bblogging.TestLogging.test_logoutput_fail: FAILED (0.01s) 2021-09-10 17:21:55,263 - oe-selftest - INFO - SUMMARY: 2021-09-10 17:21:55,264 - oe-selftest - INFO - oe-selftest () - Ran 1 test in 2.407s 2021-09-10 17:21:55,264 - oe-selftest - INFO - oe-selftest - FAIL - Required tests failed (successes=0, skipped=0, failures=1, errors=0) In the failure case we do see all the right info for the failure case. The issue is that subunit pipes stdout+stderr+logger over the same stream and we can't tell which is which to display the right pieces. We can't see messages "live" as the multithreading would mix up the test output ways which would be too confusing 91386 3 richard.purdie 2021-09-10 16:29:35 +0000 So in summary, I believe we do have all the right logs in the failure case. In the success case, stdout, stderr and logger are all intermixed into the same stream so the main process can't tease them back apart. We therefore can't display things in the same way as non-parallel testing. Code in question is: # Collect stdout/stderr into an io buffer output = io.BytesIO() testserver = ProtocolTestCase(stream, passthrough=output) in concurrencytest. To fix this we'd need to encode the logger, stdout and stderr into different streams for separate processing. Not sure how feasible that is (or how important?). 96414 4 richard.purdie 2023-09-14 15:08:48 +0000 The output is there on the autobuilder now but it is very confusing as it contains all the output from all the tests, not just the one that failed. There is therefore something likely still need of improvement but the error logs are there. 96978 5 randy.macleod 2023-10-24 14:24:55 +0000 Bulk move from 4.99 or 0.00 to 5.99