diff --git a/CHANGELOG.md b/CHANGELOG.md index 205b3a1c7..3bedaaaea 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,6 +28,10 @@ All notable changes to Bambuddy will be documented in this file. - **Settings page: permission-gated instead of admin-only** — the Settings sidebar entry has always been visible to any user holding `settings:read`, but the route guard required admin role, so a non-admin with `settings:read` would see the entry, click it, and get silently redirected back to the dashboard. The route guard now matches the sidebar: any user with `settings:read` can open the page, and the individual tabs / cards continue to enforce their own per-feature permissions (`users:read`, `groups:update`, `oidc:*`, etc. — many of them admin-only, some not). Group editor routes moved to permission-based guards too (`groups:create` for `/groups/new`, `groups:update` for `/groups/:id/edit`), so permission delegation works end-to-end. Admins retain full access since admins implicitly hold every permission. ### Fixed +- **Spool auto-assign hit `IntegrityError` on Postgres when AMS pushes arrived in quick succession** — Bambu MQTT can deliver two `ams_data` push frames for the same printer ~30 ms apart (observed on H2D + dual AMS at K-profile-load / RFID-read boundaries). Each frame triggers `on_ams_change` in `backend/app/main.py`, whose auto-assign block reads `(printer_id, ams_id, tray_id)`, decides "no existing assignment", and INSERTs via `auto_assign_spool` — and the two callbacks raced in their respective sessions, both deciding to insert, with the second commit losing on `spool_assignment_printer_id_ams_id_tray_id_key`. SQLite's WAL serial-write semantics had been silently swallowing the race for ~7 weeks since the spool-assignment feature shipped (latent in `ec82092b`); when optional Postgres support landed in `610431d6` and asyncpg started allowing true concurrent transactions, it surfaced as `WARNING [main] RFID spool auto-assign failed: ... duplicate key value violates unique constraint ...; DETAIL: Key (printer_id, ams_id, tray_id)=(1, 0, 0) already exists`. Added a per-printer `asyncio.Lock` (`_ams_assignment_locks` keyed by `printer_id`) wrapping the auto-assign critical section so two callbacks for the same printer serialise — by the time the second one's session runs `select(SpoolAssignment).where(...)`, the first's commit is visible and the early-return "existing assignment" branch fires instead of a duplicate INSERT. The Spoolman sync block further down in the same callback intentionally stays OUTSIDE the lock — it's network-bound and idempotent, so serialising it would block subsequent AMS callbacks for the duration of a remote roundtrip. Per-printer scope keeps unrelated printers fully parallel: one printer's slow assignment never blocks another's. The auto-unlink block above the assign block isn't wrapped because its DELETE/UPDATE operations don't have the same constraint surface; the assign-block lock is sufficient because the second callback's `select` will see the first's committed state. 5 new regression tests in `test_ams_assignment_lock.py` cover same-printer-same-lock identity, different-printers-different-lock isolation, second acquirer waits for first inside the lock (proves serialisation), different printers run truly in parallel under a held lock (proves per-printer scope), and an auto-cleanup fixture resets the module-level dict between tests so cross-test loop affinity bugs can't surface. + +- **Camera TLS proxy logged "Unhandled exception in client_connected_cb" when ffmpeg dropped its half of the connection mid-stream under uvloop** — The bidirectional forwarders inside `services/camera.py::create_tls_proxy._handle` (the OpenSSL TLS shim added in [#661](https://github.com/maziggy/bambuddy/pull/661) so Bambu's RTSPS handshake works around Debian GnuTLS hardening) caught `(ConnectionError, OSError, asyncio.CancelledError)` on writes, but uvloop's `UVStream.write` raises a plain `RuntimeError` from `UVHandle._ensure_alive` when the underlying handle is already closed. asyncio's default selector loop reports the same situation as `ConnectionResetError`, so the bug only surfaced on uvloop deployments — and only at the moment the client (typically ffmpeg or a snapshot-capture subprocess) tore down its socket while the proxy was mid-flush. The `RuntimeError` slipped past the except tuple, escaped the forwarder coroutine, and asyncio's `client_connected_cb` task-exception handler logged a noisy multi-line traceback ending in `RuntimeError: unable to perform operation on ; the handler is closed`. Added `RuntimeError` to the except tuple in both `_fwd_to_server` and `_fwd_to_client` (the latter being the actual frame in the bug report — server→client is where buffered TLS chunks land after the client has gone). The forwarders are intentionally fire-and-forget on tear-down; once either peer drops, both halves of the proxy should exit quietly and the existing `dst.close()` in the `finally` block already handles cleanup. No functional regression possible — the connection is already dead by the time the exception fires; this only changes whether asyncio logs an "Unhandled exception" trace for it. 2 new regression contract tests in `test_camera_tls_proxy.py` use `inspect.getsource` to assert both forwarder closures' except clauses include `RuntimeError`, since the closures are nested inside `_handle` and extracting them just for testability would require a pure-cosmetic refactor of the proxy. + - **Background-dispatch reported "Print started successfully" when the printer never actually transitioned** ([#1134](https://github.com/maziggy/bambuddy/issues/1134), follow-up to [#1042](https://github.com/maziggy/bambuddy/issues/1042)) — The int32 `task_id` modulo fix that was the original root cause of #1042 is verified working in the reporter's most recent support pack (the published `task_id` values are well below 2^31-1 and match the `int(time.time() * 1000) % 2_147_483_647` formula exactly). The remaining residual — "the UI reports despatch success which is slightly misleading" — was a real second bug class: the post-dispatch watchdog `_verify_print_response` in `services/background_dispatch.py` was *fire-and-forget*. It would correctly detect that the printer never transitioned (e.g. P1S sitting in `gcode_state: FAILED` with HMS `0300_400C` "task was canceled", a half-broken MQTT session, an SD card error, or any other pre-print blocker), log a `did not respond to print command within 15s` warning, force-reconnect the MQTT session — and then return without touching the dispatch job state. The dispatch job had already been marked successful on the optimistic MQTT-publish-acknowledged path, so the UI carried on showing "Print started successfully" while the printer sat idle. The watchdog now returns a `bool` and is awaited inline by both call sites (`_run_reprint_archive` at line 687, `_run_print_library_file` at line 860); on `False` (timeout) the call sites raise a `RuntimeError` carrying a user-actionable message ("Printer did not acknowledge print command — state still {pre_state}. Check the printer for a pending error (HMS code, plate-clear prompt, SD card) and try again."), which routes through the existing `_mark_job_finished(failed=True, …)` path so the dispatch UI shows a real failure toast and the library-file flow's freshly-created archive is `db.rollback()`'d (no orphan rows for prints that never started). The watchdog now also accepts `subtask_id` advancing past the captured `pre_subtask_id` as a definitive "command landed" signal — same as the queue-side watchdog at `print_scheduler.py:1992` (#1078) — so slow H2D `FINISH→PREPARE` transitions (~50 s observed) don't false-fail when the printer has clearly accepted the project_file but is still in FINISH. Default timeout raised from 15 s to 90 s to match the queue-side watchdog (#967 / #1078) and give the same headroom on both dispatch paths. Brief mid-window MQTT disconnects (`get_status() is None` for one tick) now keep polling instead of immediately failing — matches what the queue watchdog already does and avoids false-failing on transient telemetry gaps. The existing `force_reconnect_stale_session` recovery is preserved on the timeout path. 8 new regression tests in `test_background_dispatch_watchdog.py` cover state-change pickup, subtask_id-change pickup with state still FINISH (the H2D case), neither-signal-changed timeout + force-reconnect, pre_subtask_id=None backwards-compat, post-dispatch subtask_id=None not counting as a change (avoids false-pass on transient reconnect), brief disconnect not short-circuiting the window, persistent disconnect for the full window returning False, and a contract test that the default timeout is 90 s. Thanks to @EdwardChamberlain for the detailed retest with logs that pinpointed the watchdog's no-propagation gap. - **Bambu RFID auto-match created duplicate inventory rows for Quick-Add and non-Bambu-branded spools** ([#918](https://github.com/maziggy/bambuddy/issues/918)) — `find_matching_untagged_spool` is supposed to attach a Bambu RFID UID to a pre-existing manually-logged spool of the same material/color so users who log inventory before scanning don't end up with a duplicate row on first AMS read. Two bugs in the matcher meant it almost never worked for the actual reporting workflow: **(1)** the subtype filter was strict — when the AMS tray reports `tray_sub_brands="PLA Basic"` the matcher required `Spool.subtype = 'Basic'` exactly, so any Quick-Add row (Quick-Add only requires `material`, leaving `subtype=NULL`) was excluded and duplicated on first AMS read. **(2)** the docstring claimed it filtered on brand but the WHERE clause didn't, so a same-color *Polymaker* untagged spool would silently acquire a Bambu Lab tray UUID, leaving the user with `brand="Polymaker"` but a Bambu UUID — silent data corruption. Both bugs are addressed in the same query: subtype now prefers an exact match but accepts a NULL-subtype row as fallback (with a `CASE` in `ORDER BY` so an exact match still wins when both exist), and brand is now restricted to "contains 'bambu' (case-insensitive)" or NULL — matching `'Bambu'` (the form's `DEFAULT_BRANDS` value), `'Bambu Lab'` (the catalog value), `'BambuLab'`, `'bambu lab'`, etc., while rejecting any explicitly-named third-party brand. 6 new regression tests in `test_spool_tag_matcher.py` cover the NULL-subtype fallback, exact-subtype-wins-over-NULL ordering, non-Bambu brand rejection, NULL brand acceptance, all four Bambu brand spelling variants, and the full Quick-Add scenario (`brand=NULL` + `subtype=NULL`). The broader UI proposals in #918 (manual override / merge / disambiguation prompt) are intentionally out of scope — once the matcher works, the duplicate-on-RFID complaint that motivated those proposals goes away. Thanks to @ViridityCorn for the report and pointing at the right function, and to @Arn0uDz for confirming with a 20-spool repro. diff --git a/backend/app/main.py b/backend/app/main.py index f104cc3b1..4c44267da 100644 --- a/backend/app/main.py +++ b/backend/app/main.py @@ -313,6 +313,35 @@ _user_stopped_printers: set[int] = set() # {(printer_id, filename): created_by_id} _expected_print_creators: dict[tuple[int, str], int] = {} +# Per-printer lock that serialises the spool-assignment side of on_ams_change +# (auto-unlink stale + auto-assign new) when MQTT bursts deliver multiple AMS +# updates for the same printer in quick succession (~30 ms apart, observed in +# the wild on H2D + dual AMS). +# +# Without this serialisation, two concurrent on_ams_change callbacks each read +# "no assignment for (printer, ams, tray)", each call auto_assign_spool, and +# the second commit hits +# IntegrityError: duplicate key value violates unique constraint +# "spool_assignment_printer_id_ams_id_tray_id_key" +# SQLite's WAL serial-write semantics had been silently swallowing the race +# until optional Postgres support landed (asyncpg allows true concurrent +# transactions and surfaces the constraint violation). +# +# Scope is intentionally narrow: only the two DB-mutating blocks (unlink + +# assign) are inside the lock. The Spoolman sync block further down stays +# concurrent because it's network-bound and idempotent. +_ams_assignment_locks: dict[int, asyncio.Lock] = {} + + +def _get_ams_assignment_lock(printer_id: int) -> asyncio.Lock: + """Return the per-printer assignment lock, creating it on first use.""" + lock = _ams_assignment_locks.get(printer_id) + if lock is None: + lock = asyncio.Lock() + _ams_assignment_locks[printer_id] = lock + return lock + + # TTL for expected-print entries: evict registrations older than this to prevent # unbounded growth when a print is registered but never starts (e.g. printer # disconnect, app restart, print started from the printer panel). @@ -887,9 +916,15 @@ async def on_ams_change(printer_id: int, ams_data: list): except Exception as e: logger.warning("Spool assignment cleanup failed: %s", e, exc_info=True) - # Auto-manage inventory spools from AMS tray data (skip if Spoolman manages AMS) + # Auto-manage inventory spools from AMS tray data (skip if Spoolman manages AMS). + # Serialised per-printer via _ams_assignment_locks: MQTT bursts can deliver + # two AMS pushes ~30 ms apart, and without the lock both callbacks read + # "no existing assignment" for the same (printer, ams, tray) and race to + # INSERT, hitting the spool_assignment_printer_id_ams_id_tray_id_key + # unique constraint on Postgres. SQLite's WAL serialises writes so the + # bug stayed latent there. See _ams_assignment_locks comment for details. try: - async with async_session() as db: + async with _get_ams_assignment_lock(printer_id), async_session() as db: from backend.app.api.routes.settings import get_setting from backend.app.models.spool_assignment import SpoolAssignment as SA from backend.app.services.spool_tag_matcher import ( diff --git a/backend/tests/unit/test_ams_assignment_lock.py b/backend/tests/unit/test_ams_assignment_lock.py new file mode 100644 index 000000000..9a7932b88 --- /dev/null +++ b/backend/tests/unit/test_ams_assignment_lock.py @@ -0,0 +1,147 @@ +"""Regression tests for ``_ams_assignment_locks`` (per-printer serialisation +of ``on_ams_change``'s spool-assignment block). + +Background +========== + +MQTT bursts can deliver two ``ams_data`` push frames for the same printer ~30 +ms apart (observed in the wild: H2D + dual AMS at K-profile load + RFID-read +boundaries). Without serialisation, both ``on_ams_change`` callbacks read +"no assignment for ``(printer, ams, tray)``" in their respective sessions, +both call ``auto_assign_spool``, both ``INSERT``, and the second commit +violates ``spool_assignment_printer_id_ams_id_tray_id_key``: + + asyncpg.exceptions.UniqueViolationError: duplicate key value violates + unique constraint "spool_assignment_printer_id_ams_id_tray_id_key" + DETAIL: Key (printer_id, ams_id, tray_id)=(1, 0, 0) already exists. + +SQLite's WAL serialises writes so the bug stayed latent there for ~7 weeks. +It surfaced when optional Postgres support landed and asyncpg started +allowing true concurrent transactions. + +These tests assert the lock primitive's properties, not the full +``on_ams_change`` flow — wiring the whole callback through a real DB at unit +scope would dwarf the size of the fix and add no signal beyond what the +existing integration suite already covers. +""" + +from __future__ import annotations + +import asyncio + +import pytest + +from backend.app.main import _ams_assignment_locks, _get_ams_assignment_lock + + +@pytest.fixture(autouse=True) +def _isolate_locks_dict(): + """Each test gets a fresh module-level locks dict — otherwise prior + tests' lazy-created locks leak across runs and a stale ``Lock`` object + bound to an already-closed event loop trips uvloop's "Future attached to + a different loop" assertion.""" + saved = dict(_ams_assignment_locks) + _ams_assignment_locks.clear() + try: + yield + finally: + _ams_assignment_locks.clear() + _ams_assignment_locks.update(saved) + + +class TestLockKeySeparation: + def test_same_printer_returns_same_lock(self): + """Two callbacks for the same printer must contend on the same lock — + otherwise serialisation buys us nothing.""" + a = _get_ams_assignment_lock(7) + b = _get_ams_assignment_lock(7) + assert a is b + + def test_different_printers_get_different_locks(self): + """Per-printer scope: one printer's slow assignment must not block + unrelated printers from processing their own AMS pushes.""" + a = _get_ams_assignment_lock(7) + b = _get_ams_assignment_lock(8) + assert a is not b + + +class TestLockSerialisesConcurrentCallbacks: + @pytest.mark.asyncio + async def test_second_acquirer_waits_for_first(self): + """The exact race the bug fix targets: two coroutines for the same + printer must serialise inside the lock, so the second only enters + the critical section after the first has committed.""" + printer_id = 42 + order: list[str] = [] + first_inside = asyncio.Event() + first_release = asyncio.Event() + + async def first(): + async with _get_ams_assignment_lock(printer_id): + order.append("first-enter") + first_inside.set() + # Hold the lock until the test allows release; this is what + # gives the second coroutine a chance to queue up if the + # primitive is doing its job. + await first_release.wait() + order.append("first-exit") + + async def second(): + await first_inside.wait() # ensure first holds the lock + async with _get_ams_assignment_lock(printer_id): + order.append("second-enter") + + task_a = asyncio.create_task(first()) + task_b = asyncio.create_task(second()) + + await first_inside.wait() + # Yield the loop a few times so `second()` has every opportunity to + # mistakenly enter early; without the lock, "second-enter" would land + # before "first-exit". + for _ in range(5): + await asyncio.sleep(0) + + assert order == ["first-enter"] + + first_release.set() + await asyncio.gather(task_a, task_b) + + assert order == ["first-enter", "first-exit", "second-enter"] + + @pytest.mark.asyncio + async def test_different_printers_run_in_parallel(self): + """Cross-printer independence: two callbacks for distinct printers + must NOT block each other, otherwise a single slow printer would + stall every other printer's AMS handling.""" + order: list[str] = [] + printer_a_inside = asyncio.Event() + printer_a_release = asyncio.Event() + + async def printer_a(): + async with _get_ams_assignment_lock(1): + order.append("a-enter") + printer_a_inside.set() + await printer_a_release.wait() + order.append("a-exit") + + async def printer_b(): + await printer_a_inside.wait() + async with _get_ams_assignment_lock(2): + order.append("b-enter-and-exit") + + task_a = asyncio.create_task(printer_a()) + task_b = asyncio.create_task(printer_b()) + + # Wait for printer_a to be holding the lock, then yield for printer_b. + await printer_a_inside.wait() + for _ in range(5): + await asyncio.sleep(0) + + # printer_b must have entered AND exited its own lock while + # printer_a is still holding lock A. If the locks were a single + # global mutex, "b-enter-and-exit" would not yet appear. + assert "b-enter-and-exit" in order + assert "a-exit" not in order + + printer_a_release.set() + await asyncio.gather(task_a, task_b)