diff --git a/backend/app/services/bambu_mqtt.py b/backend/app/services/bambu_mqtt.py index b24b67cee..ed91f00c1 100644 --- a/backend/app/services/bambu_mqtt.py +++ b/backend/app/services/bambu_mqtt.py @@ -1642,6 +1642,44 @@ class BambuMQTTClient: self._pending_cali_acks[ack_seq] = print_data elif cmd in ("extrusion_cali_sel", "ams_filament_setting"): logger.debug("[%s] %s response: %s", self.serial_number, cmd, print_data) + # A refused ams_filament_setting is the printer's verdict on + # a write the user just made, and at DEBUG it never reached + # a support bundle: #2756 reported six manual Configure Slot + # attempts on an X1C, each returning HTTP 200 with the + # read-back still showing the previous profile, and no + # record of what the printer said about any of them. Same + # promotion as extrusion_cali_set (#2718) and + # ams_filament_drying (#1447) — but only on a non-success, + # because unlike those two this command is not rare: every + # spool assignment and every K-profile re-apply sends one, + # so promoting each ack would bury the interesting line. + # + # The developer-mode probe is excluded. It sends this exact + # command to the external slot precisely to see it refused + # on P1 firmware, so its failure is a normal reading rather + # than a fault. Its response is still matched below (this + # runs before _handle_dev_mode_probe_response clears the + # seq), and user-initiated commands can't be mistaken for + # it — they publish a hardcoded sequence_id of "0". + result = print_data.get("result") + is_dev_mode_probe = ( + self._dev_mode_probe_seq is not None + and print_data.get("sequence_id") == self._dev_mode_probe_seq + ) + if ( + cmd == "ams_filament_setting" + and not is_dev_mode_probe + and isinstance(result, str) + and result.lower() != "success" + ): + logger.info( + "[%s] ams_filament_setting refused: result=%s reason=%s ams_id=%s tray_id=%s", + self.serial_number, + result, + print_data.get("reason", ""), + print_data.get("ams_id"), + print_data.get("tray_id"), + ) # AMS drying responses are rare (user-initiated only) and the # full payload — including `result` and any `reason` code — # is the only way to diagnose silent rejections like #1447. diff --git a/backend/tests/unit/services/test_bambu_mqtt.py b/backend/tests/unit/services/test_bambu_mqtt.py index db3771887..f1a82c92a 100644 --- a/backend/tests/unit/services/test_bambu_mqtt.py +++ b/backend/tests/unit/services/test_bambu_mqtt.py @@ -7451,3 +7451,122 @@ class TestEndOfPrintProbe: probe_lines = [line for line in caplog.text.splitlines() if "EOP-PROBE" in line] assert probe_lines assert not any("12345678" in line for line in probe_lines) + + +class TestAmsFilamentSettingRefusalLogging: + """A refused `ams_filament_setting` reaches the log at INFO (#2756). + + The reporter configured a slot on an X1C six times. Every request returned + HTTP 200, every publish carried the complete `GFG99`/`GFSG99` pair, and + every #2582 read-back showed the previous profile still in place — with no + record anywhere of what the printer answered, because the response sat at + DEBUG and support bundles are collected at INFO. + + Only a non-success is promoted. This command is not rare — every spool + assignment and every K-profile re-apply sends one — so logging each ack + would bury the one line worth reading. + """ + + @pytest.fixture + def mqtt_client(self): + from backend.app.services.bambu_mqtt import BambuMQTTClient + + return BambuMQTTClient( + ip_address="192.168.1.100", + serial_number="TEST123", + access_code="12345678", + ) + + def _refusals(self, caplog): + return [line for line in caplog.text.splitlines() if "ams_filament_setting refused" in line] + + def test_refusal_is_logged_at_info_with_result_and_reason(self, mqtt_client, caplog): + caplog.set_level(logging.INFO, logger="backend.app.services.bambu_mqtt") + + mqtt_client._process_message( + { + "print": { + "command": "ams_filament_setting", + "result": "fail", + "reason": "invalid tray_id", + "ams_id": 0, + "tray_id": 1, + "sequence_id": "0", + } + } + ) + + refusals = self._refusals(caplog) + assert len(refusals) == 1 + # The reason is the whole point of the promotion — a bare "fail" would + # not have told the reporter anything the read-back hadn't already. + assert "result=fail" in refusals[0] + assert "invalid tray_id" in refusals[0] + assert "ams_id=0" in refusals[0] + assert "tray_id=1" in refusals[0] + + def test_success_stays_quiet(self, mqtt_client, caplog): + caplog.set_level(logging.INFO, logger="backend.app.services.bambu_mqtt") + + mqtt_client._process_message( + {"print": {"command": "ams_filament_setting", "result": "success", "sequence_id": "0"}} + ) + + assert self._refusals(caplog) == [] + + def test_response_without_a_result_field_stays_quiet(self, mqtt_client, caplog): + """Firmware that omits `result` tells us nothing — don't invent a refusal.""" + caplog.set_level(logging.INFO, logger="backend.app.services.bambu_mqtt") + + mqtt_client._process_message({"print": {"command": "ams_filament_setting", "sequence_id": "0"}}) + + assert self._refusals(caplog) == [] + + def test_developer_mode_probe_failure_is_not_reported_as_a_refusal(self, mqtt_client, caplog): + """The probe sends this command to the external slot *expecting* a + refusal on P1 firmware — that is a reading, not a fault, and promoting + it would put an alarming line in every P1 bundle on every reconnect.""" + caplog.set_level(logging.INFO, logger="backend.app.services.bambu_mqtt") + mqtt_client._dev_mode_probe_seq = "7" + + mqtt_client._process_message( + { + "print": { + "command": "ams_filament_setting", + "result": "failed", + "reason": "mqtt message verify failed", + "sequence_id": "7", + } + } + ) + + assert self._refusals(caplog) == [] + + def test_user_command_is_not_mistaken_for_the_probe(self, mqtt_client, caplog): + """User-initiated publishes hardcode sequence_id "0", so a refusal is + still reported while a probe is outstanding under a different seq.""" + caplog.set_level(logging.INFO, logger="backend.app.services.bambu_mqtt") + mqtt_client._dev_mode_probe_seq = "7" + + mqtt_client._process_message( + { + "print": { + "command": "ams_filament_setting", + "result": "fail", + "reason": "", + "sequence_id": "0", + } + } + ) + + assert len(self._refusals(caplog)) == 1 + + def test_extrusion_cali_sel_is_untouched(self, mqtt_client, caplog): + """The sibling in the same branch keeps its DEBUG-only handling; this + change is scoped to the write #2756 is about.""" + caplog.set_level(logging.INFO, logger="backend.app.services.bambu_mqtt") + + mqtt_client._process_message({"print": {"command": "extrusion_cali_sel", "result": "fail", "sequence_id": "0"}}) + + assert self._refusals(caplog) == [] + assert "extrusion_cali_sel" not in caplog.text