Przeglądaj źródła

fix(inventory): hand assign, unassign and add-from-slot wait for the printer's slot lock; the AMS remain sync and a print's usage no longer overwrite a weight set by hand or weighed meanwhile; a spool deleted while a print is charged is skipped

maziggy 3 dni temu
rodzic
commit
5b34997dfa

+ 4 - 0
CHANGELOG.md

@@ -164,6 +164,10 @@ 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
+- **Spool weights and slot assignments written at the same moment no longer undo each other** — Three cases:
+  - **Assigning or unassigning a spool by hand, or adding a slot's spool to the inventory,** while the printer reported an AMS change for the same slot (or on a double-click) could fail with a server error on PostgreSQL. These now wait for the AMS update, as AMS updates already wait for each other.
+  - **A weight set by hand or weighed on the SpoolBuddy scale** just as the AMS remain% sync ran could be overwritten by the AMS figure, with the weight still marked as locked.
+  - **The same weight set at the end of a print** was replaced by the weight from before it plus the print's usage. The usage is now added to the stored weight.
 - **Inventory views stay current, and spools follow their printers and slots** — Five cases:
   - **Deleting a spool** left it shown in its AMS slot in other open tabs, and **a weight from the SpoolBuddy scale, the automatic AMS sync or "Sync Weights from AMS"** reached other open tabs and the printer cards only when they next refreshed. These changes are now announced like any other inventory change, and the printer cards also show the weight a finished print leaves straight away.
   - **Deleting a printer** on SQLite (the default database) left its spools assigned to it, shown as loaded on a printer that no longer exists. Their slots are now freed, and assignments left behind by earlier deletes are cleared at the next start.

+ 51 - 44
backend/app/api/routes/inventory.py

@@ -61,6 +61,7 @@ from backend.app.schemas.supplier import (
     SupplierUpdate,
 )
 from backend.app.services import slot_unlink_grace
+from backend.app.services.ams_assignment_lock import get_ams_assignment_lock
 from backend.app.services.ams_slot_presence import spool_present
 from backend.app.services.location_service import (
     DUPLICATE_LOCATION_NAME,
@@ -2261,29 +2262,31 @@ async def assign_spool(
                     tray_state = raw_state
                 tray_has_spool = spool_present(tray)
 
-    # 3. Upsert assignment (replace if same printer+ams+tray)
-    existing = await db.execute(
-        select(SpoolAssignment).where(
-            SpoolAssignment.printer_id == data.printer_id,
-            SpoolAssignment.ams_id == data.ams_id,
-            SpoolAssignment.tray_id == data.tray_id,
+    # 3. Upsert assignment (replace if same printer+ams+tray), under the lock
+    # the AMS change handler writes the printer's slots with.
+    async with get_ams_assignment_lock(data.printer_id):
+        existing = await db.execute(
+            select(SpoolAssignment).where(
+                SpoolAssignment.printer_id == data.printer_id,
+                SpoolAssignment.ams_id == data.ams_id,
+                SpoolAssignment.tray_id == data.tray_id,
+            )
         )
-    )
-    old = existing.scalar_one_or_none()
-    if old:
-        await db.delete(old)
-        await db.flush()
-
-    assignment = SpoolAssignment(
-        spool_id=data.spool_id,
-        printer_id=data.printer_id,
-        ams_id=data.ams_id,
-        tray_id=data.tray_id,
-        fingerprint_color=fingerprint_color,
-        fingerprint_type=fingerprint_type,
-    )
-    db.add(assignment)
-    await db.commit()
+        old = existing.scalar_one_or_none()
+        if old:
+            await db.delete(old)
+            await db.flush()
+
+        assignment = SpoolAssignment(
+            spool_id=data.spool_id,
+            printer_id=data.printer_id,
+            ams_id=data.ams_id,
+            tray_id=data.tray_id,
+            fingerprint_color=fingerprint_color,
+            fingerprint_type=fingerprint_type,
+        )
+        db.add(assignment)
+        await db.commit()
     await db.refresh(assignment)
     slot_unlink_grace.forget_slot(data.printer_id, data.ams_id, data.tray_id)
 
@@ -2422,19 +2425,20 @@ async def unassign_spool(
     _: User | None = RequirePrinterPermissionIfAuthEnabled(Permission.INVENTORY_UPDATE),
 ):
     """Unassign a spool from an AMS slot."""
-    result = await db.execute(
-        select(SpoolAssignment).where(
-            SpoolAssignment.printer_id == printer_id,
-            SpoolAssignment.ams_id == ams_id,
-            SpoolAssignment.tray_id == tray_id,
+    async with get_ams_assignment_lock(printer_id):
+        result = await db.execute(
+            select(SpoolAssignment).where(
+                SpoolAssignment.printer_id == printer_id,
+                SpoolAssignment.ams_id == ams_id,
+                SpoolAssignment.tray_id == tray_id,
+            )
         )
-    )
-    assignment = result.scalar_one_or_none()
-    if not assignment:
-        raise HTTPException(404, "Assignment not found")
+        assignment = result.scalar_one_or_none()
+        if not assignment:
+            raise HTTPException(404, "Assignment not found")
 
-    await db.delete(assignment)
-    await db.commit()
+        await db.delete(assignment)
+        await db.commit()
 
     await ws_manager.broadcast(
         {
@@ -3260,17 +3264,20 @@ async def create_spool_from_slot(
     if not is_valid_tag(tray.get("tag_uid", ""), tray.get("tray_uuid", "")):
         raise HTTPException(status_code=400, detail="Slot has no RFID tag")
 
-    spool = await create_spool_from_tray(db, tray)
-    await auto_assign_spool(
-        req.printer_id,
-        req.ams_id,
-        req.tray_id,
-        spool,
-        printer_manager,
-        db,
-        tray_info_idx=tray.get("tray_info_idx", ""),
-    )
-    await db.commit()
+    # Under the slot lock from the first write: on SQLite the spool insert takes
+    # the write lock, which an AMS update holding the slot lock would wait for.
+    async with get_ams_assignment_lock(req.printer_id):
+        spool = await create_spool_from_tray(db, tray)
+        await auto_assign_spool(
+            req.printer_id,
+            req.ams_id,
+            req.tray_id,
+            spool,
+            printer_manager,
+            db,
+            tray_info_idx=tray.get("tray_info_idx", ""),
+        )
+        await db.commit()
     await ws_manager.broadcast({"type": "inventory_changed"})
     await ws_manager.broadcast(
         {

+ 31 - 42
backend/app/main.py

@@ -11,6 +11,7 @@ from contextlib import asynccontextmanager
 from datetime import datetime, timedelta, timezone
 from logging.handlers import RotatingFileHandler
 from pathlib import Path, PurePosixPath
+from typing import cast
 from urllib.parse import urlparse
 
 from fastapi import FastAPI
@@ -18,7 +19,8 @@ from fastapi.encoders import jsonable_encoder
 from fastapi.exceptions import RequestValidationError
 from fastapi.responses import FileResponse, JSONResponse
 from fastapi.staticfiles import StaticFiles
-from sqlalchemy import delete, inspect as sa_inspect, or_, select, text, update
+from sqlalchemy import delete, func, inspect as sa_inspect, or_, select, text, update
+from sqlalchemy.engine import CursorResult
 from sqlalchemy.exc import IntegrityError
 from sqlalchemy.orm.exc import StaleDataError
 
@@ -101,6 +103,7 @@ from backend.app.core.static_assets import AssetStaticFiles
 from backend.app.core.tasks import spawn_background_task
 from backend.app.core.websocket import ws_manager
 from backend.app.services import kprofile_drift, print_dispatch_context, slot_unlink_grace
+from backend.app.services.ams_assignment_lock import get_ams_assignment_lock
 from backend.app.services.archive import ArchiveService, peek_plate_index_in_3mf, swap_plate_suffix
 from backend.app.services.archive_cost_estimate import (
     schedule_archive_cost_estimate as _schedule_archive_cost_estimate,
@@ -706,35 +709,6 @@ def derive_failure_reason(status: str, hms_errors: list[dict] | None) -> str | N
 # {(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
-
-
 # Per-printer dedup for unknown_tag WS broadcasts. Keyed by
 # (ams_id, tray_id) -> (tag_uid, tray_uuid); we only re-broadcast when the
 # tag tuple changes for the slot. Cleared when the slot is reported empty
@@ -2453,7 +2427,7 @@ async def _unlink_stale_assignments(printer_id: int, ams_data: list, printing_no
     # per-printer assignment lock since #3186: the held-removal re-check runs
     # this outside any MQTT push, so it can now overlap one.
     try:
-        async with _get_ams_assignment_lock(printer_id), async_session() as db:
+        async with get_ams_assignment_lock(printer_id), async_session() as db:
             from sqlalchemy.orm import selectinload
 
             from backend.app.api.routes.inventory import _find_tray_in_ams_data
@@ -2979,14 +2953,14 @@ async def on_ams_change(printer_id: int, ams_data: list):
     await _unlink_stale_assignments(printer_id, ams_data, printing_now)
 
     # Auto-manage inventory spools from AMS tray data (skip if Spoolman manages AMS).
-    # Serialised per-printer via _ams_assignment_locks: MQTT bursts can deliver
+    # Serialised per-printer via services/ams_assignment_lock: 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.
+    # bug stayed latent there. See services/ams_assignment_lock for details.
     try:
-        async with _get_ams_assignment_lock(printer_id), async_session() as db:
+        async with get_ams_assignment_lock(printer_id), async_session() as db:
             from sqlalchemy.orm import selectinload
 
             from backend.app.api.routes.settings import get_setting
@@ -3055,16 +3029,31 @@ async def on_ams_change(printer_id: int, ams_data: list):
                                     new_used = round(lw * (100 - remain_val) / 100.0, 1)
                                     current_used = existing_assignment.spool.weight_used or 0
                                     if new_used > current_used + 1:
-                                        logger.info(
-                                            "Weight sync: spool %d weight_used %s -> %s (remain=%d)",
-                                            existing_assignment.spool_id,
-                                            current_used,
-                                            new_used,
-                                            remain_val,
+                                        # Rechecked in the statement: the spool was loaded
+                                        # before this, and a weight set by hand (or weighed)
+                                        # and locked since then must stay (WL-6).
+                                        result = cast(
+                                            CursorResult,
+                                            await db.execute(
+                                                update(Spool)
+                                                .where(
+                                                    Spool.id == existing_assignment.spool_id,
+                                                    Spool.weight_locked.is_not(True),
+                                                    func.coalesce(Spool.weight_used, 0) < new_used - 1,
+                                                )
+                                                .values(weight_used=new_used)
+                                            ),
                                         )
-                                        existing_assignment.spool.weight_used = new_used
                                         await db.commit()
-                                        await ws_manager.broadcast({"type": "inventory_changed"})
+                                        if result.rowcount:
+                                            logger.info(
+                                                "Weight sync: spool %d weight_used %s -> %s (remain=%d)",
+                                                existing_assignment.spool_id,
+                                                current_used,
+                                                new_used,
+                                                remain_val,
+                                            )
+                                            await ws_manager.broadcast({"type": "inventory_changed"})
 
                             # A K-profile the slot lost (the default K after a reset or
                             # power cycle) is put back by kprofile_drift on the next idle

+ 38 - 0
backend/app/services/ams_assignment_lock.py

@@ -0,0 +1,38 @@
+"""Per-printer lock for writes to a printer's spool assignments (AMS slots).
+
+on_ams_change serialises its spool-assignment side (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).
+
+The assign, unassign and create-from-slot routes write the same rows and take
+the same lock (SA-5), before their first write: on SQLite a session that
+already holds the write lock would otherwise wait here on an AMS update that
+waits for that write lock.
+
+Scope is intentionally narrow: only the DB-mutating blocks are inside the lock.
+The Spoolman sync block in on_ams_change stays concurrent because it's
+network-bound and idempotent.
+"""
+
+import asyncio
+
+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

+ 35 - 7
backend/app/services/usage_tracker.py

@@ -14,7 +14,7 @@ import re
 from dataclasses import dataclass, field
 from datetime import datetime, timezone
 
-from sqlalchemy import select
+from sqlalchemy import func, select, update
 from sqlalchemy.ext.asyncio import AsyncSession
 
 from backend.app.models.spool import Spool
@@ -297,6 +297,34 @@ def _tray_map_from_json(mapping: dict | None) -> dict[tuple[int, int], int]:
     return result
 
 
+async def _charge_spool(db: AsyncSession, spool: Spool, grams: float) -> bool:
+    """Add *grams* to the spool's usage in the database itself (WU-4).
+
+    The spool was loaded several awaits earlier; a weight set by hand or
+    weighed on the scale since then would be lost to a write of the value
+    computed from that copy. The loaded copy is set to the stored result: from
+    this statement until the commit, the transaction holds the row (the write
+    lock on SQLite), so writing it back on flush changes nothing.
+
+    False when the spool was deleted meanwhile: the caller skips it, since a
+    usage row for it would break its foreign key on PostgreSQL and roll back
+    the whole completion.
+    """
+    now = datetime.now(timezone.utc)
+    stored = await db.scalar(
+        update(Spool)
+        .where(Spool.id == spool.id)
+        .values(weight_used=func.coalesce(Spool.weight_used, 0) + grams, last_used=now)
+        .returning(Spool.weight_used)
+        .execution_options(synchronize_session=False)
+    )
+    if stored is None:
+        return False
+    spool.weight_used = stored
+    spool.last_used = now
+    return True
+
+
 async def persist_session(
     db: AsyncSession,
     session: PrintSession,
@@ -926,8 +954,8 @@ async def on_print_complete(
                 weight_grams = (delta_pct / 100.0) * spool.label_weight
 
                 # Update spool
-                spool.weight_used = (spool.weight_used or 0) + weight_grams
-                spool.last_used = datetime.now(timezone.utc)
+                if not await _charge_spool(db, spool, weight_grams):
+                    continue
 
                 # Calculate cost for this usage
                 cost = None
@@ -1753,8 +1781,8 @@ async def _track_from_3mf(
                 if not spool:
                     continue
 
-                spool.weight_used = (spool.weight_used or 0) + segment_grams
-                spool.last_used = datetime.now(timezone.utc)
+                if not await _charge_spool(db, spool, segment_grams):
+                    continue
 
                 percent = round(segment_grams / (spool.label_weight or 1000) * 100)
 
@@ -1925,8 +1953,8 @@ async def _track_from_3mf(
             continue
 
         # Update spool
-        spool.weight_used = (spool.weight_used or 0) + weight_grams
-        spool.last_used = datetime.now(timezone.utc)
+        if not await _charge_spool(db, spool, weight_grams):
+            continue
 
         percent = round(weight_grams / (spool.label_weight or 1000) * 100)
 

+ 47 - 3
backend/tests/integration/test_ams_remain_sync_while_printing.py

@@ -9,13 +9,20 @@ stale persisted session never registers.
 from unittest.mock import AsyncMock, MagicMock, patch
 
 import pytest
+from sqlalchemy import event
 from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
+from sqlalchemy.orm.attributes import set_committed_value
 
 from backend.app.models.spool import Spool
 from backend.app.models.spool_assignment import SpoolAssignment
 from backend.app.services.usage_tracker import _active_sessions
 
 
+def _loaded_before_the_hand_edit(spool, _context):
+    set_committed_value(spool, "weight_locked", False)
+    set_committed_value(spool, "weight_used", 100)
+
+
 @pytest.fixture(autouse=True)
 def _no_sessions():
     _active_sessions.clear()
@@ -24,12 +31,22 @@ def _no_sessions():
 
 
 async def _weight_after_ams_push(
-    test_engine, db_session, printer_factory, state: str, sent: list[str] | None = None
+    test_engine,
+    db_session,
+    printer_factory,
+    state: str,
+    sent: list[str] | None = None,
+    *,
+    weight_used: float = 100,
+    weight_locked: bool = False,
+    loaded_as_unlocked: bool = False,
 ) -> float:
+    """``loaded_as_unlocked``: the sync loads the spool unlocked at 100 g, as
+    it was before a hand edit that committed right after that load."""
     from backend.app.main import on_ams_change
 
     printer = await printer_factory(name="X1C")
-    spool = Spool(material="PLA", label_weight=1000, weight_used=100)
+    spool = Spool(material="PLA", label_weight=1000, weight_used=weight_used, weight_locked=weight_locked)
     db_session.add(spool)
     await db_session.flush()
     db_session.add(
@@ -67,7 +84,13 @@ async def _weight_after_ams_push(
         mock_ws.send_printer_status = AsyncMock()
         mock_ws.broadcast = AsyncMock()
 
-        await on_ams_change(printer.id, ams_data)
+        if loaded_as_unlocked:
+            event.listen(Spool, "load", _loaded_before_the_hand_edit)
+        try:
+            await on_ams_change(printer.id, ams_data)
+        finally:
+            if loaded_as_unlocked:
+                event.remove(Spool, "load", _loaded_before_the_hand_edit)
 
     if sent is not None:
         sent.extend(c.args[0]["type"] for c in mock_ws.broadcast.call_args_list)
@@ -97,3 +120,24 @@ async def test_a_synced_weight_is_announced(test_engine, db_session, printer_fac
 
     assert await _weight_after_ams_push(test_engine, db_session, printer_factory, "IDLE", sent) == 500
     assert "inventory_changed" in sent
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_a_weight_set_by_hand_meanwhile_is_kept(test_engine, db_session, printer_factory):
+    """WL-6: the sync decided on the spool as it had loaded it. A weight set by
+    hand (and so locked) after that load was overwritten, with the lock left set."""
+    sent: list[str] = []
+    weight = await _weight_after_ams_push(
+        test_engine,
+        db_session,
+        printer_factory,
+        "IDLE",
+        sent,
+        weight_used=300,
+        weight_locked=True,
+        loaded_as_unlocked=True,
+    )
+
+    assert weight == 300
+    assert "inventory_changed" not in sent, "nothing changed, so nothing to announce"

+ 107 - 0
backend/tests/integration/test_assignment_routes_take_the_slot_lock.py

@@ -0,0 +1,107 @@
+"""Spool assignments made by hand wait for the printer's assignment lock (SA-5).
+
+The AMS change handler writes a printer's slot assignments under a per-printer
+lock, so two of its updates can't both find a slot free and both insert. The
+assign, unassign and create-from-slot routes wrote the same rows without it: a
+manual assign racing an AMS update (or a double-click) on PostgreSQL failed
+with a 500 on the unique (printer, AMS, tray) constraint, or on a row the other
+writer had just deleted.
+"""
+
+import asyncio
+from types import SimpleNamespace
+from unittest.mock import AsyncMock, MagicMock, patch
+
+import pytest
+from sqlalchemy import select
+
+from backend.app.models.spool import Spool
+from backend.app.models.spool_assignment import SpoolAssignment
+from backend.app.services.ams_assignment_lock import ams_assignment_locks, get_ams_assignment_lock
+
+pytestmark = [pytest.mark.asyncio, pytest.mark.integration]
+
+
+@pytest.fixture(autouse=True)
+def _fresh_locks():
+    """A contended lock binds to its test's event loop; printer ids repeat."""
+    ams_assignment_locks.clear()
+    yield
+    ams_assignment_locks.clear()
+
+
+TRAY = {"id": 0, "tray_type": "PLA", "tray_color": "FF0000FF", "tag_uid": "A1B2C3D4E5F60708", "state": 11}
+
+
+async def _waits_for_the_lock(printer_id: int, request) -> object:
+    """Run *request* while the lock is held: it must not finish until released."""
+    lock = get_ams_assignment_lock(printer_id)
+    await lock.acquire()
+    try:
+        task = asyncio.ensure_future(request)
+        await asyncio.sleep(0.3)
+        assert not task.done(), "the route wrote the slot without waiting for the lock"
+    finally:
+        lock.release()
+    return await asyncio.wait_for(task, 10)
+
+
+@pytest.fixture
+def printer_status():
+    status = SimpleNamespace(raw_data={"ams": [{"id": 0, "tray": [TRAY]}]}, state="IDLE", connected=True)
+    with (
+        patch("backend.app.services.printer_manager.printer_manager.get_status", MagicMock(return_value=status)),
+        patch("backend.app.services.printer_manager.printer_manager.get_client", MagicMock(return_value=None)),
+        patch("backend.app.api.routes.inventory.ws_manager") as ws,
+    ):
+        ws.broadcast = AsyncMock()
+        yield
+
+
+async def _spool(db_session) -> Spool:
+    spool = Spool(material="PLA", label_weight=1000, weight_used=0)
+    db_session.add(spool)
+    await db_session.commit()
+    return spool
+
+
+async def test_assigning(async_client, db_session, printer_factory, printer_status):
+    printer = await printer_factory()
+    spool = await _spool(db_session)
+
+    response = await _waits_for_the_lock(
+        printer.id,
+        async_client.post(
+            "/api/v1/inventory/assignments",
+            json={"spool_id": spool.id, "printer_id": printer.id, "ams_id": 0, "tray_id": 0},
+        ),
+    )
+
+    assert response.status_code == 200, response.text
+
+
+async def test_unassigning(async_client, db_session, printer_factory, printer_status):
+    printer = await printer_factory()
+    spool = await _spool(db_session)
+    db_session.add(SpoolAssignment(spool_id=spool.id, printer_id=printer.id, ams_id=0, tray_id=0))
+    await db_session.commit()
+
+    response = await _waits_for_the_lock(
+        printer.id, async_client.delete(f"/api/v1/inventory/assignments/{printer.id}/0/0")
+    )
+
+    assert response.status_code == 200, response.text
+    assert (await db_session.execute(select(SpoolAssignment))).scalars().first() is None
+
+
+async def test_creating_a_spool_from_a_slot(async_client, db_session, printer_factory, printer_status):
+    printer = await printer_factory()
+
+    response = await _waits_for_the_lock(
+        printer.id,
+        async_client.post(
+            "/api/v1/inventory/spools/from-slot", json={"printer_id": printer.id, "ams_id": 0, "tray_id": 0}
+        ),
+    )
+
+    assert response.status_code == 200, response.text

+ 15 - 0
backend/tests/unit/services/test_usage_tracker.py

@@ -20,6 +20,21 @@ from backend.app.services.usage_tracker import (
 )
 
 
+async def _charge_in_memory(_db, spool, grams):
+    """The fake session has no database for the tracker's UPDATE: add the
+    grams to the mock spool, which is what these tests check. The statement
+    itself is tested against a real database in test_usage_tracker_charge_race."""
+    spool.weight_used = (spool.weight_used or 0) + grams
+    spool.last_used = datetime.now(timezone.utc)
+    return True
+
+
+@pytest.fixture(autouse=True)
+def _charge_spools_in_memory():
+    with patch("backend.app.services.usage_tracker._charge_spool", _charge_in_memory):
+        yield
+
+
 def _make_spool(*, id=1, label_weight=1000, weight_used=0, tag_uid=None, tray_uuid=None, rgba=None):
     """Create a mock Spool object."""
     spool = MagicMock()

+ 14 - 14
backend/tests/unit/test_ams_assignment_lock.py

@@ -1,4 +1,4 @@
-"""Regression tests for ``_ams_assignment_locks`` (per-printer serialisation
+"""Regression tests for ``ams_assignment_locks`` (per-printer serialisation
 of ``on_ams_change``'s spool-assignment block).
 
 Background
@@ -31,7 +31,7 @@ import asyncio
 
 import pytest
 
-from backend.app.main import _ams_assignment_locks, _get_ams_assignment_lock
+from backend.app.services.ams_assignment_lock import ams_assignment_locks, get_ams_assignment_lock
 
 
 @pytest.fixture(autouse=True)
@@ -40,28 +40,28 @@ def _isolate_locks_dict():
     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()
+    saved = dict(ams_assignment_locks)
+    ams_assignment_locks.clear()
     try:
         yield
     finally:
-        _ams_assignment_locks.clear()
-        _ams_assignment_locks.update(saved)
+        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)
+        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)
+        a = get_ams_assignment_lock(7)
+        b = get_ams_assignment_lock(8)
         assert a is not b
 
 
@@ -77,7 +77,7 @@ class TestLockSerialisesConcurrentCallbacks:
         first_release = asyncio.Event()
 
         async def first():
-            async with _get_ams_assignment_lock(printer_id):
+            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
@@ -88,7 +88,7 @@ class TestLockSerialisesConcurrentCallbacks:
 
         async def second():
             await first_inside.wait()  # ensure first holds the lock
-            async with _get_ams_assignment_lock(printer_id):
+            async with get_ams_assignment_lock(printer_id):
                 order.append("second-enter")
 
         task_a = asyncio.create_task(first())
@@ -118,7 +118,7 @@ class TestLockSerialisesConcurrentCallbacks:
         printer_a_release = asyncio.Event()
 
         async def printer_a():
-            async with _get_ams_assignment_lock(1):
+            async with get_ams_assignment_lock(1):
                 order.append("a-enter")
                 printer_a_inside.set()
                 await printer_a_release.wait()
@@ -126,7 +126,7 @@ class TestLockSerialisesConcurrentCallbacks:
 
         async def printer_b():
             await printer_a_inside.wait()
-            async with _get_ams_assignment_lock(2):
+            async with get_ams_assignment_lock(2):
                 order.append("b-enter-and-exit")
 
         task_a = asyncio.create_task(printer_a())

+ 15 - 0
backend/tests/unit/test_shared_tray_usage_3230.py

@@ -21,6 +21,21 @@ from backend.app.services.usage_tracker import _track_from_3mf
 pytestmark = pytest.mark.unit
 
 
+async def _charge_in_memory(_db, spool, grams):
+    """The fake session has no database for the tracker's UPDATE: add the
+    grams to the mock spool, which is what these tests check. The statement
+    itself is tested against a real database in test_usage_tracker_charge_race."""
+    spool.weight_used = (spool.weight_used or 0) + grams
+    spool.last_used = datetime.now(timezone.utc)
+    return True
+
+
+@pytest.fixture(autouse=True)
+def _charge_spools_in_memory():
+    with patch("backend.app.services.usage_tracker._charge_spool", _charge_in_memory):
+        yield
+
+
 def _spool(spool_id: int):
     spool = MagicMock()
     spool.id = spool_id

+ 3 - 2
backend/tests/unit/test_state_writers.py

@@ -34,8 +34,9 @@ GUARDED_FIELDS = [
             ("backend/app/main.py", "on_ams_change"): "AMS remain% sync while idle",
             ("backend/app/api/routes/inventory.py", "sync_weights_from_ams"): "manual Sync AMS weights",
             ("backend/app/api/routes/spoolbuddy.py", "update_spool_weight"): "SpoolBuddy scale reading",
-            ("backend/app/services/usage_tracker.py", "on_print_complete"): "AMS remain% delta fallback",
-            ("backend/app/services/usage_tracker.py", "_track_from_3mf"): "3MF per-filament usage",
+            ("backend/app/services/usage_tracker.py", "_charge_spool"): (
+                "a print's usage (3MF, 3MF split, AMS remain% delta), added in SQL"
+            ),
             ("backend/app/services/spool_tag_matcher.py", "create_spool_from_tray"): "new spool from an RFID tray",
             ("backend/app/core/database.py", "_migrate_repair_rfid_core_weight"): "one-shot #2909 backfill",
             ("backend/app/api/routes/inventory.py", "create_spool"): "Spool(**payload) from the add form",

+ 231 - 0
backend/tests/unit/test_usage_tracker_charge_race.py

@@ -0,0 +1,231 @@
+"""The tracker adds a print's usage to what is stored, not to its own copy (WU-4).
+
+Completion loads the spool, awaits more lookups, and only then charges it. A
+weight set by hand or weighed on the SpoolBuddy scale in between was lost:
+the tracker wrote back its earlier copy plus the print's grams. Each test
+stores 300 g used (the hand edit) while the tracker's copy still reads the
+100 g it loaded before that edit.
+"""
+
+from datetime import datetime, timezone
+from types import SimpleNamespace
+from unittest.mock import AsyncMock, MagicMock, patch
+
+import pytest
+from sqlalchemy import event, select
+from sqlalchemy.ext.asyncio import AsyncSession, async_sessionmaker
+from sqlalchemy.orm.attributes import set_committed_value
+
+from backend.app.models.spool import Spool
+from backend.app.services.usage_tracker import (
+    PrintSession,
+    _active_sessions,
+    _charge_spool,
+    _track_from_3mf,
+    on_print_complete,
+)
+
+pytestmark = pytest.mark.asyncio
+
+HAND_SET = 300.0
+
+
+def _loaded_before_the_hand_edit(spool, _context):
+    set_committed_value(spool, "weight_used", 100.0)
+
+
+@pytest.fixture
+def stale_loads():
+    event.listen(Spool, "load", _loaded_before_the_hand_edit)
+    yield
+    event.remove(Spool, "load", _loaded_before_the_hand_edit)
+
+
+@pytest.fixture
+async def maker(test_engine):
+    return async_sessionmaker(test_engine, class_=AsyncSession, expire_on_commit=False)
+
+
+async def _spools(maker, count: int = 1) -> list[int]:
+    async with maker() as db:
+        rows = [Spool(material="PLA", label_weight=1000, weight_used=HAND_SET) for _ in range(count)]
+        db.add_all(rows)
+        await db.commit()
+        return [row.id for row in rows]
+
+
+async def _printer(maker) -> int:
+    from backend.app.models.printer import Printer
+
+    async with maker() as db:
+        printer = Printer(name="P", serial_number="RACE01", ip_address="10.0.0.9", access_code="12345678")
+        db.add(printer)
+        await db.commit()
+        return printer.id
+
+
+async def _stored(maker, spool_id: int) -> float:
+    """Read as a column, so the stale-load hook does not touch it."""
+    async with maker() as db:
+        return await db.scalar(select(Spool.weight_used).where(Spool.id == spool_id))
+
+
+async def test_the_charge_adds_to_the_stored_weight(maker, stale_loads):
+    (spool_id,) = await _spools(maker)
+
+    async with maker() as db:
+        spool = await db.get(Spool, spool_id)
+        assert spool.weight_used == 100.0, "the copy is the stale one"
+        await _charge_spool(db, spool, 25.0)
+        assert spool.weight_used == HAND_SET + 25.0, "the copy follows what is stored"
+        await db.commit()
+
+    assert await _stored(maker, spool_id) == HAND_SET + 25.0
+
+
+async def test_a_spool_deleted_meanwhile_is_left_alone(maker):
+    (spool_id,) = await _spools(maker)
+
+    async with maker() as db:
+        spool = await db.get(Spool, spool_id)
+        async with maker() as other:
+            await other.delete(await other.get(Spool, spool_id))
+            await other.commit()
+        assert await _charge_spool(db, spool, 25.0) is False
+        await db.commit()
+
+
+async def _track_3mf(
+    maker, tmp_path, spool_ids: dict[tuple[int, int], int], slots: int = 1, mapping=(0,), **state
+) -> None:
+    printer_id = await _printer(maker)
+    threemf = tmp_path / "part.3mf"
+    threemf.write_bytes(b"3mf")
+    status = SimpleNamespace(
+        progress=100, layer_num=90, tray_now=0, last_loaded_tray=-1, raw_data={}, **{"total_layers": 0, **state}
+    )
+    printer_manager = MagicMock()
+    printer_manager.get_status.return_value = status
+
+    async def resolve(printer_id, ams_id, tray_id, **kwargs):
+        return spool_ids.get((ams_id, tray_id))
+
+    usage = [{"slot_id": n, "used_g": 9.0, "type": "PLA", "color": "#FFFFFF"} for n in range(1, slots + 1)]
+    with (
+        patch("backend.app.utils.threemf_tools.extract_filament_usage_from_3mf", return_value=usage),
+        patch("backend.app.utils.threemf_tools.extract_layer_filament_usage_from_3mf", return_value=None),
+        patch("backend.app.utils.threemf_tools.extract_filament_properties_from_3mf", return_value={}),
+        patch("backend.app.services.usage_tracker._resolve_spool_id_for_tray", side_effect=resolve),
+    ):
+        async with maker() as db:
+            await _track_from_3mf(
+                printer_id=printer_id,
+                archive_id=None,
+                status="completed",
+                print_name="part",
+                handled_trays=set(),
+                printer_manager=printer_manager,
+                db=db,
+                ams_mapping=list(mapping),
+                print_started_at=datetime.now(timezone.utc),
+                threemf_path=threemf,
+            )
+            await db.commit()
+
+
+async def test_the_3mf_charge(maker, tmp_path, stale_loads):
+    (spool_id,) = await _spools(maker)
+
+    await _track_3mf(maker, tmp_path, {(0, 0): spool_id}, tray_change_log=[])
+
+    assert await _stored(maker, spool_id) == HAND_SET + 9.0
+
+
+async def test_the_3mf_charge_split_across_trays(maker, tmp_path, stale_loads):
+    first, second = await _spools(maker, 2)
+
+    await _track_3mf(
+        maker, tmp_path, {(0, 0): first, (0, 1): second}, tray_change_log=[(0, 0), (1, 45)], total_layers=90
+    )
+
+    assert (await _stored(maker, first), await _stored(maker, second)) == (HAND_SET + 4.5, HAND_SET + 4.5)
+
+
+@pytest.mark.parametrize("deleted", [False, True], ids=["charged", "deleted-meanwhile"])
+async def test_the_remain_percentage_charge(maker, stale_loads, deleted):
+    from backend.app.models.spool_assignment import SpoolAssignment
+
+    (spool_id,) = await _spools(maker)
+    printer_id = await _printer(maker)
+    async with maker() as db:
+        db.add(SpoolAssignment(spool_id=spool_id, printer_id=printer_id, ams_id=0, tray_id=0))
+        await db.commit()
+
+    # 80% -> 70% of a 1000 g spool: 100 g.
+    _active_sessions[printer_id] = PrintSession(
+        printer_id=printer_id, print_name="part", started_at=datetime.now(timezone.utc), tray_remain_start={(0, 0): 80}
+    )
+    status = SimpleNamespace(
+        raw_data={"ams": [{"id": 0, "tray": [{"id": 0, "remain": 70}]}]}, progress=100, layer_num=0, tray_now=255
+    )
+    printer_manager = MagicMock()
+    printer_manager.get_status.return_value = status
+    try:
+        with (
+            patch("backend.app.api.routes.settings.get_setting", new_callable=AsyncMock, return_value=None),
+            patch("backend.app.services.usage_tracker._track_from_3mf", AsyncMock(return_value=[])),
+            patch(
+                "backend.app.services.usage_tracker._charge_spool",
+                _deleting(maker, spool_id if deleted else -1),
+            ),
+        ):
+            async with maker() as db:
+                await on_print_complete(printer_id, {"status": "completed"}, printer_manager, db)
+    finally:
+        _active_sessions.pop(printer_id, None)
+
+    if deleted:
+        assert await _charged(maker) == []
+    else:
+        assert await _stored(maker, spool_id) == HAND_SET + 100.0
+
+
+@pytest.mark.parametrize("split", [True, False], ids=["split-across-trays", "one-tray-per-slot"])
+async def test_a_spool_deleted_while_the_print_is_charged_is_skipped(maker, tmp_path, split):
+    """The rest of the print is still charged: a usage row for the deleted spool
+    broke the foreign key on PostgreSQL and rolled the whole completion back."""
+    first, second = await _spools(maker, 2)
+
+    with patch("backend.app.services.usage_tracker._charge_spool", _deleting(maker, first)):
+        if split:
+            await _track_3mf(
+                maker, tmp_path, {(0, 0): first, (0, 1): second}, tray_change_log=[(0, 0), (1, 45)], total_layers=90
+            )
+        else:
+            await _track_3mf(maker, tmp_path, {(0, 0): first, (0, 1): second}, slots=2, mapping=(0, 1))
+
+    assert await _stored(maker, second) == HAND_SET + (4.5 if split else 9.0)
+    assert await _charged(maker) == [second]
+
+
+def _deleting(maker, spool_id: int):
+    """_charge_spool, with *spool_id* deleted by someone else just before."""
+    from backend.app.services import usage_tracker
+
+    real_charge = usage_tracker._charge_spool
+
+    async def charge(db, spool, grams):
+        if spool.id == spool_id:
+            async with maker() as other:
+                await other.delete(await other.get(Spool, spool_id))
+                await other.commit()
+        return await real_charge(db, spool, grams)
+
+    return charge
+
+
+async def _charged(maker) -> list[int]:
+    from backend.app.models.spool_usage_history import SpoolUsageHistory
+
+    async with maker() as db:
+        return list((await db.execute(select(SpoolUsageHistory.spool_id))).scalars().all())