Propagate Gunicorn Uvicorn worker logs

Author: br3ndonland

.basedpyright/baseline.json

@@ -1445,6 +1445,86 @@
                     "lineCount": 1
                 }
             },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 21,
+                    "endColumn": 59,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 21,
+                    "endColumn": 59,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 21,
+                    "endColumn": 62,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 21,
+                    "endColumn": 62,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 4,
+                    "endColumn": 16,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 19,
+                    "endColumn": 32,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 14,
+                    "endColumn": 37,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 40,
+                    "endColumn": 61,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 4,
+                    "endColumn": 11,
+                    "lineCount": 1
+                }
+            },
+            {
+                "code": "reportAny",
+                "range": {
+                    "startColumn": 20,
+                    "endColumn": 33,
+                    "lineCount": 1
+                }
+            },
             {
                 "code": "reportAny",
                 "range": {

docs/logging.md

@@ -13,6 +13,9 @@ See [environment variable reference](environment.md).
 - inboard's logging configuration logic is located in [`logging_conf.py`](https://github.com/br3ndonland/inboard/blob/HEAD/inboard/logging_conf.py). By default, inboard will load the `LOGGING_CONFIG` dictionary in this module. The dictionary was named for consistency with [Uvicorn's logging configuration dictionary](https://github.com/encode/uvicorn/blob/HEAD/uvicorn/config.py).
 - When running Uvicorn alone, logging is configured programmatically from within the [`start.py` start script](https://github.com/br3ndonland/inboard/blob/HEAD/inboard/start.py), by passing the `LOGGING_CONFIG` dictionary to `uvicorn.run()`.
 - When running Gunicorn with the Uvicorn worker, the logging configuration dictionary is specified within the [`gunicorn_conf.py`](https://github.com/br3ndonland/inboard/blob/HEAD/inboard/gunicorn_conf.py) configuration file.
+- The Gunicorn Uvicorn worker has been updated to remove handlers from `uvicorn.error` and `uvicorn.access` and instead propagate those log records to the root logger. This avoids duplicate records and ensures the root handler applies the configured formatter and filters.
+    - The Uvicorn worker class originally disabled propagation because it resulted in duplicate logs if enabled ([encode/uvicorn#614](https://github.com/encode/uvicorn/issues/614), [encode/uvicorn#623](https://github.com/encode/uvicorn/pull/623)). As the [docs](https://docs.python.org/3/library/logging.html#logging.Logger.propagate) on `logging.Logger.propagate` explain, "If you attach a handler to a logger _and_ one or more of its ancestors, it may emit the same record multiple times."
+    - Instead of disabling propagation and keeping Gunicorn handlers set on the logger, another solution is to remove the Gunicorn handlers and enable propagation so the root logger can manage all logs ([br3ndonland/inboard#131](https://github.com/br3ndonland/inboard/discussions/131)).
 
 ## Filtering log messages
 
@@ -128,7 +131,8 @@ If the inboard Python package is installed from PyPI, the logging configuration
         "()": "package.custom_logging.MyFormatterClass",
     }
 
-    # only show access logs when running Uvicorn with LOG_LEVEL=debug
+    # only show access logs when running Uvicorn alone with LOG_LEVEL=debug
+    # Gunicorn-managed Uvicorn workers always propagate access logs to root
     LOGGING_CONFIG["loggers"]["gunicorn.access"] = {"propagate": False}
     LOGGING_CONFIG["loggers"]["uvicorn.access"] = {
         "propagate": str(os.getenv("LOG_LEVEL")) == "debug"
@@ -143,7 +147,7 @@ If the inboard Python package is installed from PyPI, the logging configuration
 
 ## Overriding the logging config
 
-Want to override inboard's entire logging config? No problem. Set up a separate `LOGGING_CONFIG` dictionary, and pass inboard the path to the module containing the dictionary. Try something like this:
+Want to override inboard's entire logging config? No problem. Set up a separate `LOGGING_CONFIG` dictionary, and pass inboard the path to the module containing the dictionary. Gunicorn-managed Uvicorn workers route `uvicorn.error` and `uvicorn.access` through the root logger, so configure the root handler with the formatter and output stream those records should use. Logger-specific Uvicorn handlers only apply when running Uvicorn without Gunicorn. Try something like this:
 
 !!! example "Example of a complete custom logging config"
 
@@ -161,11 +165,7 @@ Want to override inboard's entire logging config? No problem. Set up a separate
                 "format": "%(asctime)s [%(process)d] [%(levelname)s] %(message)s",
                 "datefmt": "[%Y-%m-%d %H:%M:%S %z]",
             },
-            # Format Uvicorn loggers with Uvicorn's config directly
-            "uvicorn.access": {
-                "()": UVICORN_LOGGING_CONFIG["formatters"]["access"]["()"],
-                "format": UVICORN_LOGGING_CONFIG["formatters"]["access"]["fmt"],
-            },
+            # Format propagated logs with Uvicorn's default formatter
             "uvicorn.default": {
                 "()": UVICORN_LOGGING_CONFIG["formatters"]["default"]["()"],
                 "format": UVICORN_LOGGING_CONFIG["formatters"]["default"]["fmt"],
@@ -190,12 +190,6 @@ Want to override inboard's entire logging config? No problem. Set up a separate
                 "formatter": "gunicorn.access",
                 "stream": "ext://sys.stdout",
             },
-            # Add a separate handler just for uvicorn.access
-            "uvicorn.access": {
-                "class": "logging.StreamHandler",
-                "formatter": "uvicorn.access",
-                "stream": "ext://sys.stdout",
-            },
         },
         "loggers": {
             "fastapi": {"propagate": True},
@@ -207,20 +201,17 @@ Want to override inboard's entire logging config? No problem. Set up a separate
                 "level": "INFO",
                 "propagate": False,
             },
-            # Use the uvicorn.access handler, and don't propagate to root
+            # Propagate Uvicorn logs to the configured root handler
             "uvicorn.access": {
-                "handlers": ["uvicorn.access"],
                 "level": "INFO",
-                "propagate": False,
+                "propagate": True,
             },
-            # Use the error handler to output to stderr, and don't propagate to root
             "uvicorn.error": {
-                "handlers": ["error"],
                 "level": "INFO",
-                "propagate": False,
+                "propagate": True,
             },
         },
-        # Use the uvicorn.default formatter for root
+        # Format all propagated logs with uvicorn.default
         "root": {"handlers": ["default"], "level": "INFO"},
     }
 

inboard/gunicorn_workers.py

@@ -40,7 +40,7 @@
 from uvicorn.server import Server
 
 
-class UvicornWorker(Worker):  # type: ignore[misc]
+class UvicornWorker(Worker):
     """
     A worker class for Gunicorn that interfaces with an ASGI consumer callable,
     rather than a WSGI callable.
@@ -52,14 +52,14 @@ def __init__(self, *args: Any, **kwargs: Any) -> None:
         super().__init__(*args, **kwargs)
 
         logger = logging.getLogger("uvicorn.error")
-        logger.handlers = self.log.error_log.handlers
+        logger.handlers = []
         logger.setLevel(self.log.error_log.level)
-        logger.propagate = False
+        logger.propagate = True
 
         logger = logging.getLogger("uvicorn.access")
-        logger.handlers = self.log.access_log.handlers
+        logger.handlers = []
         logger.setLevel(self.log.access_log.level)
-        logger.propagate = False
+        logger.propagate = True
 
         config_kwargs: dict[str, Any] = {
             "app": None,

tests/test_gunicorn_workers.py

@@ -86,6 +86,15 @@ async def app_with_lifespan_startup_failure(
             await send(lifespan_startup_failed_event)
 
 
+async def app_with_unhandled_exception(
+    scope: Scope, _: ASGIReceiveCallable, send: ASGISendCallable
+) -> None:
+    """An ASGI app for testing unhandled request exceptions."""
+    del send
+    assert scope["type"] == "http"
+    raise RuntimeError("Unhandled ASGI exception")
+
+
 @pytest.fixture
 def tls_certificate_authority() -> trustme.CA:
     return trustme.CA()
@@ -163,6 +172,26 @@ def worker_class(request: pytest.FixtureRequest) -> str:
     )
 
 
+@pytest.fixture(
+    params=(
+        pytest.param(gunicorn_workers_inboard.UvicornWorker, marks=pytestmarks),
+        pytest.param(gunicorn_workers_inboard.UvicornH11Worker, marks=pytestmarks),
+    )
+)
+def worker_class_uvicorn(request: pytest.FixtureRequest) -> str:
+    """Gunicorn Uvicorn worker class names to test.
+
+    This is a parametrized fixture. When the fixture is used in a test, the test
+    will be automatically parametrized, running once for each fixture parameter. All
+    tests using the fixture will be automatically marked with `pytest.mark.subprocess`.
+
+    https://docs.pytest.org/en/latest/how-to/fixtures.html
+    https://docs.pytest.org/en/latest/proposals/parametrize_with_fixtures.html
+    """
+    worker_class = request.param
+    return f"{worker_class.__module__}.{worker_class.__name__}"
+
+
 @pytest.fixture(
     params=(
         pytest.param(False, id="TLS off"),
@@ -229,6 +258,74 @@ def gunicorn_process(
             assert process.poll() is not None
 
 
+@pytest.fixture(
+    params=(
+        pytest.param(False, id="TLS off"),
+        pytest.param(True, id="TLS on"),
+    )
+)
+def gunicorn_uvicorn_process_with_unhandled_exception(
+    request: pytest.FixtureRequest,
+    tls_ca_certificate_pem_path: str,
+    tls_ca_ssl_context: SSLContext,
+    tls_certificate_private_key_path: str,
+    tls_certificate_server_cert_path: str,
+    unused_tcp_port: int,
+    worker_class_uvicorn: str,
+) -> Generator[Process, None, None]:
+    """Yield a subprocess running a Gunicorn arbiter with a Uvicorn worker.
+
+    An instance of `httpxyz.Client` is available on the `client` attribute.
+    Output is saved to a temporary file and accessed with `read_output()`.
+    """
+    app_module = f"{__name__}:{app_with_unhandled_exception.__name__}"
+    bind = f"127.0.0.1:{unused_tcp_port}"
+    use_tls: bool = request.param
+    args = [
+        "gunicorn",
+        "--bind",
+        bind,
+        "--config",
+        "python:inboard.gunicorn_conf",
+        "--graceful-timeout",
+        "1",
+        "--log-level",
+        "debug",
+        "--worker-class",
+        worker_class_uvicorn,
+        "--workers",
+        "1",
+    ]
+    if use_tls is True:
+        args_for_tls = [
+            "--ca-certs",
+            tls_ca_certificate_pem_path,
+            "--certfile",
+            tls_certificate_server_cert_path,
+            "--keyfile",
+            tls_certificate_private_key_path,
+        ]
+        args.extend(args_for_tls)
+        base_url = f"https://{bind}"
+        verify: SSLContext | bool = tls_ca_ssl_context
+    else:
+        base_url = f"http://{bind}"
+        verify = False
+    args.append(app_module)
+    transport = httpxyz.HTTPTransport(retries=5, verify=verify)
+    with (
+        httpxyz.Client(base_url=base_url, transport=transport) as client,
+        tempfile.TemporaryFile() as output,
+    ):
+        with Process(args, client=client, output=output) as process:
+            time.sleep(2)
+            assert process.poll() is None
+            yield process
+            process.terminate()
+            _ = process.wait(timeout=5)
+            assert process.poll() is not None
+
+
 @pytest.fixture
 def gunicorn_process_with_lifespan_startup_failure(
     unused_tcp_port: int,
@@ -306,11 +403,11 @@ def test_uvicorn_worker_boot_error(
 ) -> None:
     """Test Gunicorn arbiter shutdown behavior after Uvicorn worker boot errors.
 
-    Previously, if Uvicorn workers raised exceptions during startup,
-    Gunicorn continued trying to boot workers ([#1066]). To avoid this,
-    the Uvicorn worker was updated to exit with `Arbiter.WORKER_BOOT_ERROR`,
-    but no tests were included at that time ([#1077]). This test verifies
-    that Gunicorn shuts down appropriately after a Uvicorn worker boot error.
+    Previously, if Uvicorn workers raised exceptions during startup, Gunicorn continued
+    trying to boot workers ([encode/uvicorn#1066]). To avoid this, the Uvicorn worker
+    was updated to exit with `Arbiter.WORKER_BOOT_ERROR`, but no tests were included at
+    that time ([encode/uvicorn#1077]). This test verifies that Gunicorn shuts down
+    appropriately after a Uvicorn worker boot error.
 
     When a worker exits with `Arbiter.WORKER_BOOT_ERROR`, the Gunicorn arbiter will
     also terminate, so there is no need to send a separate signal to the arbiter.
@@ -324,6 +421,40 @@ def test_uvicorn_worker_boot_error(
     assert "Worker failed to boot" in output_text
 
 
+def test_uvicorn_worker_logging_config(
+    gunicorn_uvicorn_process_with_unhandled_exception: Process,
+) -> None:
+    """Test that Uvicorn worker logs propagate to the root logging configuration
+    instead of using Gunicorn handlers.
+
+    The Uvicorn worker class originally disabled propagation because it resulted in
+    duplicate logs if enabled ([encode/uvicorn#614], [encode/uvicorn#623]). As the
+    [docs](https://docs.python.org/3/library/logging.html#logging.Logger.propagate) on
+    `logging.Logger.propagate` explain, "If you attach a handler to a logger _and_ one
+    or more of its ancestors, it may emit the same record multiple times."
+
+    Instead of disabling propagation and keeping Gunicorn handlers set on the logger,
+    another solution is to remove the Gunicorn handlers and enable propagation so the
+    root logger can manage all logs ([br3ndonland/inboard#131]).
+
+    [br3ndonland/inboard#131]: https://github.com/br3ndonland/inboard/discussions/131
+    [encode/uvicorn#614]: https://github.com/encode/uvicorn/issues/614
+    [encode/uvicorn#623]: https://github.com/encode/uvicorn/pull/623
+    """
+    response = gunicorn_uvicorn_process_with_unhandled_exception.client.get("/")
+    output_text = gunicorn_uvicorn_process_with_unhandled_exception.read_output()
+    exception_lines = [
+        line
+        for line in output_text.splitlines()
+        if "Exception in ASGI application" in line
+    ]
+    assert response.status_code == 500
+    assert len(exception_lines) == 1
+    assert "uvicorn.error" in exception_lines[0]
+    assert output_text.count('"GET / HTTP/1.1" 500') == 1
+    assert output_text.count("RuntimeError: Unhandled ASGI exception") == 1
+
+
 def test_worker_get_request(gunicorn_process: Process) -> None:
     """Test a GET request to the Gunicorn worker's ASGI app."""
     response = gunicorn_process.client.get("/")