Merge pull request #482 from itamarst/476-infinite-exception

Fix infinite exception when destination errors

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
 ^^^^^^
 

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)
 

eliot/_message.py

@@ -116,18 +116,19 @@ 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:
             fields["message_type"] = ""
         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)

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):