feat(diagnostics): log end-of-print telemetry for finish-photo trigger research (#2547)

The finish photo needs a "printing done, toolhead parked, filament unload
    not started" moment. stg_cur=22 was meant to be it (#1721) and fires on no
    model in the field: across 247 support bundles there is not one
    FINISH PHOTO MOMENT (stage-22), including the 2026-06-13..07-08 window where
    it was the only pre-FINISH trigger in the code — 104 captures on A1, A1 Mini,
    H2C, H2D, P1S, P2S, X1C and X2D, all of them the FINISH fallback.

    A replacement can't be designed from the bundles we have. Out of that window
    Bambuddy parses only stg_cur and mc_print_sub_stage; every other stage/action
    field arrives and is dropped unread. The candidates that sound right
    (print_real_action, mc_action, mc_stage) are absent from A1/A1 Mini/P1S
    payloads, so none of them can be the universal answer alone.

    Dump the raw fields for the window between the last object layer and
    gcode_state=FINISH at DEBUG. Opens on the first end-of-print signal (last
    layer, progress >= 99, or no remaining time) so a dropped layer_num packet
    doesn't lose it, logs only what changed frame to frame, closes on the
    transition out of RUNNING, and arms once per print.

    Instrumentation only: gated on DEBUG being enabled, read-only against printer
    state, wrapped so it cannot break ingest, and capped at 400 frames per print.
    The probed fields are stage codes, counters and bitfields — nothing
    identifying, and no access code.
This commit is contained in:
maziggy
2026-08-02 09:35:49 +02:00
3 changed files with 403 additions and 0 deletions
+3
View File
@@ -24,6 +24,9 @@ All notable changes to Bambuddy will be documented in this file.
- **The size-S printer card now shows remaining time, ETA and layer progress (#2674, reporter @jakestatefarm1101-alt)** — Size S existed for exactly one job: watching a whole fleet on one screen. But it rendered only the printer name, a status pip and a progress bar — every other block on the card is gated behind the expanded view — so it could not answer the question that view is for, "which printer finishes first". Dropping to S to fit more printers meant losing the information you dropped down to compare. The compact card now carries one line of metrics under the progress bar while a print is running: **remaining time**, **ETA** in your configured 12/24-hour format, and **layer progress** — the same values the Medium card already shows, using the same formatters and the same ETA styling so the two read alike. Each value is omitted individually when the printer doesn't report it, and the row holds its height when nothing is printing so cards don't shift as prints start and finish. Card dimensions and grid density are otherwise unchanged. Frontend-only. Wiki updated. Covered by tests.
### Changed
- **Debug logs now record what the printer reports between the last layer and the end of a print (#2547, reporter @anthonyma94)** — The finish photo wants a moment that Bambu firmware does not obviously announce: printing done, toolhead parked, filament unload not yet started. Bambuddy has been driving that capture from `stg_cur=22` ("Filament unloading"), which turns out to fire on no model at all — across 247 support bundles there is not a single stage-22 capture, including the window in which it was the only trigger in the code, where all 104 captures on A1, A1 Mini, H2C, H2D, P1S, P2S, X1C and X2D fell through to the after-the-fact fallback. Choosing a replacement was not possible from the bundles we had, because outside `stg_cur` and `mc_print_sub_stage` every stage and action field the printers send is dropped unread, and the most promising candidates (`print_real_action`, `mc_action`, `mc_stage`) are absent from A1, A1 Mini and P1S payloads entirely. With debug logging enabled, Bambuddy now dumps those raw fields for the window between the last object layer and the end of the print — opening on the first end-of-print signal (last layer reached, progress at 99+, or no remaining time), logging only what changed frame to frame, and closing on the state transition — so a single debug bundle per model can show whether any firmware marks that moment. Diagnostics only: nothing reads these values, they are printer telemetry with nothing identifying in them, and at normal log levels the probe does no work at all. Covered by tests for the window boundaries, the frame budget and the guarantee that the probe cannot break status ingest.
### Fixed
- **A printer that refuses Bambuddy's access code now says so, instead of reconnecting silently forever (#2698, reporter @djepsylon)** — A printer whose access code or serial was wrong produced no explanation anywhere: the connection attempt was refused, and the only trace was a warning every 30 seconds reading `MQTT disconnected: rc=Unspecified error` — the same line you get from a printer that is simply switched off. The failure branch of the MQTT connect callback set "not connected" and discarded the reason code the printer had just sent, so the one piece of evidence that would have named the cause never reached the log, the support bundle, or the UI. In the report behind this fix, one of three printers had been in that loop for the entire capture and nothing said why. **Fix.** A refused connection is now logged with the printer's own reason ("Not authorized", "Bad user name or password") and, for those two, the remedy — the access code is regenerated every time LAN Only or Developer Mode is toggled, so it has to be re-read from the printer's screen. The reason is kept on the connection, so the **Connection Diagnostic**'s *Printer credentials* check now states plainly that the printer refused the credentials when that is what happened, and falls back to hedged wording when all Bambuddy knows is that there is no session — previously it asserted "the access code is most likely wrong" even for a printer that was merely rebooting or already at its connection limit. The same reason is returned by the pre-add connection test. The access code itself is never written to the log. Translated in all locales; wiki updated. Covered by tests for both refusal codes, the clearing of the reason on a successful reconnect, the diagnostic's reason plumbing, and the two UI variants.
- **A2L AMS filament showed as "?" in Bambu Studio through the Virtual Printer, and manual filament picks reverted (#2697, reporter @qoatzelcoat)** — Every slot of the A2L's AMS Lite rendered as an empty question mark in the slicer's Device tab while Bambuddy's own AMS card showed type, colour and spool correctly; setting a filament by hand in Studio held for a second and then snapped back to "?". **Root cause.** The A2L reports its AMS Lite as physical unit id 16, but packs the slots' presence bits at bit base 24 — so Bambuddy normalises the id to 6 at the MQTT ingest boundary and every internal reader gets the right bits. The Virtual Printer's bridge, however, parses the printer's raw payload itself (by design — the slicer-facing cache has to keep the physical ids, since Bambu Studio addresses the Lite as 16) and so still held id 16 when it ran the shared empty-slot cleanup. That cleanup read bits 64-67, where nothing is ever set, concluded all four slots were empty and wiped `tray_type`, `tray_color`, `tray_info_idx` and the RFID fields from the copy sent to the slicer — once per second, which is also why a manual pick could not survive. **Fix.** The presence-bit helper now folds the physical id 16 onto the same bit base as the normalised 6, so it computes bits 24-27 whichever id reaches it; the cached ids the slicer sees are left untouched. Only the A2L was affected — every other AMS type already reached the helper with an id whose bit base was correct, and Bambuddy's own printer card was correct throughout. Confirmed against the reporter's debug log, which shows the cleanup clearing slots at bits 64-67. Covered by tests pinning the bit base for both ids and a bridge-level regression test built from the reporter's capture.
+161
View File
@@ -566,6 +566,58 @@ def get_stage_name(stage: int) -> str:
return STAGE_NAMES.get(stage, f"Unknown stage ({stage})")
# #2547 end-of-print telemetry probe.
#
# The finish photo needs a "printing is done, toolhead parked, filament unload
# not started yet" moment. ``stg_cur=22`` was meant to be that moment (#1721)
# but fires on no model in the field: across 247 support bundles there is not a
# single ``FINISH PHOTO MOMENT (stage-22)``, including the 2026-06-13..07-08
# window where it was the only pre-FINISH trigger in the code (104 captures on
# A1, A1 Mini, H2C, H2D, P1S, P2S, X1C, X2D — all of them the FINISH fallback).
#
# We can't design a replacement from bundles we already have, because out of
# this window Bambuddy only ever parses ``stg_cur`` and ``mc_print_sub_stage``;
# every other stage/action field is dropped unread. The obvious candidates
# (``print_real_action``, ``mc_action``, ``mc_stage``) are also absent from
# A1/A1 Mini/P1S payloads, so none of them can be the universal answer on its
# own. Dumping the raw values for the window between the last object layer and
# ``gcode_state=FINISH`` lets one debug bundle per model settle what — if
# anything — marks that moment.
#
# Every field here is machine telemetry (stage codes, counters, bitfields).
# Nothing identifying, and nothing that could carry an access code.
_END_OF_PRINT_PROBE_FIELDS = (
"gcode_state",
"state",
"print_error",
"stg_cur",
"stg",
"stg_cd",
"mc_print_stage",
"mc_print_sub_stage",
"mc_action",
"mc_stage",
"print_real_action",
"print_gcode_action",
"spd_lvl",
"mc_percent",
"mc_remaining_time",
"layer_num",
"total_layer_num",
"home_flag",
"prepare_per",
)
# Frame budget for one print's probe. A long final layer can hold the window
# open for minutes at ~1 frame/second; this stops a single print from filling
# the log the user then has to upload.
_END_OF_PRINT_PROBE_MAX_FRAMES = 400
# States that close the window. FINISH is the interesting one — the probe's
# whole job is to show what happened in the run-up to it.
_END_OF_PRINT_PROBE_CLOSING_STATES = frozenset({"FINISH", "FAILED", "IDLE", "PREPARE"})
class BambuMQTTClient:
"""MQTT client for Bambu Lab printer communication."""
@@ -669,6 +721,12 @@ class BambuMQTTClient:
# and the FINISH-state fallback don't both fire on the same
# print. Reset to False on every print start.
self._finish_photo_captured: bool = False
# #2547 end-of-print telemetry probe state. `_armed` is cleared once the
# window has run for a print so a late FINISH re-send can't reopen it.
self._eop_probe_armed: bool = True
self._eop_probe_open: bool = False
self._eop_probe_frames: int = 0
self._eop_probe_last: dict = {}
self._last_valid_progress: float = 0.0 # Last non-zero progress (firmware resets on cancel)
self._last_valid_layer_num: int = 0 # Last non-zero layer (firmware resets on cancel)
# The subtask_id minted for the most recent start_print() command. The
@@ -2790,10 +2848,108 @@ class BambuMQTTClient:
except Exception:
logger.exception("[%s] on_assignment_verified callback failed", self.serial_number)
@staticmethod
def _probe_number(value, fallback: float | None = None) -> float | None:
"""Coerce a telemetry field to a number, or return `fallback`.
Firmware is inconsistent about whether these arrive as ints or as
numeric strings, and the probe must never raise on a surprise type.
"""
try:
return float(value)
except (TypeError, ValueError):
return fallback
def _probe_end_of_print(self, data: dict) -> None:
"""Log raw end-of-print telemetry for one print at DEBUG (#2547).
Opens on the first frame that looks like end-of-print (last object
layer reached, progress at 99+, or no remaining time), then logs each
frame in which any probed field changed, and closes on the transition
out of RUNNING. Armed once per print — see the module-level comment on
``_END_OF_PRINT_PROBE_FIELDS`` for why this window is the one we can't
currently see into.
Read-only with respect to printer state: this is instrumentation, and
nothing downstream may come to depend on it.
"""
if not logger.isEnabledFor(logging.DEBUG):
return
if not self._eop_probe_open and not (self._eop_probe_armed and self._was_running):
return
present = {k: data[k] for k in _END_OF_PRINT_PROBE_FIELDS if k in data}
if not present:
return
if not self._eop_probe_open:
# Open on any end-of-print signal. Read from the raw frame first so
# the frame that *carries* the signal is itself captured — state
# fields are only updated further down this same call.
layer = self._probe_number(data.get("layer_num"), self.state.layer_num) or 0
total = self._probe_number(data.get("total_layer_num"), self.state.total_layers) or 0
percent = self._probe_number(data.get("mc_percent"), self.state.progress) or 0
remaining = self._probe_number(data.get("mc_remaining_time"), self.state.remaining_time)
at_last_layer = total > 0 and layer >= total
# `remaining <= 0` is only meaningful once the print has actually
# progressed — it reads 0 during the pre-print calibration too.
out_of_time = remaining is not None and remaining <= 0 and percent > 0
if not (at_last_layer or percent >= 99 or out_of_time):
return
self._eop_probe_open = True
self._eop_probe_frames = 0
self._eop_probe_last = {}
logger.debug(
"[%s] EOP-PROBE open — layer=%s/%s percent=%s remaining=%s",
self.serial_number,
layer,
total,
percent,
remaining,
)
closing = str(data.get("gcode_state") or "") in _END_OF_PRINT_PROBE_CLOSING_STATES
changed = {k: v for k, v in present.items() if self._eop_probe_last.get(k, object()) != v}
self._eop_probe_last.update(present)
if self._eop_probe_frames >= _END_OF_PRINT_PROBE_MAX_FRAMES and not closing:
if self._eop_probe_frames == _END_OF_PRINT_PROBE_MAX_FRAMES:
self._eop_probe_frames += 1
logger.debug(
"[%s] EOP-PROBE frame budget (%s) reached — suppressing until FINISH",
self.serial_number,
_END_OF_PRINT_PROBE_MAX_FRAMES,
)
return
if changed or closing:
self._eop_probe_frames += 1
logger.debug(
"[%s] EOP-PROBE %s%s: %s",
self.serial_number,
self._eop_probe_frames,
" CLOSE" if closing else "",
# `changed` on a closing frame can be empty; fall back to the
# full picture so the last line is always self-contained.
changed if changed else present,
)
if closing:
self._eop_probe_open = False
self._eop_probe_armed = False
self._eop_probe_last = {}
def _update_state(self, data: dict):
"""Update printer state from message data."""
_previous_state = self.state.state
# #2547: instrumentation only — runs before any state mutation so the
# frame carrying an end-of-print signal is logged as it arrived.
try:
self._probe_end_of_print(data)
except Exception: # pragma: no cover - a probe must never break ingest
logger.debug("[%s] EOP-PROBE failed", self.serial_number, exc_info=True)
# Update state fields
if "gcode_state" in data:
self.state.state = data["gcode_state"]
@@ -3938,6 +4094,11 @@ class BambuMQTTClient:
self._completion_triggered = False
# #1721: rearm the end-of-print finish-photo trigger for the new print
self._finish_photo_captured = False
# #2547: rearm the end-of-print telemetry probe for the new print
self._eop_probe_armed = True
self._eop_probe_open = False
self._eop_probe_frames = 0
self._eop_probe_last = {}
# Reset last valid progress/layer for usage tracking
self._last_valid_progress = 0.0
self._last_valid_layer_num = 0
@@ -6738,3 +6738,242 @@ class TestConnectRefusalReporting:
assert "MQTT disconnected" in caplog.text
assert "refused" not in caplog.text
class TestEndOfPrintProbe:
"""Tests for #2547: the end-of-print telemetry probe.
The probe exists to answer a question no existing support bundle can:
what do the stage/action fields do between the last object layer and
gcode_state=FINISH? stg_cur=22 was supposed to mark "toolhead parked,
before filament unload" (#1721) and fires on no model in the field, and
Bambuddy drops every other stage field unread. These tests pin the
window's boundaries and the guarantee that instrumentation stays
instrumentation — it must never raise into the ingest path.
"""
LOGGER = "backend.app.services.bambu_mqtt"
@pytest.fixture
def mqtt_client(self):
from backend.app.services.bambu_mqtt import BambuMQTTClient
client = BambuMQTTClient(
ip_address="192.168.1.100",
serial_number="TEST123",
access_code="12345678",
)
client._was_running = True
client.state.state = "RUNNING"
client.state.total_layers = 100
client.state.layer_num = 98
client.state.progress = 90.0
client.state.remaining_time = 12
return client
def test_silent_when_debug_logging_is_off(self, mqtt_client, caplog):
"""The probe is a debug tool; at INFO it must cost nothing and say
nothing, including for a frame that would otherwise open the window."""
with caplog.at_level(logging.INFO, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100}})
assert "EOP-PROBE" not in caplog.text
assert mqtt_client._eop_probe_open is False
def test_does_not_open_mid_print(self, mqtt_client, caplog):
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 99, "mc_percent": 91}})
assert "EOP-PROBE" not in caplog.text
assert mqtt_client._eop_probe_open is False
def test_opens_on_the_last_layer_frame_itself(self, mqtt_client, caplog):
"""The frame carrying the signal must be captured, not just the ones
after it — so the probe has to read the raw frame rather than state,
which _update_state only updates further down the same call."""
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100, "stg_cur": 0}})
assert "EOP-PROBE open" in caplog.text
assert "'layer_num': 100" in caplog.text
assert mqtt_client._eop_probe_open is True
def test_opens_on_progress_when_the_last_layer_packet_is_missed(self, mqtt_client, caplog):
"""The layer_num edge is a single transient packet and is dropped
intermittently (the reason #1867 needed a second mechanism). Progress
has to be able to open the window on its own."""
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"mc_percent": 99}})
assert "EOP-PROBE open" in caplog.text
assert mqtt_client._eop_probe_open is True
def test_zero_remaining_does_not_open_before_the_print_progresses(self, mqtt_client, caplog):
"""mc_remaining_time reads 0 during pre-print calibration too, so it
only counts once progress is non-zero."""
mqtt_client.state.progress = 0.0
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"mc_remaining_time": 0, "mc_percent": 0}})
assert "EOP-PROBE" not in caplog.text
def test_does_not_open_when_the_print_never_ran(self, mqtt_client, caplog):
"""Bambuddy restarted mid-print, or firmware replayed a stale frame."""
mqtt_client._was_running = False
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100}})
assert "EOP-PROBE" not in caplog.text
def test_logs_only_changed_fields_after_opening(self, mqtt_client, caplog):
"""Most probed fields are static across the window; logging all of
them every frame would bury the transitions we're looking for."""
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100, "stg_cur": 0}})
caplog.clear()
# Identical frame — nothing moved, so nothing to say.
mqtt_client._process_message({"print": {"layer_num": 100, "stg_cur": 0}})
assert "EOP-PROBE" not in caplog.text
mqtt_client._process_message({"print": {"layer_num": 100, "stg_cur": 22}})
assert "'stg_cur': 22" in caplog.text
assert "layer_num" not in caplog.text.split("EOP-PROBE")[-1]
def test_captures_the_fields_bambuddy_does_not_parse(self, mqtt_client, caplog):
"""The whole point: mc_stage / mc_action / print_real_action are read
by nothing else in the codebase, so only the probe can show them."""
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100}})
mqtt_client._process_message(
{
"print": {
"mc_stage": 3,
"mc_action": 8,
"print_real_action": 2,
"print_gcode_action": 5,
"stg_cd": 1,
"home_flag": 2231371,
"spd_lvl": 0,
}
}
)
for field in ("mc_stage", "mc_action", "print_real_action", "print_gcode_action", "stg_cd", "spd_lvl"):
assert field in caplog.text
def test_closes_on_finish_and_does_not_reopen(self, mqtt_client, caplog):
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100}})
mqtt_client._process_message({"print": {"gcode_state": "FINISH"}})
assert "EOP-PROBE 2 CLOSE" in caplog.text
assert mqtt_client._eop_probe_open is False
assert mqtt_client._eop_probe_armed is False
caplog.clear()
# Firmware re-sending FINISH, or a stale replay, must not restart it.
mqtt_client._process_message({"print": {"layer_num": 100, "mc_percent": 100}})
assert "EOP-PROBE" not in caplog.text
def test_closing_frame_is_self_contained_when_nothing_changed(self, mqtt_client, caplog):
"""A FINISH frame that repeats values already seen still has to log
something — otherwise the window has no visible end."""
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"gcode_state": "RUNNING", "mc_percent": 100}})
caplog.clear()
mqtt_client._process_message({"print": {"gcode_state": "FINISH"}})
# Same value the probe already recorded on the opening frame.
mqtt_client._eop_probe_open = True
mqtt_client._eop_probe_armed = True
mqtt_client._eop_probe_last = {"gcode_state": "FINISH"}
mqtt_client._process_message({"print": {"gcode_state": "FINISH"}})
assert "CLOSE" in caplog.text
assert "'gcode_state': 'FINISH'" in caplog.text
def test_rearms_for_the_next_print(self, mqtt_client, caplog):
# A completion callback is what lets _update_state finish the print
# (and clear _was_running), which the new-print detection depends on.
mqtt_client.on_print_complete = lambda data: None
mqtt_client.state.gcode_file = "current.3mf"
mqtt_client._previous_gcode_state = "RUNNING"
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100}})
mqtt_client._process_message({"print": {"gcode_state": "FINISH"}})
assert mqtt_client._eop_probe_armed is False
# New print: RUNNING again with a file, after the previous print
# completed. _update_state rearms the probe alongside the
# finish-photo one-shot.
mqtt_client._process_message(
{"print": {"gcode_state": "RUNNING", "gcode_file": "next.3mf", "subtask_name": "next"}}
)
assert mqtt_client._eop_probe_armed is True
caplog.clear()
mqtt_client.state.total_layers = 50
mqtt_client._process_message({"print": {"layer_num": 50}})
assert "EOP-PROBE open" in caplog.text
def test_frame_budget_caps_output_but_still_logs_the_close(self, mqtt_client, caplog):
"""A long final layer holds the window open at ~1 frame/second; the
user still has to be able to upload the resulting log."""
from backend.app.services.bambu_mqtt import _END_OF_PRINT_PROBE_MAX_FRAMES
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100}})
for i in range(_END_OF_PRINT_PROBE_MAX_FRAMES + 50):
mqtt_client._process_message({"print": {"mc_remaining_time": i}})
assert "frame budget" in caplog.text
caplog.clear()
mqtt_client._process_message({"print": {"gcode_state": "FINISH"}})
assert "CLOSE" in caplog.text
def test_opens_on_numeric_strings(self, mqtt_client, caplog):
"""Firmware sends these as ints or as numeric strings depending on
model and field, so the window checks must coerce rather than compare
a str against an int and silently never open."""
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": "100", "mc_percent": "99"}})
assert "EOP-PROBE open" in caplog.text
assert mqtt_client._eop_probe_open is True
def test_coercion_helper_falls_back_on_junk(self, mqtt_client):
"""Unit-level, because feeding junk through _process_message would trip
the pre-existing parsers before ever reaching the probe. The guarantee
under test is only that the probe's own reads can't raise."""
assert mqtt_client._probe_number("100") == 100.0
assert mqtt_client._probe_number("not-a-number", 7) == 7
assert mqtt_client._probe_number(None) is None
assert mqtt_client._probe_number({"unexpected": "shape"}, 0) == 0
def test_probe_failure_cannot_break_ingest(self, mqtt_client, caplog, monkeypatch):
"""Instrumentation must stay instrumentation: if the probe ever throws,
state parsing still has to complete."""
def boom(_data):
raise RuntimeError("probe exploded")
monkeypatch.setattr(mqtt_client, "_probe_end_of_print", boom)
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"gcode_state": "RUNNING", "layer_num": 100}})
assert mqtt_client.state.layer_num == 100
assert "EOP-PROBE failed" in caplog.text
def test_never_logs_the_access_code(self, mqtt_client, caplog):
with caplog.at_level(logging.DEBUG, logger=self.LOGGER):
mqtt_client._process_message({"print": {"layer_num": 100}})
mqtt_client._process_message({"print": {"gcode_state": "FINISH"}})
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)