Files
bambuddy/backend/tests/integration/test_trace_middleware.py
T
maziggy 1878d2aab5 feat(observability): trace ID column on every log line + X-Trace-Id header
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).
2026-04-26 10:01:17 +02:00

145 lines
6.0 KiB
Python

"""Integration test for the trace-ID middleware contract.
Tests focus on observable surface — what headers go out, what
ContextVar value the route handler sees — rather than re-testing the
ContextVar / filter primitives (those are covered in
``tests/unit/test_trace.py``).
A minimal FastAPI app is used instead of the production ``backend.app.main``
app: importing main.py would pull in the entire startup graph (DB
migrations, MQTT subscribers, scheduler, etc.) just to assert "the
middleware sets a header", and that overhead would dwarf the test value.
The middleware function is copied inline so the test pins the exact
contract expected of it.
"""
from __future__ import annotations
import re
import pytest
from fastapi import FastAPI
from fastapi.testclient import TestClient
from backend.app.core.trace import (
generate_trace_id,
get_trace_id,
normalise_inbound_trace_id,
trace_id_var,
)
def _build_app_with_trace_middleware() -> FastAPI:
"""Construct a minimal FastAPI app with the trace middleware wired up
the same way main.py does it."""
app = FastAPI()
@app.middleware("http")
async def trace_id_middleware(request, call_next):
inbound = normalise_inbound_trace_id(request.headers.get("X-Trace-Id"))
trace_id = inbound if inbound is not None else generate_trace_id()
token = trace_id_var.set(trace_id)
try:
response = await call_next(request)
finally:
trace_id_var.reset(token)
response.headers["X-Trace-Id"] = trace_id
return response
@app.get("/echo-trace")
async def echo_trace():
# Read the ContextVar from inside the request handler so the
# test can assert that what's in the header matches what
# downstream code sees. If these ever diverge, application
# logs would be stamped with a different ID than the one the
# client gets back — useless for correlation.
return {"trace_id": get_trace_id()}
return app
@pytest.fixture
def client() -> TestClient:
return TestClient(_build_app_with_trace_middleware())
class TestGeneratedTraceId:
def test_response_carries_x_trace_id_header(self, client):
"""Every response must echo X-Trace-Id so a client can paste it
into a server-side log search later — without it, the trace ID
column in bambuddy.log is one-way only."""
response = client.get("/echo-trace")
assert response.status_code == 200
assert "X-Trace-Id" in response.headers
assert response.headers["X-Trace-Id"]
def test_generated_id_matches_handler_view(self, client):
"""The X-Trace-Id header value must equal what the route handler
saw in its ContextVar — otherwise client-side and server-side
log searches use different keys and never join up."""
response = client.get("/echo-trace")
body_id = response.json()["trace_id"]
header_id = response.headers["X-Trace-Id"]
assert body_id == header_id
def test_each_request_gets_a_unique_id(self, client):
"""Two consecutive requests should produce two different IDs —
otherwise the column in the log file is useless for telling
requests apart."""
first = client.get("/echo-trace").headers["X-Trace-Id"]
second = client.get("/echo-trace").headers["X-Trace-Id"]
assert first != second
def test_generated_id_format_is_short_hex(self, client):
"""Bound the visible width and shape of the column. If the
generator ever switches format (e.g. UUID-with-dashes) the
format-string column width changes and grep patterns that
downstream tooling might rely on break — make the change
deliberate by failing this test instead."""
tid = client.get("/echo-trace").headers["X-Trace-Id"]
assert re.fullmatch(r"[0-9a-f]+", tid), tid
assert 4 <= len(tid) <= 32
class TestInboundTraceIdRespected:
def test_safe_inbound_id_is_echoed(self, client):
"""When the caller sends a sane X-Trace-Id, we honour it — this
is the cross-system correlation case (caller's tracing system
wants its span ID propagated)."""
response = client.get("/echo-trace", headers={"X-Trace-Id": "client-sent-abc123"})
assert response.headers["X-Trace-Id"] == "client-sent-abc123"
assert response.json()["trace_id"] == "client-sent-abc123"
def test_hostile_inbound_id_is_replaced(self, client):
"""A header that fails the validator (control chars,
log-injection-shaped chars, etc.) must NOT reach the response
header or the log column — silently mint fresh and carry on,
so a hostile/buggy caller can't break our log file but also
can't break their own request by sending a bad header."""
response = client.get("/echo-trace", headers={"X-Trace-Id": "abc\ndef rm -rf /"})
echoed = response.headers["X-Trace-Id"]
assert echoed != "abc\ndef rm -rf /"
assert "\n" not in echoed
assert " " not in echoed
def test_overlong_inbound_id_is_replaced(self, client):
"""The cap protects bambuddy.log from a 1KB-per-line blowup if
a caller sends a huge X-Trace-Id."""
too_long = "a" * 100
response = client.get("/echo-trace", headers={"X-Trace-Id": too_long})
assert response.headers["X-Trace-Id"] != too_long
class TestContextResetAfterRequest:
def test_trace_id_var_resets_after_request_completes(self, client):
"""The middleware must reset the ContextVar in its ``finally``
block. Without this, a record emitted in a totally unrelated
background task that happens to inherit the test client's
context would keep referencing a long-gone request's ID."""
from backend.app.core.trace import TRACE_ID_PLACEHOLDER
client.get("/echo-trace")
# After the request returns, the test fixture's context should
# no longer hold the request's ID.
assert get_trace_id() == TRACE_ID_PLACEHOLDER