Kaynağa Gözat

feat(vp): surface why MQTT bridge IP encoding didn't arm (#1429 defensive)

  _refresh_ip_encoding had 4 silent early-returns. When the rewrite
  silently no-op'd on a user's setup, the only signal was the absence of
  the "armed" INFO line, and diagnosing which path was firing meant
  grepping the source.

  Each path now emits one INFO line naming the specific reason. A
  _not_armed_reason dedup field throttles to one line per state change,
  so an idle unarmed bridge doesn't spam every 30s refresh tick. Cleared
  on successful arm so regressions re-emit.

  Not a fix for #1429 itself — the bridge logic is unchanged; this just
  turns the silent failure into visible signal so the next "fix didn't
  work for me" report can be triaged in one round-trip.
maziggy 3 ay önce
ebeveyn
işleme
db1c664fce

+ 3 - 0
CHANGELOG.md

@@ -4,6 +4,9 @@ All notable changes to Bambuddy will be documented in this file.
 
 ## [0.2.5b1] - Unreleased
 
+### Added
+- **VP MQTT bridge surfaces why `net.info[].ip` rewrite didn't arm (#1429 defensive)** — `MQTTBridge._refresh_ip_encoding` had 4 silent early-return paths (`target_client is None`, `printer client has no ip_address yet`, `no host interface shares a subnet with printer IP X and bind_address is 0.0.0.0/empty`, `invalid IPv4 …`). When the rewrite silently no-op'd on a user's setup, the only signal was the absence of the `MQTT bridge IP encoding armed` INFO line — diagnosing which path was firing meant grepping the source. Each path now emits one `MQTT bridge IP encoding NOT armed: <specific reason>` INFO line; the message names the actual failure (target IP, the missing-interface case, etc.). Throttled via a `_not_armed_reason` dedup field so an idle unarmed bridge doesn't spam one line per 30s refresh tick — only state changes log. Cleared on successful arm so a regression (e.g. printer client unbinds) re-emits the diagnostic. 5 new tests in `TestNotArmedDiagnosticLogging` pin each path's specific reason text, the once-per-state-change throttle, and the arm-clears-dedup behaviour. **Not a fix for #1429 itself** — the bridge logic is unchanged; this just turns the silent failure into visible signal so the next "fix didn't work for me" report can be triaged in one round-trip instead of multiple.
+
 ### Fixed
 - **Label printing produced two identical PDFs per click (#1628)** — `LabelTemplatePickerModal.tsx::openBlobInNewTab` called `window.open(url, '_blank', 'noopener,noreferrer')` and treated a `null` return as "popup blocked → fall back to `<a download>` click." Per the WindowFeatures spec, `noopener` deliberately forces `window.open` to return `null` even on success, so the `if (!win)` fallback fired on EVERY click. Path 1 (window.open) opened the blob tab — on Linux Chromium without an inline PDF viewer the OS saved a random-named copy (the `zo70GhSL.pdf` / `f7w0OcDi.pdf` files in the reporter's screenshot). Path 2 (fallback) downloaded a second copy named `bambuddy-labels.pdf`. Two identical PDFs per click. Fix: drop `noopener,noreferrer`. The blob is same-origin (created via `URL.createObjectURL` from our own fetch response), the destination is a passive PDF preview tab with no script context to abuse `window.opener`, and `noreferrer` is a no-op for blob URLs. After removal, `window.open` returns a real window reference on success → `if (!win)` only fires on genuine popup-block, single PDF per click. Existing 17 vitest cases in `LabelTemplatePickerModal.test.tsx` still pass; the change is comment + one parameter.
 

+ 27 - 1
backend/app/services/virtual_printer/mqtt_bridge.py

@@ -244,6 +244,14 @@ class MQTTBridge:
         self._target_serial: str | None = None
         self._target_ip_uint32_le: int | None = None
         self._vp_ip_uint32_le: int | None = None
+        # Last reason `_refresh_ip_encoding` early-returned without arming.
+        # Used to throttle the "NOT armed" diagnostic log to one line per
+        # state change — refresh runs every 30s, so without throttling an
+        # idle-but-unarmed bridge would emit one line per tick forever. Set
+        # to None once arming succeeds so the next failure re-logs. #1429
+        # follow-up: makes silent early-returns visible without grepping the
+        # source.
+        self._not_armed_reason: str | None = None
         self._loop: asyncio.AbstractEventLoop | None = None
         self._refresh_task: asyncio.Task | None = None
         self._stopping = False
@@ -389,12 +397,23 @@ class MQTTBridge:
         arms on a default-config flat-LAN install and `net.info[].ip` leaks
         the real printer IP — slicer follows it on Send (#1429 residual).
         """
+
+        def _log_not_armed(reason: str) -> None:
+            # Throttle: only log when the reason changes, otherwise an idle
+            # unarmed bridge would emit one INFO line every refresh tick
+            # (~30s) forever. Cleared on arm so a regression re-logs.
+            if reason != self._not_armed_reason:
+                logger.info("[%s] MQTT bridge IP encoding NOT armed: %s", self.vp_name, reason)
+                self._not_armed_reason = reason
+
         client = self._target_client
         if client is None:
+            _log_not_armed("target_client is None (bridge not bound to a printer)")
             return
 
         target_ip = getattr(client, "ip_address", None)
         if not target_ip:
+            _log_not_armed("printer client has no ip_address yet")
             return
 
         vp_ip = getattr(self._mqtt_server, "bind_address", None)
@@ -402,6 +421,10 @@ class MQTTBridge:
         if not vp_ip or vp_ip in ("0.0.0.0", ""):  # nosec B104
             resolved = _resolve_host_interface_for_target(target_ip)
             if not resolved:
+                _log_not_armed(
+                    f"no host interface shares a subnet with printer IP {target_ip} "
+                    "(and VP bind_address is 0.0.0.0/empty)"
+                )
                 return
             vp_ip = resolved
             vp_ip_source = "auto-resolved"
@@ -409,7 +432,8 @@ class MQTTBridge:
         try:
             new_target_le = _ip_to_uint32_le(target_ip)
             new_vp_le = _ip_to_uint32_le(vp_ip)
-        except ValueError:
+        except ValueError as e:
+            _log_not_armed(f"invalid IPv4 (target={target_ip!r}, vp={vp_ip!r}): {e}")
             return
 
         if new_target_le == self._target_ip_uint32_le and new_vp_le == self._vp_ip_uint32_le:
@@ -420,6 +444,8 @@ class MQTTBridge:
         was_armed = self._target_ip_uint32_le is not None and self._vp_ip_uint32_le is not None
         self._target_ip_uint32_le = new_target_le
         self._vp_ip_uint32_le = new_vp_le
+        # Clear the dedup so a future failure re-emits the diagnostic line.
+        self._not_armed_reason = None
         logger.info(
             "[%s] MQTT bridge IP encoding %s: target=%s vp=%s (%s)",
             self.vp_name,

+ 81 - 0
backend/tests/unit/test_vp_mqtt_bridge.py

@@ -2,6 +2,7 @@
 
 import asyncio
 import json
+import logging
 from pathlib import Path
 from unittest.mock import AsyncMock, MagicMock, patch
 
@@ -1184,3 +1185,83 @@ class TestBindAddressAutoResolve:
             return_value=None,
         ):
             assert _resolve_host_interface_for_target("203.0.113.1") is None
+
+
+class TestNotArmedDiagnosticLogging:
+    """#1429 follow-up: every silent early-return in `_refresh_ip_encoding`
+    now emits one INFO line explaining WHY the rewrite couldn't arm. Throttled
+    to one line per state change so an idle unarmed bridge doesn't spam the
+    log every 30s tick. Cleared on arm so a future failure re-emits.
+    """
+
+    def test_no_client_logs_once(self, caplog):
+        bridge = _make_bridge(_make_server())
+        # Force the "no client" path: bridge starts with _target_client=None.
+        assert bridge._target_client is None
+        with caplog.at_level(logging.INFO, logger="backend.app.services.virtual_printer.mqtt_bridge"):
+            bridge._refresh_ip_encoding()
+            bridge._refresh_ip_encoding()  # 2nd tick — same reason, must NOT re-log.
+            bridge._refresh_ip_encoding()
+        not_armed = [r for r in caplog.records if "NOT armed" in r.getMessage()]
+        assert len(not_armed) == 1
+        assert "target_client is None" in not_armed[0].getMessage()
+
+    def test_missing_target_ip_logs_specific_reason(self, caplog):
+        bridge = _make_bridge(_make_server())
+        # Manually attach a client with no ip_address (simulates pre-DHCP).
+        client = _make_paho_client()
+        client.ip_address = ""
+        bridge._target_client = client
+        with caplog.at_level(logging.INFO, logger="backend.app.services.virtual_printer.mqtt_bridge"):
+            bridge._refresh_ip_encoding()
+        not_armed = [r for r in caplog.records if "NOT armed" in r.getMessage()]
+        assert len(not_armed) == 1
+        assert "no ip_address" in not_armed[0].getMessage()
+
+    def test_no_matching_host_interface_logs_specific_reason(self, caplog):
+        server = _make_server(bind_address="0.0.0.0")
+        bridge = _make_bridge(server)
+        with (
+            patch(
+                "backend.app.services.virtual_printer.mqtt_bridge._resolve_host_interface_for_target",
+                return_value=None,
+            ),
+            caplog.at_level(logging.INFO, logger="backend.app.services.virtual_printer.mqtt_bridge"),
+        ):
+            bridge._target_client = _make_paho_client()
+            bridge._refresh_ip_encoding()
+        not_armed = [r for r in caplog.records if "NOT armed" in r.getMessage()]
+        assert len(not_armed) == 1
+        msg = not_armed[0].getMessage()
+        assert H2D_IP in msg
+        assert "no host interface" in msg
+
+    def test_invalid_ipv4_logs_value_error(self, caplog):
+        server = _make_server(bind_address=VP_IP)
+        bridge = _make_bridge(server)
+        client = _make_paho_client()
+        client.ip_address = "not.an.ip"
+        bridge._target_client = client
+        with caplog.at_level(logging.INFO, logger="backend.app.services.virtual_printer.mqtt_bridge"):
+            bridge._refresh_ip_encoding()
+        not_armed = [r for r in caplog.records if "NOT armed" in r.getMessage()]
+        assert len(not_armed) == 1
+        assert "invalid IPv4" in not_armed[0].getMessage()
+
+    def test_successful_arm_clears_dedup_so_future_failure_relogs(self, caplog):
+        """After a successful arm, the dedup must reset so a subsequent
+        regression (e.g. printer client unbinds) re-emits the diagnostic
+        line instead of being silenced by the previous failure reason."""
+        bridge = _make_bridge(_make_server(bind_address=VP_IP))
+        bridge._target_client = _make_paho_client()
+        with caplog.at_level(logging.INFO, logger="backend.app.services.virtual_printer.mqtt_bridge"):
+            bridge._refresh_ip_encoding()  # arms
+            assert bridge._not_armed_reason is None
+            # Simulate a regression — target_client drops away.
+            bridge._target_client = None
+            bridge._refresh_ip_encoding()
+            bridge._refresh_ip_encoding()  # 2nd same-reason tick must not re-log
+        not_armed = [r for r in caplog.records if "NOT armed" in r.getMessage()]
+        assert len(not_armed) == 1  # the post-arm failure
+        armed = [r for r in caplog.records if "MQTT bridge IP encoding armed" in r.getMessage()]
+        assert len(armed) == 1