fix(inventory): serialise spool auto-assign per printer to fix Postgres race

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 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:

      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 serial-write semantics had been silently swallowing the
  race for ~7 weeks since the spool-assignment feature shipped (latent in
  ec82092b "Sync", 2026-02-12). When optional Postgres support landed in
  610431d6 (2026-04-03) and asyncpg started allowing true concurrent
  transactions, it surfaced. Net impact: log noise + one assignment cycle
  skipped, retried on the next on_ams_change.

  Adds a per-printer asyncio.Lock (_ams_assignment_locks keyed by
  printer_id) wrapping the auto-assign critical section. By the time the
  second callback's session runs the SELECT, 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 on_ams_change 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. The auto-unlink block above isn't wrapped because its
  DELETE/UPDATE operations don't have the same constraint surface.

  5 new regression tests in test_ams_assignment_lock.py: same-printer-
  same-lock identity, different-printers-different-lock isolation, second
  acquirer waits for first (proves serialisation), different printers run
  truly in parallel under a held lock (proves per-printer scope), and an
  autouse fixture that resets the module-level dict between tests so
  cross-test loop affinity bugs can't surface.
This commit is contained in:
maziggy
2026-04-26 09:40:02 +02:00
parent 60d0c33172
commit 352e619ad7
3 changed files with 188 additions and 2 deletions
+4
View File
@@ -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 <TCPTransport closed=True ...>; 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.
+37 -2
View File
@@ -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 (
@@ -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)