2 Commits

Include renames

Author	SHA1	Message	Date
maziggy	88b5f56eb2	fix: cancel = layer shift, stuck "1 problem", and dropped child-logger logs ... Three bugs that surfaced together while debugging an H2D cancel: 1. Cancelling a print stamped failure_reason="Layer shift" in archives AND left the printer card stuck on "1 problem" forever. Four causes: (a) POST /printers/{id}/print/stop never set the user-stopped flag, so on_print_complete couldn't override "failed" -> "cancelled". (b) HMS-derived failure_reason heuristic mapped any module-0x0C HMS to "Layer shift". Module 0x0C is "Motion Controller" broadly (includes cameras, markers, AND the cancel-sequence echo 0C00_001B). Real layer-shift codes live in module 0x03. Same false-positive class existed for "Filament runout" (any 0x07) and "Clogged nozzle" (any 0x05). Replaced with a 23-code curated short-code map; unknowns leave failure_reason=None. (c) Cancel-echo HMS codes (0300_400C "The task was canceled.", 0500_400E "Printing was cancelled.") were polluting state.hms_errors via both the hms[] and print_error parse paths. Filter them at parse time so the frontend never sees them. (d) Frontend bucketed gcode_state="FAILED" as a problem unconditionally. Real failures attach an HMS error; user-cancels don't — so FAILED- without-HMS now buckets as "finished" and only escalates to "error" when there's an active known HMS. 2. logs/bambuddy.log was silently dropping records from named child loggers. TraceIDFilter was attached to root_logger, but Python's logging only invokes a Logger's filters on records originating at that logger — propagated child-logger records skipped it, formatter raised KeyError, handler.handleError dropped the record. Moved the filter from root_logger.addFilter() to handler.addFilter() on each handler, matching the filter's own docstring guidance. derive_failure_reason() extracted as a pure function for testability. status="cancelled" now symmetrically yields "User cancelled" alongside "aborted". 20 regression tests across: - backend/tests/unit/test_failure_reason_derivation.py (11) - backend/tests/unit/services/test_bambu_mqtt.py::TestHMSUserActionFiltering (4) - backend/tests/unit/test_trace.py::TestFilterMustBeAttachedToHandlerNotLogger (1) - frontend/src/__tests__/pages/PrintersPageBucketing.test.ts (5; includes the H2D-cancel-echo "FAILED + only unknown HMS" case)	2026-04-26 14:24:28 +02:00
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