mirror of
https://github.com/maziggy/bambuddy.git
synced 2026-09-30 11:12:35 +02:00
maziggy
1878d2aab5
Builds on the recent uvicorn-access-log-into-bambuddy.log change.
Until now the access line told us who called an endpoint, but there
was no way to tie that line to the application records emitted on the
server side while handling that request. The rogue stop_print mystery
on 2026-04-26 left exactly that gap: even with access logs piped in,
correlating "this POST landed" with "this MQTT publish went out 6 ms
later" required eyeball-matching timestamps across different loggers.
A new ContextVar + middleware + logging filter wire a trace ID through
every record:
* trace_id_middleware mints an 8-char hex ID per request (or honours
a sane inbound X-Trace-Id for cross-system correlation), stores it
in trace_id_var (ContextVar), echoes it on the response as
X-Trace-Id, and resets the var in finally.
* TraceIDFilter, attached to root + uvicorn.access, copies the
current trace_id_var value onto every LogRecord so the format
string [%(trace_id)s] resolves to the right ID per record.
* Records emitted outside any request scope (startup, MQTT
callbacks, scheduler) get a stable "-" placeholder so the column
stays visually aligned and grep stays simple.
ContextVars are the right plumbing because asyncio copies the current
context into every asyncio.create_task, so background work spawned
from inside a request inherits the same ID without explicit threading.
request.state can't make that hop. The logging filter also has no
access to the FastAPI request object — it runs synchronously inside
the stdlib logging machinery — and the ContextVar is the only
mechanism that bridges async request scope to sync log emission.
Inbound X-Trace-Id is hard-validated against [A-Za-z0-9_-]+ (max 64
chars) before being honoured — a hostile/buggy caller cannot smuggle
log-injection payloads (newlines, control chars, megabyte blobs) into
bambuddy.log via the trace ID column; values that fail the gate
silently trigger a freshly minted server-side ID rather than failing
the request.
Middleware is decorated AFTER auth_middleware on purpose: Starlette
stacks @app.middleware decorators LIFO so the last-decorated runs
first inbound, making trace stamp the OUTERMOST layer — auth log
lines and every record emitted on the way down to and back from the
route handler all carry the same ID.
Output now correlates as:
2026-04-26 09:51:39,152 INFO [uvicorn.access] [a4f3b1e7] - "POST
/api/v1/printers/1/print/stop HTTP/1.1" 200
2026-04-26 09:51:39,158 INFO [bambu_mqtt] [a4f3b1e7] [SERIAL] Sent
stop print command
One grep a4f3b1e7 returns the full causality chain.
30 new tests: 22 unit (ContextVar placeholder, filter copies value,
asyncio task propagation, concurrent-request isolation, hex generator
uniqueness, hostile-payload validator, max-length boundary, all four
write verbs survive, GET/HEAD/OPTIONS dropped, URL-substring false-
match guards, edge cases) and 8 integration (X-Trace-Id round-trips,
body matches header, hostile inbound replaced, overlong inbound
replaced, ContextVar resets after request, generator format stable,
each request gets unique ID).