Merge pull request #118 from lsst-sqre/tickets/DM-35879

[DM-35879] Support sending Uvicorn logs through structlog

CHANGELOG.md

@@ -5,8 +5,10 @@ Headline template:
 X.Y.Z (YYYY-MM-DD)
 -->
 
-## 3.3.0 (unreleased)
+## 3.3.0 (2022-09-15)
 
+- Add new function `safir.logging.configure_uvicorn_logging` that routes Uvicorn logging through structlog for consistent formatting.
+  It also adds context to Uvicorn logs in the format recognized by Google's Cloud Logging.
 - Support the newer project metadata structure and URL naming used by `pyproject.toml`-only packages in `safir.metadata.get_metadata`.
 
 ## 3.2.0 (2022-05-13)

docs/user-guide/logging.rst

@@ -36,6 +36,25 @@ To configure logging, run the `safir.logging.configure_logging` function in appl
 
    See the `~safir.logging.configure_logging` for details about the parameters.
 
+Including uvicorn logs
+----------------------
+
+Uvicorn_ is normally used to run FastAPI web applications.
+It logs messages about its own operations, and logs each request to the underlying web application.
+By default, those logs use a separate logging profile and do not honor structlog configuration settings such as whether to log messages in JSON.
+
+For consistency, you may want to route Uvicorn log messages through structlog.
+Safir provides the `safir.logging.configure_uvicorn_logging` function to modify the Uvicorn logging configuration to do so:
+
+.. code-block:: python
+
+   configure_uvicorn_logging(config.log_level)
+
+This should be called after `~safir.logging.configure_logging`.
+To ensure that logging is reconfigured before Uvicorn logs its first message, it should be called either during import time of the module that provides the FastAPI application or during execution of a callable that constructs the FastAPI application
+
+When `~safir.logging.configure_uvicorn_logging` is called, it will also add a log processor that parses the Uvicorn access log messages and adds structlog context in the format expected by Google's Cloud Logging system.
+
 .. _logging-in-handlers:
 
 Logging in request handlers

src/safir/logging.py

@@ -3,14 +3,21 @@
 from __future__ import annotations
 
 import logging
+import logging.config
+import re
 import sys
 from typing import Any, List, Optional
 
 import structlog
 from structlog.stdlib import add_log_level
 from structlog.types import EventDict
 
-__all__ = ["add_log_severity", "configure_logging", "logger_name"]
+__all__ = [
+    "add_log_severity",
+    "configure_logging",
+    "configure_uvicorn_logging",
+    "logger_name",
+]
 
 logger_name: Optional[str] = None
 """Name of the configured global logger.
@@ -23,6 +30,9 @@
 `configure_logging` change the stored logger name.
 """
 
+_UVICORN_ACCESS_REGEX = re.compile(r'^[0-9.]+:[0-9]+ - "([^"]+)" ([0-9]+)$')
+"""Regex to parse Uvicorn access logs."""
+
 
 def add_log_severity(
     logger: logging.Logger, method_name: str, event_dict: EventDict
@@ -169,3 +179,126 @@ def configure_logging(
     # Set the configured name for the global logger.
     global logger_name
     logger_name = name
+
+
+def _process_uvicorn_access_log(
+    logger: logging.Logger, method_name: str, event_dict: EventDict
+) -> EventDict:
+    """Parse a Uvicorn access log entry into key/value pairs.
+
+    Intended for use as a structlog processor.
+
+    This checks whether the log message is a Uvicorn access log entry and, if
+    so, parses the message into key/value pairs for JSON logging so that the
+    details can be programmatically extracted.  ``remoteIp`` is intentionally
+    omitted since it isn't aware of ``X-Forwarded-For`` and will therefore
+    always point to an uninteresting in-cluster IP.
+
+    Parameters
+    ----------
+    logger : `logging.Logger`
+        The wrapped logger object.
+    method_name : `str`
+        The name of the wrapped method (``warning`` or ``error``, for
+        example).
+    event_dict : `structlog.types.EventDict`
+        Current context and current event. This parameter is also modified in
+        place, matching the normal behavior of structlog processors.
+
+    Returns
+    -------
+    event_dict : `structlog.types.EventDict`
+        The modified `~structlog.types.EventDict` with the added key.
+    """
+    match = _UVICORN_ACCESS_REGEX.match(event_dict["event"])
+    if not match:
+        return event_dict
+    request = match.group(1)
+    method, rest = request.split(" ", 1)
+    url, protocol = rest.rsplit(" ", 1)
+    if "httpRequest" not in event_dict:
+        event_dict["httpRequest"] = {}
+    event_dict["httpRequest"]["protocol"] = protocol
+    event_dict["httpRequest"]["requestMethod"] = method
+    event_dict["httpRequest"]["requestUrl"] = url
+    event_dict["httpRequest"]["status"] = match.group(2)
+    return event_dict
+
+
+def configure_uvicorn_logging(loglevel: str = "info") -> None:
+    """Set up logging.
+
+    This configures Uvicorn to use structlog for output formatting and
+    installs a custom processor to parse its access log messages into
+    additional log context that matches the format of Google log messages.
+    This helps Google's Cloud Logging system understand the logs.
+
+    Parameters
+    ----------
+    loglevel : `str`
+        The log level for Uvicorn logs, in string form (case-insensitive):
+
+        - ``DEBUG``
+        - ``INFO``
+        - ``WARNINGS``
+        - ``ERROR``
+
+        The default is ``INFO``.
+
+    Notes
+    -----
+    This method should normally be called after `configure_logging` during
+    FastAPI app creation. It should be called during Python module import or
+    inside the function that creates and returns the FastAPI app that Uvicorn
+    will run. This ensures the logging setup is complete before Uvicorn logs
+    its first message.
+    """
+    processors = [
+        structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+        structlog.processors.JSONRenderer(),
+    ]
+    logging.config.dictConfig(
+        {
+            "version": 1,
+            "disable_existing_loggers": False,
+            "formatters": {
+                "json-access": {
+                    "()": structlog.stdlib.ProcessorFormatter,
+                    "processors": processors,
+                    "foreign_pre_chain": [
+                        add_log_severity,
+                        _process_uvicorn_access_log,
+                    ],
+                },
+                "json": {
+                    "()": structlog.stdlib.ProcessorFormatter,
+                    "processors": processors,
+                    "foreign_pre_chain": [add_log_severity],
+                },
+            },
+            "handlers": {
+                "uvicorn.access": {
+                    "level": loglevel.upper(),
+                    "class": "logging.StreamHandler",
+                    "formatter": "json-access",
+                },
+                "uvicorn.default": {
+                    "level": loglevel.upper(),
+                    "class": "logging.StreamHandler",
+                    "formatter": "json",
+                },
+            },
+            "loggers": {
+                "uvicorn.error": {
+                    "handlers": ["uvicorn.default"],
+                    "level": loglevel.upper(),
+                    "propagate": False,
+                },
+                "uvicorn.access": {
+                    "handlers": ["uvicorn.access"],
+                    "level": loglevel.upper(),
+                    "propagate": False,
+                },
+            },
+        }
+    )