debug(vp): env-flagged bridge-synthesised reply trace for slicer↔printer #1622 round-3 triage

  Round-2 cmd.jsonl from shaddowlink proves the bridge forwards both commands and
  responses correctly: ams_filament_setting round-trips with result=success on P1S,
  the cached push_status carries tray_info_idx=GFA11/tray_type=PLA-AERO/K-n/cali_idx
  intact, and the visible "unload" symptom comes from the slicer's choice of
  extrusion_cali_set (push K direct, P1S firmware rejects) vs extrusion_cali_sel
  (select by id, both H2D and P1S accept). The open question is what makes the
  slicer pick _set vs _sel — likely the info.get_version response Bambuddy
  synthesises or the first cached pushall reply the slicer reads at connect.
  Round 2 captured neither; the JSONL had slicer_to_bridge and printer_to_slicer
  but no direction for the bridge's own synthesised replies.

  Same BAMBUDDY_VP_DUMP_WIRE=1 flag now also appends a bridge_to_slicer line for
  every bridge-synthesised reply (info.get_version answer, project_file ack,
  on-demand pushall response). Capture is in _publish_to_report — the single
  chokepoint — gated on a new log_event param; the 1Hz periodic push threads
  log_event=False so the JSONL isn't flooded (~60 lines/min/VP) because
  dump_wire already covers cache shape per tick.

  Diagnostic-only, no data-path change. Default param preserves every existing
  call site's behaviour.

backend/app/services/virtual_printer/_debug.py

@@ -10,12 +10,15 @@ Set ``BAMBUDDY_VP_DUMP_WIRE=1`` to enable two complementary capture modes:
    ``*_in.json`` and ``*_out.json`` for the failing VP against a known-good
    one (e.g. H2D vs P1S).
 
-2. ``append_event``: time-ordered JSONL log of every slicer↔printer command
-   payload that flows through the VP (excludes the cached-as-base 1Hz push,
-   which dump_wire already covers). Triages command-flow bugs (e.g. #1622
-   round 2) where the cached state looks right but a slicer-initiated
-   write (ams_filament_setting / extrusion_cali_set / xcam / system) ends
-   up corrupting state. One line per event with wall-clock timestamp.
+2. ``append_event``: time-ordered JSONL log of every slicer↔bridge↔printer
+   command payload that flows through the VP (excludes the cached-as-base
+   1Hz push, which dump_wire already covers). Triages command-flow bugs
+   (e.g. #1622 round 2 / round 3) where the cached state looks right but a
+   slicer-initiated write (ams_filament_setting / extrusion_cali_set /
+   xcam / system) ends up corrupting state, or where the slicer's choice
+   of command flow depends on what the bridge replies to its initial
+   info.get_version / pushall probe. One line per event with wall-clock
+   timestamp.
 
 Layout:
 - snapshot: ``<log_dir>/vp_wire/<sanitized_vp_name>_<direction>.json``
@@ -100,10 +103,14 @@ def append_event(vp_name: str, direction: str, topic: str, payload: dict | bytes
     """Append one event line to ``<log_dir>/vp_wire/<vp_name>_cmd.jsonl``.
 
     No-op when the env flag is unset. ``direction`` should be one of
-    ``"slicer_to_bridge"`` or ``"printer_to_slicer"`` so a diff between
-    a working VP and a broken VP can be read top-to-bottom in causal order.
-    Bytes payloads are utf-8 decoded then json-parsed best-effort; un-parseable
-    payloads are logged as ``{"raw": "<text>"}`` so the line is still valid JSON.
+    ``"slicer_to_bridge"`` (slicer-originated publish reaching the bridge),
+    ``"printer_to_slicer"`` (real-printer response fanned out to the slicer),
+    or ``"bridge_to_slicer"`` (bridge-synthesised reply: info.get_version
+    answer, project_file ack, on-demand pushall response). A diff between
+    a working VP and a broken VP can then be read top-to-bottom in causal
+    order. Bytes payloads are utf-8 decoded then json-parsed best-effort;
+    un-parseable payloads are logged as ``{"raw": "<text>"}`` so the line
+    is still valid JSON.
     """
     if not _enabled():
         return

backend/app/services/virtual_printer/mqtt_server.py

@@ -432,7 +432,11 @@ class SimpleMQTTServer:
                             disconnected.append(client_id)
                             continue
                         serial = self._client_serials.get(client_id, self.serial)
-                        await self._send_status_report(writer, serial=serial)
+                        # log_event=False: the 1Hz cached push is already
+                        # captured by ``dump_wire`` snapshot mode (see
+                        # _debug.py); appending it to the cmd.jsonl would
+                        # flood the file ~60 lines/min per VP.
+                        await self._send_status_report(writer, serial=serial, log_event=False)
                         push_counts[client_id] = push_counts.get(client_id, 0) + 1
                     except OSError as e:
                         logger.debug("Failed to push status to %s: %s", client_id, e)
@@ -846,7 +850,9 @@ class SimpleMQTTServer:
         except (IndexError, ValueError, OSError) as e:
             logger.debug("MQTT SUBSCRIBE error: %s", e)
 
-    async def _send_status_report(self, writer: asyncio.StreamWriter, serial: str | None = None) -> None:
+    async def _send_status_report(
+        self, writer: asyncio.StreamWriter, serial: str | None = None, log_event: bool = True
+    ) -> None:
         """Send a status report to the slicer after connection.
 
         When a bridge is active and has cached the real printer's latest
@@ -915,7 +921,7 @@ class SimpleMQTTServer:
                 print_block["print_error"] = 0
                 status = {"print": print_block}
                 dump_wire(self.vp_name, "out", status)
-                await self._publish_to_report(writer, status, serial or self.serial)
+                await self._publish_to_report(writer, status, serial or self.serial, log_event=log_event)
                 return
 
             # No bridge / no cache yet — fall back to the synthetic stub.
@@ -992,7 +998,7 @@ class SimpleMQTTServer:
                 }
             }
 
-            await self._publish_to_report(writer, status, serial or self.serial)
+            await self._publish_to_report(writer, status, serial or self.serial, log_event=log_event)
 
         except OSError as e:
             logger.error("Failed to send status report: %s", e)
@@ -1088,13 +1094,24 @@ class SimpleMQTTServer:
         self._current_file = filename
         self._prepare_percent = prepare_percent
 
-    async def _publish_to_report(self, writer: asyncio.StreamWriter, payload: dict, serial: str = "") -> None:
+    async def _publish_to_report(
+        self, writer: asyncio.StreamWriter, payload: dict, serial: str = "", log_event: bool = True
+    ) -> None:
         """Publish a message on the device report topic.
 
         Real Bambu printers wire-format push_status JSON with 4-space indentation
         (32254 bytes for an idle H2D push vs 14268 bytes compact). BambuStudio's
         Send pre-flight rejects compact JSON — without matching the on-wire
         format the slicer never proceeds to FTP upload.
+
+        ``log_event=True`` records the publish in ``vp_wire/<vp>_cmd.jsonl``
+        under the ``bridge_to_slicer`` direction so #1622-style triages can
+        diff the bridge's own outbound replies (info.get_version answer,
+        project_file ack, on-demand pushall response) against the real
+        printer's ``printer_to_slicer`` forwards. The 1Hz periodic push
+        sets ``log_event=False`` because dump_wire's overwrite-snapshot
+        already covers cache shape and a per-second JSONL line would dwarf
+        the actual command events.
         """
         topic = f"device/{serial or self.serial}/report"
         message = json.dumps(payload, indent=4)
@@ -1116,6 +1133,16 @@ class SimpleMQTTServer:
         packet += topic_bytes
         packet += message_bytes
 
+        if log_event:
+            # Env-flagged command trace (#1622): captures bridge-synthesised
+            # replies (info.get_version, project_file ack, on-demand pushall
+            # response) AFTER the payload is finalised but before it hits
+            # the wire — so the cmd.jsonl reflects exactly what the slicer
+            # parses. Pair with the slicer_to_bridge events from
+            # _handle_publish and the printer_to_slicer fan-outs from
+            # mqtt_bridge.
+            append_event(self.vp_name, "bridge_to_slicer", topic, payload)
+
         writer.write(packet)
         # Timeout the drain to prevent blocking the event loop if the
         # MQTT client stops reading (e.g. slicer busy with FTP upload).

backend/tests/unit/test_vp_mqtt_bridge.py

@@ -743,7 +743,7 @@ class TestStatusReportCachedAsBase:
         """Wrap _publish_to_report to capture (topic, payload_dict)."""
         published: list = []
 
-        async def _capture(writer, payload, serial=""):
+        async def _capture(writer, payload, serial="", log_event=True):
             published.append((serial or server.serial, payload))
 
         server._publish_to_report = _capture  # type: ignore[assignment]
@@ -939,6 +939,52 @@ class TestWireFormat:
         body = b"".join(captured)
         assert b'\n    "print"' in body, "publish_to_report must use indent=4 JSON"
 
+    @pytest.mark.asyncio
+    async def test_publish_records_bridge_to_slicer_event_by_default(self, monkeypatch):
+        """#1622 round 3: every bridge-synthesised reply (info.get_version answer,
+        project_file ack, on-demand pushall response) must show up in the
+        cmd.jsonl trace under the ``bridge_to_slicer`` direction so a P1S↔H2D
+        diff captures the fingerprint the slicer reads back from us."""
+        server = _make_server()
+        writer = MagicMock()
+        writer.write = lambda data: None
+        writer.drain = AsyncMock()
+
+        recorded: list = []
+        monkeypatch.setattr(
+            "backend.app.services.virtual_printer.mqtt_server.append_event",
+            lambda vp_name, direction, topic, payload: recorded.append((vp_name, direction, topic, payload)),
+        )
+
+        payload = {"info": {"command": "get_version", "sequence_id": "0"}}
+        await server._publish_to_report(writer, payload)
+
+        assert len(recorded) == 1
+        vp_name, direction, topic, recorded_payload = recorded[0]
+        assert direction == "bridge_to_slicer"
+        assert topic.endswith("/report")
+        assert recorded_payload == payload
+
+    @pytest.mark.asyncio
+    async def test_publish_skips_event_when_log_event_false(self, monkeypatch):
+        """The 1Hz periodic-push path passes ``log_event=False`` so dump_wire's
+        snapshot stays the canonical record of cache shape and the cmd.jsonl
+        isn't flooded with ~60 lines/min per VP."""
+        server = _make_server()
+        writer = MagicMock()
+        writer.write = lambda data: None
+        writer.drain = AsyncMock()
+
+        recorded: list = []
+        monkeypatch.setattr(
+            "backend.app.services.virtual_printer.mqtt_server.append_event",
+            lambda *args, **kwargs: recorded.append(args),
+        )
+
+        await server._publish_to_report(writer, {"print": {"command": "push_status"}}, log_event=False)
+
+        assert recorded == []
+
 
 # ---------------------------------------------------------------------------
 # Routing: _handle_publish