From c32bc82dd428dddfe8c08ea21fe7b1b789800ff2 Mon Sep 17 00:00:00 2001 From: maziggy Date: Mon, 29 Jun 2026 12:59:09 +0200 Subject: [PATCH] fix(scheduler): cancel during queue dispatch actually cancels (#1853) Symptom: user queued a batch of 10 prints, pressed Cancel on a pending row, the print started anyway. Repeated consecutively. Support bundle also showed 15x "sqlite3.OperationalError: database is locked" from the sensor history recorder in the same 8-minute window. Root cause is a check-then-act race in _start_print. check_queue takes a snapshot of pending items, then _start_print does FTP delete + FTP upload (5-30s) before the unconditional item.status = "printing"; db.commit() at line 2792. /cancel commits status='cancelled' in a separate session during that window; the scheduler's stale in-memory write overwrites it and start_print ships. The lock-contention finding is the same shape from a different angle: _start_print did await db.flush() at line 2555 (after item.archive_id set + library_file delete) which opens the SQLite WAL writer lock and holds it through the FTP upload, queueing every concurrent writer behind it including the user's own cancel commit. Three guards layered: 1) Atomic CAS at the pending->printing transition. UPDATE print_queue SET status='printing', started_at=NOW() WHERE id=:id AND status='pending'. rowcount==0 means user won; log abort, best-effort delete_file_async the file we just FTP'd up so it doesn't leak into the printer's BambuStudio file picker, send queue_item_failed WS event with reason="cancelled_mid_dispatch", return without calling printer_manager.start_print. 2) Early db.refresh(item) + bail right after the printer connectivity check. Saves the wasted FTP upload when the row was already cancelled before _start_print resumed. Defense in depth; guard 1 catches the same case at the CAS point. 3) flush -> commit before the FTP block. The library-file-to-archive promotion's writes commit cleanly, WAL writer lock releases, sensor history and concurrent cancels stop queueing behind the scheduler. The flush-not-commit pattern was rolling back a pointer to an already-committed archive row, so the new behaviour matches reality (archive committed, pointer committed, FTP unblocked). --- CHANGELOG.md | 2 + backend/app/services/print_scheduler.py | 77 +++++- .../tests/unit/test_scheduler_cancel_race.py | 237 ++++++++++++++++++ 3 files changed, 312 insertions(+), 4 deletions(-) create mode 100644 backend/tests/unit/test_scheduler_cancel_race.py diff --git a/CHANGELOG.md b/CHANGELOG.md index c166bdd1f..c94203fa8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,8 @@ All notable changes to Bambuddy will be documented in this file. - **Preheat & Heat Soak before queued prints — per-item override + per-filament chamber targets (#1468, reporter @embed-3d)** — New scheduler stage that heats the bed (and the chamber, on printers that support it) and holds at temperature before each queued print starts, intended for engineering filaments (PA, ABS) where adhesion and warp depend on a warm chamber. **Why it doesn't already work in the slicer.** BambuStudio / OrcaSlicer can emit `M191` (wait-for-chamber-temp) in start-G-code, but Bambu firmware silently ignores `M191`, so any "wait for chamber" line in the slicer's start sequence is a no-op. The reporter confirmed this by trying the [MakerWorld chamber-heating G-code](https://makerworld.com/de/models/1200262-g-code-for-x1c-chamber-heating-and-heat-soak) in OrcaSlicer and finding the chamber-heating step wouldn't fire. Implementing this at the orchestration layer — Bambuddy waiting on `state.temperatures` between FTP upload and `start_print` — is the right architectural place; the slicer side is a dead end. **Where it fires.** `print_scheduler._preheat_and_soak()`, called from `_start_print()` immediately before the FTP upload section (`print_scheduler.py:2306`-ish). Best-effort: any failure (printer drops, gcode refused, no bed temp in metadata) logs and returns rather than failing the queue item — the normal upload + start path runs straight after. **Hardware-tier behaviour (three branches; the OP collapsed two of them and we kept them distinct):** (1) Active chamber heater — `H2C / H2D / H2D Pro / H2S / X2D / X1E` (`supports_chamber_heater()` true) — dispatches `M141 Sx` for the configured target then polls `state.temperatures["chamber"]` against it. (2) Chamber sensor only — `X1C / P2S` (`supports_chamber_temp()` true but `supports_chamber_heater()` false) — no `M141`, polls the chamber sensor and considers the chamber phase satisfied when bed radiation has driven the sensor to target. Radiant warm-up to ABS-friendly temps on a cold X1C is 20-30 min — the `max_wait_seconds` cap (default 900 s, range 60-3600) is a hard ceiling so a cold room can't stall the queue indefinitely; falls through to the soak phase if the chamber never converges. (3) No chamber sensor — `P1S / P1P / A1 / A1 Mini` — no chamber wait possible (the `chamber_temper` value these models report is meaningless per `printer_manager.supports_chamber_temp`), so only the bed phase + soak timer apply. **Bed target** is read from the archive's parsed `bed_temperature` metadata (the same `bed_temperature_initial_layer` / `bed_temperature` field `archive.py:438` already extracts from the 3MF); if missing the preheat stage skips and logs rather than guessing a default that might wreck a non-PLA print. **Settings — Settings → Workflow → Queue & Dispatch → Preheat & Heat Soak card.** Master toggle (`preheat_enabled`, default off — disabled installs see no behavioural change), `preheat_chamber_target` (°C, 0-60, default 0 = chamber phase disabled; PA: 50, ABS: 45, PETG-CF: 40), `preheat_max_wait_seconds` (60-3600, default 900), `preheat_soak_seconds` (0-1800, default 300). The numeric fields auto-disable in the UI when the master toggle is off so they read as "config that's not currently doing anything." A static helper line under the inputs spells out the three hardware tiers so users don't have to consult the wiki to know what their printer will do. **Tests.** Eight new cases in `backend/tests/unit/test_scheduler_preheat.py`: disabled-setting skip (no M140 / M141 dispatched), no-bed-temp-in-archive skip, `H2D` dispatches both `M140` and `M141`, `X1C` dispatches only `M140` (the explicit chamber-sensor-but-no-heater regression guard — wiring this to `supports_chamber_temp()` alone would have falsely fired `M141` on the entire X1 family), `P1S` ignores its meaningless `chamber` reading and lets only the soak timer run, `preheat_chamber_target=0` keeps the bed phase but skips chamber even on a heater-capable printer, lost-client mid-flow returns silently, lost-state mid-wait exits the poll loop gracefully and still soaks. `asyncio.sleep` patched to `AsyncMock` so the soak phase doesn't actually wait — assertions are on what was scheduled, not wall-clock. 8/8 green. **Wiki.** `bambuddy-wiki/docs/features/monitoring.md` gains a new "Preheat & Heat Soak" subsection under the queue/scheduling area documenting the three hardware tiers and the four-setting interface, so users with X1C or P1S know upfront what the feature can and cannot do for their printer. **i18n.** 13 new keys × 11 locales (en/de/es/fr/it/ja/ko/pt-BR/tr/zh-CN/zh-TW), real translations everywhere — no English fallback. **Scope.** Backend (scheduler + schema + settings route) + frontend (settings card + AppSettings type) + tests + wiki. No DB migration (uses the existing key/value `Settings` table). No new permission (Settings → Workflow already gates on the same admin scope). The OP's "select option per print" UX is not part of this drop — preheat is a global default applied to every queued item that has a parseable bed temperature; per-queue-item override would need a `PrintQueueItem` schema migration plus print-modal and queue-modify UI work that would have widened the change beyond the scope agreed with the user. **Rework on user review.** First cut shipped a global-only design: one single `preheat_chamber_target` int in Settings → Workflow, no per-print override. User flagged two gaps on review: (1) you can't enable preheat for a single queue item, (2) different filaments need different chamber temps but the setting was a single value. Both are fair: PA needs 50, PETG-CF wants 40, PLA wants 0, but the global single-int forced one number across all of them. Reworked the data shape: replaced the single `preheat_chamber_target` int with `preheat_filament_targets` (JSON map of normalised filament type → °C, user-editable in the same card via the new `PreheatFilamentTargetsEditor` component) and added two columns to `PrintQueueItem` — `preheat_override` (`inherit` / `on` / `off`, default `inherit`) and `preheat_chamber_target_override` (nullable int, beats the filament-map derivation). The scheduler's resolution order: `item.preheat_override == 'off'` skips entirely; `'inherit'` falls back to the global `preheat_enabled` master toggle; `'on'` forces the stage even when the global is off. Chamber target: `item.preheat_chamber_target_override` (explicit °C) > max of `preheat_filament_targets[normalize(t.tray_type)]` across loaded AMS slots > 0. Mixed PA+PLA load picks PA's 50 (max-across-slots, NOT lowest-common-denominator — PA's chamber requirement is the binding constraint, PLA doesn't suffer from being warm). PLA-only prints derive 0 and skip the chamber phase automatically without the user touching anything. The per-print UI lives in `PrintModal`'s "Print Options" panel — tri-state segmented control (Inherit / On / Off) plus an optional chamber-target override input (shown only when override ≠ Off, blank = use filament map). Same control in edit-queue-item mode so you can flip preheat on an already-queued print. Tests grew from 8 cases to 15 across three categories — override resolution (3), chamber-target derivation (5), hardware-tier branching (5), plus 2 helper-fn tests — all green. DB migration added: `preheat_override VARCHAR(10) DEFAULT 'inherit'` and `preheat_chamber_target_override INTEGER NULL` on `print_queue`, idempotent via `_safe_execute`. Existing rows behave exactly as before (inherit + null = use global). i18n grew from 13 keys to 19 × 11 locales — real translations for the new override radio + per-filament editor strings, no English fallback. Frontend `PrintQueueItem` TS interface and `PrintQueueItemCreate` / `PrintQueueItemUpdate` shapes updated to carry the new fields end-to-end. **PrintOptions.tsx now uses `options[key as 'bed_levelling']` for the boolean rows since `options[key]` would type-error against the new non-boolean preheat keys** — minor TS-only adjustment, no behavioural change. **Airduct flap follows the resolved chamber target — bidirectional, idempotent.** Reported by user mid-test on H2D: preheat ran M141 for ABS but the cooling/heating airduct flap stayed in cooling, the open exhaust vent actively fought the heater and the chamber crawled toward target. The H-series (H2C/H2D/H2D Pro/H2S), X2D, and P2S all have a motorised flap with two modes: cooling (modeId=0, open exhaust, vents heat — right for PLA/PETG/TPU) and heating (modeId=1, closed exhaust, recirculates warm air — right for ABS/ASA/PC/PA). Bambu's firmware does **not** auto-switch the flap based on M141; whatever mode the user last left it in persists. So a PLA→ABS workflow inherits PLA's cooling-mode flap and the heater never wins; conversely an ABS→PLA workflow inherits ABS's heating-mode recirculation and runs PLA's chamber hot. **Fix.** New `supports_airduct(model)` helper in `printer_manager.py` mirrors the frontend whitelist (`P2S`, `X2D`, `H2C`, `H2D`, `H2D Pro`, `H2S` plus their internal codes). In `_preheat_and_soak`, after the bed dispatch and BEFORE the chamber M141: read the printer's current `state.airduct_mode`, derive the desired mode from the resolved chamber target (`chamber_target > 0` → heating, `chamber_target == 0` → cooling), and only fire `set_airduct_mode` when current ≠ desired. **The bidirectional switch is the load-bearing part** per Martin: when the resolved chamber target is 0 (PLA-only print, or per-item override disables chamber), the flap MUST switch to cooling even on a heater-capable printer that was previously running ABS, otherwise the closed-flap recirculation cooks PLA. The idempotency check (read `state.airduct_mode`, compare against desired before sending) keeps the flap motor from cycling needlessly when it's already where we want it. **Gating** is on `supports_airduct(model)` only — distinct from `supports_chamber_heater(model)`: X1E has a chamber heater but no flap (skipped), P2S has a flap but no active heater (still flipped, because even a passive-sensor printer benefits from the right airflow for its filament); the intersection that needs both is H2C/H2D/H2D Pro/H2S/X2D and they all work. **No post-print restoration** per Martin's preference — once a preheat sets the flap, it stays there for the print's duration (the print itself wants the same mode the preheat picked) and for any subsequent prints until the next preheat decision flips it. Best-effort: any `set_airduct_mode` failure logs and continues; M141 still fires regardless so a stuck flap doesn't kill the print. **Tests.** Four new cases in `test_scheduler_preheat.py`: `test_h2d_chamber_heat_switches_airduct_to_heating` (the OP scenario — cooling→heating before M141 for ABS), `test_h2d_chamber_zero_switches_airduct_to_cooling` (heating→cooling for a PLA print on a previously-warm flap), `test_h2d_airduct_already_correct_idempotent` (no command sent when current mode matches desired), `test_x1c_no_airduct_flap_never_fires_set_airduct` (gate regression guard — X1C has chamber sensor + chamber heater logic adjacent but no flap, must not leak the command). 21/21 in the file now. ### Fixed +- **Cancel during queue dispatch actually cancels — no more "pressed cancel and the print started" (#1853, reporter @guy-blotnick)** — Symptom: user queued a batch of 10 print jobs of the same item across two P2S printers (Windows installation, v0.2.4.8), clicked Cancel on a pending row, and the print started anyway. Repeated consecutively. Support-bundle log scan reported 15× `sqlite3.OperationalError: database is locked` from the printer sensor history recorder in the same 8-minute window — a tell-tale that something was holding the SQLite WAL writer lock for the full 15 s `busy_timeout`. **Root cause (the race).** `_start_print()` in `backend/app/services/print_scheduler.py` carried a check-then-act window of several seconds between "scheduler's `check_queue` snapshotted this row as pending" and "scheduler sent the MQTT start_print command". The scheduler reads `item` via its session, then does FTP delete + FTP upload of the 3MF (5-30 s on a typical archive) before the unconditional `item.status = "printing"; await db.commit()` at line 2792. If the user pressed Cancel in that window, `/cancel` (a separate session) saw `status == 'pending'`, flipped to `cancelled`, and returned 200 — but the scheduler's stale in-memory write overwrote the cancellation in the very next commit. Then `printer_manager.start_print` shipped to the printer and the print commenced. The `cancel_queue_item` route at `print_queue.py:1245` correctly guards against late cancels (`status not in ("pending",)` → 400) but is useless if the scheduler races back to `pending → printing` AFTER the cancel commit. **Root cause (the lock contention amplifier).** `_start_print()` did `await db.flush()` at line 2555 immediately after writing `item.archive_id = archive.id` and `await db.delete(library_file)` (the library-file-to-archive promotion path) — `flush()` opens the SQLite write transaction but doesn't commit, holding the WAL writer lock through the FTP upload below. Every other writer in the process (sensor history task every 60 s, runtime tracking every 30 s, MQTT state UPDATEs from the live H2D/P2S, the user's own concurrent /cancel commits) blocks behind that lock for the full upload duration. With 15 s `busy_timeout` and FTP uploads regularly exceeding 15 s on larger 3MFs, the sensor history task hit its first lock error → logged + slept 60 s → next tick still blocked → repeat. The lock contention also widened the cancel-race window (the user's cancel commit was queued behind the scheduler's held write), making the race that much easier to lose. **Fix is three guards layered in defence-in-depth.** **(1) Atomic CAS at the pending→printing transition.** Replaced `item.status = "printing"; await db.commit()` with `UPDATE print_queue SET status='printing', started_at=NOW() WHERE id=:id AND status='pending'`. If `rowcount == 0` the user already won the race; log the abort, best-effort `delete_file_async` the file we just FTP'd up to the printer's SD card (no leftover that would surface in BambuStudio's file picker), send a `queue_item_failed{reason: "cancelled_mid_dispatch"}` WebSocket event so the user sees their cancel actually took effect, and return WITHOUT calling `printer_manager.start_print`. The in-memory `item.status` / `item.started_at` are synced from the CAS values so the rest of `_start_print` reads consistent state for notifications. **(2) Early refresh + bail before FTP I/O.** Right after the printer-connectivity check (~line 2487) the scheduler now `await db.refresh(item)` and returns early if `item.status != "pending"`. Saves the wasted 5-30 s FTP upload when the user cancelled BEFORE the scheduler tick reached this row (the snapshot is taken at the top of `check_queue` but iterated through serially; with 10 items in the batch the last item can be picked up minutes after the snapshot, by which time it may already be `cancelled`). Not load-bearing for correctness — guard (1) catches the same case at the CAS point — but cuts wasted FTP bandwidth, printer SD writes, and downstream cleanup work. **(3) `flush()` → `commit()` before FTP.** Replaced the `await db.flush()` at line 2555 with `await db.commit()` so the library-file-to-archive promotion's writes (`item.archive_id` set, `library_file` deleted) commit cleanly before the FTP block. SQLite WAL writer lock releases immediately; concurrent writers — the sensor history task, the user's /cancel commit, the MQTT UPDATE path — stop queueing behind the scheduler's session. The flush-not-commit pattern existed because the original code wanted to roll back the archive promotion if a later step failed, but `archive_service.archive_print()` (called four lines above) had already committed the `PrintArchive` row in its own session, so the rollback was only ever rolling back the `item.archive_id` pointer back to NULL — which doesn't actually undo the archive creation. The new behaviour matches reality: archive is created (committed), pointer is set (committed), FTP runs without writer-lock contention. Subsequent failure paths still mark the item as `failed` correctly; they don't try to un-create the archive. **Tests.** Three new cases in `backend/tests/unit/test_scheduler_cancel_race.py`: `test_cancel_during_ftp_upload_aborts_before_mqtt` simulates the headline scenario (cancel commits in a separate session inside `upload_file_async`'s mock side-effect, then the CAS sees rowcount==0 → `start_print` mock asserted not-called → row stays `cancelled` → `started_at` stays `None` → two `delete_file_async` calls, one pre-upload sweep and one post-CAS cleanup); `test_cancel_before_ftp_upload_skips_dispatch` mirrors the early-bail path (row pre-cancelled before `_start_print` runs → upload never awaited → `start_print` never called); `test_happy_path_still_dispatches` is the regression guard so the CAS doesn't accidentally block normal dispatch on a row that was always pending. 3/3 green + 140/140 in the wider scheduler suite (`test_scheduler_cleanup_library.py`, `test_scheduler_preheat.py`, `test_scheduler_dispatch_hold.py`, `test_scheduler_watchdog.py`, `test_scheduler_ams_mapping.py`) regression-clean. **Scope.** Backend-only. No DB migration. No schema change. No new permission. No new i18n key. No frontend change — the existing `queue_item_failed` WebSocket toast already renders for the new `cancelled_mid_dispatch` reason via its generic display path. The `database is locked` errors are addressed structurally by guard (3); a more invasive session-lifetime restructure inside `_start_print` was considered and deferred — flush→commit catches the dominant offender (library-file-promoted dispatches, which the OP's 10-item batch hits per copy) without widening the change beyond what #1853 needs. + - **`Inject auto-print G-code` checkbox can be ticked in PrintModal create mode (#1852, reporter @Lamcois)** — Symptom: in v0.2.4.8 the user opens the print dialog for a single archive, sees the *Inject auto-print G-code* toggle next to the gcode-snippet section, clicks it, and the checkbox visually flips back to unchecked instantly. Submitting and then editing the queued item lets the same toggle be ticked normally — so the bug was only in the create-mode flow. **Root cause.** `PrintModal/index.tsx:947-955` carried a `useEffect` that reset `scheduleOptions.gcodeInjection` to `false` whenever `mode === 'create'` AND `(effectiveQuantity <= 1 || !settings?.gcode_snippets)`. The reset's stale code-comment claimed "the checkbox only renders for create + snippets configured + quantity > 1" — but the actual render gate in `ScheduleOptions.tsx:277` is just `{hasGcodeSnippets && (...)}` with no quantity check. So with snippets configured + quantity = 1 (the OP scenario): user clicks the checkbox → React updates state to `true` → the parent's useEffect immediately sees the gate's `effectiveQuantity <= 1` condition and resets it to `false` → the checkbox appears un-clickable. Edit-queue-item mode worked because `mode !== 'create'` short-circuited the reset before it could fire. **Fix.** Drop the `effectiveQuantity <= 1` clause from the reset. The legitimate cleanup that survives — the `!settings?.gcode_snippets` half — handles the actual edge case the effect was guarding against: an admin removing every snippet while the modal is open, in which case the checkbox's render gate hides the control but the boolean would otherwise still be `true` on submit. The scheduler's `_start_print` (`print_scheduler.py:2306`) reads `item.gcode_injection` per queue item regardless of batch size, so there's no underlying reason to block injection on single prints — that gate was inserted in error and never matched the render condition. **Tests.** New regression case in `frontend/src/__tests__/components/PrintModal.test.tsx`: `quantity 1 + snippets configured: checkbox toggles cleanly (#1852)` opens the modal in create mode at the default quantity = 1, asserts the checkbox starts unchecked, clicks it, `waitFor` confirms the displayed `checked` state stays `true` after re-render (the pre-fix reset would have flipped the displayed `checked` back to `false`), and confirms the `gcode_injection: true` flag actually reaches the queue API on submit. 61/61 in `PrintModal.test.tsx` (was 60 + 1 new). Existing batch-mode case (`injection ON queues all copies and dispatches none immediately`) still passes — my fix doesn't affect the quantity > 1 multi-copy fan-out path. **Scope.** Frontend-only, one-line behavioural change inside an existing effect. No backend change, no i18n key, no permission. - **`Ignore and Resume` now actually ignores the fault — wrong-plate HMS no longer re-pauses 1-2 s after click** — Symptom (continuation of #1869): clicking `Ignore and Resume` on a wrong-plate `0500_8051` HMS cleared the modal, the printer left PAUSE, then ~1-2 s later re-detected the wrong plate and re-paused with the identical HMS code — the modal popped back open and the user could not actually print on the "wrong" plate (the whole point of the Ignore button). **Root cause:** Bambuddy's `execute_hms_action` (`backend/app/services/bambu_mqtt.py:5496-5523`) redirected `IGNORE_RESUME` on `state == "PAUSE"` to a plain `resume` command, with a code comment claiming BambuStudio's "err-bearing shape" was "silently rejected by Bambu firmware" (verified during #1830). That diagnosis was wrong on two counts. (1) **`IGNORE_RESUME` doesn't map to `resume` at all in BambuStudio.** Source-of-truth from BambuStudio `src/slic3r/GUI/DeviceErrorDialog.cpp:600-602` and `src/slic3r/GUI/DeviceManager.cpp:1450-1462` (commit `4019d2e`): the button dispatches `command_hms_ignore`, whose wire shape is `{"print": {"command": "ignore", "err": "", "param": "reserve", "job_id": "", "sequence_id": "..."}}`. The firmware treats `command: "ignore"` as "suppress this check on the next attempt AND auto-resume the paused print" — semantically distinct from `command: "resume"` which means "I fixed the problem, re-check normally" and is exactly why the wrong-plate check re-fired. (2) **`err` is a DECIMAL string of the int, not the hex shortcode.** BambuStudio passes `std::to_string(m_error_code)` where `m_error_code` is the 32-bit `int` value of the print_error code — so for `0x05008051` the wire string is `"83918929"`, not `"05008051"`. The #1830 H2D test that "verified" the err-bearing shape was silently rejected almost certainly sent the hex string, which the firmware couldn't match against the active int fault → silent rejection looked like the entire shape was broken, when the actual problem was the format of one field. **Fix.** Replace the `hms_ignore(persistent)` helper with two distinct helpers matching BambuStudio's source: `hms_ignore_command()` publishes `command_hms_ignore`'s shape (`command: "ignore"`, decimal `err`, `param: "reserve"`, `job_id`); `hms_idle_ignore(persistent)` publishes `command_hms_idle_ignore`'s shape (`command: "idle_ignore"`, decimal `err`, `type: 0|1`). Wire `IGNORE_RESUME`, `IGNORE_NO_REMINDER_NEXT_TIME`, and `DONT_REMIND_NEXT_TIME` (alias) to `hms_ignore_command()` — BambuStudio routes all three to the same `command_hms_ignore` (`DeviceErrorDialog.cpp:596-602`), the "don't remind" half is the firmware's job. Wire `NO_REMINDER_NEXT_TIME` to `hms_idle_ignore(persistent=False)` — BambuStudio dispatches it via `command_hms_idle_ignore(..., 0)` (`DeviceErrorDialog.cpp:588-590`), distinct from the resume-bearing `ignore` command. The decimal-int conversion lives at the helper layer (`str(int(print_error, 16))` with a defensive fallback to the raw input on parse failure so the route can surface 502 rather than raising mid-dispatch). The `job_id=None` case sends an empty string, matching BambuStudio's `std::string` empty default. **Resume / stop unchanged** — the user has independently confirmed plain `resume` and plain `stop` work for `PROBLEM_SOLVED_RESUME` and `STOP_PRINTING` on their printer; BambuStudio's `command_hms_resume` / `command_hms_stop` do carry the same `err`+`param: "reserve"`+`job_id` fields, but changing a working shape without a field test risks regressing a path the user has confirmed, so the plain shape stays. The previous stale comments about "verified silently rejected" are removed and replaced with citations to BambuStudio's exact source lines. **Tests.** Six cases in `TestExecuteHmsActionDispatch` (`backend/tests/unit/services/test_hms_actions.py`) rewritten to assert the BambuStudio shape: `test_ignore_resume_sends_bambustudio_ignore_command_paused` pins the full payload (the exact #1869 trace), `test_ignore_resume_state_independent` confirms no PAUSE/RUNNING branch (BambuStudio's dispatch is unconditional), `test_ignore_no_reminder_uses_ignore_command_not_idle_ignore` pins the `DONT_REMIND_NEXT_TIME` → `command: "ignore"` route, `test_no_reminder_next_time_uses_idle_ignore_type_zero` pins the still-correct `NO_REMINDER_NEXT_TIME` → `idle_ignore` route (decimal `err` now), `test_ignore_accepts_16_char_full_code_as_decimal` covers the 64-bit hms[]-array fault shape, `test_ignore_with_no_job_id_sends_empty_string` pins the empty-string sentinel. 35/35 in `test_hms_actions.py`, 12/12 in HMS-touching `test_printers_api.py` integration cases, `ruff check` clean. **Scope.** Backend-only. Same modal, same API contract, same dispatch route — just a different MQTT command shape on the wire for the ignore branch. No DB migration, no permission, no i18n key. diff --git a/backend/app/services/print_scheduler.py b/backend/app/services/print_scheduler.py index a5a762398..fee1dc245 100644 --- a/backend/app/services/print_scheduler.py +++ b/backend/app/services/print_scheduler.py @@ -7,7 +7,7 @@ import time from datetime import datetime, timezone from pathlib import Path -from sqlalchemy import func, select +from sqlalchemy import func, select, update from sqlalchemy.ext.asyncio import AsyncSession from sqlalchemy.orm import selectinload @@ -2486,6 +2486,22 @@ class PrintScheduler: await self._power_off_if_needed(db, item) return + # Cancel-while-dispatching race (#1853): the scheduler's snapshot of + # `items` was taken at the top of check_queue, but the user can /cancel + # any pending row in the gap before we reach this point. Re-read the + # row and bail out cleanly instead of starting an FTP upload for a row + # that's already cancelled. The atomic CAS at the pending→printing + # transition (below, before start_print) is the load-bearing guard; + # this is the early-exit optimisation that avoids wasted FTP I/O. + await db.refresh(item) + if item.status != "pending": + logger.info( + "Queue item %s no longer pending (status=%s) — aborting dispatch", + item.id, + item.status, + ) + return + # Determine source: archive or library file archive = None library_file = None @@ -2552,7 +2568,12 @@ class PrintScheduler: await db.delete(library_file) file_path = settings.base_dir / archive.file_path filename = archive.filename - await db.flush() + # Commit, not flush — flush opens the SQLite write + # transaction (item.archive_id update + library_file + # delete) and would hold the WAL writer lock through the + # FTP upload below, causing "database is locked" cascades + # for sensor history + concurrent cancels (#1853). + await db.commit() logger.info( "Queue item %s: Created archive %s from library file %s", item.id, @@ -2789,9 +2810,57 @@ class PrintScheduler: # If we crash after this commit but before start_print(), the item will be # in "printing" status without actually printing - but that's safer than # accidentally reprinting the same file hours later. - item.status = "printing" - item.started_at = datetime.now(timezone.utc) + # + # Atomic CAS (#1853): a user pressing /cancel mid-dispatch (between the + # initial pending read at the top of check_queue and this point) flips + # the row to "cancelled" in a separate session. Without the WHERE + # status='pending' clause, the unconditional update here would silently + # overwrite that cancellation and we'd ship the MQTT start_print below + # — printer obeys, user sees "I pressed cancel and the print started". + # rowcount==0 means the user won the race; bail out, best-effort delete + # the file we just uploaded, do NOT send start_print. + now_utc = datetime.now(timezone.utc) + cas = await db.execute( + update(PrintQueueItem) + .where(PrintQueueItem.id == item.id) + .where(PrintQueueItem.status == "pending") + .values(status="printing", started_at=now_utc) + ) await db.commit() + if cas.rowcount == 0: + logger.info( + "Queue item %s no longer pending at print-command time " + "(cancelled or removed mid-dispatch) — aborting before MQTT send (#1853)", + item.id, + ) + try: + await delete_file_async( + printer.ip_address, + printer.access_code, + remote_path, + socket_timeout=ftp_timeout, + printer_model=printer.model, + ) + except Exception as cleanup_err: + logger.debug( + "Queue item %s: best-effort cleanup of uploaded file failed: %s", + item.id, + cleanup_err, + ) + try: + await ws_manager.send_queue_item_failed( + user_id=toast_uid, + queue_item_id=item.id, + printer_id=item.printer_id, + reason="cancelled_mid_dispatch", + ) + except Exception: + pass + return + # Sync the in-memory item so subsequent code that reads item.status / + # item.started_at sees the values we just persisted. + item.status = "printing" + item.started_at = now_utc for cleanup_path in cleanup_disk_paths: try: diff --git a/backend/tests/unit/test_scheduler_cancel_race.py b/backend/tests/unit/test_scheduler_cancel_race.py new file mode 100644 index 000000000..54113c6e1 --- /dev/null +++ b/backend/tests/unit/test_scheduler_cancel_race.py @@ -0,0 +1,237 @@ +"""Cancel-during-dispatch race regression (#1853). + +The user reported: queued a batch of 10 prints, pressed Cancel on a pending +item, the print started anyway. Root cause is a check-then-act race in +``_start_print``: the snapshot of pending items is taken at the top of +``check_queue``, then ``_start_print`` does FTP delete + FTP upload (5-30 s) +before flipping the row to ``"printing"`` and sending MQTT. If the user wins +the race and ``/cancel`` lands during that window, the scheduler's stale +in-memory write of ``status="printing"`` silently overwrites the cancellation. + +Three guards exercised here: + +* Early refresh after the connectivity check — bails before FTP I/O if the + row is already cancelled. +* Atomic CAS at the pending→printing transition — UPDATE WHERE + status='pending'; rowcount==0 means user won, do NOT send MQTT. +* Best-effort delete of the file we just FTP'd up when the CAS aborts. +""" + +from contextlib import ExitStack +from pathlib import Path +from types import SimpleNamespace +from unittest.mock import AsyncMock, MagicMock, patch + +import pytest +from sqlalchemy.ext.asyncio import async_sessionmaker, create_async_engine + +import backend.app.models # noqa: F401 - populate Base.metadata +import backend.app.services.print_scheduler as scheduler_module +from backend.app.core.database import Base +from backend.app.models.archive import PrintArchive +from backend.app.models.print_queue import PrintQueueItem +from backend.app.models.printer import Printer +from backend.app.services.print_scheduler import PrintScheduler + + +@pytest.fixture +async def queue_factory(tmp_path): + engine = create_async_engine("sqlite+aiosqlite:///:memory:", echo=False) + async with engine.begin() as conn: + await conn.run_sync(Base.metadata.create_all) + + session_maker = async_sessionmaker(engine, expire_on_commit=False) + case_counter = 0 + + async def make_case(*, status="pending"): + nonlocal case_counter + case_counter += 1 + + base_dir = tmp_path / f"case-{case_counter}" + base_dir.mkdir() + archive_rel = Path("archives") / f"job-{case_counter}.3mf" + archive_abs = base_dir / archive_rel + archive_abs.parent.mkdir(parents=True, exist_ok=True) + archive_abs.write_bytes(b"archive payload") + + async with session_maker() as db: + printer = Printer( + name=f"Printer {case_counter}", + serial_number=f"SERIAL-{case_counter}", + ip_address="127.0.0.1", + access_code="access-code", + model="X1C", + ) + db.add(printer) + await db.flush() + + archive = PrintArchive( + printer_id=printer.id, + filename=f"job-{case_counter}.3mf", + file_path=str(archive_rel), + file_size=archive_abs.stat().st_size, + content_hash=None, + thumbnail_path=None, + timelapse_path=None, + print_time_seconds=120, + status="completed", + ) + db.add(archive) + await db.flush() + + item = PrintQueueItem( + printer_id=printer.id, + archive_id=archive.id, + status=status, + bed_levelling=True, + flow_cali=False, + vibration_cali=True, + layer_inspect=False, + timelapse=False, + use_ams=True, + nozzle_offset_cali=True, + ) + db.add(item) + await db.commit() + + return SimpleNamespace( + session_maker=session_maker, + base_dir=base_dir, + archive_path=archive_abs, + printer_id=printer.id, + archive_id=archive.id, + queue_item_id=item.id, + upload=AsyncMock(return_value=True), + start_print=MagicMock(return_value=True), + delete_file=AsyncMock(return_value=True), + ) + + try: + yield make_case + finally: + await engine.dispose() + + +async def _dispatch(ctx, *, upload_side_effect=None): + scheduler = PrintScheduler() + + if upload_side_effect is not None: + ctx.upload.side_effect = upload_side_effect + + patches = [ + patch.object(scheduler_module.settings, "base_dir", ctx.base_dir), + patch("backend.app.services.print_scheduler.printer_manager.is_connected", MagicMock(return_value=True)), + patch("backend.app.services.print_scheduler.printer_manager.get_status", MagicMock(return_value=None)), + patch("backend.app.services.print_scheduler.printer_manager.start_print", ctx.start_print), + patch("backend.app.services.print_scheduler.printer_manager.set_awaiting_plate_clear", MagicMock()), + patch( + "backend.app.services.print_scheduler.get_ftp_retry_settings", + AsyncMock(return_value=(False, 0, 0, 1.0)), + ), + patch("backend.app.services.print_scheduler.delete_file_async", ctx.delete_file), + patch("backend.app.services.print_scheduler.upload_file_async", ctx.upload), + patch("backend.app.services.print_scheduler.cache_3mf_download", MagicMock()), + patch("backend.app.services.print_scheduler.spawn_background_task", MagicMock()), + patch( + "backend.app.services.notification_service.notification_service.on_queue_job_started", + AsyncMock(), + ), + patch( + "backend.app.services.notification_service.notification_service.on_queue_job_failed", + AsyncMock(), + ), + patch("backend.app.services.mqtt_relay.mqtt_relay.on_queue_job_started", AsyncMock()), + patch.object(scheduler, "_propagate_owner_to_printer_manager", AsyncMock()), + patch.object(scheduler, "_power_off_if_needed", AsyncMock()), + patch.object(scheduler, "_preheat_and_soak", AsyncMock()), + ] + + with ExitStack() as stack: + for patcher in patches: + stack.enter_context(patcher) + + async with ctx.session_maker() as db: + item = await db.get(PrintQueueItem, ctx.queue_item_id) + await scheduler._start_print(db, item) + + +async def _final_status(ctx): + async with ctx.session_maker() as db: + item = await db.get(PrintQueueItem, ctx.queue_item_id) + return item.status, item.started_at + + +@pytest.mark.asyncio +async def test_cancel_during_ftp_upload_aborts_before_mqtt(queue_factory): + """User wins the race during the FTP upload — CAS must detect & bail. + + This is the headline #1853 scenario: snapshot saw pending, FTP upload + starts, user clicks Cancel, /cancel commits ``cancelled`` to the row, + FTP finishes successfully, scheduler reaches the CAS. CAS rowcount must + be 0; ``printer_manager.start_print`` must NOT be called; row must stay + ``cancelled``; uploaded file must be deleted from the printer's SD. + """ + ctx = await queue_factory() + + async def cancel_mid_upload(*args, **kwargs): + # Simulate /cancel landing in a separate session while FTP is in + # flight. The endpoint commits status='cancelled' then returns 200. + async with ctx.session_maker() as other_db: + other_item = await other_db.get(PrintQueueItem, ctx.queue_item_id) + other_item.status = "cancelled" + await other_db.commit() + return True + + await _dispatch(ctx, upload_side_effect=cancel_mid_upload) + + status, started_at = await _final_status(ctx) + assert status == "cancelled", "CAS overwrote the user's cancellation" + assert started_at is None, "started_at must not be stamped on a cancelled row" + ctx.start_print.assert_not_called() + # Two delete calls — the pre-upload sweep and the post-CAS cleanup. + assert ctx.delete_file.await_count == 2 + + +@pytest.mark.asyncio +async def test_cancel_before_ftp_upload_skips_dispatch(queue_factory): + """Early-refresh path: row was cancelled before _start_print resumed. + + Mirrors the case where ``/cancel`` lands between the ``check_queue`` + snapshot and the time ``_start_print`` runs. The early ``db.refresh`` + after the connectivity check sees ``cancelled`` and returns immediately + — no FTP upload, no MQTT send, row unchanged. + """ + ctx = await queue_factory() + + # Flip to cancelled before _start_print runs; the in-memory snapshot + # the scheduler holds still reads 'pending', exactly the bug shape. + async with ctx.session_maker() as other_db: + item = await other_db.get(PrintQueueItem, ctx.queue_item_id) + item.status = "cancelled" + await other_db.commit() + + await _dispatch(ctx) + + status, started_at = await _final_status(ctx) + assert status == "cancelled" + assert started_at is None + ctx.upload.assert_not_awaited() + ctx.start_print.assert_not_called() + + +@pytest.mark.asyncio +async def test_happy_path_still_dispatches(queue_factory): + """Sanity: no cancel, no race — pending row flips to printing, MQTT fires. + + Regression guard so the CAS doesn't accidentally block normal dispatch + on a row that was always pending. + """ + ctx = await queue_factory() + + await _dispatch(ctx) + + status, started_at = await _final_status(ctx) + assert status == "printing" + assert started_at is not None + ctx.upload.assert_awaited_once() + ctx.start_print.assert_called_once()