feat(vp): mirror live print progress to the slicer (#1887)

A server-mode VP with a target printer bound showed the print as a bare
filename in Bambu Studio / OrcaSlicer -- no stage, percentage, layer count or
time remaining. The data was already in the bridge cache; we were overwriting
it with zeros, because passing it through made the slicer read the VP as busy
and hide the Send button (#1558).

Both slicers gate the progress panel and the Send button on one predicate,
MachineObject::is_in_printing() -- gcode_state in RUNNING/PAUSE/SLICING/PREPARE
-- so there is no field-level way to have both. FINISH is the one state in the
gap: StatusPanel::update_subtask() renders the panel for it, and
SelectMachineDialog::update_show_status() does not disable Send. The VP already
parks at FINISH after each upload (#1280 / #1658), so it only needed the real
numbers underneath it.

While the target prints and no upload is in flight, the report now holds
gcode_state=FINISH and passes mc_print_stage, mc_percent, mc_remaining_time,
stg, stg_cur, layer_num and total_layer_num through from the cache. Mirroring
is suppressed during PREPARE and for 5s after the last upload transition, so
the slicer still receives the FINISH carrying its own subtask_name and releases
its send modal. print_error is never mirrored -- it would raise a modal error
dialog for a fault the VP did not throw.
This commit is contained in:
maziggy
2026-07-11 10:06:03 +02:00
parent 6b3dd63513
commit f2e113ce20
3 changed files with 282 additions and 65 deletions
+1
View File
File diff suppressed because one or more lines are too long
@@ -11,6 +11,7 @@ import json
import logging
import socket
import ssl
import time
from collections.abc import Callable
from pathlib import Path
from typing import TYPE_CHECKING
@@ -41,6 +42,27 @@ _AUTH_RATE_LIMIT_WINDOW_SECONDS = 60.0
# commands without ever consuming responses can't leak memory.
_PENDING_REQUEST_MAX_ENTRIES = 256
# Target-printer gcode_states for which the VP mirrors live print progress to
# the slicer (#1887). BambuStudio and OrcaSlicer gate BOTH the Device-tab
# progress panel and the Send button on the same predicate —
# `MachineObject::is_in_printing()`, i.e. gcode_state in
# {RUNNING, PAUSE, SLICING, PREPARE} — so reporting the real state verbatim
# would show progress at the cost of blocking Send for as long as the printer
# prints. That is exactly the #1558 regression. `FINISH` is the one state that
# renders the progress panel (`is_in_printing() || print_status == "FINISH"` in
# StatusPanel::update_subtask) while leaving Send enabled, so the mirror keeps
# reporting FINISH and only fills in the numbers underneath it.
_MIRRORED_PRINT_STATES = frozenset({"RUNNING", "PAUSE"})
# How long after the last upload-state transition the VP keeps echoing the
# slicer's own filename back at it before switching the report over to whatever
# the target printer is really printing. The slicer releases its in-flight-job
# lock when it sees gcode_state=FINISH carrying the subtask_name it uploaded
# (#1280 / #1658); swapping in the printer's filename while that handshake is
# still in flight wedges the send modal at "Downloading". 5 s covers the 1.5 s
# `_schedule_finish_release` timer plus several 1 Hz pushes.
_UPLOAD_SETTLE_SECONDS = 5.0
# Model code → product_name for version response (must match what slicer expects)
MODEL_PRODUCT_NAMES = {
"BL-P001": "X1 Carbon",
@@ -245,6 +267,11 @@ class SimpleMQTTServer:
self._gcode_state = "IDLE"
self._current_file = ""
self._prepare_percent = "0"
# Monotonic timestamp of the last upload-state transition, so the live-
# progress mirror can tell whether the slicer is still waiting on its
# own upload handshake. Starts at -inf: a VP that has never seen an
# upload has no handshake to protect and can mirror immediately.
self._state_changed_at = float("-inf")
# MQTT bridge for non-proxy modes — set by VirtualPrinterInstance after start().
# When the bridge is_active, real printer pushes are fanned out to slicers and
@@ -895,6 +922,11 @@ class SimpleMQTTServer:
push_status shape against what it expects from the printer model, and
the synthetic stub introduced fields the real H2D doesn't have (storage,
the wrong chamber_temper shape, etc.) which trip the check.
While the target printer is actually printing and the VP has no upload
handshake of its own in flight, the live-progress fields are mirrored
through instead of zeroed, under a forced gcode_state=FINISH — see
``_mirroring_live_progress`` for why that specific state (#1887).
"""
try:
self._sequence_id += 1
@@ -913,14 +945,23 @@ class SimpleMQTTServer:
print_block["sequence_id"] = str(self._sequence_id)
print_block["command"] = "push_status"
print_block["msg"] = 0
print_block["gcode_state"] = self._gcode_state
print_block["gcode_file"] = self._current_file
print_block["gcode_file_prepare_percent"] = self._prepare_percent
if self._current_file:
print_block["subtask_name"] = self._current_file.replace(".3mf", "")
else:
# Don't override real subtask_name with empty if no upload pending.
mirroring = self._mirroring_live_progress(cached)
if mirroring:
# gcode_file / subtask_name / the progress fields stay as the
# printer reported them — the slicer renders what is really
# on the bed. FINISH keeps the Send button enabled.
print_block["gcode_state"] = "FINISH"
print_block["gcode_file_prepare_percent"] = "100"
print_block.setdefault("subtask_name", "")
else:
print_block["gcode_state"] = self._gcode_state
print_block["gcode_file"] = self._current_file
print_block["gcode_file_prepare_percent"] = self._prepare_percent
if self._current_file:
print_block["subtask_name"] = self._current_file.replace(".3mf", "")
else:
# Don't override real subtask_name with empty if no upload pending.
print_block.setdefault("subtask_name", "")
# Storage-availability indicators the slicer's "Send" pre-flight reads
# (#1228). P1S/A1-class firmware doesn't always include these in
# push_status (no SD card inserted, older field shapes), and BambuStudio
@@ -936,21 +977,25 @@ class SimpleMQTTServer:
print_block["sdcard"] = True
print_block.setdefault("storage", {"free": 1_000_000_000, "total": 32_000_000_000})
# Live-progress fields the slicer's Send pre-flight reads
# (#1558). When the real target printer is mid-print, the
# cached push_status carries the real values for these
# fields and the slicer reads the VP as "busy" — refusing
# Send — even though gcode_state above is forced to IDLE.
# For VP usage the VP isn't actually running the print
# the printer is, so these need to mirror the synthetic
# stub's idle values. Same shape as #1228 (storage) — the
# cached-branch override set just needed extending.
print_block["mc_print_stage"] = ""
print_block["mc_percent"] = 0
print_block["mc_remaining_time"] = 0
print_block["stg"] = []
print_block["stg_cur"] = 0
print_block["layer_num"] = 0
print_block["total_layer_num"] = 0
# (#1558). When the VP reports itself idle, these have to read
# idle too: the cached push_status carries the printer's real
# values, and a report that says gcode_state=IDLE while
# mc_percent>0 / stg_cur>0 is internally contradictory — the
# slicer takes it as busy and blocks Send. Same shape as #1228
# (storage). When the mirror is on, gcode_state=FINISH agrees
# with a non-zero progress set, so they pass through instead.
if not mirroring:
print_block["mc_print_stage"] = ""
print_block["mc_percent"] = 0
print_block["mc_remaining_time"] = 0
print_block["stg"] = []
print_block["stg_cur"] = 0
print_block["layer_num"] = 0
print_block["total_layer_num"] = 0
# print_error is never mirrored: StatusPanel raises a modal error
# dialog for a non-zero code, and the VP is not the machine that
# threw it — the user's own printer card in Bambuddy reports the
# fault. Zero it in both branches.
print_block["print_error"] = 0
status = {"print": print_block}
dump_wire(self.vp_name, "out", status)
@@ -1126,6 +1171,36 @@ class SimpleMQTTServer:
self._gcode_state = state
self._current_file = filename
self._prepare_percent = prepare_percent
self._state_changed_at = time.monotonic()
def _mirroring_live_progress(self, cached: dict) -> bool:
"""True when the report should carry the target printer's live progress.
The slicers gate the Device-tab progress panel and the Send button on
the same predicate (``MachineObject::is_in_printing()``), so the VP
cannot report the printer's real gcode_state without also telling the
slicer it is too busy to accept a job — which is the whole point of a
non-proxy VP, and was the #1558 regression. Reporting FINISH instead
renders the panel (StatusPanel checks ``is_in_printing() ||
print_status == "FINISH"``) and leaves Send enabled, so the mirror is
FINISH plus the printer's real numbers.
Two things suppress it:
* The VP's own upload state machine owns the report while a job is
being handed over (PREPARE), and for a short settle window after —
the slicer only releases its in-flight-job lock once it sees FINISH
carrying the ``subtask_name`` it just uploaded (#1280 / #1658), and
swapping in the printer's filename mid-handshake wedges the send
modal at "Downloading".
* The printer isn't printing, in which case there is no progress to
show and the VP's own state is the honest thing to report.
"""
if self._gcode_state == "PREPARE":
return False
if time.monotonic() - self._state_changed_at < _UPLOAD_SETTLE_SECONDS:
return False
return str(cached.get("gcode_state") or "").upper() in _MIRRORED_PRINT_STATES
async def _publish_to_report(
self, writer: asyncio.StreamWriter, payload: dict, serial: str = "", log_event: bool = True
@@ -1207,10 +1282,10 @@ class SimpleMQTTServer:
self, writer: asyncio.StreamWriter, sequence_id: str, filename: str, serial: str | None = None
) -> None:
"""Send project_file acknowledgment matching real Bambu printer behavior."""
# Update state so periodic status pushes reflect preparation
self._gcode_state = "PREPARE"
self._current_file = filename
self._prepare_percent = "0"
# Update state so periodic status pushes reflect preparation. Goes
# through set_gcode_state so the live-progress mirror sees the
# transition and holds off until the upload handshake has settled.
self.set_gcode_state("PREPARE", filename=filename, prepare_percent="0")
try:
# Send command acknowledgment — slicer expects to see
+180 -39
View File
@@ -4,6 +4,7 @@ import asyncio
import json
import logging
import socket
import time
from pathlib import Path
from unittest.mock import AsyncMock, MagicMock, patch
@@ -15,7 +16,10 @@ from backend.app.services.virtual_printer.mqtt_bridge import (
_resolve_host_interface_for_target,
_resolve_target_to_ipv4,
)
from backend.app.services.virtual_printer.mqtt_server import SimpleMQTTServer
from backend.app.services.virtual_printer.mqtt_server import (
_UPLOAD_SETTLE_SECONDS,
SimpleMQTTServer,
)
H2D_SERIAL = "0948BB540200427"
VP_SERIAL = "09400A391800003"
@@ -1093,18 +1097,22 @@ class TestForwardToPrinter:
# ---------------------------------------------------------------------------
def _capture_published(server: SimpleMQTTServer) -> list:
"""Wrap _publish_to_report to capture (topic, payload_dict)."""
published: list = []
async def _capture(writer, payload, serial="", log_event=True):
published.append((serial or server.serial, payload))
server._publish_to_report = _capture # type: ignore[assignment]
return published
class TestStatusReportCachedAsBase:
"""`_send_status_report` sends near-byte-identical real data when bridge cache exists."""
def _capture_published(self, server: SimpleMQTTServer):
"""Wrap _publish_to_report to capture (topic, payload_dict)."""
published: list = []
async def _capture(writer, payload, serial="", log_event=True):
published.append((serial or server.serial, payload))
server._publish_to_report = _capture # type: ignore[assignment]
return published
return _capture_published(server)
@pytest.mark.asyncio
async def test_uses_real_cache_when_bridge_active(self):
@@ -1227,47 +1235,180 @@ class TestStatusReportCachedAsBase:
assert payload["print"]["gcode_state"] == "PREPARE"
assert payload["print"]["gcode_file"] == "foo.3mf"
# ---------------------------------------------------------------------------
# Live print progress (#1887 / #1558)
# ---------------------------------------------------------------------------
def _printing_cache(**overrides) -> dict:
"""Bridge cache for a target printer that is mid-print."""
cache = {
"command": "push_status",
"msg": 0,
"gcode_state": "RUNNING",
"gcode_file": "Metadata/plate_1.gcode",
"subtask_name": "benchy",
"mc_print_stage": "2",
"mc_percent": 47,
"mc_remaining_time": 3600,
"stg": [1, 2, 3],
"stg_cur": 14,
"layer_num": 120,
"total_layer_num": 250,
"print_error": 0,
}
cache.update(overrides)
return cache
class TestLiveProgressMirror:
"""The VP mirrors the target printer's progress without ever looking busy.
Both slicers gate the Device-tab progress panel and the Send button on the
same predicate — `MachineObject::is_in_printing()`, i.e. gcode_state in
{RUNNING, PAUSE, SLICING, PREPARE}. Reporting the printer's real state
shows progress but blocks Send for as long as it prints (#1558); zeroing
everything keeps Send alive but shows nothing (#1887). FINISH is the one
state that does both: StatusPanel renders on `is_in_printing() ||
print_status == "FINISH"`, while SelectMachineDialog only blocks on
`is_in_printing()`.
"""
@pytest.mark.asyncio
async def test_live_progress_fields_zeroed_in_cached_branch(self):
"""#1558: when the real target printer is mid-print, the cached
push_status carries live values for mc_percent / stg_cur / layer_num /
etc. BambuStudio's Send pre-flight reads any of these as "VP busy"
even when gcode_state above is forced to IDLE — blocking Send while
the target prints. The cached branch must override these to the same
idle values the synthetic stub uses.
"""
async def test_progress_mirrored_while_target_prints(self):
"""#1887: the numbers the slicer needs come straight from the cache."""
server = _make_server()
bridge = MagicMock()
# Real printer mid-print state: gcode_state may be RUNNING upstream,
# but the VP's own _gcode_state is IDLE (Send is requesting a
# new upload, the VP isn't running anything).
bridge.get_latest_print_state.return_value = {
"command": "push_status",
"msg": 0,
"gcode_state": "RUNNING",
"mc_print_stage": "2",
"mc_percent": 47,
"mc_remaining_time": 3600,
"stg": [1, 2, 3],
"stg_cur": 14,
"layer_num": 120,
"total_layer_num": 250,
"print_error": 0,
}
bridge.get_latest_print_state.return_value = _printing_cache()
server.set_bridge(bridge)
published = self._capture_published(server)
published = _capture_published(server)
await server._send_status_report(MagicMock())
_serial, payload = published[0]
# Every live-progress field must reflect "idle / VP isn't busy".
assert payload["print"]["mc_print_stage"] == "2"
assert payload["print"]["mc_percent"] == 47
assert payload["print"]["mc_remaining_time"] == 3600
assert payload["print"]["stg"] == [1, 2, 3]
assert payload["print"]["stg_cur"] == 14
assert payload["print"]["layer_num"] == 120
assert payload["print"]["total_layer_num"] == 250
# The job the printer is really running, not the VP's last upload.
assert payload["print"]["subtask_name"] == "benchy"
@pytest.mark.asyncio
@pytest.mark.parametrize("target_state", ["RUNNING", "PAUSE"])
async def test_mirror_never_reports_a_printing_gcode_state(self, target_state):
"""#1558 guard: any state in `is_in_printing()` disables the Send button.
This is the assertion that keeps the mirror honest — it may show the
printer's numbers, but it must never claim the VP itself is printing.
"""
server = _make_server()
bridge = MagicMock()
bridge.get_latest_print_state.return_value = _printing_cache(gcode_state=target_state)
server.set_bridge(bridge)
published = _capture_published(server)
await server._send_status_report(MagicMock())
_serial, payload = published[0]
assert payload["print"]["gcode_state"] == "FINISH"
assert payload["print"]["gcode_state"] not in ("RUNNING", "PAUSE", "SLICING", "PREPARE")
@pytest.mark.asyncio
async def test_progress_zeroed_while_target_idle(self):
"""Nothing to mirror — the VP's own upload state owns the report."""
server = _make_server()
server.set_gcode_state("FINISH", filename="foo.3mf", prepare_percent="100")
server._state_changed_at = time.monotonic() - 60 # settled long ago
bridge = MagicMock()
bridge.get_latest_print_state.return_value = _printing_cache(gcode_state="IDLE", mc_percent=0, layer_num=0)
server.set_bridge(bridge)
published = _capture_published(server)
await server._send_status_report(MagicMock())
_serial, payload = published[0]
assert payload["print"]["gcode_state"] == "FINISH" # the VP's own, not mirrored
assert payload["print"]["subtask_name"] == "foo"
assert payload["print"]["mc_print_stage"] == ""
assert payload["print"]["mc_percent"] == 0
assert payload["print"]["mc_remaining_time"] == 0
assert payload["print"]["stg"] == []
assert payload["print"]["stg_cur"] == 0
assert payload["print"]["layer_num"] == 0
assert payload["print"]["total_layer_num"] == 0
@pytest.mark.asyncio
async def test_progress_zeroed_while_upload_in_flight(self):
"""A job being handed over outranks the mirror.
The slicer is watching its own PREPARE → FINISH cycle here; feeding it
the printer's progress mid-handshake would contradict the PREPARE it is
waiting on.
"""
server = _make_server()
server.set_gcode_state("PREPARE", filename="bar.3mf", prepare_percent="0")
bridge = MagicMock()
bridge.get_latest_print_state.return_value = _printing_cache()
server.set_bridge(bridge)
published = _capture_published(server)
await server._send_status_report(MagicMock())
_serial, payload = published[0]
assert payload["print"]["gcode_state"] == "PREPARE"
assert payload["print"]["gcode_file"] == "bar.3mf"
assert payload["print"]["subtask_name"] == "bar"
assert payload["print"]["mc_percent"] == 0
assert payload["print"]["layer_num"] == 0
@pytest.mark.asyncio
async def test_upload_settle_window_keeps_the_slicers_own_filename(self):
"""#1658: the send modal releases on FINISH carrying the name it uploaded.
Swapping in the printer's filename while that handshake is still in
flight wedges the slicer at "Downloading", so the mirror waits.
"""
server = _make_server()
bridge = MagicMock()
bridge.get_latest_print_state.return_value = _printing_cache()
server.set_bridge(bridge)
published = _capture_published(server)
server.set_gcode_state("FINISH", filename="bar.3mf", prepare_percent="100")
await server._send_status_report(MagicMock())
_serial, payload = published[0]
assert payload["print"]["subtask_name"] == "bar"
assert payload["print"]["mc_percent"] == 0
@pytest.mark.asyncio
async def test_mirror_resumes_once_the_upload_has_settled(self):
"""Same VP as above, once the slicer has had its FINISH."""
server = _make_server()
bridge = MagicMock()
bridge.get_latest_print_state.return_value = _printing_cache()
server.set_bridge(bridge)
published = _capture_published(server)
server.set_gcode_state("FINISH", filename="bar.3mf", prepare_percent="100")
server._state_changed_at = time.monotonic() - _UPLOAD_SETTLE_SECONDS - 1
await server._send_status_report(MagicMock())
_serial, payload = published[0]
assert payload["print"]["subtask_name"] == "benchy"
assert payload["print"]["mc_percent"] == 47
@pytest.mark.asyncio
async def test_print_error_never_mirrored(self):
"""A fault on the printer must not raise a modal error dialog in the slicer.
The VP is not the machine that threw it — Bambuddy's own printer card
reports the fault.
"""
server = _make_server()
bridge = MagicMock()
bridge.get_latest_print_state.return_value = _printing_cache(print_error=515)
server.set_bridge(bridge)
published = _capture_published(server)
await server._send_status_report(MagicMock())
_serial, payload = published[0]
assert payload["print"]["print_error"] == 0
assert payload["print"]["mc_percent"] == 47 # the rest still mirrors
# ---------------------------------------------------------------------------