Asynchronous bug

[lsabi]

Hi,

I'm using an async web framework with loguru. The framework runs in a single process, so there should not be any race condition. Though, when logging, I get the following error

Traceback (most recent call last):
File "/home/user/.local/lib/python3.7/site-packages/loguru/_handler.py", line 259, in _queued_writer
message = queue.get()
File "/usr/lib/python3.7/multiprocessing/queues.py", line 354, in get
return _ForkingPickler.loads(res)
TypeError: init() missing 1 required positional argument: 'status_code'
--- End of logging error ---
--- Logging error in Loguru Handler #1 ---

Is there a simple workaround to this issue? I'm using Ubuntu and the problem is different from #108 and #171 (although I tried to await logger.complete and did not change the situation).

Thanks.

Here's also part of the logged exception. I couldn't post it all due to sensitive content

Traceback (most recent call last):
File "", line 1, in
File "/usr/lib/python3.7/multiprocessing/spawn.py", line 105, in spawn_main
exitcode = _main(fd)
│ └ 7
└ <function _main at 0x7fd8fd17a290>
File "/usr/lib/python3.7/multiprocessing/spawn.py", line 118, in _main
return self._bootstrap()
│ └ <function BaseProcess._bootstrap at 0x7fd8fd228050>
└ <SpawnProcess(SpawnProcess-2, started)>
File "/usr/lib/python3.7/multiprocessing/process.py", line 297, in _bootstrap
self.run()
│ └ <function BaseProcess.run at 0x7fd8fd224680>
└ <SpawnProcess(SpawnProcess-2, started)>
File "/usr/lib/python3.7/multiprocessing/process.py", line 99, in run
self._target(*self._args, **self._kwargs)
│ │ │ │ │ └ {'config': <uvicorn.config.Config object at 0x7fd8fd1a1890>, 'target': <bound method Server.run of <uvicorn.main.Server objec...
│ │ │ │ └ <SpawnProcess(SpawnProcess-2, started)>
│ │ │ └ ()
│ │ └ <SpawnProcess(SpawnProcess-2, started)>
│ └ <function subprocess_started at 0x7fd8fd1a2560>
└ <SpawnProcess(SpawnProcess-2, started)>

[Delgan]

Hi. Could you please show me the part of your code where you .add() handlers and configure the logger?

[lsabi]

Hi,

I tried with both commenting and uncommenting the enqueue parameter, but nothing changed

from loguru import logger


logger.remove()
logger.add(
    "logs/api_{time}.log",
    format="[{time:YYYY-MM-DD HH:mm:00}, {name}] {level}: {message}",
    rotation="250 MB",
    level="INFO",
    filter="app.api",
    # enqueue=True,
    backtrace=True,
    diagnose=True
)

Instead, my code is as follows. I omitted some parts, but the essential is here. Also, the logging file is a module with an init.py that import from the file where the logger above is declared.

from .logging import logger
try:
        new_id = await my_function(my_params)
    except Exception:
        logger.exception("Exception!!!")
        await logger.complete()

[Delgan]

Thanks for the code. 👍

Unfortunately, it's hard to help you without being able to reproduce the bug. Is there any way you could try to reduce your code to a minimal reproducible example, so I can investigate what is going wrong?

I guess Uvicorn is internally using multiprocessing as seen in the traceback. The error is maybe caused by the location where the logger is configured. Also, do you call .bind() anywhere?

[lsabi]

Basically, it's a fastAPI app with a module having the logger instantiation and an init file that exposes it (from which I import the logger). Apart from that, there's nothing special going on in my app.

No, I don't use bind(). Should I be using it?

[Delgan]

No, you don't have to use .bind(). I'm trying to understand where does the status_code in the traceback come from. Curiously, this looks like this error reported a few months ago: #108 (comment)

I guess if enqueue=False the error should not be the same because Loguru will not use _queued_writer which appears in the traceback. Could you please show me the entire Loguru error reported in such a case, including the Record was: ... part (stripping sensitive data)?

[lsabi]

The log file with the error is reported below. With enqueue=False the app does not freeze, although it is much slower with respect to when I don't log anything. Probably this was my mistake: I was simply commenting enqueue=True instead of explicitly setting it to False.

[2020-03-31 09:22:00, app.api.v_10.functions] ERROR: Exception
Traceback (most recent call last):
  File "<string>", line 1, in <module>
  File "/usr/lib/python3.7/multiprocessing/spawn.py", line 105, in spawn_main
    exitcode = _main(fd)
               │     └ 7
               └ <function _main at 0x7f957dede290>
  File "/usr/lib/python3.7/multiprocessing/spawn.py", line 118, in _main
    return self._bootstrap()
           │    └ <function BaseProcess._bootstrap at 0x7f957df8c050>
           └ <SpawnProcess(SpawnProcess-2, started)>
  File "/usr/lib/python3.7/multiprocessing/process.py", line 297, in _bootstrap
    self.run()
    │    └ <function BaseProcess.run at 0x7f957df88680>
    └ <SpawnProcess(SpawnProcess-2, started)>
  File "/usr/lib/python3.7/multiprocessing/process.py", line 99, in run
    self._target(*self._args, **self._kwargs)
    │    │        │    │        │    └ {'config': <uvicorn.config.Config object at 0x7f957df057d0>, 'target': <bound method Server.run of <uvicorn.main.Server objec...
    │    │        │    │        └ <SpawnProcess(SpawnProcess-2, started)>
    │    │        │    └ ()
    │    │        └ <SpawnProcess(SpawnProcess-2, started)>
    │    └ <function subprocess_started at 0x7f957df06560>
    └ <SpawnProcess(SpawnProcess-2, started)>
  File "/home/usr/.local/lib/python3.7/site-packages/uvicorn/subprocess.py", line 61, in subprocess_started
    target(sockets=sockets)
    │              └ [<socket.socket fd=3, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 8000)>]
    └ <bound method Server.run of <uvicorn.main.Server object at 0x7f957d5e69d0>>
  File "/home/usr/.local/lib/python3.7/site-packages/uvicorn/main.py", line 382, in run
    loop.run_until_complete(self.serve(sockets=sockets))
    │    │                  │    │             └ [<socket.socket fd=3, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=0, laddr=('127.0.0.1', 8000)>]
    │    │                  │    └ <function Server.serve at 0x7f957df00320>
    │    │                  └ <uvicorn.main.Server object at 0x7f957d5e69d0>
    │    └ <method 'run_until_complete' of 'uvloop.loop.Loop' objects>
    └ <uvloop.Loop running=True closed=False debug=False>
  File "/home/usr/.local/lib/python3.7/site-packages/uvicorn/protocols/http/httptools_impl.py", line 385, in run_asgi
    result = await app(self.scope, self.receive, self.send)
                   │   │    │      │    │        │    └ <function RequestResponseCycle.send at 0x7f957d3d4f80>
                   │   │    │      │    │        └ <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f9577416090>
                   │   │    │      │    └ <function RequestResponseCycle.receive at 0x7f957d3d5050>
                   │   │    │      └ <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f9577416090>
                   │   │    └ {'type': 'http', 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 55270), 'scheme': 'http', 'met...
                   │   └ <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f9577416090>
                   └ <uvicorn.middleware.proxy_headers.ProxyHeadersMiddleware object at 0x7f957746b590>
  File "/home/usr/.local/lib/python3.7/site-packages/uvicorn/middleware/proxy_headers.py", line 45, in __call__
    return await self.app(scope, receive, send)
                 │    │   │      │        └ <bound method RequestResponseCycle.send of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774160...
                 │    │   │      └ <bound method RequestResponseCycle.receive of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774...
                 │    │   └ {'type': 'http', 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 55270), 'scheme': 'http', 'met...
                 │    └ <fastapi.applications.FastAPI object at 0x7f957cf395d0>
                 └ <uvicorn.middleware.proxy_headers.ProxyHeadersMiddleware object at 0x7f957746b590>
  File "/home/usr/.local/lib/python3.7/site-packages/fastapi/applications.py", line 149, in __call__
    await super().__call__(scope, receive, send)
                           │      │        └ <bound method RequestResponseCycle.send of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774160...
                           │      └ <bound method RequestResponseCycle.receive of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774...
                           └ {'type': 'http', 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 55270), 'scheme': 'http', 'met...
  File "/home/usr/.local/lib/python3.7/site-packages/starlette/applications.py", line 102, in __call__
    await self.middleware_stack(scope, receive, send)
          │    │                │      │        └ <bound method RequestResponseCycle.send of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774160...
          │    │                │      └ <bound method RequestResponseCycle.receive of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774...
          │    │                └ {'type': 'http', 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 55270), 'scheme': 'http', 'met...
          │    └ <starlette.middleware.errors.ServerErrorMiddleware object at 0x7f9577464a10>
          └ <fastapi.applications.FastAPI object at 0x7f957cf395d0>
  File "/home/usr/.local/lib/python3.7/site-packages/starlette/middleware/errors.py", line 159, in __call__
    await self.app(scope, receive, _send)
          │    │   │      │        └ <function ServerErrorMiddleware.__call__.<locals>._send at 0x7f957740d4d0>
          │    │   │      └ <bound method RequestResponseCycle.receive of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774...
          │    │   └ {'type': 'http', 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 55270), 'scheme': 'http', 'met...
          │    └ <starlette.exceptions.ExceptionMiddleware object at 0x7f9577464910>
          └ <starlette.middleware.errors.ServerErrorMiddleware object at 0x7f9577464a10>
  File "/home/usr/.local/lib/python3.7/site-packages/starlette/exceptions.py", line 71, in __call__
    await self.app(scope, receive, sender)
          │    │   │      │        └ <function ExceptionMiddleware.__call__.<locals>.sender at 0x7f957740d5f0>
          │    │   │      └ <bound method RequestResponseCycle.receive of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774...
          │    │   └ {'type': 'http', 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 55270), 'scheme': 'http', 'met...
          │    └ <fastapi.routing.APIRouter object at 0x7f957cf39750>
          └ <starlette.exceptions.ExceptionMiddleware object at 0x7f9577464910>
  File "/home/usr/.local/lib/python3.7/site-packages/starlette/routing.py", line 550, in __call__
    await route.handle(scope, receive, send)
          │     │      │      │        └ <function ExceptionMiddleware.__call__.<locals>.sender at 0x7f957740d5f0>
          │     │      │      └ <bound method RequestResponseCycle.receive of <uvicorn.protocols.http.httptools_impl.RequestResponseCycle object at 0x7f95774...
          │     │      └ {'type': 'http', 'http_version': '1.1', 'server': ('127.0.0.1', 8000), 'client': ('127.0.0.1', 55270), 'scheme': 'http', 'met...
          │     └ <function Route.handle at 0x7f9579d31680>
          └ <fastapi.routing.APIRoute object at 0x7f9577477710>
  File "/home/usr/.local/lib/python3.7/site-packages/starlette/routing.py", line 227, in handle

[Delgan]

The enqueue parameter defaults to False, so it doesn't matter if you comment it or define it explicitly. 👍

Anyway, I don't see anything related to Loguru in the traceback of your exception. 😕
Are you sure the problem is related to logging?
This looks related to multiprocessing and spawned process, maybe some object can't be serialized properly or maybe there is a configuration issue.

Unfortunately, without being able to reproduce the error and without seeing the full traceback, I can't guess what's going wrong. If it is not possible to have more information, I will conclude that it is not a bug related to Loguru. 😬

[lsabi]

Don't worry, now it's logging (despite being somehow slow). The problem may be below Loguru, i.e. some dependencies.

If I find the problem, I'll provide a sample config for using the library with async/await (so that other people don't make my same mistake). Shall I add it in the docs?

[Delgan]

Well, if you figure out anything that could help investigate this issue further, please let us know! At that time, we will decide if we need to update the documentation or if there is a bug that needs to be fixed.