From d1c65a665926d7cb91ea3c6d3eb9bd49dd0d65f6 Mon Sep 17 00:00:00 2001 From: maziggy Date: Thu, 13 Aug 2026 17:23:41 +0200 Subject: [PATCH] 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. --- CHANGELOG.md | 1 + backend/app/services/bambu_mqtt.py | 46 +++++++++- .../unit/test_unnamed_print_stage_logging.py | 92 +++++++++++++++++++ 3 files changed, 138 insertions(+), 1 deletion(-) create mode 100644 backend/tests/unit/test_unnamed_print_stage_logging.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 1fa9d8533..2e7d948b3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,6 +30,7 @@ All notable changes to Bambuddy will be documented in this file. - **Error and warning toasts now stay up twice as long** — Every pop-up notification disappeared after three seconds regardless of what it said. That is about right for "Settings saved", which confirms something you just did and is skimmed rather than read, but errors and warnings are a different kind of message: they carry a reason, often one relayed from the printer or the backend, and they run to a couple of lines. Three seconds was not long enough to finish reading one, and a missed error message is gone for good — there is no notification history to go back to. Errors and warnings now hold for six seconds. Success and informational toasts keep the three-second default, so the common case of clicking something and seeing it confirmed is unchanged, and the close button and the manual dismiss work exactly as before on all of them. The background print-dispatch toast is unaffected: it stays up while it has work in progress and clears itself shortly after the last job settles. Covered by frontend tests. ### Fixed +- **A print stage Bambuddy has no name for now says so in the log** — The printer reports its current activity as a number, and Bambuddy keeps a table of what those numbers mean. The table is hand-maintained and every new model adds to it, so a printer occasionally reports one that is not in it and the card reads "Unknown stage (72)" — which happened on an H2C, where the table runs to 66 and then jumps to 74. Stage changes were logged, but at debug level, which is off in normal running: the only record that it had happened at all was the card, and by the time anyone looked the printer had moved on. An unnamed stage is now recorded at the normal log level, once per stage number, along with the model, the stage it came from and what the printer was doing at the time — which is what identifying it afterwards actually needs. Stages that do have names stay at debug as before, so a normal print logs nothing new. Fixing this turned up a latent crash beside it: the stage-change log line builds its text before the log level is consulted, so a printer reporting a stage that was not a number at all — malformed telemetry rather than an unknown stage — would abort processing of that update entirely. Labelling a value can no longer do that. Covered by backend tests. - **An H2C refused to start a multi-colour print, reporting that its hotends did not match the sliced file** — The print uploaded, the printer took the command, and then stopped immediately with "the print has stopped because the available hotend quantity or model does not match the sliced file" (HMS 0500-4047). Bambuddy was telling the printer that one of the filaments the plate prints goes to no hotend at all, while the AMS mapping alongside it named the exact tray that filament comes from — a contradiction the firmware will not start a job on. The mistake was in reading the sliced file. Each filament in a 3MF names the *group* it belongs to, and on every other dual-nozzle Bambu that group number happens to also be the extruder it prints on, so Bambuddy read it as one. On a nozzle-rack machine it is not: the rack carriage can hold six hotends against the fixed carriage's one, so the slicer writes one group per nozzle it wants rather than one per carriage, and a three-colour plate can carry groups 0, 1 and 2 on a printer with two extruders. The filament in the group that ran past the end was quietly dropped, and a dropped filament is indistinguishable further down from a slot the plate genuinely does not print. Bambuddy now reads the group-to-extruder table the file states for itself, which is the only place the real answer is written. Where a filament still cannot be placed, no mapping is sent at all rather than a partial one, and the reason is logged: the printer then chooses its own nozzle, which is what it did before any of this existed and is much better than being handed an answer that contradicts itself. Two things were corrected alongside it. The mapping is now read from the plate being printed rather than from every plate in the file at once — a project with several plates can assign the same slot to different extruders on each, and the wrong plate's answer was as likely as the right one. And the mapping sent to the printer is now as long as the plate has filament slots, matching what Bambu Studio itself sends, instead of being padded to a fixed 32 entries. Covered by backend tests, and verified against the file that failed. - **Interchangeable filaments were reported as the wrong material, and the pre-flight check disagreed with what would actually print** — Bambu's firmware treats PA-CF, PA12-CF and PAHT-CF as the same material, and the scheduler has always matched them accordingly, so a PA12-CF spool would happily print a job asking for PA-CF. The interface compared the raw type names instead, so it labelled that same pairing a type mismatch — the badge contradicted what the printer was about to do, and the manual override picker made it worse by *offering* the spool the badge then rejected. Every place that judges whether a spool suits a requirement now reads one shared table. The pipeline pre-flight check had drifted the other way: it carried its own copy of that table, and the copy had come to disagree in both directions — it treated **PLA Basic** as interchangeable with **PLA** where the matcher never has, so a run could clear the check and then fail to map its slots, and it lacked the nylon grouping, so it flagged runs the matcher handles without complaint. It now answers with the matcher's rules, which is the only answer worth giving: a check that predicts dispatch is wrong whenever it disagrees with dispatch, whichever way it leans. **This makes the pre-flight check stricter in one case** — a printer reporting a product name such as "PLA Basic" where the generic material is expected is now flagged rather than passed. That is the honest answer, and it is rare in practice, because the printer reports the material and the product name in separate fields. Nothing about which spool a print actually uses has changed. Covered by backend and frontend tests. - **A process preset that turns supports on had them switched back off by the file being sliced (#2820, reported by @zevulos)** — The server slicer is handed the picked process preset as the authoritative settings for the slice, so anything the preset does not name comes from the file's own embedded settings. Since #1881 four support fields travel the other way as well — supports on/off, the support and interface filament slots, and tree versus normal — because Bambu's shipped process presets all set supports off (supports are a decision per print, not per quality level), and without carrying them a project exported with supports configured came out of the slicer as a single-material print with a PVA slot loaded and never used. That carry ran in both directions, which is wrong in the direction nobody asked for: a file that ships with supports off, which is very nearly every published model, stripped supports back out of a preset that deliberately turned them on. The reporter's own preset turns supports on with normal(auto) and snug, and the slice came back with supports disabled and set to tree(auto) — the only setting of the three that survived was the style, and only because it is not one of the four fields carried and they had re-entered it in the slice dialog. The file can now switch supports on but never off. Nothing is lost by that: since every shipped preset has supports off, a preset that has them on is a deliberate choice by whoever wrote it, and a file that wants supports still gets them along with its slot assignments. A file that never states whether it wants supports at all is treated the same as one that says no. The carry is also written to the log now, naming the fields it took, because the slice dialog shows the picked preset's values and a carried field quietly disagrees with what was on screen — with nothing in the log to say so, this bug reads as the preset being ignored, and the log line the report understandably keyed on was an unrelated one about the source file's own settings. 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) == []