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.

CHANGELOG.md

@@ -5,6 +5,7 @@ All notable changes to Bambuddy will be documented in this file.
 ## [1.2.6b1] - Unreleased
 
 ### Fixed
+- **A print that never starts now says AMS drying was running, instead of blaming the SD card (#2758)** — Sending a job to an X2D with two AMS units mid-drying failed silently: the file uploaded, the printer accepted it and then simply stayed idle. Bambuddy waited out the start watchdog, re-uploaded the whole 3MF, waited again, and after three attempts gave up with advice to check the printer's screen and the SD card — while Bambu Studio, asked directly, said it could not start the job because of the drying. Bambuddy now watches the AMS drying telemetry it already receives across the dispatch window and, when a job never starts while a unit was drying, names the units in the failure message and records the correlation in the log from the first attempt rather than only after the retries are spent. This is deliberately a diagnosis and not a rule: the printers concerned support drying *continuing* through a print, so drying and printing are not in conflict as such, and the report also involved one AMS drying without its external power supply — which would make the start-of-print calibration a power problem rather than a drying one. Stopping the cycle automatically would therefore be acting on a guess, and could tear down drying the hardware was happy to continue. Until it is known which of the two is the real obstacle, Bambuddy tells you what it saw and leaves the call to you. The message for a stalled dispatch with no drying involved is unchanged. Wiki updated. Covered by backend tests.
 - **A hand-written systemd service left the Virtual Printer unable to start, with nothing obvious to blame (#2549, reporter @Ru3ck3)** — The Virtual Printer binds ports 990 and 322, both below 1024, which a service running as a normal user may not do without the `CAP_NET_BIND_SERVICE` capability. Without it the rest of Bambuddy works perfectly and only the Virtual Printer is dead: its sockets never open, the slicer never finds the printer, and the sole trace is one line in the journal. The reporter lost days to this before someone on Discord spotted the missing line. The install script has carried it since March, but the three other places that define the same service did not — the manual-install template, the combined Bambuddy plus SpoolBuddy installer, and the unit the wiki tells you to paste. All three have it now, and the wiki no longer claims the capability is always included when its own instructions omitted it. Bambuddy also diagnoses this itself: **Diagnose** on the virtual printer card previously reported only that nothing was listening on port 990, which reads identically to an ordinary port conflict. It now checks whether the process actually holds the capability and, when that is what is wrong, says so and gives the line to add. The check stays quiet when the port is answering, since fronting it another way (an iptables redirect is the documented alternative) is a legitimate setup, and it stays quiet when the capability is held, so a port that failed for some other reason is not misattributed. Existing installs are unaffected until reinstalled; the diagnostic tells you whether yours needs the line. Translated in all locales; wiki updated. Covered by backend tests.
 - **A refused AMS filament setting now says so in the log (#2756, reporter @Jostxxl)** — Configuring a slot publishes an `ams_filament_setting` command, and the printer answers it with a verdict. That answer was received and then thrown away at debug level, so a printer that refused the write left no trace at the log level support bundles are collected at. The reporter hit exactly that: six manual **Configure Slot** attempts on one X1C, every one returning success, every one read back by the #2582 verification as still holding the previous profile, and nothing anywhere to say what the printer had made of the command. A refusal is now logged with the printer's own `result` and `reason` alongside the AMS and tray it concerned. Only refusals are promoted — unlike the K-profile and drying commands this one is not rare, since every spool assignment and every K-profile re-apply sends one, and logging each acknowledgement would bury the line worth reading. The developer-mode probe is excluded as well: it sends this same command to the external slot specifically to watch it be refused on P1 firmware, so its failure is a measurement rather than a fault. Diagnostics only — nothing about which commands are sent or how they are built has changed. Covered by backend tests.
 - **Live updates stopped arriving while the Bambuddy tab was in the background (#2754, reporter @mic4rd)** — The progress percentage in the tab title froze whenever you switched to another tab and jumped straight to the current value the moment you switched back, which defeats the point of putting it in the title. The cause was not in the tab-title feature: every printer status arriving over the WebSocket was written into the browser's cache from inside an animation-frame callback, and a browser gives a hidden tab no frames at all. Those callbacks are not slowed down, they are held — so the connection stayed up, the messages kept arriving, and every one of them parked in a queue that only ran when the tab was shown again. The same applied to the archive, inventory and spool refreshes, and to the queue that carries every non-status message, which stalled completely and accumulated messages until the tab came back. The animation frames were added alongside the real fix for a browser freeze on print completion — that fix was the batching, which is untouched; the frames only ever deferred each write by about a sixteenth of a second and are gone. One limit is worth knowing about and is the browser's rather than ours: browsers deliberately slow down timers in tabs you are not looking at, to roughly once a second, and to about once a minute once a tab has been hidden for five minutes. So the title keeps moving in the background, but on a tab left alone for a long time it steps rather than ticks. Covered by frontend tests that reproduce a hidden tab.

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