Merge pull request #973 from LeastAuthority/3600.eliotutil-vs-skips

Fix the per-test Eliot decoration to interact better with testtools skips

Fixes: ticket:3600

src/allmydata/test/eliotutil.py

@@ -6,29 +6,43 @@ Tools aimed at the interaction between tests and Eliot.
 # Can't use `builtins.str` because it's not JSON encodable:
 # `exceptions.TypeError: <class 'future.types.newstr.newstr'> is not JSON-encodeable`
 from past.builtins import unicode as str
-from future.utils import PY3
+from future.utils import PY2
+from six import ensure_text
 
 __all__ = [
     "RUN_TEST",
     "EliotLoggedRunTest",
-    "eliot_logged_test",
 ]
 
+try:
+    from typing import Callable
+except ImportError:
+    pass
+
 from functools import (
-    wraps,
     partial,
+    wraps,
 )
 
 import attr
 
+from zope.interface import (
+    implementer,
+)
+
 from eliot import (
     ActionType,
     Field,
+    MemoryLogger,
+    ILogger,
+)
+from eliot.testing import (
+    swap_logger,
+    check_for_errors,
 )
-from eliot.testing import capture_logging
 
-from twisted.internet.defer import (
-    maybeDeferred,
+from twisted.python.monkey import (
+    MonkeyPatcher,
 )
 
 from ..util.jsonbytes import BytesJSONEncoder
@@ -48,92 +62,12 @@ RUN_TEST = ActionType(
 )
 
 
-def eliot_logged_test(f):
-    """
-    Decorate a test method to run in a dedicated Eliot action context.
-
-    The action will finish after the test is done (after the returned Deferred
-    fires, if a Deferred is returned).  It will note the name of the test
-    being run.
-
-    All messages emitted by the test will be validated.  They will still be
-    delivered to the global logger.
-    """
-    # A convenient, mutable container into which nested functions can write
-    # state to be shared among them.
-    class storage(object):
-        pass
-
-
-    # On Python 3, we want to use our custom JSON encoder when validating
-    # messages can be encoded to JSON:
-    if PY3:
-        capture = lambda f : capture_logging(None, encoder_=BytesJSONEncoder)(f)
-    else:
-        capture = lambda f : capture_logging(None)(f)
-
-    @wraps(f)
-    def run_and_republish(self, *a, **kw):
-        # Unfortunately the only way to get at the global/default logger...
-        # This import is delayed here so that we get the *current* default
-        # logger at the time the decorated function is run.
-        from eliot._output import _DEFAULT_LOGGER as default_logger
-
-        def republish():
-            # This is called as a cleanup function after capture_logging has
-            # restored the global/default logger to its original state.  We
-            # can now emit messages that go to whatever global destinations
-            # are installed.
-
-            # storage.logger.serialize() seems like it would make more sense
-            # than storage.logger.messages here.  However, serialize()
-            # explodes, seemingly as a result of double-serializing the logged
-            # messages.  I don't understand this.
-            for msg in storage.logger.messages:
-                default_logger.write(msg)
-
-            # And now that we've re-published all of the test's messages, we
-            # can finish the test's action.
-            storage.action.finish()
-
-        @capture
-        def run(self, logger):
-            # Record the MemoryLogger for later message extraction.
-            storage.logger = logger
-            # Give the test access to the logger as well.  It would be just
-            # fine to pass this as a keyword argument to `f` but implementing
-            # that now will give me conflict headaches so I'm not doing it.
-            self.eliot_logger = logger
-            return f(self, *a, **kw)
-
-        # Arrange for all messages written to the memory logger that
-        # `capture_logging` installs to be re-written to the global/default
-        # logger so they might end up in a log file somewhere, if someone
-        # wants.  This has to be done in a cleanup function (or later) because
-        # capture_logging restores the original logger in a cleanup function.
-        # We install our cleanup function here, before we call run, so that it
-        # runs *after* the cleanup function capture_logging installs (cleanup
-        # functions are a stack).
-        self.addCleanup(republish)
-
-        # Begin an action that should comprise all messages from the decorated
-        # test method.
-        with RUN_TEST(name=self.id()).context() as action:
-            # When the test method Deferred fires, the RUN_TEST action is
-            # done.  However, we won't have re-published the MemoryLogger
-            # messages into the global/default logger when this Deferred
-            # fires.  So we need to delay finishing the action until that has
-            # happened.  Record the action so we can do that.
-            storage.action = action
-
-            # Support both Deferred-returning and non-Deferred-returning
-            # tests.
-            d = maybeDeferred(run, self)
-
-            # Let the test runner do its thing.
-            return d
-
-    return run_and_republish
+# On Python 3, we want to use our custom JSON encoder when validating messages
+# can be encoded to JSON:
+if PY2:
+    _memory_logger = MemoryLogger
+else:
+    _memory_logger = lambda: MemoryLogger(encoder=BytesJSONEncoder)
 
 
 @attr.s
@@ -174,10 +108,91 @@ class EliotLoggedRunTest(object):
     def id(self):
         return self.case.id()
 
-    @eliot_logged_test
-    def run(self, result=None):
-        return self._run_tests_with_factory(
-            self.case,
-            self.handlers,
-            self.last_resort,
-        ).run(result)
+    def run(self, result):
+        """
+        Run the test case in the context of a distinct Eliot action.
+
+        The action will finish after the test is done.  It will note the name of
+        the test being run.
+
+        All messages emitted by the test will be validated.  They will still be
+        delivered to the global logger.
+        """
+        # The idea here is to decorate the test method itself so that all of
+        # the extra logic happens at the point where test/application logic is
+        # expected to be.  This `run` method is more like test infrastructure
+        # and things do not go well when we add too much extra behavior here.
+        # For example, exceptions raised here often just kill the whole
+        # runner.
+        patcher = MonkeyPatcher()
+
+        # So, grab the test method.
+        name = self.case._testMethodName
+        original = getattr(self.case, name)
+        decorated = with_logging(ensure_text(self.case.id()), original)
+        patcher.addPatch(self.case, name, decorated)
+        try:
+            # Patch it in
+            patcher.patch()
+            # Then use the rest of the machinery to run it.
+            return self._run_tests_with_factory(
+                self.case,
+                self.handlers,
+                self.last_resort,
+            ).run(result)
+        finally:
+            # Clean up the patching for idempotency or something.
+            patcher.restore()
+
+
+def with_logging(
+        test_id,      # type: str
+        test_method,  # type: Callable
+):
+    """
+    Decorate a test method with additional log-related behaviors.
+
+    1. The test method will run in a distinct Eliot action.
+    2. Typed log messages will be validated.
+    3. Logged tracebacks will be added as errors.
+
+    :param test_id: The full identifier of the test being decorated.
+    :param test_method: The method itself.
+    """
+    @wraps(test_method)
+    def run_with_logging(*args, **kwargs):
+        validating_logger = _memory_logger()
+        original = swap_logger(None)
+        try:
+            swap_logger(_TwoLoggers(original, validating_logger))
+            with RUN_TEST(name=test_id):
+                try:
+                    return test_method(*args, **kwargs)
+                finally:
+                    check_for_errors(validating_logger)
+        finally:
+            swap_logger(original)
+    return run_with_logging
+
+
+@implementer(ILogger)
+class _TwoLoggers(object):
+    """
+    Log to two loggers.
+
+    A single logger can have multiple destinations so this isn't typically a
+    useful thing to do.  However, MemoryLogger has inline validation instead
+    of destinations.  That means this *is* useful to simultaneously write to
+    the normal places and validate all written log messages.
+    """
+    def __init__(self, a, b):
+        """
+        :param ILogger a: One logger
+        :param ILogger b: Another logger
+        """
+        self._a = a # type: ILogger
+        self._b = b # type: ILogger
+
+    def write(self, dictionary, serializer=None):
+        self._a.write(dictionary, serializer)
+        self._b.write(dictionary, serializer)

src/allmydata/test/test_eliotutil.py

@@ -18,17 +18,25 @@ if PY2:
 from sys import stdout
 import logging
 
+from unittest import (
+    skip,
+)
+
 from fixtures import (
     TempDir,
 )
 from testtools import (
     TestCase,
 )
+from testtools import (
+    TestResult,
+)
 from testtools.matchers import (
     Is,
     IsInstance,
     MatchesStructure,
     Equals,
+    HasLength,
     AfterPreprocessing,
 )
 from testtools.twistedsupport import (
@@ -38,12 +46,16 @@ from testtools.twistedsupport import (
 
 from eliot import (
     Message,
+    MessageType,
+    fields,
     FileDestination,
+    MemoryLogger,
 )
 from eliot.twisted import DeferredContext
 from eliot.testing import (
     capture_logging,
     assertHasAction,
+    swap_logger,
 )
 
 from twisted.internet.defer import (
@@ -173,6 +185,62 @@ class EliotLoggingTests(TestCase):
             ),
         )
 
+    def test_validation_failure(self):
+        """
+        If a test emits a log message that fails validation then an error is added
+        to the result.
+        """
+        # Make sure we preserve the original global Eliot state.
+        original = swap_logger(MemoryLogger())
+        self.addCleanup(lambda: swap_logger(original))
+
+        class ValidationFailureProbe(SyncTestCase):
+            def test_bad_message(self):
+                # This message does not validate because "Hello" is not an
+                # int.
+                MSG = MessageType("test:eliotutil", fields(foo=int))
+                MSG(foo="Hello").write()
+
+        result = TestResult()
+        case = ValidationFailureProbe("test_bad_message")
+        case.run(result)
+
+        self.assertThat(
+            result.errors,
+            HasLength(1),
+        )
+
+    def test_skip_cleans_up(self):
+        """
+        After a skipped test the global Eliot logging state is restored.
+        """
+        # Save the logger that's active before we do anything so that we can
+        # restore it later.  Also install another logger so we can compare it
+        # to the active logger later.
+        expected = MemoryLogger()
+        original = swap_logger(expected)
+
+        # Restore it, whatever else happens.
+        self.addCleanup(lambda: swap_logger(original))
+
+        class SkipProbe(SyncTestCase):
+            @skip("It's a skip test.")
+            def test_skipped(self):
+                pass
+
+        case = SkipProbe("test_skipped")
+        case.run()
+
+        # Retrieve the logger that's active now that the skipped test is done
+        # so we can check it against the expected value.
+        actual = swap_logger(MemoryLogger())
+        self.assertThat(
+            actual,
+            Is(expected),
+        )
+
+
+
 class LogCallDeferredTests(TestCase):
     """
     Tests for ``log_call_deferred``.