Merge remote-tracking branch 'origin/master' into 2972.magic-folder-eliot-logs

newsfragments/2975.feature

@@ -0,0 +1 @@
+The `tahoe` CLI now accepts arguments for configuring structured logging messages which Tahoe-LAFS is being converted to emit.  This change does not introduce any new defaults for on-filesystem logging.

setup.py

@@ -273,6 +273,8 @@ setup(name="tahoe-lafs", # also set in __init__.py
               "hypothesis >= 3.6.1",
               "treq",
               "towncrier",
+              "testtools",
+              "fixtures",
           ],
           "tor": [
               "foolscap[tor] >= 0.12.5",

src/allmydata/_auto_deps.py

@@ -104,6 +104,9 @@ install_requires = [
     # 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",
+
+    # A great way to define types of values.
+    "attrs >= 18.2.0",
 ]
 
 # Includes some indirect dependencies, but does not include allmydata.
@@ -133,6 +136,7 @@ package_imports = [
     ('magic-wormhole',   'wormhole'),
     ('setuptools',       'setuptools'),
     ('eliot',            'eliot'),
+    ('attrs',            'attr'),
 ]
 
 # Dependencies for which we don't know how to get a version number at run-time.

src/allmydata/scripts/runner.py

@@ -10,6 +10,10 @@ from allmydata.scripts import debug, create_node, cli, \
     stats_gatherer, admin, magic_folder_cli, tahoe_daemonize, tahoe_start, \
     tahoe_stop, tahoe_restart, tahoe_run, tahoe_invite
 from allmydata.util.encodingutil import quote_output, quote_local_unicode_path, get_io_encoding
+from allmydata.util.eliotutil import (
+    opt_eliot_destination,
+    opt_help_eliot_destinations,
+)
 
 def GROUP(s):
     # Usage.parseOptions compares argv[1] against command[0], so it will
@@ -89,6 +93,9 @@ class Options(usage.Options):
         print >>self.stdout, allmydata.get_package_versions_string(show_paths=True, debug=True)
         self.no_command_needed = True
 
+    opt_eliot_destination = opt_eliot_destination
+    opt_help_eliot_destinations = opt_help_eliot_destinations
+
     def __str__(self):
         return ("\nUsage: tahoe [global-options] <command> [command-options]\n"
                 + self.getUsage())

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(
-                None,
-                self.successResultOf(g()),
-            )
+            self.assertThat(g(), succeeded(Is(None)))
         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(
-                None,
-                self.successResultOf(d),
-            )
+            self.assertThat(d, succeeded(Is(None)))
         assert_expected_action_tree(
             self,
             logger,
@@ -412,3 +438,92 @@ class InlineCallbacksTests(TestCase):
                 u"b",
             ],
         )
+
+
+class  ParseDestinationDescriptionTests(SyncTestCase):
+    """
+    Tests for ``_parse_destination_description``.
+    """
+    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/test/test_runner.py

@@ -168,6 +168,25 @@ class BinTahoe(common_util.SignalMixin, unittest.TestCase, RunBinTahoeMixin):
         d.addCallback(_cb)
         return d
 
+    @inlineCallbacks
+    def test_help_eliot_destinations(self):
+        out, err, rc_or_sig = yield self.run_bintahoe(["--help-eliot-destinations"])
+        self.assertIn("\tfile:<path>", out)
+        self.assertEqual(rc_or_sig, 0)
+
+    @inlineCallbacks
+    def test_eliot_destination(self):
+        out, err, rc_or_sig = yield self.run_bintahoe([
+            # Proves little but maybe more than nothing.
+            "--eliot-destination=file:-",
+            # Throw in *some* command or the process exits with error, making
+            # it difficult for us to see if the previous arg was accepted or
+            # not.
+            "--help",
+        ])
+        self.assertEqual(rc_or_sig, 0)
+
+
 
 class CreateNode(unittest.TestCase):
     # exercise "tahoe create-node", create-introducer,

src/allmydata/util/eliotutil.py

@@ -5,13 +5,17 @@ Tools aimed at the interaction between Tahoe-LAFS implementation and Eliot.
 from __future__ import (
     unicode_literals,
     print_function,
-    division,
     absolute_import,
+    division,
 )
 
 __all__ = [
+    "use_generator_context",
     "eliot_friendly_generator_function",
     "inline_callbacks",
+    "eliot_logging_service",
+    "opt_eliot_destination",
+    "opt_help_eliot_destinations",
     "validateInstanceOf",
     "validateSetMembership",
     "RELPATH",
@@ -22,16 +26,38 @@ __all__ = [
     "PATHINFO",
 ]
 
-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 eliot import (
-    Message,
+from zope.interface import (
+    implementer,
 )
 
+import attr
+from attr.validators import (
+    optional,
+    provides,
+)
+
+from eliot import (
+    ILogger,
+    Message,
+    FileDestination,
+    add_destinations,
+    remove_destination,
+    write_traceback,
+)
 from eliot import (
     Field,
 )
@@ -39,9 +65,22 @@ from eliot._validation import (
     ValidationError,
 )
 
+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
+
 
 from .fileutil import (
     PathInfo,
@@ -226,3 +265,189 @@ PATHINFO = Field(
     u"The metadata for this version of this file.",
     validateInstanceOf((type(None), PathInfo)),
 )
+
+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.
+
+    See ``--help-eliot-destinations`` for details about supported
+    destinations.
+    """
+    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.  May be given more than once.
+    """
+    self.setdefault("destinations", []).append(
+        _parse_destination_description(description)
+    )
+
+
+def opt_help_eliot_destinations(self):
+    """
+    Emit usage information for --eliot-destination.
+    """
+    print(
+        "Available destinations:\n"
+        # Might want to generate this from some metadata someday but we just
+        # have one hard-coded destination type now, it's easier to hard-code
+        # the help.
+        "\tfile:<path>[:rotate_length=<bytes>][:max_rotated_files=<count>]\n"
+        "\tSensible defaults are supplied for rotate_length and max_rotated_files\n"
+        "\tif they are not given.\n",
+        file=self.stdout,
+    )
+    raise SystemExit(0)
+
+
+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