Merge pull request #551 from tahoe-lafs/2973.eliot-inlinecallbacks-support

Add an Eliot-friendly inlineCallbacks-alike decorator.

Fixes: ticket:2973

See also upstream effort: https://github.com/itamarst/eliot/pull/375

newsfragments/2973.other

@@ -0,0 +1 @@
+Several utilities to facilitate the use of the Eliot causal logging library have been introduced.

src/allmydata/_auto_deps.py

@@ -97,6 +97,13 @@ install_requires = [
 
     # for 'tahoe invite' and 'tahoe join'
     "magic-wormhole >= 0.10.2",
+
+    # Eliot is contemplating dropping Python 2 support.  Stick to a version we
+    # know works on Python 2.7.  Because we don't have support for `==`
+    # constraints, pin 1.6.x this way.  I feel pretty safe betting that we
+    # won't end up stuck on Eliot 1.6.100 with a critical fix only present in
+    # 1.6.101.  And if we do, I know how to deal with that situation.
+    "eliot >= 1.6.0, <= 1.6.100",
 ]
 
 # Includes some indirect dependencies, but does not include allmydata.
@@ -124,7 +131,8 @@ package_imports = [
     ('pycparser',        'pycparser'),
     ('PyYAML',           'yaml'),
     ('magic-wormhole',   'wormhole'),
-    ('setuptools',       'setuptools')
+    ('setuptools',       'setuptools'),
+    ('eliot',            'eliot'),
 ]
 
 # Dependencies for which we don't know how to get a version number at run-time.

src/allmydata/test/eliotutil.py

@@ -0,0 +1,103 @@
+"""
+Tools aimed at the interaction between tests and Eliot.
+"""
+
+from functools import wraps
+
+from eliot import (
+    ActionType,
+    Field,
+)
+from eliot.testing import capture_logging
+
+from twisted.internet.defer import (
+    maybeDeferred,
+)
+
+_NAME = Field.for_types(
+    u"name",
+    [unicode],
+    u"The name of the test.",
+)
+
+RUN_TEST = ActionType(
+    u"run-test",
+    [_NAME],
+    [],
+    u"A test is run.",
+)
+
+
+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:
+        pass
+
+    @wraps(f)
+    def run_and_republish(self, *a, **kw):
+        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.
+
+            # Unfortunately the only way to get at the global/default
+            # logger...
+            from eliot._output import _DEFAULT_LOGGER as logger
+
+            # 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:
+                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_logging(None)
+        def run(self, logger):
+            # Record the MemoryLogger for later message extraction.
+            storage.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().decode("utf-8")).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

src/allmydata/test/test_eliotutil.py

@@ -0,0 +1,414 @@
+"""
+Tests for ``allmydata.test.eliotutil``.
+"""
+
+from pprint import pformat
+
+from eliot import (
+    Message,
+    start_action,
+)
+from eliot.twisted import DeferredContext
+from eliot.testing import (
+    capture_logging,
+    assertHasAction,
+)
+
+from twisted.trial.unittest import TestCase
+from twisted.internet.defer import (
+    Deferred,
+    succeed,
+)
+from twisted.internet.task import deferLater
+from twisted.internet import reactor
+
+from .eliotutil import (
+    eliot_logged_test,
+)
+
+from ..util.eliotutil import (
+    eliot_friendly_generator_function,
+    inline_callbacks,
+)
+
+class EliotLoggedTestTests(TestCase):
+    @eliot_logged_test
+    def test_returns_none(self):
+        Message.log(hello="world")
+
+    @eliot_logged_test
+    def test_returns_fired_deferred(self):
+        Message.log(hello="world")
+        return succeed(None)
+
+    @eliot_logged_test
+    def test_returns_unfired_deferred(self):
+        Message.log(hello="world")
+        # @eliot_logged_test automatically gives us an action context but it's
+        # still our responsibility to maintain it across stack-busting
+        # operations.
+        d = DeferredContext(deferLater(reactor, 0.0, lambda: None))
+        d.addCallback(lambda ignored: Message.log(goodbye="world"))
+        # We didn't start an action.  We're not finishing an action.
+        return d.result
+
+
+
+def assert_logged_messages_contain_fields(testcase, logged_messages, expected_fields):
+    testcase.assertEqual(len(logged_messages), len(expected_fields))
+    actual_fields = list(
+        {key: msg.message[key] for key in expected if key in msg.message}
+        for (msg, expected)
+        in zip(logged_messages, expected_fields)
+    )
+    testcase.assertEqual(actual_fields, expected_fields)
+
+
+def assert_logged_action_contains_messages(testcase, logger, expected_action, expected_fields):
+    action = assertHasAction(
+        testcase,
+        logger,
+        expected_action,
+        True,
+    )
+    assert_logged_messages_contain_fields(
+        testcase,
+        action.children,
+        expected_fields,
+    )
+
+def assert_expected_action_tree(testcase, logger, expected_action_type, expected_type_tree):
+    logged_action = assertHasAction(
+        testcase,
+        logger,
+        expected_action_type,
+        True,
+    )
+    type_tree = logged_action.type_tree()
+    testcase.assertEqual(
+        {expected_action_type: expected_type_tree},
+        type_tree,
+        "Logger had messages:\n{}".format(pformat(logger.messages, indent=4)),
+    )
+
+def assert_generator_logs_action_tree(testcase, generator_function, logger, expected_action_type, expected_type_tree):
+    list(eliot_friendly_generator_function(generator_function)())
+    assert_expected_action_tree(
+        testcase,
+        logger,
+        expected_action_type,
+        expected_type_tree,
+    )
+
+
+class EliotFriendlyGeneratorFunctionTests(TestCase):
+    # Get our custom assertion failure messages *and* the standard ones.
+    longMessage = True
+
+    @capture_logging(None)
+    def test_yield_none(self, logger):
+        @eliot_friendly_generator_function
+        def g():
+            Message.log(message_type=u"hello")
+            yield
+            Message.log(message_type=u"goodbye")
+
+        with start_action(action_type=u"the-action"):
+            list(g())
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action",
+            [u"hello", u"yielded", u"goodbye"],
+        )
+
+    @capture_logging(None)
+    def test_yield_value(self, logger):
+        expected = object()
+
+        @eliot_friendly_generator_function
+        def g():
+            Message.log(message_type=u"hello")
+            yield expected
+            Message.log(message_type=u"goodbye")
+
+        with start_action(action_type=u"the-action"):
+            self.assertEqual([expected], list(g()))
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action",
+            [u"hello", u"yielded", u"goodbye"],
+        )
+
+    @capture_logging(None)
+    def test_yield_inside_another_action(self, logger):
+        @eliot_friendly_generator_function
+        def g():
+            Message.log(message_type=u"a")
+            with start_action(action_type=u"confounding-factor"):
+                Message.log(message_type=u"b")
+                yield None
+                Message.log(message_type=u"c")
+            Message.log(message_type=u"d")
+
+        with start_action(action_type=u"the-action"):
+            list(g())
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action",
+            [u"a",
+             {u"confounding-factor": [u"b", u"yielded", u"c"]},
+             u"d",
+            ],
+        )
+
+    @capture_logging(None)
+    def test_yield_inside_nested_actions(self, logger):
+        @eliot_friendly_generator_function
+        def g():
+            Message.log(message_type=u"a")
+            with start_action(action_type=u"confounding-factor"):
+                Message.log(message_type=u"b")
+                yield None
+                with start_action(action_type=u"double-confounding-factor"):
+                    yield None
+                    Message.log(message_type=u"c")
+                Message.log(message_type=u"d")
+            Message.log(message_type=u"e")
+
+        with start_action(action_type=u"the-action"):
+            list(g())
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action", [
+                u"a",
+                {u"confounding-factor": [
+                    u"b",
+                    u"yielded",
+                    {u"double-confounding-factor": [
+                        u"yielded",
+                        u"c",
+                    ]},
+                    u"d",
+                ]},
+                u"e",
+            ],
+        )
+
+    @capture_logging(None)
+    def test_generator_and_non_generator(self, logger):
+        @eliot_friendly_generator_function
+        def g():
+            Message.log(message_type=u"a")
+            yield
+            with start_action(action_type=u"action-a"):
+                Message.log(message_type=u"b")
+                yield
+                Message.log(message_type=u"c")
+
+            Message.log(message_type=u"d")
+            yield
+
+        with start_action(action_type=u"the-action"):
+            generator = g()
+            next(generator)
+            Message.log(message_type=u"0")
+            next(generator)
+            Message.log(message_type=u"1")
+            next(generator)
+            Message.log(message_type=u"2")
+            self.assertRaises(StopIteration, lambda: next(generator))
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action", [
+                u"a",
+                u"yielded",
+                u"0",
+                {
+                    u"action-a": [
+                        u"b",
+                        u"yielded",
+                        u"c",
+                    ],
+                },
+                u"1",
+                u"d",
+                u"yielded",
+                u"2",
+            ],
+        )
+
+    @capture_logging(None)
+    def test_concurrent_generators(self, logger):
+        @eliot_friendly_generator_function
+        def g(which):
+            Message.log(message_type=u"{}-a".format(which))
+            with start_action(action_type=which):
+                Message.log(message_type=u"{}-b".format(which))
+                yield
+                Message.log(message_type=u"{}-c".format(which))
+            Message.log(message_type=u"{}-d".format(which))
+
+        gens = [g(u"1"), g(u"2")]
+        with start_action(action_type=u"the-action"):
+            while gens:
+                for g in gens[:]:
+                    try:
+                        next(g)
+                    except StopIteration:
+                        gens.remove(g)
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action", [
+                u"1-a",
+                {u"1": [
+                    u"1-b",
+                    u"yielded",
+                    u"1-c",
+                ]},
+                u"2-a",
+                {u"2": [
+                    u"2-b",
+                    u"yielded",
+                    u"2-c",
+                ]},
+                u"1-d",
+                u"2-d",
+            ],
+        )
+
+    @capture_logging(None)
+    def test_close_generator(self, logger):
+        @eliot_friendly_generator_function
+        def g():
+            Message.log(message_type=u"a")
+            try:
+                yield
+                Message.log(message_type=u"b")
+            finally:
+                Message.log(message_type=u"c")
+
+
+        with start_action(action_type=u"the-action"):
+            gen = g()
+            next(gen)
+            gen.close()
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action", [
+                u"a",
+                u"yielded",
+                u"c",
+            ],
+        )
+
+    @capture_logging(None)
+    def test_nested_generators(self, logger):
+        @eliot_friendly_generator_function
+        def g(recurse):
+            with start_action(action_type=u"a-recurse={}".format(recurse)):
+                Message.log(message_type=u"m-recurse={}".format(recurse))
+                if recurse:
+                    set(g(False))
+                else:
+                    yield
+
+        with start_action(action_type=u"the-action"):
+            set(g(True))
+
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action", [{
+                u"a-recurse=True": [
+                    u"m-recurse=True", {
+                        u"a-recurse=False": [
+                            u"m-recurse=False",
+                            u"yielded",
+                        ],
+                    },
+                ],
+            }],
+        )
+
+
+class InlineCallbacksTests(TestCase):
+    # Get our custom assertion failure messages *and* the standard ones.
+    longMessage = True
+
+    def _a_b_test(self, logger, g):
+        with start_action(action_type=u"the-action"):
+            self.assertIs(
+                None,
+                self.successResultOf(g()),
+            )
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action", [
+                u"a",
+                u"yielded",
+                u"b",
+            ],
+        )
+
+    @capture_logging(None)
+    def test_yield_none(self, logger):
+        @inline_callbacks
+        def g():
+            Message.log(message_type=u"a")
+            yield
+            Message.log(message_type=u"b")
+
+        self._a_b_test(logger, g)
+
+    @capture_logging(None)
+    def test_yield_fired_deferred(self, logger):
+        @inline_callbacks
+        def g():
+            Message.log(message_type=u"a")
+            yield succeed(None)
+            Message.log(message_type=u"b")
+
+        self._a_b_test(logger, g)
+
+    @capture_logging(None)
+    def test_yield_unfired_deferred(self, logger):
+        waiting = Deferred()
+
+        @inline_callbacks
+        def g():
+            Message.log(message_type=u"a")
+            yield waiting
+            Message.log(message_type=u"b")
+
+        with start_action(action_type=u"the-action"):
+            d = g()
+            self.assertNoResult(waiting)
+            waiting.callback(None)
+            self.assertIs(
+                None,
+                self.successResultOf(d),
+            )
+        assert_expected_action_tree(
+            self,
+            logger,
+            u"the-action", [
+                u"a",
+                u"yielded",
+                u"b",
+            ],
+        )

src/allmydata/util/eliotutil.py

@@ -0,0 +1,134 @@
+"""
+Tools aimed at the interaction between Tahoe-LAFS implementation and Eliot.
+"""
+
+from sys import exc_info
+from functools import wraps
+from contextlib import contextmanager
+from weakref import WeakKeyDictionary
+
+
+from eliot import (
+    Message,
+)
+
+from twisted.internet.defer import (
+    inlineCallbacks,
+)
+
+class _GeneratorContext(object):
+    def __init__(self, execution_context):
+        self._execution_context = execution_context
+        self._contexts = WeakKeyDictionary()
+        self._current_generator = None
+
+    def init_stack(self, generator):
+        stack = list(self._execution_context._get_stack())
+        self._contexts[generator] = stack
+
+    def get_stack(self):
+        if self._current_generator is None:
+            # If there is no currently active generator then we have no
+            # special stack to supply.  Let the execution context figure out a
+            # different answer on its own.
+            return None
+        # Otherwise, give back the action context stack we've been tracking
+        # for the currently active generator.  It must have been previously
+        # initialized (it's too late to do it now)!
+        return self._contexts[self._current_generator]
+
+    @contextmanager
+    def context(self, generator):
+        previous_generator = self._current_generator
+        try:
+            self._current_generator = generator
+            yield
+        finally:
+            self._current_generator = previous_generator
+
+
+from eliot._action import _context
+_the_generator_context = _GeneratorContext(_context)
+
+
+def use_generator_context():
+    _context.get_sub_context = _the_generator_context.get_stack
+use_generator_context()
+
+
+def eliot_friendly_generator_function(original):
+    """
+    Decorate a generator function so that the Eliot action context is
+    preserved across ``yield`` expressions.
+    """
+    @wraps(original)
+    def wrapper(*a, **kw):
+        # Keep track of whether the next value to deliver to the generator is
+        # a non-exception or an exception.
+        ok = True
+
+        # Keep track of the next value to deliver to the generator.
+        value_in = None
+
+        # Create the generator with a call to the generator function.  This
+        # happens with whatever Eliot action context happens to be active,
+        # which is fine and correct and also irrelevant because no code in the
+        # generator function can run until we call send or throw on it.
+        gen = original(*a, **kw)
+
+        # Initialize the per-generator Eliot action context stack to the
+        # current action stack.  This might be the main stack or, if another
+        # decorated generator is running, it might be the stack for that
+        # generator.  Not our business.
+        _the_generator_context.init_stack(gen)
+        while True:
+            try:
+                # Whichever way we invoke the generator, we will do it
+                # with the Eliot action context stack we've saved for it.
+                # Then the context manager will re-save it and restore the
+                # "outside" stack for us.
+                with _the_generator_context.context(gen):
+                    if ok:
+                        value_out = gen.send(value_in)
+                    else:
+                        value_out = gen.throw(*value_in)
+                    # We have obtained a value from the generator.  In
+                    # giving it to us, it has given up control.  Note this
+                    # fact here.  Importantly, this is within the
+                    # generator's action context so that we get a good
+                    # indication of where the yield occurred.
+                    #
+                    # This might be too noisy, consider dropping it or
+                    # making it optional.
+                    Message.log(message_type=u"yielded")
+            except StopIteration:
+                # When the generator raises this, it is signaling
+                # completion.  Leave the loop.
+                break
+            else:
+                try:
+                    # Pass the generator's result along to whoever is
+                    # driving.  Capture the result as the next value to
+                    # send inward.
+                    value_in = yield value_out
+                except:
+                    # Or capture the exception if that's the flavor of the
+                    # next value.
+                    ok = False
+                    value_in = exc_info()
+                else:
+                    ok = True
+
+    return wrapper
+
+
+def inline_callbacks(original):
+    """
+    Decorate a function like ``inlineCallbacks`` would but in a more
+    Eliot-friendly way.  Use it just like ``inlineCallbacks`` but where you
+    want Eliot action contexts to Do The Right Thing inside the decorated
+    function.
+    """
+    return inlineCallbacks(
+        eliot_friendly_generator_function(original)
+    )