Log session id from handlers on selected auth routes. Adds request.state.log_extra for handlers to print access log extra.

paskia/fastapi/api.py

@@ -21,6 +21,7 @@ from paskia.fastapi import authz, session, user
 from paskia.fastapi.response import MsgspecResponse
 from paskia.fastapi.session import AUTH_COOKIE, AUTH_COOKIE_NAME, get_client_ip
 from paskia.globals import passkey as global_passkey
+from paskia.util.crypto import hash_secret
 from paskia.util import hostutil, htmlutil, passphrase, permutil, userinfo
 from paskia.util.apistructs import (
     ApiCheckUserResponse,
@@ -56,6 +57,12 @@ async def http_exception_handler(_request: Request, exc: HTTPException):
 _REFRESH_INTERVAL = timedelta(minutes=5)
 
 
+def _set_log_extra(request: Request, *parts: str) -> None:
+    values = [part for part in parts if part]
+    if values:
+        request.state.log_extra = " ".join(values)
+
+
 @app.exception_handler(ValueError)
 async def value_error_handler(_request: Request, exc: ValueError):
     return JSONResponse(status_code=400, content={"detail": str(exc)})
@@ -110,6 +117,7 @@ async def validate_token(
             )
             session.set_session_cookie(response, auth)
             renewed = True
+        _set_log_extra(request, ctx.session.key)
     return MsgspecResponse(
         ApiValidateResponse(
             valid=True,
@@ -202,6 +210,7 @@ async def forward_authentication(
             host=request.headers.get("host"),
             max_age=max_age,
         )
+        _set_log_extra(request, request.headers.get("x-forwarded-uri", ""), ctx.session.key)
         # Build permission scopes for Remote-Groups header
         role_permissions = (
             {p.scope for p in ctx.permissions} if ctx.permissions else set()
@@ -276,6 +285,8 @@ async def api_user_info(
             clear_session=True,
         )
 
+    _set_log_extra(request, ctx.session.key)
+
     return MsgspecResponse(
         await userinfo.build_user_info(
             user_uuid=ctx.user.uuid,
@@ -351,5 +362,6 @@ async def api_set_session(
     if not ctx:
         raise HTTPException(401, f"Session not found on {host}")
 
+    _set_log_extra(request, hash_secret("cookie", secret))
     session.set_session_cookie(response, secret)
     return {"status": "ok", "user": str(ctx.user.uuid)}

paskia/fastapi/logging.py

@@ -112,7 +112,13 @@ def method_color(method: str) -> str:
 
 
 def format_access_log(
-    client: str, status: int, method: str, host: str, path: str, duration_ms: float
+    client: str,
+    status: int,
+    method: str,
+    host: str,
+    path: str,
+    duration_ms: float,
+    extra: str = "",
 ) -> str:
     """Format access log line with colors and aligned fields."""
     # Format components with fixed widths for alignment
@@ -126,8 +132,9 @@ def format_access_log(
     host_str = f"{_HOST}{host}{_RESET}"
     path_str = f"{_PATH}{path}{_RESET}"
 
-    # Format: "IP STATUS METHOD host path TIMING"
-    return f"{ip} {status_str} {method_str} {host_str}{path_str} {timing_str}"
+    # Format: "IP STATUS METHOD host path [extra] TIMING"
+    extra_str = f" {_TIMING}{extra}{_RESET}" if extra else ""
+    return f"{ip} {status_str} {method_str} {host_str}{path_str}{extra_str} {timing_str}"
 
 
 # WebSocket connection counter (mod 100)
@@ -152,20 +159,21 @@ def log_ws_open(ws) -> int:
     origin = ws.headers.get("origin")
 
     ip = format_client_ip(client).ljust(19)
-    id_str = f"{ws_id:02d}".ljust(7)  # Align with method field (7 chars)
+    # ID right-aligned like status codes (3 chars), emoji formatted like method
+    id_str = f"{_WS_OPEN}{str(ws_id).rjust(3)}{_RESET}"
+    # Emoji (2 display width) + 6 spaces = 8 display chars, but within color for alignment
+    emoji_str = f"{_METHOD_READ}🔌      {_RESET}"
 
     # Determine if origin should be shown (omit when same as host)
     # Origin header includes scheme (e.g., "https://example.com"), compare host part
     origin_host = origin.split("://", 1)[-1] if origin else None
     show_origin = origin_host and origin_host != host
 
-    # 🔌 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}"
     origin_str = f" {_RESET}from {_HOST}{origin_host}{_RESET}" if show_origin else ""
 
-    logger.info(f"{ip} {prefix} {host_str}{path_str}{origin_str}")
+    logger.info(f"{ip} {id_str} {emoji_str}{host_str}{path_str}{origin_str}")
     return ws_id
 
 
@@ -191,21 +199,25 @@ WS_CLOSE_CODES = {
 
 def log_ws_close(ws_id: int, close_code: int | None, duration: float) -> None:
     """Log WebSocket connection close with duration and status."""
-    id_str = f"{ws_id:02d}".ljust(7)  # Align with method field (7 chars)
+    # ID right-aligned like status codes (3 chars), "closed" formatted like method
+    id_str = f"{_WS_CLOSE}{str(ws_id).rjust(3)}{_RESET}"
+    # Pad within the dim color to keep full width in color (8 display chars)
+    closed_str = f"{_TIMING}closed  {_RESET}"
     timing = f"{duration * 1000:.0f}ms"
 
     # Convert close code to status text
     if close_code is None:
-        status = "closed"
+        code = "----"
+        status = "unknown"
     else:
+        code = str(close_code)
         status = WS_CLOSE_CODES.get(close_code, f"code {close_code}")
 
-    # 🔌 aligned with status, ID aligned with method
-    prefix = f"🔌  {_WS_CLOSE}{id_str}{_RESET}"
-    status_str = f"{_WS_STATUS}{status}{_RESET}"
+    # Status code and text in normal color, not dim
+    status_str = f"{code} {status}"
     timing_str = f"{_TIMING}{timing}{_RESET}"
 
-    logger.info(f"{' ' * 19} {prefix} {status_str} {timing_str}")
+    logger.info(f"{' ' * 19} {id_str} {closed_str}{status_str} {timing_str}")
 
 
 def log_permission_denied(
@@ -244,7 +256,11 @@ class AccessLogMiddleware(BaseHTTPMiddleware):
             path = f"{path}?{request.url.query}"
         status = response.status_code
 
-        line = format_access_log(client, status, method, host, path, duration_ms)
+        extra = getattr(request.state, "log_extra", "")
+
+        line = format_access_log(
+            client, status, method, host, path, duration_ms, extra=extra
+        )
         logger.info(line)
 
         return response