fix(mqtt): keep the layer total that arrives with the print-start frame (#2702)

fix(support): redact push_status values, not the serialised JSON (#2702)
This commit is contained in:
maziggy
2026-08-02 09:41:19 +02:00
5 changed files with 536 additions and 20 deletions
+36 -6
View File
@@ -1227,6 +1227,35 @@ def _redact_raw_push_status(raw: dict) -> dict:
return out
def _sanitize_push_status_values(node, sensitive_strings: dict[str, str]):
"""Sanitize a push_status snapshot's string *values*, never its JSON text.
This used to run :func:`sanitize_log_content` over the serialised snapshot.
That pass includes a generic Bambu-serial regex
(``0[0-3][A-Z0-9][A-Z0-9]{9,13}`` in ``log_reader``) which matches the
decimal expansion of a float just as happily as a serial: an AMS ``k`` flow
factor of ``0.0199999995529652`` came out as ``0.[SERIAL]``, and the bundle
shipped invalid JSON — unusable for exactly the ground-truth purpose the
snapshot exists for (found while diagnosing #2702).
Walking the structure instead leaves numbers, bools and None untouched, so
the output always parses. Keys are structural and never rewritten.
"""
if isinstance(node, str):
return sanitize_log_content(node, sensitive_strings)
if isinstance(node, dict):
return {k: _sanitize_push_status_values(v, sensitive_strings) for k, v in node.items()}
if isinstance(node, list | tuple):
# Tuples too: `json.dumps` renders them as arrays, so stringifying one
# here would change the file's shape rather than just its content.
return [_sanitize_push_status_values(v, sensitive_strings) for v in node]
if node is None or isinstance(node, bool | int | float):
return node
# Anything else (datetime, Decimal, …) would be stringified by json.dumps'
# ``default=str`` *after* this pass and so escape sanitisation entirely.
return sanitize_log_content(str(node), sensitive_strings)
async def _get_recent_sanitized_logs(max_lines: int = 200) -> str:
"""Get recent log lines, sanitized for inclusion in bug reports."""
# Collect sensitive strings from DB for redaction
@@ -1300,12 +1329,13 @@ async def generate_support_bundle(
"captured_at": datetime.now(timezone.utc).isoformat(),
"raw_data": redacted,
}
# Belt-and-suspenders: pass the JSON text through the string-based
# sanitizer so any user-named string (printer name, serial baked
# into a tray uuid) the structural pass missed still gets caught.
snapshot_json = json.dumps(snapshot, indent=2, default=str)
snapshot_json = sanitize_log_content(snapshot_json, sensitive_strings)
zf.writestr(f"push-status/printer-{i + 1}.json", snapshot_json)
# Belt-and-suspenders: pass every string value through the
# string-based sanitizer so any user-named string (printer name,
# serial baked into a tray uuid) the structural pass missed still
# gets caught. Values only — sanitizing the serialised JSON text
# corrupted numeric literals (see _sanitize_push_status_values).
snapshot = _sanitize_push_status_values(snapshot, sensitive_strings)
zf.writestr(f"push-status/printer-{i + 1}.json", json.dumps(snapshot, indent=2, default=str))
# Add log file
# Off the event loop: this reads up to 10 MB and then runs one full regex
+77 -14
View File
@@ -736,6 +736,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
# #2702: one-shot re-request of the layer total. Armed at print start
# when the starting frame carried no `total_layer_num`, spent on the
# first layer advance that still has no denominator. Bambu firmware
# only re-sends *changed* fields, so a total we never received (or
# dropped) is only recoverable via a full pushall.
self._total_layers_refresh_armed: 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
@@ -2993,6 +2999,29 @@ class BambuMQTTClient:
f"{self.state.mc_print_sub_stage} -> {new_sub_stage}"
)
self.state.mc_print_sub_stage = new_sub_stage
# Positive `total_layer_num` carried by *this* frame, or 0. Read up
# front because three places below consult it and they run in an order
# that is not the order they read most naturally in: the layer-advance
# refresh (#2702) must not fire on a frame that already answers it, the
# apply step must ignore firmware-reset 0s (#1771), and the new-print
# reset must not discard a total that belongs to the starting print.
total_from_this_frame = 0
if "total_layer_num" in data:
try:
total_from_this_frame = max(int(data["total_layer_num"] or 0), 0)
except (TypeError, ValueError):
# Must not escape. `_on_message` catches only JSONDecodeError
# and paho is left at `suppress_exceptions = False`, so an
# exception raised here is re-raised on the network thread and
# takes the printer connection down over one unusable field.
# Treat it as "not reported": the refresh below then recovers
# the real total from a pushall.
logger.debug(
"[%s] ignoring unusable total_layer_num: %r",
self.serial_number,
data["total_layer_num"],
)
if "layer_num" in data:
new_layer = int(data["layer_num"])
old_layer = self.state.layer_num
@@ -3003,6 +3032,25 @@ class BambuMQTTClient:
# Trigger layer change callback if layer increased
if new_layer > old_layer and self.on_layer_change:
self.on_layer_change(new_layer)
# #2702: the print is demonstrably laying down layers but we still
# have no denominator, so the pushall requested at print start
# either went unanswered or raced the printer learning the total.
# Ask once more — by layer 1 the printer definitely knows it.
# One-shot: an unanswered pushall must not turn into a per-layer
# retry loop for the rest of the print.
if (
new_layer > old_layer
and self._total_layers_refresh_armed
and not self.state.total_layers
and not total_from_this_frame
):
self._total_layers_refresh_armed = False
logger.debug(
"[%s] layer %s with no total_layer_num — re-requesting full status",
self.serial_number,
new_layer,
)
self._request_push_all()
# #1867 last-layer finish-photo trigger. A1 Mini (and other
# firmware variants) skips `stg_cur=22`, so the fallback fires
# at gcode_state=FINISH — which runs AFTER user End G-code
@@ -3032,15 +3080,12 @@ class BambuMQTTClient:
"timelapse_was_active": self._timelapse_during_print,
}
)
if "total_layer_num" in data:
# Some firmware (P1S observed) resets `total_layer_num` to 0 at
# print end — same shape as the `layer_num` reset guarded above.
# Preserve the last known good value so the usage-tracker split
# path (#1771) has a denominator that survives the reset frame.
# Explicit reset to 0 happens on print start (`_handle_print_start`).
new_total = int(data["total_layer_num"])
if new_total > 0:
self.state.total_layers = new_total
if total_from_this_frame:
# Firmware (P1S observed) resets `total_layer_num` to 0 at print
# end — same shape as the `layer_num` reset guarded above. Applying
# only positive values preserves the last known good denominator so
# the usage-tracker split path (#1771) survives the reset frame.
self.state.total_layers = total_from_this_frame
# Fan speeds (MQTT sends as string "0"-"15" representing speed levels, or percentage)
# Convert to 0-100 percentage for display
@@ -4152,11 +4197,29 @@ class BambuMQTTClient:
# Reset layer tracking for new print (needed for layer-based timelapse)
self.state.layer_num = 0
# Reset total_layers so the previous print's value can't bleed into
# this print's usage-tracker split before the new push_status arrives
# with the slicer's total (#1771 follow-on to the preservation guard
# above at line ~2135 — the guard now ignores firmware-reset 0s, so
# the explicit reset has to happen here instead).
self.state.total_layers = 0
# this print's usage-tracker split (#1771 follow-on to the
# preservation guard at the `total_layer_num` parse above — that
# guard ignores firmware-reset 0s, so the explicit reset has to
# happen here instead).
#
# #2702: reset to *this frame's* total, not to 0. The frame that
# trips the new-print detection can carry the new print's
# `total_layer_num` as well — the parse above has already applied
# it, and zeroing unconditionally threw it away. That looked
# harmless but is not recoverable: Bambu firmware sends only
# changed fields, so the printer never offers the total again, and
# the print runs to completion at `n/0` in the UI, in
# `{total_layers}` notifications, and as the usage-split
# denominator. The value only reappears on the next full pushall
# (reconnect / Force Refresh), which is why the symptom looked
# random and why a *stable* connection made it worse.
self.state.total_layers = total_from_this_frame
# If the starting frame brought no total, ask for one. Costs one
# MQTT message per print and covers the ordering where the printer
# published the total a frame or two before the state flip.
self._total_layers_refresh_armed = not total_from_this_frame
if self._total_layers_refresh_armed:
self._request_push_all()
# Reset completion tracking for new print
self._was_running = True
self._completion_triggered = False
@@ -0,0 +1,255 @@
"""The layer total must survive the print-start reset (#2702).
`_update_state` applies `total_layer_num` early and, further down, resets
`total_layers` when it detects a new print (added by #1771 so the previous
print's total can't bleed into the next one's usage split). Those two run in
the same function on the same frame, so a frame that carried both the new
print's total *and* the transition into RUNNING had its total applied and then
zeroed.
That is unrecoverable rather than merely late: Bambu firmware sends only
changed fields, so the printer never re-sends a total it already published.
The value reappears only in a full pushall — i.e. on reconnect or a manual
Force Refresh — which is why the reporter saw `n/0` for nine minutes on a
flawless connection, why it looked random, and why a *stable* link made it
worse.
Frames here are trimmed to the fields the code under test reads. No printer is
needed: the fix is a property of how one function orders its own writes.
"""
from __future__ import annotations
import json
import pytest
@pytest.fixture
def client():
"""A client with a recording stand-in for the MQTT connection."""
from unittest.mock import MagicMock
from backend.app.services.bambu_mqtt import BambuMQTTClient
c = BambuMQTTClient(
ip_address="192.168.1.100",
serial_number="TEST123",
access_code="12345678",
)
c._client = MagicMock()
# A new print is only detected once a previous state has been observed
# (#1304 guard), so give every test a plausible pre-print history.
c._previous_gcode_state = "IDLE"
c._previous_gcode_file = None
c._was_running = False
return c
def pushalls(client) -> list[dict]:
"""Every pushall published on this client, decoded."""
sent = []
for call in client._client.publish.call_args_list:
payload = json.loads(call.args[1])
if payload.get("pushing", {}).get("command") == "pushall":
sent.append(payload)
return sent
def running_frame(**extra) -> dict:
"""A frame that flips the printer into RUNNING with a file — a new print."""
return {"gcode_state": "RUNNING", "gcode_file": "widget.3mf", "subtask_name": "widget", **extra}
# ---------------------------------------------------------------------------
# The regression
# ---------------------------------------------------------------------------
def test_total_arriving_with_the_start_frame_survives(client):
"""The reported bug: total and transition in one frame lost the total."""
client._update_state(running_frame(total_layer_num=33, layer_num=0))
assert client.state.total_layers == 33
def test_total_arriving_with_the_start_frame_needs_no_pushall(client):
"""We already have the denominator, so don't spend a round-trip on it."""
client._update_state(running_frame(total_layer_num=33))
assert pushalls(client) == []
assert client._total_layers_refresh_armed is False
def test_previous_prints_total_still_cannot_bleed_through(client):
"""#1771's reason for the reset — preserved exactly.
A start frame with no total of its own must land on 0, never on the
finished print's denominator.
"""
client.state.total_layers = 120 # left over from the print that just ended
client._update_state(running_frame())
assert client.state.total_layers == 0
def test_start_frame_without_a_total_asks_the_printer_for_one(client):
"""Covers the ordering where the total was published a frame or two early.
Re-applying this frame's own value can't help there — the value was
already consumed and zeroed — so recovery has to come from a pushall,
the only message that re-sends unchanged fields.
"""
client._update_state(running_frame())
assert len(pushalls(client)) == 1
assert client._total_layers_refresh_armed is True
# ---------------------------------------------------------------------------
# The one-shot re-request
# ---------------------------------------------------------------------------
def test_first_layer_advance_without_a_total_re_requests_once(client):
client._update_state(running_frame())
assert len(pushalls(client)) == 1 # from print start
client._update_state({"layer_num": 1})
assert len(pushalls(client)) == 2
assert client._total_layers_refresh_armed is False
def test_later_layer_advances_do_not_keep_re_requesting(client):
"""An unanswered pushall must not become a per-layer retry loop."""
client._update_state(running_frame())
client._update_state({"layer_num": 1})
before = len(pushalls(client))
for layer in range(2, 12):
client._update_state({"layer_num": layer})
assert len(pushalls(client)) == before
def test_no_re_request_once_the_total_is_known(client):
"""The pushall answered: layers advance without further traffic."""
client._update_state(running_frame())
client._update_state({"total_layer_num": 33}) # the pushall's answer
before = len(pushalls(client))
client._update_state({"layer_num": 1})
client._update_state({"layer_num": 2})
assert client.state.total_layers == 33
assert len(pushalls(client)) == before
def test_the_recovered_total_is_what_downstream_reads(client):
"""End-to-end on the reporter's sequence, minus the 9-minute wait.
Start with no total, layers advance at `n/0`, the pushall answers, and
from then on the UI, `{total_layers}` notifications and the usage-split
denominator all see 33 — they read this one field.
"""
client._update_state(running_frame())
client._update_state({"layer_num": 1})
assert client.state.total_layers == 0 # the symptom in the screenshot
client._update_state({"layer_num": 2, "total_layer_num": 33})
assert (client.state.layer_num, client.state.total_layers) == (2, 33)
def test_the_pushall_answer_does_not_re_trigger_the_reset(client):
"""Loop safety: the answer is a *full* frame, gcode_state and file included.
If that re-tripped the new-print detection it would reset the total it just
delivered and request another pushall, once per round-trip, forever.
"""
client._update_state(running_frame())
assert len(pushalls(client)) == 1
client._update_state(running_frame(total_layer_num=33, layer_num=1, mc_percent=3))
assert client.state.total_layers == 33
assert len(pushalls(client)) == 1
# ---------------------------------------------------------------------------
# Interaction with the pre-existing firmware-reset guard
# ---------------------------------------------------------------------------
def test_firmware_reset_to_zero_mid_print_is_still_ignored(client):
"""P1S zeroes total_layer_num at print end; #1771's guard keeps the total."""
client._update_state(running_frame(total_layer_num=33))
client._update_state({"layer_num": 33, "total_layer_num": 0})
assert client.state.total_layers == 33
@pytest.mark.parametrize("value", [None, "", 0, "0", -1, "abc", "33.7", [], {}, 3.9])
def test_unusable_totals_do_not_break_ingest(client, value):
"""A bad total must not escape `_update_state`.
The old parse did a bare ``int(data["total_layer_num"])``. `_on_message`
catches only `JSONDecodeError` and paho is left at
``suppress_exceptions = False``, so anything this raised was re-raised on
the network thread and took the printer connection down over one field.
`None`, `[]` and `{}` all did exactly that.
"""
client._update_state(running_frame(total_layer_num=value))
assert client.state.total_layers in (0, 3) # 3.9 truncates; the rest are 0
assert client.state.gcode_file == "widget.3mf" # the rest of the frame landed
def test_an_unusable_total_does_not_stop_the_layer_counter(client):
"""The read happens before the layer block, so it must not be able to raise.
Otherwise a firmware sending a malformed total would freeze `layer_num` for
the whole print — the frame would abort before reaching it.
"""
client._update_state(running_frame())
client._update_state({"layer_num": 7, "total_layer_num": "not-a-number"})
assert client.state.layer_num == 7
def test_a_string_total_is_accepted(client):
"""Bambu ships numbers as strings in plenty of other fields."""
client._update_state(running_frame(total_layer_num="33"))
assert client.state.total_layers == 33
def test_a_zero_total_on_the_start_frame_counts_as_no_total(client):
"""`total_layer_num: 0` is the firmware's "don't know yet", not a value."""
client.state.total_layers = 120
client._update_state(running_frame(total_layer_num=0))
assert client.state.total_layers == 0
assert len(pushalls(client)) == 1
# ---------------------------------------------------------------------------
# A restarted print (file change while RUNNING) takes the same path
# ---------------------------------------------------------------------------
def test_file_change_while_running_also_keeps_its_own_total(client):
"""`is_file_change` shares the reset, so it needs the same treatment."""
client._update_state(running_frame(total_layer_num=33))
client._was_running = True
client._update_state(
{"gcode_state": "RUNNING", "gcode_file": "other.3mf", "subtask_name": "other", "total_layer_num": 77}
)
assert client.state.total_layers == 77
+166
View File
@@ -1285,3 +1285,169 @@ class TestRedactRawPushStatus:
assert _redact_raw_push_status(None) == {} # type: ignore[arg-type]
assert _redact_raw_push_status([]) == {} # type: ignore[arg-type]
assert _redact_raw_push_status("") == {} # type: ignore[arg-type]
class TestSanitizePushStatusValues:
"""The bundled push_status snapshot must stay parseable JSON.
Sanitization used to run over the *serialised* snapshot. The generic
Bambu-serial regex in ``log_reader`` (``0[0-3][A-Z0-9][A-Z0-9]{9,13}``)
matches the decimal expansion of a float as readily as a serial, so an AMS
``k`` flow factor came out as ``0.[SERIAL]`` and the whole file stopped
parsing — found in a real bundle while diagnosing #2702, which is exactly
the case the snapshot was added to serve.
"""
def test_float_that_matches_the_serial_regex_survives(self):
"""The observed reproducer, verbatim."""
import json
from backend.app.api.routes.support import _sanitize_push_status_values
raw = {"ams": [{"tray": [{"k": 0.0199999995529652}]}]}
out = _sanitize_push_status_values(raw, {})
assert json.loads(json.dumps(out)) == raw
def test_output_always_parses(self):
"""Whatever it does to values, the result must be valid JSON."""
import json
from backend.app.api.routes.support import _sanitize_push_status_values
raw = {
"k_values": [0.0199999995529652, 0.019999999552965164, 0.02],
"home_flag": 7554487,
"sdcard": True,
"resolution": "",
"nozzle": None,
}
json.loads(json.dumps(_sanitize_push_status_values(raw, {})))
def test_still_redacts_strings(self):
"""The point of the pass is not lost — string values are sanitized."""
from backend.app.api.routes.support import _sanitize_push_status_values
raw = {"tag_uid": "0123456789ABCDEF", "name": "Martin's P1S", "ip": "192.168.1.50"}
out = _sanitize_push_status_values(raw, {"Martin's P1S": "[PRINTER]"})
assert out["tag_uid"] == "[SERIAL]"
assert out["name"] == "[PRINTER]"
assert out["ip"] == "[IP]"
def test_walks_nested_containers(self):
from backend.app.api.routes.support import _sanitize_push_status_values
raw = {"ams": [{"tray": [{"tray_uuid": "0123456789ABCDEF"}]}]}
out = _sanitize_push_status_values(raw, {})
assert out["ams"][0]["tray"][0]["tray_uuid"] == "[SERIAL]"
def test_keys_are_left_alone(self):
"""Keys are structural — renaming one would break the schema."""
from backend.app.api.routes.support import _sanitize_push_status_values
raw = {"0123456789ABCDEF": 1}
assert list(_sanitize_push_status_values(raw, {})) == ["0123456789ABCDEF"]
def test_non_json_scalars_are_sanitized_not_smuggled(self):
"""``json.dumps(default=str)`` runs after this pass, so do it here."""
from datetime import datetime, timezone
from backend.app.api.routes.support import _sanitize_push_status_values
raw = {"seen_at": datetime(2026, 7, 29, 23, 12, 40, tzinfo=timezone.utc), "who": object()}
out = _sanitize_push_status_values(raw, {"2026-07-29": "[WHEN]"})
assert out["seen_at"].startswith("[WHEN]")
assert isinstance(out["who"], str)
def test_bools_stay_bools(self):
"""`isinstance(True, int)` — a bool must not fall through to str()."""
from backend.app.api.routes.support import _sanitize_push_status_values
out = _sanitize_push_status_values({"sdcard": True, "force_upgrade": False}, {})
assert out["sdcard"] is True
assert out["force_upgrade"] is False
def test_the_full_bundle_chain_on_a_real_p1s_payload(self):
"""The route's transform, end to end, on the shape from the #2702 bundle.
`_redact_raw_push_status` then `_sanitize_push_status_values` then
`json.dumps(default=str)` — the composition the bundle writer applies.
The bundle that exposed this had five `k` values corrupted, so the
snapshot could not be read at all; the field the report was about
(`total_layer_num`) was sitting in it, intact and unreachable.
"""
import json
from backend.app.api.routes.support import (
_redact_raw_push_status,
_sanitize_push_status_values,
)
raw = {
"gcode_file": "AMS_Filament_Clip_3MF.3mf",
"layer_num": 2,
"total_layer_num": 33,
"home_flag": 7554487,
"sdcard": True,
"net": {"info": [{"ip": "192.168.1.50", "mask": 0}]},
"ams": {
"ams": [
{
"id": "0",
"humidity": "5",
"tray": [
{"id": "0", "k": 0.0199999995529652, "tag_uid": "0123456789ABCDEF"},
{"id": "1", "k": 0.0209999997168779, "tag_uid": "44F782D000000100"},
],
}
]
},
}
snapshot = {
"model": "P1S",
"firmware_version": "01.10.00.00",
"raw_data": _redact_raw_push_status(raw),
}
text = json.dumps(_sanitize_push_status_values(snapshot, {}), indent=2, default=str)
parsed = json.loads(text) # used to raise "Expecting ',' delimiter"
trays = parsed["raw_data"]["ams"]["ams"][0]["tray"]
assert [t["k"] for t in trays] == [0.0199999995529652, 0.0209999997168779]
assert parsed["raw_data"]["total_layer_num"] == 33
# Redaction still did its job on both fronts.
assert "gcode_file" not in parsed["raw_data"]
assert trays[0]["tag_uid"] == "[SERIAL]"
# The structural pass replaces the printer's LAN address with the
# sentinel 0.0.0.0, which is itself an IPv4 literal, so the value pass
# then masks it to [IP]. Harmless — the real address is already gone —
# and matches what shipped in the bundle behind #2702.
assert parsed["raw_data"]["net"]["info"][0]["ip"] == "[IP]"
def test_does_not_mutate_the_live_snapshot(self):
"""`state.raw_data` is read by the dispatcher on every tick.
The bundle writer passes a redacted copy, but a walker that mutated in
place would still be one refactor away from redacting the live state.
"""
import copy
from backend.app.api.routes.support import _sanitize_push_status_values
raw = {"tag_uid": "0123456789ABCDEF", "ams": [{"tray": [{"k": 0.02, "n": "0123456789ABCDEF"}]}]}
before = copy.deepcopy(raw)
out = _sanitize_push_status_values(raw, {})
assert raw == before, "input was mutated"
assert out["tag_uid"] == "[SERIAL]" # and the copy really was redacted