Bug 11746 - oe-selftest: capture self.logger output messages in parallel test case with -j
Summary: oe-selftest: capture self.logger output messages in parallel test case with -j
Status: NEW
Alias: None
Product: Runtime Testing
Classification: QA/Testing
Component: general (show other bugs)
Version: unspecified
Hardware: x86 Multiple
: Medium enhancement
Target Milestone: 6.99
Assignee: Unassigned
QA Contact:
URL:
Whiteboard:
Depends on:
Blocks:
 
Reported: 2017-07-03 06:50 UTC by Patrick Ohly
Modified: 2026-08-06 15:26 UTC (History)
6 users (show)

See Also:
OS type for building Yocto: ---
Type of Regression: ---
Verified:
Documentation change: No (bug/feature does not impact docs)

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Patrick Ohly 2017-07-03 06:50:48 UTC 
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
Comment 1 Joshua Lock 2017-12-07 15:15:08 UTC 
This may have been implemented already in recent logger changes from Richard. Need to test and check whether the issue is resolved.
Comment 2 Richard Purdie 2021-09-10 16:26:07 UTC 
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
Comment 3 Richard Purdie 2021-09-10 16:29:35 UTC 
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?).
Comment 4 Richard Purdie 2023-09-14 15:08:48 UTC 
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.
Comment 5 Randy MacLeod 2023-10-24 14:24:55 UTC 
Bulk move from 4.99 or 0.00 to 5.99