From 9d0418688c4685964866134ee2b26fc507f72b53 Mon Sep 17 00:00:00 2001 From: maziggy Date: Sun, 26 Apr 2026 08:58:08 +0200 Subject: [PATCH] fix(#1134): propagate background-dispatch watchdog timeout as job failure MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Follow-up to #1042. The post-dispatch watchdog _verify_print_response was fire-and-forget — it correctly detected when the printer never transitioned (HMS error pending, half-broken MQTT session, plate-clear gate, SD card fault) and force-reconnected the MQTT session, but the dispatch job had already been marked successful on the optimistic MQTT-publish-acknowledged path. The UI carried on showing "Print started successfully" while the printer sat idle. The watchdog now returns bool and is awaited inline by both call sites in _run_reprint_archive and _run_print_library_file. On False the call sites raise a RuntimeError carrying a user-actionable message ("Printer did not acknowledge print command — state still {pre_state}. Check the printer for a pending error...") which routes through the existing _run_active_job → _mark_job_finished(failed=True) → background_dispatch WS broadcast path. Library-file flow rolls back the freshly-created archive on timeout so no phantom row is left behind for a print that never started. The watchdog now also accepts subtask_id advancing past pre_subtask_id as a definitive "command landed" signal — same as the queue-side watchdog at print_scheduler.py:1992 — so slow H2D FINISH→PREPARE transitions (~50 s observed) don't false-fail when the printer has clearly accepted the project_file but is still in FINISH. Default timeout raised from 15 s to 90 s to match the queue-side watchdog and give the same headroom on both dispatch paths. Brief mid-window MQTT disconnects keep polling instead of immediately failing — matches what the queue watchdog already does and avoids false-failing on transient telemetry gaps. 11 new tests in test_background_dispatch_watchdog.py: state-change pickup, subtask_id-change pickup with state still FINISH, neither-changed timeout plus force_reconnect_stale_session call, pre_subtask_id=None backwards- compat, post-dispatch subtask_id=None not counting as a change, brief disconnect not short-circuiting the window, persistent disconnect for the full window returning False, default-timeout=90s contract, _run_reprint_archive raises RuntimeError with the captured pre-state args on watchdog False, _run_reprint_archive happy path doesn't rollback, _run_active_job marks the job failed with the message when _process_job raises RuntimeError. --- CHANGELOG.md | 2 + backend/app/services/background_dispatch.py | 91 ++- .../test_background_dispatch_watchdog.py | 521 ++++++++++++++++++ 3 files changed, 600 insertions(+), 14 deletions(-) create mode 100644 backend/tests/unit/services/test_background_dispatch_watchdog.py diff --git a/CHANGELOG.md b/CHANGELOG.md index a562e773c..205b3a1c7 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,6 +28,8 @@ All notable changes to Bambuddy will be documented in this file. - **Settings page: permission-gated instead of admin-only** — the Settings sidebar entry has always been visible to any user holding `settings:read`, but the route guard required admin role, so a non-admin with `settings:read` would see the entry, click it, and get silently redirected back to the dashboard. The route guard now matches the sidebar: any user with `settings:read` can open the page, and the individual tabs / cards continue to enforce their own per-feature permissions (`users:read`, `groups:update`, `oidc:*`, etc. — many of them admin-only, some not). Group editor routes moved to permission-based guards too (`groups:create` for `/groups/new`, `groups:update` for `/groups/:id/edit`), so permission delegation works end-to-end. Admins retain full access since admins implicitly hold every permission. ### Fixed +- **Background-dispatch reported "Print started successfully" when the printer never actually transitioned** ([#1134](https://github.com/maziggy/bambuddy/issues/1134), follow-up to [#1042](https://github.com/maziggy/bambuddy/issues/1042)) — The int32 `task_id` modulo fix that was the original root cause of #1042 is verified working in the reporter's most recent support pack (the published `task_id` values are well below 2^31-1 and match the `int(time.time() * 1000) % 2_147_483_647` formula exactly). The remaining residual — "the UI reports despatch success which is slightly misleading" — was a real second bug class: the post-dispatch watchdog `_verify_print_response` in `services/background_dispatch.py` was *fire-and-forget*. It would correctly detect that the printer never transitioned (e.g. P1S sitting in `gcode_state: FAILED` with HMS `0300_400C` "task was canceled", a half-broken MQTT session, an SD card error, or any other pre-print blocker), log a `did not respond to print command within 15s` warning, force-reconnect the MQTT session — and then return without touching the dispatch job state. The dispatch job had already been marked successful on the optimistic MQTT-publish-acknowledged path, so the UI carried on showing "Print started successfully" while the printer sat idle. The watchdog now returns a `bool` and is awaited inline by both call sites (`_run_reprint_archive` at line 687, `_run_print_library_file` at line 860); on `False` (timeout) the call sites raise a `RuntimeError` carrying a user-actionable message ("Printer did not acknowledge print command — state still {pre_state}. Check the printer for a pending error (HMS code, plate-clear prompt, SD card) and try again."), which routes through the existing `_mark_job_finished(failed=True, …)` path so the dispatch UI shows a real failure toast and the library-file flow's freshly-created archive is `db.rollback()`'d (no orphan rows for prints that never started). The watchdog now also accepts `subtask_id` advancing past the captured `pre_subtask_id` as a definitive "command landed" signal — same as the queue-side watchdog at `print_scheduler.py:1992` (#1078) — so slow H2D `FINISH→PREPARE` transitions (~50 s observed) don't false-fail when the printer has clearly accepted the project_file but is still in FINISH. Default timeout raised from 15 s to 90 s to match the queue-side watchdog (#967 / #1078) and give the same headroom on both dispatch paths. Brief mid-window MQTT disconnects (`get_status() is None` for one tick) now keep polling instead of immediately failing — matches what the queue watchdog already does and avoids false-failing on transient telemetry gaps. The existing `force_reconnect_stale_session` recovery is preserved on the timeout path. 8 new regression tests in `test_background_dispatch_watchdog.py` cover state-change pickup, subtask_id-change pickup with state still FINISH (the H2D case), neither-signal-changed timeout + force-reconnect, pre_subtask_id=None backwards-compat, post-dispatch subtask_id=None not counting as a change (avoids false-pass on transient reconnect), brief disconnect not short-circuiting the window, persistent disconnect for the full window returning False, and a contract test that the default timeout is 90 s. Thanks to @EdwardChamberlain for the detailed retest with logs that pinpointed the watchdog's no-propagation gap. + - **Bambu RFID auto-match created duplicate inventory rows for Quick-Add and non-Bambu-branded spools** ([#918](https://github.com/maziggy/bambuddy/issues/918)) — `find_matching_untagged_spool` is supposed to attach a Bambu RFID UID to a pre-existing manually-logged spool of the same material/color so users who log inventory before scanning don't end up with a duplicate row on first AMS read. Two bugs in the matcher meant it almost never worked for the actual reporting workflow: **(1)** the subtype filter was strict — when the AMS tray reports `tray_sub_brands="PLA Basic"` the matcher required `Spool.subtype = 'Basic'` exactly, so any Quick-Add row (Quick-Add only requires `material`, leaving `subtype=NULL`) was excluded and duplicated on first AMS read. **(2)** the docstring claimed it filtered on brand but the WHERE clause didn't, so a same-color *Polymaker* untagged spool would silently acquire a Bambu Lab tray UUID, leaving the user with `brand="Polymaker"` but a Bambu UUID — silent data corruption. Both bugs are addressed in the same query: subtype now prefers an exact match but accepts a NULL-subtype row as fallback (with a `CASE` in `ORDER BY` so an exact match still wins when both exist), and brand is now restricted to "contains 'bambu' (case-insensitive)" or NULL — matching `'Bambu'` (the form's `DEFAULT_BRANDS` value), `'Bambu Lab'` (the catalog value), `'BambuLab'`, `'bambu lab'`, etc., while rejecting any explicitly-named third-party brand. 6 new regression tests in `test_spool_tag_matcher.py` cover the NULL-subtype fallback, exact-subtype-wins-over-NULL ordering, non-Bambu brand rejection, NULL brand acceptance, all four Bambu brand spelling variants, and the full Quick-Add scenario (`brand=NULL` + `subtype=NULL`). The broader UI proposals in #918 (manual override / merge / disambiguation prompt) are intentionally out of scope — once the matcher works, the duplicate-on-RFID complaint that motivated those proposals goes away. Thanks to @ViridityCorn for the report and pointing at the right function, and to @Arn0uDz for confirming with a 20-spool repro. - **Swagger UI link in Settings → API Keys rendered a blank page** — the global CSP applied by `security_headers_middleware` set `script-src 'self'` and `style-src 'self' 'unsafe-inline' https://fonts.googleapis.com`, which blocked both the inline `