fix(queue): pipeline cancel stops the preheat and frees the budget; an offline stop frees the budget; the SD cleanup at a print's end is bounded to 45 s; a refused print start is logged and retried at once without a reconnect

CHANGELOG.md

@@ -164,6 +164,11 @@ All notable changes to Bambuddy will be documented in this file.
 - **The frontend build no longer warns about `path` and `crypto` being externalized for the STEP previewer (#2976)** — `occt-import-js`, the Emscripten build behind STEP previews, requires both modules, but only inside its `ENVIRONMENT_IS_NODE` branches; in the browser it loads its `.wasm` from the URL the preview worker passes and draws randomness from `crypto.getRandomValues`. Vite still externalized both and printed two warnings on every build. `vite.config.ts` now drops exactly those two warnings for that one package through `build.rolldownOptions.onLog`, so an externalization anywhere else, or of any other module, still shows.
 
 ### Fixed
+- **Stopping and cancelling leave nothing running or reserved** — Four cases:
+  - **Cancelling a pipeline run** set its queued jobs to cancelled, but a job already preheating went on heating the printer (up to its soak time), and its share of the cost centre's budget stayed reserved. Both now happen as when the job is cancelled from the queue.
+  - **Stopping a job while its printer is offline** left its share of the cost centre's budget reserved until Bambuddy restarted; it is now released at once.
+  - **A printer slow to answer the end-of-print file cleanup** (up to about nine minutes) held up the end of the print so long that the stranded-job check closed the job first, and its auto power-off and its charge were skipped. The cleanup now gives up after 45 seconds and leaves the file on the card.
+  - **A print start the printer refused** is now logged with the printer's reason, and the job goes back to the queue for a retry at once. Bambuddy used to read the refusal as a print it accepted and waited three minutes for it to start.
 - **Queue jobs added through the API reach the printers they should** — Three cases in the API and webhooks:
   - **A model in lower case** (`"target_model": "x1c"`) was refused with "No active printers for model", although the scheduler matches models without regard to case. Adding (one job, alternatives, or library files), editing and pipelines now match it the same way and store the printers' own spelling (`X1C`); two alternatives for one model in different case are refused as the same printers. A pipeline aimed at a model class in lower case found no printers.
   - **A reprint through the webhook** (`/webhook/queue/add`) of a print sent through the virtual printer ignored the AMS slots the slicer had picked, so the scheduler matched slots by colour and type again. It now reuses them on the printer they were picked on, as a reprint from the UI does.

backend/app/api/routes/pipeline_runs.py

@@ -999,6 +999,9 @@ async def cancel_run(
     if not run.error_message:
         run.error_message = "Cancelled by user"
 
+    from backend.app.services.finance_budget import release_budget_reservation
+
+    cancelled_entries: list[int] = []
     job_rows = (await db.execute(select(PipelineJob).where(PipelineJob.pipeline_run_id == run.id))).scalars().all()
     for job in job_rows:
         queue_entry = None
@@ -1009,6 +1012,11 @@ async def cancel_run(
             if queue_entry is not None and queue_entry.status in ("pending", "queued"):
                 queue_entry.status = "cancelled"
                 queue_entry.completed_at = datetime.now(timezone.utc)
+                # As a cancel from the queue does: its budget hold is freed
+                await release_budget_reservation(
+                    db, source_type="print_queue", source_id=queue_entry.id, status="released"
+                )
+                cancelled_entries.append(queue_entry.id)
         if job.status in ("queued", "printing") and queue_entry is None:
             # Dispatched, its entry gone: whether it printed is unknown, and
             # calling it cancelled would make retry print it again.
@@ -1018,6 +1026,15 @@ async def cancel_run(
             job.completed_at = datetime.now(timezone.utc)
 
     await db.commit()
+    if cancelled_entries:
+        from backend.app.services.print_batch import refresh_batches_after
+        from backend.app.services.print_scheduler import scheduler
+
+        await refresh_batches_after(cancelled_entries)
+        # A preheating entry's dispatch is parked in a sleep and cannot see the
+        # status written above (#2727): told, it stops heating the printer.
+        for entry_id in cancelled_entries:
+            scheduler.notify_dispatch_cancelled(entry_id)
     await db.refresh(run)
     await _publish_run_event(db, run)
     return await _materialise_run(db, run)

backend/app/api/routes/print_queue.py

@@ -2648,6 +2648,11 @@ async def stop_queue_item(
                 created_by_id=archive.created_by_id,
             )
             closed_archive_id = archive.id
+    if not stop_sent:
+        # No print end will come to charge the run and release what the job
+        # held of its cost centre's budget, so release it here, as a cancel
+        # does. A stop that reached the printer leaves it to the print's end.
+        await release_budget_reservation(db, source_type="print_queue", source_id=item.id, status="released")
 
     await db.commit()
     await refresh_batches_after([item.id])

backend/app/main.py

@@ -7884,6 +7884,10 @@ async def _recover_fallback_from_cache_before_eviction(printer_id: int, data: di
             logger.debug("[RECOVER] Pre-eviction recovery for %s failed: %s", name, e)
 
 
+# Longest the print's end waits for its file to be deleted from the SD card
+_SD_CLEANUP_BUDGET_SECONDS = 45.0
+
+
 async def _cleanup_sd_card_after_print(
     printer_id: int, subtask_name: str | None, archive_id: int | None, logger
 ) -> None:
@@ -8188,7 +8192,25 @@ async def on_print_complete(printer_id: int, data: dict):
                 if archive:
                     archive_id = archive.id
 
-    await _cleanup_sd_card_after_print(printer_id, subtask_name, archive_id, logger)
+    # Bounded: a printer whose FTP hangs on DELE took up to 3 candidates x 3
+    # attempts x a 60 s timeout, about nine minutes, before the queue item was
+    # closed below. The stranded-job closer gives up after five and closed it
+    # first, so the job's auto-off and its billing never ran. Inline rather
+    # than in the background, so the next job of the same file isn't released
+    # (and uploaded under the name being deleted) while the cleanup still
+    # works on it. A delete already sent may still finish in its FTP thread
+    # after the cutoff, as one past delete_file_async's own timeout always did.
+    try:
+        await asyncio.wait_for(
+            _cleanup_sd_card_after_print(printer_id, subtask_name, archive_id, logger),
+            timeout=_SD_CLEANUP_BUDGET_SECONDS,
+        )
+    except TimeoutError:
+        logger.warning(
+            "SD card cleanup on printer %s took over %ss; leaving the file there and closing the print",
+            printer_id,
+            _SD_CLEANUP_BUDGET_SECONDS,
+        )
 
     log_timing("SD card cleanup")
 

backend/app/services/bambu_mqtt.py

@@ -1455,6 +1455,10 @@ class BambuMQTTClient:
         # printer hasn't reported it yet, letting queue/scheduled archives
         # persist a restart-stable id from the moment they dispatch (#1485).
         self.last_dispatch_subtask_id: str | None = None
+        # The printer's answer to the last print start it refused, as (result,
+        # reason); cleared when the next start is sent. The start watchdog
+        # reads it to stop waiting for a print that will not come.
+        self.last_start_refusal: tuple[str, str | None] | None = None
         self._is_dual_nozzle: bool = False  # Set when device.extruder.info has >= 2 entries
         self._message_log: deque[MQTTLogEntry] = deque(maxlen=100)
         self._logging_enabled: bool = False
@@ -2210,8 +2214,18 @@ class BambuMQTTClient:
         if not isinstance(print_data, dict) or print_data.get("command") != "project_file":
             return
         # A refused dispatch names a file that was never written. Acting on it
-        # would pin an archive on a destination nothing ever went to.
-        if print_data.get("result") != "SUCCESS":
+        # would pin an archive on a destination nothing ever went to. Logged:
+        # nothing else says the printer refused a print it was sent.
+        result = str(print_data.get("result") or "")
+        if result.upper() != "SUCCESS":
+            logger.info(
+                "[%s] Printer refused a print start (project_file): result=%s reason=%s url=%s",
+                self.serial_number,
+                result,
+                print_data.get("reason"),
+                print_data.get("url"),
+            )
+            self.last_start_refusal = (result, print_data.get("reason"))
             return
         url = print_data.get("url")
         if not isinstance(url, str) or not url:
@@ -4378,12 +4392,20 @@ class BambuMQTTClient:
         if "gcode_file" in data:
             self.state.gcode_file = data["gcode_file"]
             self.state.current_print = data["gcode_file"]
-        if "subtask_name" in data:
+        # The answer to a print start the printer refused names the job it
+        # refused, not one it runs: read as status, its job id told the start
+        # watchdog the file had landed.
+        refused_start = (
+            data.get("command") == "project_file"
+            and data.get("result") is not None
+            and str(data["result"]).upper() != "SUCCESS"
+        )
+        if "subtask_name" in data and not refused_start:
             self.state.subtask_name = data["subtask_name"]
             # Prefer subtask_name as current_print if available
             if data["subtask_name"]:
                 self.state.current_print = data["subtask_name"]
-        if "subtask_id" in data:
+        if "subtask_id" in data and not refused_start:
             self.state.subtask_id = data["subtask_id"]
         if "mc_percent" in data:
             # Billing: retain this frame's latest positive value immediately.
@@ -6353,6 +6375,7 @@ class BambuMQTTClient:
             # Remember it so on_print_start can persist a restart-stable id on
             # the archive even before the printer echoes subtask_id back (#1485).
             self.last_dispatch_subtask_id = submission_id
+            self.last_start_refusal = None
 
             # Tri-state calibration options → BambuStudio's getValueInt encoding:
             # off=0 (never), on=1 (force every print), auto=2 (printer runs it

backend/app/services/print_scheduler.py

@@ -9622,6 +9622,9 @@ class PrintScheduler:
         # once is what matters — it is the state the printer was in when it
         # declined to start (#2758).
         drying_ams_ids: list[int] = []
+        # The printer answered the start with a refusal: nothing will start,
+        # and the command was not lost, so no reconnect either.
+        start_refusal: tuple[str, str | None] | None = None
         deadline = time.monotonic() + timeout
         while time.monotonic() < deadline:
             await asyncio.sleep(poll_interval)
@@ -9661,6 +9664,10 @@ class PrintScheduler:
             if _mqtt_commands_rejected(status):
                 command_rejected = True
                 break
+            refusal = getattr(printer_manager.get_client(printer_id), "last_start_refusal", None)
+            if isinstance(refusal, tuple):
+                start_refusal = refusal
+                break
             if pre_subtask_id is not None and status.subtask_id is not None and status.subtask_id != pre_subtask_id:
                 # Phase A exit — printer accepted the file (subtask_id flipped
                 # to our submission id). Don't return yet: the printer may
@@ -9865,7 +9872,16 @@ class PrintScheduler:
             )
             await scheduler._notify_dispatch_gave_up(queue_item_id, printer_id, created_by_id)
         elif revert_outcome == "reverted":
-            if landed_on_subtask:
+            if start_refusal is not None:
+                logger.warning(
+                    "Queue item %s: printer %d refused the print start (result=%s, reason=%s) — "
+                    "reverted to 'pending' for retry",
+                    queue_item_id,
+                    printer_id,
+                    start_refusal[0],
+                    start_refusal[1],
+                )
+            elif landed_on_subtask:
                 logger.warning(
                     "Queue item %s: printer %d accepted project_file (subtask_id "
                     "advanced) but never transitioned to an active state within "
@@ -9891,7 +9907,7 @@ class PrintScheduler:
         # project_file landed on the printer. A forced reconnect at this point
         # would interrupt the printer's parse and trigger 0500_4003 (#1150) —
         # skip the recovery entirely.
-        if landed_on_subtask:
+        if landed_on_subtask or start_refusal is not None:
             return
 
         # Phase A timeout path: if the printer's gcode_file changed since

backend/tests/integration/test_pipeline_runs_api.py

@@ -472,6 +472,45 @@ class TestCancelRun:
         assert cancel_resp.status_code == 200
         assert cancel_resp.json()["status"] == "cancelled"
 
+    @pytest.mark.asyncio
+    @pytest.mark.integration
+    async def test_cancel_stops_the_queue_entry_like_a_queue_cancel(
+        self,
+        async_client: AsyncClient,
+        pipeline_factory,
+        printer_factory,
+        library_file_factory,
+        db_session,
+    ):
+        """QS/I7: a preheating entry stops heating, its budget hold is freed."""
+        from backend.app.models.finance import BudgetReservation, CostCenter
+        from backend.app.models.pipeline_run import PipelineJob, PipelineRun
+        from backend.app.models.print_queue import PrintQueueItem
+
+        printer = await printer_factory()
+        pipeline = await pipeline_factory(target_printer_id=printer.id)
+        src = await library_file_factory()
+        center = CostCenter(name="Lab", is_active=True, is_private=False)
+        entry = PrintQueueItem(printer_id=printer.id, library_file_id=src.id, status="pending")
+        db_session.add_all([center, entry])
+        await db_session.flush()
+        run = PipelineRun(pipeline_id=pipeline["id"], source_library_file_id=src.id, status="running", copies=1)
+        db_session.add(run)
+        await db_session.flush()
+        db_session.add(PipelineJob(pipeline_run_id=run.id, queue_entry_id=entry.id, status="queued"))
+        hold = BudgetReservation(cost_center_id=center.id, amount=5.0, source_type="print_queue", source_id=entry.id)
+        db_session.add(hold)
+        await db_session.commit()
+
+        with patch("backend.app.services.print_scheduler.scheduler.notify_dispatch_cancelled") as notify:
+            response = await async_client.post(f"/api/v1/pipeline-runs/{run.id}/cancel")
+
+        assert response.status_code == 200, response.text
+        notify.assert_called_once_with(entry.id)
+        await db_session.refresh(hold)
+        await db_session.refresh(entry)
+        assert (entry.status, hold.status) == ("cancelled", "released")
+
     @pytest.mark.asyncio
     @pytest.mark.integration
     async def test_run_accepts_archive_source(

backend/tests/integration/test_print_complete_end_to_end.py

@@ -219,6 +219,43 @@ class TestAStopWhileThePrinterIsOffline:
         ]
         assert ws.send_archive_updated.await_args.args[0] == {"id": queued_print["archive"], "status": "cancelled"}
 
+    async def test_frees_the_budget_held_for_the_print(self, async_client, db_session, queued_print):
+        """QS/I5: no completion will come to release it, which left the cost
+        centre's budget reserved until Bambuddy restarted."""
+        from backend.app.models.finance import BudgetReservation
+
+        hold = BudgetReservation(
+            cost_center_id=queued_print["center"], amount=5.0, source_type="print_queue", source_id=queued_print["item"]
+        )
+        db_session.add(hold)
+        await db_session.commit()
+
+        await self._stop(async_client, queued_print)
+
+        await db_session.refresh(hold)
+        assert hold.status == "released"
+
+    async def test_a_stop_that_reached_the_printer_leaves_it_to_the_print_s_end(
+        self, async_client, db_session, queued_print
+    ):
+        """The print's end charges the run and releases the hold itself."""
+        from backend.app.models.finance import BudgetReservation
+
+        hold = BudgetReservation(
+            cost_center_id=queued_print["center"], amount=5.0, source_type="print_queue", source_id=queued_print["item"]
+        )
+        db_session.add(hold)
+        await db_session.commit()
+
+        with (
+            patch("backend.app.services.print_control.stop_print_by_user", return_value=True),
+            patch("backend.app.api.routes.print_queue.ws_manager"),
+        ):
+            await async_client.post(f"/api/v1/queue/{queued_print['item']}/stop")
+
+        await db_session.refresh(hold)
+        assert hold.status == "active"
+
     async def test_a_completion_that_arrives_after_all_replaces_it(
         self, async_client, test_engine, db_session, queued_print
     ):
@@ -343,3 +380,21 @@ async def test_the_registered_mapping_is_drained_when_the_printer_reported_one(t
         assert queued_print["archive"] not in main_module._print_ams_mappings
     finally:
         main_module._print_ams_mappings.pop(queued_print["archive"], None)
+
+
+async def test_a_hung_sd_cleanup_does_not_hold_up_the_print_s_end(test_engine, db_session, queued_print, monkeypatch):
+    """QS/I9: the job is closed (and billed) by its end, not by the stranded-job
+    closer, however long the printer takes to answer a delete."""
+    import asyncio
+
+    async def hangs(*_args, **_kwargs):
+        await asyncio.sleep(30)
+
+    monkeypatch.setattr(main_module, "_SD_CLEANUP_BUDGET_SECONDS", 0.2)
+    monkeypatch.setattr(main_module, "_cleanup_sd_card_after_print", hangs)
+
+    await asyncio.wait_for(_complete(test_engine, queued_print["printer"], "completed"), timeout=15)
+
+    _archive, item, _logs, charges = await _rows(db_session, queued_print["archive"], queued_print["item"])
+    assert item.status == "completed"
+    assert len(charges) == 1

backend/tests/unit/test_refused_project_file_ack.py

@@ -0,0 +1,74 @@
+"""A print start the printer refused is logged, and its answer is not read as
+an accepted print (FW-C1).
+
+The printer answers a ``project_file`` command on the report topic. A refusal
+went unlogged, so a support bundle showed nothing of it; and its job id was
+copied into the state like any status field, which the start watchdog reads
+as "the printer took the file" and so waited out its full 180 s before giving
+up.
+"""
+
+import logging
+
+from backend.app.services.bambu_mqtt import BambuMQTTClient
+
+
+def _client() -> BambuMQTTClient:
+    client = BambuMQTTClient(ip_address="10.0.0.9", serial_number="SN-FW", access_code="x", model="X1C")
+    client.state.subtask_id = "100"
+    client.state.subtask_name = "previous"
+    return client
+
+
+def _ack(result: str) -> dict:
+    return {
+        "print": {
+            "command": "project_file",
+            "result": result,
+            "reason": "file not found",
+            "subtask_id": "200",
+            "subtask_name": "refused",
+            "url": "ftp://refused.3mf",
+        }
+    }
+
+
+def test_a_refusal_is_logged_and_changes_no_job(caplog):
+    client = _client()
+
+    with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+        client._process_message(_ack("FAIL"))
+
+    assert (client.state.subtask_id, client.state.subtask_name) == ("100", "previous")
+    assert any("refused" in r.getMessage() and "FAIL" in r.getMessage() for r in caplog.records)
+
+
+def test_an_accepted_start_still_names_its_job():
+    client = _client()
+
+    client._process_message(_ack("SUCCESS"))
+
+    assert (client.state.subtask_id, client.state.subtask_name) == ("200", "refused")
+
+
+def test_a_refusal_is_remembered_until_the_next_start_is_sent():
+    from unittest.mock import MagicMock
+
+    client = _client()
+    client._process_message(_ack("FAIL"))
+    assert client.last_start_refusal == ("FAIL", "file not found")
+
+    client._client = MagicMock()
+    client.state.connected = True
+    client.start_print("next.3mf")
+
+    assert client.last_start_refusal is None
+
+
+def test_success_in_lower_case_is_not_a_refusal():
+    client = _client()
+
+    client._process_message(_ack("success"))
+
+    assert client.last_start_refusal is None
+    assert client.state.subtask_id == "200"

backend/tests/unit/test_scheduler_watchdog.py

@@ -907,3 +907,33 @@ class TestWatchdogNamesDryingAsTheObstacle:
             item = await db.get(PrintQueueItem, 1)
         assert item.status == "printing"
         assert (item.dispatch_attempts or 0) == 0
+
+
+class TestARefusedStart:
+    """FW-C1: the printer answered the start with a refusal. Nothing will
+    start, and the command was not lost: no full wait, no reconnect."""
+
+    @pytest.mark.asyncio
+    async def test_reverts_at_once_without_a_reconnect(self, db_session):
+        get_status = MagicMock(return_value=_status("FINISH", "OLD_SUBTASK", gcode_file="/old.3mf"))
+        client = MagicMock(last_start_refusal=("FAIL", "file not found"))
+
+        with (
+            patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
+            patch("backend.app.services.print_scheduler.printer_manager.get_client", MagicMock(return_value=client)),
+            patch("backend.app.services.print_scheduler.async_session", db_session),
+            patch("backend.app.core.database.async_session", db_session),
+        ):
+            await PrintScheduler._watchdog_print_start(
+                queue_item_id=1,
+                printer_id=42,
+                pre_state="FINISH",
+                pre_subtask_id="OLD_SUBTASK",
+                pre_gcode_file="/old.3mf",
+                timeout=30,
+                poll_interval=0.05,
+            )
+
+        client.force_reconnect_stale_session.assert_not_called()
+        async with db_session() as db:
+            assert (await db.get(PrintQueueItem, 1)).status == "pending"