Просмотр исходного кода

debug(vp): env-flagged wire-payload dump for slicer-mirror triage (#1622)

  Add a BAMBUDDY_VP_DUMP_WIRE=1 escape hatch that writes the bridge's
  cached push_status (in) and the 1Hz slicer-facing copy (out) to
  <log_dir>/vp_wire/<vp_name>_<direction>.json, overwritten each tick.

  #1622's symptom — empty filament dropdown in slicer's AMS slot details
  for P1S/A1 but not H2D in non-proxy VP modes — needs visibility into
  the actual wire bytes flowing through the bridge to bisect between
  "cache is missing fields" and "_send_status_report strips them on copy."
  The existing logs prove the bridge is bound and pushing at 1Hz, but
  not what's in the payload.

  Off by default, single env flag, single file per VP per direction
  (bounded disk footprint), failures swallowed at debug so a broken
  dump can never break the 1Hz loop. 21 tests pin the helper contract:
  disabled-by-default, atomic writes, sanitized vp_name (no path
  escape), per-call env check so toggling without restart works.
maziggy 2 месяцев назад
Родитель
Сommit
4ab7339fe4

Разница между файлами не показана из-за своего большого размера
+ 0 - 0
CHANGELOG.md


+ 66 - 0
backend/app/services/virtual_printer/_debug.py

@@ -0,0 +1,66 @@
+"""Env-flagged wire-payload dump for VP MQTT debug (gated; off by default).
+
+Set ``BAMBUDDY_VP_DUMP_WIRE=1`` to write the most recent inbound (bridge
+cache input) and outbound (slicer-facing 1Hz push) MQTT payloads to disk,
+one file per VP per direction, overwritten each tick.
+
+Used to triage shape-of-payload bugs (e.g. #1622) where the question is
+"is the bridge missing fields in the cache, or is something else stripping
+them on the way out to the slicer?" Compare ``*_in.json`` and ``*_out.json``
+for the failing VP against a known-good VP (e.g. H2D vs P1S).
+
+Layout: ``<log_dir>/vp_wire/<sanitized_vp_name>_<direction>.json``
+
+Failure modes are swallowed at debug level — debug instrumentation must
+never break the bridge or slicer-facing 1Hz loop. Disable by unsetting the
+env var; the in-progress files stay on disk and can be deleted manually.
+"""
+
+from __future__ import annotations
+
+import json
+import logging
+import os
+import re
+
+from backend.app.core.config import settings as app_settings
+
+logger = logging.getLogger(__name__)
+
+_ENV_FLAG = "BAMBUDDY_VP_DUMP_WIRE"
+_NAME_SAFE = re.compile(r"[^A-Za-z0-9._-]+")
+
+
+def _enabled() -> bool:
+    return os.environ.get(_ENV_FLAG, "").strip().lower() in ("1", "true", "yes", "on")
+
+
+def _sanitize(name: str) -> str:
+    safe = _NAME_SAFE.sub("_", name or "vp").strip("_")
+    return safe or "vp"
+
+
+def dump_wire(vp_name: str, direction: str, payload: dict | bytes | str) -> None:
+    """Write ``payload`` to ``<log_dir>/vp_wire/<vp_name>_<direction>.json``.
+
+    No-op when the env flag is unset. Accepts dict (json-encoded with
+    ``indent=2``), bytes (decoded as utf-8 with errors='replace'), or
+    str (written verbatim).
+    """
+    if not _enabled():
+        return
+    try:
+        target_dir = app_settings.log_dir / "vp_wire"
+        target_dir.mkdir(parents=True, exist_ok=True)
+        path = target_dir / f"{_sanitize(vp_name)}_{_sanitize(direction)}.json"
+        if isinstance(payload, dict):
+            text = json.dumps(payload, indent=2, default=str)
+        elif isinstance(payload, bytes):
+            text = payload.decode("utf-8", errors="replace")
+        else:
+            text = str(payload)
+        tmp = path.with_suffix(path.suffix + ".tmp")
+        tmp.write_text(text, encoding="utf-8")
+        tmp.replace(path)
+    except OSError as e:
+        logger.debug("[%s] vp_wire dump (%s) failed: %s", vp_name, direction, e)

+ 3 - 0
backend/app/services/virtual_printer/mqtt_bridge.py

@@ -41,6 +41,8 @@ import logging
 import socket
 from typing import TYPE_CHECKING
 
+from backend.app.services.virtual_printer._debug import dump_wire
+
 if TYPE_CHECKING:
     from backend.app.services.bambu_mqtt import BambuMQTTClient
     from backend.app.services.printer_manager import PrinterManager
@@ -634,6 +636,7 @@ class MQTTBridge:
                     ):
                         new_state["ams"] = _merge_ams_dict(prev["ams"], new_state["ams"])
             self._latest_print_state = new_state
+            dump_wire(self.vp_name, "in", new_state)
             return
 
         # info.get_version responses → cache the module list so the synthetic

+ 3 - 0
backend/app/services/virtual_printer/mqtt_server.py

@@ -15,6 +15,8 @@ from collections.abc import Callable
 from pathlib import Path
 from typing import TYPE_CHECKING
 
+from backend.app.services.virtual_printer._debug import dump_wire
+
 if TYPE_CHECKING:
     from backend.app.services.virtual_printer.mqtt_bridge import MQTTBridge
 
@@ -912,6 +914,7 @@ class SimpleMQTTServer:
                 print_block["total_layer_num"] = 0
                 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)
                 return
 

+ 123 - 0
backend/tests/unit/test_vp_wire_dump.py

@@ -0,0 +1,123 @@
+"""Tests for the env-flagged VP wire-payload dump helper used to triage
+shape-of-payload bugs like #1622."""
+
+import json
+import os
+from unittest.mock import patch
+
+import pytest
+
+from backend.app.core.config import settings as app_settings
+from backend.app.services.virtual_printer import _debug
+
+
+@pytest.fixture
+def _isolated_log_dir(tmp_path, monkeypatch):
+    with patch.object(app_settings, "log_dir", tmp_path):
+        yield tmp_path
+
+
+def test_disabled_by_default_writes_nothing(_isolated_log_dir, monkeypatch):
+    monkeypatch.delenv("BAMBUDDY_VP_DUMP_WIRE", raising=False)
+    _debug.dump_wire("VP1", "out", {"hello": "world"})
+    assert not (_isolated_log_dir / "vp_wire").exists()
+
+
+def test_enabled_writes_dict_as_pretty_json(_isolated_log_dir, monkeypatch):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    payload = {"print": {"ams": {"ams": [{"id": 0, "tray": [{"id": 0, "tray_type": "PLA"}]}]}}}
+    _debug.dump_wire("Bambuddy P1S", "out", payload)
+    out = _isolated_log_dir / "vp_wire" / "Bambuddy_P1S_out.json"
+    assert out.is_file()
+    assert json.loads(out.read_text()) == payload
+
+
+def test_overwrites_on_repeat_call(_isolated_log_dir, monkeypatch):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    _debug.dump_wire("VP1", "out", {"v": 1})
+    _debug.dump_wire("VP1", "out", {"v": 2})
+    out = _isolated_log_dir / "vp_wire" / "VP1_out.json"
+    assert json.loads(out.read_text()) == {"v": 2}
+
+
+def test_separate_files_per_direction(_isolated_log_dir, monkeypatch):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    _debug.dump_wire("VP1", "in", {"src": "printer"})
+    _debug.dump_wire("VP1", "out", {"src": "slicer"})
+    assert (_isolated_log_dir / "vp_wire" / "VP1_in.json").is_file()
+    assert (_isolated_log_dir / "vp_wire" / "VP1_out.json").is_file()
+
+
+def test_sanitizes_path_traversal_in_vp_name(_isolated_log_dir, monkeypatch):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    _debug.dump_wire("../../etc/passwd", "out", {"x": 1})
+    vp_wire = _isolated_log_dir / "vp_wire"
+    files = list(vp_wire.glob("*"))
+    assert len(files) == 1
+    # The actual safety property: the written file is inside vp_wire/.
+    # `..` as a substring of a single filename component is harmless because
+    # the path separator (/) is collapsed to _ before construction.
+    assert files[0].resolve().parent == vp_wire.resolve()
+    assert "/" not in files[0].name
+
+
+def test_empty_vp_name_falls_back_to_default(_isolated_log_dir, monkeypatch):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    _debug.dump_wire("", "out", {"x": 1})
+    assert (_isolated_log_dir / "vp_wire" / "vp_out.json").is_file()
+
+
+def test_bytes_payload_decoded(_isolated_log_dir, monkeypatch):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    _debug.dump_wire("VP1", "in", b'{"raw": true}')
+    out = _isolated_log_dir / "vp_wire" / "VP1_in.json"
+    assert out.read_text() == '{"raw": true}'
+
+
+def test_unwritable_dir_is_swallowed(_isolated_log_dir, monkeypatch):
+    """A debug-instrumentation failure must not crash the bridge or 1Hz loop."""
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    # Point log_dir at a location that mkdir refuses (a regular file occupying
+    # the path). Failure must be swallowed.
+    blocker = _isolated_log_dir / "blocker"
+    blocker.write_text("not a dir")
+    with patch.object(app_settings, "log_dir", blocker):
+        _debug.dump_wire("VP1", "out", {"x": 1})  # must not raise
+
+
+@pytest.mark.parametrize("flag_value", ["0", "false", "off", "", "no"])
+def test_falsy_flag_values_disable(_isolated_log_dir, monkeypatch, flag_value):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", flag_value)
+    _debug.dump_wire("VP1", "out", {"x": 1})
+    assert not (_isolated_log_dir / "vp_wire").exists()
+
+
+@pytest.mark.parametrize("flag_value", ["1", "true", "TRUE", "yes", "on", "On"])
+def test_truthy_flag_values_enable(_isolated_log_dir, monkeypatch, flag_value):
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", flag_value)
+    _debug.dump_wire("VP1", "out", {"x": 1})
+    assert (_isolated_log_dir / "vp_wire" / "VP1_out.json").is_file()
+
+
+def test_idempotent_atomic_no_partial_file_visible(_isolated_log_dir, monkeypatch):
+    """tmp+rename pattern means a reader never sees a half-written .json file."""
+    monkeypatch.setenv("BAMBUDDY_VP_DUMP_WIRE", "1")
+    _debug.dump_wire("VP1", "out", {"x": 1})
+    files = sorted(p.name for p in (_isolated_log_dir / "vp_wire").iterdir())
+    # No leftover .tmp file after a successful write.
+    assert files == ["VP1_out.json"]
+
+
+def test_env_check_is_per_call_not_module_load(_isolated_log_dir, monkeypatch):
+    """Flag toggle must take effect on the next call without restarting; we
+    re-read the env var inside ``dump_wire`` rather than caching at import."""
+    monkeypatch.delenv("BAMBUDDY_VP_DUMP_WIRE", raising=False)
+    _debug.dump_wire("VP1", "out", {"v": 1})
+    assert not (_isolated_log_dir / "vp_wire").exists()
+
+    os.environ["BAMBUDDY_VP_DUMP_WIRE"] = "1"
+    try:
+        _debug.dump_wire("VP1", "out", {"v": 2})
+        assert (_isolated_log_dir / "vp_wire" / "VP1_out.json").is_file()
+    finally:
+        os.environ.pop("BAMBUDDY_VP_DUMP_WIRE", None)

Некоторые файлы не были показаны из-за большого количества измененных файлов