diff --git a/fastapi-vue/fastapi_vue/logging.py b/fastapi-vue/fastapi_vue/logging.py index 1290769..2380d8b 100644 --- a/fastapi-vue/fastapi_vue/logging.py +++ b/fastapi-vue/fastapi_vue/logging.py @@ -1,10 +1,9 @@ -"""Access log formatting, adapted from uvicorn's logging module. +"""Logging integration: tracerite loading and colored access log formatting. -Unlike uvicorn's AccessFormatter, the colored fields (``client``, ``status``, -``method``, ``host``, ``path``, ``extra``, ``timing``) are supplied by the -access log middleware via ``extra=``. When colors are disabled the ANSI -escape codes are stripped from the assembled output so the same formatting -code path produces plain text. +The access log middleware supplies colored fields (``client``, ``status``, +``method``, ``host``, ``path``, ``extra``, ``timing``) via ``extra=``. When +colors are disabled the ANSI escape codes are stripped from the assembled +output so the same formatting code path produces plain text. """ from __future__ import annotations @@ -12,46 +11,59 @@ from __future__ import annotations import logging import re import sys -from collections.abc import Callable from contextlib import suppress from copy import deepcopy -from typing import Any, Literal +from typing import Literal + +import tracerite +from uvicorn.config import Config + +from .accesslog import AccessLogMiddleware ANSI_ESCAPE_RE = re.compile(r"\x1b\[[0-9;]*m") ACCESS_LOG_FMT = "%(client)s %(status)s %(method)s %(host)s%(path)s %(extra)s%(timing)s" +ACCESS_LOGGER = "fastapi_vue.access" + def strip_ansi(text: str) -> str: return ANSI_ESCAPE_RE.sub("", text) -LogConfigPatch = Callable[[dict[str, Any]], None] +class Formatter(logging.Formatter): + """Formatter for the combined HTTP/WebSocket access log. -_LOG_CONFIG_PATCHES: list[LogConfigPatch] = [] - - -def log_config_patch(patch: LogConfigPatch) -> LogConfigPatch: - """Register a best-effort log config patch (applied by patch_log_config).""" - _LOG_CONFIG_PATCHES.append(patch) - return patch - - -def patch_log_config(log_config: Any) -> Any: # noqa: ANN401 - """Apply registered patches to a uvicorn log_config. - - Users presumably base their config on uvicorn's default dict, but any - shape is tolerated: each patch is applied on a best-effort basis and - silently skipped when the config does not have the expected structure. - Non-dict configs (e.g. an ini file path) pass through untouched. + Instantiation always loads tracerite, and with ``access=True`` also + installs the access-log middleware: ``dictConfig`` builds formatters while + uvicorn applies ``log_config``, which happens before the app is loaded — + including in reload/worker subprocesses that re-import the config without + calling ``fastapi_vue.server.run()`` again. """ - if not isinstance(log_config, dict): - return log_config - config = deepcopy(log_config) - for patch in _LOG_CONFIG_PATCHES: - with suppress(Exception): - patch(config) - return config + + def __init__( + self, + fmt: str | None = None, + datefmt: str | None = None, + style: Literal["%", "{", "$"] = "%", + use_colors: bool | None = None, + *, + access: bool = False, + ) -> None: + tracerite.load() + if access: + install_access_log() + if use_colors in (True, False): + self.use_colors = use_colors + else: + self.use_colors = sys.stdout.isatty() + super().__init__(fmt=fmt, datefmt=datefmt, style=style) + + def formatMessage(self, record: logging.LogRecord) -> str: + formatted = super().formatMessage(record) + if not self.use_colors: + formatted = strip_ansi(formatted) + return formatted class WebSocketChatterFilter(logging.Filter): @@ -71,98 +83,78 @@ class WebSocketChatterFilter(logging.Filter): return not msg.startswith(self._PREFIXES) -class AccessFormatter(logging.Formatter): - """Formatter for the combined HTTP/WebSocket access log. - - Instantiation installs the middleware patch: ``dictConfig`` builds this - formatter while uvicorn applies ``log_config``, which happens before the - app is loaded — including in reload/worker subprocesses that re-import the - config without calling ``fastapi_vue.server.run()`` again. - """ - - def __init__( - self, - fmt: str | None = None, - datefmt: str | None = None, - style: Literal["%", "{", "$"] = "%", - use_colors: bool | None = None, - ): - install_access_log() - if use_colors in (True, False): - self.use_colors = use_colors - else: - self.use_colors = sys.stdout.isatty() - super().__init__(fmt=fmt, datefmt=datefmt, style=style) - - def formatMessage(self, record: logging.LogRecord) -> str: - formatted = super().formatMessage(record) - if not self.use_colors: - formatted = strip_ansi(formatted) - return formatted +_installed = False def install_access_log() -> None: - """Wrap apps loaded by uvicorn with AccessLogMiddleware (idempotent).""" - from uvicorn.config import Config + """Wrap apps loaded by uvicorn with AccessLogMiddleware, once per process. - from .accesslog import AccessLogMiddleware - - if getattr(Config, "_fastapi_vue_accesslog", False): - return - Config._fastapi_vue_accesslog = True # type: ignore[attr-defined] - - if hasattr(Config, "load_app"): # uvicorn < 0.40 - original_load_app = Config.load_app - - def load_app(self): # noqa: ANN001, ANN202 - app = original_load_app(self) - return app if isinstance(app, AccessLogMiddleware) else AccessLogMiddleware(app) - - Config.load_app = load_app # type: ignore[method-assign] - else: - original_load = Config.load - - def load(self): # noqa: ANN001, ANN202 - original_load(self) - if not isinstance(self.loaded_app, AccessLogMiddleware): - self.loaded_app = AccessLogMiddleware(self.loaded_app) - - Config.load = load # type: ignore[method-assign] - - -@log_config_patch -def _patch_access_log(config: dict[str, Any]) -> None: - """Rewire a uvicorn log_config dict for our colored access logging. - - Logs to a private ``fastapi_vue.access`` logger: uvicorn's protocol-level - access logging is driven by ``uvicorn.access.hasHandlers()``, so we must - not attach handlers to that logger (``access_log=False`` strips them). + The guard is deliberately module-level: reload/worker subprocesses + re-import this module, resetting it so the patch is re-applied there. """ - formatters = config.get("formatters") - if isinstance(formatters, dict): - formatters["access"] = { - "()": "fastapi_vue.logging.AccessFormatter", - "fmt": ACCESS_LOG_FMT, - "use_colors": None, - } - - handlers = config.get("handlers") - if not isinstance(handlers, dict): + global _installed + if _installed: return + _installed = True - loggers = config.setdefault("loggers", {}) - if isinstance(loggers, dict) and "access" in handlers: - loggers["fastapi_vue.access"] = { - "handlers": ["access"], - "level": "INFO", - "propagate": False, + original_load = Config.load + + def load(self): # noqa: ANN001, ANN202 + original_load(self) + if not isinstance(self.loaded_app, AccessLogMiddleware): + self.loaded_app = AccessLogMiddleware(self.loaded_app) + + Config.load = load # type: ignore[method-assign] + + +def patch_log_config(log_config, *, access_log: bool = True): # noqa: ANN001, ANN201 + """Patch a uvicorn log_config dict for our logging, best-effort. + + Users presumably base their config on uvicorn's default dict, but any + shape is tolerated: pieces that do not fit the config's structure are + silently skipped. Non-dict configs (e.g. an ini file path) pass through + untouched. + + Always adds an unreferenced NullHandler whose Formatter instantiation + loads tracerite in every process uvicorn applies the config in, and a + filter dropping stock uvicorn's WebSocket chatter from ``uvicorn.error``. + With ``access_log``, additionally rewires the ``access`` formatter to our + Formatter and attaches its handler to our ``fastapi_vue.access`` logger. + We must not attach handlers to ``uvicorn.access``: uvicorn gates its own + protocol-level access logging on ``uvicorn.access.hasHandlers()``. + """ + if not isinstance(log_config, dict): + return log_config + config = deepcopy(log_config) + + with suppress(Exception): + config["formatters"]["fastapi_vue"] = {"()": "fastapi_vue.logging.Formatter"} + config["handlers"]["fastapi_vue"] = { + "class": "logging.NullHandler", + "formatter": "fastapi_vue", } - default = handlers.get("default") - if isinstance(default, dict): + with suppress(Exception): filters = config.setdefault("filters", {}) - if isinstance(filters, dict): - filters["ws_chatter"] = {"()": "fastapi_vue.logging.WebSocketChatterFilter"} - handler_filters = default.setdefault("filters", []) - if isinstance(handler_filters, list) and "ws_chatter" not in handler_filters: - handler_filters.append("ws_chatter") + filters["ws_chatter"] = {"()": "fastapi_vue.logging.WebSocketChatterFilter"} + handler_filters = config["handlers"]["default"].setdefault("filters", []) + if "ws_chatter" not in handler_filters: + handler_filters.append("ws_chatter") + + if access_log: + with suppress(Exception): + config["formatters"]["access"] = { + "()": "fastapi_vue.logging.Formatter", + "fmt": ACCESS_LOG_FMT, + "use_colors": None, + "access": True, + } + with suppress(Exception): + if "access" in config["handlers"]: + config.setdefault("loggers", {})[ACCESS_LOGGER] = { + "handlers": ["access"], + "level": "INFO", + "propagate": False, + } + + return config diff --git a/fastapi-vue/fastapi_vue/server.py b/fastapi-vue/fastapi_vue/server.py index 8024a84..06c23bb 100644 --- a/fastapi-vue/fastapi_vue/server.py +++ b/fastapi-vue/fastapi_vue/server.py @@ -7,12 +7,14 @@ from contextlib import suppress from pathlib import Path from typing import Any +import tracerite import uvicorn from uvicorn import Config, Server from .hostutil import parse_endpoints from .logging import install_access_log, patch_log_config +tracerite.load() # Early load on CLI load (import server); uvicorn workers reload via log config logger = logging.getLogger(__name__) @@ -37,11 +39,12 @@ def run( # noqa: PLR0913 directory. True enables reload without setting a reload directory. False disables reload and clears any reload_dirs. workers: Number of worker processes (requires uvicorn.run, single endpoint only). - access_log: Enable our colored HTTP/WebSocket access logging (uvicorn's - own access log is disabled either way). - log_config: Logging config passed to uvicorn. When access_log is - enabled, dict configs are patched best-effort for our access log - formatting (see fastapi_vue.logging.patch_log_config). + access_log: Enable our colored HTTP/WebSocket access logging middleware + (uvicorn's own access logging is always bypassed). + log_config: Logging config passed to uvicorn. Dict configs are patched + best-effort (see fastapi_vue.logging.patch_log_config): tracerite + loading and WebSocket chatter filtering are always installed, and + when access_log is enabled the access formatting is rewired too. **uvicorn_config: Additional uvicorn config options (overrides all other settings). """ @@ -57,9 +60,8 @@ def run( # noqa: PLR0913 if access_log: install_access_log() - log_config = patch_log_config(log_config) - uvicorn_config["access_log"] = False - uvicorn_config["log_config"] = log_config + uvicorn_config["access_log"] = False # We always bypass uvicorn's own access logging + uvicorn_config["log_config"] = patch_log_config(log_config, access_log=access_log) conf: dict[str, object] = {"app": app, "reload": bool(reload), "workers": workers} proxy = os.getenv("FORWARDED_ALLOW_IPS", "127.0.0.1,::1") diff --git a/fastapi-vue/pyproject.toml b/fastapi-vue/pyproject.toml index efd10b6..4459098 100644 --- a/fastapi-vue/pyproject.toml +++ b/fastapi-vue/pyproject.toml @@ -8,6 +8,7 @@ dependencies = [ "fastapi>=0.115.0", "zstandard>=0.23.0", "blake3>=1.0.8", + "tracerite>=2.6.5", ] [project.urls]