Say when AMS drying was running and a print never started (#2758)

    Dispatching to an X2D with two AMS units mid-drying failed silently: the
    file uploaded, the printer accepted it and stayed idle. The watchdog waits
    for an active state or HMS_MQTT_VERIFY_FAILED, and a drying refusal is
    neither, so it timed out, re-uploaded the whole 3MF twice more, and closed
    with advice about the printer screen and the SD card. Studio, asked
    directly, said it could not start the job because of the drying.

    Latch the AMS dry_time telemetry across both watchdog phases and name the
    units in the give-up message, plus an INFO log on every failed window so
    the correlation reaches a support bundle from the first attempt.

    Detection only, no gate. These models support drying CONTINUING through a
    print (supports_drying_while_printing covers X2D from 01.01.00.00), so
    drying is not incompatible with printing and stopping it before every
    dispatch would tear down cycles the hardware is happy to run. One of the
    two units was also drying without its external PSU, which would make this a
    power budget problem at start-of-print calibration rather than a drying one
    -- dry_sf_reason 1/8 exist for exactly that. The message names both
    possibilities rather than asserting one.

    Also correct _sync_drying_state's docstring, which claimed to adopt drying
    it did not start; it only prunes. Behaviour unchanged -- populating it would
    let the scheduler stop a cycle the user started by hand.

backend/app/services/print_scheduler.py

@@ -324,6 +324,34 @@ def _mqtt_commands_rejected(status) -> bool:
     return False
 
 
+def _drying_ams_ids(status) -> list[int]:
+    """AMS unit ids currently running a drying cycle, per firmware telemetry.
+
+    ``dry_time`` is minutes remaining, so >0 is the firmware's own statement that
+    a cycle is active. Used by the dispatch watchdog to say *why* a print never
+    started (#2758) — it is a diagnostic, not a gate.
+
+    Deliberately not used to block or stop drying before dispatch. This printer
+    class supports drying concurrently with an active print
+    (``supports_drying_while_printing``), so drying is not incompatible with
+    printing in general; what #2758 shows is one X2D refusing to *begin* a print
+    while two AMS units were drying, one of them without its external PSU. Until
+    it is known whether the blocker is drying itself or the power budget
+    (``dry_sf_reason`` 1 / 8), acting on this would tear down drying that the
+    hardware is perfectly happy to continue.
+    """
+    ids: list[int] = []
+    for unit in (getattr(status, "raw_data", None) or {}).get("ams") or []:
+        if not isinstance(unit, dict):
+            continue
+        try:
+            if int(unit.get("dry_time") or 0) > 0:
+                ids.append(int(unit.get("id", 0)))
+        except (TypeError, ValueError):
+            continue
+    return ids
+
+
 def _installed_nozzle_diameters(status) -> list[float]:
     """Parse the installed nozzle diameters from a PrinterState (#1899).
 
@@ -2713,10 +2741,18 @@ class PrintScheduler:
                     self._drying_in_progress[pid] = time.monotonic()
 
     def _sync_drying_state(self):
-        """Sync in-memory drying state with actual printer status.
-
-        Handles backend restart — if a printer is drying but we don't know about it,
-        update our state. If we think it's drying but it's not, clear it.
+        """Drop printers from ``_drying_in_progress`` that are no longer drying.
+
+        One direction only: it prunes, it never adds. A printer drying without an
+        entry here — because the user started the cycle from Studio, the printer's
+        screen or Bambuddy's own manual Dry button, or because Bambuddy restarted
+        mid-cycle — stays unknown to the scheduler, so the "print takes priority"
+        stop at ``check_queue`` only ever applies to cycles Bambuddy itself began.
+
+        That is deliberate for now rather than an oversight: populating this from
+        telemetry would hand the scheduler authority to stop drying a user started
+        by hand. It also means the backend-restart case this used to claim to
+        handle is not handled.
         """
         to_remove = []
         for pid in self._drying_in_progress:
@@ -4122,6 +4158,11 @@ class PrintScheduler:
         # every push carrying an `hms` key, so the fault can come and go between
         # 3-second polls. Seeing it once inside the dispatch window is enough.
         command_rejected = False
+        # Latched for the same reason as command_rejected: drying can finish, or
+        # be stopped by the user, part-way through the dispatch window. Seeing it
+        # once is what matters — it is the state the printer was in when it
+        # declined to start (#2758).
+        drying_ams_ids: list[int] = []
         deadline = time.monotonic() + timeout
         while time.monotonic() < deadline:
             await asyncio.sleep(poll_interval)
@@ -4152,6 +4193,7 @@ class PrintScheduler:
                 except Exception:
                     pass
                 return
+            drying_ams_ids = drying_ams_ids or _drying_ams_ids(status)
             # Checked only after the active-state exit above: a stale HMS left
             # over from an earlier job must never abort a print that is visibly
             # running. An actually-refused command leaves the printer idle, so
@@ -4188,6 +4230,7 @@ class PrintScheduler:
                     except Exception:
                         pass
                     return
+                drying_ams_ids = drying_ams_ids or _drying_ams_ids(status)
                 # Same ordering rule as Phase A: a running print wins over a
                 # lingering HMS.
                 if _mqtt_commands_rejected(status):
@@ -4198,6 +4241,17 @@ class PrintScheduler:
         # Drop the in-memory hold so the retry isn't blocked by it.
         scheduler._release_dispatch_hold(printer_id)
 
+        # Logged on every failed dispatch window, not just the last one, so a
+        # support bundle shows the correlation from the first attempt rather than
+        # only after the retry budget is spent (#2758).
+        if drying_ams_ids:
+            logger.info(
+                "Queue item %s: printer %d never started while AMS %s drying — this may be why, see #2758",
+                queue_item_id,
+                printer_id,
+                ", ".join(str(i) for i in drying_ams_ids),
+            )
+
         # Four outcomes from the revert attempt, each routed differently:
         #   "reverted":          row flipped from printing -> pending, run recovery
         #   "gave_up":           same, but the retry budget is spent — row failed
@@ -4249,11 +4303,29 @@ class PrintScheduler:
                 return "command_rejected"
             if item.dispatch_attempts >= DISPATCH_MAX_ATTEMPTS:
                 item.status = "failed"
-                item.error_message = (
-                    f"The printer accepted the file but never started printing, after "
-                    f"{item.dispatch_attempts} attempts. Check the printer's screen for a "
-                    f"prompt or error, confirm its SD card is readable, and start the job again."
-                )
+                if drying_ams_ids:
+                    # #2758: the generic message below sent the reporter looking
+                    # at the SD card while the actual obstacle — AMS units in a
+                    # drying cycle — was on screen the whole time. Name what we
+                    # observed and let the user judge it; Bambuddy does not stop
+                    # the cycle itself, because on this hardware drying can run
+                    # alongside a print and stopping it may not be the fix.
+                    units = ", ".join(f"AMS {i}" for i in drying_ams_ids)
+                    item.error_message = (
+                        f"The printer accepted the file but never started printing, after "
+                        f"{item.dispatch_attempts} attempts. {units} "
+                        f"{'was' if len(drying_ams_ids) == 1 else 'were'} drying throughout — "
+                        f"some printers refuse to begin a print while an AMS is in a drying "
+                        f"cycle, and an AMS drying without its external power supply can also "
+                        f"leave too little power for the start-of-print calibration. Stop the "
+                        f"drying, or connect the AMS power supply, and start the job again."
+                    )
+                else:
+                    item.error_message = (
+                        f"The printer accepted the file but never started printing, after "
+                        f"{item.dispatch_attempts} attempts. Check the printer's screen for a "
+                        f"prompt or error, confirm its SD card is readable, and start the job again."
+                    )
                 item.completed_at = datetime.now(timezone.utc)
                 await db.commit()
                 return "gave_up"

backend/tests/unit/test_scheduler_watchdog.py

@@ -13,6 +13,7 @@ belt-and-braces for slow transitions that also don't emit an early subtask_id
 tick.
 """
 
+import itertools
 from types import SimpleNamespace
 from unittest.mock import AsyncMock, MagicMock, patch
 
@@ -722,3 +723,187 @@ class TestWatchdogCommandRejected:
             item = await db.get(PrintQueueItem, 1)
             assert item.status == "printing"
             assert item.dispatch_attempts == 0
+
+
+def _drying_status(state: str, subtask_id: str | None = None, *, drying: dict[int, int] | None = None, **kw):
+    """``_status`` plus the ``raw_data['ams']`` shape the drying probe reads.
+
+    ``drying`` maps AMS unit id -> dry_time in minutes (0 = idle unit).
+    """
+    st = _status(state, subtask_id, **kw)
+    st.raw_data = {"ams": [{"id": i, "dry_time": t} for i, t in (drying or {}).items()]}
+    return st
+
+
+class TestDryingAmsIds:
+    """``_drying_ams_ids`` is a diagnostic read of firmware telemetry (#2758)."""
+
+    def test_reports_units_with_time_remaining(self):
+        from backend.app.services.print_scheduler import _drying_ams_ids
+
+        assert _drying_ams_ids(_drying_status("IDLE", drying={0: 45, 1: 0, 128: 12})) == [0, 128]
+
+    def test_no_raw_data_is_not_an_error(self):
+        """Every watchdog poll calls this, including against the bare status
+        objects other tests build, so a missing field must read as 'not drying'
+        rather than raise inside the dispatch loop."""
+        from backend.app.services.print_scheduler import _drying_ams_ids
+
+        assert _drying_ams_ids(_status("IDLE")) == []
+        assert _drying_ams_ids(SimpleNamespace(raw_data={})) == []
+
+    def test_unparseable_entries_are_skipped_not_fatal(self):
+        from backend.app.services.print_scheduler import _drying_ams_ids
+
+        status = SimpleNamespace(raw_data={"ams": ["nonsense", {"id": 2, "dry_time": "20"}, {"dry_time": None}]})
+        assert _drying_ams_ids(status) == [2]
+
+
+class TestWatchdogNamesDryingAsTheObstacle:
+    """#2758: an X2D with two AMS units drying accepted the file and never
+    started. The watchdog waited out both phases three times, re-uploading the
+    whole 3MF each lap, and closed with a message about the SD card — while the
+    actual obstacle was on the printer's own screen the whole time.
+
+    Detection only. Bambuddy does not stop the cycle: this hardware supports
+    drying concurrently with an active print, so drying is not incompatible with
+    printing, and it is not yet established whether the blocker is the drying or
+    the power budget of an AMS drying without its external PSU.
+    """
+
+    @staticmethod
+    async def _wedge_while_drying(db_session, *, drying: dict[int, int], item_id: int = 1):
+        get_status = MagicMock(return_value=_drying_status("IDLE", "NEW_SUBTASK", gcode_file="/new.3mf", drying=drying))
+        with (
+            patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
+            patch("backend.app.services.print_scheduler.printer_manager.get_client", MagicMock()),
+            patch("backend.app.services.print_scheduler.async_session", db_session),
+            patch("backend.app.core.database.async_session", db_session),
+            patch(
+                "backend.app.services.notification_service.notification_service.on_queue_job_failed",
+                AsyncMock(),
+            ),
+        ):
+            await PrintScheduler._watchdog_print_start(
+                queue_item_id=item_id,
+                printer_id=42,
+                pre_state="IDLE",
+                pre_subtask_id="OLD_SUBTASK",
+                pre_gcode_file="/old.3mf",
+                timeout=0.2,
+                phase_b_timeout=0.2,
+                poll_interval=0.05,
+            )
+
+    @pytest.mark.asyncio
+    async def test_give_up_message_names_the_drying_units(self, db_session):
+        for _ in range(DISPATCH_MAX_ATTEMPTS):
+            async with db_session() as db:
+                item = await db.get(PrintQueueItem, 1)
+                item.status = "printing"
+                await db.commit()
+            await self._wedge_while_drying(db_session, drying={0: 45, 128: 12})
+
+        async with db_session() as db:
+            item = await db.get(PrintQueueItem, 1)
+        assert item.status == "failed"
+        assert "AMS 0, AMS 128" in item.error_message
+        assert "were drying" in item.error_message
+        # The old text sent the reporter to check the SD card. It must not be
+        # what a drying-blocked dispatch says.
+        assert "SD card" not in item.error_message
+
+    @pytest.mark.asyncio
+    async def test_single_unit_reads_naturally(self, db_session):
+        for _ in range(DISPATCH_MAX_ATTEMPTS):
+            async with db_session() as db:
+                item = await db.get(PrintQueueItem, 1)
+                item.status = "printing"
+                await db.commit()
+            await self._wedge_while_drying(db_session, drying={128: 30})
+
+        async with db_session() as db:
+            item = await db.get(PrintQueueItem, 1)
+        assert "AMS 128 was drying" in item.error_message
+
+    @pytest.mark.asyncio
+    async def test_no_drying_keeps_the_original_message(self, db_session):
+        """The generic advice is still right when drying had nothing to do with
+        it — this must not become the answer to every stalled dispatch."""
+        for _ in range(DISPATCH_MAX_ATTEMPTS):
+            async with db_session() as db:
+                item = await db.get(PrintQueueItem, 1)
+                item.status = "printing"
+                await db.commit()
+            await self._wedge_while_drying(db_session, drying={0: 0})
+
+        async with db_session() as db:
+            item = await db.get(PrintQueueItem, 1)
+        assert item.status == "failed"
+        assert "SD card" in item.error_message
+        assert "drying" not in item.error_message
+
+    @pytest.mark.asyncio
+    async def test_a_cycle_that_ends_mid_window_is_still_reported(self, db_session):
+        """Latched, not level-tested. Drying finishing (or the user stopping it)
+        part-way through the dispatch window must not erase the fact that it was
+        what the printer was doing when it declined to start."""
+        drying = _drying_status("IDLE", "NEW_SUBTASK", gcode_file="/new.3mf", drying={1: 5})
+        finished = _drying_status("IDLE", "NEW_SUBTASK", gcode_file="/new.3mf", drying={1: 0})
+
+        for _ in range(DISPATCH_MAX_ATTEMPTS):
+            async with db_session() as db:
+                item = await db.get(PrintQueueItem, 1)
+                item.status = "printing"
+                await db.commit()
+            # Fresh per run: the first poll of each dispatch window sees the
+            # cycle, every later poll sees it finished.
+            get_status = MagicMock(side_effect=itertools.chain([drying], itertools.repeat(finished)))
+            with (
+                patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
+                patch("backend.app.services.print_scheduler.printer_manager.get_client", MagicMock()),
+                patch("backend.app.services.print_scheduler.async_session", db_session),
+                patch("backend.app.core.database.async_session", db_session),
+                patch(
+                    "backend.app.services.notification_service.notification_service.on_queue_job_failed",
+                    AsyncMock(),
+                ),
+            ):
+                await PrintScheduler._watchdog_print_start(
+                    queue_item_id=1,
+                    printer_id=42,
+                    pre_state="IDLE",
+                    pre_subtask_id="OLD_SUBTASK",
+                    pre_gcode_file="/old.3mf",
+                    timeout=0.2,
+                    phase_b_timeout=0.2,
+                    poll_interval=0.05,
+                )
+
+        async with db_session() as db:
+            item = await db.get(PrintQueueItem, 1)
+        assert "AMS 1 was drying" in item.error_message
+
+    @pytest.mark.asyncio
+    async def test_drying_does_not_make_a_successful_start_fail(self, db_session):
+        """Drying is not an error condition. A printer that starts the job while
+        an AMS dries — which this hardware supports — must be left alone."""
+        get_status = MagicMock(return_value=_drying_status("RUNNING", "NEW_SUBTASK", drying={0: 45}))
+        with (
+            patch("backend.app.services.print_scheduler.printer_manager.get_status", get_status),
+            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="IDLE",
+                pre_subtask_id="OLD_SUBTASK",
+                timeout=0.3,
+                poll_interval=0.05,
+            )
+
+        async with db_session() as db:
+            item = await db.get(PrintQueueItem, 1)
+        assert item.status == "printing"
+        assert (item.dispatch_attempts or 0) == 0