Logging errors when running paperless-ngx with uvicorn 0.20.0

[eomanis]

Basically, when using uvicorn to run paperless-ngx, the application server produces many "logging errors" accompanied by stack traces.

The error message is:

TypeError: cannot unpack non-iterable NoneType object

The logging errors can be silenced by disabling access logs with --no-access-log.

Apart from that the application runs as expected; it mainly is a nuisance that forces the user to switch off access logging lest the log gets flooded.

Before I file an issue for uvicorn I would like to rule out that paperless-ngx is misbehaving.

The current version of paperless-ngx, 1.10.1, pulls uvicorn 0.19.0 in its requirements.txt.
This issue is present with both uvicorn 0.19.0 and 0.20.0.

Example:

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/__init__.py", line 1100, in emit
    msg = self.format(record)
  File "/usr/lib/python3.10/logging/__init__.py", line 943, in format
    return fmt.format(record)
  File "/usr/lib/python3.10/logging/__init__.py", line 681, in format
    s = self.formatMessage(record)
  File "/srv/paperless/python-venv/lib/python3.10/site-packages/uvicorn/logging.py", line 104, in formatMessage
    (
TypeError: cannot unpack non-iterable NoneType object
Call stack:
  File "/usr/lib/python3.10/threading.py", line 973, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "/srv/paperless/python-venv/lib/python3.10/site-packages/concurrent_log_handler/queue.py", line 49, in _monitor
    super()._monitor()
Message: 'XXX.XXX.XXX.XXX:XXXXX - "GET /accounts/login/?next=/ HTTP/1.0" 200'
Arguments: None

Any feedback is appreciated.

[Kludex]

Can you reproduce with standalone uvicorn?

[eomanis]

Can you reproduce with standalone uvicorn?

No, I can't. Running this ASGI example in the same environment with the same parameters as paperless-ngx produces clean access logs:

[paperless@theserver paperless]$ ./uvicorn-test-launch
Working directory is /srv/paperless/uvicorn-test
INFO:     Started server process [869223]
INFO:     Waiting for application startup.
INFO:     ASGI 'lifespan' protocol appears unsupported.
INFO:     Application startup complete.
INFO:     Uvicorn running on unix socket ../socket/paperless.sock (Press CTRL+C to quit)
INFO:     XXX.XXX.XXX.XXX:XXXXX - "GET /accounts/login/?next=/ HTTP/1.0" 200 OK
INFO:     XXX.XXX.XXX.XXX:XXXXX - "GET /favicon.ico HTTP/1.0" 200 OK

As far as I can tell, the code that throws the error is in uvicorn logging.py AccessFormatter.formatMessage():104:

(
    client_addr,
    method,
    full_path,
    http_version,
    status_code,
) = recordcopy.args  # type: ignore[misc]

As someone who does not know Python I assume that this code splits up recordcopy.args and assigns the parts to some variables. Could recordcopy.args being None cause this kind of error?

[Kludex]

Yeah, that's exactly why this error is.

The thing is... If we can't reproduce with standalone uvicorn, then we don't have a proof that something is wrong with uvicorn, and I'll assume that the issue is on paperless-ngx.