test_scheduler_cancel_race.py 9.2 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238
  1. """Cancel-during-dispatch race regression (#1853).
  2. The user reported: queued a batch of 10 prints, pressed Cancel on a pending
  3. item, the print started anyway. Root cause is a check-then-act race in
  4. ``_start_print``: the snapshot of pending items is taken at the top of
  5. ``check_queue``, then ``_start_print`` does FTP delete + FTP upload (5-30 s)
  6. before flipping the row to ``"printing"`` and sending MQTT. If the user wins
  7. the race and ``/cancel`` lands during that window, the scheduler's stale
  8. in-memory write of ``status="printing"`` silently overwrites the cancellation.
  9. Three guards exercised here:
  10. * Early refresh after the connectivity check — bails before FTP I/O if the
  11. row is already cancelled.
  12. * Atomic CAS at the pending→printing transition — UPDATE WHERE
  13. status='pending'; rowcount==0 means user won, do NOT send MQTT.
  14. * Best-effort delete of the file we just FTP'd up when the CAS aborts.
  15. """
  16. from contextlib import ExitStack
  17. from pathlib import Path
  18. from types import SimpleNamespace
  19. from unittest.mock import AsyncMock, MagicMock, patch
  20. import pytest
  21. from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine
  22. import backend.app.models # noqa: F401 - populate Base.metadata
  23. import backend.app.services.print_scheduler as scheduler_module
  24. from backend.app.core.database import Base
  25. from backend.app.models.archive import PrintArchive
  26. from backend.app.models.print_queue import PrintQueueItem
  27. from backend.app.models.printer import Printer
  28. from backend.app.services.print_scheduler import PrintScheduler
  29. from backend.tests._fixtures.background_tasks import discarding_spawn_patch
  30. @pytest.fixture
  31. async def queue_factory(tmp_path):
  32. engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False)
  33. async with engine.begin() as conn:
  34. await conn.run_sync(Base.metadata.create_all)
  35. session_maker = async_sessionmaker(engine, expire_on_commit=False)
  36. case_counter = 0
  37. async def make_case(*, status="pending"):
  38. nonlocal case_counter
  39. case_counter += 1
  40. base_dir = tmp_path / f"case-{case_counter}"
  41. base_dir.mkdir()
  42. archive_rel = Path("archives") / f"job-{case_counter}.3mf"
  43. archive_abs = base_dir / archive_rel
  44. archive_abs.parent.mkdir(parents=True, exist_ok=True)
  45. archive_abs.write_bytes(b"archive payload")
  46. async with session_maker() as db:
  47. printer = Printer(
  48. name=f"Printer {case_counter}",
  49. serial_number=f"SERIAL-{case_counter}",
  50. ip_address="127.0.0.1",
  51. access_code="access-code",
  52. model="X1C",
  53. )
  54. db.add(printer)
  55. await db.flush()
  56. archive = PrintArchive(
  57. printer_id=printer.id,
  58. filename=f"job-{case_counter}.3mf",
  59. file_path=str(archive_rel),
  60. file_size=archive_abs.stat().st_size,
  61. content_hash=None,
  62. thumbnail_path=None,
  63. timelapse_path=None,
  64. print_time_seconds=120,
  65. status="completed",
  66. )
  67. db.add(archive)
  68. await db.flush()
  69. item = PrintQueueItem(
  70. printer_id=printer.id,
  71. archive_id=archive.id,
  72. status=status,
  73. bed_levelling="on",
  74. flow_cali="off",
  75. vibration_cali=True,
  76. layer_inspect=False,
  77. timelapse=False,
  78. use_ams=True,
  79. nozzle_offset_cali="on",
  80. )
  81. db.add(item)
  82. await db.commit()
  83. return SimpleNamespace(
  84. session_maker=session_maker,
  85. base_dir=base_dir,
  86. archive_path=archive_abs,
  87. printer_id=printer.id,
  88. archive_id=archive.id,
  89. queue_item_id=item.id,
  90. upload=AsyncMock(return_value=True),
  91. start_print=MagicMock(return_value=True),
  92. delete_file=AsyncMock(return_value=True),
  93. )
  94. try:
  95. yield make_case
  96. finally:
  97. await engine.dispose()
  98. async def _dispatch(ctx, *, upload_side_effect=None):
  99. scheduler = PrintScheduler()
  100. if upload_side_effect is not None:
  101. ctx.upload.side_effect = upload_side_effect
  102. patches = [
  103. patch.object(scheduler_module.settings, "base_dir", ctx.base_dir),
  104. patch("backend.app.services.print_scheduler.printer_manager.is_connected", MagicMock(return_value=True)),
  105. patch("backend.app.services.print_scheduler.printer_manager.get_status", MagicMock(return_value=None)),
  106. patch("backend.app.services.print_scheduler.printer_manager.start_print", ctx.start_print),
  107. patch("backend.app.services.print_scheduler.printer_manager.set_awaiting_plate_clear", MagicMock()),
  108. patch(
  109. "backend.app.services.print_scheduler.get_ftp_retry_settings",
  110. AsyncMock(return_value=(False, 0, 0, 1.0)),
  111. ),
  112. patch("backend.app.services.print_scheduler.delete_file_async", ctx.delete_file),
  113. patch("backend.app.services.print_scheduler.upload_file_async", ctx.upload),
  114. patch("backend.app.services.print_scheduler.cache_3mf_download", MagicMock()),
  115. discarding_spawn_patch(),
  116. patch(
  117. "backend.app.services.notification_service.notification_service.on_queue_job_started",
  118. AsyncMock(),
  119. ),
  120. patch(
  121. "backend.app.services.notification_service.notification_service.on_queue_job_failed",
  122. AsyncMock(),
  123. ),
  124. patch("backend.app.services.mqtt_relay.mqtt_relay.on_queue_job_started", AsyncMock()),
  125. patch.object(scheduler, "_propagate_owner_to_printer_manager", AsyncMock()),
  126. patch.object(scheduler, "_power_off_if_needed", AsyncMock()),
  127. patch.object(scheduler, "_preheat_and_soak", AsyncMock()),
  128. ]
  129. with ExitStack() as stack:
  130. for patcher in patches:
  131. stack.enter_context(patcher)
  132. async with ctx.session_maker() as db:
  133. item = await db.get(PrintQueueItem, ctx.queue_item_id)
  134. await scheduler._start_print(db, item)
  135. async def _final_status(ctx):
  136. async with ctx.session_maker() as db:
  137. item = await db.get(PrintQueueItem, ctx.queue_item_id)
  138. return item.status, item.started_at
  139. @pytest.mark.asyncio
  140. async def test_cancel_during_ftp_upload_aborts_before_mqtt(queue_factory):
  141. """User wins the race during the FTP upload — CAS must detect & bail.
  142. This is the headline #1853 scenario: snapshot saw pending, FTP upload
  143. starts, user clicks Cancel, /cancel commits ``cancelled`` to the row,
  144. FTP finishes successfully, scheduler reaches the CAS. CAS rowcount must
  145. be 0; ``printer_manager.start_print`` must NOT be called; row must stay
  146. ``cancelled``; uploaded file must be deleted from the printer's SD.
  147. """
  148. ctx = await queue_factory()
  149. async def cancel_mid_upload(*args, **kwargs):
  150. # Simulate /cancel landing in a separate session while FTP is in
  151. # flight. The endpoint commits status='cancelled' then returns 200.
  152. async with ctx.session_maker() as other_db:
  153. other_item = await other_db.get(PrintQueueItem, ctx.queue_item_id)
  154. other_item.status = "cancelled"
  155. await other_db.commit()
  156. return True
  157. await _dispatch(ctx, upload_side_effect=cancel_mid_upload)
  158. status, started_at = await _final_status(ctx)
  159. assert status == "cancelled", "CAS overwrote the user's cancellation"
  160. assert started_at is None, "started_at must not be stamped on a cancelled row"
  161. ctx.start_print.assert_not_called()
  162. # Two delete calls — the pre-upload sweep and the post-CAS cleanup.
  163. assert ctx.delete_file.await_count == 2
  164. @pytest.mark.asyncio
  165. async def test_cancel_before_ftp_upload_skips_dispatch(queue_factory):
  166. """Early-refresh path: row was cancelled before _start_print resumed.
  167. Mirrors the case where ``/cancel`` lands between the ``check_queue``
  168. snapshot and the time ``_start_print`` runs. The early ``db.refresh``
  169. after the connectivity check sees ``cancelled`` and returns immediately
  170. — no FTP upload, no MQTT send, row unchanged.
  171. """
  172. ctx = await queue_factory()
  173. # Flip to cancelled before _start_print runs; the in-memory snapshot
  174. # the scheduler holds still reads 'pending', exactly the bug shape.
  175. async with ctx.session_maker() as other_db:
  176. item = await other_db.get(PrintQueueItem, ctx.queue_item_id)
  177. item.status = "cancelled"
  178. await other_db.commit()
  179. await _dispatch(ctx)
  180. status, started_at = await _final_status(ctx)
  181. assert status == "cancelled"
  182. assert started_at is None
  183. ctx.upload.assert_not_awaited()
  184. ctx.start_print.assert_not_called()
  185. @pytest.mark.asyncio
  186. async def test_happy_path_still_dispatches(queue_factory):
  187. """Sanity: no cancel, no race — pending row flips to printing, MQTT fires.
  188. Regression guard so the CAS doesn't accidentally block normal dispatch
  189. on a row that was always pending.
  190. """
  191. ctx = await queue_factory()
  192. await _dispatch(ctx)
  193. status, started_at = await _final_status(ctx)
  194. assert status == "printing"
  195. assert started_at is not None
  196. ctx.upload.assert_awaited_once()
  197. ctx.start_print.assert_called_once()