Fix errors due to non-unpicklable Exception when "enqueue=True" (#329)

CHANGELOG.rst

@@ -5,7 +5,8 @@
 - Add support for true colors on Windows using ANSI/VT console when available (`#934 <https://github.com/Delgan/loguru/issues/934>`_, thanks `@tunaflsh <https://github.com/tunaflsh>`_).
 - Fix file possibly rotating too early or too late when re-starting an application around midnight (`#894 <https://github.com/Delgan/loguru/issues/894>`_).
 - Fix inverted ``"<hide>"`` and ``"<strike>"`` color tags (`#943 <https://github.com/Delgan/loguru/pull/943>`_, thanks `@tunaflsh <https://github.com/tunaflsh>`_).
-- Fix possible errors raised by logging non-picklable ``Exception`` instances while using ``enqueue=True`` (`#342 <https://github.com/Delgan/loguru/issues/342>`_, thanks `@ncoudene <https://github.com/ncoudene>`_).
+- Fix possible untraceable errors raised when logging non-unpicklable ``Exception`` instances while using ``enqueue=True`` (`#329 <https://github.com/Delgan/loguru/issues/329>`_).
+- Fix possible errors raised when logging non-picklable ``Exception`` instances while using ``enqueue=True`` (`#342 <https://github.com/Delgan/loguru/issues/342>`_, thanks `@ncoudene <https://github.com/ncoudene>`_).
 - Fix missing seconds and microseconds when formatting timezone offset that requires such accuracy (`#961 <https://github.com/Delgan/loguru/issues/961>`_).
 - Raise ``ValueError`` if an attempt to use nanosecond precision for time formatting is detected (`#855 <https://github.com/Delgan/loguru/issues/855>`_).
 

loguru/_recattrs.py

@@ -64,16 +64,27 @@ def __repr__(self):
         return "(type=%r, value=%r, traceback=%r)" % (self.type, self.value, self.traceback)
 
     def __reduce__(self):
-        # The traceback is not picklable so we need to remove it. Also, some custom exception
-        # values aren't picklable either. For user convenience, we try first to serialize it and
-        # we remove the value in case or error. As an optimization, we could have re-used the
-        # dumped value during unpickling, but this requires using "pickle.loads()" which is
-        # flagged as insecure by some security tools.
-        # __reduce__ function does not alway raise PickleError. Multidict, for example, raise
-        # TypeError. To manage all the cases, we catch Exception.
+        # The traceback is not picklable, therefore it needs to be removed. Additionally, there's a
+        # possibility that the exception value is not picklable either. In such cases, we also need
+        # to remove it. This is done for user convenience, aiming to prevent error logging caused by
+        # custom exceptions from third-party libraries. If the serialization succeeds, we can reuse
+        # the pickled value later for optimization (so that it's not pickled twice). It's important
+        # to note that custom exceptions might not necessarily raise a PickleError, hence the
+        # generic Exception catch.
         try:
-            pickle.dumps(self.value)
+            pickled_value = pickle.dumps(self.value)
         except Exception:
             return (RecordException, (self.type, None, None))
         else:
-            return (RecordException, (self.type, self.value, None))
+            return (RecordException._from_pickled_value, (self.type, pickled_value, None))
+
+    @classmethod
+    def _from_pickled_value(cls, type_, pickled_value, traceback_):
+        try:
+            # It's safe to use "pickle.loads()" in this case because the pickled value is generated
+            # by the same code and is not coming from an untrusted source.
+            value = pickle.loads(pickled_value)
+        except Exception:
+            return cls(type_, None, traceback_)
+        else:
+            return cls(type_, value, traceback_)

tests/test_add_option_enqueue.py

@@ -34,6 +34,14 @@ def __setstate__(self, state):
         raise pickle.UnpicklingError("You shall not de-serialize me!")
 
 
+class NotUnpicklableTypeError:
+    def __getstate__(self):
+        return "..."
+
+    def __setstate__(self, state):
+        raise TypeError("You shall not de-serialize me!")
+
+
 class NotWritable:
     def write(self, message):
         if "fail" in message.record["extra"]:
@@ -97,24 +105,6 @@ def test_caught_exception_queue_put(writer, capsys):
     assert lines[-1] == "--- End of logging error ---"
 
 
-def test_caught_exception_queue_put_typerror(writer, capsys):
-    logger.add(writer, enqueue=True, catch=True, format="{message}")
-
-    logger.info("It's fine")
-    logger.bind(broken=NotPicklableTypeError()).info("Bye bye...")
-    logger.info("It's fine again")
-    logger.remove()
-
-    out, err = capsys.readouterr()
-    lines = err.strip().splitlines()
-    assert writer.read() == "It's fine\nIt's fine again\n"
-    assert out == ""
-    assert lines[0] == "--- Logging error in Loguru Handler #0 ---"
-    assert re.match(r"Record was: \{.*Bye bye.*\}", lines[1])
-    assert lines[-2].endswith("TypeError: You shall not serialize me!")
-    assert lines[-1] == "--- End of logging error ---"
-
-
 def test_caught_exception_queue_get(writer, capsys):
     logger.add(writer, enqueue=True, catch=True, format="{message}")
 
@@ -166,22 +156,6 @@ def test_not_caught_exception_queue_put(writer, capsys):
     assert err == ""
 
 
-def test_not_caught_exception_queue_put_typeerror(writer, capsys):
-    logger.add(writer, enqueue=True, catch=False, format="{message}")
-
-    logger.info("It's fine")
-
-    with pytest.raises(TypeError, match=r"You shall not serialize me!"):
-        logger.bind(broken=NotPicklableTypeError()).info("Bye bye...")
-
-    logger.remove()
-
-    out, err = capsys.readouterr()
-    assert writer.read() == "It's fine\n"
-    assert out == ""
-    assert err == ""
-
-
 def test_not_caught_exception_queue_get(writer, capsys):
     logger.add(writer, enqueue=True, catch=False, format="{message}")
 
@@ -274,7 +248,8 @@ def slow_sink(message):
     assert err == "".join("%d\n" % i for i in range(10))
 
 
-def test_logging_not_picklable_exception():
+@pytest.mark.parametrize("exception_value", [NotPicklable(), NotPicklableTypeError()])
+def test_logging_not_picklable_exception(exception_value):
     exception = None
 
     def sink(message):
@@ -284,7 +259,7 @@ def sink(message):
     logger.add(sink, enqueue=True, catch=False)
 
     try:
-        raise ValueError(NotPicklable())
+        raise ValueError(exception_value)
     except Exception:
         logger.exception("Oups")
 
@@ -296,8 +271,8 @@ def sink(message):
     assert traceback_ is None
 
 
-@pytest.mark.skip(reason="No way to safely deserialize exception yet")
-def test_logging_not_unpicklable_exception():
+@pytest.mark.parametrize("exception_value", [NotUnpicklable(), NotUnpicklableTypeError()])
+def test_logging_not_unpicklable_exception(exception_value):
     exception = None
 
     def sink(message):
@@ -307,7 +282,7 @@ def sink(message):
     logger.add(sink, enqueue=True, catch=False)
 
     try:
-        raise ValueError(NotUnpicklable())
+        raise ValueError(exception_value)
     except Exception:
         logger.exception("Oups")