From e07ab220cbd093978ca77b01ed8e89c5ead7056c Mon Sep 17 00:00:00 2001 From: Leo Vasanko Date: Thu, 23 Apr 2026 18:06:22 +0000 Subject: [PATCH] Add cleaner access logging for HTTP requests and WebSockets --- cista/app.py | 26 +++++ cista/sanic_logging.py | 220 +++++++++++++++++++++++++++++++++++++++ cista/serve.py | 2 +- cista/util/apphelpers.py | 20 ++++ 4 files changed, 267 insertions(+), 1 deletion(-) create mode 100644 cista/sanic_logging.py diff --git a/cista/app.py b/cista/app.py index e1fba8b..df5a0c1 100644 --- a/cista/app.py +++ b/cista/app.py @@ -1,6 +1,7 @@ import asyncio import datetime import mimetypes +import time from concurrent.futures import ThreadPoolExecutor from multiprocessing import cpu_count from pathlib import Path, PurePath, PurePosixPath @@ -19,11 +20,15 @@ from zstandard import ZstdCompressor from cista import auth, config, preview, session, sso, watching from cista.api import bp +from cista.sanic_logging import configure_access_logging, format_access_log +from cista.sanic_logging import logger as access_logger from cista.util.apphelpers import handle_sanic_exception # Workaround until Sanic PR #2824 is merged sanic.helpers._ENTITY_HEADERS = frozenset() +configure_access_logging() + app = Sanic("cista", strict_slashes=True) # Register either SSO proxy or built-in auth routes based on PASKIA_BACKEND_URL if sso.paskia_enabled(): @@ -64,6 +69,7 @@ async def main_stop(app): @app.on_request async def use_session(req): + req.ctx._log_start = time.perf_counter() req.ctx.session = session.get(req) try: req.ctx.username = req.ctx.session["username"] # type: ignore @@ -81,6 +87,26 @@ async def use_session(req): raise Forbidden("Invalid origin: Cross-Site requests not permitted") +@app.on_response +async def log_access(req, res): + """Log HTTP access in a clean single-line format.""" + if req.headers.get("upgrade", "").lower() == "websocket": + return res + start = getattr(req.ctx, "_log_start", None) + duration_ms = (time.perf_counter() - start) * 1000 if start is not None else 0.0 + client = req.ip or "-" + host = req.host or "-" + path = req.path + if req.query_string: + qs = req.query_string + if isinstance(qs, bytes): + qs = qs.decode(errors="replace") + path = f"{path}?{qs}" + line = format_access_log(client, res.status, req.method, host, path, duration_ms) + access_logger.info(line) + return res + + @app.on_response async def forward_sso_cookies(req, res): """Forward Set-Cookie headers from SSO validation to client.""" diff --git a/cista/sanic_logging.py b/cista/sanic_logging.py new file mode 100644 index 0000000..69504a3 --- /dev/null +++ b/cista/sanic_logging.py @@ -0,0 +1,220 @@ +"""Custom access logging middleware for Sanic.""" + +import logging +import sys +import unicodedata +from ipaddress import IPv6Address + +logger = logging.getLogger("cista.access") + +_RESET = "\033[0m" +_STATUS_INFO = "\033[32m" # 1xx (green) +_STATUS_OK = "\033[1;92m" # 2xx (bright green) +_STATUS_REDIRECT = "\033[32m" # 3xx (green) +_STATUS_CLIENT_ERR = "\033[0;31m" # 4xx (red) +_STATUS_SERVER_ERR = "\033[1;91m" # 5xx (bold bright red) +_METHOD_READ = "\033[0;34m" # GET, HEAD, OPTIONS (blue) +_METHOD_WRITE = "\033[1;94m" # POST, PUT, DELETE, PATCH (bold bright blue) +_HOST = "\033[38;5;242m" # hostname (dark grey) +_PATH = "\033[38;5;250m" # path (light grey) +_TIMING = "\033[38;5;242m" # timing (dark grey) +_WS_OPEN = "\033[1;93m" # WebSocket connect (bold bright yellow) +_WS_CLOSE = "\033[33m" # WebSocket disconnect (yellow) +_WS_STATUS = "\033[38;5;250m" # WebSocket close status (normal white) + + +def format_ipv6_network(ip: str) -> str: + """Format IPv6 address to show only network part (first 64 bits).""" + try: + ip = ip.strip("[]") + if "%" in ip: + ip = ip.split("%")[0] + addr = IPv6Address(ip) + if addr.is_loopback: + return "::1" + if addr.is_unspecified: + return "::" + if addr.ipv4_mapped: + return str(addr.ipv4_mapped) + if addr.is_link_local: + return str(addr) + network_int = int(addr) >> 64 + groups = [] + for _ in range(4): + groups.insert(0, format(network_int & 0xFFFF, "x")) + network_int >>= 16 + result = ":".join(groups) + "::" + return str(IPv6Address(result + "0")).removesuffix("::") + 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 "-" + stripped = ip.strip("[]") + if ":" in stripped: + return format_ipv6_network(ip) + return ip + + +def status_color(status: int) -> str: + 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: + if method in ("GET", "HEAD", "OPTIONS"): + return _METHOD_READ + return _METHOD_WRITE + + +def format_duration_ms(duration_ms: float) -> str: + rounded_ms = round(duration_ms) + if rounded_ms < 2000: + return f"{rounded_ms}ms" + total_s = round(duration_ms / 1000) + if total_s < 60: + return f"{total_s}s" + if total_s <= 3600: + minutes, seconds = divmod(total_s, 60) + return f"{minutes}m{seconds}s" + hours, remainder = divmod(total_s, 3600) + minutes = round(remainder / 60) + if minutes == 60: + hours += 1 + minutes = 0 + return f"{hours}h{minutes}m" + + +def _display_width(text: str) -> int: + width = 0 + for char in text: + width += 2 if unicodedata.east_asian_width(char) in {"F", "W"} else 1 + return width + + +def _format_left(label: str) -> str: + return label[:19].ljust(19) + + +def _format_method_label(label: str, *, color: str | None = None) -> str: + color_value = _METHOD_WRITE if color is None else color + padding = max(0, 7 - _display_width(label)) + return f"{color_value}{label}{' ' * padding}{_RESET}" + + +def format_access_log( + client: str, status: int, method: str, host: str, path: str, duration_ms: float +) -> str: + ip = _format_left(format_client_ip(client)) + status_str = f"{status_color(status)}{str(status).rjust(3)}{_RESET}" + method_str = _format_method_label(method, color=method_color(method)) + host_str = f"{_HOST}{host}{_RESET}" + path_str = f"{_PATH}{path}{_RESET}" + timing_str = f"{_TIMING}{format_duration_ms(duration_ms)}{_RESET}" + return f"{ip} {status_str} {method_str} {host_str}{path_str} {timing_str}" + + +_ws_counter = 1 + + +def _next_ws_id() -> int: + global _ws_counter + ws_id = _ws_counter + _ws_counter += 1 + return ws_id + + +def _format_ws_id(ws_id: int, *, bright: bool = False) -> str: + value = str(ws_id) if ws_id >= 100 else f"{ws_id:02d}" + color = _WS_OPEN if bright else _WS_CLOSE + return f"{color}{value.rjust(3)}{_RESET}" + + +def log_ws_open(request, extra: str | None = None) -> int: + """Log WebSocket connection open. Returns connection ID for use in log_ws_close.""" + ws_id = _next_ws_id() + + client = request.ip or "-" + host = request.host or "-" + path = request.path + origin = request.headers.get("origin") + + ip = _format_left(format_client_ip(client)) + id_str = _format_ws_id(ws_id, bright=True) + + origin_host = origin.split("://", 1)[-1] if origin else None + show_origin = origin_host and origin_host != host + + method_str = _format_method_label("🔌", color=_WS_OPEN) + host_str = f"{_HOST}{host}{_RESET}" + path_str = f"{_PATH}{path}{_RESET}" + origin_str = f" {_RESET}from {_HOST}{origin_host}{_RESET}" if show_origin else "" + extra_str = f" {_TIMING}{extra}{_RESET}" if extra else "" + + logger.info( + "%s %s %s %s%s%s", + ip, + id_str, + method_str, + host_str, + path_str, + origin_str + extra_str, + ) + return ws_id + + +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(ws_id: int, close_code: int | None, duration: float) -> None: + """Log WebSocket connection close with duration and status.""" + id_str = _format_ws_id(ws_id) + timing = format_duration_ms(duration * 1000) + + if close_code is None: + code = "----" + status = "unknown" + else: + code = str(close_code) + status = WS_CLOSE_CODES.get(close_code, f"code {close_code}") + + method_str = _format_method_label("closed", color=_TIMING) + status_str = f"{_WS_STATUS}{code} {status}{_RESET}" + timing_str = f"{_TIMING}{timing}{_RESET}" + + logger.info("%s %s %s %s %s", " " * 19, id_str, method_str, status_str, timing_str) + + +def configure_access_logging() -> None: + """Configure the cista.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/cista/serve.py b/cista/serve.py index 414d52b..bd10aeb 100644 --- a/cista/serve.py +++ b/cista/serve.py @@ -27,7 +27,7 @@ def run(*, dev=False): motd=False, dev=dev, auto_reload=dev, - access_log=True, + access_log=False, ) # type: ignore if dev: Sanic.serve() diff --git a/cista/util/apphelpers.py b/cista/util/apphelpers.py index f6e943c..497c681 100644 --- a/cista/util/apphelpers.py +++ b/cista/util/apphelpers.py @@ -1,3 +1,4 @@ +import time from functools import wraps import msgspec @@ -8,6 +9,7 @@ from sanic.response import raw, redirect from cista import auth from cista.protocol import ErrorMsg +from cista.sanic_logging import log_ws_close, log_ws_open def asend(ws, msg): @@ -54,6 +56,10 @@ def websocket_wrapper(handler): @wraps(handler) async def wrapper(request, ws, *args, **kwargs): + username = getattr(request.ctx, "username", None) + extra = username if username else None + start = time.perf_counter() + ws_id = log_ws_open(request, extra=extra) try: await auth.verify(request) await handler(request, ws, *args, **kwargs) @@ -67,5 +73,19 @@ def websocket_wrapper(handler): if not getattr(e, "quiet", False) or code == 500: logger.exception(f"{code} {e!r}") raise + finally: + duration = time.perf_counter() - start + close_code = None + try: + p = ws.ws_proto + if p.close_rcvd is not None: + close_code = p.close_rcvd.code + elif p.close_sent is not None: + close_code = p.close_sent.code + elif getattr(p, "close_code", None) is not None: + close_code = p.close_code + except AttributeError: + pass + log_ws_close(ws_id, close_code, duration) return wrapper