Add helpers for configuring and using Eliot logging

src/allmydata/test/common.py

@@ -1,12 +1,23 @@
 import os, random, struct
 import treq
+
 from zope.interface import implementer
+
+from testtools import (
+    TestCase,
+)
+from testtools.twistedsupport import (
+    AsynchronousDeferredRunTest,
+    SynchronousDeferredRunTest,
+)
+
 from twisted.internet import defer
 from twisted.internet.defer import inlineCallbacks, returnValue
 from twisted.internet.interfaces import IPullProducer
 from twisted.python import failure
 from twisted.application import service
 from twisted.web.error import Error as WebError
+
 from allmydata import uri
 from allmydata.interfaces import IMutableFileNode, IImmutableFileNode,\
                                  NotEnoughSharesError, ICheckable, \
@@ -24,6 +35,11 @@ from allmydata.util.consumer import download_to_data
 import allmydata.test.common_util as testutil
 from allmydata.immutable.upload import Uploader
 
+from .eliotutil import (
+    eliot_logged_test,
+)
+
+
 TEST_RSA_KEY_SIZE = 522
 
 @implementer(IPullProducer)
@@ -817,3 +833,35 @@ def _corrupt_uri_extension(data, debug=False):
         uriextlen = struct.unpack(">Q", data[0x0c+uriextoffset:0x0c+uriextoffset+8])[0]
 
     return corrupt_field(data, 0x0c+uriextoffset, uriextlen)
+
+
+class _TestCaseMixin(object):
+    """
+    A mixin for ``TestCase`` which collects helpful behaviors for subclasses.
+
+    Those behaviors are:
+
+    * All of the features of testtools TestCase.
+    * Each test method will be run in a unique Eliot action context which
+      identifies the test and collects all Eliot log messages emitted by that
+      test (including setUp and tearDown messages).
+    """
+    @eliot_logged_test
+    def run(self, result):
+        return super(TestCase, self).run(result)
+
+
+class SyncTestCase(_TestCaseMixin, TestCase):
+    """
+    A ``TestCase`` which can run tests that may return an already-fired
+    ``Deferred``.
+    """
+    run_tests_with = SynchronousDeferredRunTest
+
+
+class AsyncTestCase(_TestCaseMixin, TestCase):
+    """
+    A ``TestCase`` which can run tests that may return a Deferred that will
+    only fire if the global reactor is running.
+    """
+    run_tests_with = AsynchronousDeferredRunTest

src/allmydata/test/test_eliotutil.py

@@ -2,10 +2,37 @@
 Tests for ``allmydata.test.eliotutil``.
 """
 
+from __future__ import (
+    unicode_literals,
+    print_function,
+    absolute_import,
+    division,
+)
+
 from pprint import pformat
+from sys import stdout
+import logging
+
+from fixtures import (
+    TempDir,
+)
+from testtools import (
+    TestCase,
+)
+from testtools.matchers import (
+    Is,
+    MatchesStructure,
+    Equals,
+    AfterPreprocessing,
+)
+from testtools.twistedsupport import (
+    has_no_result,
+    succeeded,
+)
 
 from eliot import (
     Message,
+    FileDestination,
     start_action,
 )
 from eliot.twisted import DeferredContext
@@ -14,7 +41,6 @@ from eliot.testing import (
     assertHasAction,
 )
 
-from twisted.trial.unittest import TestCase
 from twisted.internet.defer import (
     Deferred,
     succeed,
@@ -29,9 +55,15 @@ from .eliotutil import (
 from ..util.eliotutil import (
     eliot_friendly_generator_function,
     inline_callbacks,
+    _parse_destination_description,
+    _EliotLogging,
+)
+from .common import (
+    SyncTestCase,
+    AsyncTestCase,
 )
 
-class EliotLoggedTestTests(TestCase):
+class EliotLoggedTestTests(AsyncTestCase):
     @eliot_logged_test
     def test_returns_none(self):
         Message.log(hello="world")
@@ -101,7 +133,7 @@ def assert_generator_logs_action_tree(testcase, generator_function, logger, expe
     )
 
 
-class EliotFriendlyGeneratorFunctionTests(TestCase):
+class EliotFriendlyGeneratorFunctionTests(SyncTestCase):
     # Get our custom assertion failure messages *and* the standard ones.
     longMessage = True
 
@@ -345,16 +377,13 @@ class EliotFriendlyGeneratorFunctionTests(TestCase):
         )
 
 
-class InlineCallbacksTests(TestCase):
+class InlineCallbacksTests(SyncTestCase):
     # 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(
+            self.assertThat(g(), succeeded(Is(None)))
-                None,
-                self.successResultOf(g()),
-            )
         assert_expected_action_tree(
             self,
             logger,
@@ -397,12 +426,9 @@ class InlineCallbacksTests(TestCase):
 
         with start_action(action_type=u"the-action"):
             d = g()
-            self.assertNoResult(waiting)
+            self.assertThat(waiting, has_no_result())
             waiting.callback(None)
-            self.assertIs(
+            self.assertThat(d, succeeded(Is(None)))
-                None,
-                self.successResultOf(d),
-            )
         assert_expected_action_tree(
             self,
             logger,
@@ -412,3 +438,89 @@ class InlineCallbacksTests(TestCase):
                 u"b",
             ],
         )
+
+
+class  ParseDestinationDescriptionTests(SyncTestCase):
+    def test_stdout(self):
+        """
+        A ``file:`` description with a path of ``-`` causes logs to be written to
+        stdout.
+        """
+        reactor = object()
+        self.assertThat(
+            _parse_destination_description("file:-")(reactor),
+            Equals(FileDestination(stdout)),
+        )
+
+
+    def test_regular_file(self):
+        """
+        A ``file:`` description with any path other than ``-`` causes logs to be
+        written to a file with that name.
+        """
+        tempdir = TempDir()
+        self.useFixture(tempdir)
+
+        reactor = object()
+        path = tempdir.join("regular_file")
+
+        self.assertThat(
+            _parse_destination_description("file:{}".format(path))(reactor),
+            MatchesStructure(
+                file=MatchesStructure(
+                    path=Equals(path),
+                    rotateLength=AfterPreprocessing(bool, Equals(True)),
+                    maxRotatedFiles=AfterPreprocessing(bool, Equals(True)),
+                ),
+            ),
+        )
+
+
+# Opt out of the great features of common.SyncTestCase because we're
+# interacting with Eliot in a very obscure, particular, fragile way. :/
+class EliotLoggingTests(TestCase):
+    """
+    Tests for ``_EliotLogging``.
+    """
+    def test_stdlib_event_relayed(self):
+        """
+        An event logged using the stdlib logging module is delivered to the Eliot
+        destination.
+        """
+        collected = []
+        service = _EliotLogging([collected.append])
+        service.startService()
+        self.addCleanup(service.stopService)
+
+        # The first destination added to the global log destinations gets any
+        # buffered messages delivered to it.  We don't care about those.
+        # Throw them on the floor.  Sorry.
+        del collected[:]
+
+        logging.critical("oh no")
+        self.assertThat(
+            collected,
+            AfterPreprocessing(
+                len,
+                Equals(1),
+            ),
+        )
+
+    def test_twisted_event_relayed(self):
+        """
+        An event logged with a ``twisted.logger.Logger`` is delivered to the Eliot
+        destination.
+        """
+        collected = []
+        service = _EliotLogging([collected.append])
+        service.startService()
+        self.addCleanup(service.stopService)
+
+        from twisted.logger import Logger
+        Logger().critical("oh no")
+        self.assertThat(
+            collected,
+            AfterPreprocessing(
+                len, Equals(1),
+            ),
+        )

src/allmydata/util/eliotutil.py

@@ -13,21 +13,59 @@ __all__ = [
     "use_generator_context",
     "eliot_friendly_generator_function",
     "inline_callbacks",
+    "eliot_logging_service",
+    "opt_eliot_destination",
 ]
 
-from sys import exc_info
+from sys import (
+    exc_info,
+    stdout,
+)
 from functools import wraps
 from contextlib import contextmanager
 from weakref import WeakKeyDictionary
+from logging import (
+    INFO,
+    Handler,
+    getLogger,
+)
+from json import loads
 
-
+from zope.interface import (
-from eliot import (
+    implementer,
-    Message,
 )
 
+import attr
+from attr.validators import (
+    optional,
+    provides,
+)
+
+from eliot import (
+    ILogger,
+    Message,
+    FileDestination,
+    add_destinations,
+    remove_destination,
+    write_traceback,
+)
+
+from twisted.python.filepath import (
+    FilePath,
+)
+from twisted.python.logfile import (
+    LogFile,
+)
+from twisted.logger import (
+    ILogObserver,
+    eventAsJSON,
+    globalLogPublisher,
+)
 from twisted.internet.defer import (
     inlineCallbacks,
 )
+from twisted.application.service import Service
+
 
 class _GeneratorContext(object):
     def __init__(self, execution_context):
@@ -145,3 +183,177 @@ def inline_callbacks(original):
     return inlineCallbacks(
         eliot_friendly_generator_function(original)
     )
+
+
+def eliot_logging_service(reactor, destinations):
+    """
+    Parse the given Eliot destination descriptions and return an ``IService``
+    which will add them when started and remove them when stopped.
+
+    The following destinations are supported:
+
+    * ``file:<path>[:rotated_length=<bytes>][:max_rotated_files=<count>]``
+      Sensible defaults are supplied for rotated_length and max_rotated_files
+      if they are not given.
+    """
+    return _EliotLogging(destinations=list(
+        get_destination(reactor)
+        for get_destination
+        in destinations
+    ))
+
+
+# An Options-based argument parser for configuring Eliot logging.  Set this as
+# a same-named attribute on your Options subclass.
+def opt_eliot_destination(self, description):
+    """
+    Add an Eliot logging destination.
+    """
+    self.setdefault("destinations", []).append(
+        _parse_destination_description(description)
+    )
+
+
+
+class _EliotLogging(Service):
+    """
+    A service which adds stdout as an Eliot destination while it is running.
+    """
+    def __init__(self, destinations):
+        """
+        :param list destinations: The Eliot destinations which will is added by this
+            service.
+        """
+        self.destinations = destinations
+
+
+    def startService(self):
+        self.stdlib_cleanup = _stdlib_logging_to_eliot_configuration(getLogger())
+        self.twisted_observer = _TwistedLoggerToEliotObserver()
+        globalLogPublisher.addObserver(self.twisted_observer)
+        add_destinations(*self.destinations)
+
+
+    def stopService(self):
+        for dest in self.destinations:
+            remove_destination(dest)
+        globalLogPublisher.removeObserver(self.twisted_observer)
+        self.stdlib_cleanup()
+
+
+
+@implementer(ILogObserver)
+@attr.s(frozen=True)
+class _TwistedLoggerToEliotObserver(object):
+    """
+    An ``ILogObserver`` which re-publishes events as Eliot messages.
+    """
+    logger = attr.ib(default=None, validator=optional(provides(ILogger)))
+
+    def _observe(self, event):
+        flattened = loads(eventAsJSON(event))
+        # We get a timestamp from Eliot.
+        flattened.pop(u"log_time")
+        # This is never serializable anyway.  "Legacy" log events (from
+        # twisted.python.log) don't have this so make it optional.
+        flattened.pop(u"log_logger", None)
+
+        Message.new(
+            message_type=u"eliot:twisted",
+            **flattened
+        ).write(self.logger)
+
+
+    # The actual ILogObserver interface uses this.
+    __call__ = _observe
+
+
+class _StdlibLoggingToEliotHandler(Handler):
+    def __init__(self, logger=None):
+        Handler.__init__(self)
+        self.logger = logger
+
+    def emit(self, record):
+        Message.new(
+            message_type=u"eliot:stdlib",
+            log_level=record.levelname,
+            logger=record.name,
+            message=record.getMessage()
+        ).write(self.logger)
+
+        if record.exc_info:
+            write_traceback(
+                logger=self.logger,
+                exc_info=record.exc_info,
+            )
+
+
+def _stdlib_logging_to_eliot_configuration(stdlib_logger, eliot_logger=None):
+    """
+    Add a handler to ``stdlib_logger`` which will relay events to
+    ``eliot_logger`` (or the default Eliot logger if ``eliot_logger`` is
+    ``None``).
+    """
+    handler = _StdlibLoggingToEliotHandler(eliot_logger)
+    handler.set_name(u"eliot")
+    handler.setLevel(INFO)
+    stdlib_logger.addHandler(handler)
+    return lambda: stdlib_logger.removeHandler(handler)
+
+
+class _DestinationParser(object):
+    def parse(self, description):
+        description = description.decode(u"ascii")
+
+        kind, args = description.split(u":", 1)
+        try:
+            parser = getattr(self, u"_parse_{}".format(kind))
+        except AttributeError:
+            raise ValueError(
+                u"Unknown destination description: {}".format(description)
+            )
+        else:
+            return parser(kind, args)
+
+    def _get_arg(self, arg_name, default, arg_list):
+        return dict(
+            arg.split(u"=", 1)
+            for arg
+            in arg_list
+        ).get(
+            arg_name,
+            default,
+        )
+
+    def _parse_file(self, kind, arg_text):
+        # Reserve the possibility of an escape character in the future.
+        if u"\\" in arg_text:
+            raise ValueError(
+                u"Unsupported escape character (\\) in destination text ({!r}).".format(arg_text),
+            )
+        arg_list = arg_text.split(u":")
+        path_name = arg_list.pop(0)
+        if path_name == "-":
+            get_file = lambda: stdout
+        else:
+            path = FilePath(path_name)
+            rotate_length = int(self._get_arg(
+                u"rotate_length",
+                1024 * 1024 * 1024,
+                arg_list,
+            ))
+            max_rotated_files = int(self._get_arg(
+                u"max_rotated_files",
+                10,
+                arg_list,
+            ))
+            get_file = lambda: LogFile(
+                path.basename(),
+                path.dirname(),
+                rotateLength=rotate_length,
+                maxRotatedFiles=max_rotated_files,
+            )
+        return lambda reactor: FileDestination(get_file())
+
+
+_parse_destination_description = _DestinationParser().parse