gabriel / musehub public
access_log.py python
103 lines 4.0 KB
Raw
sha256:bb2baaabdd19320bde50cb69d447fd1c1e571467df729be1a23b5e93064b046a feat(intel): standardize headers, gauge icon, velocity card… Sonnet 4.6 minor ⚠ breaking 143 days ago
1 """Per-request structured access logging middleware.
2
3 Injects ``request_id`` (UUID4) and ``user_id`` into contextvars so every
4 log record emitted during the request carries them. Emits a single access
5 log line at the end of the request:
6
7 {"timestamp":...,"level":"INFO","message":"GET /api/v1/repos 200 14.3ms",
8 "request_id":"...","user_id":"gabriel","method":"GET","path":"...","status":200,"duration_ms":14.3}
9
10 Design choices:
11 * User identity — only the MSign ``handle`` is logged (never the raw token).
12 * /healthz — logged at DEBUG to avoid noise in monitoring dashboards.
13 * No request/response body logging — eliminates PII risk at the middleware level.
14 * request_id is a UUID4 generated per-request; inject it into response headers
15 as ``X-Request-Id`` so clients can correlate errors with log entries.
16 """
17 from __future__ import annotations
18
19 import logging
20 import re
21 import time
22 import uuid
23
24 from starlette.types import ASGIApp, Message, Receive, Scope, Send
25
26 from musehub.logging_config import request_id_var, user_id_var
27
28 logger = logging.getLogger(__name__)
29
30 # Extract the handle from Authorization: MSign handle="gabriel" ts=... sig=...
31 _MSIGN_HANDLE_RE = re.compile(r'handle="([^"]+)"')
32
33 _HEALTH_PATH = "/healthz"
34 _STATIC_PREFIX = "/static/"
35
36
37 class AccessLogMiddleware:
38 """ASGI middleware: structured per-request access log + X-Request-Id header."""
39
40 def __init__(self, app: ASGIApp) -> None:
41 self.app = app
42
43 async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
44 if scope["type"] != "http":
45 await self.app(scope, receive, send)
46 return
47
48 # ── Inject request_id ─────────────────────────────────────────────────
49 request_id = str(uuid.uuid4())
50 token_rid = request_id_var.set(request_id)
51
52 # ── Extract user_id from MSign Authorization header ───────────────────
53 # Never log the raw token value — only the human-readable handle.
54 user_id = ""
55 for raw_key, raw_val in scope.get("headers", []):
56 if raw_key.lower() == b"authorization":
57 auth_header = raw_val.decode("latin-1", errors="replace")
58 m = _MSIGN_HANDLE_RE.search(auth_header)
59 if m:
60 user_id = m.group(1)
61 break
62 token_uid = user_id_var.set(user_id)
63
64 status_code = 500
65 response_started = False
66
67 async def send_with_request_id(message: Message) -> None:
68 nonlocal status_code, response_started
69 if message["type"] == "http.response.start":
70 status_code = message["status"]
71 response_started = True
72 # Inject X-Request-Id into response headers.
73 headers = list(message.get("headers", []))
74 headers.append((b"x-request-id", request_id.encode()))
75 message = {**message, "headers": headers}
76 await send(message)
77
78 start = time.monotonic()
79 try:
80 await self.app(scope, receive, send_with_request_id)
81 finally:
82 duration_ms = round((time.monotonic() - start) * 1000, 1)
83 path = scope.get("path", "")
84 method = scope.get("method", "")
85
86 # /healthz and /static/* at DEBUG — suppress from INFO dashboards.
87 is_noisy = path == _HEALTH_PATH or path.startswith(_STATIC_PREFIX)
88 level = logging.DEBUG if is_noisy else logging.INFO
89
90 logger.log(
91 level,
92 "%s %s %s %.1fms",
93 method, path, status_code, duration_ms,
94 extra={
95 "method": method,
96 "path": path,
97 "status": status_code,
98 "duration_ms": duration_ms,
99 },
100 )
101
102 request_id_var.reset(token_rid)
103 user_id_var.reset(token_uid)
File History 1 commit
sha256:bb2baaabdd19320bde50cb69d447fd1c1e571467df729be1a23b5e93064b046a feat(intel): standardize headers, gauge icon, velocity card… Sonnet 4.6 minor ⚠ 143 days ago