stestr doesn't handle unittest.subTests well in its output log

[chriseclectic]

Issue description

When running unittests that make use of unittest.subTest stestr doesn't report individual subtest failure in its output log

Steps to reproduce the problem

Consider the following example case:

import unittest

class TestSubTest(unittest.TestCase):
    """Test unittest.SubTest."""

    def test_subtest(self):
        """Test subtests failure logging and messages"""
        values = ["A", "B", "C", "D"]
        success = [True, False, True, False]

        for i, value in enumerate(values):
            with self.subTest(msg=f"Subtest value {value}", i=i, value=value):
                self.assertTrue(success[i], msg=f"Fail msg for subtest {i} with value {value}")

Expected behavior

If running the job directly through unittest the following output is returned

======================================================================
FAIL: test_subtest (test.test_subtest.TestSubTest) [Subtest value B] (i=1, value='B')
Test subtests failure logging and messages
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/cjwood/git/qiskit/qiskit-experiments/test/test_subtest.py", line 26, in test_subtest
    self.assertTrue(success[i], msg=f"Fail msg for subtest {i} with value {value}")
AssertionError: False is not true : Fail msg for subtest 1 with value B

======================================================================
FAIL: test_subtest (test.test_subtest.TestSubTest) [Subtest value D] (i=3, value='D')
Test subtests failure logging and messages
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/cjwood/git/qiskit/qiskit-experiments/test/test_subtest.py", line 26, in test_subtest
    self.assertTrue(success[i], msg=f"Fail msg for subtest {i} with value {value}")
AssertionError: False is not true : Fail msg for subtest 3 with value D

----------------------------------------------------------------------
Ran 1 test in 0.000s

FAILED (failures=2)

Actual behavior

When running through stestr this is the current output which only shows the failure message of the first failing subtest, and doesn't seem to report the total number of subtest failures since it seems to terminate the test after the first subtest fails.

{0} test.test_subtest.TestSubTest.test_subtest [0.000159s] ... FAILED

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    Traceback (most recent call last):

      File "/Users/cjwood/git/qiskit/qiskit-experiments/test/test_subtest.py", line 26, in test_subtest
    self.assertTrue(success[i], msg=f"Fail msg for subtest {i} with value {value}")

      File "/Users/cjwood/anaconda3/envs/qiskit-dev/lib/python3.9/unittest/case.py", line 680, in assertTrue
    raise self.failureException(msg)

    AssertionError: False is not true : Fail msg for subtest 1 with value B


==============================
Failed 1 tests - output below:
==============================

test.test_subtest.TestSubTest.test_subtest
------------------------------------------

Captured traceback:
~~~~~~~~~~~~~~~~~~~
    Traceback (most recent call last):

      File "/Users/cjwood/git/qiskit/qiskit-experiments/test/test_subtest.py", line 26, in test_subtest
    self.assertTrue(success[i], msg=f"Fail msg for subtest {i} with value {value}")

      File "/Users/cjwood/anaconda3/envs/qiskit-dev/lib/python3.9/unittest/case.py", line 680, in assertTrue
    raise self.failureException(msg)

    AssertionError: False is not true : Fail msg for subtest 1 with value B



======
Totals
======
Ran: 1 tests in 0.0002 sec.
 - Passed: 0
 - Skipped: 0
 - Expected Fail: 0
 - Unexpected Success: 0
 - Failed: 1
Sum of execute time for each test: 0.0002 sec.

==============
Worker Balance
==============
 - Worker 0 (1 tests) => 0:00:00.000159

Specifications like the version of the project, operating system, or hardware

System information

• OS: MacOS 11.6.4
• stestr version (stestr --version): 3.2.1
• Python release (python --version): 3.9
• pip packages (pip freeze):

Additional information

In subTests unittest reports failure number as number of subtests failed, while tests run is the number of total tests. So you can have num failures > num tests. While stestr will only report the number of failures as the whole test, not individual subtests. This can make it difficult to debug multiple subtest failures as you only see the first one that failed, not a list of all failing subtests if there are more than one.

This is less important but it also seems stestr prints a redundant line in its traceback of:

 File "/Users/cjwood/anaconda3/envs/qiskit-dev/lib/python3.9/unittest/case.py", line 680, in assertTrue
    raise self.failureException(msg)

which unittest doesn't show. Over a large number of tests this could lead to unnecessarily large logs.

[chriseclectic]

To try and check if stestr runs the subtests I added a sleep statement to the above code:

with self.subTest(msg=f"Subtest value {value}", i=i, value=value):
    self.assertTrue(success[i], msg=f"Fail msg for subtest {i} with value {value}")
    time.sleep(2)

And it looks like stestr does indeed terminate the test at first subtest failure.

With unittest:

Ran 1 test in 4.008s

so it is calling the sleep command twice for both subtest blocks where the subtests pass

For stestr:

Ran: 1 tests in 2.0013 sec.

So its only calling sleep for the first passing subtest and terminating after the first failure, so the remaining two subtest cases appear to never be run.