Sfoglia il codice sorgente

Report a print stage we cannot name at the default log level

    STAGE_NAMES is hand-maintained and every new model adds to it, so a printer
    occasionally reports a number that is not in it and the card reads "Unknown
    stage (72)" -- which an H2C did, where the table runs to 66 and then jumps
    to 74. Stage transitions were logged only at DEBUG, off in normal running,
    so the sole record that it had happened was the card itself, and by the
    time anyone looked the printer had moved on.

    The asymmetry is the point: a stage we can name is worth DEBUG, and the one
    we cannot is the interesting one. An unnamed stage is now logged at INFO,
    once per stage number per session, with the model, the stage it came from
    and the print state at the time -- which is what naming it afterwards
    needs. Named stages are unchanged, so a normal print logs nothing new. -1
    is excluded: it is Bambuddy's own "not in a stage" sentinel and the field's
    initial value, so every print would otherwise report it on the way out of
    its last real stage.

    Fixes a latent crash found while testing this. The stage-change log line
    builds its text before the log level is consulted, so get_stage_name runs
    on every transition whatever the level is set to; a stg_cur that was not
    hashable -- malformed telemetry rather than an unknown stage -- raised
    TypeError out of STAGE_NAMES.get and aborted the whole state update.
    Labelling a value can no longer do that.
maziggy 3 settimane fa
parent
commit
3ce4ecfcf7

+ 45 - 1
backend/app/services/bambu_mqtt.py

@@ -728,7 +728,15 @@ STAGE_NAMES = {
 
 def get_stage_name(stage: int) -> str:
     """Get human-readable stage name from stage number."""
-    return STAGE_NAMES.get(stage, f"Unknown stage ({stage})")
+    try:
+        return STAGE_NAMES.get(stage, f"Unknown stage ({stage})")
+    except TypeError:
+        # `stage` is an int by convention only -- it comes straight out of the
+        # printer's JSON, and an unhashable value there would otherwise raise
+        # from inside the f-string that builds the stage-change log line, which
+        # is evaluated on every transition whatever the log level is set to.
+        # Labelling a value must not be able to abort the state update.
+        return f"Unknown stage ({stage})"
 
 
 # #2547 end-of-print telemetry probe.
@@ -893,6 +901,9 @@ class BambuMQTTClient:
         # 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()
+        # Stage numbers this printer has reported that STAGE_NAMES has no entry
+        # for, so each is reported once rather than on every transition into it.
+        self._unnamed_stages_seen: set[int] = set()
 
         self.state = PrinterState()
         self._client: mqtt.Client | None = None
@@ -3508,6 +3519,39 @@ class BambuMQTTClient:
                 logger.debug(
                     f"[{self.serial_number}] stg_cur changed: {prev_stg} -> {new_stg} ({get_stage_name(new_stg)})"
                 )
+                # A stage we cannot name is the one worth seeing at the default
+                # log level: the DEBUG line above is off in normal running, so
+                # an unnamed stage otherwise reaches the user as "Unknown stage
+                # (72)" on a card with nothing behind it to say when it
+                # happened or what the printer was doing. Recorded once per
+                # stage number per session, with the stage it came from and the
+                # print state, which is what naming it later needs. Guarded on
+                # the int type because the field is whatever the firmware sent.
+                if (
+                    isinstance(new_stg, int)
+                    and not isinstance(new_stg, bool)
+                    # -1 is Bambuddy's own "not in a stage" sentinel and the
+                    # initial value of the field, not something the firmware
+                    # reports; every print would otherwise report it on the way
+                    # out of its last real stage.
+                    and new_stg != -1
+                    and new_stg not in STAGE_NAMES
+                    and new_stg not in self._unnamed_stages_seen
+                ):
+                    self._unnamed_stages_seen.add(new_stg)
+                    logger.info(
+                        "[%s] Unnamed print stage %s on model %s, entered from %s (%s); "
+                        "state=%s progress=%s%% layer=%s/%s",
+                        self.serial_number,
+                        new_stg,
+                        self.model,
+                        prev_stg,
+                        get_stage_name(prev_stg),
+                        self.state.state,
+                        self.state.progress,
+                        self.state.layer_num,
+                        self.state.total_layers,
+                    )
             self.state.stg_cur = new_stg
             # #1721 end-of-print finish photo trigger.
             # Stage 22 = "Filament unloading" fires at end-of-print AND

+ 92 - 0
backend/tests/unit/test_unnamed_print_stage_logging.py

@@ -0,0 +1,92 @@
+"""A print stage Bambuddy cannot name has to leave a trace at the default log level.
+
+``STAGE_NAMES`` is a hand-maintained table and every new printer adds to it: an
+H2C first print surfaced stage 72, where the table runs 0-66 and then jumps
+straight to 74. The card showed "Unknown stage (72)" and there was nothing
+behind it -- stage transitions are logged at DEBUG, which is off in normal
+running, so the only record of the event was a screenshot.
+
+The asymmetry is the point. A stage we can name is worth DEBUG; one we cannot
+is the interesting one, and it is the one that was invisible. Naming it later
+needs the number, the model, the stage it came from and what the printer was
+doing, so all of that is recorded -- once per stage number, because a stage can
+be entered repeatedly in one print.
+"""
+
+import logging
+
+import pytest
+
+from backend.app.services.bambu_mqtt import STAGE_NAMES, BambuMQTTClient
+
+
+@pytest.fixture
+def client():
+    return BambuMQTTClient(
+        ip_address="192.168.1.100",
+        serial_number="TEST-H2C",
+        access_code="12345678",
+        model="H2C",
+    )
+
+
+def _stage_records(caplog):
+    return [r for r in caplog.records if "Unnamed print stage" in r.getMessage()]
+
+
+class TestUnnamedStageIsReported:
+    def test_the_h2c_stage_that_prompted_this(self, client, caplog):
+        with caplog.at_level(logging.INFO):
+            client._update_state({"stg_cur": 72})
+        records = _stage_records(caplog)
+        assert len(records) == 1
+        message = records[0].getMessage()
+        assert "72" in message
+        assert "H2C" in message
+
+    def test_the_message_carries_what_naming_it_later_needs(self, client, caplog):
+        client._update_state({"gcode_state": "RUNNING", "layer_num": 7, "total_layer_num": 240})
+        with caplog.at_level(logging.INFO):
+            client._update_state({"stg_cur": 72})
+        message = _stage_records(caplog)[0].getMessage()
+        # Where it came from, named, so a sequence can be reconstructed from
+        # several of these lines rather than only the stage in isolation.
+        assert "entered from -1" in message
+        assert "layer=7/240" in message
+
+    def test_reported_once_per_stage_not_once_per_transition(self, client, caplog):
+        """A stage can be entered repeatedly within a single print."""
+        with caplog.at_level(logging.INFO):
+            client._update_state({"stg_cur": 72})
+            client._update_state({"stg_cur": 0})
+            client._update_state({"stg_cur": 72})
+        assert len(_stage_records(caplog)) == 1
+
+    def test_a_second_unnamed_stage_is_still_reported(self, client, caplog):
+        with caplog.at_level(logging.INFO):
+            client._update_state({"stg_cur": 72})
+            client._update_state({"stg_cur": 71})
+        assert len(_stage_records(caplog)) == 2
+
+
+class TestQuietWhereItShouldBe:
+    @pytest.mark.parametrize("stage", [0, 22, 39, 66, 74])
+    def test_a_stage_we_can_name_says_nothing_at_info(self, client, caplog, stage):
+        assert stage in STAGE_NAMES
+        with caplog.at_level(logging.INFO):
+            client._update_state({"stg_cur": stage})
+        assert _stage_records(caplog) == []
+
+    def test_idle_is_not_an_unnamed_stage(self, client, caplog):
+        """-1 is Bambuddy's own "not in a stage" sentinel, not a firmware value."""
+        with caplog.at_level(logging.INFO):
+            client._update_state({"stg_cur": 0})
+            client._update_state({"stg_cur": -1})
+        assert _stage_records(caplog) == []
+
+    @pytest.mark.parametrize("junk", ["72", 72.5, None, True, [72]])
+    def test_a_non_integer_stage_is_not_reported_and_never_raises(self, client, caplog, junk):
+        """The field is whatever the firmware sent, and this runs on every push."""
+        with caplog.at_level(logging.INFO):
+            client._update_state({"stg_cur": junk})
+        assert _stage_records(caplog) == []