Say why a drying cycle ended when the firmware cuts it short (#2770)

An H2D started a twelve-hour PETG dry at 65 degC and the AMS gave up on it
twenty minutes in, with 700 of the 720 minutes still on the clock. It cooled,
humidity climbed back over the threshold, auto-drying started another
twelve-hour cycle, and that one went the same way; the reporter's AMS
temperature history shows the loop running all morning.

The log had one line for it: "AMS 0 drying complete", which is exactly what it
says for a dry that ran its full twelve hours. Nothing in a support bundle told
the two apart, and the one number that does -- the time still remaining -- was
written into that line as the previous value, where it reads like a duration
rather than a shortfall. The reporter took 700 for seconds and concluded the
cycle had lasted twelve minutes.

Bambuddy did not stop that cycle; every stop it sends is logged with the full
outgoing command and there was none. So ending it was the printer's decision,
and the account of why lives in three things already received and parsed and
never written down: the drying phase and sub-phase from the AMS info hex, the
per-unit dry_sf_reason constraint codes, and the live HMS errors.

A cycle that ends with most of its countdown left now logs all three alongside
how much of the requested duration ran. One that reaches its duration keeps the
single line it has always had. A stop Bambuddy sent is named as ours -- it is
short of its duration too, and on the telemetry alone is indistinguishable from
the firmware abandoning the cycle, so without tracking it the print-takes-priority
stop and the Stop button would both have been blamed on the printer.

Diagnostics only. Nothing about when drying starts or stops has changed, and the
restart loop is not addressed: what the firmware objects to has to be established
before Bambuddy can sensibly decide how long to wait before trying again.

backend/app/services/bambu_mqtt.py

@@ -46,6 +46,16 @@ _ACTIVE_PRINT_STATES = frozenset({"PREPARE", "SLICING", "RUNNING", "PAUSE"})
 # are deliberately excluded — those SHOULD end it.
 _ACTIVE_DRY_STATUSES = frozenset({1, 2, 3})  # Checking, Drying, Cooling
 
+# A drying cycle that runs to term ends with its countdown all but exhausted, so
+# the last dry_time we saw before the drop to 0 tells us whether the firmware
+# ended the cycle on schedule or aborted it. More than this many minutes still on
+# the clock means it was cut short, and the firmware's own reason codes are worth
+# capturing at INFO — #2770 aborted a 12-hour cycle 20 minutes in (700 minutes
+# left), and the log said only "drying complete", so the report carried no
+# evidence of why. The margin absorbs a stale last observation between AMS
+# pushes; it is not a judgement about how short "short" is.
+_EARLY_DRY_END_MINUTES = 5
+
 # CONNACK reason codes that mean the printer actively refused our credentials,
 # as opposed to being unreachable or busy. Bambu speaks MQTT 3.1.1, whose
 # single-byte CONNACK return codes paho maps onto the v5 reason-code space:
@@ -750,6 +760,11 @@ class BambuMQTTClient:
         # — only the dry_time countdown — so we cache what we sent to drive
         # the UI badge. Cleared on stop or on the dry_time falling edge to 0.
         self._drying_targets: dict[int, dict[str, object]] = {}
+        # AMS ids we have sent a stop for and not yet seen end. A stop always
+        # ends a cycle far short of its duration, which on the telemetry alone
+        # is indistinguishable from the firmware abandoning it — so the cycle-end
+        # log would otherwise blame the printer for our own decision (#2770).
+        self._drying_stops_sent: set[int] = set()
 
         self.state = PrinterState()
         self._client: mqtt.Client | None = None
@@ -2819,13 +2834,7 @@ class BambuMQTTClient:
             previous = self._previous_dry_times.get(ams_id, 0)
             self._previous_dry_times[ams_id] = current
             if previous > 0 and current == 0:
-                logger.info(
-                    "[%s] AMS %d drying complete (dry_time %d → 0)",
-                    self.serial_number,
-                    ams_id,
-                    previous,
-                )
-                self._drying_targets.pop(ams_id, None)
+                self._log_drying_cycle_end(ams_id, previous, ams_unit, self._drying_targets.pop(ams_id, None))
                 if self.on_drying_complete:
                     self.on_drying_complete(ams_id)
 
@@ -2865,6 +2874,71 @@ class BambuMQTTClient:
         if self._pending_assignments:
             self._check_assignment_verifications()
 
+    def _log_drying_cycle_end(
+        self,
+        ams_id: int,
+        remaining: int,
+        ams_unit: dict,
+        target: dict[str, object] | None,
+    ) -> None:
+        """Report a finished drying cycle, with the firmware's reason when it was
+        cut short (#2770).
+
+        A cycle that reaches its configured duration needs no explanation and
+        keeps the one-line "drying complete" it has always had. One that ends
+        with most of its countdown left was ended by somebody, and there are
+        only two candidates: a stop Bambuddy sent — the print-takes-priority
+        stop, or the user's Stop button — which is named as such, or the
+        firmware.
+
+        For the firmware case the only account of why lives in fields we already
+        parse but have never written down: the ``dry_status`` /
+        ``dry_sub_status`` phase from the info hex, the per-unit
+        ``dry_sf_reason`` constraint codes, and whatever HMS errors are live at
+        that moment. Logging them at INFO puts them in every support bundle by
+        default, which is what a report like #2770 needs before its cause can be
+        argued about at all.
+        """
+        if ams_id in self._drying_stops_sent:
+            self._drying_stops_sent.discard(ams_id)
+            logger.info(
+                "[%s] AMS %d drying stopped by Bambuddy (dry_time %d → 0)",
+                self.serial_number,
+                ams_id,
+                remaining,
+            )
+            return
+
+        if remaining <= _EARLY_DRY_END_MINUTES:
+            logger.info(
+                "[%s] AMS %d drying complete (dry_time %d → 0)",
+                self.serial_number,
+                ams_id,
+                remaining,
+            )
+            return
+
+        requested_minutes: int | None = None
+        if target is not None:
+            try:
+                requested_minutes = int(target.get("duration_hours") or 0) * 60 or None
+            except (TypeError, ValueError):
+                requested_minutes = None
+
+        logger.info(
+            "[%s] AMS %d drying ended early — %d of %s minutes still on the clock. "
+            "Bambuddy sent no stop command, so the firmware ended this cycle: "
+            "dry_status=%s dry_sub_status=%s dry_sf_reason=%s hms=%s",
+            self.serial_number,
+            ams_id,
+            remaining,
+            requested_minutes if requested_minutes is not None else "?",
+            ams_unit.get("dry_status"),
+            ams_unit.get("dry_sub_status"),
+            ams_unit.get("dry_sf_reason") or [],
+            [e.full_code for e in self.state.hms_errors] or "none",
+        )
+
     def register_assignment_verification(
         self,
         ams_id: int,
@@ -5492,13 +5566,22 @@ class BambuMQTTClient:
         )
         # Track the active-cycle target so the badge can show "PETG @ 65°C"
         # while drying. Bambu only echoes dry_time on subsequent pushes.
+        # duration_hours is not shown anywhere; it is what lets the cycle-end log
+        # say how much of the requested time the firmware actually ran (#2770).
         if mode == 1:
             self._drying_targets[ams_id] = {
                 "filament": filament or "",
                 "temp": int(temp),
+                "duration_hours": int(duration),
             }
+            self._drying_stops_sent.discard(ams_id)
         else:
             self._drying_targets.pop(ams_id, None)
+            # Remember that this cycle's end is ours, so the cycle-end log
+            # attributes it to Bambuddy instead of to the firmware (#2770). A
+            # stop always ends the cycle far short of its duration, which is
+            # otherwise indistinguishable from the firmware abandoning it.
+            self._drying_stops_sent.add(ams_id)
         return True
 
     @staticmethod

backend/tests/unit/services/test_bambu_mqtt.py

@@ -4044,13 +4044,13 @@ class TestSendDryingCommand:
     def test_start_caches_target_for_badge(self, mqtt_client):
         """mode=1 send populates _drying_targets so the badge can render it."""
         mqtt_client.send_drying_command(ams_id=2, temp=65, duration=12, mode=1, filament="PETG")
-        assert mqtt_client._drying_targets[2] == {"filament": "PETG", "temp": 65}
+        assert mqtt_client._drying_targets[2] == {"filament": "PETG", "temp": 65, "duration_hours": 12}
 
     def test_start_overwrites_prior_target_for_same_ams(self, mqtt_client):
         """A second start on the same AMS replaces the cached target."""
         mqtt_client.send_drying_command(ams_id=0, temp=55, duration=4, mode=1, filament="PLA")
         mqtt_client.send_drying_command(ams_id=0, temp=70, duration=6, mode=1, filament="ABS")
-        assert mqtt_client._drying_targets[0] == {"filament": "ABS", "temp": 70}
+        assert mqtt_client._drying_targets[0] == {"filament": "ABS", "temp": 70, "duration_hours": 6}
 
     def test_stop_clears_target(self, mqtt_client):
         """mode=0 send drops the cache so the badge stops showing the target."""
@@ -4065,7 +4065,7 @@ class TestSendDryingCommand:
         mqtt_client.send_drying_command(ams_id=128, temp=80, duration=6, mode=1, filament="PA-CF")
         mqtt_client.send_drying_command(ams_id=0, temp=0, duration=0, mode=0)
         assert 0 not in mqtt_client._drying_targets
-        assert mqtt_client._drying_targets[128] == {"filament": "PA-CF", "temp": 80}
+        assert mqtt_client._drying_targets[128] == {"filament": "PA-CF", "temp": 80, "duration_hours": 6}
 
 
 class TestStartPrintAmsMapping:
@@ -6120,6 +6120,89 @@ class TestDryingCompleteCallback:
         mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 0, "tray": []}]})
         assert mqtt_client._drying_events == [0]
 
+    def test_early_end_logs_firmware_reason_codes(self, mqtt_client, caplog):
+        """#2770 — a 12-hour cycle the firmware abandoned 20 minutes in logged
+        only 'drying complete', so the report carried no evidence of why. An
+        early end now names the shortfall and the reason fields we already
+        parse: phase, sub-phase, cannot-dry codes and live HMS."""
+        from backend.app.services.bambu_mqtt import HMSError
+
+        mqtt_client.state.hms_errors = [
+            HMSError(code="0x2000003", attr=0x07008000, module=7, severity=2, full_code="0700800002000003")
+        ]
+        mqtt_client._client = MagicMock()
+        mqtt_client.send_drying_command(ams_id=0, temp=65, duration=12, mode=1, filament="PETG")
+        mqtt_client._handle_ams_data(
+            {"ams": [{"id": "0", "dry_time": 700, "info": "10002123", "dry_sf_reason": [1], "tray": []}]}
+        )
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            mqtt_client._handle_ams_data(
+                {"ams": [{"id": "0", "dry_time": 0, "info": "10002103", "dry_sf_reason": [1], "tray": []}]}
+            )
+
+        assert mqtt_client._drying_events == [0]
+        message = "\n".join(r.getMessage() for r in caplog.records)
+        assert "drying ended early" in message
+        # The shortfall, against the duration we asked the firmware for.
+        assert "700 of 720 minutes" in message
+        # dry_status 0 (Off) and dry_sub_status 0 from info hex 10002103.
+        assert "dry_status=0" in message
+        assert "dry_sub_status=0" in message
+        # InsufficientPower, and the AMS heater-fan HMS that goes with it.
+        assert "dry_sf_reason=[1]" in message
+        assert "0700800002000003" in message
+
+    def test_early_end_without_a_cached_target_still_logs(self, mqtt_client, caplog):
+        """A cycle Bambuddy did not start — from the printer's screen, from
+        Studio, or from before a restart — has no cached duration to compare
+        against. The remaining time alone still proves it was cut short, so the
+        reason codes must be logged rather than withheld for lack of a target."""
+        mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 480, "tray": []}]})
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 0, "tray": []}]})
+
+        message = "\n".join(r.getMessage() for r in caplog.records)
+        assert "drying ended early" in message
+        assert "480 of ? minutes" in message
+        assert "hms=none" in message
+
+    def test_stop_we_sent_is_not_blamed_on_the_firmware(self, mqtt_client, caplog):
+        """A stop Bambuddy sends — print takes priority, or the user's Stop
+        button — also ends the cycle far short of its duration, which on the
+        telemetry alone looks exactly like the firmware abandoning it. It must
+        be named as ours rather than reported as an unexplained early end."""
+        mqtt_client._client = MagicMock()
+        mqtt_client.send_drying_command(ams_id=0, temp=65, duration=12, mode=1, filament="PETG")
+        mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 700, "tray": []}]})
+        mqtt_client.send_drying_command(ams_id=0, temp=0, duration=0, mode=0)
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 0, "tray": []}]})
+
+        message = "\n".join(r.getMessage() for r in caplog.records)
+        assert "drying stopped by Bambuddy" in message
+        assert "ended early" not in message
+        # And the attribution is consumed, so a later firmware-ended cycle on
+        # the same unit is not credited to a stop we sent hours earlier.
+        mqtt_client.send_drying_command(ams_id=0, temp=65, duration=12, mode=1, filament="PETG")
+        mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 700, "tray": []}]})
+        caplog.clear()
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 0, "tray": []}]})
+        assert "drying ended early" in "\n".join(r.getMessage() for r in caplog.records)
+
+    def test_cycle_that_runs_to_term_keeps_the_plain_completion_log(self, mqtt_client, caplog):
+        """The countdown of a cycle that finishes normally is all but exhausted
+        when it drops to 0. Nothing needs explaining, so it keeps the one-line
+        message it has always had — the early-end diagnostics must not become
+        noise on every completed dry."""
+        mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 1, "tray": []}]})
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            mqtt_client._handle_ams_data({"ams": [{"id": "0", "dry_time": 0, "tray": []}]})
+
+        message = "\n".join(r.getMessage() for r in caplog.records)
+        assert "drying complete (dry_time 1 → 0)" in message
+        assert "ended early" not in message
+
 
 class TestPrintRunningObservedCallback:
     """#1485 follow-up: on_print_running_observed fires the FIRST time we