access_log.py
python
sha256:8e05daa29ba6702b4a2380a16d690ba31cc099d69c5c859bc6e6f16a0e945f99
Merge 'fix/deploy-memory-limits-and-log-group' into 'dev' —…
Human
10 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
3 commits
sha256:8e05daa29ba6702b4a2380a16d690ba31cc099d69c5c859bc6e6f16a0e945f99
Merge 'fix/deploy-memory-limits-and-log-group' into 'dev' —…
Human
10 days ago
sha256:3fadb0439bba9451b89229676971c0d4a40900dec7810e9d5f8791b8d950d505
fix: install.sh version from latest published tarball, not …
Sonnet 4.6
minor
⚠
102 days ago
sha256:763eb2cb8675073b84c19345b27586d2ed939a9aee97c5479b69f502f1a70eff
fix(tests): update test suite to match current implementation
Sonnet 4.6
patch
123 days ago