test_scheduler_watchdog.py 32 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724
  1. """Regression tests for ``_watchdog_print_start``.
  2. The watchdog reverts queue items to ``pending`` when a dispatched print never
  3. lands on the printer (half-broken MQTT session — #887/#936/#967). H2D firmware
  4. can sit at ``FINISH`` for 50+ seconds after accepting a ``project_file``
  5. command before flipping ``gcode_state`` to ``PREPARE``, which used to trip the
  6. state-only watchdog and cause the scheduler to revert the item; the subsequent
  7. successful dispatch then looked like a reprint of the just-finished job (#1078).
  8. The fix: treat ``subtask_id`` advancing past the pre-dispatch value as an
  9. equivalent "command landed" signal, and raise the timeout from 45 s to 90 s as
  10. belt-and-braces for slow transitions that also don't emit an early subtask_id
  11. tick.
  12. """
  13. from types import SimpleNamespace
  14. from unittest.mock import AsyncMock, MagicMock, patch
  15. import pytest
  16. from backend.app.models.print_queue import PrintQueueItem
  17. from backend.app.services.print_scheduler import DISPATCH_MAX_ATTEMPTS, PrintScheduler
  18. @pytest.fixture
  19. async def db_session():
  20. """In-memory SQLite with one ``printing`` queue item at id=1."""
  21. from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine
  22. import backend.app.models # noqa: F401 — populate Base.metadata
  23. from backend.app.core.database import Base
  24. engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False)
  25. async with engine.begin() as conn:
  26. await conn.run_sync(Base.metadata.create_all)
  27. session_maker = async_sessionmaker(engine, expire_on_commit=False)
  28. async with session_maker() as db:
  29. db.add(PrintQueueItem(id=1, printer_id=42, archive_id=99, status="printing"))
  30. await db.commit()
  31. try:
  32. yield session_maker
  33. finally:
  34. await engine.dispose()
  35. def _status(state: str, subtask_id: str | None = None, gcode_file: str | None = None):
  36. """Minimal stand-in for PrinterState — only the fields the watchdog reads."""
  37. return SimpleNamespace(state=state, subtask_id=subtask_id, gcode_file=gcode_file)
  38. class TestWatchdogExitsEarlyOnPickup:
  39. """The watchdog must NOT revert when the printer has clearly picked up the job."""
  40. @pytest.mark.asyncio
  41. async def test_exits_on_state_change(self, db_session):
  42. """State transitioning away from pre_state is the primary "accepted" signal."""
  43. get_status = MagicMock(return_value=_status("RUNNING", "OLD_SUBTASK"))
  44. with (
  45. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  46. patch("backend.app.services.print_scheduler.async_session", db_session),
  47. ):
  48. await PrintScheduler._watchdog_print_start(
  49. queue_item_id=1,
  50. printer_id=42,
  51. pre_state="FINISH",
  52. pre_subtask_id="OLD_SUBTASK",
  53. timeout=0.3,
  54. poll_interval=0.05,
  55. )
  56. # Item should remain "printing" — watchdog recognised the pickup.
  57. async with db_session() as db:
  58. item = await db.get(PrintQueueItem, 1)
  59. assert item.status == "printing"
  60. @pytest.mark.asyncio
  61. async def test_h2d_finish_to_running_via_subtask_id_then_active_state(self, db_session):
  62. """Regression for #1078 (preserved through the two-phase rewrite for #1678):
  63. H2D keeps state=FINISH for ~50 s after accepting project_file, but
  64. subtask_id flips to our new submission_id almost immediately. The
  65. watchdog must NOT revert on the basis of state staying at FINISH —
  66. Phase A exits on the subtask_id advance, Phase B then keeps watching
  67. and exits SUCCESS as soon as the printer transitions to PREPARE /
  68. RUNNING within the longer Phase B window.
  69. """
  70. # First poll: state still FINISH, subtask_id advanced (Phase A → B).
  71. # Second poll: state has flipped to RUNNING (Phase B success).
  72. get_status = MagicMock(
  73. side_effect=[
  74. _status("FINISH", "NEW_SUBTASK_12345"),
  75. _status("RUNNING", "NEW_SUBTASK_12345"),
  76. ]
  77. + [_status("RUNNING", "NEW_SUBTASK_12345")] * 10,
  78. )
  79. with (
  80. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  81. patch("backend.app.services.print_scheduler.async_session", db_session),
  82. ):
  83. await PrintScheduler._watchdog_print_start(
  84. queue_item_id=1,
  85. printer_id=42,
  86. pre_state="FINISH",
  87. pre_subtask_id="OLD_SUBTASK_99999",
  88. timeout=0.3,
  89. phase_b_timeout=0.3,
  90. poll_interval=0.05,
  91. )
  92. async with db_session() as db:
  93. item = await db.get(PrintQueueItem, 1)
  94. assert item.status == "printing", (
  95. "Phase A exit on subtask_id advance + Phase B observing the "
  96. "active-state transition is the H2D success path — watchdog "
  97. "must keep the item 'printing' (#1078)"
  98. )
  99. class TestWatchdogRevertsWhenStuck:
  100. """Genuine half-broken sessions still need the revert + reconnect recovery."""
  101. @pytest.mark.asyncio
  102. async def test_reverts_when_neither_state_nor_subtask_id_changes(self, db_session):
  103. """Both signals unchanged across the full timeout → revert to pending
  104. and force MQTT reconnect (the #967 recovery path)."""
  105. get_status = MagicMock(return_value=_status("FINISH", "OLD_SUBTASK"))
  106. client = MagicMock()
  107. get_client = MagicMock(return_value=client)
  108. with (
  109. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  110. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  111. patch("backend.app.services.print_scheduler.async_session", db_session),
  112. patch("backend.app.core.database.async_session", db_session),
  113. ):
  114. await PrintScheduler._watchdog_print_start(
  115. queue_item_id=1,
  116. printer_id=42,
  117. pre_state="FINISH",
  118. pre_subtask_id="OLD_SUBTASK",
  119. timeout=0.2,
  120. poll_interval=0.05,
  121. )
  122. async with db_session() as db:
  123. item = await db.get(PrintQueueItem, 1)
  124. assert item.status == "pending"
  125. assert item.started_at is None
  126. client.force_reconnect_stale_session.assert_called_once()
  127. @pytest.mark.asyncio
  128. async def test_reverts_on_finish_to_idle_user_dismissed_prompt(self, db_session):
  129. """Regression for #1370: when pre_state is FINISH and the printer
  130. transitions to IDLE during the watchdog window, that's the user
  131. dismissing a post-print prompt — NOT acceptance of our project_file.
  132. The bundle in #1370 showed exactly this: queue item dispatched while
  133. printer was in FINISH (residual from a previous print), command sent
  134. but silently rejected by firmware, then the user manually cleared
  135. the screen prompt so the printer moved to IDLE. The original
  136. ``state != pre_state`` check returned early on this transition and
  137. the queue row was left stuck in 'printing' indefinitely, blocking
  138. all future dispatches to that printer.
  139. The watchdog now only treats transitions into the active-print
  140. state set (PREPARE / SLICING / RUNNING / PAUSE) as a valid "command
  141. landed" signal.
  142. """
  143. get_status = MagicMock(return_value=_status("IDLE", "OLD_SUBTASK"))
  144. client = MagicMock()
  145. get_client = MagicMock(return_value=client)
  146. with (
  147. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  148. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  149. patch("backend.app.services.print_scheduler.async_session", db_session),
  150. patch("backend.app.core.database.async_session", db_session),
  151. ):
  152. await PrintScheduler._watchdog_print_start(
  153. queue_item_id=1,
  154. printer_id=42,
  155. pre_state="FINISH",
  156. pre_subtask_id="OLD_SUBTASK",
  157. timeout=0.2,
  158. poll_interval=0.05,
  159. )
  160. async with db_session() as db:
  161. item = await db.get(PrintQueueItem, 1)
  162. assert item.status == "pending", (
  163. "FINISH -> IDLE is the user dismissing a screen prompt, not "
  164. "the printer accepting project_file — item must be reverted "
  165. "to 'pending' so the scheduler can retry (#1370)"
  166. )
  167. assert item.started_at is None
  168. @pytest.mark.asyncio
  169. async def test_does_not_revert_on_pickup_via_active_state(self, db_session):
  170. """Counterpart to the #1370 fix: transitions into the active-print
  171. state set ARE a valid "command landed" signal. PREPARE / SLICING /
  172. RUNNING / PAUSE all keep the item in 'printing'.
  173. """
  174. for active_state in ("PREPARE", "SLICING", "RUNNING", "PAUSE"):
  175. async with db_session() as db:
  176. item = await db.get(PrintQueueItem, 1)
  177. item.status = "printing"
  178. item.started_at = None
  179. await db.commit()
  180. get_status = MagicMock(return_value=_status(active_state, "OLD_SUBTASK"))
  181. with (
  182. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  183. patch("backend.app.services.print_scheduler.async_session", db_session),
  184. patch("backend.app.core.database.async_session", db_session),
  185. ):
  186. await PrintScheduler._watchdog_print_start(
  187. queue_item_id=1,
  188. printer_id=42,
  189. pre_state="IDLE",
  190. pre_subtask_id="OLD_SUBTASK",
  191. timeout=0.2,
  192. poll_interval=0.05,
  193. )
  194. async with db_session() as db:
  195. item = await db.get(PrintQueueItem, 1)
  196. assert item.status == "printing", (
  197. f"transition IDLE -> {active_state} must be treated as a "
  198. f"valid 'command landed' signal — watchdog must not revert"
  199. )
  200. @pytest.mark.asyncio
  201. async def test_default_timeout_is_90_seconds(self):
  202. """The default timeout must cover slow H2D FINISH→PREPARE transitions
  203. (~50 s observed). A 45 s default would trip on the exact scenario the
  204. subtask_id check is guarding against, leaving no fallback for printers
  205. that don't echo subtask_id."""
  206. import inspect
  207. sig = inspect.signature(PrintScheduler._watchdog_print_start)
  208. assert sig.parameters["timeout"].default == 90.0
  209. @pytest.mark.asyncio
  210. async def test_default_phase_b_timeout_is_180_seconds(self):
  211. """Phase B (subtask_id advanced, waiting for active state) must
  212. comfortably exceed the H2D FINISH→PREPARE delay (~50 s observed)
  213. before declaring a printer-side wedge. 180 s gives ~3.5× headroom
  214. and reverts the queue item in well under the previous 2-hour
  215. expected_print TTL (#1678)."""
  216. import inspect
  217. sig = inspect.signature(PrintScheduler._watchdog_print_start)
  218. assert sig.parameters["phase_b_timeout"].default == 180.0
  219. @pytest.mark.asyncio
  220. async def test_reverts_when_subtask_advanced_but_state_never_active(self, db_session):
  221. """Regression for #1678: P1S on old firmware, power-cycled mid-print,
  222. cloud+LAN re-auth dance in flight. Printer accepts project_file
  223. (gcode_file updates, subtask_id advances to our submission id) but
  224. never transitions from IDLE/FINISH to PREPARE/RUNNING. The pre-fix
  225. watchdog returned SUCCESS as soon as subtask_id advanced and the
  226. queue item stayed in 'printing' until container restart. Phase B now
  227. keeps watching; if the active-state transition never arrives, the
  228. item reverts to 'pending' so the user can retry without restarting.
  229. """
  230. get_status = MagicMock(
  231. return_value=_status("IDLE", "NEW_SUBTASK_12345", gcode_file="/new.3mf"),
  232. )
  233. client = MagicMock() # NOT None — must verify reconnect isn't called
  234. get_client = MagicMock(return_value=client)
  235. with (
  236. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  237. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  238. patch("backend.app.services.print_scheduler.async_session", db_session),
  239. patch("backend.app.core.database.async_session", db_session),
  240. ):
  241. await PrintScheduler._watchdog_print_start(
  242. queue_item_id=1,
  243. printer_id=42,
  244. pre_state="IDLE",
  245. pre_subtask_id="OLD_SUBTASK_99999",
  246. pre_gcode_file="/old.3mf",
  247. timeout=0.2,
  248. phase_b_timeout=0.2,
  249. poll_interval=0.05,
  250. )
  251. async with db_session() as db:
  252. item = await db.get(PrintQueueItem, 1)
  253. assert item.status == "pending", (
  254. "subtask_id advanced (Phase A → B) but state never reached an "
  255. "active value — printer-side wedge; the queue item must be "
  256. "reverted to 'pending' (#1678)"
  257. )
  258. assert item.started_at is None
  259. # File landed (subtask_id advance proves this), so a forced reconnect
  260. # would trigger 0500_4003 mid-parse (#1150) — skip.
  261. client.force_reconnect_stale_session.assert_not_called()
  262. class TestWatchdogFallbackBehaviour:
  263. """Backwards-compat and defensive behaviour around missing data."""
  264. @pytest.mark.asyncio
  265. async def test_pre_subtask_id_none_falls_back_to_state_only(self, db_session):
  266. """When we never captured a pre-dispatch subtask_id (e.g. printer just
  267. connected), the watchdog must still work on the state signal alone —
  268. and still revert when state stays unchanged, so half-broken sessions
  269. are still recovered."""
  270. get_status = MagicMock(return_value=_status("FINISH", "SOMETHING"))
  271. get_client = MagicMock(return_value=None)
  272. with (
  273. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  274. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  275. patch("backend.app.services.print_scheduler.async_session", db_session),
  276. patch("backend.app.core.database.async_session", db_session),
  277. ):
  278. await PrintScheduler._watchdog_print_start(
  279. queue_item_id=1,
  280. printer_id=42,
  281. pre_state="FINISH",
  282. pre_subtask_id=None,
  283. timeout=0.2,
  284. poll_interval=0.05,
  285. )
  286. async with db_session() as db:
  287. item = await db.get(PrintQueueItem, 1)
  288. assert item.status == "pending"
  289. @pytest.mark.asyncio
  290. async def test_current_subtask_id_none_does_not_trigger_early_exit(self, db_session):
  291. """If the printer transiently reports subtask_id=None (e.g. during
  292. reconnect), that must not be treated as "changed" — otherwise the
  293. watchdog would exit early without a real pickup signal and leave the
  294. item stuck in "printing" after a genuinely broken session."""
  295. get_status = MagicMock(return_value=_status("FINISH", None))
  296. get_client = MagicMock(return_value=None)
  297. with (
  298. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  299. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  300. patch("backend.app.services.print_scheduler.async_session", db_session),
  301. patch("backend.app.core.database.async_session", db_session),
  302. ):
  303. await PrintScheduler._watchdog_print_start(
  304. queue_item_id=1,
  305. printer_id=42,
  306. pre_state="FINISH",
  307. pre_subtask_id="OLD_SUBTASK",
  308. timeout=0.2,
  309. poll_interval=0.05,
  310. )
  311. async with db_session() as db:
  312. item = await db.get(PrintQueueItem, 1)
  313. assert item.status == "pending"
  314. @pytest.mark.asyncio
  315. async def test_printer_disconnected_returns_without_reverting(self, db_session):
  316. """If the printer drops during the watchdog window, don't touch the DB —
  317. the reconnect path will sort the queue state out."""
  318. get_status = MagicMock(return_value=None)
  319. with (
  320. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  321. patch("backend.app.services.print_scheduler.async_session", db_session),
  322. ):
  323. await PrintScheduler._watchdog_print_start(
  324. queue_item_id=1,
  325. printer_id=42,
  326. pre_state="FINISH",
  327. pre_subtask_id="OLD_SUBTASK",
  328. timeout=0.2,
  329. poll_interval=0.05,
  330. )
  331. async with db_session() as db:
  332. item = await db.get(PrintQueueItem, 1)
  333. assert item.status == "printing"
  334. @pytest.mark.asyncio
  335. async def test_no_revert_if_item_already_completed(self, db_session):
  336. """If the print completed between watchdog arm-time and timeout (item is
  337. no longer "printing"), the watchdog must not clobber whatever status it
  338. ended up in — #967 race guard. Additionally it must NOT run the MQTT
  339. session-recovery path (forced reconnect): when on_print_complete has
  340. already moved the row, the print clearly landed on the printer and a
  341. forced reconnect on a healthy session would break ongoing prints on
  342. the same printer.
  343. """
  344. # Move item on to "completed" before the watchdog fires.
  345. async with db_session() as db:
  346. item = await db.get(PrintQueueItem, 1)
  347. item.status = "completed"
  348. await db.commit()
  349. get_status = MagicMock(return_value=_status("FINISH", "OLD_SUBTASK"))
  350. client = MagicMock() # NOT None — must verify reconnect isn't called
  351. get_client = MagicMock(return_value=client)
  352. with (
  353. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  354. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  355. patch("backend.app.services.print_scheduler.async_session", db_session),
  356. patch("backend.app.core.database.async_session", db_session),
  357. ):
  358. await PrintScheduler._watchdog_print_start(
  359. queue_item_id=1,
  360. printer_id=42,
  361. pre_state="FINISH",
  362. pre_subtask_id="OLD_SUBTASK",
  363. timeout=0.2,
  364. poll_interval=0.05,
  365. )
  366. async with db_session() as db:
  367. item = await db.get(PrintQueueItem, 1)
  368. assert item.status == "completed" # untouched
  369. client.force_reconnect_stale_session.assert_not_called()
  370. class TestGcodeFileDiscriminator:
  371. """#1150 vs #887/#936: skip the forced reconnect when gcode_file changed
  372. (project_file landed, slow parse — reconnecting causes 0500_4003).
  373. Reconnect when gcode_file is unchanged (publish dropped — half-broken
  374. session needs the original recovery)."""
  375. @pytest.mark.asyncio
  376. async def test_skips_reconnect_when_gcode_file_changed(self, db_session):
  377. get_status = MagicMock(
  378. return_value=_status("FINISH", "OLD_SUBTASK", gcode_file="/new.3mf"),
  379. )
  380. client = MagicMock()
  381. get_client = MagicMock(return_value=client)
  382. with (
  383. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  384. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  385. patch("backend.app.services.print_scheduler.async_session", db_session),
  386. patch("backend.app.core.database.async_session", db_session),
  387. ):
  388. await PrintScheduler._watchdog_print_start(
  389. queue_item_id=1,
  390. printer_id=42,
  391. pre_state="FINISH",
  392. pre_subtask_id="OLD_SUBTASK",
  393. pre_gcode_file="/old.3mf",
  394. timeout=0.2,
  395. poll_interval=0.05,
  396. )
  397. # Item still reverts (the user-facing failure stays correct), but the
  398. # MQTT session is left intact so the slow printer can finish parsing.
  399. async with db_session() as db:
  400. item = await db.get(PrintQueueItem, 1)
  401. assert item.status == "pending"
  402. client.force_reconnect_stale_session.assert_not_called()
  403. @pytest.mark.asyncio
  404. async def test_reconnects_when_gcode_file_unchanged(self, db_session):
  405. get_status = MagicMock(
  406. return_value=_status("FINISH", "OLD_SUBTASK", gcode_file="/old.3mf"),
  407. )
  408. client = MagicMock()
  409. get_client = MagicMock(return_value=client)
  410. with (
  411. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  412. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  413. patch("backend.app.services.print_scheduler.async_session", db_session),
  414. patch("backend.app.core.database.async_session", db_session),
  415. ):
  416. await PrintScheduler._watchdog_print_start(
  417. queue_item_id=1,
  418. printer_id=42,
  419. pre_state="FINISH",
  420. pre_subtask_id="OLD_SUBTASK",
  421. pre_gcode_file="/old.3mf",
  422. timeout=0.2,
  423. poll_interval=0.05,
  424. )
  425. client.force_reconnect_stale_session.assert_called_once()
  426. class TestWatchdogRetryBudget:
  427. """A revert hands the item straight back to the next queue pass, which
  428. re-uploads the whole 3MF and waits the watchdog out again. For a printer
  429. that is genuinely wedged that loop never terminates — the #2555 reporter had
  430. one printer "since this morning still not launch" — and every lap also burns
  431. an upload slot the rest of the farm is queueing for. Retrying is right;
  432. retrying forever is not.
  433. """
  434. @staticmethod
  435. async def _wedge(db_session, *, item_id: int = 1):
  436. """Run one watchdog cycle against a printer that accepts but never starts."""
  437. get_status = MagicMock(return_value=_status("IDLE", "NEW_SUBTASK", gcode_file="/new.3mf"))
  438. get_client = MagicMock(return_value=MagicMock())
  439. with (
  440. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  441. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  442. patch("backend.app.services.print_scheduler.async_session", db_session),
  443. patch("backend.app.core.database.async_session", db_session),
  444. patch(
  445. "backend.app.services.notification_service.notification_service.on_queue_job_failed",
  446. AsyncMock(),
  447. ) as notify,
  448. ):
  449. await PrintScheduler._watchdog_print_start(
  450. queue_item_id=item_id,
  451. printer_id=42,
  452. pre_state="IDLE",
  453. pre_subtask_id="OLD_SUBTASK",
  454. pre_gcode_file="/old.3mf",
  455. timeout=0.2,
  456. phase_b_timeout=0.2,
  457. poll_interval=0.05,
  458. )
  459. return notify
  460. @pytest.mark.asyncio
  461. async def test_early_wedges_still_revert_for_retry(self, db_session):
  462. """Attempts below the budget must keep the existing #1678 behaviour.
  463. The transient causes are real and the watchdog already recovers from
  464. them (a publish lost on a half-broken session is fixed by the forced
  465. reconnect on the very next attempt), so the first wedges must not fail
  466. the job.
  467. """
  468. await self._wedge(db_session)
  469. async with db_session() as db:
  470. item = await db.get(PrintQueueItem, 1)
  471. assert item.status == "pending", "first wedge must still be retried"
  472. assert item.dispatch_attempts == 1
  473. assert item.started_at is None
  474. @pytest.mark.asyncio
  475. async def test_attempts_accumulate_across_wedges(self, db_session):
  476. """The counter is what bounds the loop, so it must survive the revert."""
  477. for expected in (1, 2):
  478. # Each pass starts from a fresh dispatch, i.e. the row is 'printing' again.
  479. async with db_session() as db:
  480. item = await db.get(PrintQueueItem, 1)
  481. item.status = "printing"
  482. await db.commit()
  483. await self._wedge(db_session)
  484. async with db_session() as db:
  485. item = await db.get(PrintQueueItem, 1)
  486. assert item.dispatch_attempts == expected
  487. assert item.status == "pending"
  488. @pytest.mark.asyncio
  489. async def test_gives_up_and_fails_the_item_at_the_budget(self, db_session):
  490. """The third wedge fails the row instead of queueing a fourth re-upload."""
  491. notify = None
  492. for _ in range(DISPATCH_MAX_ATTEMPTS):
  493. async with db_session() as db:
  494. item = await db.get(PrintQueueItem, 1)
  495. item.status = "printing"
  496. await db.commit()
  497. notify = await self._wedge(db_session)
  498. async with db_session() as db:
  499. item = await db.get(PrintQueueItem, 1)
  500. assert item.status == "failed", f"after {DISPATCH_MAX_ATTEMPTS} wedges the item must stop going round again"
  501. assert item.dispatch_attempts == DISPATCH_MAX_ATTEMPTS
  502. assert item.completed_at is not None
  503. # The message has to tell the user where to look — the fault is on
  504. # the printer, and no amount of retrying from our side will fix it.
  505. assert "never started printing" in item.error_message
  506. notify.assert_awaited_once()
  507. @pytest.mark.asyncio
  508. async def test_a_successful_start_never_touches_the_counter(self, db_session):
  509. """Only the revert path increments. A printer that picks the job up
  510. must not accumulate attempts towards a future give-up."""
  511. get_status = MagicMock(return_value=_status("RUNNING", "NEW_SUBTASK"))
  512. with (
  513. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  514. patch("backend.app.services.print_scheduler.async_session", db_session),
  515. patch("backend.app.core.database.async_session", db_session),
  516. ):
  517. await PrintScheduler._watchdog_print_start(
  518. queue_item_id=1,
  519. printer_id=42,
  520. pre_state="IDLE",
  521. pre_subtask_id="OLD_SUBTASK",
  522. timeout=0.2,
  523. poll_interval=0.05,
  524. )
  525. async with db_session() as db:
  526. item = await db.get(PrintQueueItem, 1)
  527. assert item.status == "printing"
  528. assert item.dispatch_attempts == 0
  529. class TestWatchdogCommandRejected:
  530. """A printer reporting HMS 0500_0500_0001_0007 refused the command outright.
  531. It is not wedged and it is not slow: its authorization check rejected a
  532. command it could not verify, and it will reject the next two identically.
  533. Spending the full 270 s and two more full 3MF uploads on that is 15 minutes
  534. of a farm's upload capacity buying nothing, and it ends with a message about
  535. SD cards (#2732).
  536. """
  537. @staticmethod
  538. def _rejected_status(state: str = "IDLE", subtask_id: str | None = "NEW_SUBTASK"):
  539. from backend.app.services.bambu_mqtt import HMS_MQTT_VERIFY_FAILED
  540. return SimpleNamespace(
  541. state=state,
  542. subtask_id=subtask_id,
  543. gcode_file="/new.3mf",
  544. hms_errors=[SimpleNamespace(full_code=HMS_MQTT_VERIFY_FAILED)],
  545. )
  546. @staticmethod
  547. async def _run(db_session, status):
  548. get_status = MagicMock(return_value=status)
  549. get_client = MagicMock(return_value=MagicMock())
  550. with (
  551. patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
  552. patch("backend.app.services.print_scheduler.printer_manager.get_client", get_client),
  553. patch("backend.app.services.print_scheduler.async_session", db_session),
  554. patch("backend.app.core.database.async_session", db_session),
  555. patch(
  556. "backend.app.services.notification_service.notification_service.on_queue_job_failed",
  557. AsyncMock(),
  558. ) as notify,
  559. ):
  560. await PrintScheduler._watchdog_print_start(
  561. queue_item_id=1,
  562. printer_id=42,
  563. pre_state="IDLE",
  564. pre_subtask_id="OLD_SUBTASK",
  565. pre_gcode_file="/old.3mf",
  566. timeout=0.2,
  567. phase_b_timeout=0.2,
  568. poll_interval=0.05,
  569. )
  570. return get_client, notify
  571. @pytest.mark.asyncio
  572. async def test_fails_on_the_first_attempt(self, db_session):
  573. await self._run(db_session, self._rejected_status())
  574. async with db_session() as db:
  575. item = await db.get(PrintQueueItem, 1)
  576. assert item.status == "failed", "a refused command must not be retried"
  577. assert item.dispatch_attempts == 1, "it must not burn the whole budget"
  578. assert item.completed_at is not None
  579. @pytest.mark.asyncio
  580. async def test_error_message_names_the_fix(self, db_session):
  581. """The old wording sent this user to check their SD card."""
  582. await self._run(db_session, self._rejected_status())
  583. async with db_session() as db:
  584. item = await db.get(PrintQueueItem, 1)
  585. assert "0500-0500-0001-0007" in item.error_message
  586. assert "Developer Mode" in item.error_message
  587. assert "SD card" not in item.error_message
  588. @pytest.mark.asyncio
  589. async def test_detected_in_phase_a_before_any_subtask_advance(self, db_session):
  590. """The printer can refuse without ever echoing a subtask_id."""
  591. await self._run(db_session, self._rejected_status(subtask_id="OLD_SUBTASK"))
  592. async with db_session() as db:
  593. item = await db.get(PrintQueueItem, 1)
  594. assert item.status == "failed"
  595. assert item.dispatch_attempts == 1
  596. @pytest.mark.asyncio
  597. async def test_skips_the_forced_reconnect(self, db_session):
  598. """The MQTT session is fine — reconnecting would only add 0500_4003 (#1150)."""
  599. get_client, _ = await self._run(db_session, self._rejected_status(subtask_id="OLD_SUBTASK"))
  600. get_client.assert_not_called()
  601. @pytest.mark.asyncio
  602. async def test_notifies_with_the_rejection_reason(self, db_session):
  603. _, notify = await self._run(db_session, self._rejected_status())
  604. notify.assert_awaited_once()
  605. assert "rejected" in notify.await_args.kwargs["reason"]
  606. @pytest.mark.asyncio
  607. async def test_unrelated_hms_still_takes_the_retry_path(self, db_session):
  608. """Only this code short-circuits; every other fault keeps its retries."""
  609. status = self._rejected_status()
  610. status.hms_errors = [SimpleNamespace(full_code="0300020000018012")]
  611. await self._run(db_session, status)
  612. async with db_session() as db:
  613. item = await db.get(PrintQueueItem, 1)
  614. assert item.status == "pending"
  615. assert item.dispatch_attempts == 1
  616. @pytest.mark.asyncio
  617. async def test_a_printer_that_actually_starts_is_unaffected(self, db_session):
  618. """A stale HMS from a previous job must not kill a print that is running."""
  619. await self._run(db_session, self._rejected_status(state="RUNNING"))
  620. async with db_session() as db:
  621. item = await db.get(PrintQueueItem, 1)
  622. assert item.status == "printing"
  623. assert item.dispatch_attempts == 0