fix(queue): two-phase dispatch watchdog so a printer that accepts project_file but never starts doesn't wedge the queue (#1678)

_watchdog_print_start now treats subtask_id-advance as Phase A
  "command landed", not as final success. Phase B (180s) keeps watching
  for the active-state transition; if it never arrives — printer
  accepted the file but stalled (cloud+LAN re-auth after a power cycle
  on old firmware was the reported trigger) — revert the queue item to
  'pending' instead of leaving it stuck in 'printing' until container
  restart. Phase B skips force_reconnect because subtask_id-advance
  proves the project_file landed; a reconnect mid-parse would trigger
  0500_4003 (#1150). Phase A's H2D 50s FINISH→PREPARE tolerance (#1078)
  is preserved by Phase B's 180s headroom.
This commit is contained in:
maziggy
2026-06-08 07:54:24 +02:00
parent a104ccc95c
commit fdaff37975
3 changed files with 165 additions and 47 deletions
+82 -8
View File
@@ -76,11 +76,25 @@ class TestWatchdogExitsEarlyOnPickup:
assert item.status == "printing"
@pytest.mark.asyncio
async def test_exits_on_subtask_id_change_even_if_state_still_finish(self, db_session):
"""Regression for #1078: H2D keeps state=FINISH for ~50 s after accepting
project_file, but subtask_id flips to our new submission_id almost
immediately. That must short-circuit the revert."""
get_status = MagicMock(return_value=_status("FINISH", "NEW_SUBTASK_12345"))
async def test_h2d_finish_to_running_via_subtask_id_then_active_state(self, db_session):
"""Regression for #1078 (preserved through the two-phase rewrite for #1678):
H2D keeps state=FINISH for ~50 s after accepting project_file, but
subtask_id flips to our new submission_id almost immediately. The
watchdog must NOT revert on the basis of state staying at FINISH —
Phase A exits on the subtask_id advance, Phase B then keeps watching
and exits SUCCESS as soon as the printer transitions to PREPARE /
RUNNING within the longer Phase B window.
"""
# First poll: state still FINISH, subtask_id advanced (Phase A → B).
# Second poll: state has flipped to RUNNING (Phase B success).
get_status = MagicMock(
side_effect=[
_status("FINISH", "NEW_SUBTASK_12345"),
_status("RUNNING", "NEW_SUBTASK_12345"),
]
+ [_status("RUNNING", "NEW_SUBTASK_12345")] * 10,
)
with (
patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
patch("backend.app.services.print_scheduler.async_session", db_session),
@@ -91,15 +105,16 @@ class TestWatchdogExitsEarlyOnPickup:
pre_state="FINISH",
pre_subtask_id="OLD_SUBTASK_99999",
timeout=0.3,
phase_b_timeout=0.3,
poll_interval=0.05,
)
async with db_session() as db:
item = await db.get(PrintQueueItem, 1)
assert item.status == "printing", (
"subtask_id advanced past pre_subtask_id — the printer accepted our "
"project_file and the watchdog must not revert the queue item even "
"though state is still FINISH (#1078)"
"Phase A exit on subtask_id advance + Phase B observing the "
"active-state transition is the H2D success path — watchdog "
"must keep the item 'printing' (#1078)"
)
@@ -228,6 +243,65 @@ class TestWatchdogRevertsWhenStuck:
sig = inspect.signature(PrintScheduler._watchdog_print_start)
assert sig.parameters["timeout"].default == 90.0
@pytest.mark.asyncio
async def test_default_phase_b_timeout_is_180_seconds(self):
"""Phase B (subtask_id advanced, waiting for active state) must
comfortably exceed the H2D FINISH→PREPARE delay (~50 s observed)
before declaring a printer-side wedge. 180 s gives ~3.5× headroom
and reverts the queue item in well under the previous 2-hour
expected_print TTL (#1678)."""
import inspect
sig = inspect.signature(PrintScheduler._watchdog_print_start)
assert sig.parameters["phase_b_timeout"].default == 180.0
@pytest.mark.asyncio
async def test_reverts_when_subtask_advanced_but_state_never_active(self, db_session):
"""Regression for #1678: P1S on old firmware, power-cycled mid-print,
cloud+LAN re-auth dance in flight. Printer accepts project_file
(gcode_file updates, subtask_id advances to our submission id) but
never transitions from IDLE/FINISH to PREPARE/RUNNING. The pre-fix
watchdog returned SUCCESS as soon as subtask_id advanced and the
queue item stayed in 'printing' until container restart. Phase B now
keeps watching; if the active-state transition never arrives, the
item reverts to 'pending' so the user can retry without restarting.
"""
get_status = MagicMock(
return_value=_status("IDLE", "NEW_SUBTASK_12345", gcode_file="/new.3mf"),
)
client = MagicMock() # NOT None — must verify reconnect isn't called
get_client = MagicMock(return_value=client)
with (
patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
patch("backend.app.services.print_scheduler.async_session", db_session),
patch("backend.app.core.database.async_session", db_session),
):
await PrintScheduler._watchdog_print_start(
queue_item_id=1,
printer_id=42,
pre_state="IDLE",
pre_subtask_id="OLD_SUBTASK_99999",
pre_gcode_file="/old.3mf",
timeout=0.2,
phase_b_timeout=0.2,
poll_interval=0.05,
)
async with db_session() as db:
item = await db.get(PrintQueueItem, 1)
assert item.status == "pending", (
"subtask_id advanced (Phase A → B) but state never reached an "
"active value — printer-side wedge; the queue item must be "
"reverted to 'pending' (#1678)"
)
assert item.started_at is None
# File landed (subtask_id advance proves this), so a forced reconnect
# would trigger 0500_4003 mid-parse (#1150) — skip.
client.force_reconnect_stale_session.assert_not_called()
class TestWatchdogFallbackBehaviour:
"""Backwards-compat and defensive behaviour around missing data."""