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. 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. diff --git a/src/allmydata/scripts/runner.py b/src/allmydata/scripts/runner.py index 70ff75bf2..9b71ee708 100644 --- a/src/allmydata/scripts/runner.py +++ b/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-options]\n" + self.getUsage()) 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..8a19edcc5 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,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), + ), + ) 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 5de10ddc5..2e899741d 100644 --- a/src/allmydata/util/eliotutil.py +++ b/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:[: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): + """ + 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