From f3646ed6c5ab0e2c84e5995844aa039fcf43c2c3 Mon Sep 17 00:00:00 2001 From: Leo Vasanko Date: Wed, 28 Jan 2026 23:01:35 +0000 Subject: [PATCH] Improved access logging. --- paskia/fastapi/__main__.py | 1 + paskia/fastapi/logging.py | 218 +++++++++++++++++++++++++++++++++++++ paskia/fastapi/mainapp.py | 12 +- paskia/fastapi/wsutil.py | 17 ++- 4 files changed, 244 insertions(+), 4 deletions(-) create mode 100644 paskia/fastapi/logging.py diff --git a/paskia/fastapi/__main__.py b/paskia/fastapi/__main__.py index 2868dee..50d2182 100644 --- a/paskia/fastapi/__main__.py +++ b/paskia/fastapi/__main__.py @@ -189,6 +189,7 @@ def main(): run_kwargs: dict = { "log_level": "info", + "access_log": False, # We use custom AccessLogMiddleware instead } if devmode: diff --git a/paskia/fastapi/logging.py b/paskia/fastapi/logging.py new file mode 100644 index 0000000..5fa4281 --- /dev/null +++ b/paskia/fastapi/logging.py @@ -0,0 +1,218 @@ +"""Custom access logging middleware for FastAPI/Uvicorn.""" + +import logging +import sys +import time +from ipaddress import IPv6Address + +from starlette.middleware.base import BaseHTTPMiddleware +from starlette.requests import Request +from starlette.responses import Response + +logger = logging.getLogger("paskia.access") + +_RESET = "\033[0m" +_STATUS_INFO = "\033[32m" # 1xx (green) +_STATUS_OK = "\033[92m" # 2xx (bright green) +_STATUS_REDIRECT = "\033[32m" # 3xx (green) +_STATUS_CLIENT_ERR = "\033[0;31m" # 4xx (red) +_STATUS_SERVER_ERR = "\033[1;31m" # 5xx (bright red) +_METHOD_READ = "\033[0;34m" # GET, HEAD, OPTIONS (blue) +_METHOD_WRITE = "\033[1;34m" # POST, PUT, DELETE, PATCH (bright blue) +_HOST = "\033[1;30m" # hostname (dark grey) +_PATH = "\033[0m" # path (default) +_TIMING = "\033[2m" # timing (dim) +_WS_OPEN = "\033[1;33m" # WebSocket connect (bright yellow) +_WS_CLOSE = "\033[0;33m" # WebSocket disconnect (yellow) +_WS_STATUS = "\033[1;30m" # WebSocket close status (dark grey) + + +def format_ipv6_network(ip: str) -> str: + """Format IPv6 address to show only network part (first 64 bits).""" + try: + addr = IPv6Address(ip) + # Get the integer representation and mask to first 64 bits + network_int = int(addr) >> 64 + # Format as IPv6 with trailing :: + # Split into 4 groups of 16 bits + groups = [] + for _ in range(4): + groups.insert(0, format(network_int & 0xFFFF, "x")) + network_int >>= 16 + # Compress consecutive zero groups + result = ":".join(groups) + "::" + # Simplify leading zeros in groups and compress + return str(IPv6Address(result + "0")) + except Exception: + return ip + + +def format_client_ip(ip: str) -> str: + """Format client IP, compressing IPv6 to network part only.""" + if not ip or ip == "-": + return "-" + if ":" in ip: + return format_ipv6_network(ip) + return ip + + +def status_color(status: int) -> str: + """Return color code based on HTTP status.""" + if status < 200: + return _STATUS_INFO + if status < 300: + return _STATUS_OK + if status < 400: + return _STATUS_REDIRECT + if status < 500: + return _STATUS_CLIENT_ERR + return _STATUS_SERVER_ERR + + +def method_color(method: str) -> str: + """Return color code based on HTTP method.""" + if method in ("GET", "HEAD", "OPTIONS"): + return _METHOD_READ + return _METHOD_WRITE + + +def format_access_log( + client: str, status: int, method: str, host: str, path: str, duration_ms: float +) -> str: + """Format access log line with colors and aligned fields.""" + use_color = sys.stderr.isatty() + + # Format components with fixed widths for alignment + ip = format_client_ip(client).ljust(15) # IPv4 max 15 chars + timing = f"{duration_ms:.0f}ms" + method_padded = method.ljust(7) # Longest method is OPTIONS (7) + + if use_color: + status_str = f"{status_color(status)}{status}{_RESET}" + timing_str = f"{_TIMING}{timing}{_RESET}" + method_str = f"{method_color(method)}{method_padded}{_RESET}" + host_str = f"{_HOST}{host}{_RESET}" + path_str = f"{_PATH}{path}{_RESET}" + else: + status_str = str(status) + timing_str = timing + method_str = method_padded + host_str = host + path_str = path + + # Format: "IP STATUS METHOD host path TIMING" + return f"{ip} {status_str} {method_str} {host_str}{path_str} {timing_str}" + + +# WebSocket connection counter (mod 100) +_ws_counter = 0 + + +def _next_ws_id() -> int: + """Get next WebSocket connection ID (0-99).""" + global _ws_counter + ws_id = _ws_counter + _ws_counter = (_ws_counter + 1) % 100 + return ws_id + + +def log_ws_open(client: str, host: str, path: str) -> int: + """Log WebSocket connection open. Returns connection ID for use in close.""" + use_color = sys.stderr.isatty() + ws_id = _next_ws_id() + + ip = format_client_ip(client).ljust(15) + id_str = f"{ws_id:02d}".ljust(7) # Align with method field (7 chars) + + if use_color: + # 🔌 aligned with status (takes ~2 char width), ID aligned with method + prefix = f"🔌 {_WS_OPEN}{id_str}{_RESET}" + host_str = f"{_HOST}{host}{_RESET}" + path_str = f"{_PATH}{path}{_RESET}" + else: + prefix = f"WS+ {id_str}" + host_str = host + path_str = path + + logger.info(f"{ip} {prefix} {host_str}{path_str}") + return ws_id + + +# WebSocket close codes to human-readable status +WS_CLOSE_CODES = { + 1000: "ok", + 1001: "going away", + 1002: "protocol error", + 1003: "unsupported", + 1005: "no status", + 1006: "abnormal", + 1007: "invalid data", + 1008: "policy violation", + 1009: "too large", + 1010: "extension required", + 1011: "server error", + 1012: "restarting", + 1013: "try again", + 1014: "bad gateway", + 1015: "tls error", +} + + +def log_ws_close( + client: str, ws_id: int, close_code: int | None, duration_ms: float +) -> None: + """Log WebSocket connection close with duration and status.""" + use_color = sys.stderr.isatty() + + ip = format_client_ip(client).ljust(15) + id_str = f"{ws_id:02d}".ljust(7) # Align with method field (7 chars) + timing = f"{duration_ms:.0f}ms" + + # Convert close code to status text + if close_code is None: + status = "closed" + else: + status = WS_CLOSE_CODES.get(close_code, f"code {close_code}") + + if use_color: + # 🔌 aligned with status, ID aligned with method + prefix = f"🔌 {_WS_CLOSE}{id_str}{_RESET}" + status_str = f"{_WS_STATUS}{status}{_RESET}" + timing_str = f"{_TIMING}{timing}{_RESET}" + else: + prefix = f"WS- {id_str}" + status_str = status + timing_str = timing + + logger.info(f"{ip} {prefix} {status_str} {timing_str}") + + +class AccessLogMiddleware(BaseHTTPMiddleware): + """Middleware that logs HTTP requests with custom format.""" + + async def dispatch(self, request: Request, call_next) -> Response: + start = time.perf_counter() + response = await call_next(request) + duration_ms = (time.perf_counter() - start) * 1000 + + client = request.client.host if request.client else "-" + host = request.headers.get("host", "-") + method = request.method + path = request.url.path + if request.url.query: + path = f"{path}?{request.url.query}" + status = response.status_code + + line = format_access_log(client, status, method, host, path, duration_ms) + logger.info(line) + + return response + + +def configure_access_logging(): + """Configure the access logger to output to stderr.""" + handler = logging.StreamHandler(sys.stderr) + handler.setFormatter(logging.Formatter("%(message)s")) + logger.addHandler(handler) + logger.setLevel(logging.INFO) + logger.propagate = False diff --git a/paskia/fastapi/mainapp.py b/paskia/fastapi/mainapp.py index 0381e88..675a784 100644 --- a/paskia/fastapi/mainapp.py +++ b/paskia/fastapi/mainapp.py @@ -11,9 +11,13 @@ from fastapi_vue import Frontend from paskia import globals from paskia.db import start_background, stop_background from paskia.fastapi import admin, api, auth_host, ws +from paskia.fastapi.logging import AccessLogMiddleware, configure_access_logging from paskia.fastapi.session import AUTH_COOKIE from paskia.util import hostutil, passphrase, vitedev +# Configure custom access logging +configure_access_logging() + # Vue Frontend static files frontend = Frontend( Path(__file__).parent.parent / "frontend-build", @@ -48,10 +52,11 @@ async def lifespan(app: FastAPI): # pragma: no cover - startup path # Re-raise to fail fast raise - # Restore info level logging after startup (suppressed during uvicorn init in dev mode) + # Restore uvicorn info logging (suppressed during startup in dev mode) + # Keep uvicorn.error at WARNING to suppress WebSocket "connection open/closed" messages if frontend.devmode: logging.getLogger("uvicorn").setLevel(logging.INFO) - logging.getLogger("uvicorn.access").setLevel(logging.INFO) + logging.getLogger("uvicorn.error").setLevel(logging.WARNING) await frontend.load() await start_background() @@ -67,6 +72,9 @@ app = FastAPI( openapi_url=None, ) +# Custom access logging (uvicorn's access_log is disabled) +app.add_middleware(AccessLogMiddleware) + # Apply redirections to auth-host if configured (deny access to restricted endpoints, remove /auth/) app.middleware("http")(auth_host.redirect_middleware) diff --git a/paskia/fastapi/wsutil.py b/paskia/fastapi/wsutil.py index a2c2028..0a64d4f 100644 --- a/paskia/fastapi/wsutil.py +++ b/paskia/fastapi/wsutil.py @@ -3,6 +3,7 @@ Shared WebSocket utilities for FastAPI endpoints. """ import logging +import time from functools import wraps import base64url @@ -10,6 +11,7 @@ from fastapi import WebSocket, WebSocketDisconnect from webauthn.helpers.exceptions import InvalidAuthenticationResponse from paskia.fastapi import authz +from paskia.fastapi.logging import log_ws_close, log_ws_open from paskia.globals import passkey from paskia.util import pow @@ -19,11 +21,19 @@ def websocket_error_handler(func): @wraps(func) async def wrapper(ws: WebSocket, *args, **kwargs): + client = ws.client.host if ws.client else "-" + host = ws.headers.get("host", "-") + path = ws.url.path + + start = time.perf_counter() + ws_id = log_ws_open(client, host, path) + close_code = None + try: await ws.accept() return await func(ws, *args, **kwargs) - except WebSocketDisconnect: - pass + except WebSocketDisconnect as e: + close_code = e.code except authz.AuthException as e: await ws.send_json( { @@ -36,6 +46,9 @@ def websocket_error_handler(func): except Exception: logging.exception("Internal Server Error") await ws.send_json({"status": 500, "detail": "Internal Server Error"}) + finally: + duration_ms = (time.perf_counter() - start) * 1000 + log_ws_close(client, ws_id, close_code, duration_ms) return wrapper