Fix not picklable logging methods failing multiprocess (#102)

CHANGELOG.rst

@@ -10,6 +10,7 @@ Unreleased
 - Add coloration of exception traceback even if ``diagnose`` and ``backtrace`` options are ``False``
 - Add a way to limit the depth of formatted exceptions traceback by setting the conventional ``sys.tracebacklimit`` variable (`#77 <https://github.com/Delgan/loguru/issues/77>`_)
 - The ``record["exception"]`` attribute is now unpackable as a ``(type, value, traceback)`` tuple
+- Fix logging methods not being serializable with ``pickle`` and hence raising exception while being passed to some ``multiprocessing`` functions (`#102 <https://github.com/Delgan/loguru/issues/102>`_)
 - Fix exception stack trace not colorizing source code lines on Windows
 - Fix possible ``AttributeError`` while formatting exceptions within a ``celery`` task (`#52 <https://github.com/Delgan/loguru/issues/52>`_)
 - Fix ``logger.catch`` decorator not working with generator and coroutine functions (`#75 <https://github.com/Delgan/loguru/issues/75>`_)

loguru/_logger.py

@@ -984,18 +984,14 @@ def __exit__(self_, type_, value, traceback_):
                 else:
                     back = 1
 
-                logger_ = self.opt(
+                self.opt(
                     exception=True,
                     record=True,
                     lazy=self._lazy,
                     ansi=self._ansi,
                     raw=self._raw,
                     depth=self._depth + back,
-                )
-
-                log = logger_._make_log_function(level)
-
-                log(logger_, message)
+                ).log(level, message)
 
                 return not reraise
 
@@ -1550,165 +1546,166 @@ def _find_iter(fileobj, regex, chunk):
                 buffer = buffer[end:]
                 yield from matches[:-1]
 
-    @staticmethod
-    @functools.lru_cache()
-    def _make_log_function(level):
+    def _log(self, level_id, static_level_no, exception, message, args, kwargs):
+        if not self._handlers:
+            return
 
-        if isinstance(level, str):
-            level_id = level_name = level
-        elif isinstance(level, int):
-            if level < 0:
-                raise ValueError(
-                    "Invalid level value, it should be a positive integer, not: %d" % level
-                )
-            level_id = None
-            level_name = "Level %d" % level
-        else:
-            raise ValueError(
-                "Invalid level, it should be an integer or a string, not: '%s'"
-                % type(level).__name__
-            )
+        frame = get_frame(self._depth + 2)
+        name = frame.f_globals["__name__"]
 
-        def log_function(_self, _message, *args, **kwargs):
-            if not _self._handlers:
+        try:
+            if not self._enabled[name]:
                 return
+        except KeyError:
+            dotted_name = name + "."
+            for dotted_module_name, status in self._activation_list:
+                if dotted_name[: len(dotted_module_name)] == dotted_module_name:
+                    if status:
+                        break
+                    self._enabled[name] = False
+                    return
+            self._enabled[name] = True
 
-            frame = get_frame(_self._depth + 1)
-            name = frame.f_globals["__name__"]
+        current_datetime = aware_now()
 
+        if level_id is None:
+            level_icon = " "
+            level_no = static_level_no
+            level_name = "Level %d" % level_no
+        else:
             try:
-                if not _self._enabled[name]:
-                    return
+                level_no, _, level_icon = self._levels[level_id]
+                level_name = level_id
             except KeyError:
-                dotted_name = name + "."
-                for dotted_module_name, status in _self._activation_list:
-                    if dotted_name[: len(dotted_module_name)] == dotted_module_name:
-                        if status:
-                            break
-                        _self._enabled[name] = False
-                        return
-                _self._enabled[name] = True
-
-            current_datetime = aware_now()
-
-            if level_id is None:
-                level_no, level_icon = level, " "
-            else:
-                try:
-                    level_no, _, level_icon = _self._levels[level_name]
-                except KeyError:
-                    raise ValueError("Level '%s' does not exist" % level_name)
-
-            if level_no < _self._min_level:
-                return
-
-            code = frame.f_code
-            file_path = code.co_filename
-            file_name = basename(file_path)
-            thread = current_thread()
-            process = current_process()
-            elapsed = current_datetime - start_time
-
-            level_recattr = LevelRecattr(level_name)
-            level_recattr.no, level_recattr.name, level_recattr.icon = (
-                level_no,
-                level_name,
-                level_icon,
-            )
+                raise ValueError("Level '%s' does not exist" % level_id)
+
+        if level_no < self._min_level:
+            return
+
+        code = frame.f_code
+        file_path = code.co_filename
+        file_name = basename(file_path)
+        thread = current_thread()
+        process = current_process()
+        elapsed = current_datetime - start_time
+
+        level_recattr = LevelRecattr(level_name)
+        level_recattr.no, level_recattr.name, level_recattr.icon = (
+            level_no,
+            level_name,
+            level_icon,
+        )
 
-            file_recattr = FileRecattr(file_name)
-            file_recattr.name, file_recattr.path = file_name, file_path
+        file_recattr = FileRecattr(file_name)
+        file_recattr.name, file_recattr.path = file_name, file_path
 
-            thread_ident = thread.ident
-            thread_recattr = ThreadRecattr(thread_ident)
-            thread_recattr.id, thread_recattr.name = thread_ident, thread.name
+        thread_ident = thread.ident
+        thread_recattr = ThreadRecattr(thread_ident)
+        thread_recattr.id, thread_recattr.name = thread_ident, thread.name
 
-            process_ident = process.ident
-            process_recattr = ProcessRecattr(process_ident)
-            process_recattr.id, process_recattr.name = process_ident, process.name
+        process_ident = process.ident
+        process_recattr = ProcessRecattr(process_ident)
+        process_recattr.id, process_recattr.name = process_ident, process.name
 
-            if _self._exception:
-                exc = _self._exception
-                if isinstance(exc, BaseException):
-                    type_, value, traceback = (type(exc), exc, exc.__traceback__)
-                elif isinstance(exc, tuple):
-                    type_, value, traceback = exc
-                else:
-                    type_, value, traceback = sys.exc_info()
-                exception = ExceptionRecattr(type_, value, traceback)
+        if exception:
+            if isinstance(exception, BaseException):
+                type_, value, traceback = (type(exception), exception, exception.__traceback__)
+            elif isinstance(exception, tuple):
+                type_, value, traceback = exception
             else:
-                exception = None
-
-            record = {
-                "elapsed": elapsed,
-                "exception": exception,
-                "extra": {**_self._extra_class, **_self._extra},
-                "file": file_recattr,
-                "function": code.co_name,
-                "level": level_recattr,
-                "line": frame.f_lineno,
-                "message": _message,
-                "module": splitext(file_name)[0],
-                "name": name,
-                "process": process_recattr,
-                "thread": thread_recattr,
-                "time": current_datetime,
-            }
-
-            if _self._lazy:
-                args = [arg() for arg in args]
-                kwargs = {key: value() for key, value in kwargs.items()}
-
-            if _self._record:
-                record["message"] = _message.format(*args, **kwargs, record=record)
-            elif args or kwargs:
-                record["message"] = _message.format(*args, **kwargs)
-
-            if Logger._patcher_class:
-                Logger._patcher_class(record)
-
-            if _self._patcher:
-                _self._patcher(record)
-
-            for handler in _self._handlers.values():
-                handler.emit(record, level_id, _self._ansi, _self._raw)
-
-        doc = r"Log ``_message.format(*args, **kwargs)`` with severity ``'%s'``." % level_name
-        log_function.__doc__ = doc
-
-        return log_function
-
-    trace = _make_log_function.__func__("TRACE")
-    debug = _make_log_function.__func__("DEBUG")
-    info = _make_log_function.__func__("INFO")
-    success = _make_log_function.__func__("SUCCESS")
-    warning = _make_log_function.__func__("WARNING")
-    error = _make_log_function.__func__("ERROR")
-    critical = _make_log_function.__func__("CRITICAL")
+                type_, value, traceback = sys.exc_info()
+            exception_ = ExceptionRecattr(type_, value, traceback)
+        else:
+            exception_ = None
+
+        record = {
+            "elapsed": elapsed,
+            "exception": exception_,
+            "extra": {**self._extra_class, **self._extra},
+            "file": file_recattr,
+            "function": code.co_name,
+            "level": level_recattr,
+            "line": frame.f_lineno,
+            "message": message,
+            "module": splitext(file_name)[0],
+            "name": name,
+            "process": process_recattr,
+            "thread": thread_recattr,
+            "time": current_datetime,
+        }
+
+        if self._lazy:
+            args = [arg() for arg in args]
+            kwargs = {key: value() for key, value in kwargs.items()}
+
+        if self._record:
+            record["message"] = message.format(*args, **kwargs, record=record)
+        elif args or kwargs:
+            record["message"] = message.format(*args, **kwargs)
+
+        if Logger._patcher_class:
+            Logger._patcher_class(record)
+
+        if self._patcher:
+            self._patcher(record)
+
+        for handler in self._handlers.values():
+            handler.emit(record, level_id, self._ansi, self._raw)
+
+    def trace(_self, _message, *args, **kwargs):
+        r"""Log ``_message.format(*args, **kwargs)`` with severity ``'TRACE'``."""
+        _self._log("TRACE", None, _self._exception, _message, args, kwargs)
+
+    def debug(_self, _message, *args, **kwargs):
+        r"""Log ``_message.format(*args, **kwargs)`` with severity ``'DEBUG'``."""
+        _self._log("DEBUG", None, _self._exception, _message, args, kwargs)
+
+    def info(_self, _message, *args, **kwargs):
+        r"""Log ``_message.format(*args, **kwargs)`` with severity ``'INFO'``."""
+        _self._log("INFO", None, _self._exception, _message, args, kwargs)
+
+    def success(_self, _message, *args, **kwargs):
+        r"""Log ``_message.format(*args, **kwargs)`` with severity ``'SUCCESS'``."""
+        _self._log("SUCCESS", None, _self._exception, _message, args, kwargs)
+
+    def warning(_self, _message, *args, **kwargs):
+        r"""Log ``_message.format(*args, **kwargs)`` with severity ``'WARNING'``."""
+        _self._log("WARNING", None, _self._exception, _message, args, kwargs)
+
+    def error(_self, _message, *args, **kwargs):
+        r"""Log ``_message.format(*args, **kwargs)`` with severity ``'ERROR'``."""
+        _self._log("ERROR", None, _self._exception, _message, args, kwargs)
+
+    def critical(_self, _message, *args, **kwargs):
+        r"""Log ``_message.format(*args, **kwargs)`` with severity ``'CRITICAL'``."""
+        _self._log("CRITICAL", None, _self._exception, _message, args, kwargs)
+
+    def exception(_self, _message, *args, **kwargs):
+        r"""Convenience method for logging an ``'ERROR'`` with exception information."""
+        _self._log("ERROR", None, True, _message, args, kwargs)
 
     def log(_self, _level, _message, *args, **kwargs):
         r"""Log ``_message.format(*args, **kwargs)`` with severity ``_level``."""
-        logger = _self.opt(
-            exception=_self._exception,
-            record=_self._record,
-            lazy=_self._lazy,
-            ansi=_self._ansi,
-            raw=_self._raw,
-            depth=_self._depth + 1,
-        )
-        logger._make_log_function(_level)(logger, _message, *args, **kwargs)
+        level_id, static_level_no = _self._dynamic_level(_level)
+        _self._log(level_id, static_level_no, _self._exception, _message, args, kwargs)
 
-    def exception(_self, _message, *args, **kwargs):
-        r"""Convenience method for logging an ``'ERROR'`` with exception information."""
-        logger = _self.opt(
-            exception=True,
-            record=_self._record,
-            lazy=_self._lazy,
-            ansi=_self._ansi,
-            raw=_self._raw,
-            depth=_self._depth + 1,
+    @staticmethod
+    @functools.lru_cache(maxsize=32)
+    def _dynamic_level(level):
+
+        if isinstance(level, str):
+            return (level, None)
+
+        if isinstance(level, int):
+            if level < 0:
+                raise ValueError(
+                    "Invalid level value, it should be a positive integer, not: %d" % level
+                )
+            return (None, level)
+
+        raise ValueError(
+            "Invalid level, it should be an integer or a string, not: '%s'" % type(level).__name__
         )
-        logger._make_log_function("ERROR")(logger, _message, *args, **kwargs)
 
     def start(self, *args, **kwargs):
         """Deprecated function to |add| a new handler.

tests/test_pickling.py

@@ -0,0 +1,51 @@
+from loguru import logger
+import pickle
+import sys
+import pytest
+
+
+def test_pickling_logging_method(writer):
+    logger.add(writer, format="{level} - {function} - {message}")
+    pickled = pickle.dumps(logger.critical)
+    func = pickle.loads(pickled)
+    func("A message")
+    assert writer.read() == "CRITICAL - test_pickling_logging_method - A message\n"
+
+
+def test_pickling_log_method(writer):
+    logger.add(writer, format="{level} - {function} - {message}")
+    pickled = pickle.dumps(logger.log)
+    func = pickle.loads(pickled)
+    func(19, "A message")
+    assert writer.read() == "Level 19 - test_pickling_log_method - A message\n"
+
+
+def test_pickling_logger(writer):
+    pickled = pickle.dumps(logger)
+    inst = pickle.loads(pickled)
+    inst.add(writer, format="{level} - {function} - {message}")
+    inst.debug("A message")
+    assert writer.read() == "DEBUG - test_pickling_logger - A message\n"
+
+
+@pytest.mark.parametrize(
+    "method",
+    [
+        logger.add,
+        logger.remove,
+        logger.catch,
+        logger.opt,
+        logger.bind,
+        logger.patch,
+        logger.level,
+        logger.disable,
+        logger.enable,
+        logger.configure,
+        logger.parse,
+        logger.exception,
+    ],
+)
+def test_pickling_no_error(method):
+    pickled = pickle.dumps(method)
+    unpickled = pickle.loads(pickled)
+    assert unpickled