From 5fef83078d863843ef1f5f8a35990bfc3fcdb338 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 29 Nov 2021 13:08:11 -0500 Subject: [PATCH 1/6] news fragment --- newsfragments/3847.minor | 0 1 file changed, 0 insertions(+), 0 deletions(-) create mode 100644 newsfragments/3847.minor diff --git a/newsfragments/3847.minor b/newsfragments/3847.minor new file mode 100644 index 0000000000..e69de29bb2 From 66a0c6f3f43ecd018cdbb571ebd6eab740b6cca7 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 29 Nov 2021 13:43:06 -0500 Subject: [PATCH 2/6] add a direct test for the non-utf-8 bytestring behavior --- src/allmydata/test/test_eliotutil.py | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/allmydata/test/test_eliotutil.py b/src/allmydata/test/test_eliotutil.py index 3f915ecd27..00110530cb 100644 --- a/src/allmydata/test/test_eliotutil.py +++ b/src/allmydata/test/test_eliotutil.py @@ -78,6 +78,9 @@ class EliotLoggedTestTests(AsyncTestCase): + """ + Tests for the automatic log-related provided by ``EliotLoggedRunTest``. + """ def test_returns_none(self): Message.log(hello="world") @@ -95,6 +98,12 @@ def test_returns_unfired_deferred(self): # We didn't start an action. We're not finishing an action. return d.result + def test_logs_non_utf_8_byte(self): + """ + If an Eliot message is emitted that contains a non-UTF-8 byte string then + the test nevertheless passes. + """ + Message.log(hello=b"\xFF") class ParseDestinationDescriptionTests(SyncTestCase): From f40da7dc27d089e3bdfdca48e51aec25aea282c0 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 29 Nov 2021 13:23:59 -0500 Subject: [PATCH 3/6] Put the choice of JSON encoder for Eliot into its own module and use it in a few places --- src/allmydata/test/__init__.py | 4 ++-- src/allmydata/test/test_eliotutil.py | 4 ++-- src/allmydata/util/_eliot_updates.py | 28 ++++++++++++++++++++++++++++ src/allmydata/util/eliotutil.py | 7 ++++--- 4 files changed, 36 insertions(+), 7 deletions(-) create mode 100644 src/allmydata/util/_eliot_updates.py diff --git a/src/allmydata/test/__init__.py b/src/allmydata/test/__init__.py index 893aa15ce9..ad245ca77d 100644 --- a/src/allmydata/test/__init__.py +++ b/src/allmydata/test/__init__.py @@ -125,5 +125,5 @@ def _listening(lp): initialize() from eliot import to_file -from allmydata.util.jsonbytes import AnyBytesJSONEncoder -to_file(open("eliot.log", "wb"), encoder=AnyBytesJSONEncoder) +from allmydata.util.eliotutil import eliot_json_encoder +to_file(open("eliot.log", "wb"), encoder=eliot_json_encoder) diff --git a/src/allmydata/test/test_eliotutil.py b/src/allmydata/test/test_eliotutil.py index 00110530cb..0be02b2770 100644 --- a/src/allmydata/test/test_eliotutil.py +++ b/src/allmydata/test/test_eliotutil.py @@ -65,11 +65,11 @@ from twisted.internet import reactor from ..util.eliotutil import ( + eliot_json_encoder, log_call_deferred, _parse_destination_description, _EliotLogging, ) -from ..util.jsonbytes import AnyBytesJSONEncoder from .common import ( SyncTestCase, @@ -118,7 +118,7 @@ def test_stdout(self): reactor = object() self.assertThat( _parse_destination_description("file:-")(reactor), - Equals(FileDestination(stdout, encoder=AnyBytesJSONEncoder)), + Equals(FileDestination(stdout, encoder=eliot_json_encoder)), ) diff --git a/src/allmydata/util/_eliot_updates.py b/src/allmydata/util/_eliot_updates.py new file mode 100644 index 0000000000..4300f2be82 --- /dev/null +++ b/src/allmydata/util/_eliot_updates.py @@ -0,0 +1,28 @@ +""" +Bring in some Eliot updates from newer versions of Eliot than we can +depend on in Python 2. + +Every API in this module (except ``eliot_json_encoder``) should be obsolete as +soon as we depend on Eliot 1.14 or newer. + +Ported to Python 3. +""" + +from __future__ import absolute_import +from __future__ import division +from __future__ import print_function +from __future__ import unicode_literals + +from future.utils import PY2 +if PY2: + from builtins import filter, map, zip, ascii, chr, hex, input, next, oct, open, pow, round, super, bytes, dict, list, object, range, str, max, min # noqa: F401 + +from .jsonbytes import AnyBytesJSONEncoder + +# There are currently a number of log messages that include non-UTF-8 bytes. +# Allow these, at least for now. Later when the whole test suite has been +# converted to our SyncTestCase or AsyncTestCase it will be easier to turn +# this off and then attribute log failures to specific codepaths so they can +# be fixed (and then not regressed later) because those instances will result +# in test failures instead of only garbage being written to the eliot log. +eliot_json_encoder = AnyBytesJSONEncoder diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index 4e48fbb9f9..ff858531da 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -87,8 +87,9 @@ ) from twisted.application.service import Service -from .jsonbytes import AnyBytesJSONEncoder - +from ._eliot_updates import ( + eliot_json_encoder, +) def validateInstanceOf(t): """ @@ -306,7 +307,7 @@ def get_file(): rotateLength=rotate_length, maxRotatedFiles=max_rotated_files, ) - return lambda reactor: FileDestination(get_file(), AnyBytesJSONEncoder) + return lambda reactor: FileDestination(get_file(), eliot_json_encoder) _parse_destination_description = _DestinationParser().parse From 3eb1a5e7cb6bc227feda6f254b43e35b1807446d Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 29 Nov 2021 13:25:03 -0500 Subject: [PATCH 4/6] Add a MemoryLogger that prefers our encoder and use it instead of Eliot's --- src/allmydata/test/eliotutil.py | 16 ++----- src/allmydata/util/_eliot_updates.py | 62 +++++++++++++++++++++++++++- src/allmydata/util/eliotutil.py | 2 + 3 files changed, 67 insertions(+), 13 deletions(-) diff --git a/src/allmydata/test/eliotutil.py b/src/allmydata/test/eliotutil.py index 1685744fd9..dd21f1e9d2 100644 --- a/src/allmydata/test/eliotutil.py +++ b/src/allmydata/test/eliotutil.py @@ -42,7 +42,6 @@ from eliot import ( ActionType, Field, - MemoryLogger, ILogger, ) from eliot.testing import ( @@ -54,8 +53,9 @@ MonkeyPatcher, ) -from ..util.jsonbytes import AnyBytesJSONEncoder - +from ..util.eliotutil import ( + MemoryLogger, +) _NAME = Field.for_types( u"name", @@ -71,14 +71,6 @@ ) -# On Python 3, we want to use our custom JSON encoder when validating messages -# can be encoded to JSON: -if PY2: - _memory_logger = MemoryLogger -else: - _memory_logger = lambda: MemoryLogger(encoder=AnyBytesJSONEncoder) - - @attr.s class EliotLoggedRunTest(object): """ @@ -170,7 +162,7 @@ def with_logging( """ @wraps(test_method) def run_with_logging(*args, **kwargs): - validating_logger = _memory_logger() + validating_logger = MemoryLogger() original = swap_logger(None) try: swap_logger(_TwoLoggers(original, validating_logger)) diff --git a/src/allmydata/util/_eliot_updates.py b/src/allmydata/util/_eliot_updates.py index 4300f2be82..4ff0caf4de 100644 --- a/src/allmydata/util/_eliot_updates.py +++ b/src/allmydata/util/_eliot_updates.py @@ -1,6 +1,7 @@ """ Bring in some Eliot updates from newer versions of Eliot than we can -depend on in Python 2. +depend on in Python 2. The implementations are copied from Eliot 1.14 and +only changed enough to add Python 2 compatibility. Every API in this module (except ``eliot_json_encoder``) should be obsolete as soon as we depend on Eliot 1.14 or newer. @@ -17,6 +18,13 @@ if PY2: from builtins import filter, map, zip, ascii, chr, hex, input, next, oct, open, pow, round, super, bytes, dict, list, object, range, str, max, min # noqa: F401 +import json as pyjson +from functools import partial + +from eliot import ( + MemoryLogger as _MemoryLogger, +) + from .jsonbytes import AnyBytesJSONEncoder # There are currently a number of log messages that include non-UTF-8 bytes. @@ -26,3 +34,55 @@ # be fixed (and then not regressed later) because those instances will result # in test failures instead of only garbage being written to the eliot log. eliot_json_encoder = AnyBytesJSONEncoder + +class _CustomEncoderMemoryLogger(_MemoryLogger): + """ + Override message validation from the Eliot-supplied ``MemoryLogger`` to + use our chosen JSON encoder. + + This is only necessary on Python 2 where we use an old version of Eliot + that does not parameterize the encoder. + """ + def __init__(self, encoder=eliot_json_encoder): + """ + @param encoder: A JSONEncoder subclass to use when encoding JSON. + """ + self._encoder = encoder + super(_CustomEncoderMemoryLogger, self).__init__() + + def _validate_message(self, dictionary, serializer): + """Validate an individual message. + + As a side-effect, the message is replaced with its serialized contents. + + @param dictionary: A message C{dict} to be validated. Might be mutated + by the serializer! + + @param serializer: C{None} or a serializer. + + @raises TypeError: If a field name is not unicode, or the dictionary + fails to serialize to JSON. + + @raises eliot.ValidationError: If serializer was given and validation + failed. + """ + if serializer is not None: + serializer.validate(dictionary) + for key in dictionary: + if not isinstance(key, str): + if isinstance(key, bytes): + key.decode("utf-8") + else: + raise TypeError(dictionary, "%r is not unicode" % (key,)) + if serializer is not None: + serializer.serialize(dictionary) + + try: + pyjson.dumps(dictionary, cls=self._encoder) + except Exception as e: + raise TypeError("Message %s doesn't encode to JSON: %s" % (dictionary, e)) + +if PY2: + MemoryLogger = partial(_CustomEncoderMemoryLogger, encoder=eliot_json_encoder) +else: + MemoryLogger = partial(_MemoryLogger, encoder=eliot_json_encoder) diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index ff858531da..5067876c5e 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -16,6 +16,7 @@ ) __all__ = [ + "MemoryLogger", "inline_callbacks", "eliot_logging_service", "opt_eliot_destination", @@ -88,6 +89,7 @@ from twisted.application.service import Service from ._eliot_updates import ( + MemoryLogger, eliot_json_encoder, ) From 20e0626e424276c83cd1f2eb42fdddb7cf56072e Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 29 Nov 2021 13:27:17 -0500 Subject: [PATCH 5/6] add capture_logging that parameterizes JSON encoder --- src/allmydata/util/_eliot_updates.py | 100 ++++++++++++++++++++++++++- src/allmydata/util/eliotutil.py | 13 +--- 2 files changed, 102 insertions(+), 11 deletions(-) diff --git a/src/allmydata/util/_eliot_updates.py b/src/allmydata/util/_eliot_updates.py index 4ff0caf4de..8e3beca450 100644 --- a/src/allmydata/util/_eliot_updates.py +++ b/src/allmydata/util/_eliot_updates.py @@ -19,12 +19,17 @@ from builtins import filter, map, zip, ascii, chr, hex, input, next, oct, open, pow, round, super, bytes, dict, list, object, range, str, max, min # noqa: F401 import json as pyjson -from functools import partial +from functools import wraps, partial from eliot import ( MemoryLogger as _MemoryLogger, ) +from eliot.testing import ( + check_for_errors, + swap_logger, +) + from .jsonbytes import AnyBytesJSONEncoder # There are currently a number of log messages that include non-UTF-8 bytes. @@ -86,3 +91,96 @@ def _validate_message(self, dictionary, serializer): MemoryLogger = partial(_CustomEncoderMemoryLogger, encoder=eliot_json_encoder) else: MemoryLogger = partial(_MemoryLogger, encoder=eliot_json_encoder) + +def validateLogging( + assertion, *assertionArgs, **assertionKwargs +): + """ + Decorator factory for L{unittest.TestCase} methods to add logging + validation. + + 1. The decorated test method gets a C{logger} keyword argument, a + L{MemoryLogger}. + 2. All messages logged to this logger will be validated at the end of + the test. + 3. Any unflushed logged tracebacks will cause the test to fail. + + For example: + + from unittest import TestCase + from eliot.testing import assertContainsFields, validateLogging + + class MyTests(TestCase): + def assertFooLogging(self, logger): + assertContainsFields(self, logger.messages[0], {"key": 123}) + + + @param assertion: A callable that will be called with the + L{unittest.TestCase} instance, the logger and C{assertionArgs} and + C{assertionKwargs} once the actual test has run, allowing for extra + logging-related assertions on the effects of the test. Use L{None} if you + want the cleanup assertions registered but no custom assertions. + + @param assertionArgs: Additional positional arguments to pass to + C{assertion}. + + @param assertionKwargs: Additional keyword arguments to pass to + C{assertion}. + + @param encoder_: C{json.JSONEncoder} subclass to use when validating JSON. + """ + encoder_ = assertionKwargs.pop("encoder_", eliot_json_encoder) + def decorator(function): + @wraps(function) + def wrapper(self, *args, **kwargs): + skipped = False + + kwargs["logger"] = logger = MemoryLogger(encoder=encoder_) + self.addCleanup(check_for_errors, logger) + # TestCase runs cleanups in reverse order, and we want this to + # run *before* tracebacks are checked: + if assertion is not None: + self.addCleanup( + lambda: skipped + or assertion(self, logger, *assertionArgs, **assertionKwargs) + ) + try: + return function(self, *args, **kwargs) + except self.skipException: + skipped = True + raise + + return wrapper + + return decorator + +# PEP 8 variant: +validate_logging = validateLogging + +def capture_logging( + assertion, *assertionArgs, **assertionKwargs +): + """ + Capture and validate all logging that doesn't specify a L{Logger}. + + See L{validate_logging} for details on the rest of its behavior. + """ + encoder_ = assertionKwargs.pop("encoder_", eliot_json_encoder) + def decorator(function): + @validate_logging( + assertion, *assertionArgs, encoder_=encoder_, **assertionKwargs + ) + @wraps(function) + def wrapper(self, *args, **kwargs): + logger = kwargs["logger"] + previous_logger = swap_logger(logger) + + def cleanup(): + swap_logger(previous_logger) + + self.addCleanup(cleanup) + return function(self, *args, **kwargs) + + return wrapper + + return decorator diff --git a/src/allmydata/util/eliotutil.py b/src/allmydata/util/eliotutil.py index 5067876c5e..789ef38ff1 100644 --- a/src/allmydata/util/eliotutil.py +++ b/src/allmydata/util/eliotutil.py @@ -23,6 +23,7 @@ "opt_help_eliot_destinations", "validateInstanceOf", "validateSetMembership", + "capture_logging", ] from future.utils import PY2 @@ -33,7 +34,7 @@ from sys import ( stdout, ) -from functools import wraps, partial +from functools import wraps from logging import ( INFO, Handler, @@ -67,8 +68,6 @@ DeferredContext, inline_callbacks, ) -from eliot.testing import capture_logging as eliot_capture_logging - from twisted.python.usage import ( UsageError, ) @@ -91,6 +90,7 @@ from ._eliot_updates import ( MemoryLogger, eliot_json_encoder, + capture_logging, ) def validateInstanceOf(t): @@ -330,10 +330,3 @@ def logged_f(*a, **kw): return DeferredContext(d).addActionFinish() return logged_f return decorate_log_call_deferred - -# On Python 3, encoding bytes to JSON doesn't work, so we have a custom JSON -# encoder we want to use when validating messages. -if PY2: - capture_logging = eliot_capture_logging -else: - capture_logging = partial(eliot_capture_logging, encoder_=AnyBytesJSONEncoder) From 7626a02bdb84013e4f45bad81c8a3f5ba4586401 Mon Sep 17 00:00:00 2001 From: Jean-Paul Calderone Date: Mon, 29 Nov 2021 13:27:28 -0500 Subject: [PATCH 6/6] remove redundant assertion --- src/allmydata/test/test_util.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/src/allmydata/test/test_util.py b/src/allmydata/test/test_util.py index a03845ed6d..9a0af1e06a 100644 --- a/src/allmydata/test/test_util.py +++ b/src/allmydata/test/test_util.py @@ -553,11 +553,6 @@ def test_any_bytes(self): o, cls=jsonbytes.AnyBytesJSONEncoder)), expected, ) - self.assertEqual( - json.loads(jsonbytes.dumps(o, any_bytes=True)), - expected - ) - class FakeGetVersion(object):