Quellcode durchsuchen

Report a refused AMS filament setting instead of discarding it (#2756)

Configuring a slot publishes ams_filament_setting and the printer answers
with a verdict. The answer was received and dropped at DEBUG, so a refusal
left no trace at the level support bundles are collected at: the reporter
saw six Configure Slot attempts on an X1C all return success, all read back
by the #2582 verification as holding the previous profile, and no record of
what the printer said about any of them.

Promote a non-success response to INFO with result, reason, ams_id and
tray_id. Refusals only -- unlike extrusion_cali_set (#2718) and
ams_filament_drying (#1447) this command is not rare, since every spool
assignment and K-profile re-apply sends one, so promoting each ack would
bury the interesting line.

The developer-mode probe is excluded: it sends this same command to the
external slot expecting a refusal on P1 firmware, so promoting it would
put an alarming line in every P1 bundle on every reconnect. Matched by
sequence id, which user commands cannot collide with -- they publish a
hardcoded "0".

Diagnostics only; no change to which commands are sent or how they are built.
maziggy vor 1 Monat
Ursprung
Commit
4af782cc2f
3 geänderte Dateien mit 158 neuen und 0 gelöschten Zeilen
  1. 1 0
      CHANGELOG.md
  2. 38 0
      backend/app/services/bambu_mqtt.py
  3. 119 0
      backend/tests/unit/services/test_bambu_mqtt.py

+ 1 - 0
CHANGELOG.md

@@ -5,6 +5,7 @@ All notable changes to Bambuddy will be documented in this file.
 ## [1.2.6b1] - Unreleased
 
 ### Fixed
+- **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.
 - **The bug-report button no longer covers the controls in the bottom-right corner (#2750, reporter @goodjaltman)** — On a phone the floating red button sits on top of whatever else is in that corner, which turns out to be most things: the scroll-to-top button on Profiles was ~83% underneath it and, since both sit at the same stacking level, which one you could actually tap came down to the order they happened to render in. The floating camera window parks there, as do the Group Edit save bar, the bulk-selection toolbars, and — because the button is pinned to the viewport rather than the page — the per-card action buttons on File Manager and Archives simply scroll underneath it. The reporter asked for a switch to hide the button, but it is the only way into the report form, and that form is not just a text box: it runs the printer connection diagnostic, scans your logs against the known-issue catalog, optionally captures five minutes of debug logging and attaches a support bundle. Hiding it doesn't produce smaller reports, it produces reports with nothing attached. So the button moves instead of disappearing. Once the window is narrow enough that the sidebar collapses into a menu button, the bug icon moves into that top bar and the corner is left alone; above that width nothing changes. That threshold is the one the layout already switches on, so there is no new breakpoint and no third state to reason about, and it covers tablets and half-width desktop windows rather than only phones. The report form itself is now a proper bottom sheet on phones, which also fixes it hanging 16 pixels off the left edge of the screen — it was sized to the full viewport width and then inset from the right, so a strip of the form was simply unreachable on anything under about 460 pixels wide. The scroll-to-top button on Profiles has been nudged clear of the corner as well, for the wide layouts where the floating button stays. Wiki updated. Covered by frontend tests.
 - **The Print Log's cost and energy figures were never sent to the browser** — Bambuddy has been recording what each run cost and how much power it drew, but the two Print Log endpoints built their responses field by field and never mentioned `cost`, `energy_kwh` or `energy_cost`. A field nobody names comes back as its default, so the values arrived as nulls — indistinguishable from a column that genuinely holds nothing, with no error and no log line to say otherwise. The same trap had already swallowed the failure-cause classification once before. Both endpoints now validate straight off the database row, which removes the opportunity to forget a field rather than fixing the three that happened to be missing. Existing rows need no migration: the data was always there. Covered by backend tests.

+ 38 - 0
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.

+ 119 - 0
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