"""requestlog — one id per request, carried through every door and seam, and one log line that says what happened.
When a live test failed against crm-demo, nothing in Ignite's logs connected the failing request to the use
case it ran, the neighbour it called or the retries it sat through: there was a 500, and a guess. So every
request now gets an id, and ends with exactly one JSON line on the `erp_platform.request` logger:
{"request_id": "…", "method": "POST", "path": "/quotes/{quote_id}/accept", "status": 200,
"duration_ms": 41.7, "use_case": "accept_quote", "door": "http", "sub": "3f1c…", "retries": 1,
"outcome": "ok", "error": null}
THE ID. A caller's `X-Request-Id` is kept when it is sane (≤128 chars of `[A-Za-z0-9._:-]`) — the gateway or
a test harness can then follow its own id through us — and replaced otherwise: the value lands in log lines
and in headers we send on, so a newline or a kilobyte of attacker text is not ours to forward. Every
response carries the id back, the sign-in gate's 401 and the 500 of a crash included, because those are
exactly the replies someone will paste into a ticket. A seam sends it to the neighbour, so at any tier one
id finds every line a request produced in every brick.
WHERE IT LIVES. A ContextVar, set by the middleware. Use cases run on worker threads
(`anyio.to_thread.run_sync`), and anyio runs those in a COPY of the caller's context — so the id is visible
there, and the per-request record below is the SAME object, which is how a retry on the worker thread
reaches the request line. Both properties are tested, not assumed (tests/test_requestlog.py). A use case
that wants the id calls `requestlog.request_id()`.
WHAT IS NEVER LOGGED, and why the line has a fixed set of fields rather than "whatever is useful": request
bodies and tool arguments carry customer data, headers carry tokens, and an exception's MESSAGE can quote
either — so the line holds the route TEMPLATE (`/quotes/{quote_id}`, never `/quotes/Q-1`), the exception's
TYPE, and the caller's `sub`. A `sub` that is an email address (the seam's acting human, local dev
identities) is replaced by a stable pseudonym (`anon:` + 12 hex of its SHA-256): lines still correlate per
person, and no address is written.
"""
import hashlib
import json
import logging
import os
import re
import sys
import time
import uuid
from contextvars import ContextVar
from dataclasses import dataclass
from typing import Optional
HEADER = "X-Request-Id"
_HEADER_KEY = HEADER.lower().encode()
_SANE = re.compile(r"[A-Za-z0-9._:-]{1,128}")
_SECRETISH = re.compile(r"[A-Za-z0-9_\-.~%]{20,}")
FIELDS = ("request_id", "method", "path", "status", "duration_ms", "use_case", "door", "sub",
"retries", "outcome", "error")
log = logging.getLogger("erp_platform.request")
@dataclass
class _Request:
"""What one request did, filled in by whoever learns it: the middleware, a door, the retry loop."""
id: str
door: str = "http"
use_case: Optional[str] = None
sub: Optional[str] = None
retries: int = 0
outcome: Optional[str] = None # set by a door when the status alone would mislead (MCP: 200 + refusal)
error: Optional[str] = None # an exception's type name — never its message
_CURRENT: ContextVar[Optional[_Request]] = ContextVar("erp_platform_request", default=None)
def request_id() -> str:
"""The id of the request this code is running for, or "" outside one (a job, a script)."""
req = _CURRENT.get()
return req.id if req else ""
def accept(raw: Optional[str]) -> str:
"""The caller's id if it is safe to repeat in logs and headers; a fresh one otherwise."""
if raw and _SANE.fullmatch(raw):
return raw
return uuid.uuid4().hex
def note(*, door: Optional[str] = None, use_case: Optional[str] = None, sub: Optional[str] = None) -> None:
"""Record what this request resolved to. Outside a request it does nothing."""
req = _CURRENT.get()
if req is None:
return
if door:
req.door = door
if use_case:
req.use_case = use_case
if sub:
req.sub = _pseudonym(sub)
def mark(outcome: str, error: Optional[BaseException] = None) -> None:
"""The use case refused, or crashed. The type of the exception is kept; its message is not."""
req = _CURRENT.get()
if req is None:
return
req.outcome = outcome
if error is not None:
req.error = type(error).__name__
def count_retry() -> None:
req = _CURRENT.get()
if req is not None:
req.retries += 1
def _pseudonym(sub: str) -> str:
if "@" not in sub:
return sub
return "anon:" + hashlib.sha256(sub.encode()).hexdigest()[:12]
def _path(scope: dict) -> str:
"""The route template the request matched — path parameters are customer data, the template is not.
Unmatched (a 404, the sign-in gate's 401 before routing): the raw path, with any segment that could be
an address replaced, because a mistyped URL is still a URL a person typed their email into — and any
segment long enough to be a secret (a public link's token, `/p/<43 chars>/x`) replaced too.
"""
route = scope.get("route")
template = getattr(route, "path_format", None) or getattr(route, "path", None)
if template:
return template
return "/".join("{redacted}" if "@" in s or _SECRETISH.fullmatch(s) else s
for s in scope.get("path", "").split("/"))
class RequestLog:
"""ASGI middleware: assign the id, return it on every response, write the request line.
Pure ASGI rather than Starlette's BaseHTTPMiddleware, which runs the app in a separate task — the
ContextVar set here would not be the one the endpoint sees.
"""
def __init__(self, app):
self.app = app
async def __call__(self, scope, receive, send):
if scope["type"] != "http":
return await self.app(scope, receive, send)
raw = next((v.decode("latin-1") for k, v in scope.get("headers", []) if k.lower() == _HEADER_KEY),
None)
req = _Request(accept(raw))
token = _CURRENT.set(req)
started = time.perf_counter()
status: dict = {}
async def send_with_id(message):
if message["type"] == "http.response.start":
status["code"] = message["status"]
headers = [(k, v) for k, v in message.get("headers", []) if k.lower() != _HEADER_KEY]
message = {**message, "headers": headers + [(_HEADER_KEY, req.id.encode())]}
await send(message)
try:
await self.app(scope, receive, send_with_id)
except Exception as exc:
req.outcome, req.error = "error", req.error or type(exc).__name__
if "code" not in status:
# Answer the 500 here, so it carries the id. Re-raised below, the server still logs the
# traceback it always did; the response has already gone, so it sends nothing more.
body = json.dumps({"detail": "internal error", "request_id": req.id}).encode()
await send_with_id({"type": "http.response.start", "status": 500,
"headers": [(b"content-type", b"application/json"),
(b"content-length", str(len(body)).encode())]})
await send_with_id({"type": "http.response.body", "body": body})
raise
finally:
code = status.get("code", 500)
outcome = req.outcome or ("error" if code >= 500 else "refused" if code >= 400 else "ok")
log.info(json.dumps({
"request_id": req.id, "method": scope.get("method"), "path": _path(scope),
"status": code, "duration_ms": round((time.perf_counter() - started) * 1000, 1),
"use_case": req.use_case, "door": req.door, "sub": req.sub, "retries": req.retries,
"outcome": outcome, "error": req.error}))
_CURRENT.reset(token)
_configured = False
def configure() -> None:
"""Make the lines appear with no setup: `erp_platform.*` at LOG_LEVEL (default INFO), to stdout.
Ignite keeps stdout. If the process has configured logging already (a root handler, or one on
`erp_platform`), that configuration wins and only the level is set — never a second handler that
would print every line twice. Configure logging BEFORE serve() to send these lines elsewhere.
"""
global _configured
if _configured:
return
_configured = True
logger = logging.getLogger("erp_platform")
level = os.environ.get("LOG_LEVEL", "").strip().upper()
try:
if level:
logger.setLevel(level)
except ValueError: # a typo in LOG_LEVEL must not stop the app starting
level = ""
if not level and logger.level == logging.NOTSET:
logger.setLevel(logging.INFO)
if not logger.handlers and not logging.getLogger().handlers:
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(logging.Formatter("%(message)s"))
logger.addHandler(handler)
logger.propagate = False