gabriel / musehub public
access_log.py python
101 lines 4.0 KB
Raw
sha256:34035d72cef530c1ab9d6a6f53be18d803dde705fc3157617d70352a96d0747b Merge branch 'fix/wire-push-external-parent-manifest' into dev Human 8 days ago
1 """Per-request structured access logging middleware.
2
3 Injects ``request_id`` 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 random hex string generated per-request; injected into response
15 headers as ``X-Request-Id`` so clients can correlate errors with log entries.
16 """
17
18 import logging
19 import re
20 import secrets
21 import time
22
23 from starlette.types import ASGIApp, Message, Receive, Scope, Send
24
25 from musehub.logging_config import request_id_var, user_id_var
26
27 logger = logging.getLogger(__name__)
28
29 # Extract the handle from Authorization: MSign handle="gabriel" ts=... sig=...
30 _MSIGN_HANDLE_RE = re.compile(r'handle="([^"]+)"')
31
32 _HEALTH_PATH = "/healthz"
33 _STATIC_PREFIX = "/static/"
34
35 class AccessLogMiddleware:
36 """ASGI middleware: structured per-request access log + X-Request-Id header."""
37
38 def __init__(self, app: ASGIApp) -> None:
39 self.app = app
40
41 async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
42 if scope["type"] != "http":
43 await self.app(scope, receive, send)
44 return
45
46 # ── Inject request_id ─────────────────────────────────────────────────
47 request_id = secrets.token_hex(16)
48 token_rid = request_id_var.set(request_id)
49
50 # ── Extract user_id from MSign Authorization header ───────────────────
51 # Never log the raw token value — only the human-readable handle.
52 user_id = ""
53 for raw_key, raw_val in scope.get("headers", []):
54 if raw_key.lower() == b"authorization":
55 auth_header = raw_val.decode("latin-1", errors="replace")
56 m = _MSIGN_HANDLE_RE.search(auth_header)
57 if m:
58 user_id = m.group(1)
59 break
60 token_uid = user_id_var.set(user_id)
61
62 status_code = 500
63 response_started = False
64
65 async def send_with_request_id(message: Message) -> None:
66 nonlocal status_code, response_started
67 if message["type"] == "http.response.start":
68 status_code = message["status"]
69 response_started = True
70 # Inject X-Request-Id into response headers.
71 headers = list(message.get("headers", []))
72 headers.append((b"x-request-id", request_id.encode()))
73 message = {**message, "headers": headers}
74 await send(message)
75
76 start = time.monotonic()
77 try:
78 await self.app(scope, receive, send_with_request_id)
79 finally:
80 duration_ms = round((time.monotonic() - start) * 1000, 1)
81 path = scope.get("path", "")
82 method = scope.get("method", "")
83
84 # /healthz and /static/* at DEBUG — suppress from INFO dashboards.
85 is_noisy = path == _HEALTH_PATH or path.startswith(_STATIC_PREFIX)
86 level = logging.DEBUG if is_noisy else logging.INFO
87
88 logger.log(
89 level,
90 "%s %s %s %.1fms",
91 method, path, status_code, duration_ms,
92 extra={
93 "method": method,
94 "path": path,
95 "status": status_code,
96 "duration_ms": duration_ms,
97 },
98 )
99
100 request_id_var.reset(token_rid)
101 user_id_var.reset(token_uid)
File History 14 commits
sha256:34035d72cef530c1ab9d6a6f53be18d803dde705fc3157617d70352a96d0747b Merge branch 'fix/wire-push-external-parent-manifest' into dev Human 8 days ago
sha256:fc04e4cae9e1774d6a21b65c45daeed0e6787eb581d13aa1b03bfe9384a34226 Merge branch 'fix/two-column-scroll-layout' into dev Human 8 days ago
sha256:408916fc5973ba59c6e4eebaa80ebdcc801c0a63205651e25009d11548f79454 chore: bump version to 0.2.0.dev2 — nightly.2, matching muse Sonnet 4.6 patch 11 days ago
sha256:d035733f21ccff27735fddebfbbe0ed24565a32a22db8de5885402262671ecd2 chore: bump version to 0.2.0rc15 for musehub#113 fix release Sonnet 4.6 patch 14 days ago
sha256:0032d6cfa33bc3c8367436ad768e7dd0e339b4332153160247da8266cb5fa352 Merge branch 'task/version-tags-phase3-server' into dev Human 17 days ago
sha256:4669620efda9ff41c55bdefd1f7bfe1c239d468428744c84ead9957e5a003a53 merge: rescue snapshot-recovery hardening (c00aa21d) into d… Opus 4.8 minor ⚠ 29 days ago
sha256:a59da49c4611b970fc4b6ae48678ce4943261c213a07ddbd73ce9201df869b4a fix: remove false-positive proposal_comments index drop fro… Sonnet 4.6 patch 34 days ago
sha256:0a240d6dbff234f07d98a28a4a9a68db702f3f9ff9260196f24219bdb1c0b6f3 feat: render markdown mists as HTML with heading anchor links Sonnet 4.6 patch 34 days ago
sha256:24a7d47486ebc4ebd1832830580e177ec6f877b48dced8c000e198cdec4ce9d6 Merge 'task/bump-version-rc12' into 'dev' — proposal: Bump … Human 35 days ago
sha256:b9ff931d147e0114a1f17060f415b89ed551c170a91ff226c70437aa5c85f9ee Merge 'task/bump-version-rc12' into 'dev' — proposal: Bump … Human 35 days ago
sha256:d1122d21e73471879b460037b22c0b50fded7c423444a176f248428f75dac39c Merge 'task/fix-issue-pagination-cursor' into 'dev' — propo… Human 35 days ago
sha256:01e18975e73d2b3cd5b6db7929c895bef9aa6e0d4391dc5b2adfc548b41318dd Merge 'feat/adding-debug-logs-to-staging' into 'dev' — prop… Human 36 days ago
sha256:6b1949fc2797ca4c1936a637a4cbfec828ef56cf52398a2e74ca3c4f494e728f fix: use wire_bytes not mpack_bytes_raw in compute_object_b… Sonnet 4.6 patch 48 days ago
sha256:b99f2455dc346966d040133f5203297e6e3ef5803a93728a2c30568d0a0f7583 rename: delta_add → delta_upsert across wire format, models… Sonnet 4.6 patch 50 days ago