fix(reconcile): don't synthesize aborted PRINT COMPLETE on the bare-connect edge before push_status arrives (#1679)

on_printer_status_change fires from MQTT _on_connect BEFORE the first
  push_status round-trips, when PrinterState is still on construction
  defaults (state="unknown", subtask_name=""). The connected-edge
  reconcile was treating that degenerate state as evidence and
  synthesising aborted PRINT COMPLETE for every in-flight archive on
  every Bambuddy restart. The reactive PRINT COMPLETE then created a
  duplicate archive (lookup misses on cleared _active_prints), so
  filament got deducted twice.

  Two-layer guard: gate the reconcile spawn on a real state.state, and
  make _is_active_archive_stale return not-stale on unknown/empty input
  as defensive fallback. #1542 behaviour preserved — real stale archives
  still get caught the moment a real push_status arrives.
This commit is contained in:
maziggy
2026-06-08 08:18:13 +02:00
parent fdaff37975
commit d0d6a659e9
3 changed files with 56 additions and 4 deletions
+2
View File
@@ -5,6 +5,8 @@ All notable changes to Bambuddy will be documented in this file.
## [0.2.5b1] - Unreleased
### Fixed
- **Restarting Bambuddy mid-print no longer marks the live archive as "cancelled / aborted" + duplicates it + double-counts filament (#1679, reported by @IndividualGhost1905)** — Reporter on X1C, daily build `v0.2.5b1-daily.20260607`: a print was running, the host was restarted (planned reboot / power outage / watchtower image update), and Bambuddy's printer card showed the print as **cancelled** while the printer continued printing happily. Print log showed `aborted` for that row, filament usage was deducted at the cancellation moment (48.6 g / 5 % in the supplied screenshots), and when the print actually finished a *second* archive was created and filament was deducted *again*. Net effect: filament inventory off by the entire print weight, statistics showing one "user-cancelled" entry alongside one "completed" entry for the same physical print. Second confirmed hit from the same reporter, plus a corroborating comment from @Arn0uDz on watchtower-driven restarts. **Root cause: connected-edge reconciliation fired on a bare MQTT-connected state that had no real data yet.** On Bambuddy startup, a fresh `BambuMQTTClient` is constructed with `PrinterState` defaults — most importantly `state.state = "unknown"` and `state.subtask_name = ""`. The MQTT `_on_connect` callback (`bambu_mqtt.py:668-669`) broadcasts `on_state_change(self.state)` *immediately* after the broker accepts the connection — BEFORE the `_request_push_all` round-trips with the printer's real status. `on_printer_status_change` (`main.py:825`) sees `state.connected=True` flip on the connected-edge, spawns `reconcile_stale_active_prints` for that printer. The reconcile walks every archive in `status="printing"`, calls `_is_active_archive_stale` (`main.py:3352`) — which sees `state.state="UNKNOWN"` (skips the IDLE/FINISH/FAILED branch), then `state.subtask_name=""` (matches trigger 3, "printer subtask_name empty") and **returns stale**. A synthesised `aborted` PRINT COMPLETE fires for every in-flight archive on every printer, clears `_active_prints`, and when the real PRINT COMPLETE finally arrives at print end, `_active_prints` doesn't have the entry, so a brand-new archive row is created instead of overwriting the synthesised one. The pre-existing comment at `_is_active_archive_stale` ("the next real PRINT COMPLETE would have overwritten the status anyway") was wrong: the reactive completion handler uses `_active_prints` for lookup, not a join on filename/subtask_id, so the original row stays cancelled and a duplicate is born. Timing-dependent in practice — on hosts where the printer's first `push_status` response wins the race against the reconcile background task, state is real and reconcile doesn't false-positive; on slower hosts or busy MQTT brokers, the bare-connect-edge fires first and the bug hits. The reporter is on a slower-race host and saw it twice. **Fix: two-layer guard.** (1) Primary: `on_printer_status_change` now gates the reconcile spawn on `state.state` being a real value — `state_known = bool(state.state) and state.state.upper() not in ("", "UNKNOWN")` — so reconcile doesn't fire until the first `push_status` updates `state.state` to a real Bambu firmware value (RUNNING / IDLE / FINISH / PREPARE / SLICING / PAUSE / FAILED). When that real push arrives, `on_printer_status_change` fires again, the connected-edge flag is still `False` (we never set it), and reconcile runs against actual evidence. The existing #1542 mechanism — synthesising a missed PRINT COMPLETE for prints that finished during a disconnect window — keeps working: if the printer reports `IDLE` on its first real push after reconnect, reconcile catches it the way it always did. (2) Belt-and-braces: `_is_active_archive_stale` now returns `(False, "")` when `state.state` is empty / `"unknown"` / `None`, regardless of the subtask fields. Strictly more conservative than the previous behaviour; only suppresses the degenerate-input false positive. Any future caller that bypasses the primary gate still can't synthesise an aborted completion from defaults. **Tests:** `test_reconcile_stale_active_prints.py` 26 cases (up from 21) — new parametrize `test_pre_push_state_returns_not_stale_even_with_empty_subtask` pins all five degenerate forms (`"unknown"`, `"UNKNOWN"`, `"Unknown"`, `""`, `None`) and asserts none triggers stale even with empty `subtask_id` + empty `subtask_name`. The existing #1542 regression coverage stays green — terminal-state, subtask-id-mismatch, and empty-subtask-name-under-RUNNING all still report stale on real state pushes. Full backend suite: 3836 / 3836 pass. ruff clean.
- **Print queue no longer wedges in "Currently Printing" when a printer accepts `project_file` but never starts (#1678, reported by @kleinwareio)** — Reporter on two P1S, one was power-cycled mid-print and came back online; from then on Bambuddy showed the next queue item as "Currently Printing" at 0% while the printer card showed "Idle / Ready to print". The same file also re-appeared in the Queued list as Pending after the user resubmitted. Only restarting the Bambuddy container ever recovered it. Support log + screenshots confirm: at dispatch time MQTT `project_file` was ACK'd, printer pushed `gcode_state=IDLE, gcode_file=<our-file>, subtask_id=<our-submission-id>` — i.e. the file landed on the printer but the printer never transitioned IDLE → PREPARE → RUNNING. **Root cause: `_watchdog_print_start` returned SUCCESS as soon as `subtask_id` advanced.** The subtask_id-as-pickup-signal was added for H2D, which can sit at `FINISH` for ~50 s after accepting `project_file` before flipping to PREPARE (#1078) — but it's strictly a "command landed" signal, not "actually printing". When the printer accepts the file but then wedges (cloud+LAN re-auth dance after a power cycle, old firmware, partial network outage), the watchdog returned success, the queue row stayed at `status='printing'`, the in-memory `_expected_prints` entry stayed registered (TTL is 2 hours and only clears the dict, not the DB row), and every subsequent queue item was blocked because the printer was still "in flight". This reporter's firmware (01.07.00.00, current is 01.08.x+) and `bambu_cloud_token`-enabled cloud+LAN mode make the post-power-cycle wedge measurably more likely on their box, but the queue-wedge bug applies to any printer that accepts a file but stalls before starting. **Fix: split the watchdog into two phases.** Phase A (up to `timeout`, default 90 s, unchanged behaviour) waits for either an active-state transition OR a `subtask_id` advance — if neither happens the publish was lost on a half-broken MQTT session (#887/#936) and we revert + force-reconnect (the original #967 recovery path). Phase B (new, up to `phase_b_timeout`, default 180 s) only runs when Phase A exited via subtask_id-alone: keep watching for the active-state transition. 180 s is ~3.5× the worst observed H2D FINISH → PREPARE delay (#1078), so the H2D path stays green. If Phase B times out the queue item is reverted to `pending` so the user can retry without restarting Bambuddy — and Phase B explicitly does NOT force a MQTT reconnect because subtask_id-advance proves the project_file landed and a forced reconnect mid-parse triggers 0500_4003 (#1150). Phase A's existing `gcode_file`-changed discriminator (#1150) stays put for the no-subtask-id-advance case. **Tests:** `test_scheduler_watchdog.py` 14 cases (up from 13) — the #1078 H2D regression test rewritten to step the status through Phase A (subtask_id advance with state=FINISH) then Phase B (state flips to RUNNING) and pin success; new `test_reverts_when_subtask_advanced_but_state_never_active` pins the #1678 wedge case (subtask_id advances, state stays IDLE for the full Phase B window → revert + NO force_reconnect call); new `test_default_phase_b_timeout_is_180_seconds` pins the new default so a future refactor doesn't silently shrink the H2D headroom. Existing #967 / #1150 / #1370 / disconnect / fallback / discriminator regression coverage all stays green. Wider scheduler + queue + dispatch test surface (305 tests) stays green; ruff clean.
- **Service-worker activate handler no longer hangs first-install browsers (demo site stuck spinner + Firefox Corrupted-Content)** — Reproduced live on the demo platform: a visitor lands on `{session}.demo.bambuddy.cool/`, the Printers page renders, but clicking any sidebar entry sticks the next page on a spinner; only a manual reload recovers. In Firefox the same race surfaces as a "Corrupted Content Error" with `sw.js` stuck in `activating` for the entire session. **Root cause:** the `client.navigate(client.url)` call added to the `activate` handler in `sw.js` (commit `18d534c9`, shipped 2026-06-04 alongside the Orca Cloud landing) was intended to force kiosks running an old SW to reload after a deploy, but its only guard was `client.url && typeof client.navigate === 'function'` — neither distinguishes a first install from an upgrade. On every fresh origin (every demo session is a new subdomain, but also any browser visiting Bambuddy for the first time, or after clearing site data) the activate handler still fired the forced navigation: Chromium raced it against React Router's in-flight SPA mount and wedged the page; Firefox's `event.waitUntil` deadlocked on `await client.navigate(...)` because the SW intercepts its own document fetch while still `activating`, the document load aborts, and the SW never reaches `activated`. The "first install on a never-controlled client" guard the commit's comment claimed simply didn't exist in code. **Fix: split the lifecycle correctly.** `sw.js` activate handler is reduced to cache cleanup + `clients.claim()` (matches the standard PWA lifecycle and lets activation complete in low single-digit ms regardless of in-flight document state). The deploy-pickup reload moves to `sw-register.js`: capture `hadController = !!navigator.serviceWorker.controller` at script load (true ⇔ a previous SW was controlling the document), listen for `controllerchange`, and only `location.reload()` when `hadController` was true. A returning kiosk hits a new deploy → had a controller → reloads as before. A first-install visitor (no prior SW, or hard-refresh, or first demo session) → no controller → no forced navigation → React mount completes cleanly. `CACHE_NAME` bumped `bambuddy-v29 → bambuddy-v30` and `STATIC_CACHE` `bambuddy-static-v28 → bambuddy-static-v29` so existing browsers fetching the new `sw.js` drop the old CacheStorage in the same pass — without the bump the SW file byte content might equal the cached one and the upgrade installs nothing. The SpoolBuddy-kiosk unregister branch at the top of `sw-register.js` is unchanged (still wipes registrations on `/spoolbuddy` paths). The `notificationclick` handler in `sw.js` (open-tab-on-push) still uses `client.navigate(url)` — different code path, unrelated, unchanged.
+36 -4
View File
@@ -822,7 +822,22 @@ async def on_printer_status_change(printer_id: int, state: PrinterState):
# WebSocket dedup / broadcast logic below, and the connected edge is
# marked True BEFORE the await so concurrent status updates inside
# the same connection don't re-trigger reconciliation.
if state.connected and not _printer_reconciled_since_connect.get(printer_id, False):
#
# Wait for a real push_status before reconciling (#1679): MQTT
# `_on_connect` broadcasts `state` IMMEDIATELY after the broker accepts
# the connection, BEFORE `_request_push_all` round-trips. At that
# instant the `PrinterState` is still on construction defaults — most
# importantly `state.state == "unknown"` and `state.subtask_name == ""`.
# If reconcile spawns here, every in-flight archive falls through to
# the empty-subtask_name trigger and gets synthesised `aborted`, which
# creates a duplicate archive on the real PRINT COMPLETE and
# double-counts filament. Gating on `state.state ∉ ("", "unknown")`
# keeps the #1542 mechanism intact: once the first real push_status
# updates `state.state` (RUNNING / IDLE / FINISH / …), this handler
# fires again with the flag still False — reconcile then runs against
# actual evidence.
state_known = bool(state.state) and state.state.upper() not in ("", "UNKNOWN")
if state.connected and state_known and not _printer_reconciled_since_connect.get(printer_id, False):
_printer_reconciled_since_connect[printer_id] = True
spawn_background_task(
reconcile_stale_active_prints(printer_id),
@@ -3371,11 +3386,28 @@ def _is_active_archive_stale(archive, state) -> tuple[bool, str]:
Conservative on purpose: PAUSE / PREPARE / SLICING and any RUNNING state
with matching subtask_id+subtask_name is left alone. The cost of a false
positive is a single misreported "aborted" status that the next real
PRINT COMPLETE would have overwritten with the correct status anyway.
The cost of a false negative is the ghost-print loop in #1542.
positive is a duplicate archive on the next real PRINT COMPLETE — the
reactive handler uses ``_active_prints`` for lookup, which the reconcile
clears on synthesis, so the real completion creates a fresh row instead
of overwriting the synthesised one (#1679). The cost of a false negative
is the ghost-print loop in #1542.
Pre-push guard (#1679): when ``state.state`` is empty or ``"unknown"``,
MQTT has connected but the first ``push_status`` response hasn't been
applied yet — ``PrinterState`` is sitting on its construction defaults.
The reconcile caller in ``on_printer_status_change`` is already gated
on a real ``state.state``, so in normal operation this branch is
unreachable; it's kept as belt-and-braces for future callers and for
the narrow window where a partial state update could arrive
(``state.state`` set but ``subtask_name`` not yet populated). Returning
``not stale`` on degenerate input is strictly conservative: a real
stale archive will still be caught by the next push_status arriving
with terminal state.
"""
current_state = (state.state or "").upper()
if current_state in ("", "UNKNOWN"):
# No real push_status yet — PrinterState defaults are not evidence.
return False, ""
if current_state in ("IDLE", "FINISH", "FAILED"):
return True, f"printer state {current_state}"
# Below here the printer is in a running / pre-running state (RUNNING /
@@ -129,6 +129,24 @@ class TestIsActiveArchiveStale:
assert is_stale is True
assert "IDLE" in reason
# #1679: defensive pre-push guard. Even if reconcile gets called against
# a PrinterState that's still on construction defaults (state="unknown"
# / empty / None, subtask_name=""), the function must NOT report stale —
# otherwise the reactive PRINT COMPLETE later creates a duplicate
# archive and filament gets double-counted. The on_printer_status_change
# caller is the primary fix (gates the reconcile spawn on real state),
# but this guard is belt-and-braces for any future caller.
@pytest.mark.parametrize("degenerate_state", ["unknown", "UNKNOWN", "Unknown", "", None])
def test_pre_push_state_returns_not_stale_even_with_empty_subtask(self, degenerate_state):
archive = _archive(subtask_id="ABC123")
state = _state(degenerate_state, subtask_id="", subtask_name="")
is_stale, _ = _is_active_archive_stale(archive, state)
assert is_stale is False, (
f"state.state={degenerate_state!r} means MQTT hasn't pushed real data yet; "
"treating an in-flight archive as stale here causes the #1679 "
"duplicate-archive + filament-double-count regression"
)
class TestReconcileStaleActivePrints:
"""Orchestrator-level tests — mock the printer manager + DB session so