From a36c0009a5c07e990b266d4660800f26b587fe5e Mon Sep 17 00:00:00 2001 From: maziggy Date: Sat, 26 Sep 2026 11:14:25 +0200 Subject: [PATCH] fix(diagnostics): name the stalled step when a bundle's connection check times out (issue #3164) The support bundle gives each printer's connection diagnostic 15 s and discarded the whole result on overrun, recording only "timed_out". A 14-printer farm's bundle carried that marker for every printer and nothing else, so it could not say which check was slow. run_connection_diagnostic now keeps an optional progress dict current (finished checks + the step in flight). On timeout the snapshot records stalled_in, elapsed_s and the checks that completed. --- CHANGELOG.md | 1 + backend/app/services/diagnostic_snapshot.py | 15 +++- backend/app/services/printer_diagnostic.py | 18 +++++ .../tests/unit/test_diagnostic_snapshot.py | 77 +++++++++++++++++++ 4 files changed, 110 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0830a45ed..9e24ae1c0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -36,6 +36,7 @@ All notable changes to Bambuddy will be documented in this file. - **The frontend build no longer warns about `path` and `crypto` being externalized for the STEP previewer (#2976)** — `occt-import-js`, the Emscripten build behind STEP previews, requires both modules, but only inside its `ENVIRONMENT_IS_NODE` branches; in the browser it loads its `.wasm` from the URL the preview worker passes and draws randomness from `crypto.getRandomValues`. Vite still externalized both and printed two warnings on every build. `vite.config.ts` now drops exactly those two warnings for that one package through `build.rolldownOptions.onLog`, so an externalization anywhere else, or of any other module, still shows. ### Fixed +- **A connection check that overruns in the support bundle now says which step hung, and keeps what finished (#3164)** — The support bundle gives each printer's connection diagnostic 15 seconds and used to discard the whole result when it overran, recording only `timed_out`. A 14-printer farm's bundle came back with that marker on every printer and nothing else, so it could not show which check was slow or whether the printers were reachable at all. The diagnostic now records each check as it finishes and the step it is on; a timed-out entry carries `stalled_in` (the step that was still running), `elapsed_s`, and the checks that completed before it. - **PDF previews in the File Manager failed on any browser older than Chrome 145 or Firefox 144 (#2976)** — Every PDF showed "This file cannot be previewed." pdf.js 6 calls `Map.prototype.getOrInsertComputed` and other recent APIs directly, and the preview loaded its standard build, which assumes them. It now loads pdf.js's legacy build, which bundles polyfills for both the page and the worker. The worker is also bundled through Vite (`?worker&url`) instead of being copied as-is: the copied file kept a class static block that Safari 16.0-16.3 cannot parse, and `build.target` now lowers it like the rest of the app. The Safari 16 baseline check missed that file because it only scanned `.js` output; it now scans `.mjs` too. Checked in a real Chromium without the API, under the app's own Content-Security-Policy: a two-page text PDF renders, pages, and reopens. - **The concurrent-dispatch tests no longer depend on machine speed to prove the scheduler dispatches in parallel** — `tests/unit/test_scheduler_concurrent_dispatch.py` failed on CI and passed locally on a commit that touched nothing but a text file, and it had two independent reasons to. The first: the fixtures built their farm on `sqlite+aiosqlite:///:memory:`, and SQLAlchemy backs an in-memory SQLite with a `StaticPool` — one DBAPI connection handed to every session, with nothing keeping them apart. That was harmless while `check_queue` awaited its uploads inline, because only one session was ever live at a time. Under the refillable upload pool (#2602) the uploads run as concurrent background tasks with a session each, so their transactions interleave on that single connection: a sibling session's `close()` rolls back another's flushed-but-uncommitted UPDATE, which is how six queue items were each logged as `Status set to 'printing'` and four of them read back as `pending`. The fixtures now put the database in the test's own `tmp_path` and open it through the application's own connect listener, so each session gets its own connection and the file is opened the way the running system opens one — WAL, `synchronous = NORMAL`, a 15 s busy timeout — rather than with SQLite's defaults, which spend an fsync per commit and lock the whole file. The second reason was underneath the first and would have outlived it: `peak == 6` means the sixth dispatch reached its upload before the first one finished, and each dispatch runs a preamble of database work first, so the assertion was really a race between that spread and a fixed 0.15 s sleep. The spread is ~14 ms on a workstation and passed 150 ms on a CI runner, which recorded a peak of 4 out of 6 for a scheduler that was dispatching all six correctly. The uploads now hold until every upload the pass launched has arrived — `scheduler._inflight` is filled synchronously at launch, so its length is the batch size — which states the property directly, with no time in it, and ends sooner than the sleep it replaces. Reproduced both ways before and after: with one printer's preamble delayed by a second, the old recorder reports exactly the "high-water mark was 4" CI saw and the new one passes. Nothing in the scheduler changes; the concurrency under test was correct throughout. - **An AMS that reports no humidity percentage no longer shows the drop index as one (#3140, reported by @Sawtaytoes)** — Bambu sends two humidity fields that are not the same quantity: `humidity_raw` is relative humidity in percent, and `humidity` is the 1-5 drop index, which runs the other way — a high index means dry where a high percentage means wet. Bambuddy used the index whenever no percentage arrived, so a unit sending only the index rendered as "2%" in the green band while being the second-wettest of the five steps, charted an average of index values as a percentage, and could never cross a humidity alarm or auto-drying threshold, since no index reaches one. Such a unit now reports no humidity at all: the card hides the water-drop indicator, the history chart leaves a gap, and the alarm and auto-drying skip the unit instead of reading it as permanently bone dry. Temperature is recorded and alarmed on as before. No supported printer is known to be affected — the report came from an install running X1Plus, which Bambuddy does not support — and printers that send a percentage keep it, including two readings that previously fell through to the index because they would not parse as a whole number: one with a decimal point, and `38.0`. A unit that sends the index and no percentage now says so once in the log, with its firmware versions requested, so a supported printer that turns out to do this is visible rather than silently blank. Three smaller faults in the same paths went with it: a humidity of exactly 0% was stored as NULL when the firmware sent it as a number, a history window averaging exactly 0 reported no average at all while the minimum and maximum beside it reported 0, and a `humidity_raw` that was not a number at all aborted the whole recording pass for every printer, not just the one that sent it. diff --git a/backend/app/services/diagnostic_snapshot.py b/backend/app/services/diagnostic_snapshot.py index f6199676e..de37ed25e 100644 --- a/backend/app/services/diagnostic_snapshot.py +++ b/backend/app/services/diagnostic_snapshot.py @@ -22,6 +22,7 @@ from __future__ import annotations import asyncio import logging import re +import time from typing import Any from sqlalchemy import select @@ -54,6 +55,8 @@ async def _run_connection_for(printer) -> dict: from backend.app.services.printer_diagnostic import run_connection_diagnostic base = {"printer_id": printer.id, "printer_name": printer.name} + progress: dict[str, Any] = {} + started = time.monotonic() try: result = await asyncio.wait_for( run_connection_diagnostic( @@ -61,12 +64,22 @@ async def _run_connection_for(printer) -> dict: printer=printer, serial_number=printer.serial_number, access_code=printer.access_code, + progress=progress, ), timeout=_PER_DIAGNOSTIC_TIMEOUT_SECONDS, ) return {**base, "result": _serialize(result)} except asyncio.TimeoutError: - return {**base, "error": "timed_out"} + # Name the step that hung and keep the checks that finished before it. + # Without them a bundle from a farm whose every printer overran said + # only "timed_out" fourteen times, and nothing about why (#3164). + return { + **base, + "error": "timed_out", + "stalled_in": progress.get("stage"), + "elapsed_s": round(time.monotonic() - started, 1), + "checks": [_serialize(c) for c in progress.get("checks", [])], + } except Exception as e: # Log with traceback so the bundle generation isn't silent about # a broken probe, but never propagate. diff --git a/backend/app/services/printer_diagnostic.py b/backend/app/services/printer_diagnostic.py index 1ca1ded85..1f8b37b86 100644 --- a/backend/app/services/printer_diagnostic.py +++ b/backend/app/services/printer_diagnostic.py @@ -413,6 +413,7 @@ async def run_connection_diagnostic( serial_number: str | None = None, access_code: str | None = None, wait_for_publish_seconds: float = 0.0, + progress: dict | None = None, ) -> PrinterDiagnosticResult: """Run connection checks for a printer. @@ -422,10 +423,20 @@ async def run_connection_diagnostic( Each check carries a stable ``id`` and a ``status`` of pass / fail / warn / skip; the frontend renders the human-readable title and fix text (localized) keyed on that id + status. + + ``progress``, when given, is kept current while the checks run: its + ``checks`` key is the list of finished checks and ``stage`` names the step + in flight. The support bundle cancels a run that overruns its budget, and + this is how it can still say which step hung and keep what finished -- + a bare "timed out" for every printer is all #3164's bundle could show. """ checks: list[DiagnosticCheck] = [] + if progress is None: + progress = {} + progress["checks"] = checks # --- Port reachability (probed in parallel) --- + progress["stage"] = "ports" camera_port, camera_protocol = _camera_port_for_printer(printer) mqtt_ok, ftps_state, camera_ok = await asyncio.gather( _check_port(ip_address, PORT_MQTT), @@ -452,6 +463,7 @@ async def run_connection_diagnostic( ) # --- macOS Local Network permission --- + progress["stage"] = "macos_local_network" # Appended on macOS only. Everywhere else there is nothing to say, and a # permanently dimmed "skipped" row would be noise for the users who make # up nearly all of them. @@ -485,6 +497,7 @@ async def run_connection_diagnostic( checks.append(DiagnosticCheck(id="macos_local_network", status="warn", params={"reason": "permission"})) # --- Container network mode --- + progress["stage"] = "network_mode" # Not Docker-only: Podman runs Bambuddy in exactly the same two shapes and # its users were told "Not running in Docker", which reads as "you are on # bare metal" and sent them looking for the problem somewhere else (#3092). @@ -514,6 +527,7 @@ async def run_connection_diagnostic( ) # --- Subnet match --- + progress["stage"] = "subnet" # Skipped in bridge mode: the container IP is the bridge IP, not the host's, # so the comparison is meaningless and the network_mode check already covers it. if network_mode == "bridge": @@ -534,6 +548,7 @@ async def run_connection_diagnostic( ) # --- External storage (printer-side "Store sent files on external storage") --- + progress["stage"] = "external_storage" # Install step 4. The setting has two variants depending on # firmware/slicer combo: on newer firmware the toggle lives on the # printer (P2S 01.02 / BambuStudio 2.6+), on older versions it's @@ -632,6 +647,7 @@ async def run_connection_diagnostic( checks.append(DiagnosticCheck(id="external_storage", status="skip")) # --- MQTT credentials / connection --- + progress["stage"] = "mqtt_auth" if not mqtt_ok: # Can't reach the broker at all — the port check already reported it. checks.append(DiagnosticCheck(id="mqtt_auth", status="skip")) @@ -671,6 +687,7 @@ async def run_connection_diagnostic( checks.append(DiagnosticCheck(id="mqtt_auth", status="skip")) # --- LAN developer mode (only readable over a live MQTT connection) --- + progress["stage"] = "developer_mode" if state is not None and state.connected: if state.developer_mode is True: dev_status = "pass" @@ -683,6 +700,7 @@ async def run_connection_diagnostic( checks.append(DiagnosticCheck(id="developer_mode", status="skip")) # --- Printer is actually publishing on its report topic --- + progress["stage"] = "printer_publishing" # The mqtt_auth check above only proves TCP + TLS + auth + SUBSCRIBE # succeed. A printer with a wrong-cased serial — or one that simply isn't # publishing for some other reason — still passes mqtt_auth because the diff --git a/backend/tests/unit/test_diagnostic_snapshot.py b/backend/tests/unit/test_diagnostic_snapshot.py index b81311afd..e603de883 100644 --- a/backend/tests/unit/test_diagnostic_snapshot.py +++ b/backend/tests/unit/test_diagnostic_snapshot.py @@ -159,6 +159,83 @@ async def test_snapshot_emits_timed_out_marker_when_probe_exceeds_cap(): assert out["connection_diagnostics"][0]["error"] == "timed_out" +@pytest.mark.asyncio +async def test_timed_out_entry_names_the_stalled_step_and_keeps_finished_checks(): + """#3164: every printer of a 14-printer farm came back as a bare + `timed_out`, so the bundle could not say which step hung. The real + diagnostic runs here with the ports answering and the subnet lookup + hanging; the entry must name `subnet` and carry the port checks that + finished before it.""" + import time as _time + + printers = [ + SimpleNamespace( + id=1, + name="A1", + model="A1", + ip_address="10.0.0.5", + serial_number="s", + access_code="a", + ) + ] + db = _make_db_with_printers_and_vps(printers, []) + + def hanging_subnet(*_a, **_k): + _time.sleep(1.0) # blocks its worker thread well past the cap below + return True + + with ( + patch("backend.app.services.printer_diagnostic._check_port", new=AsyncMock(return_value=True)), + patch("backend.app.services.printer_diagnostic._check_ftps_tls", new=AsyncMock(return_value="ok")), + patch("backend.app.services.printer_diagnostic.detect_container_runtime", return_value=None), + patch("backend.app.services.printer_diagnostic._host_source_ip", return_value="10.0.0.2"), + patch("backend.app.services.printer_diagnostic._same_subnet", side_effect=hanging_subnet), + patch("backend.app.services.diagnostic_snapshot._PER_DIAGNOSTIC_TIMEOUT_SECONDS", 0.2), + patch( + "backend.app.services.diagnostic_snapshot._run_log_health", + new=AsyncMock(return_value={"findings": []}), + ), + ): + out = await collect_diagnostic_snapshot(db) + + entry = out["connection_diagnostics"][0] + assert entry["error"] == "timed_out" + assert entry["stalled_in"] == "subnet" + assert 0.1 <= entry["elapsed_s"] < 1.0 + finished = {c["id"]: c["status"] for c in entry["checks"]} + assert finished["port_mqtt"] == "pass" + assert finished["port_ftps"] == "pass" + assert finished["network_mode"] == "skip" + assert "subnet" not in finished + + +@pytest.mark.asyncio +async def test_timed_out_entry_without_progress_still_has_the_marker(): + """A diagnostic that hangs before recording anything still yields the + marker with an empty check list rather than a KeyError.""" + printers = [SimpleNamespace(id=1, name="slow", ip_address="1.1.1.1", serial_number="s", access_code="a")] + db = _make_db_with_printers_and_vps(printers, []) + + async def hang(*a, **k): + import asyncio + + await asyncio.sleep(5) + + with ( + patch("backend.app.services.printer_diagnostic.run_connection_diagnostic", new=AsyncMock(side_effect=hang)), + patch("backend.app.services.diagnostic_snapshot._PER_DIAGNOSTIC_TIMEOUT_SECONDS", 0.05), + patch( + "backend.app.services.diagnostic_snapshot._run_log_health", + new=AsyncMock(return_value={"findings": []}), + ), + ): + out = await collect_diagnostic_snapshot(db) + + entry = out["connection_diagnostics"][0] + assert entry["stalled_in"] is None + assert entry["checks"] == [] + + @pytest.mark.asyncio async def test_snapshot_masks_ip_addresses_in_all_diagnostic_fields(): """The diagnostic schemas embed raw IPv4 in three places — the top-level