fix(dispatch): don't send start-print to a busy printer; scheduler defers (#2598)

start_print() published project_file guarding only on connection state, so a
re-dispatch onto a printer that had already started — e.g. a watchdog revert
(#2555) after the printer sat in FINISH past accepting the job — collided with
the live print. The firmware answers 0500_4004 ("Device is busy and cannot
start a new task"), which on an A1 mini cancels the running job.

Defense-in-depth at the paths that can reach a busy printer:

- bambu_mqtt: refuse to publish project_file when gcode_state is
  PREPARE/SLICING/RUNNING/PAUSE and return without sending. This is the one
  publish choke point every dispatch path funnels through (queue scheduler,
  manual start, webhook, Virtual-Printer forward). IDLE/FINISH/FAILED still
  start.
- print_scheduler: re-check the live printer state right before the FTP upload
  and defer a busy printer (leave the item pending for a later tick) instead of
  uploading and dispatching. If the printer goes busy in the upload window and
  the start is refused, revert the item to pending rather than marking it
  failed — a busy printer is a deferral, not a failure.

A transport-level MQTT QoS-1 replay on reconnect would bypass the client guard,
but the dispatch/watchdog reconnect path already hard-resets the client with a
fresh session, so it has no inflight project_file to replay.
This commit is contained in:
maziggy
2026-07-18 16:41:15 +02:00
parent 80687982c1
commit d7093c7fe4
5 changed files with 297 additions and 0 deletions
+1
View File
@@ -8,6 +8,7 @@ All notable changes to Bambuddy will be documented in this file.
- **Orca Cloud profile sync now connects by approving a code instead of the copy-paste sign-in** — Connecting Bambuddy to Orca Cloud used to mean opening an OAuth sign-in in a new tab, watching it redirect to a `localhost` URL that fails to load, then copying that dead URL out of the address bar and pasting it back into Bambuddy. That dance existed only because Orca's auth backend (Supabase) accepts no redirect target other than `localhost`, and the deliberately-broken redirect page confused nearly everyone who reached it. OrcaSlicer has since shipped a first-class external-app pairing API (the OAuth 2.0 Device Authorization Grant, RFC 8628), so the flow is now: click **Connect**, approve a short code on your Orca Cloud settings page, and Bambuddy pairs itself — no redirect, no paste, no client secret, and it behaves identically from a LAN IP, `localhost`, or behind a reverse proxy. Bambuddy requests **read-only** access (it only lists and views your Orca Cloud profiles), keeps the pairing alive with the API's rotating refresh tokens (validated end-to-end against Orca's staging and production servers), and stores nothing beyond the issued token pair. The profile list and detail views are unchanged, so nothing downstream of the connect step looks different. The old paste-based sign-in and the email/password fallback are removed. Points at production Orca Cloud by default; `ORCA_CLOUD_API_BASE` overrides the endpoint for testing.
### Fixed
- **A start-print dispatched to an already-busy printer could cancel the running job (#2598, reporter @khaosdoctor)** — On an A1 mini across a night of prints, jobs were cancelled with no apparent cause; debug logs showed Bambuddy sending `project_file` twice ~3 minutes apart with no completion between, and the printer answering `0500_4004` ("Device is busy and cannot start a new task") — which on that model cancels the RUNNING print. **Root cause.** `start_print()` in the MQTT client guarded only on connection state (`self._client and self.state.connected`) — it published `project_file` with no check on the printer's `gcode_state`. The scheduler *does* gate dispatch on an idle check, but that check treats `FINISH` as idle, and a printer can keep reporting `FINISH` for tens of seconds *after* it accepted a `project_file`; combined with a dispatch watchdog that reverts a queue item and releases its dispatch hold when it doesn't observe the active-state transition in time (#2555), a re-selected item could reach the FTP upload while the printer had actually started, so the start command landed on a live print. **Fix (defense-in-depth).** (a) `start_print()` now refuses to publish `project_file` when the printer is in an active state (`PREPARE` / `SLICING` / `RUNNING` / `PAUSE`) and returns without sending — a single guard at the one publish choke point that every dispatch path (queue, manual, webhook, Virtual-Printer forward) funnels through. `IDLE` / `FINISH` / `FAILED` remain valid start targets. (b) The scheduler re-checks the live printer state right before the FTP upload and *defers* a busy printer (leaves the item pending for a later tick) instead of uploading and dispatching — no wasted transfer, no collision. (c) If the printer goes busy during the upload window and the start command is refused, the scheduler reverts the item to pending (a deferral) rather than marking it failed — a busy printer is not a failure. Covered by tests for the client-level guard (refused while busy, published while idle, guard precedes the connection check) and the scheduler deferring both before the upload and after a busy-refused start. Note: a transport-level MQTT QoS-1 replay on reconnect would bypass the client guard, but the dispatch/watchdog reconnect path already hard-resets the client with a fresh session so it has no inflight `project_file` to replay.
- **Three more idle-in-transaction / thundering-herd paths surfaced by continued farm testing (#2572, reporter @Jostxxl)** — On `origin/dev` with 93 printers and multiple concurrent UI clients the reporter timestamp-correlated the surviving pool pressure to three remaining paths, none of them auth-related. **(a) The scheduler held its per-item session across preheat and the FTP upload.** `_dispatch_selected` opens one `async_session` per queue item and hands it to `_start_print`, which reads the printer/archive rows up front and then runs the preheat/heat-soak wait and the FTP delete+upload — all on the transaction opened by those first `SELECT`s. One correlated session's last statement was a `settings` `SELECT` at the exact moment the log showed "Starting queue item" → preheat → "FTP upload started" for a 96 MB 3MF; the transaction stayed open for the whole transfer. (This refines the earlier note that the scheduler paths were "already bounded" — the per-item session itself was the hold.) `_start_print` now commits right before the FTP delete/upload, and `_preheat_and_soak` commits after its read phase and before the up-to-15-minute soak wait (both loops touch only `printer_manager` state and `asyncio.sleep`, no DB). `expire_on_commit=False` keeps the loaded rows readable; the status writes afterward (upload-failure path and the pending→printing CAS) transparently open a fresh transaction. **(b) `/cloud/filament-info` held its request session across sequential Bambu Cloud round-trips and single-flighted nothing.** The route took its session via `Depends(get_db)` (held for the whole request), read the stored token, then looped over the uncached ids issuing one external `get_setting_detail` HTTP call each — so the session sat idle-in-transaction across N cloud calls, and because the printer overview mounts one filament-info request per printer card, several browsers hit the same uncached preset at once and each issued its own cloud call. The route now releases the transaction (`rollback`) right after the token read and before the cloud loop (Phase 3's local-preset read reopens a fresh one), and concurrent misses for the same id single-flight through one shared cloud call. **(c) `/printers/{id}/cover` had no in-flight coalescing.** The connection was already released before the download, but simultaneous clients could all miss the cache and each run the full multi-path FTP lookup + 3MF extraction (one observed transfer pulled an 81 MB 3MF while real print uploads were in flight). Identical concurrent cover requests now coalesce: the first becomes the leader and the rest await it, then serve from the positive/negative cache it filled. Also adds `pool_use_lifo` (PostgreSQL default on, `DB_POOL_USE_LIFO` override, shown in `/system/db-pool`) so a bursty farm keeps a small hot connection set busy and lets excess overflow connections age out via `pool_recycle` instead of churning the whole pool. Covered by tests: the scheduler releasing its connection before both the FTP upload and the soak wait, the filament-info single-flight (concurrent misses share one cloud call, cache-hit skips cloud, a failed fetch leaves no stuck in-flight entry), and concurrent cover requests downloading once.
- **An "Any [model]" queue job dispatched from a Virtual Printer printed to the empty external spool and aborted at layer 0 (#2595, diagnosed by @Sawtaytoes, PR #2596)** — On a farm of identical X1Cs with different filaments loaded per AMS, the intended flow — VP in Queue mode, auto-dispatch, target **Any X1C**, force-colour-match picks the printer that has the right spool — sent the job to the correctly-matched printer and then failed: the printer ignored the AMS, pulled the empty external spool, and aborted with "not enough filament", even though the mapped slot was loaded (the same print via a specific printer, or straight from the slicer, worked). **Root cause.** A slicer talking to a Virtual Printer only ever sees the VP's external spool — a VP advertises no AMS — so the slicer sends `use_ams=false`, and VP intake stamps that onto the queue item. But an "Any [model]" item is colour-matched to a real printer *at dispatch*, resolving a real AMS slot in `ams_mapping`; the scheduler still forwarded the stale `use_ams=false`. The print-command builder only ever forced `use_ams` **off** (the all-external case) and never back **on**, so `use_ams=false` shipped alongside `ams_mapping=[<real tray>]` → external spool → abort. **Fix.** For single-nozzle printers the resolved mapping is now authoritative: a real AMS tray (0-253) forces `use_ams=true`; an explicit external selection (254/255) still forces it false; an unresolved `-1` mapping does neither (preserving the #2589 contract — it should have been recomputed upstream, and must not be silently promoted to AMS or downgraded to external). Dual-nozzle printers are untouched, where `use_ams` encodes nozzle routing rather than an on/off flag. Because the correction lives at the single command-builder choke point, it fixes the VP, queue, and manual paths alike. Covered by tests for the VP `false`+real-tray promotion, padded mappings, all-external staying off, unresolved `-1` staying put, the original all-external downgrade, and the dual-nozzle bypass.
- **Reconnecting or restarting inflated Stats → Total Print Time by hundreds of hours on large farms (#2592, reporter @Jostxxl)** — On the reporter's farm a restart pushed Total Print Time from ~1,500h to 3,215h. When a printer reconnects, the connected edge runs `reconcile_stale_active_prints`, which closes out every archive still stuck in `status="printing"` (missed completions, disconnects, restarts) by synthesising an aborted `on_print_complete`. That wrote a `PrintLogEntry` whose duration was `completed_at - started_at` — but for a reconciled archive the real end time is unknown: the print stopped somewhere during the disconnect, and `completed_at` is only the reconnect moment. So each stale archive banked its entire multi-day gap as print time (one row was 51.9h), and a printer with several stale archives contributed hundreds of fabricated hours at once. Worse, the Stats total *recomputed* `completed_at - started_at` whenever the stored duration was falsy, so storing NULL wouldn't have helped. Reconciled completions now log an explicit `duration_seconds = 0` (honest "no measured runtime") and the two Stats time paths trust a stored 0 instead of recomputing from the stale timestamps — legacy rows that never recorded a duration still fall back as before. Reconciled aborts also get a truthful `failure_reason` ("Stale - reconciled after reconnect, end time unknown") instead of being mislabelled "User cancelled". Genuine long prints are untouched: nothing is capped, a still-running >24h print is never treated as stale, and a real >24h run keeps its full measured duration. Re-running reconciliation is already idempotent (the archive flips to `aborted`, so it isn't re-selected). Existing inflated rows from before this fix are not auto-corrected — they're indistinguishable from real cancellations in the database, and a blanket cap would clobber genuine long prints; the reporter repaired his own rows by hand. Covered by tests for the multi-day reconcile, multiple stale archives per printer, a retained >24h print, and the Stats total ignoring reconciled time while still counting real runtime.
+32
View File
@@ -32,6 +32,14 @@ logger = logging.getLogger(__name__)
# "n3s/<id>" – AMS HT (H2D Pro and similar; IDs typically start at 128)
_AMS_MODULE_PREFIXES = ("ams/", "n3f/", "n3s/")
# gcode_state values that mean the printer is not idle and must not be handed a
# new start-print (#2598). The firmware rejects a project_file while busy with
# 0500_4004 "Device is busy and cannot start a new task", and on some models
# (A1 mini reported) that error cancels the RUNNING job. IDLE / FINISH / FAILED
# are valid start targets and are deliberately excluded. Mirrors
# printer_manager.ACTIVE_PRINT_STATES and print_scheduler._ACTIVE_PRINT_STATES.
_ACTIVE_PRINT_STATES = frozenset({"PREPARE", "SLICING", "RUNNING", "PAUSE"})
def parse_ams_filament_backup_from_cfg(cfg_raw: object) -> bool | None:
"""Extract AMS Filament Backup state from a Bambu push_status ``print.cfg`` value.
@@ -3851,7 +3859,31 @@ class BambuMQTTClient:
firmware honours the user's slicer pick instead of falling
back to "last matching nozzle" auto-pick. Silently ignored
on single-nozzle printers.
Returns True when the start command was published, False otherwise
(not connected, or the printer is already busy — see the run-state
guard below).
"""
# Never dispatch project_file to a printer that is not idle (#2598).
# This is the single publish choke point for every dispatch path — the
# queue scheduler, a manual start, a webhook, and a Virtual-Printer
# forwarded job all funnel through here — so one guard covers them all.
# The firmware rejects a start while busy with 0500_4004 ("Device is
# busy and cannot start a new task"), and on an A1 mini that error
# cancels the RUNNING job (#2598). IDLE / FINISH / FAILED are valid
# start targets; only the active-print states are refused. (A
# transport-level QoS-1 replay on reconnect would bypass this guard,
# but the dispatch/watchdog reconnect path hard-resets the client with a
# fresh client_id, so paho has no inflight project_file to replay there.)
if self.state.state in _ACTIVE_PRINT_STATES:
logger.warning(
"[%s] start_print refused: printer busy (gcode_state=%s) — not publishing project_file for %s",
self.serial_number,
self.state.state,
filename,
)
return False
if self._client and self.state.connected:
# Bambu print command format — matches Bambu Studio's format.
# The calibration/leveling fields (timelapse, bed_leveling,
+45
View File
@@ -2868,6 +2868,28 @@ class PrintScheduler:
)
return
# Busy-printer guard (#2598). check_queue gates dispatch on
# _is_printer_idle(), but that treats FINISH as idle and a printer can
# keep reporting FINISH for tens of seconds *after* it accepted a
# project_file (see the watchdog's phase-B note). A watchdog revert
# (#2555) also releases the dispatch hold, so a re-selected item can
# reach here while its printer has actually started printing. Uploading
# and dispatching then collides with the live job — the firmware answers
# 0500_4004 and, on an A1 mini, cancels the running print. Re-check the
# live state right before the expensive FTP upload: if the printer is
# busy, leave the item pending and let a later tick dispatch it once the
# printer is genuinely idle. No wasted upload, no collision.
pre_dispatch_state = getattr(printer_manager.get_status(item.printer_id), "state", None)
if pre_dispatch_state in _ACTIVE_PRINT_STATES:
logger.info(
"Queue item %s: printer %s is busy (state=%s) — deferring dispatch, "
"leaving item pending for a later tick (#2598)",
item.id,
item.printer_id,
pre_dispatch_state,
)
return
# Determine source: archive or library file
archive = None
library_file = None
@@ -3447,6 +3469,29 @@ class PrintScheduler:
except Exception:
pass # Best-effort — don't fail the error handler
# Busy-refusal is a deferral, not a failure (#2598). The printer's
# state can flip from idle to active in the window between the
# pre-dispatch check above and this publish (the FTP upload takes
# seconds); start_print() then refuses to send project_file to the
# now-busy printer and returns False. Failing the item here would be
# wrong — the printer is fine, it is simply busy — so revert to
# pending and let a later tick dispatch it once the printer is idle,
# exactly like the pre-dispatch guard. Only a start_print() False on
# an idle/unknown printer is a genuine command failure.
post_dispatch_state = getattr(printer_manager.get_status(item.printer_id), "state", None)
if post_dispatch_state in _ACTIVE_PRINT_STATES:
logger.info(
"Queue item %s: printer %s became busy (state=%s) before the start "
"command was sent — deferring, reverting item to pending (#2598)",
item.id,
item.printer_id,
post_dispatch_state,
)
item.status = "pending"
item.started_at = None
await db.commit()
return
# Print command failed - revert status
item.status = "failed"
item.error_message = "Failed to send print command to printer"
@@ -0,0 +1,60 @@
"""start_print() must not publish project_file to a busy printer (#2598).
The firmware rejects a start command while the printer is not idle with
0500_4004 ("Device is busy and cannot start a new task"), and on an A1 mini
that error cancels the RUNNING job. Because every dispatch path (queue
scheduler, manual start, webhook, Virtual-Printer forward) funnels through
BambuMQTTClient.start_print, a run-state guard here covers them all.
IDLE / FINISH / FAILED are valid start targets; only PREPARE / SLICING /
RUNNING / PAUSE are refused.
"""
import json
from unittest.mock import MagicMock
import pytest
from backend.app.services.bambu_mqtt import BambuMQTTClient
def _connected_client() -> BambuMQTTClient:
client = BambuMQTTClient(ip_address="127.0.0.1", serial_number="TEST123", access_code="12345678")
client._client = MagicMock()
client.state.connected = True
return client
@pytest.mark.parametrize("busy_state", ["RUNNING", "PREPARE", "PAUSE", "SLICING"])
def test_start_print_refused_when_printer_busy(busy_state):
client = _connected_client()
client.state.state = busy_state
result = client.start_print("job.3mf")
assert result is False, f"start_print should refuse while {busy_state}"
client._client.publish.assert_not_called()
@pytest.mark.parametrize("idle_state", ["IDLE", "FINISH", "FAILED"])
def test_start_print_publishes_when_printer_idle(idle_state):
client = _connected_client()
client.state.state = idle_state
result = client.start_print("job.3mf")
assert result is True, f"start_print should proceed while {idle_state}"
client._client.publish.assert_called_once()
topic, payload = client._client.publish.call_args.args[:2]
assert json.loads(payload)["print"]["command"] == "project_file"
def test_busy_guard_takes_precedence_over_disconnected():
"""A busy printer is refused even if the connection flag is stale/false —
the guard runs before the connection check, so no publish is attempted."""
client = _connected_client()
client.state.connected = False
client.state.state = "RUNNING"
assert client.start_print("job.3mf") is False
client._client.publish.assert_not_called()
@@ -0,0 +1,159 @@
"""The scheduler defers (never fails) a dispatch that hits a busy printer (#2598).
check_queue gates dispatch on _is_printer_idle(), but that treats FINISH as
idle and a printer can keep reporting FINISH for tens of seconds after it
accepted a project_file; a watchdog revert (#2555) also releases the dispatch
hold. So a re-selected item can reach _start_print while its printer has
actually started printing. Two guards keep that from cancelling the live job:
* pre-dispatch — before the FTP upload, a busy printer defers (item stays
pending), so there is no wasted upload and no start command;
* post-dispatch — if the printer goes busy in the upload window and
start_print() returns False, the item is reverted to pending (deferred), not
marked failed.
"""
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 dispatch_case(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)
base_dir = tmp_path / "case"
base_dir.mkdir()
archive_rel = Path("archives") / "job.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="Printer",
serial_number="SERIAL",
ip_address="127.0.0.1",
access_code="access-code",
model="A1MINI",
)
db.add(printer)
await db.flush()
archive = PrintArchive(
printer_id=printer.id,
filename="job.3mf",
file_path=str(archive_rel),
file_size=archive_abs.stat().st_size,
status="completed",
)
db.add(archive)
await db.flush()
item = PrintQueueItem(printer_id=printer.id, archive_id=archive.id, status="pending")
db.add(item)
await db.commit()
ids = SimpleNamespace(printer_id=printer.id, archive_id=archive.id, item_id=item.id)
try:
yield SimpleNamespace(session_maker=session_maker, base_dir=base_dir, ids=ids)
finally:
await engine.dispose()
def _base_patches(scheduler, ctx, upload_mock, start_print_mock, get_status):
return [
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", get_status),
patch("backend.app.services.print_scheduler.printer_manager.start_print", start_print_mock),
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", AsyncMock(return_value=True)),
patch("backend.app.services.print_scheduler.upload_file_async", upload_mock),
patch("backend.app.services.print_scheduler.cache_3mf_download", MagicMock()),
patch("backend.app.services.print_scheduler.spawn_background_task", MagicMock()),
patch.object(scheduler, "_propagate_owner_to_printer_manager", AsyncMock()),
patch.object(scheduler, "_power_off_if_needed", AsyncMock()),
patch.object(scheduler, "_preheat_and_soak", AsyncMock()),
]
async def _final_item(ctx):
async with ctx.session_maker() as db:
return await db.get(PrintQueueItem, ctx.ids.item_id)
@pytest.mark.asyncio
async def test_pre_dispatch_busy_defers_without_upload(dispatch_case):
"""Printer already RUNNING when _start_print begins → defer, no upload/start."""
scheduler = PrintScheduler()
upload = AsyncMock(return_value=True)
start_print = MagicMock(return_value=True)
get_status = MagicMock(return_value=SimpleNamespace(state="RUNNING", subtask_id=None, gcode_file=None))
async with dispatch_case.session_maker() as db:
item = await db.get(PrintQueueItem, dispatch_case.ids.item_id)
with ExitStack() as stack:
for p in _base_patches(scheduler, dispatch_case, upload, start_print, get_status):
stack.enter_context(p)
await scheduler._start_print(db, item)
upload.assert_not_awaited()
start_print.assert_not_called()
final = await _final_item(dispatch_case)
assert final.status == "pending", "a busy printer must defer the item, not consume it"
@pytest.mark.asyncio
async def test_post_dispatch_busy_reverts_to_pending_not_failed(dispatch_case):
"""Printer goes busy in the upload window; start_print returns False → defer."""
scheduler = PrintScheduler()
upload = AsyncMock(return_value=True)
holder = {"state": "IDLE"}
class _Status:
subtask_id = None
gcode_file = None
@property
def state(self):
return holder["state"]
def _start_print(*args, **kwargs):
# The printer became busy between the pre-dispatch check and the publish.
holder["state"] = "RUNNING"
return False # start_print() refused: busy
start_print = MagicMock(side_effect=_start_print)
get_status = MagicMock(return_value=_Status())
async with dispatch_case.session_maker() as db:
item = await db.get(PrintQueueItem, dispatch_case.ids.item_id)
with ExitStack() as stack:
for p in _base_patches(scheduler, dispatch_case, upload, start_print, get_status):
stack.enter_context(p)
await scheduler._start_print(db, item)
upload.assert_awaited_once() # it proceeded past the (idle) pre-dispatch check
start_print.assert_called_once()
final = await _final_item(dispatch_case)
assert final.status == "pending", "a busy-refused start must defer, not fail the item"
assert final.started_at is None