python:subunit: Avoid misleading "Test was never started" error message

subunithelper.py keeps track of tests that have been started, and
displays an error message if a test reports an outcome without having
previously been started. However, it makes the assumption that a test
has finished once it has reported a single outcome. This means that a
misleading error message will be displayed if it receives multiple
outcomes from the same test (which can happen if a test using the Python
unittest framework does not complete successfully, and the cleanup
subsequently fails), and any actual errors from the cleanup remain
undisplayed.

This commit ensures that only a single outcome is reported for each
test, and only after the test has finished. Outcomes are buffered up
until the stopTest() function is called, when a single outcome is
determined and all errors received for that test are output.

FilterOps still needs to output test outcomes immediately rather than
buffering them, otherwise they are never picked up and passed on to the
remote test case by subunithelper.parse_results(). This would result in
an error as the test would be considered to have never finished.

    Example subunitrun output before the change:

time: 2021-04-28 01:28:49.862123Z
test: samba.tests.example.ExampleTests.test
time: 2021-04-28 01:28:49.862215Z
failure: samba.tests.example.ExampleTests.test [
Traceback (most recent call last):
  File "bin/python/samba/tests/example.py", line 28, in test
    self.fail()
AssertionError: None
]
time: 2021-04-28 01:28:49.862407Z
failure: samba.tests.example.ExampleTests.test [
Traceback (most recent call last):
  File "bin/python/samba/tests/example.py", line 31, in tearDown
    self.fail()
AssertionError: None
]
time: 2021-04-28 01:28:49.862467Z
time: 2021-04-28 01:28:49.862510Z

    and after:

time: 2021-04-28 01:29:19.949347Z
test: samba.tests.example.ExampleTests.test
time: 2021-04-28 01:29:19.949440Z
time: 2021-04-28 01:29:19.949590Z
time: 2021-04-28 01:29:19.949640Z
failure: samba.tests.example.ExampleTests.test [
Traceback (most recent call last):
  File "bin/python/samba/tests/example.py", line 28, in test
    self.fail()
AssertionError: None
Traceback (most recent call last):
  File "bin/python/samba/tests/example.py", line 31, in tearDown
    self.fail()
AssertionError: None
]
time: 2021-04-28 01:29:19.949702Z

Signed-off-by: Joseph Sutton <josephsutton@catalyst.net.nz>
Reviewed-by: Andreas Schneider <asn@samba.org>
Reviewed-by: Andrew Bartlett <abartlet@samba.org>

diff --git a/python/samba/subunit/run.py b/python/samba/subunit/run.py
index b9f6afe0c71f607f1e1b48649f22acbf2be66687..913c61f0d1b4322e984d37804f2e2cfd7891b716 100755 (executable)
--- a/python/samba/subunit/run.py
+++ b/python/samba/subunit/run.py
@@ -52,83 +52,28 @@ class TestProtocolClient(unittest.TestResult):
     def __init__(self, stream):
         unittest.TestResult.__init__(self)
         self._stream = stream
-        self.failed = False
+        self.successes = []
 
-    def wasSuccessful(self):
-        return not self.failed
-
-    def addError(self, test, error=None):
-        """Report an error in test test.
-
-        :param error: Standard unittest positional argument form - an
-            exc_info tuple.
-        """
-        super().addError(test, error)
-        self._addOutcome("error", test, error=self.errors[-1][1])
-        self.failed = True
-
-    def addExpectedFailure(self, test, error=None):
-        """Report an expected failure in test test.
-
-        :param error: Standard unittest positional argument form - an
-            exc_info tuple.
-        """
-        super().addExpectedFailure(test, error)
-        self._addOutcome("xfail", test, error=self.expectedFailures[-1][1])
-
-    def addFailure(self, test, error=None):
-        """Report a failure in test test.
-
-        :param error: Standard unittest positional argument form - an
-            exc_info tuple.
-        """
-        super().addFailure(test, error)
-        self._addOutcome("failure", test, error=self.failures[-1][1])
-        self.failed = True
-
-    def _addOutcome(self, outcome, test, error=None, error_permitted=True):
-        """Report a failure in test test.
+    def _addOutcome(self, outcome, test, errors=None):
+        """Report an outcome of test test.
 
         :param outcome: A string describing the outcome - used as the
             event name in the subunit stream.
-        :param error: Standard unittest positional argument form - an
-            exc_info tuple.
-        :param error_permitted: If True then error must be supplied.
-            If False then error must not be supplied.
+        :param errors: A list of strings describing the errors.
         """
         self._stream.write(("%s: " % outcome) + test.id())
-        if error_permitted:
-            if error is None:
-                raise ValueError
-        else:
-            if error is not None:
-                raise ValueError
-        if error is not None:
+        if errors:
             self._stream.write(" [\n")
-            self._stream.write(error)
-        else:
-            self._stream.write("\n")
-        if error is not None:
-            self._stream.write("]\n")
-
-    def addSkip(self, test, reason=None):
-        """Report a skipped test."""
-        if not reason:
-            self._addOutcome("skip", test, error_permitted=None)
-        else:
-            self._stream.write("skip: %s [\n" % test.id())
-            self._stream.write("%s\n" % reason)
-            self._stream.write("]\n")
+            for error in errors:
+                self._stream.write(error)
+                if not error.endswith('\n'):
+                    self._stream.write('\n')
+            self._stream.write("]")
+        self._stream.write("\n")
 
     def addSuccess(self, test):
         """Report a success in a test."""
-        self._addOutcome("successful", test, error_permitted=False)
-
-    def addUnexpectedSuccess(self, test):
-        """Report an unexpected success in test test.
-        """
-        self._addOutcome("uxsuccess", test, error_permitted=False)
-        self.failed = True
+        self.successes.append(test)
 
     def startTest(self, test):
         """Mark a test as starting its test run."""
@@ -137,9 +82,81 @@ class TestProtocolClient(unittest.TestResult):
         self._stream.flush()
 
     def stopTest(self, test):
+        """Mark a test as having finished its test run."""
         super(TestProtocolClient, self).stopTest(test)
+        self.writeOutcome(test)
+
+    def writeOutcome(self, test):
+        """Output the overall outcome for test test."""
+        err,       self.errors              = self._filterErrors(test,    self.errors)
+        fail,      self.failures            = self._filterErrors(test,    self.failures)
+        xfail,     self.expectedFailures    = self._filterErrors(test,    self.expectedFailures)
+        skip,      self.skipped             = self._filterErrors(test,    self.skipped)
+        success,   self.successes           = self._filterSuccesses(test, self.successes)
+        uxsuccess, self.unexpectedSuccesses = self._filterSuccesses(test, self.unexpectedSuccesses)
+
+        if err:
+            outcome = "error"
+        elif fail:
+            outcome = "failure"
+        elif skip:
+            outcome = "skip"
+        elif uxsuccess:
+            outcome = "uxsuccess"
+        elif xfail:
+            outcome = "xfail"
+        elif success:
+            outcome = "successful"
+        else:
+            outcome = None
+
+        if outcome:
+            self._addOutcome(outcome, test, errors=err+fail+skip+xfail)
+
         self._stream.flush()
 
+    def _filterErrors(self, test, errors):
+        """Filter a list of errors by test test.
+
+        :param test: The test to filter by.
+        :param errors: A list of <test, error> pairs to filter.
+
+        :return: A pair whose first element is a list of strings containing
+            errors that apply to test test, and whose second element is a list
+            of the remaining elements.
+        """
+        filtered = []
+        unfiltered = []
+
+        for error in errors:
+            if error[0] is test:
+                filtered.append(error[1])
+            else:
+                unfiltered.append(error)
+
+        return (filtered, unfiltered)
+
+    def _filterSuccesses(self, test, successes):
+        """Filter a list of successes by test test.
+
+        :param test: The test to filter by.
+        :param successes: A list of tests to filter.
+
+        :return: A tuple whose first element is a boolean stating whether test
+            test was found in the list of successes, and whose second element is
+            a list of the remaining elements.
+        """
+        filtered = False
+        unfiltered = []
+
+        for success in successes:
+            if success is test:
+                filtered = True
+            else:
+                unfiltered.append(success)
+
+        return (filtered, unfiltered)
+
     def time(self, a_datetime):
         """Inform the client of the time.
 

diff --git a/selftest/subunithelper.py b/selftest/subunithelper.py
index 61e3289080eba1a1fa40f61e8d48e6efad297ef8..2b78d16eb3aee7bbfc63c0731fdf8ba0e04e1958 100644 (file)
--- a/selftest/subunithelper.py
+++ b/selftest/subunithelper.py
@@ -312,6 +312,7 @@ class FilterOps(unittest.TestResult):
         self.error_added += 1
         self.total_error += 1
         self._ops.addError(test, err)
+        self._ops.writeOutcome(test)
         self.output = None
         if self.fail_immediately:
             raise ImmediateFail()
@@ -320,11 +321,13 @@ class FilterOps(unittest.TestResult):
         self.seen_output = True
         test = self._add_prefix(test)
         self._ops.addSkip(test, reason)
+        self._ops.writeOutcome(test)
         self.output = None
 
     def addExpectedFailure(self, test, err=None):
         test = self._add_prefix(test)
         self._ops.addExpectedFailure(test, err)
+        self._ops.writeOutcome(test)
         self.output = None
 
     def addUnexpectedSuccess(self, test):
@@ -332,6 +335,7 @@ class FilterOps(unittest.TestResult):
         self.uxsuccess_added += 1
         self.total_uxsuccess += 1
         self._ops.addUnexpectedSuccess(test)
+        self._ops.writeOutcome(test)
         if self.output:
             self._ops.output_msg(self.output)
         self.output = None
@@ -347,10 +351,12 @@ class FilterOps(unittest.TestResult):
             self.xfail_added += 1
             self.total_xfail += 1
             self._ops.addExpectedFailure(test, err)
+            self._ops.writeOutcome(test)
         else:
             self.fail_added += 1
             self.total_fail += 1
             self._ops.addFailure(test, err)
+            self._ops.writeOutcome(test)
             if self.output:
                 self._ops.output_msg(self.output)
             if self.fail_immediately:
@@ -364,12 +370,14 @@ class FilterOps(unittest.TestResult):
             self.uxsuccess_added += 1
             self.total_uxsuccess += 1
             self._ops.addUnexpectedSuccess(test)
+            self._ops.writeOutcome(test)
             if self.output:
                 self._ops.output_msg(self.output)
             if self.fail_immediately:
                 raise ImmediateFail()
         else:
             self._ops.addSuccess(test)
+            self._ops.writeOutcome(test)
         self.output = None
 
     def skip_testsuite(self, name, reason=None):