Options for logging in AsynchronousDeferredRunTest

* Exposes `CaptureTwistedLogs`, a fixture responsible for adding Twisted
  logs as a detail
* Adds `suppress_twisted_logging` and `store_twisted_logs` parameters to
  `AsynchronousDeferredRunTest`

NEWS

@@ -9,6 +9,14 @@ Next
 Changes
 -------
 
+* ``AsynchronousDeferredRunTest`` now has ``suppress_twisted_logging`` and
+  ``store_twisted_logs`` parameters that can be used to override the default
+  logging behaviour.  (Jonathan Lange, #942785)
+
+* New fixture ``CaptureTwistedLogs`` that can be used with
+  ``AsynchronousDeferredRunTest`` to attach a detail containing everything
+  logged to Twisted during the test run.  (Jonathan Lange, #1515362)
+
 * Python 2.6 and 3.2 are no longer supported. If you want to use either of
   these versions of Python, use testtools 1.9.0. (Jonathan Lange)
 

doc/api.rst

@@ -30,3 +30,4 @@ testtools.twistedsupport
 
 .. automodule:: testtools.twistedsupport
    :members:
+   :special-members: __init__

doc/for-test-authors.rst

@@ -984,6 +984,7 @@ exception or mangle the display.  In most cases simply avoiding the ``%s``
 format specifier and using ``%r`` instead will be enough.  For examples of
 more complex formatting see the ``testtools.matchers`` implementatons.
 
+.. _details:
 
 Details
 =======
@@ -1254,7 +1255,7 @@ Twisted support
 ---------------
 
 testtools provides support for running Twisted tests – tests that return a
-Deferred_ and rely on the Twisted reactor. See (XXX - jml - insert link)
+Deferred_ and rely on the Twisted reactor. See :ref:`twisted-support`.
 
 force_failure
 -------------

doc/twisted-support.rst

@@ -1,3 +1,5 @@
+.. _twisted-support:
+
 Twisted support
 ===============
 
@@ -72,6 +74,47 @@ test runner::
            # ...
            return d
 
+See :py:class:`~testtools.twistedsupport.AsynchronousDeferredRunTest` and
+:py:class:`~testtools.twistedsupport.AsynchronousDeferredRunTestForBrokenTwisted`
+for more information.
+
+
+Controlling the Twisted logs
+----------------------------
+
+Users of Twisted Trial will be accustomed to all tests logging to
+``_trial_temp/test.log``. By default,
+:py:class:`~testtools.twistedsupport.AsynchronousDeferredRunTest` will *not*
+do this, but will instead:
+
+ 1. suppress all messages logged during the test run
+ 2. attach them as the ``twisted-log`` detail (see :ref:`details`) which is
+    shown if the test fails
+
+The first behavior is controlled by the ``suppress_twisted_logging`` parameter
+to :py:class:`~testtools.twistedsupport.AsynchronousDeferredRunTest`, which is
+set to ``True`` by default. The second is controlled by the
+``store_twisted_logs`` parameter, which is also ``True`` by default.
+
+If ``store_twisted_logs`` is set to ``False``, you can still get the logs
+attached as a detail by using the
+:py:class:`~testtools.twistedsupport.CaptureTwistedLogs` fixture. Using the
+:py:class:`~testtools.twistedsupport.CaptureTwistedLogs` fixture is equivalent
+to setting ``store_twisted_logs`` to ``True``.
+
+For example::
+
+    class DoNotCaptureLogsTests(TestCase):
+        run_tests_with = partial(AsynchronousDeferredRunTest,
+                                 store_twisted_logs=False)
+
+        def test_foo(self):
+            log.msg('logs from this test are not attached')
+
+        def test_bar(self):
+            self.useFixture(CaptureTwistedLogs())
+            log.msg('logs from this test *are* attached')
+
 
 Converting Trial tests to testtools tests
 -----------------------------------------

testtools/deferredruntest.py

@@ -145,8 +145,27 @@ class _ErrorObserver(Fixture):
         return self._error_observer.flushErrors(*error_types)
 
 
-class _CaptureTwistedLogs(Fixture):
+class CaptureTwistedLogs(Fixture):
-    """Capture all the Twisted logs and add them as a detail."""
+    """Capture all the Twisted logs and add them as a detail.
+
+    Much of the time, you won't need to use this directly, as
+    :py:class:`AsynchronousDeferredRunTest` captures Twisted logs when the
+    ``store_twisted_logs`` is set to ``True`` (which it is by default).
+
+    However, if you want to do custom processing of Twisted's logs, then this
+    class can be useful.
+
+    For example::
+
+        class TwistedTests(TestCase):
+            run_tests_with(
+                partial(AsynchronousDeferredRunTest, store_twisted_logs=False))
+
+            def setUp(self):
+                super(TwistedTests, self).setUp()
+                twisted_logs = self.useFixture(CaptureTwistedLogs())
+                # ... do something with twisted_logs ...
+    """
 
     LOG_DETAIL_NAME = 'twisted-log'
 
@@ -223,8 +242,9 @@ class AsynchronousDeferredRunTest(_DeferredRunTest):
     """
 
     def __init__(self, case, handlers=None, last_resort=None, reactor=None,
-                 timeout=0.005, debug=False):
+                 timeout=0.005, debug=False, suppress_twisted_logging=True,
-        """Construct an `AsynchronousDeferredRunTest`.
+                 store_twisted_logs=True):
+        """Construct an ``AsynchronousDeferredRunTest``.
 
         Please be sure to always use keyword syntax, not positional, as the
         base class may add arguments in future - and for core code
@@ -244,6 +264,11 @@ class AsynchronousDeferredRunTest(_DeferredRunTest):
         :param debug: Whether or not to enable Twisted's debugging.  Use this
             to get information about unhandled Deferreds and left-over
             DelayedCalls.  Defaults to False.
+        :param bool suppress_twisted_logging: If True, then suppress Twisted's
+            default logging while the test is being run. Defaults to True.
+        :param bool store_twisted_logs: If True, then store the Twisted logs
+            that took place during the run as the 'twisted-log' detail.
+            Defaults to True.
         """
         super(AsynchronousDeferredRunTest, self).__init__(
             case, handlers, last_resort)
@@ -252,9 +277,12 @@ class AsynchronousDeferredRunTest(_DeferredRunTest):
         self._reactor = reactor
         self._timeout = timeout
         self._debug = debug
+        self._suppress_twisted_logging = suppress_twisted_logging
+        self._store_twisted_logs = store_twisted_logs
 
     @classmethod
-    def make_factory(cls, reactor=None, timeout=0.005, debug=False):
+    def make_factory(cls, reactor=None, timeout=0.005, debug=False,
+                     suppress_twisted_logging=True, store_twisted_logs=True):
         """Make a factory that conforms to the RunTest factory interface.
 
         Example::
@@ -270,7 +298,9 @@ class AsynchronousDeferredRunTest(_DeferredRunTest):
         class AsynchronousDeferredRunTestFactory:
             def __call__(self, case, handlers=None, last_resort=None):
                 return cls(
-                    case, handlers, last_resort, reactor, timeout, debug)
+                    case, handlers, last_resort, reactor, timeout, debug,
+                    suppress_twisted_logging, store_twisted_logs,
+                )
         return AsynchronousDeferredRunTestFactory()
 
     @defer.deferredGenerator
@@ -371,6 +401,17 @@ class AsynchronousDeferredRunTest(_DeferredRunTest):
             self._log_user_exception(TimeoutError(self.case, self._timeout))
             return False, []
 
+    def _get_log_fixture(self):
+        """Return the log fixture we're configured to use."""
+        fixtures = []
+        # TODO: Expose these fixtures and deprecate both of these options in
+        # favour of them.
+        if self._suppress_twisted_logging:
+            fixtures.append(_NoTwistedLogObservers())
+        if self._store_twisted_logs:
+            fixtures.append(CaptureTwistedLogs())
+        return _CompoundFixture(fixtures)
+
     def _run_core(self):
         # XXX: Blatting over the namespace of the test case isn't a nice thing
         # to do. Find a better way of communicating between runtest and test
@@ -378,17 +419,11 @@ class AsynchronousDeferredRunTest(_DeferredRunTest):
         self.case.reactor = self._reactor
         spinner = self._make_spinner()
 
-        # XXX: We want to make the use of these _NoTwistedLogObservers and
-        # _CaptureTwistedLogs optional, and ideally, make it so they aren't
-        # used by default.
-        logging_fixture = _CompoundFixture(
-            [_NoTwistedLogObservers(), _CaptureTwistedLogs()])
-
         # We can't just install these as fixtures on self.case, because we
         # need the clean up to run even if the test times out.
         #
         # See https://bugs.launchpad.net/testtools/+bug/897196.
-        with logging_fixture as capture_logs:
+        with self._get_log_fixture() as capture_logs:
             for name, detail in capture_logs.getDetails().items():
                 self.case.addDetail(name, detail)
             with _ErrorObserver(_log_observer) as error_fixture:

testtools/tests/test_deferredruntest.py

@@ -237,11 +237,15 @@ class TestAsynchronousDeferredRunTest(NeedsTwistedTestCase):
     def make_result(self):
         return ExtendedTestResult()
 
-    def make_runner(self, test, timeout=None):
+    def make_runner(self, test, timeout=None, suppress_twisted_logging=True,
+                    store_twisted_logs=True):
         if timeout is None:
             timeout = self.make_timeout()
         return AsynchronousDeferredRunTest(
-            test, test.exception_handlers, timeout=timeout)
+            test, test.exception_handlers, timeout=timeout,
+            suppress_twisted_logging=suppress_twisted_logging,
+            store_twisted_logs=store_twisted_logs,
+        )
 
     def make_timeout(self):
         return 0.005
@@ -629,7 +633,7 @@ class TestAsynchronousDeferredRunTest(NeedsTwistedTestCase):
                     f = failure.Failure()
                 log.err(f)
         test = LogAnError('test_something')
-        runner = self.make_runner(test)
+        runner = self.make_runner(test, store_twisted_logs=False)
         result = self.make_result()
         runner.run(result)
         self.assertThat(
@@ -641,10 +645,6 @@ class TestAsynchronousDeferredRunTest(NeedsTwistedTestCase):
                         'Traceback (most recent call last):',
                         'ZeroDivisionError',
                         ])),
-                    'twisted-log': AsText(ContainsAll([
-                        'Traceback (most recent call last):',
-                        'ZeroDivisionError',
-                        ])),
                     }),
                 ('stopTest', test)))
 
@@ -660,28 +660,25 @@ class TestAsynchronousDeferredRunTest(NeedsTwistedTestCase):
                 log.err(f)
                 flush_logged_errors(ZeroDivisionError)
         test = LogAnError('test_something')
-        runner = self.make_runner(test)
+        runner = self.make_runner(test, store_twisted_logs=False)
         result = self.make_result()
         runner.run(result)
         self.assertThat(
             result._events,
             MatchesEvents(
                 ('startTest', test),
-                ('addSuccess', test, {
+                ('addSuccess', test),
-                    'twisted-log': AsText(ContainsAll([
-                        'Traceback (most recent call last):',
-                        'ZeroDivisionError',
-                        ])),
-                    }),
                 ('stopTest', test)))
 
     def test_log_in_details(self):
+        # If store_twisted_logs is True, we include the Twisted logs as
+        # details.
         class LogAnError(TestCase):
             def test_something(self):
                 log.msg("foo")
                 1/0
         test = LogAnError('test_something')
-        runner = self.make_runner(test)
+        runner = self.make_runner(test, store_twisted_logs=True)
         result = self.make_result()
         runner.run(result)
         self.assertThat(
@@ -695,9 +692,8 @@ class TestAsynchronousDeferredRunTest(NeedsTwistedTestCase):
                 ('stopTest', test)))
 
     def test_do_not_log_to_twisted(self):
-        # By default, we don't log anything to the default Twisted loggers.
+        # If suppress_twisted_logging is True, we don't log anything to the
-        # XXX: We want to make this behaviour optional, and (ideally)
+        # default Twisted loggers.
-        # deprecated.
         messages = []
         publisher, _ = _get_global_publisher_and_observers()
         publisher.addObserver(messages.append)
@@ -708,11 +704,30 @@ class TestAsynchronousDeferredRunTest(NeedsTwistedTestCase):
                 log.msg("foo")
 
         test = LogSomething('test_something')
-        runner = self.make_runner(test)
+        runner = self.make_runner(test, suppress_twisted_logging=True)
         result = self.make_result()
         runner.run(result)
         self.assertThat(messages, Equals([]))
 
+    def test_log_to_twisted(self):
+        # If suppress_twisted_logging is False, we log to the default Twisted
+        # loggers.
+        messages = []
+        publisher, _ = _get_global_publisher_and_observers()
+        publisher.addObserver(messages.append)
+
+        class LogSomething(TestCase):
+            def test_something(self):
+                log.msg("foo")
+
+        test = LogSomething('test_something')
+        runner = self.make_runner(test, suppress_twisted_logging=False)
+        result = self.make_result()
+        runner.run(result)
+        self.assertThat(
+            messages,
+            MatchesListwise([ContainsDict({'message': Equals(('foo',))})]))
+
     def test_restore_observers(self):
         # We restore the original observers.
         publisher, observers = _get_global_publisher_and_observers()
@@ -978,15 +993,15 @@ class TestErrorObserver(NeedsTwistedTestCase):
 
 
 class TestCaptureTwistedLogs(NeedsTwistedTestCase):
-    """Tests for _CaptureTwistedLogs."""
+    """Tests for CaptureTwistedLogs."""
 
     def test_captures_logs(self):
-        # _CaptureTwistedLogs stores all Twisted log messages as a detail.
+        # CaptureTwistedLogs stores all Twisted log messages as a detail.
-        from testtools.deferredruntest import _CaptureTwistedLogs
+        from testtools.deferredruntest import CaptureTwistedLogs
 
         class SomeTest(TestCase):
             def test_something(self):
-                self.useFixture(_CaptureTwistedLogs())
+                self.useFixture(CaptureTwistedLogs())
                 log.msg('foo')
 
         test = SomeTest('test_something')

testtools/twistedsupport/__init__.py

@@ -12,6 +12,7 @@ __all__ = [
     'AsynchronousDeferredRunTest',
     'AsynchronousDeferredRunTestForBrokenTwisted',
     'SynchronousDeferredRunTest',
+    'CaptureTwistedLogs',
     'assert_fails_with',
     'flush_logged_errors',
 ]
@@ -26,6 +27,7 @@ from testtools.deferredruntest import (
     AsynchronousDeferredRunTest,
     AsynchronousDeferredRunTestForBrokenTwisted,
     SynchronousDeferredRunTest,
+    CaptureTwistedLogs,
     assert_fails_with,
     flush_logged_errors,
 )