diff --git a/docs/source/news.rst b/docs/source/news.rst index a33af13..501d6cf 100644 --- a/docs/source/news.rst +++ b/docs/source/news.rst @@ -9,6 +9,10 @@ Features: * ``Action.continue_task`` now takes ``action_task`` and extra fields to use for the action, so the default ``eliot:remote_task`` can be changed. * Added support for Python 3.10. +Bug fixes: + +* Fix infinite recursion when a logging destination raises exceptions forever. Thanks to to @alextatarinov. + 1.13.0 ^^^^^^ diff --git a/eliot/_action.py b/eliot/_action.py index 56d9b4f..7ecbd11 100644 --- a/eliot/_action.py +++ b/eliot/_action.py @@ -440,7 +440,9 @@ def log(self, message_type, **fields): fields[TASK_UUID_FIELD] = self._identification[TASK_UUID_FIELD] fields[TASK_LEVEL_FIELD] = self._nextTaskLevel().as_list() fields[MESSAGE_TYPE_FIELD] = message_type - self._logger.write(fields, fields.pop("__eliot_serializer__", None)) + # Loggers will hopefully go away... + logger = fields.pop("__eliot_logger__", self._logger) + logger.write(fields, fields.pop("__eliot_serializer__", None)) class WrongTask(Exception): @@ -951,10 +953,10 @@ def log_message(message_type, **fields): If there is no current action, a new UUID will be generated. """ - # Loggers will hopefully go away... - logger = fields.pop("__eliot_logger__", None) action = current_action() if action is None: + # Loggers will hopefully go away... + logger = fields.pop("__eliot_logger__", None) action = Action(logger, str(uuid4()), TaskLevel(level=[]), "") action.log(message_type, **fields) diff --git a/eliot/_message.py b/eliot/_message.py index d8eaef6..ca4aa52 100644 --- a/eliot/_message.py +++ b/eliot/_message.py @@ -116,10 +116,10 @@ def write(self, logger=None, action=None): Byte field names will be converted to Unicode. @type logger: L{eliot.ILogger} or C{None} indicating the default one. + Should not be set if the action is also set. - @param action: The L{Action} which is the context for this message. If - C{None}, the L{Action} will be deduced from the current call - stack. + @param action: The L{Action} which is the context for this message. If + C{None}, the L{Action} will be deduced from the current call stack. """ fields = dict(self._contents) if "message_type" not in fields: @@ -127,7 +127,8 @@ def write(self, logger=None, action=None): if self._serializer is not None: fields["__eliot_serializer__"] = self._serializer if action is None: - fields["__eliot_logger__"] = logger + if logger is not None: + fields["__eliot_logger__"] = logger log_message(**fields) else: action.log(**fields) diff --git a/eliot/_output.py b/eliot/_output.py index debff7c..9d22e1d 100644 --- a/eliot/_output.py +++ b/eliot/_output.py @@ -2,7 +2,6 @@ Implementation of hooks and APIs for outputting log messages. """ -import sys import traceback import inspect import json as pyjson @@ -22,16 +21,9 @@ from ._validation import ValidationError -class _DestinationsSendError(Exception): - """ - An error occured sending to one or more destinations. - - @ivar errors: A list of tuples output from C{sys.exc_info()}. - """ - - def __init__(self, errors): - self.errors = errors - Exception.__init__(self, errors) +# Action type for log messages due to a (hopefully temporarily) broken +# destination. +DESTINATION_FAILURE = "eliot:destination_failure" class BufferingDestination(object): @@ -70,24 +62,57 @@ def addGlobalFields(self, **fields): """ self._globalFields.update(fields) - def send(self, message): + def send(self, message, logger=None): """ Deliver a message to all destinations. The passed in message might be mutated. + This should never raise an exception. + @param message: A message dictionary that can be serialized to JSON. @type message: L{dict} + + @param logger: The ``ILogger`` that wrote the message, if any. """ message.update(self._globalFields) errors = [] + is_destination_error_message = ( + message.get("message_type", None) == DESTINATION_FAILURE + ) for dest in self._destinations: try: dest(message) + except Exception as e: + # If the destination is broken not because of a specific + # message, but rather continously, we will get a + # "eliot:destination_failure" log message logged, and so we + # want to ensure it doesn't do infinite recursion. + if not is_destination_error_message: + errors.append(e) + + for exception in errors: + from ._action import log_message + + try: + new_msg = { + MESSAGE_TYPE_FIELD: DESTINATION_FAILURE, + REASON_FIELD: safeunicode(exception), + EXCEPTION_FIELD: exception.__class__.__module__ + + "." + + exception.__class__.__name__, + "message": _safe_unicode_dictionary(message), + } + if logger is not None: + # This is really only useful for testing, should really + # figure out way to get rid of this mechanism... + new_msg["__eliot_logger__"] = logger + log_message(**new_msg) except: - errors.append(sys.exc_info()) - if errors: - raise _DestinationsSendError(errors) + # Nothing we can do here, raising exception to caller will + # break business logic, better to have that continue to + # work even if logging isn't. + pass def add(self, *destinations): """ @@ -144,6 +169,28 @@ def write(dictionary, serializer=None): """ +def _safe_unicode_dictionary(dictionary): + """ + Serialize a dictionary to a unicode string no matter what it contains. + + The resulting dictionary will loosely follow Python syntax but it is + not expected to actually be a lossless encoding in all cases. + + @param dictionary: A L{dict} to serialize. + + @return: A L{unicode} string representing the input dictionary as + faithfully as can be done without putting in too much effort. + """ + try: + return str( + dict( + (saferepr(key), saferepr(value)) for (key, value) in dictionary.items() + ) + ) + except: + return saferepr(dictionary) + + @implementer(ILogger) class Logger(object): """ @@ -155,29 +202,6 @@ class Logger(object): """ _destinations = Destinations() - _log_tracebacks = True - - def _safeUnicodeDictionary(self, dictionary): - """ - Serialize a dictionary to a unicode string no matter what it contains. - - The resulting dictionary will loosely follow Python syntax but it is - not expected to actually be a lossless encoding in all cases. - - @param dictionary: A L{dict} to serialize. - - @return: A L{unicode} string representing the input dictionary as - faithfully as can be done without putting in too much effort. - """ - try: - return str( - dict( - (saferepr(key), saferepr(value)) - for (key, value) in dictionary.items() - ) - ) - except: - return saferepr(dictionary) def write(self, dictionary, serializer=None): """ @@ -193,38 +217,12 @@ def write(self, dictionary, serializer=None): log_message( "eliot:serialization_failure", - message=self._safeUnicodeDictionary(dictionary), + message=_safe_unicode_dictionary(dictionary), __eliot_logger__=self, ) return - try: - self._destinations.send(dictionary) - except _DestinationsSendError as e: - from ._action import log_message - - if self._log_tracebacks: - for (exc_type, exception, exc_traceback) in e.errors: - # Can't use same Logger as serialization errors because - # if destination continues to error out we will get - # infinite recursion. So instead we have to manually - # construct a Logger that won't retry. - logger = Logger() - logger._log_tracebacks = False - logger._destinations = self._destinations - msg = { - MESSAGE_TYPE_FIELD: "eliot:destination_failure", - REASON_FIELD: safeunicode(exception), - EXCEPTION_FIELD: exc_type.__module__ + "." + exc_type.__name__, - "message": self._safeUnicodeDictionary(dictionary), - "__eliot_logger__": logger, - } - log_message(**msg) - else: - # Nothing we can do here, raising exception to caller will - # break business logic, better to have that continue to - # work even if logging isn't. - pass + self._destinations.send(dictionary, self) def exclusively(f): diff --git a/eliot/tests/test_output.py b/eliot/tests/test_output.py index 6b608c6..078f3e1 100644 --- a/eliot/tests/test_output.py +++ b/eliot/tests/test_output.py @@ -27,8 +27,9 @@ bytesjson as json, to_file, FileDestination, - _DestinationsSendError, + _safe_unicode_dictionary, ) +from .._action import start_action from .._validation import ValidationError, Field, _MessageSerializer from .._traceback import write_traceback from ..testing import assertContainsFields @@ -372,7 +373,7 @@ def test_send(self): self.assertEqual(dest2, [message]) self.assertEqual(dest3, [message]) - def test_destinationExceptionMultipleDestinations(self): + def test_destination_exception_multiple_destinations(self): """ If one destination throws an exception, other destinations still get the message. @@ -386,10 +387,11 @@ def test_destinationExceptionMultipleDestinations(self): destinations.add(dest3.append) message = {"hello": 123} - self.assertRaises(_DestinationsSendError, destinations.send, {"hello": 123}) - self.assertEqual((dest, dest3), ([message], [message])) + destinations.send(message) + self.assertIn(message, dest) + self.assertIn(message, dest3) - def test_destinationExceptionContinue(self): + def test_destination_exception_continue(self): """ If a destination throws an exception, future messages are still sent to it. @@ -398,9 +400,12 @@ def test_destinationExceptionContinue(self): dest = BadDestination() destinations.add(dest) - self.assertRaises(_DestinationsSendError, destinations.send, {"hello": 123}) - destinations.send({"hello": 200}) - self.assertEqual(dest, [{"hello": 200}]) + msg1 = {"hello": 123} + msg2 = {"world": 456} + destinations.send(msg1) + self.assertNotIn(msg1, dest) + destinations.send(msg2) + self.assertIn(msg2, dest) def test_remove(self): """ @@ -560,9 +565,9 @@ def test_passedInDictionaryUnmodified(self): logger.write(d, serializer) self.assertEqual(d, original) - def test_safeUnicodeDictionary(self): + def test_safe_unicode_dictionary(self): """ - L{Logger._safeUnicodeDictionary} converts the given dictionary's + L{_safe_unicode_dictionary} converts the given dictionary's values and keys to unicode using C{safeunicode}. """ @@ -573,20 +578,20 @@ def __repr__(self): dictionary = {badobject(): 123, 123: badobject()} badMessage = "eliot: unknown, unicode() raised exception" self.assertEqual( - eval(Logger()._safeUnicodeDictionary(dictionary)), + eval(_safe_unicode_dictionary(dictionary)), {badMessage: "123", "123": badMessage}, ) - def test_safeUnicodeDictionaryFallback(self): + def test_safe_unicode_dictionary_fallback(self): """ If converting the dictionary failed for some reason, - L{Logger._safeUnicodeDictionary} runs C{repr} on the object. + L{_safe_unicode_dictionary} runs C{repr} on the object. """ - self.assertEqual(Logger()._safeUnicodeDictionary(None), "None") + self.assertEqual(_safe_unicode_dictionary(None), "None") - def test_safeUnicodeDictionaryFallbackFailure(self): + def test_safe_unicode_dictionary_fallback_failure(self): """ - If all else fails, L{Logger._safeUnicodeDictionary} just gives up. + If all else fails, L{_safe_unicode_dictionary} just gives up. """ class badobject(object): @@ -594,7 +599,7 @@ def __repr__(self): raise TypeError() self.assertEqual( - Logger()._safeUnicodeDictionary(badobject()), + _safe_unicode_dictionary(badobject()), "eliot: unknown, unicode() raised exception", ) @@ -628,7 +633,7 @@ def raiser(i): }, ) self.assertIn("RuntimeError: oops", tracebackMessage["traceback"]) - # Calling _safeUnicodeDictionary multiple times leads to + # Calling _safe_unicode_dictionary multiple times leads to # inconsistent results due to hash ordering, so compare contents: assertContainsFields( self, written[1], {"message_type": "eliot:serialization_failure"} @@ -638,7 +643,7 @@ def raiser(i): dict((repr(key), repr(value)) for (key, value) in message.items()), ) - def test_destinationExceptionCaught(self): + def test_destination_exception_caught(self): """ If a destination throws an exception, an appropriate error is logged. @@ -655,13 +660,13 @@ def test_destinationExceptionCaught(self): dest[0], { "message_type": "eliot:destination_failure", - "message": logger._safeUnicodeDictionary(message), + "message": _safe_unicode_dictionary(message), "reason": "ono", "exception": "eliot.tests.test_output.MyException", }, ) - def test_destinationMultipleExceptionsCaught(self): + def test_destination_multiple_exceptions_caught(self): """ If multiple destinations throw an exception, an appropriate error is logged for each. @@ -705,13 +710,13 @@ def remove(key): message, { "message_type": "eliot:destination_failure", - "message": logger._safeUnicodeDictionary(message), + "message": _safe_unicode_dictionary(message), "reason": "ono", "exception": "eliot.tests.test_output.MyException", }, { "message_type": "eliot:destination_failure", - "message": logger._safeUnicodeDictionary(message), + "message": _safe_unicode_dictionary(message), "reason": zero_divide, "exception": zero_type, }, @@ -719,7 +724,7 @@ def remove(key): ), ) - def test_destinationExceptionCaughtTwice(self): + def test_destination_exception_caught_twice(self): """ If a destination throws an exception, and the logged error about it also causes an exception, then just drop that exception on the @@ -733,10 +738,15 @@ def always_raise(message): logger._destinations.add(always_raise) - # No exception raised; since everything is dropped no other - # assertions to be made. + # Just a message. No exception raised; since everything is dropped no + # other assertions to be made. logger.write({"hello": 123}) + # With an action. No exception raised; since everything is dropped no + # other assertions to be made. + with start_action(logger, "sys:do"): + logger.write({"hello": 123}) + class PEP8Tests(TestCase): """ diff --git a/setup.cfg b/setup.cfg index 259cc72..2268133 100644 --- a/setup.cfg +++ b/setup.cfg @@ -16,3 +16,6 @@ versionfile_build = eliot/_version.py tag_prefix = parentdir_prefix = eliot- +[flake8] +max-line-length = 88 +extend-ignore = E203 \ No newline at end of file