test_run_lifecycle.py 50 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720721722723724725726727728729730731732733734735736737738739740741742743744745746747748749750751752753754755756757758759760761762763764765766767768769770771772773774775776777778779780781782783784785786787788789790791792793794795796797798799800801802803804805806807808809810811812813814815816817818819820821822823824825826827828829830831832833834835836837838839840841842843844845846847848849850851852853854855856857858859860861862863864865866867868869870871872873874875876877878879880881882883884885886887888889890891892893894895896897898899900901902903904905906907908909910911912913914915916917918919920921922923924925926927928929930931932933934935936937938939940941942943944945946947948949950951952953954955956957958959960961962963964965966967968969970971972973974975976977978979980981982983984985986987988989990991992993994995996997998999100010011002100310041005100610071008100910101011101210131014101510161017101810191020102110221023102410251026102710281029103010311032103310341035103610371038103910401041104210431044104510461047104810491050105110521053105410551056105710581059106010611062106310641065106610671068106910701071107210731074107510761077107810791080108110821083108410851086108710881089109010911092109310941095109610971098109911001101110211031104110511061107110811091110111111121113111411151116111711181119112011211122112311241125112611271128112911301131113211331134113511361137113811391140114111421143114411451146114711481149115011511152115311541155115611571158115911601161116211631164116511661167116811691170117111721173117411751176117711781179
  1. """Every print of an archive keeps its own record, start to end (archive redesign P0).
  2. The archive redesign moves what describes one print -- status, times, plate,
  3. failure reason, charge -- from the archive onto the run. These tests drive
  4. real print starts and completions against the database and pin what each run
  5. records today, so every step of the move is checked against the same outcome.
  6. They assert on the print log first; what the archive row shows is pinned
  7. where the archive page reads it today, and changes there are meant to be
  8. made here on purpose.
  9. """
  10. from __future__ import annotations
  11. import asyncio
  12. from types import SimpleNamespace
  13. import pytest
  14. from sqlalchemy import func, select
  15. from backend.app import main as main_module
  16. from backend.app.main import register_expected_print
  17. from backend.app.models.archive import PrintArchive
  18. from backend.app.models.finance import CostCenter, WalletTransaction
  19. from backend.app.models.print_log import PrintLogEntry
  20. from backend.app.models.print_queue import PrintQueueItem
  21. from backend.app.models.settings import Settings
  22. from backend.app.models.user import User
  23. from backend.tests.integration.test_external_print_confirmation_1898 import ( # noqa: F401
  24. SUBTASK,
  25. _clear_print_state,
  26. _drive_print_start,
  27. )
  28. from backend.tests.integration.test_print_complete_end_to_end import _complete as _complete_concurrently
  29. pytestmark = [pytest.mark.asyncio, pytest.mark.integration]
  30. FILE = f"{SUBTASK}.gcode.3mf"
  31. async def _complete(test_engine, printer_id: int, status: str, name: str, extra: dict | None = None):
  32. """``on_print_complete`` with its background work run one task at a time.
  33. The SQLite test database is one shared connection, so tasks writing at
  34. the same time fail each other ("cannot commit transaction - SQL
  35. statements in progress"), which a real database does not. The finish
  36. photo is left out of the turn-taking: the notification task waits for it.
  37. """
  38. from unittest.mock import patch
  39. from backend.app.core.tasks import spawn_background_task
  40. turn = asyncio.Lock()
  41. async def in_turn(coro):
  42. async with turn:
  43. return await coro
  44. def spawn(coro, name=None, **kwargs):
  45. if name != "background-finish-photo":
  46. coro = in_turn(coro)
  47. return spawn_background_task(coro, name=name, **kwargs)
  48. with patch("backend.app.main.spawn_background_task", side_effect=spawn):
  49. return await _complete_concurrently(test_engine, printer_id, status, name=name, extra=extra)
  50. @pytest.fixture(autouse=True)
  51. def _clean():
  52. from backend.app.services.printer_manager import printer_manager
  53. main_module._print_plate_ids.clear()
  54. main_module._archive_runs_finishing.clear()
  55. yield
  56. main_module._print_plate_ids.clear()
  57. main_module._archive_runs_finishing.clear()
  58. printer_manager._awaiting_plate_clear.clear()
  59. @pytest.fixture
  60. async def farm(db_session, printer_factory):
  61. """A printer, a user paying from a cost centre, and an archive of a
  62. multi-plate file printed before."""
  63. db_session.add_all(
  64. [Settings(key="capture_finish_photo", value="false"), Settings(key="billing_enabled", value="true")]
  65. )
  66. printer = await printer_factory(name="P")
  67. user = User(username="payer", password_hash="x", is_active=True)
  68. center = CostCenter(name="Lab", is_active=True, is_private=False)
  69. db_session.add_all([user, center])
  70. await db_session.flush()
  71. archive = PrintArchive(
  72. printer_id=printer.id,
  73. filename=FILE,
  74. file_path=f"archives/test/{FILE}",
  75. file_size=1,
  76. print_name=SUBTASK,
  77. status="completed",
  78. cost=5.0,
  79. created_by_id=user.id,
  80. )
  81. db_session.add(archive)
  82. await db_session.commit()
  83. return SimpleNamespace(printer=printer.id, user=user.id, center=center.id, archive=archive.id)
  84. async def _run(test_engine, db_session, farm, *, plate: int, status: str, run_id: str) -> int:
  85. """One queued print of the archive's plate, from dispatch to its end.
  86. Returns the queue item's id."""
  87. item = PrintQueueItem(
  88. printer_id=farm.printer,
  89. archive_id=farm.archive,
  90. status="printing",
  91. position=1,
  92. plate_id=plate,
  93. created_by_id=farm.user,
  94. cost_center_id=farm.center,
  95. estimated_cost=5.0,
  96. billing_run_id=run_id,
  97. )
  98. db_session.add(item)
  99. # As the scheduler's dispatch writes it (_start_print).
  100. (await db_session.get(PrintArchive, farm.archive)).plate_id = plate
  101. await db_session.commit()
  102. item_id = item.id
  103. register_expected_print(farm.printer, FILE, farm.archive, plate_id=plate, cost_center_id=farm.center)
  104. await _drive_print_start(test_engine, SimpleNamespace(id=farm.printer), download_ok=False)
  105. await _complete(test_engine, farm.printer, status, name=SUBTASK)
  106. return item_id
  107. async def _runs(db_session, archive_id: int) -> list[PrintLogEntry]:
  108. db_session.expire_all()
  109. return list(
  110. (
  111. await db_session.scalars(
  112. select(PrintLogEntry).where(PrintLogEntry.archive_id == archive_id).order_by(PrintLogEntry.id)
  113. )
  114. ).all()
  115. )
  116. async def test_a_queued_print_of_an_archive_is_one_run_on_it(test_engine, db_session, farm):
  117. item = await _run(test_engine, db_session, farm, plate=1, status="completed", run_id="run-1")
  118. runs = await _runs(db_session, farm.archive)
  119. assert [(r.status, r.plate_id, r.queue_item_id, r.printer_id) for r in runs] == [
  120. ("completed", 1, item, farm.printer)
  121. ]
  122. assert runs[0].started_at is not None and runs[0].completed_at is not None
  123. assert runs[0].completed_at >= runs[0].started_at
  124. archive = await db_session.get(PrintArchive, farm.archive)
  125. assert (archive.status, archive.plate_id) == ("completed", 1)
  126. assert await db_session.scalar(select(func.count()).select_from(PrintArchive)) == 1
  127. async def test_each_run_keeps_its_own_plate_outcome_and_times(test_engine, db_session, farm):
  128. """Plate 1 fails, then plate 2 prints: neither run takes the other's."""
  129. first = await _run(test_engine, db_session, farm, plate=1, status="failed", run_id="run-1")
  130. second = await _run(test_engine, db_session, farm, plate=2, status="completed", run_id="run-2")
  131. runs = await _runs(db_session, farm.archive)
  132. assert [(r.status, r.plate_id, r.queue_item_id) for r in runs] == [
  133. ("failed", 1, first),
  134. ("completed", 2, second),
  135. ]
  136. assert runs[1].started_at >= runs[0].completed_at, "the second run's start is its own"
  137. assert runs[1].failure_reason is None, "a completed run carries no reason of the failed one"
  138. # The archive page shows the latest run.
  139. archive = await db_session.get(PrintArchive, farm.archive)
  140. assert (archive.status, archive.plate_id, archive.failure_reason) == ("completed", 2, None)
  141. async def test_each_run_is_charged_once_under_its_own_run_id(test_engine, db_session, farm):
  142. await _run(test_engine, db_session, farm, plate=1, status="completed", run_id="run-1")
  143. await _run(test_engine, db_session, farm, plate=2, status="completed", run_id="run-2")
  144. charges = (
  145. await db_session.scalars(
  146. select(WalletTransaction)
  147. .where(WalletTransaction.transaction_type == "print_charge")
  148. .order_by(WalletTransaction.id)
  149. )
  150. ).all()
  151. assert [(c.print_run_id, c.print_archive_id, c.cost_center_id) for c in charges] == [
  152. ("run-1", farm.archive, farm.center),
  153. ("run-2", farm.archive, farm.center),
  154. ]
  155. async def test_a_print_started_on_the_printer_is_an_archive_with_one_run(test_engine, db_session, printer_factory):
  156. db_session.add(Settings(key="capture_finish_photo", value="false"))
  157. await db_session.commit()
  158. printer_id = (await printer_factory(name="P")).id
  159. await _drive_print_start(test_engine, SimpleNamespace(id=printer_id), download_ok=False)
  160. archives = (await db_session.scalars(select(PrintArchive))).all()
  161. assert [r.status for r in await _all_runs(db_session, archives[0].id)] == ["printing"], "opened at its start"
  162. await _complete(test_engine, printer_id, "completed", name=SUBTASK)
  163. archives = (await db_session.scalars(select(PrintArchive))).all()
  164. assert len(archives) == 1
  165. runs = await _runs(db_session, archives[0].id)
  166. assert [(r.status, r.queue_item_id, r.printer_id) for r in runs] == [("completed", None, printer_id)]
  167. async def test_a_reported_end_after_an_offline_stop_replaces_the_run(test_engine, db_session, farm, async_client):
  168. """The stop could not reach the printer and logged the run as cancelled;
  169. the printer then reports how it really ended. Still one run."""
  170. from unittest.mock import AsyncMock, patch
  171. item = PrintQueueItem(
  172. printer_id=farm.printer,
  173. archive_id=farm.archive,
  174. status="printing",
  175. position=1,
  176. plate_id=2,
  177. created_by_id=farm.user,
  178. billing_run_id="run-1",
  179. )
  180. db_session.add(item)
  181. await db_session.commit()
  182. register_expected_print(farm.printer, FILE, farm.archive, plate_id=2)
  183. await _drive_print_start(test_engine, SimpleNamespace(id=farm.printer), download_ok=False)
  184. with (
  185. patch("backend.app.services.print_control.stop_print_by_user", return_value=False),
  186. patch("backend.app.api.routes.print_queue.ws_manager") as ws,
  187. ):
  188. ws.send_archive_updated = AsyncMock()
  189. assert (await async_client.post(f"/api/v1/queue/{item.id}/stop")).status_code == 200
  190. assert [(r.status, r.plate_id) for r in await _runs(db_session, farm.archive)] == [("cancelled", 2)]
  191. main_module._active_prints[(farm.printer, FILE)] = farm.archive
  192. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  193. assert [(r.status, r.plate_id) for r in await _runs(db_session, farm.archive)] == [("completed", 2)]
  194. async def test_each_run_gets_its_own_energy(test_engine, db_session, farm):
  195. """The plug's counter at each start and end: the archive card shows the
  196. first run's, each run its own."""
  197. from unittest.mock import AsyncMock, MagicMock, patch
  198. plug = MagicMock(id=1)
  199. plug.name = "Plug"
  200. counters = iter([10.5, 20.3])
  201. async def reading(candidates, read, db):
  202. return plug, {"total": next(counters)}
  203. async def started_at(kwh):
  204. archive = await db_session.get(PrintArchive, farm.archive)
  205. archive.energy_start_kwh = kwh
  206. await db_session.commit()
  207. with (
  208. patch("backend.app.main.energy_plug_candidates", AsyncMock(return_value=[plug])),
  209. patch("backend.app.main.select_energy_reading", side_effect=reading),
  210. patch("backend.app.services.energy_price.print_energy_cost", AsyncMock(return_value=0.1)),
  211. patch("backend.app.services.energy_price.current_price", AsyncMock(return_value=0.3)),
  212. ):
  213. for plate, kwh in ((1, 10.0), (2, 20.0)):
  214. item = PrintQueueItem(
  215. printer_id=farm.printer, archive_id=farm.archive, status="printing", position=1, plate_id=plate
  216. )
  217. db_session.add(item)
  218. await db_session.commit()
  219. register_expected_print(farm.printer, FILE, farm.archive, plate_id=plate)
  220. await _drive_print_start(test_engine, SimpleNamespace(id=farm.printer), download_ok=False)
  221. await started_at(kwh)
  222. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  223. runs = await _runs(db_session, farm.archive)
  224. assert [(r.plate_id, r.energy_kwh) for r in runs] == [(1, 0.5), (2, pytest.approx(0.3))]
  225. archive = await db_session.get(PrintArchive, farm.archive)
  226. assert archive.energy_kwh == 0.5
  227. async def test_each_run_keeps_its_own_verdict(test_engine, db_session, farm):
  228. """An answered outcome prompt belongs to its run; the next run asks again."""
  229. from backend.app.services.print_confirmation import apply_outcome_verdict
  230. archive = await db_session.get(PrintArchive, farm.archive)
  231. archive.confirm_requested = True
  232. await db_session.commit()
  233. await _run(test_engine, db_session, farm, plate=1, status="completed", run_id="run-1")
  234. archive = await db_session.get(PrintArchive, farm.archive)
  235. assert await apply_outcome_verdict(db_session, archive, "reject", source="dialog")
  236. await db_session.commit()
  237. await _run(test_engine, db_session, farm, plate=2, status="completed", run_id="run-2")
  238. runs = await _runs(db_session, farm.archive)
  239. assert [(r.plate_id, r.user_verdict) for r in runs] == [(1, "reject"), (2, None)]
  240. archive = await db_session.get(PrintArchive, farm.archive)
  241. assert archive.user_verdict is None, "the latest run is not judged yet"
  242. async def _all_runs(db_session, archive_id: int) -> list[PrintLogEntry]:
  243. from backend.app.models.print_log import INCLUDE_OPEN_RUNS
  244. db_session.expire_all()
  245. return list(
  246. (
  247. await db_session.scalars(
  248. select(PrintLogEntry)
  249. .where(PrintLogEntry.archive_id == archive_id)
  250. .order_by(PrintLogEntry.id)
  251. .execution_options(**{INCLUDE_OPEN_RUNS: True})
  252. )
  253. ).all()
  254. )
  255. async def _start_queued(test_engine, db_session, farm, *, plate: int, run_id: str) -> int:
  256. item = PrintQueueItem(
  257. printer_id=farm.printer,
  258. archive_id=farm.archive,
  259. status="printing",
  260. position=1,
  261. plate_id=plate,
  262. created_by_id=farm.user,
  263. cost_center_id=farm.center,
  264. billing_run_id=run_id,
  265. )
  266. db_session.add(item)
  267. (await db_session.get(PrintArchive, farm.archive)).plate_id = plate
  268. await db_session.commit()
  269. register_expected_print(farm.printer, FILE, farm.archive, plate_id=plate, cost_center_id=farm.center)
  270. await _drive_print_start(test_engine, SimpleNamespace(id=farm.printer), download_ok=False)
  271. return item.id
  272. async def test_the_run_is_written_when_the_print_starts(test_engine, db_session, farm, async_client):
  273. """Open, it is in no statistic, log or count; its end fills in the same run."""
  274. item = await _start_queued(test_engine, db_session, farm, plate=2, run_id="run-1")
  275. [run] = await _all_runs(db_session, farm.archive)
  276. assert (run.status, run.plate_id, run.queue_item_id, run.billing_run_id, run.cost_center_id, run.printer_id) == (
  277. "printing",
  278. 2,
  279. item,
  280. "run-1",
  281. farm.center,
  282. farm.printer,
  283. )
  284. archive = await db_session.get(PrintArchive, farm.archive)
  285. assert run.started_at == archive.started_at
  286. assert await _runs(db_session, farm.archive) == [], "an open run is not a print that happened"
  287. log = (await async_client.get("/api/v1/print-log/")).json()
  288. assert log["total"] == 0 and log["items"] == []
  289. stats = (await async_client.get("/api/v1/archives/stats")).json()
  290. assert stats["total_prints"] == 0
  291. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  292. assert [(r.id, r.status, r.plate_id) for r in await _all_runs(db_session, farm.archive)] == [
  293. (run.id, "completed", 2)
  294. ]
  295. async def test_a_print_start_seen_again_opens_no_second_run(test_engine, db_session, farm):
  296. """A restart resumes the running print: the run it opened stays the one."""
  297. await _start_queued(test_engine, db_session, farm, plate=1, run_id="run-1")
  298. archive = await db_session.get(PrintArchive, farm.archive)
  299. archive.subtask_id = "job-7"
  300. await db_session.commit()
  301. main_module._active_prints.clear()
  302. await _drive_print_start(
  303. test_engine,
  304. SimpleNamespace(id=farm.printer),
  305. download_ok=False,
  306. state_fields={"subtask_id": "job-7", "progress": 50.0},
  307. )
  308. assert await db_session.scalar(select(func.count()).select_from(PrintArchive)) == 1, "resumed, not archived anew"
  309. assert [r.status for r in await _all_runs(db_session, farm.archive)] == ["printing"]
  310. async def test_the_runs_energy_start_is_its_own(test_engine, db_session, farm):
  311. from unittest.mock import AsyncMock, MagicMock, patch
  312. from backend.app.main import _record_energy_start
  313. await _start_queued(test_engine, db_session, farm, plate=1, run_id="run-1")
  314. plug = MagicMock(id=4)
  315. plug.name = "Plug"
  316. archive = await db_session.get(PrintArchive, farm.archive)
  317. with (
  318. patch("backend.app.main.energy_plug_candidates", AsyncMock(return_value=[plug])),
  319. patch("backend.app.main.select_energy_reading", AsyncMock(return_value=(plug, {"total": 12.5}))),
  320. patch("backend.app.services.energy_price.current_price", AsyncMock(return_value=0.3)),
  321. ):
  322. assert await _record_energy_start(archive, farm.printer, db_session)
  323. [run] = await _all_runs(db_session, farm.archive)
  324. assert (run.energy_start_kwh, run.energy_start_plug_id, run.energy_start_price) == (12.5, 4, 0.3)
  325. archive = await db_session.get(PrintArchive, farm.archive)
  326. assert run.energy_start_at == archive.energy_start_at
  327. async def test_an_open_run_is_left_out_of_reads_updates_and_deletes(db_session, farm):
  328. from sqlalchemy import delete, update
  329. from backend.app.models.print_log import INCLUDE_OPEN_RUNS
  330. db_session.add_all(
  331. [
  332. PrintLogEntry(archive_id=farm.archive, status="completed"),
  333. PrintLogEntry(archive_id=farm.archive, status="printing"),
  334. ]
  335. )
  336. await db_session.commit()
  337. assert await db_session.scalar(select(func.count(PrintLogEntry.id))) == 1
  338. await db_session.execute(update(PrintLogEntry).values(notes="edited"))
  339. await db_session.execute(delete(PrintLogEntry))
  340. await db_session.commit()
  341. left = (
  342. await db_session.execute(
  343. select(PrintLogEntry.status, PrintLogEntry.notes).execution_options(**{INCLUDE_OPEN_RUNS: True})
  344. )
  345. ).all()
  346. assert left == [("printing", None)]
  347. @pytest.mark.parametrize("by", ["subtask", "name"])
  348. async def test_a_print_running_since_before_the_upgrade_gets_its_run(test_engine, db_session, farm, by):
  349. """Bambuddy restarts into the new version mid-print: the archive is
  350. printing and has no run; resuming the print opens it."""
  351. from datetime import datetime, timedelta
  352. archive = await db_session.get(PrintArchive, farm.archive)
  353. archive.status = "printing"
  354. started = datetime.utcnow().replace(microsecond=0) - timedelta(minutes=20)
  355. archive.started_at = started
  356. archive.subtask_id = "job-7"
  357. await db_session.commit()
  358. await _drive_print_start(
  359. test_engine,
  360. SimpleNamespace(id=farm.printer),
  361. download_ok=False,
  362. state_fields={"progress": 40.0},
  363. raw_data={"subtask_id": "job-7"} if by == "subtask" else None,
  364. )
  365. assert await db_session.scalar(select(func.count()).select_from(PrintArchive)) == 1, "resumed, not archived anew"
  366. runs = await _all_runs(db_session, farm.archive)
  367. assert [(r.status, r.subtask_id) for r in runs] == [("printing", "job-7")]
  368. assert runs[0].started_at == started
  369. async def test_a_downloaded_print_opens_its_run(test_engine, db_session, printer_factory):
  370. """Started on the printer, its 3MF fetched: the auto-archive path."""
  371. printer_id = (await printer_factory(name="P")).id
  372. await _drive_print_start(test_engine, SimpleNamespace(id=printer_id), download_ok=True)
  373. archives = (await db_session.scalars(select(PrintArchive))).all()
  374. assert len(archives) == 1
  375. assert [r.status for r in await _all_runs(db_session, archives[0].id)] == ["printing"]
  376. async def test_two_plates_on_two_printers_at_once_each_end_their_own_run(
  377. test_engine, db_session, farm, printer_factory
  378. ):
  379. """The second start moves the archive's start, printer and job id to its
  380. own. Each printer's end still finds its print, fills its own run with its
  381. own start and plate, and leaves nothing open."""
  382. other = (await printer_factory(name="Q")).id
  383. register_expected_print(farm.printer, FILE, farm.archive, plate_id=1, cost_center_id=farm.center)
  384. await _drive_print_start(test_engine, SimpleNamespace(id=farm.printer), download_ok=False)
  385. [first] = await _all_runs(db_session, farm.archive)
  386. first_start = first.started_at
  387. await asyncio.sleep(1.1) # the second start is a later second
  388. register_expected_print(other, FILE, farm.archive, plate_id=2, cost_center_id=farm.center)
  389. await _drive_print_start(test_engine, SimpleNamespace(id=other), download_ok=False)
  390. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  391. assert main_module._print_cost_center_ids == {(other, farm.archive): farm.center}
  392. # The other printer's print is still bound, for its own end.
  393. assert main_module._active_prints.get((other, FILE)) == farm.archive
  394. assert main_module._print_plate_ids == {(other, farm.archive): 2}, "the first end drains only its own"
  395. await _complete(test_engine, other, "completed", name=SUBTASK)
  396. assert main_module._print_plate_ids == {}
  397. runs = await _all_runs(db_session, farm.archive)
  398. assert [(r.printer_id, r.status, r.plate_id) for r in runs] == [
  399. (farm.printer, "completed", 1),
  400. (other, "completed", 2),
  401. ]
  402. assert runs[0].id == first.id and runs[0].started_at == first_start
  403. assert runs[1].started_at > first_start
  404. async def test_a_run_is_dated_by_its_end(test_engine, db_session, farm):
  405. """The print log and statistics filter runs by when they were logged,
  406. which was always their end."""
  407. from datetime import datetime, timedelta
  408. await _start_queued(test_engine, db_session, farm, plate=1, run_id="run-1")
  409. [run] = await _all_runs(db_session, farm.archive)
  410. run.created_at = datetime(2026, 1, 1) # opened long ago
  411. await db_session.commit()
  412. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  413. [run] = await _all_runs(db_session, farm.archive)
  414. assert run.created_at > datetime.utcnow() - timedelta(minutes=5)
  415. async def test_a_run_left_open_by_an_unseen_end_is_dropped_at_the_next_start(test_engine, db_session, farm):
  416. """A print whose end never reached its run (cancelled as stale at the next
  417. start): as before runs opened at the start, it leaves no run."""
  418. db_session.add(PrintLogEntry(archive_id=None, printer_id=farm.printer, status="printing"))
  419. await db_session.commit()
  420. await _start_queued(test_engine, db_session, farm, plate=1, run_id="run-1")
  421. runs = (
  422. await db_session.scalars(
  423. select(PrintLogEntry)
  424. .where(PrintLogEntry.printer_id == farm.printer)
  425. .execution_options(include_open_runs=True)
  426. )
  427. ).all()
  428. assert [(r.archive_id, r.status) for r in runs] == [(farm.archive, "printing")]
  429. async def test_a_print_whose_archive_was_deleted_leaves_no_run(test_engine, db_session, farm):
  430. from sqlalchemy import update
  431. await _start_queued(test_engine, db_session, farm, plate=1, run_id="run-1")
  432. # Deleted while it printed (ON DELETE SET NULL takes the run's link).
  433. await db_session.execute(update(PrintLogEntry).values(archive_id=None).execution_options(include_open_runs=True))
  434. await db_session.delete(await db_session.get(PrintArchive, farm.archive))
  435. await db_session.commit()
  436. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  437. left = (await db_session.scalars(select(PrintLogEntry).execution_options(include_open_runs=True))).all()
  438. assert left == []
  439. async def test_deleting_an_archive_with_its_stats_takes_its_open_run(db_session, farm, async_client):
  440. db_session.add(PrintLogEntry(archive_id=farm.archive, printer_id=farm.printer, status="printing"))
  441. await db_session.commit()
  442. response = await async_client.delete(f"/api/v1/archives/{farm.archive}?purge_stats=true")
  443. assert response.status_code in (200, 204), response.text
  444. left = (await db_session.scalars(select(PrintLogEntry).execution_options(include_open_runs=True))).all()
  445. assert left == []
  446. async def test_the_energy_goes_to_the_run_that_ended(test_engine, db_session, farm, printer_factory):
  447. """Its run, not the archive's newest: a run opened earlier ends after a
  448. later one of the archive was written."""
  449. from datetime import datetime
  450. from unittest.mock import AsyncMock, MagicMock, patch
  451. await _start_queued(test_engine, db_session, farm, plate=1, run_id="run-1")
  452. other = (await printer_factory(name="Q")).id
  453. later = PrintLogEntry(
  454. archive_id=farm.archive, printer_id=other, status="completed", started_at=datetime(2026, 10, 30, 9)
  455. )
  456. db_session.add(later)
  457. archive = await db_session.get(PrintArchive, farm.archive)
  458. archive.energy_start_kwh = 10.0
  459. await db_session.commit()
  460. plug = MagicMock(id=1)
  461. plug.name = "Plug"
  462. with (
  463. patch("backend.app.main.energy_plug_candidates", AsyncMock(return_value=[plug])),
  464. patch("backend.app.main.select_energy_reading", AsyncMock(return_value=(plug, {"total": 10.5}))),
  465. patch("backend.app.services.energy_price.print_energy_cost", AsyncMock(return_value=0.1)),
  466. patch("backend.app.services.energy_price.current_price", AsyncMock(return_value=0.3)),
  467. ):
  468. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  469. runs = {r.printer_id: r.energy_kwh for r in await _all_runs(db_session, farm.archive)}
  470. assert runs == {farm.printer: 0.5, other: None}
  471. async def test_a_reprint_after_an_unseen_end_opens_a_run_of_its_own(test_engine, db_session, farm):
  472. """The archive's earlier run on this printer is still open (its end never
  473. came); the new start is a new run, not that one carried on."""
  474. from datetime import datetime
  475. stale = PrintLogEntry(
  476. archive_id=farm.archive, printer_id=farm.printer, status="printing", started_at=datetime(2026, 10, 1, 8)
  477. )
  478. db_session.add(stale)
  479. await db_session.commit()
  480. await _start_queued(test_engine, db_session, farm, plate=2, run_id="run-2")
  481. [run] = await _all_runs(db_session, farm.archive)
  482. archive = await db_session.get(PrintArchive, farm.archive)
  483. assert run.started_at != datetime(2026, 10, 1, 8)
  484. assert (run.started_at, run.plate_id) == (archive.started_at, 2)
  485. async def _two_printers_printing(test_engine, db_session, farm, printer_factory) -> int:
  486. """Plate 1 on the farm's printer, then plate 2 of the archive on another,
  487. both running. Returns the other printer's id."""
  488. other = (await printer_factory(name="Q")).id
  489. register_expected_print(farm.printer, FILE, farm.archive, plate_id=1)
  490. await _drive_print_start(test_engine, SimpleNamespace(id=farm.printer), download_ok=False)
  491. await asyncio.sleep(1.1)
  492. register_expected_print(other, FILE, farm.archive, plate_id=2)
  493. await _drive_print_start(test_engine, SimpleNamespace(id=other), download_ok=False)
  494. return other
  495. async def test_after_a_restart_each_printers_end_finds_its_run(test_engine, db_session, farm, printer_factory):
  496. """A restart forgets which print runs where; the run open on the printer
  497. still says, though the archive now names the other printer."""
  498. from sqlalchemy import update
  499. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  500. await db_session.execute(
  501. update(PrintLogEntry)
  502. .where(PrintLogEntry.printer_id == farm.printer)
  503. .values(subtask_id="job-p")
  504. .execution_options(include_open_runs=True)
  505. )
  506. await db_session.commit()
  507. main_module._active_prints.clear() # the restart
  508. archive = await db_session.get(PrintArchive, farm.archive)
  509. assert archive.printer_id == other
  510. await _complete(test_engine, farm.printer, "failed", name=SUBTASK, extra={"subtask_id": "job-p"})
  511. runs = {r.printer_id: r.status for r in await _all_runs(db_session, farm.archive)}
  512. assert runs == {farm.printer: "failed", other: "printing"}
  513. async def test_the_running_print_on_each_printer_is_its_own(test_engine, db_session, farm, printer_factory):
  514. """The skip-objects, plate label and pause lookups ask which archive runs
  515. on a printer, by its job id; the archive row has the latest start's."""
  516. from unittest.mock import MagicMock
  517. from sqlalchemy import update
  518. from backend.app.main import running_print_archive
  519. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  520. await db_session.execute(
  521. update(PrintLogEntry)
  522. .where(PrintLogEntry.printer_id == farm.printer)
  523. .values(subtask_id="job-p")
  524. .execution_options(include_open_runs=True)
  525. )
  526. archive = await db_session.get(PrintArchive, farm.archive)
  527. archive.subtask_id = "job-q"
  528. await db_session.commit()
  529. main_module._active_prints.clear()
  530. found = await running_print_archive(
  531. db_session, farm.printer, MagicMock(subtask_id="job-p"), printing_only=True, by_name=False
  532. )
  533. assert found is not None and found.id == farm.archive
  534. assert archive.printer_id == other
  535. async def test_the_kill_switch_knows_its_own_print_on_each_printer(test_engine, db_session, farm, printer_factory):
  536. """Bambuddy's print on the first printer is authorized by its own run,
  537. though the archive's job id and printer are the second start's."""
  538. from unittest.mock import MagicMock
  539. from sqlalchemy import update
  540. from backend.app.main import _is_bambuddy_authorized_print
  541. await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  542. await db_session.execute(
  543. update(PrintLogEntry)
  544. .where(PrintLogEntry.printer_id == farm.printer)
  545. .values(subtask_id="job-p")
  546. .execution_options(include_open_runs=True)
  547. )
  548. archive = await db_session.get(PrintArchive, farm.archive)
  549. archive.subtask_id = "job-q"
  550. await db_session.commit()
  551. main_module._active_prints.clear()
  552. main_module._owned_print_archive_ids.clear()
  553. state = MagicMock(subtask_id="job-p", subtask_name=SUBTASK, gcode_file="")
  554. assert await _is_bambuddy_authorized_print(farm.printer, state, db_session) is True
  555. async def test_a_restart_resumes_each_printers_print_on_its_archive(test_engine, db_session, farm, printer_factory):
  556. """Bambuddy comes back while both plates print: the first printer's print
  557. is resumed on the archive by its run, not archived anew, though the
  558. archive names the other printer and its job."""
  559. from sqlalchemy import update
  560. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  561. await db_session.execute(
  562. update(PrintLogEntry)
  563. .where(PrintLogEntry.printer_id == farm.printer)
  564. .values(subtask_id="job-p")
  565. .execution_options(include_open_runs=True)
  566. )
  567. archive = await db_session.get(PrintArchive, farm.archive)
  568. archive.subtask_id = "job-q"
  569. await db_session.commit()
  570. main_module._active_prints.clear() # the restart
  571. await _drive_print_start(
  572. test_engine,
  573. SimpleNamespace(id=farm.printer),
  574. download_ok=False,
  575. state_fields={"progress": 40.0},
  576. raw_data={"subtask_id": "job-p"},
  577. )
  578. assert await db_session.scalar(select(func.count()).select_from(PrintArchive)) == 1, "resumed, not archived anew"
  579. assert main_module._active_prints.get((farm.printer, FILE)) == farm.archive
  580. runs = {r.printer_id: r.status for r in await _all_runs(db_session, farm.archive)}
  581. assert runs == {farm.printer: "printing", other: "printing"}
  582. @pytest.mark.parametrize("jobs", [("job-z", "job-y"), ("0", "0")], ids=["other-job", "no-job-ids"])
  583. async def test_a_late_end_of_an_earlier_job_leaves_the_running_print_alone(test_engine, db_session, farm, jobs):
  584. """The restart's reconcile closes a print that ended unseen, while the
  585. printer runs another one now: that one's open run is not the end's. A
  586. print started outside the cloud reports job "0", which tells nothing."""
  587. running_job, ending_job = jobs
  588. from sqlalchemy import update
  589. await _start_queued(test_engine, db_session, farm, plate=1, run_id="run-z")
  590. await db_session.execute(
  591. update(PrintLogEntry).values(subtask_id=running_job).execution_options(include_open_runs=True)
  592. )
  593. await db_session.commit()
  594. main_module._active_prints.clear() # the restart
  595. await _complete(
  596. test_engine, farm.printer, "aborted", name="Other_part", extra={"subtask_id": ending_job, "_reconciled": True}
  597. )
  598. assert [(r.status, r.subtask_id) for r in await _all_runs(db_session, farm.archive)] == [("printing", running_job)]
  599. archive = await db_session.get(PrintArchive, farm.archive)
  600. assert archive.status == "printing"
  601. async def test_the_archive_shows_its_latest_run(test_engine, db_session, farm, printer_factory):
  602. """Plate 1 ends while plate 2 still prints: the archive is left as plate
  603. 1's end wrote it -- the reconcile, the next end and the timelapse still
  604. go by its printer, status and start. When plate 2 ends, the last of its
  605. prints, it shows plate 2's outcome."""
  606. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  607. await _complete(test_engine, farm.printer, "failed", name=SUBTASK)
  608. runs = {r.printer_id: r for r in await _all_runs(db_session, farm.archive)}
  609. archive = await db_session.get(PrintArchive, farm.archive)
  610. await db_session.refresh(archive)
  611. assert (archive.status, archive.printer_id, archive.started_at) == ("failed", other, runs[other].started_at)
  612. await _complete(test_engine, other, "completed", name=SUBTASK)
  613. runs = {r.printer_id: r for r in await _all_runs(db_session, farm.archive)}
  614. archive = await db_session.get(PrintArchive, farm.archive)
  615. await db_session.refresh(archive)
  616. assert (archive.status, archive.started_at, archive.completed_at, archive.plate_id, archive.failure_reason) == (
  617. "completed",
  618. runs[other].started_at,
  619. runs[other].completed_at,
  620. 2,
  621. None,
  622. )
  623. async def test_the_end_of_an_earlier_start_does_not_take_the_card(test_engine, db_session, farm, printer_factory):
  624. """Plate 2 started later and ended first; plate 1 ends after it. The
  625. archive shows the latest start, plate 2, not the last end."""
  626. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  627. await _complete(test_engine, other, "completed", name=SUBTASK)
  628. await _complete(test_engine, farm.printer, "failed", name=SUBTASK)
  629. archive = await db_session.get(PrintArchive, farm.archive)
  630. await db_session.refresh(archive)
  631. assert (archive.status, archive.plate_id) == ("completed", 2)
  632. async def test_the_notification_of_an_end_has_its_runs_time(test_engine, db_session, farm, printer_factory):
  633. """Plate 1's end is notified with plate 1's duration, not the time since
  634. plate 2 started (the archive's start)."""
  635. await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  636. notif = await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  637. archive_data = notif.on_print_complete.await_args.kwargs["archive_data"]
  638. assert archive_data["actual_time_seconds"] is not None and archive_data["actual_time_seconds"] >= 1
  639. async def test_a_run_edited_in_the_print_log_is_shown_on_its_archive(test_engine, db_session, farm, async_client):
  640. await _run(test_engine, db_session, farm, plate=1, status="failed", run_id="run-1")
  641. [run] = await _runs(db_session, farm.archive)
  642. response = await async_client.patch(
  643. f"/api/v1/print-log/{run.id}", json={"status": "completed", "failure_reason": ""}
  644. )
  645. assert response.status_code == 200, response.text
  646. archive = await db_session.get(PrintArchive, farm.archive)
  647. await db_session.refresh(archive)
  648. assert (archive.status, archive.failure_reason) == ("completed", None)
  649. async def test_an_edit_of_the_archive_lands_on_its_latest_started_run(db_session, farm, async_client):
  650. """The run the card shows is the latest start; with plates ended the
  651. other way round that is not the highest id."""
  652. from datetime import datetime
  653. later = PrintLogEntry(
  654. archive_id=farm.archive, printer_id=farm.printer, status="completed", started_at=datetime(2026, 10, 30, 10)
  655. )
  656. earlier = PrintLogEntry(
  657. archive_id=farm.archive, printer_id=farm.printer, status="completed", started_at=datetime(2026, 10, 30, 8)
  658. )
  659. db_session.add(later)
  660. await db_session.flush()
  661. db_session.add(earlier)
  662. await db_session.commit()
  663. response = await async_client.patch(
  664. f"/api/v1/archives/{farm.archive}", json={"status": "failed", "failure_reason": "spaghetti"}
  665. )
  666. assert response.status_code == 200, response.text
  667. db_session.expire_all()
  668. rows = {r.started_at.hour: (r.status, r.failure_reason) for r in await _runs(db_session, farm.archive)}
  669. assert rows == {10: ("failed", "spaghetti"), 8: ("completed", None)}
  670. async def test_the_latest_run_is_the_latest_start(db_session, farm):
  671. """Runs written at their end (before runs were opened at the start) are
  672. numbered by their end; the card's run is still the latest start."""
  673. from datetime import datetime
  674. from backend.app.services.print_log import mirror_latest_run
  675. db_session.add(
  676. PrintLogEntry(
  677. archive_id=farm.archive, printer_id=farm.printer, status="failed", started_at=datetime(2026, 10, 30, 10)
  678. )
  679. )
  680. await db_session.flush()
  681. db_session.add(
  682. PrintLogEntry(
  683. archive_id=farm.archive, printer_id=farm.printer, status="completed", started_at=datetime(2026, 10, 30, 8)
  684. )
  685. )
  686. await db_session.flush()
  687. await mirror_latest_run(db_session, farm.archive)
  688. archive = await db_session.get(PrintArchive, farm.archive)
  689. assert (archive.status, archive.started_at) == ("failed", datetime(2026, 10, 30, 10))
  690. async def test_a_later_plates_end_leaves_no_printing_archive_for_its_reconnect(
  691. test_engine, db_session, farm, printer_factory
  692. ):
  693. """The later-started plate ends first. Its printer's reconnect looks for
  694. printing archives of that printer to close: the archive must not be one,
  695. or a second end of the print is made up."""
  696. from unittest.mock import MagicMock, patch
  697. from backend.app.main import reconcile_stale_active_prints
  698. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  699. await _complete(test_engine, other, "completed", name=SUBTASK)
  700. from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
  701. state = MagicMock(connected=True, state="FINISH", subtask_id="", progress=100, layer_num=0)
  702. maker = async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False)
  703. with (
  704. patch("backend.app.main.printer_manager.get_status", return_value=state),
  705. patch("backend.app.main.async_session", maker),
  706. ):
  707. assert await reconcile_stale_active_prints(other) == 0
  708. assert [r.printer_id for r in await _runs(db_session, farm.archive)] == [other]
  709. async def _reconcile(test_engine, printer_id: int, state) -> int:
  710. """The reconnect's reconcile on ``printer_id`` against the test database,
  711. its synthesised ends run one background task at a time."""
  712. from unittest.mock import patch
  713. from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
  714. from backend.app.main import reconcile_stale_active_prints
  715. maker = async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False)
  716. payloads: list[tuple[int, dict]] = []
  717. async def capture(pid, payload):
  718. payloads.append((pid, payload))
  719. with (
  720. patch("backend.app.main.printer_manager.get_status", return_value=state),
  721. patch("backend.app.main.async_session", maker),
  722. patch("backend.app.main.on_print_complete", side_effect=capture),
  723. ):
  724. reconciled = await reconcile_stale_active_prints(printer_id)
  725. # The ends it synthesised, run as on_print_complete runs them.
  726. for pid, payload in payloads:
  727. await _complete(
  728. test_engine,
  729. pid,
  730. payload["status"],
  731. name=payload["subtask_name"],
  732. extra={k: v for k, v in payload.items() if k not in ("status", "subtask_name")},
  733. )
  734. return reconciled
  735. async def test_the_reconnect_closes_its_printers_run_of_a_shared_archive(
  736. test_engine, db_session, farm, printer_factory
  737. ):
  738. """Plate 1's printer reconnects with its print over; the archive names
  739. the other printer, whose plate still prints. Plate 1's run is closed,
  740. plate 2's is left running."""
  741. from unittest.mock import MagicMock
  742. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  743. main_module._active_prints.clear() # the restart
  744. finished = MagicMock(connected=True, state="FINISH", subtask_id="", progress=100, layer_num=0)
  745. assert await _reconcile(test_engine, farm.printer, finished) == 1
  746. runs = {r.printer_id: r.status for r in await _all_runs(db_session, farm.archive)}
  747. assert runs[other] == "printing"
  748. assert runs[farm.printer] != "printing"
  749. async def test_the_reconnect_leaves_a_run_still_printing_alone(test_engine, db_session, farm, printer_factory):
  750. """The other printer reconnects mid-print, its own job on it: nothing to close."""
  751. from unittest.mock import MagicMock
  752. from sqlalchemy import update
  753. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  754. await db_session.execute(
  755. update(PrintLogEntry)
  756. .where(PrintLogEntry.printer_id == other)
  757. .values(subtask_id="job-q")
  758. .execution_options(include_open_runs=True)
  759. )
  760. await db_session.commit()
  761. running = MagicMock(
  762. connected=True, state="RUNNING", subtask_id="job-q", subtask_name=SUBTASK, progress=40, layer_num=3
  763. )
  764. assert await _reconcile(test_engine, other, running) == 0
  765. assert {r.printer_id: r.status for r in await _all_runs(db_session, farm.archive)}[other] == "printing"
  766. async def test_a_real_end_after_an_offline_stop_is_one_run_on_a_shared_archive(
  767. test_engine, db_session, farm, printer_factory, async_client
  768. ):
  769. """Plate 1 is stopped while its printer is offline, after plate 2 started
  770. elsewhere (the archive has plate 2's start). Its printer then reports the
  771. real end: it replaces the stop, it is not a second run."""
  772. from unittest.mock import AsyncMock, patch
  773. item = PrintQueueItem(printer_id=farm.printer, archive_id=farm.archive, status="printing", position=1, plate_id=1)
  774. db_session.add(item)
  775. await db_session.commit()
  776. item_id = item.id
  777. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  778. own_start = {r.printer_id: r.started_at for r in await _all_runs(db_session, farm.archive)}[farm.printer]
  779. with (
  780. patch("backend.app.services.print_control.stop_print_by_user", return_value=False),
  781. patch("backend.app.api.routes.print_queue.ws_manager") as ws,
  782. ):
  783. ws.send_archive_updated = AsyncMock()
  784. assert (await async_client.post(f"/api/v1/queue/{item_id}/stop")).status_code == 200
  785. main_module._active_prints[(farm.printer, FILE)] = farm.archive
  786. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  787. runs = [(r.printer_id, r.status) for r in await _all_runs(db_session, farm.archive)]
  788. assert sorted(runs) == sorted([(farm.printer, "completed"), (other, "printing")])
  789. ended = {r.printer_id: r for r in await _all_runs(db_session, farm.archive)}[farm.printer]
  790. assert ended.started_at == own_start, "timed from its own start, not the other plate's"
  791. async def test_a_stale_archive_cancelled_at_the_next_start_keeps_other_printers_bound(farm):
  792. """The stale-cancel at a print start drops the archive's bindings on its
  793. own printer only: another printer printing a plate of it keeps its own."""
  794. import ast
  795. from pathlib import Path
  796. source = Path(main_module.__file__).read_text()
  797. tree = ast.parse(source)
  798. unbinds = [
  799. ast.unparse(node)
  800. for node in ast.walk(tree)
  801. if isinstance(node, ast.ListComp) and "existing_archive.id" in ast.unparse(node)
  802. ]
  803. assert unbinds and all("printer_id" in comp for comp in unbinds), unbinds
  804. async def test_the_reconnect_closes_a_finished_print_once(test_engine, db_session, farm, printer_factory):
  805. """The later plate's printer reconnects with it over. The archive names
  806. that printer and still says printing; its run is what is closed, once,
  807. not the archive a second time as if it had no run."""
  808. from unittest.mock import MagicMock
  809. other = await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  810. main_module._active_prints.clear()
  811. finished = MagicMock(connected=True, state="FINISH", subtask_id="", progress=100, layer_num=0)
  812. assert await _reconcile(test_engine, other, finished) == 1
  813. async def test_the_reconnect_judges_each_print_by_its_own_job(test_engine, db_session, farm, printer_factory):
  814. """Plate 1's printer reconnects running its job; the archive holds the
  815. other plate's job id. Plate 1 is not taken for a print that changed."""
  816. from unittest.mock import MagicMock
  817. from sqlalchemy import update
  818. await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  819. await db_session.execute(
  820. update(PrintLogEntry)
  821. .where(PrintLogEntry.printer_id == farm.printer)
  822. .values(subtask_id="job-p")
  823. .execution_options(include_open_runs=True)
  824. )
  825. archive = await db_session.get(PrintArchive, farm.archive)
  826. archive.subtask_id = "job-q"
  827. await db_session.commit()
  828. running = MagicMock(
  829. connected=True, state="RUNNING", subtask_id="job-p", subtask_name=SUBTASK, progress=40, layer_num=3
  830. )
  831. assert await _reconcile(test_engine, farm.printer, running) == 0
  832. async def test_an_end_does_not_take_over_an_earlier_stop_of_the_file(test_engine, db_session, farm):
  833. """Stopped from the queue while the printer was online (the same status and
  834. reason an offline stop logs), then printed again: the reprint's end
  835. writes its own run. Only a stop logged while the printer was offline is
  836. the printer's real end to replace."""
  837. from datetime import datetime
  838. db_session.add(
  839. PrintLogEntry(
  840. archive_id=farm.archive,
  841. printer_id=farm.printer,
  842. status="cancelled",
  843. failure_reason="userCancelled",
  844. started_at=datetime(2026, 10, 29, 8),
  845. completed_at=datetime(2026, 10, 29, 9),
  846. )
  847. )
  848. archive = await db_session.get(PrintArchive, farm.archive)
  849. archive.status = "printing"
  850. archive.started_at = datetime(2026, 10, 30, 8) # printing since before runs were opened
  851. await db_session.commit()
  852. main_module._active_prints[(farm.printer, FILE)] = farm.archive
  853. await _complete(test_engine, farm.printer, "completed", name=SUBTASK)
  854. runs = sorted((r.started_at.day, r.status) for r in await _runs(db_session, farm.archive))
  855. assert runs == [(29, "cancelled"), (30, "completed")]
  856. async def test_a_second_offline_stop_is_a_run_of_its_own(test_engine, db_session, farm, async_client):
  857. """An earlier offline stop of the file on this printer is not this stop."""
  858. from datetime import datetime
  859. from unittest.mock import AsyncMock, patch
  860. db_session.add(
  861. PrintLogEntry(
  862. archive_id=farm.archive,
  863. printer_id=farm.printer,
  864. status="cancelled",
  865. failure_reason="userCancelled",
  866. ended_offline=True,
  867. started_at=datetime(2026, 10, 29, 8),
  868. )
  869. )
  870. archive = await db_session.get(PrintArchive, farm.archive)
  871. archive.status = "printing"
  872. archive.started_at = datetime(2026, 10, 30, 8)
  873. item = PrintQueueItem(printer_id=farm.printer, archive_id=farm.archive, status="printing", position=1)
  874. db_session.add(item)
  875. await db_session.commit()
  876. item_id = item.id
  877. with (
  878. patch("backend.app.services.print_control.stop_print_by_user", return_value=False),
  879. patch("backend.app.api.routes.print_queue.ws_manager") as ws,
  880. ):
  881. ws.send_archive_updated = AsyncMock()
  882. assert (await async_client.post(f"/api/v1/queue/{item_id}/stop")).status_code == 200
  883. assert len(await _runs(db_session, farm.archive)) == 2
  884. async def test_a_reconcile_after_the_real_end_closes_nothing(test_engine, db_session, farm, printer_factory):
  885. """The reconcile read the printer's runs while plate 1 still printed; the
  886. real end closed it before the synthesised one ran. That one ends nothing."""
  887. from unittest.mock import MagicMock, patch
  888. from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
  889. from backend.app.main import reconcile_stale_active_prints
  890. await _two_printers_printing(test_engine, db_session, farm, printer_factory)
  891. maker = async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False)
  892. payloads: list[dict] = []
  893. async def capture(pid, payload):
  894. payloads.append(payload)
  895. finished = MagicMock(connected=True, state="FINISH", subtask_id="", progress=100, layer_num=0)
  896. with (
  897. patch("backend.app.main.printer_manager.get_status", return_value=finished),
  898. patch("backend.app.main.async_session", maker),
  899. patch("backend.app.main.on_print_complete", side_effect=capture),
  900. ):
  901. await reconcile_stale_active_prints(farm.printer)
  902. await _complete(test_engine, farm.printer, "completed", name=SUBTASK) # the real end, first
  903. [payload] = payloads
  904. await _complete(
  905. test_engine,
  906. farm.printer,
  907. payload["status"],
  908. name=payload["subtask_name"],
  909. extra={k: v for k, v in payload.items() if k not in ("status", "subtask_name")},
  910. )
  911. mine = [r.status for r in await _all_runs(db_session, farm.archive) if r.printer_id == farm.printer]
  912. assert mine == ["completed"]
  913. async def test_a_stale_archive_cancelled_at_the_next_start_leaves_no_run_open(test_engine, db_session, farm):
  914. """A print whose end was never seen, its archive cancelled as stale when
  915. the next print starts: its run goes too, even when the new print's own
  916. run is not opened, or the next reconnect would close it a second time."""
  917. from datetime import datetime, timedelta
  918. from unittest.mock import AsyncMock, patch
  919. started = datetime.utcnow() - timedelta(hours=3)
  920. archive = await db_session.get(PrintArchive, farm.archive)
  921. archive.status = "printing"
  922. archive.started_at = started
  923. archive.created_at = started
  924. db_session.add(
  925. PrintLogEntry(archive_id=farm.archive, printer_id=farm.printer, status="printing", started_at=started)
  926. )
  927. await db_session.commit()
  928. with patch("backend.app.main._open_run_for", AsyncMock()):
  929. await _drive_print_start(
  930. test_engine, SimpleNamespace(id=farm.printer), download_ok=False, state_fields={"progress": 0.2}
  931. )
  932. db_session.expire_all()
  933. archive = await db_session.get(PrintArchive, farm.archive)
  934. assert archive.status == "cancelled"
  935. assert await _all_runs(db_session, farm.archive) == []