Repository: Delgan/loguru
Pull request #325 (2020-09-14 13:34:24)

Fix removing simple queue in child processes
Hello, I think this pull request could fix https://github.com/Delgan/loguru/issues/309.

There is problem with calling `multiprocessing.current_process()` which returns the instance of `_MainProcess()`. But because this code is executed before a new thread there are same values/objects. In child process is the same object as in parent process. You can check it with `id(self._owner_process)`.

Source code of multiprocessing: https://github.com/python/cpython/blob/master/Lib/multiprocessing/process.py#L41

Another way how to fix it is to move `self._owner_process = multiprocessing.current_process()` after creating a new thread. There would be different objects in every process. But I think there is better to work wih PID numbers than objects.



Delgan: Wow! Thanks a lot for taking the time to investigate and fix this issue!

Kudos for finding the solution. To be honest I'm still scratching my head trying to figure out what's going on. :astonished: 

> In child process is the same object as in parent process.

Why that?
Why does calling `multiprocessing.current_process()` in the child returns the same process as in the parent?
Why does it fail if `_owner_process` is a `Process()` object but not if it's an `init`? Is `uwsgi` somehow mutating the main process?
Why does it freeze at `stop()` anyway? 
 
It will take me probably some time to properly grasp all of that, but I will publish your correction as soon as possible. Thank you very much!
dstlmrk: I will try to describe it :) And I want to apologize because last part "Another way how to fix it..." of my previous comment is not correct.

#### 1), 2) Why does calling multiprocessing.current_process() in the child returns the same process as in the parent? and 3b) Why does it fail if _owner_process is a Process() object but not if it's an int?

Why multiprocessing returns the same object? Because of [this](https://github.com/python/cpython/blob/master/Lib/multiprocessing/process.py#L41) and [this](https://github.com/python/cpython/blob/master/Lib/multiprocessing/process.py#L416). This object/instance is created once in master process and everytime when you call `multiprocessing.current_process()` you get the same instance (it doesn't create new instance everytime when you call it). That's property of multiprocessing. It returns the same object but it behaves differently in every process. You can call [property](https://github.com/python/cpython/blob/a33f2c2bae759fc9d06e1c032fd2026135f2df45/Lib/multiprocessing/process.py#L235)  `pid` (`ident`) and it will return pid of current process. That's the reason why `self._owner_process` doesn't return pid of parent process. Actually `self._owner_process` = `multiprocessing.current_process()` everytime.

I can show you my custom output from code (everywhere is the same object but it behaves differently):

```
...
[os.getpid()=19870] I'm MASTER!!!
[os.getpid()=19870] In Handler.__init__() id(self._owner_process)=139955875152368
[os.getpid()=19870] In Handler.__init__() self._owner_process.pid=19870
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x55630ead8a50 pid: 19870 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 19870)
spawned uWSGI worker 1 (pid: 19873, cores: 1)
spawned uWSGI http 1 (pid: 19874)
^CSIGINT/SIGQUIT received...killing workers...
gateway "uWSGI http 1" has been buried (pid: 19874)
[os.getpid()=19873] Exit process
[os.getpid()=19873] In Handler.stop() id(self._owner_process)=139955875152368 ?= id(multiprocessing.current_process())=139955875152368
[os.getpid()=19873] In Handler.stop() self._owner_process.pid=19873 ?= multiprocessing.current_process().pid=19873
Thu Sep 17 12:51:19 2020 - worker 1 (pid: 19873) is taking too much time to die...NO MERCY !!!
...
```

#### 3a)  Is uwsgi somehow mutating the main process?

The `uwsgi` doesn't mutate the main process.

#### 4) Why does it freeze at stop() anyway?

[This condition](https://github.com/Delgan/loguru/blob/master/loguru/_handler.py#L187) means children should return and don't continue in code. But every child thinks he is master so every child kills logging thread (simple queue) and I don't know exactly why but it causes timeout in children/worker proccesses.

Delgan: Thanks for the explanations!

One thing is still confusing me.

> This object/instance is created once in master process and everytime when you call `multiprocessing.current_process()` you get the same instance (it doesn't create new instance everytime when you call it). 
> [...]
> Actually `self._owner_process = multiprocessing.current_process()` everytime.

That's not what I'm observing while using standard `multiprocessing` without involving `uwsgi`:

```python
import multiprocessing

main = multiprocessing.current_process()

def hello_world():
    child = multiprocessing.current_process()
    print("main == child:", main == child)

if __name__ == "__main__":
    p = multiprocessing.Process(target=hello_world)
    p.start()
    p.join()
```

This prints `"main == child: False"`. 

Using `uwsgi` I get the opposite result: 

```python
import multiprocessing
from flask import Flask

application = Flask(__name__)
main = multiprocessing.current_process()

@application.route('/')
def hello_world():
    child  = multiprocessing.current_process()
    return "main == child: {}".format(main == child)
```

That's this behavior difference that I can't understand. :confused: 
dstlmrk: Hmm.. I checked multiprocessing code and I see reason probably there. This library does some overhead before starting process. I see it calls `_bootstrap` method, [replaces](https://github.com/python/cpython/blob/master/Lib/multiprocessing/process.py#L301) `_current_process` with `self` (the child process) and [deletes](https://github.com/python/cpython/blob/master/Lib/multiprocessing/process.py#L312) the original `current_process`. I think that's the reason why child process in multiprocessing has new instance every start of `Process`.

I'm not sure but `uwsgi` doesn't use multiprocessing library probably and can't execute this overhead himself. In our applications based on uwsgi we can't use loguru without this change.
Delgan: Yeah, `uwsgi` probably implements its own bootstrapping procedure. :confused:

Anyway, thanks again. I wanted to be sure it was somehow related to `uwsgi` and  that `loguru` was working properly out of that context.

I will merge this PR and probably publish a new version during the week-end. :+1: 
dstlmrk: I am glad I could help you :)

Patch:
diff --git a/.gitignore b/.gitignore
index 26ac0bd..7c0b036 100644
--- a/.gitignore
+++ b/.gitignore
@@ -102,3 +102,6 @@ ENV/
 
 # VScode
 .vscode/
+
+# Idea IDE
+.idea/
diff --git a/CHANGELOG.rst b/CHANGELOG.rst
index b4ccdd8..ed12e90 100644
--- a/CHANGELOG.rst
+++ b/CHANGELOG.rst
@@ -1,3 +1,9 @@
+`Unreleased`_
+=============
+
+- Fix possible exception during formatting of non-string messages (`#331 <https://github.com/Delgan/loguru/issues/331>`_).
+
+
 `0.5.2`_ (2020-09-06)
 =====================
 
diff --git a/loguru/_handler.py b/loguru/_handler.py
index 0217117..fcbe88e 100644
--- a/loguru/_handler.py
+++ b/loguru/_handler.py
@@ -1,5 +1,6 @@
 import functools
 import json
+import os
 import multiprocessing
 from threading import Thread
 
@@ -66,7 +67,7 @@ class Handler:
         self._queue = None
         self._confirmation_event = None
         self._confirmation_lock = None
-        self._owner_process = None
+        self._owner_process_pid = None
         self._thread = None
 
         if self._is_formatter_dynamic:
@@ -85,7 +86,7 @@ class Handler:
             self._queue = multiprocessing.SimpleQueue()
             self._confirmation_event = multiprocessing.Event()
             self._confirmation_lock = multiprocessing.Lock()
-            self._owner_process = multiprocessing.current_process()
+            self._owner_process_pid = os.getpid()
             self._thread = Thread(
                 target=self._queued_writer, daemon=True, name="loguru-writer-%d" % self._id
             )
@@ -184,7 +185,7 @@ class Handler:
         with self._lock:
             self._stopped = True
             if self._enqueue:
-                if self._owner_process != multiprocessing.current_process():
+                if self._owner_process_pid != os.getpid():
                     return
                 self._queue.put(None)
                 self._thread.join()
@@ -201,7 +202,7 @@ class Handler:
             self._confirmation_event.clear()
 
     async def complete_async(self):
-        if self._enqueue and self._owner_process != multiprocessing.current_process():
+        if self._enqueue and self._owner_process_pid != os.getpid():
             return
 
         with self._lock:
diff --git a/loguru/_logger.py b/loguru/_logger.py
index 390ea97..c9130b7 100644
--- a/loguru/_logger.py
+++ b/loguru/_logger.py
@@ -1914,7 +1914,7 @@ class Logger:
             "function": code.co_name,
             "level": RecordLevel(level_name, level_no, level_icon),
             "line": frame.f_lineno,
-            "message": message,
+            "message": str(message),
             "module": splitext(file_name)[0],
             "name": name,
             "process": RecordProcess(process.ident, process.name),
@@ -1941,7 +1941,7 @@ class Logger:
             if args or kwargs:
                 colored_message = Colorizer.prepare_message(message, args, kwargs)
             else:
-                colored_message = Colorizer.prepare_simple_message(message)
+                colored_message = Colorizer.prepare_simple_message(str(message))
             log_record["message"] = colored_message.stripped
         elif args or kwargs:
             colored_message = None


Test patch:
diff --git a/tests/test_formatting.py b/tests/test_formatting.py
index d86c23a..49cb488 100644
--- a/tests/test_formatting.py
+++ b/tests/test_formatting.py
@@ -164,6 +164,64 @@ def test_kwargs_in_extra_dict():
     ]
 
 
+def test_non_string_message(writer):
+    logger.add(writer, format="{message}")
+
+    logger.info(1)
+    logger.info({})
+    logger.info(b"test")
+
+    assert writer.read() == "1\n{}\nb'test'\n"
+
+
+@pytest.mark.parametrize("colors", [True, False])
+def test_non_string_message_is_str_in_record(writer, colors):
+    output = ""
+
+    def sink(message):
+        nonlocal output
+        assert isinstance(message.record["message"], str)
+        output += message
+
+    def format(record):
+        assert isinstance(record["message"], str)
+        return "[{message}]\n"
+
+    logger.add(sink, format=format, catch=False)
+    logger.opt(colors=colors).info(123)
+    assert output == "[123]\n"
+
+
+@pytest.mark.parametrize("colors", [True, False])
+def test_missing_positional_field_during_formatting(writer, colors):
+    logger.add(writer)
+
+    with pytest.raises(IndexError):
+        logger.opt(colors=colors).info("Foo {} {}", 123)
+
+
+@pytest.mark.parametrize("colors", [True, False])
+def test_missing_named_field_during_formatting(writer, colors):
+    logger.add(writer)
+
+    with pytest.raises(KeyError):
+        logger.opt(colors=colors).info("Foo {bar}", baz=123)
+
+
+def test_not_formattable_message(writer):
+    logger.add(writer)
+
+    with pytest.raises(AttributeError):
+        logger.info(123, baz=456)
+
+
+def test_not_formattable_message_with_colors(writer):
+    logger.add(writer)
+
+    with pytest.raises(TypeError):
+        logger.opt(colors=True).info(123, baz=456)
+
+
 def test_invalid_color_markup(writer):
     with pytest.raises(ValueError):
         logger.add(writer, format="<red>Not closed tag", colorize=True)