From 0406487eb3ec99e9c719b2ed77c17fcb87f899f0 Mon Sep 17 00:00:00 2001 From: maziggy Date: Wed, 20 May 2026 09:39:10 +0200 Subject: [PATCH] Fix: Add Printer no longer hangs the container on P1S (#1445) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The pre-insert MQTT probe added in 0.2.4.2 (b51598ea) had two bugs that compounded on P1S firmware specifically: 1. Fixed 2-second sleep was too short. P1S broker + TLS handshake routinely needs 3-5s to surface CONNACK on a cold MQTT session (same firmware family with the documented "broker stops publishing but TCP stays alive" quirk at bambu_mqtt.py:3181), so the probe falsely rejected a printer that would have connected fine. H2C's broker is snappier and cleared the 2s window without trouble — which is why the reporter's H2C added without issue and only the P1S misbehaved. 2. client.disconnect() ran synchronously on the asyncio thread. BambuMQTTClient.disconnect() ends in paho's loop_stop() which joins the network thread; if that thread was still mid-TLS-handshake to the slow P1S socket when teardown ran, the join blocked the asyncio thread for as long as the handshake took to complete or fail. POST /printers wedged, every other HTTP request queued behind it, Docker healthcheck timed out — user-visible symptom: "the container hangs." Fix: - Replace the fixed sleep with a polling loop (8s budget, 200ms tick, early-returns the moment state.connected flips True). Slow brokers get the headroom they need; happy-path connects still finish in ~1-2s. Constants exposed as PROBE_TIMEOUT_SECONDS / PROBE_POLL_ INTERVAL_SECONDS class attributes so tests can dial them down. - Move client.disconnect() to await asyncio.to_thread(...) so paho's thread-join can never block the event loop. The empty-card-report-prevention goal of the original probe stays intact: a genuinely wrong access code still results in connected=False after the 8s budget, the 400 with code=printer_connection_failed still fires, the row is still never persisted. --- CHANGELOG.md | 2 + backend/app/services/printer_manager.py | 28 ++++- .../unit/services/test_printer_manager.py | 116 +++++++++++++++++- 3 files changed, 142 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8ce61cd95..fe8c1f71e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,8 @@ All notable changes to Bambuddy will be documented in this file. ## [0.2.5b1] - Unreleased ### Fixed +- **Printers: Add Printer no longer hangs the container on P1S (#1445, reported by @psybernoid and confirmed by @thomassjogren)** — Regression introduced in 0.2.4.2 by the `fix(printers): refuse to add a printer when the MQTT probe fails` change (b51598ea). That commit added a pre-insert MQTT probe to `POST /printers/` via `printer_manager.test_connection()` to catch mistyped access codes before persisting an empty card — but the probe had two compounding bugs that bit P1S specifically. First, a fixed `await asyncio.sleep(2)` checked `state.connected` exactly once at t=2s: P1S firmware's broker / TLS handshake routinely needs 3–5s to surface a CONNACK on a cold MQTT session (same firmware family that already has the documented "broker stops publishing but TCP stays alive" quirk at `bambu_mqtt.py:3181`), so the probe falsely rejected a printer that would have connected fine. Second, the `finally: client.disconnect()` call ran synchronously on the asyncio thread — `BambuMQTTClient.disconnect()` ends in paho's `loop_stop()` which `join()`s the network thread, and if that thread was still mid-TLS-handshake to the slow P1S socket when teardown ran, the `join()` blocked the asyncio thread for as long as the handshake took to either complete or fail. POST `/printers/` therefore wedged, all other HTTP requests queued behind it, and Docker healthcheck timed out → user-visible symptom: "the container hangs." Reporter's workaround (downgrade to 0.2.4.1, add P1S, upgrade back) worked because 0.2.4.1's create-printer route skipped the probe entirely, so the row persisted immediately and the slow handshake happened on a fire-and-forget `connect_printer()` in the background. **Fix** swaps the fixed-sleep + sync-disconnect pair for a polling loop with an 8s budget (`PROBE_TIMEOUT_SECONDS`, configurable as class attributes for tests) that early-returns the moment `state.connected` flips True — so happy-path connects still finish in ~1–2s and slow brokers get the headroom they need — and moves `client.disconnect()` to `await asyncio.to_thread(client.disconnect)` so paho's thread-join can never block the event loop. The new `connect_printer` from-existing-row flow that runs after a successful probe is unchanged (still fire-and-forget). The empty-card-report-prevention goal of the original probe stays intact: a genuinely wrong access code still results in `connected=False` after 8s of polling, the 400 with `code=printer_connection_failed` still fires, the row is still never persisted. **Tests** (2 new in `test_printer_manager.py`): `test_test_connection_polls_and_returns_early_on_connect` simulates the P1S timing — `connected=False` at probe start, flips True ~500ms in — and asserts the probe early-returns in under 1.5s with `success=True` (a regression that reverts to the fixed sleep fails this immediately); `test_test_connection_disconnect_runs_off_loop` mocks a deliberately-slow blocking disconnect (mirrors paho's `loop_stop()` join semantics) and asserts (a) `disconnect` ran on a thread other than the asyncio thread, and (b) a concurrent heartbeat coroutine kept ticking while disconnect was blocking the worker thread, proving the event loop wasn't stalled. The existing `test_test_connection_failure` test was patched to override `PROBE_TIMEOUT_SECONDS` to 0.4s so the negative path still runs fast under CI. 6 printer-create integration tests still green; ruff clean. + - **Stats: Failure Analysis widget no longer shows "Unknown" for archives classified after the fact (#1444, reported and root-caused by @needo37)** — Reporter spotted that the Stats page "Top Failure Reasons" widget grouped failed prints as `Unknown` even after they'd been classified via the Edit Archive modal. He went through the data layer and identified the desync: two `failure_reason` columns exist — `print_archives.failure_reason` written by `PATCH /archives/{id}` and `print_log_entries.failure_reason` read by the widget (`backend/app/services/failure_analysis.py:88`). `PrintLogEntry.failure_reason` gets captured exactly once at print-completion time (`backend/app/main.py:3641`) by copying `archive.failure_reason` — and at that moment the archive value is still `NULL` because the user hasn't picked a reason yet. The Edit Archive modal's PATCH route then writes only to `print_archives` via a generic `setattr` loop, never touching the log entry → widget stays stuck on `Unknown` forever. The reporter confirmed the desync at the DB level (`archive.failure_reason = 'Adhesion failure'`, `print_log_entry.failure_reason = NULL`). Fix mirrors `failure_reason` and `status` from the PATCH payload to the most recent `PrintLogEntry` for that archive (highest `id`). Latest-only because `archive.failure_reason` / `status` already reflect the *latest* run's outcome (each reprint clears the archive's reason at `main.py:2195` and rewrites it at completion), so the Edit Archive modal is implicitly showing — and editing — the latest run; reprints of an archive that succeeded on the second attempt keep the original failed run's classification intact. Scoped to those two fields only — `cost`, `print_name`, `printer_id` etc are deliberately *not* mirrored because per-run values legitimately diverge from archive-level ones (e.g. partial-print cost on a failed run differs from the source archive's full-print cost, see `_compute_run_filament_grams` at `main.py:596`). **Tests** (3 new in `test_archives_api.py`): the bug repro (failure_reason mirrors), the status case (the second field the reporter flagged), and the reprint guard (only the latest of multiple entries gets touched, an earlier entry keeps its prior reason). 55 archives-API tests green; ruff clean. - **SpoolBuddy: spool ID surfaced everywhere a spool's identity is rendered + Write-Tag page honours Spoolman mode (#1439, reported + partially prototyped by @flom89)** — Reporter buys filament in bulk and registers every individual spool in Spoolman at intake time (each gets a unique ID + a printed barcode that goes onto the physical roll when it's unboxed). When linking an NFC tag to one of those rolls in SpoolBuddy, the picker showed only material + colour + brand — so for ten identical "Black PLA" rolls every row looked the same. The user had no way to tell which physical spool they were about to bind the tag to; the original #1385 fix had surfaced the ID in Bambuddy's main UI (SpoolFormModal, FilamentHoverCard, the inventory-mode LinkSpoolModal) but the parallel SpoolBuddy components had been missed — they ship as part of the Bambuddy frontend repo under `frontend/src/components/spoolbuddy/` and `frontend/src/pages/spoolbuddy/`, not as a separate codebase. **Part 1 — ID surface, seven spots**: `#` in muted small monospace added to `LinkSpoolModal.tsx` (the link-tag-to-spool picker — the reporter's primary use case), `SpoolBuddyWriteTagPage.tsx` (write-tag picker — reporter's second screenshot), `AssignToAmsModal.tsx` header (single-spool context but disambiguating IDs help confirm the right roll was picked), `TagDetectedModal.tsx` (defined but unmounted today — kept consistent for future use), `SpoolInfoCard.tsx` (the found-tag panel on the right side of the dashboard — the "main screen" view), `InventorySpoolInfoCard.tsx` (matching inventory variant), and `SpoolBuddyAmsPage.tsx` AMS-slot assigned-spool block. All seven placements mirror the #1385 pattern (`#` with `shrink-0` so truncation never hides the ID). Frontend-only — the ID was already on the Spool / InventorySpool API shape (`spool.id`); these seven files just weren't surfacing it. **Part 2 — Spoolman-mode parity on the Write-Tag page**: reporter then surfaced that the same page hardcoded `api.getSpools(false)` regardless of inventory backend — so users in Spoolman mode (whose authoritative inventory is at Spoolman, not the internal table) saw spools they never created, and a successful tag write would bind the NFC tag to the wrong backend (the backend `/spoolbuddy/nfc/write-tag` route is mode-aware via `_get_spoolman_client_or_none`, but the frontend was driving it with internal-mode IDs that don't exist on the Spoolman side). Fix follows the wrapper pattern InventoryPage uses (`InventoryPageRouter` at `:445`): page detects `spoolmanMode` from a `getSpoolmanSettings` query at the top and threads it through, with `enabled: spoolmanModeReady` gating the spool fetch until settings load so we don't burn a wrong-backend request during the initial render. Every API call in the page now branches on `spoolmanMode` — 6 sites: the main spool list, the NewSpoolTouchForm's autocomplete spool list, the untag flow (`linkTagToSpool` vs `linkTagToSpoolmanSpool` — the Spoolman variant doesn't accept `data_origin` since Spoolman manages that), the K-profile save (`saveSpoolKProfiles` vs `saveSpoolmanKProfiles`), single-spool create (`createSpool` vs `createSpoolmanInventorySpool`), and bulk create (`bulkCreateSpools` vs `bulkCreateSpoolmanInventorySpools` — the Spoolman variant returns a `SpoolmanBulkCreateResult` envelope vs raw array, handled with a duck-typed `'created' in result` check that mirrors `SpoolFormModal`'s existing pattern). Same shape rule as [[feedback_sqlite_and_postgres_upfront]] / [[feedback_inventory_modes_parity]]: both modes ship in the same drop, no `spoolmanMode ? undefined : ...` UI gates. **Tests**: 3 new in `SpoolBuddyWriteTagPage.test.tsx` — the ID-visibility regression with two identical PLA-Red rolls IDs 42 / 43 (a future refactor that drops the ID span breaks it), plus two parity regressions (`reads from internal inventory when Spoolman mode is OFF` and `reads from Spoolman when Spoolman mode is ON` — the latter asserts `getSpools` is NOT called when the user is in Spoolman mode, so re-hardcoding the internal endpoint breaks CI immediately). 11 WriteTagPage tests + 51 other SpoolBuddy component tests green (62 total); frontend build clean. diff --git a/backend/app/services/printer_manager.py b/backend/app/services/printer_manager.py index 58ec358ba..bebf28293 100644 --- a/backend/app/services/printer_manager.py +++ b/backend/app/services/printer_manager.py @@ -616,13 +616,31 @@ class PrinterManager: return self._clients[printer_id].request_status_update() return False + # Probe budget for test_connection (#1445). Was a fixed 2s sleep, which was + # too short for P1S firmware whose broker / TLS handshake routinely takes + # 3–5s to surface a CONNACK on a cold MQTT session. We now poll up to + # PROBE_TIMEOUT_SECONDS and early-return the moment we see connected=True, + # so happy-path connections still finish in ~1–2s and slow brokers get the + # headroom they need instead of getting falsely rejected. + PROBE_TIMEOUT_SECONDS = 8.0 + PROBE_POLL_INTERVAL_SECONDS = 0.2 + async def test_connection( self, ip_address: str, serial_number: str, access_code: str, ) -> dict: - """Test connection to a printer without persisting.""" + """Test connection to a printer without persisting. + + Polls for up to PROBE_TIMEOUT_SECONDS and tears the probe client down + off-loop. The teardown matters: `client.disconnect()` ends in paho's + `loop_stop()` which `join()`s the network thread — if the thread is + still mid-TLS-handshake to a slow printer, that join blocks the + asyncio event loop and every other HTTP request queues behind it. The + original synchronous teardown produced the #1445 "Docker container + hangs" symptom on P1S when called from POST /printers/. + """ client = BambuMQTTClient( ip_address=ip_address, serial_number=serial_number, @@ -631,7 +649,9 @@ class PrinterManager: try: client.connect() - await asyncio.sleep(2) + deadline = asyncio.get_running_loop().time() + self.PROBE_TIMEOUT_SECONDS + while not client.state.connected and asyncio.get_running_loop().time() < deadline: + await asyncio.sleep(self.PROBE_POLL_INTERVAL_SECONDS) result = { "success": client.state.connected, @@ -639,7 +659,9 @@ class PrinterManager: "model": client.state.raw_data.get("device_model"), } finally: - client.disconnect() + # Off-loop teardown — see docstring. paho's loop_stop() joins the + # network thread which may still be in a slow TLS handshake. + await asyncio.to_thread(client.disconnect) return result diff --git a/backend/tests/unit/services/test_printer_manager.py b/backend/tests/unit/services/test_printer_manager.py index 62dbdf339..c31e2559a 100644 --- a/backend/tests/unit/services/test_printer_manager.py +++ b/backend/tests/unit/services/test_printer_manager.py @@ -584,12 +584,126 @@ class TestPrinterManager: mock_instance.state.connected = False MockClient.return_value = mock_instance - result = await manager.test_connection("192.168.1.100", "00M09A123456789", "12345678") + # Shorten the probe budget so the test doesn't burn the full + # 8-second production timeout while polling a failing connection. + with ( + patch.object(manager, "PROBE_TIMEOUT_SECONDS", 0.4), + patch.object(manager, "PROBE_POLL_INTERVAL_SECONDS", 0.1), + ): + result = await manager.test_connection("192.168.1.100", "00M09A123456789", "12345678") assert result["success"] is False assert result["state"] is None mock_instance.disconnect.assert_called_once() + @pytest.mark.asyncio + async def test_test_connection_polls_and_returns_early_on_connect(self, manager): + """#1445: a slow printer that finishes its handshake mid-probe must + not be reported as a failure. Previously a fixed 2s sleep meant P1S + TLS / CONNACK that took 3-5s got falsely rejected; now we poll and + early-return as soon as connected flips True. + """ + import asyncio + import time + + with patch("backend.app.services.printer_manager.BambuMQTTClient") as MockClient: + mock_instance = MagicMock() + mock_instance.state = MagicMock() + mock_instance.state.connected = False # not connected at probe start + mock_instance.state.state = "IDLE" + mock_instance.state.raw_data = {"device_model": "P1S"} + MockClient.return_value = mock_instance + + async def flip_connected_after(delay: float): + await asyncio.sleep(delay) + mock_instance.state.connected = True + + # Simulates the P1S broker finishing its slow handshake ~0.5s in, + # well past the old 2s-or-fail boundary's natural variance. + with ( + patch.object(manager, "PROBE_TIMEOUT_SECONDS", 3.0), + patch.object(manager, "PROBE_POLL_INTERVAL_SECONDS", 0.05), + ): + start = time.monotonic() + flip_task = asyncio.create_task(flip_connected_after(0.5)) + try: + result = await manager.test_connection("192.168.1.100", "00M09A123456789", "12345678") + finally: + await flip_task + elapsed = time.monotonic() - start + + assert result["success"] is True + assert result["state"] == "IDLE" + # Early-return guarantee: must come back well before the configured + # timeout once connected flips. ~0.5s + one poll interval is plenty. + assert elapsed < 1.5, f"probe should have early-returned shortly after 0.5s, took {elapsed:.2f}s" + + @pytest.mark.asyncio + async def test_test_connection_disconnect_runs_off_loop(self, manager): + """#1445: the root cause of the "Docker container hangs" symptom was + `client.disconnect()` running on the asyncio thread — paho's + `loop_stop()` does a thread-join that blocks until its network + thread exits, which on a slow P1S TLS handshake could take many + seconds. This test pins the off-loop teardown so a regression that + reintroduces sync disconnect breaks CI immediately. + """ + import asyncio + import threading + import time + + with patch("backend.app.services.printer_manager.BambuMQTTClient") as MockClient: + asyncio_thread_id = threading.get_ident() + disconnect_thread_ids: list[int] = [] + disconnect_blocked_for: list[float] = [] + + def slow_blocking_disconnect(): + # Mirrors paho.Client.loop_stop()'s thread-join semantics — + # if this runs on the asyncio thread the event loop stalls. + disconnect_thread_ids.append(threading.get_ident()) + start = time.monotonic() + time.sleep(0.4) + disconnect_blocked_for.append(time.monotonic() - start) + + mock_instance = MagicMock() + mock_instance.state = MagicMock() + mock_instance.state.connected = True + mock_instance.state.state = "IDLE" + mock_instance.state.raw_data = {"device_model": "P1S"} + mock_instance.disconnect = slow_blocking_disconnect + MockClient.return_value = mock_instance + + # Another coroutine must keep making progress while disconnect() + # runs — proves the event loop was not blocked. + event_loop_alive_ticks = 0 + + async def heartbeat(): + nonlocal event_loop_alive_ticks + while True: + await asyncio.sleep(0.05) + event_loop_alive_ticks += 1 + + heartbeat_task = asyncio.create_task(heartbeat()) + try: + await manager.test_connection("192.168.1.100", "00M09A123456789", "12345678") + finally: + heartbeat_task.cancel() + try: + await heartbeat_task + except asyncio.CancelledError: + pass + + # disconnect ran on a different thread than asyncio's + assert disconnect_thread_ids, "disconnect was never called" + assert disconnect_thread_ids[0] != asyncio_thread_id, ( + "disconnect ran on the asyncio thread — this blocks the event loop (#1445)" + ) + # Heartbeat made progress while the 0.4s disconnect was blocking + # the worker thread (proves the loop wasn't stalled). + assert event_loop_alive_ticks >= 3, ( + f"event loop appears to have stalled during disconnect " + f"(only {event_loop_alive_ticks} heartbeats; expected >=3)" + ) + # ======================================================================== # Tests for current print user tracking (Issue #206) # ========================================================================