From db1c664fcec00b748a9133b6bb0c87e8ecaee267 Mon Sep 17 00:00:00 2001 From: maziggy Date: Thu, 4 Jun 2026 11:24:20 +0200 Subject: [PATCH] feat(vp): surface why MQTT bridge IP encoding didn't arm (#1429 defensive) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit _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. --- CHANGELOG.md | 3 + .../services/virtual_printer/mqtt_bridge.py | 28 ++++++- backend/tests/unit/test_vp_mqtt_bridge.py | 81 +++++++++++++++++++ 3 files changed, 111 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c81bf8154..0b1a37f95 100644 --- a/CHANGELOG.md +++ b/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: ` 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 `` 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. diff --git a/backend/app/services/virtual_printer/mqtt_bridge.py b/backend/app/services/virtual_printer/mqtt_bridge.py index 65bbdff1a..7c81724e0 100644 --- a/backend/app/services/virtual_printer/mqtt_bridge.py +++ b/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, diff --git a/backend/tests/unit/test_vp_mqtt_bridge.py b/backend/tests/unit/test_vp_mqtt_bridge.py index 7515e30ce..5e3045dcf 100644 --- a/backend/tests/unit/test_vp_mqtt_bridge.py +++ b/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