Merge pull request #97 from cjwatson/subunit-std-streams

Add test buffering, enabled by default for subunit

src/zope/testrunner/formatter.py

@@ -15,6 +15,10 @@
 """
 from __future__ import print_function
 
+try:
+    from collections.abc import MutableMapping
+except ImportError:
+    from collections import MutableMapping
 from contextlib import contextmanager
 import doctest
 import os
@@ -323,7 +327,7 @@ def test_skipped(self, test, reason):
         sys.stdout.write(s)
         self.test_width += len(s) + 1
 
-    def test_error(self, test, seconds, exc_info):
+    def test_error(self, test, seconds, exc_info, stdout=None, stderr=None):
         """Report that an error occurred while running a test.
 
         Should be called right after start_test().
@@ -334,9 +338,10 @@ def test_error(self, test, seconds, exc_info):
             print(" (%s)" % self.format_seconds_short(seconds))
         print()
         self.print_traceback("Error in test %s" % test, exc_info)
+        self.print_std_streams(stdout, stderr)
         self.test_width = self.last_width = 0
 
-    def test_failure(self, test, seconds, exc_info):
+    def test_failure(self, test, seconds, exc_info, stdout=None, stderr=None):
         """Report that a test failed.
 
         Should be called right after start_test().
@@ -347,6 +352,7 @@ def test_failure(self, test, seconds, exc_info):
             print(" (%s)" % self.format_seconds_short(seconds))
         print()
         self.print_traceback("Failure in test %s" % test, exc_info)
+        self.print_std_streams(stdout, stderr)
         self.test_width = self.last_width = 0
 
     def print_traceback(self, msg, exc_info):
@@ -355,6 +361,21 @@ def print_traceback(self, msg, exc_info):
         print(msg)
         print(self.format_traceback(exc_info))
 
+    def print_std_streams(self, stdout, stderr):
+        """Emit contents of buffered standard streams."""
+        if stdout:
+            sys.stdout.write("Stdout:\n")
+            sys.stdout.write(stdout)
+            if not stdout.endswith("\n"):
+                sys.stdout.write("\n")
+            sys.stdout.write("\n")
+        if stderr:
+            sys.stderr.write("Stderr:\n")
+            sys.stderr.write(stderr)
+            if not stderr.endswith("\n"):
+                sys.stderr.write("\n")
+            sys.stderr.write("\n")
+
     def format_traceback(self, exc_info):
         """Format the traceback."""
         v = exc_info[1]
@@ -792,6 +813,37 @@ def status(self, **kwargs):
         self.decorated.status(**kwargs)
 
 
+class _SortedDict(MutableMapping, object):
+    """A dict that always returns items in sorted order.
+
+    This differs from collections.OrderedDict in that it returns items in
+    *sorted* order, not in insertion order.
+
+    We use this as a workaround for the fact that
+    testtools.ExtendedToStreamDecorator doesn't sort the details dict when
+    encoding it, which makes it difficult to write stable doctests for
+    subunit v2 output.
+    """
+
+    def __init__(self, items):
+        self._dict = dict(items)
+
+    def __getitem__(self, key):
+        return self._dict[key]
+
+    def __setitem__(self, key, value):
+        self._dict[key] = value
+
+    def __delitem__(self, key):
+        del self._dict[key]
+
+    def __iter__(self):
+        return iter(sorted(self._dict))
+
+    def __len__(self):
+        return len(self._dict)
+
+
 class SubunitOutputFormatter(object):
     """A subunit output formatter.
 
@@ -1052,20 +1104,20 @@ def test_threads(self, test, new_threads):
 
     def refcounts(self, rc, prev):
         """Report a change in reference counts."""
-        details = {
+        details = _SortedDict({
             'sys-refcounts': text_content(str(rc)),
             'changes': text_content(str(rc - prev)),
-        }
+        })
         # XXX: Emit the details dict as JSON?
         self._emit_fake_test(self.TAG_REFCOUNTS, self.TAG_REFCOUNTS, details)
 
     def detailed_refcounts(self, track, rc, prev):
         """Report a change in reference counts, with extra detail."""
-        details = {
+        details = _SortedDict({
             'sys-refcounts': text_content(str(rc)),
             'changes': text_content(str(rc - prev)),
             'track': text_content(str(track.delta)),
-        }
+        })
         self._emit_fake_test(self.TAG_REFCOUNTS, self.TAG_REFCOUNTS, details)
 
     def start_set_up(self, layer_name):
@@ -1194,13 +1246,26 @@ def _exc_info_to_details(self, exc_info):
         else:
             unicode_tb = traceback
 
-        return {
+        return _SortedDict({
             'traceback': Content(
                 self.TRACEBACK_CONTENT_TYPE,
                 lambda: [unicode_tb.encode('utf8')]),
-        }
-
-    def test_error(self, test, seconds, exc_info):
+        })
+
+    def _add_std_streams_to_details(self, details, stdout, stderr):
+        """Add buffered standard stream contents to a subunit details dict."""
+        if stdout:
+            if isinstance(stdout, bytes):
+                stdout = stdout.decode('utf-8', 'replace')
+            details['test-stdout'] = Content(
+                self.PLAIN_TEXT, lambda: [stdout.encode('utf-8')])
+        if stderr:
+            if isinstance(stderr, bytes):
+                stderr = stderr.decode('utf-8', 'replace')
+            details['test-stderr'] = Content(
+                self.PLAIN_TEXT, lambda: [stderr.encode('utf-8')])
+
+    def test_error(self, test, seconds, exc_info, stdout=None, stderr=None):
         """Report that an error occurred while running a test.
 
         Should be called right after start_test().
@@ -1209,9 +1274,10 @@ def test_error(self, test, seconds, exc_info):
         """
         self._emit_timestamp()
         details = self._exc_info_to_details(exc_info)
+        self._add_std_streams_to_details(details, stdout, stderr)
         self._subunit.addError(test, details=details)
 
-    def test_failure(self, test, seconds, exc_info):
+    def test_failure(self, test, seconds, exc_info, stdout=None, stderr=None):
         """Report that a test failed.
 
         Should be called right after start_test().
@@ -1220,6 +1286,7 @@ def test_failure(self, test, seconds, exc_info):
         """
         self._emit_timestamp()
         details = self._exc_info_to_details(exc_info)
+        self._add_std_streams_to_details(details, stdout, stderr)
         self._subunit.addFailure(test, details=details)
 
     def stop_test(self, test):

src/zope/testrunner/options.py

@@ -285,6 +285,16 @@ def _regex_search(s):
 it will be ignored.
 """)
 
+reporting.add_argument(
+    '--buffer', action="store_true", dest="buffer",
+    help="""\
+Buffer the standard output and standard error streams during each test.
+Output during a passing test is discarded.
+Output during failing or erroring tests is echoed.
+This option is enabled by default if --subunit or --subunit-v2 is in use, to
+avoid corrupting the subunit stream.
+""")
+
 
 ######################################################################
 # Analysis
@@ -591,6 +601,7 @@ def apply_auto_progress(args):
         """)
             options.fail = True
             return options
+        options.buffer = True
 
     if options.subunit and options.subunit_v2:
         print("""\

src/zope/testrunner/runner.py

@@ -853,6 +853,10 @@ def __init__(self, options, tests, layer_name=None):
         for test in tests:
             count += test.countTestCases()
         self.count = count
+        self._stdout_buffer = None
+        self._stderr_buffer = None
+        self._original_stdout = sys.stdout
+        self._original_stderr = sys.stderr
 
     def testSetUp(self):
         """A layer may define a setup method to be called before each
@@ -874,6 +878,31 @@ def testTearDown(self):
             if hasattr(layer, 'testTearDown'):
                 layer.testTearDown()
 
+    def _setUpStdStreams(self):
+        """Set up buffered standard streams, if requested."""
+        if self.options.buffer:
+            if self._stdout_buffer is None:
+                self._stdout_buffer = StringIO()
+            if self._stderr_buffer is None:
+                self._stderr_buffer = StringIO()
+            sys.stdout = self._stdout_buffer
+            sys.stderr = self._stderr_buffer
+
+    def _restoreStdStreams(self):
+        """Restore the buffered standard streams and return any contents."""
+        if self.options.buffer:
+            stdout = sys.stdout.getvalue()
+            stderr = sys.stderr.getvalue()
+            sys.stdout = self._original_stdout
+            sys.stderr = self._original_stderr
+            self._stdout_buffer.seek(0)
+            self._stdout_buffer.truncate(0)
+            self._stderr_buffer.seek(0)
+            self._stderr_buffer.truncate(0)
+            return stdout, stderr
+        else:
+            return None, None
+
     def startTest(self, test):
         self.testSetUp()
         unittest.TestResult.startTest(self, test)
@@ -886,17 +915,23 @@ def startTest(self, test):
         self._threads = threading.enumerate()
         self._start_time = time.time()
 
+        self._setUpStdStreams()
+
     def addSuccess(self, test):
+        self._restoreStdStreams()
         t = max(time.time() - self._start_time, 0.0)
         self.options.output.test_success(test, t)
 
     def addSkip(self, test, reason):
+        self._restoreStdStreams()
         unittest.TestResult.addSkip(self, test, reason)
         self.options.output.test_skipped(test, reason)
 
     def addError(self, test, exc_info):
+        stdout, stderr = self._restoreStdStreams()
         self.options.output.test_error(test, time.time() - self._start_time,
-                                       exc_info)
+                                       exc_info,
+                                       stdout=stdout, stderr=stderr)
 
         unittest.TestResult.addError(self, test, exc_info)
 
@@ -911,8 +946,10 @@ def addError(self, test, exc_info):
             self.stop()
 
     def addFailure(self, test, exc_info):
+        stdout, stderr = self._restoreStdStreams()
         self.options.output.test_failure(test, time.time() - self._start_time,
-                                         exc_info)
+                                         exc_info,
+                                         stdout=stdout, stderr=stderr)
 
         unittest.TestResult.addFailure(self, test, exc_info)
 
@@ -924,15 +961,18 @@ def addFailure(self, test, exc_info):
             self.stop()
 
     def addExpectedFailure(self, test, exc_info):
+        self._restoreStdStreams()
         t = max(time.time() - self._start_time, 0.0)
         self.options.output.test_success(test, t)
 
         unittest.TestResult.addExpectedFailure(self, test, exc_info)
 
     def addUnexpectedSuccess(self, test):
+        stdout, stderr = self._restoreStdStreams()
         self.options.output.test_error(
             test, time.time() - self._start_time,
-            (UnexpectedSuccess, UnexpectedSuccess(), None))
+            (UnexpectedSuccess, UnexpectedSuccess(), None),
+            stdout=stdout, stderr=stderr)
 
         unittest.TestResult.addUnexpectedSuccess(self, test)
 

src/zope/testrunner/tests/testrunner-errors.rst

@@ -366,6 +366,87 @@ If you also want a summary of errors at the end, ask for verbosity as well
 as progress output.
 
 
+Capturing output
+----------------
+
+We can ask for output on stdout and stderr to be buffered, and emitted only
+for failing and erroring tests.
+
+    >>> sys.argv = (
+    ...     'test -vv --buffer -ssample2'
+    ...     ' --tests-pattern ^stdstreamstest$'.split())
+    >>> orig_stderr = sys.stderr
+    >>> sys.stderr = sys.stdout
+    >>> testrunner.run_internal(defaults) # doctest: +NORMALIZE_WHITESPACE
+    Running tests at level 1
+    Running zope.testrunner.layer.UnitTests tests:
+      Set up zope.testrunner.layer.UnitTests in N.NNN seconds.
+      Running:
+     test_stderr_error (sample2.stdstreamstest.Test)
+    <BLANKLINE>
+    Error in test test_stderr_error (sample2.stdstreamstest.Test)
+    Traceback (most recent call last):
+     testrunner-ex/sample2/stdstreamstest.py", Line NNN, in test_stderr_error
+        raise Exception("boom")
+    Exception: boom
+    <BLANKLINE>
+    Stderr:
+    stderr output on error
+    <BLANKLINE>
+    <BLANKLINE>
+     test_stderr_failure (sample2.stdstreamstest.Test)
+    <BLANKLINE>
+    Failure in test test_stderr_failure (sample2.stdstreamstest.Test)
+    Traceback (most recent call last):
+     testrunner-ex/sample2/stdstreamstest.py", Line NNN, in test_stderr_failure
+        self.assertTrue(False)
+    AssertionError: False is not true
+    <BLANKLINE>
+    Stderr:
+    stderr output on failure
+    <BLANKLINE>
+    <BLANKLINE>
+     test_stderr_success (sample2.stdstreamstest.Test)
+     test_stdout_error (sample2.stdstreamstest.Test)
+    <BLANKLINE>
+    Error in test test_stdout_error (sample2.stdstreamstest.Test)
+    Traceback (most recent call last):
+     testrunner-ex/sample2/stdstreamstest.py", Line NNN, in test_stdout_error
+        raise Exception("boom")
+    Exception: boom
+    <BLANKLINE>
+    Stdout:
+    stdout output on error
+    <BLANKLINE>
+    <BLANKLINE>
+     test_stdout_failure (sample2.stdstreamstest.Test)
+    <BLANKLINE>
+    Failure in test test_stdout_failure (sample2.stdstreamstest.Test)
+    Traceback (most recent call last):
+     testrunner-ex/sample2/stdstreamstest.py", Line NNN, in test_stdout_failure
+        self.assertTrue(False)
+    AssertionError: False is not true
+    <BLANKLINE>
+    Stdout:
+    stdout output on failure
+    <BLANKLINE>
+    <BLANKLINE>
+     test_stdout_success (sample2.stdstreamstest.Test)
+      Ran 6 tests with 2 failures, 2 errors and 0 skipped in N.NNN seconds.
+    Tearing down left over layers:
+      Tear down zope.testrunner.layer.UnitTests in N.NNN seconds.
+    <BLANKLINE>
+    Tests with errors:
+       test_stderr_error (sample2.stdstreamstest.Test)
+       test_stdout_error (sample2.stdstreamstest.Test)
+    <BLANKLINE>
+    Tests with failures:
+       test_stderr_failure (sample2.stdstreamstest.Test)
+       test_stdout_failure (sample2.stdstreamstest.Test)
+    True
+    >>> sys.stderr = orig_stderr
+
+
 Suppressing multiple doctest errors
 -----------------------------------