diff --git a/backend/app/services/bambu_mqtt.py b/backend/app/services/bambu_mqtt.py index e52622829..a02cce12e 100644 --- a/backend/app/services/bambu_mqtt.py +++ b/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 diff --git a/backend/tests/unit/test_unnamed_print_stage_logging.py b/backend/tests/unit/test_unnamed_print_stage_logging.py new file mode 100644 index 000000000..1800dbd61 --- /dev/null +++ b/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) == []