From f90a1375520b9c21260a2062910992ece6b2329c Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 08:57:38 -0500 Subject: [PATCH 1/8] Basic housekeeping previously missed --- src/allmydata/util/eliotutil.py | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index a2bd9a583..a8018bf4a 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -2,6 +2,19 @@ Tools aimed at the interaction between Tahoe-LAFS implementation and Eliot. """ +from __future__ import ( + unicode_literals, + print_function, + absolute_import, + division, +) + +__all__ = [ + "use_generator_context", + "eliot_friendly_generator_function", + "inline_callbacks", +] + from sys import exc_info from functools import wraps from contextlib import contextmanager From abae1be9c69731de65f6795bdeac3bffd30c9672 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 11:52:50 -0500 Subject: [PATCH 2/8] Add helpers for configuring and using Eliot logging --- src/allmydata/test/common.py | 48 ++++++ src/allmydata/test/test_eliotutil.py | 138 +++++++++++++++-- src/allmydata/util/eliotutil.py | 220 ++++++++++++++++++++++++++- 3 files changed, 389 insertions(+), 17 deletions(-) diff --git a/src/allmydata/test/common.py b/src/allmydata/test/common.py index f0cccb48b..30e6b6818 100644 --- a/src/allmydata/test/common.py +++ b/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 diff --git a/src/allmydata/test/test_eliotutil.py b/src/allmydata/test/test_eliotutil.py index 3f2a75815..a5d5a6969 100644 --- a/src/allmydata/test/test_eliotutil.py +++ b/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,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), + ), + ) diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index a8018bf4a..a863f29c4 100644 --- a/src/allmydata/util/eliotutil.py +++ b/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 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 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:[:rotated_length=][:max_rotated_files=]`` + 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 From f20184ce95c5fd6079c9a6f53f79432aa641591a Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 11:55:47 -0500 Subject: [PATCH 3/8] Declare our new dependencies --- setup.py | 2 ++ src/allmydata/_auto_deps.py | 4 ++++ 2 files changed, 6 insertions(+) diff --git a/setup.py b/setup.py index 4c20b432c..3d4ccc4c0 100644 --- a/setup.py +++ b/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", diff --git a/src/allmydata/_auto_deps.py b/src/allmydata/_auto_deps.py index 05f840e34..78fa672fe 100644 --- a/src/allmydata/_auto_deps.py +++ b/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. From 4f238d0f640b799d7b785557d3e573dab0869523 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 13:11:52 -0500 Subject: [PATCH 4/8] Clarify possible usage here --- src/allmydata/util/eliotutil.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index a863f29c4..22872e952 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -207,7 +207,7 @@ def eliot_logging_service(reactor, destinations): # a same-named attribute on your Options subclass. def opt_eliot_destination(self, description): """ - Add an Eliot logging destination. + Add an Eliot logging destination. May be given more than once. """ self.setdefault("destinations", []).append( _parse_destination_description(description) From 67ca5c4b4c38459c478c921136b64fcde17f7fbb Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 13:12:03 -0500 Subject: [PATCH 5/8] Give the top-level command --eliot-destination --- src/allmydata/scripts/runner.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/src/allmydata/scripts/runner.py b/src/allmydata/scripts/runner.py index 70ff75bf2..820e88bc6 100644 --- a/src/allmydata/scripts/runner.py +++ b/src/allmydata/scripts/runner.py @@ -10,6 +10,9 @@ 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, +) def GROUP(s): # Usage.parseOptions compares argv[1] against command[0], so it will @@ -89,6 +92,8 @@ 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 + def __str__(self): return ("\nUsage: tahoe [global-options] [command-options]\n" + self.getUsage()) From 1cf4fd46ed56f9b9d1ba679a92bc02d377e4cd39 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 13:15:09 -0500 Subject: [PATCH 6/8] class docstring --- src/allmydata/test/test_eliotutil.py | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/allmydata/test/test_eliotutil.py b/src/allmydata/test/test_eliotutil.py index a5d5a6969..8a19edcc5 100644 --- a/src/allmydata/test/test_eliotutil.py +++ b/src/allmydata/test/test_eliotutil.py @@ -441,6 +441,9 @@ class InlineCallbacksTests(SyncTestCase): 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 From 7fb695f956faaede9dbbb38cb149c3e01556392f Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 13:34:02 -0500 Subject: [PATCH 7/8] Add user-facing help about destinations --- src/allmydata/scripts/runner.py | 2 ++ src/allmydata/test/test_runner.py | 19 +++++++++++++++++++ src/allmydata/util/eliotutil.py | 24 +++++++++++++++++++----- 3 files changed, 40 insertions(+), 5 deletions(-) diff --git a/src/allmydata/scripts/runner.py b/src/allmydata/scripts/runner.py index 820e88bc6..9b71ee708 100644 --- a/src/allmydata/scripts/runner.py +++ b/src/allmydata/scripts/runner.py @@ -12,6 +12,7 @@ from allmydata.scripts import debug, create_node, cli, \ 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): @@ -93,6 +94,7 @@ class Options(usage.Options): 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-options]\n" diff --git a/src/allmydata/test/test_runner.py b/src/allmydata/test/test_runner.py index 731be35a0..c47670ca7 100644 --- a/src/allmydata/test/test_runner.py +++ b/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:", 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, diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index 22872e952..29992944c 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -15,6 +15,7 @@ __all__ = [ "inline_callbacks", "eliot_logging_service", "opt_eliot_destination", + "opt_help_eliot_destinations", ] from sys import ( @@ -190,11 +191,8 @@ 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:[:rotated_length=][:max_rotated_files=]`` - Sensible defaults are supplied for rotated_length and max_rotated_files - if they are not given. + See ``--help-eliot-destinations`` for details about supported + destinations. """ return _EliotLogging(destinations=list( get_destination(reactor) @@ -214,6 +212,22 @@ def opt_eliot_destination(self, 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:[:rotate_length=][:max_rotated_files=]\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): """ From da75d43500b793b6278d8f0cf882f45b88c97d72 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 25 Feb 2019 13:45:18 -0500 Subject: [PATCH 8/8] news fragment --- newsfragments/2975.feature | 1 + 1 file changed, 1 insertion(+) create mode 100644 newsfragments/2975.feature diff --git a/newsfragments/2975.feature b/newsfragments/2975.feature new file mode 100644 index 000000000..596a11d4e --- /dev/null +++ b/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.