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