json-logging does not function with Flask / Connexion 3.x

[aholmes]

The Python package json-logging does not work with the 3.x versions of Flask or Connexion. This means the default JSON logging mechanism causes API endpoints to crash. The issue is seemingly caused by incompatible changes between the WSGI and ASGI specs.

For now, a fix is to configure plaintext logging in a Ligare.web application's config.toml:

[logging]
format = 'plaintext'

ERROR in __init__: 'Request' object has no attribute 'path'
Traceback (most recent call last):
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/flask/app.py", line 878, in full_dispatch_request
    rv = self.preprocess_request()
         ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/flask/app.py", line 1253, in preprocess_request
    rv = self.ensure_sync(before_func)()
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/json_logging/framework/connexion/__init__.py", line 53, in before_request
    if is_not_match_any_pattern(_current_request.path, exclude_url_patterns):
                                ^^^^^^^^^^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/connexion/lifecycle.py", line 243, in __getattr__
    return getattr(self._starlette_request, item)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'Request' object has no attribute 'path'
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
    ^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/werkzeug/local.py", line 318, in __get__
    obj = instance._get_current_object()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/werkzeug/local.py", line 526, in _get_current_object
    return get_name(local())
                    ^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/flask/logging.py", line 26, in wsgi_errors_stream
    return request.environ["wsgi.errors"]  # type: ignore[no-any-return]
           ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^
KeyError: 'wsgi.errors'
Call stack:
  File "gmy-ligare-app/app/__init__.py", line 14, in <module>
    app.run(host=config.host, port=int(config.port))
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/connexion/apps/abstract.py", line 281, in run
    self.middleware.run(import_string, **kwargs)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/connexion/middleware/main.py", line 497, in run
    uvicorn.run(app, **kwargs)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/uvicorn/main.py", line 579, in run
    server.run()
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
  File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/a2wsgi/wsgi.py", line 226, in sender
    await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/dependency_injection.py", line 140, in wrapped_send
    return await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 373, in wrapped_send
    _log_all_api_responses(request, response, config, log)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 281, in _log_all_api_responses
    log.info(
Message: 'Outgoing response:\n   Status code: %s\n   Status: %s'
Arguments: (500, 500)
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
    ^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/werkzeug/local.py", line 318, in __get__
    obj = instance._get_current_object()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/werkzeug/local.py", line 526, in _get_current_object
    return get_name(local())
                    ^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/flask/logging.py", line 26, in wsgi_errors_stream
    return request.environ["wsgi.errors"]  # type: ignore[no-any-return]
           ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^
KeyError: 'wsgi.errors'
Call stack:
  File "gmy-ligare-app/app/__init__.py", line 14, in <module>
    app.run(host=config.host, port=int(config.port))
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/connexion/apps/abstract.py", line 281, in run
    self.middleware.run(import_string, **kwargs)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/connexion/middleware/main.py", line 497, in run
    uvicorn.run(app, **kwargs)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/uvicorn/main.py", line 579, in run
    server.run()
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
  File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/a2wsgi/wsgi.py", line 226, in sender
    await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/dependency_injection.py", line 140, in wrapped_send
    return await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 376, in wrapped_send
    return await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 432, in wrapped_send
    log.info(
Message: 'Generated new UUID "b\'a401b7a5-6f9a-47f6-8773-826266ef4d1d\'" for X-Correlation-Id request header.'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1163, in emit
    stream.write(msg + self.terminator)
    ^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/werkzeug/local.py", line 318, in __get__
    obj = instance._get_current_object()
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/werkzeug/local.py", line 526, in _get_current_object
    return get_name(local())
                    ^^^^^^^
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/flask/logging.py", line 26, in wsgi_errors_stream
    return request.environ["wsgi.errors"]  # type: ignore[no-any-return]
           ~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^
KeyError: 'wsgi.errors'
Call stack:
  File "gmy-ligare-app/app/__init__.py", line 14, in <module>
    app.run(host=config.host, port=int(config.port))
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/connexion/apps/abstract.py", line 281, in run
    self.middleware.run(import_string, **kwargs)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/connexion/middleware/main.py", line 497, in run
    uvicorn.run(app, **kwargs)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/uvicorn/main.py", line 579, in run
    server.run()
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/uvicorn/server.py", line 65, in run
    return asyncio.run(self.serve(sockets=sockets))
  File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
  File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/a2wsgi/wsgi.py", line 226, in sender
    await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/dependency_injection.py", line 140, in wrapped_send
    return await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 376, in wrapped_send
    return await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 441, in wrapped_send
    return await send(message)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 344, in wrapped_send
    _log_all_api_requests(request, response, app, config, log)
  File "gmy-ligare-app/.venv/lib/python3.12/site-packages/Ligare/web/middleware/openapi/__init__.py", line 211, in _log_all_api_requests
    log.info(
Message: 'Incoming request:\n    %s %s\n    Host: %s\n    Remote address: %s\n    Remote user: %s'
Arguments: ('GET', '/', 'localhost:5000', '127.0.0.1:51382', 'Anonymous')
INFO:     127.0.0.1:51382 - "GET / HTTP/1.1" 500 Internal Server Error

[aholmes]

Resolving in #162 by removing json-logging and replacing with custom JSON formatter and log handler.