diff --git a/backend/app/services/bambu_mqtt.py b/backend/app/services/bambu_mqtt.py index 094030f9d..4d9d11c71 100644 --- a/backend/app/services/bambu_mqtt.py +++ b/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 diff --git a/backend/tests/unit/services/test_bambu_mqtt.py b/backend/tests/unit/services/test_bambu_mqtt.py index 6e56124c2..c36acf1bc 100644 --- a/backend/tests/unit/services/test_bambu_mqtt.py +++ b/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