fix(inventory): a finished print is not charged a second time by an AMS update while its usage is booked; a completion reported without any file name closes the print session instead of keeping the AMS weight sync off until the next print

CHANGELOG.md

@@ -164,6 +164,9 @@ 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 finished print's filament is charged once** — Two cases in the built-in inventory:
+  - **An AMS update right as a print finished** could raise the spool's used weight from the AMS remain% while the print's exact usage was still being worked out, and that usage was then added on top: the print was charged twice. The AMS sync now waits until the print is charged, as it does while the print runs.
+  - **A print the printer reported finished without any file name** (one that failed while preparing, right after Bambuddy started) kept the AMS weight sync off until the next print started. It now turns the sync back on.
 - **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.

backend/app/api/routes/inventory.py

@@ -2828,7 +2828,7 @@ async def sync_weights_from_ams(
     when it completes, on top of whatever weight the spool has by then.
     """
     from backend.app.services.printer_manager import PrinterManager, printer_manager
-    from backend.app.services.usage_tracker import _active_sessions
+    from backend.app.services.usage_tracker import printer_is_charging
 
     result = await db.execute(select(SpoolAssignment).options(selectinload(SpoolAssignment.spool)))
     # Only slots on printers the caller may see (#1727)
@@ -2857,12 +2857,10 @@ async def sync_weights_from_ams(
             skipped += 1
             continue
 
-        # Until completion has charged the print its session stays open, also
-        # after the printer has reported the print finished.
-        if (
-            str(getattr(state, "state", "") or "").upper() in PrinterManager.ACTIVE_PRINT_STATES
-            or assignment.printer_id in _active_sessions
-        ):
+        # Until completion has charged the print the printer counts as printing,
+        # also after it has reported the print finished.
+        printer_state = str(getattr(state, "state", "") or "").upper()
+        if printer_state in PrinterManager.ACTIVE_PRINT_STATES or printer_is_charging(assignment.printer_id):
             logger.info("AMS weight sync: printer %d is printing, skipping spool %d", assignment.printer_id, spool.id)
             skipped += 1
             printing += 1

backend/app/main.py

@@ -2906,11 +2906,12 @@ async def on_ams_change(printer_id: int, ams_data: list):
     """Handle AMS data changes - sync to Spoolman if enabled and auto mode."""
     logger = logging.getLogger(__name__)
 
-    # Snapshot BEFORE any await: if a print is active, skip weight sync later.
-    # on_print_complete may pop _active_sessions during our awaits (#880).
-    from backend.app.services.usage_tracker import _active_sessions
+    # Snapshot BEFORE any await: if a print is active, or a finished one is
+    # still being charged, skip weight sync later. on_print_complete may pop
+    # _active_sessions during our awaits (#880).
+    from backend.app.services.usage_tracker import printer_is_charging
 
-    _print_active = printer_id in _active_sessions
+    _print_active = printer_is_charging(printer_id)
 
     # A slot that reports empty while a print is running is a filament runout,
     # not a spool swap: the spool is still physically in the AMS, just
@@ -8012,7 +8013,22 @@ async def _cleanup_sd_card_after_print(
 
 
 async def on_print_complete(printer_id: int, data: dict):
-    """Handle print completion - update the archive status."""
+    """Handle print completion - update the archive status.
+
+    The printer counts as printing until the print's usage is booked (or this
+    ends), so the AMS remain% weight sync can't charge it a second time while
+    the usage tracker works (WU-3). Marked before the first await.
+    """
+    from backend.app.services.usage_tracker import done_completing, mark_completing
+
+    mark_completing(printer_id)
+    try:
+        await _close_out_print(printer_id, data)
+    finally:
+        done_completing(printer_id)
+
+
+async def _close_out_print(printer_id: int, data: dict):
     import time
 
     logger = logging.getLogger(__name__)
@@ -8121,7 +8137,19 @@ async def on_print_complete(printer_id: int, data: dict):
     subtask_name = data.get("subtask_name", "")
 
     if not filename and not subtask_name:
+        # Which print ended can't be told: the printer reported no name since
+        # Bambuddy started (a print that failed while preparing, a calibration).
+        # Charge nothing, but close the print session, which otherwise kept the
+        # AMS weight sync off until the next print (AS-5). A print archived as
+        # running is closed and charged by the reconnect reconcile.
         logger.warning("Print complete without filename or subtask_name")
+        try:
+            from backend.app.services.usage_tracker import discard_session
+
+            async with async_session() as db:
+                await discard_session(db, printer_id)
+        except Exception as e:
+            logger.warning("Failed to clear print session for printer %s: %s", printer_id, e)
         return
 
     logger.info("Print complete - filename: %s, subtask: %s, status: %s", filename, subtask_name, data.get("status"))

backend/app/services/usage_tracker.py

@@ -268,6 +268,30 @@ class PrintSession:
 # context — see ``persist_session`` / ``restore_session``.
 _active_sessions: dict[int, PrintSession] = {}
 
+# Printers whose finished print is being closed out. on_print_complete takes the
+# session first and charges the usage several awaits later; the printer already
+# reports FINISH, so without this mark the AMS remain% weight sync would run in
+# between and the print would be charged twice (WU-3).
+_completing: set[int] = set()
+
+
+def mark_completing(printer_id: int) -> None:
+    """The completion path's first step: hold the weight sync off until the
+    usage is booked (discard_session) or the completion ends."""
+    _completing.add(printer_id)
+
+
+def done_completing(printer_id: int) -> None:
+    _completing.discard(printer_id)
+
+
+def printer_is_charging(printer_id: int) -> bool:
+    """A print's usage is still to be charged: it runs, or it ended and its
+    completion has not booked it yet. The AMS remain% sync leaves the
+    printer's spools alone meanwhile (#880)."""
+    return printer_id in _active_sessions or printer_id in _completing
+
+
 # Serialises the read-modify-write on the persisted tray-change log, per printer.
 _tray_change_locks: dict[int, asyncio.Lock] = {}
 
@@ -450,6 +474,7 @@ async def clear_persisted_session(db: AsyncSession, printer_id: int) -> None:
 def forget_printer(printer_id: int) -> None:
     """A deleted printer's print-start context in memory (the row goes with the printer)."""
     _active_sessions.pop(printer_id, None)
+    _completing.discard(printer_id)
     _tray_change_locks.pop(printer_id, None)
 
 
@@ -461,6 +486,7 @@ async def discard_session(db: AsyncSession, printer_id: int) -> None:
     the internal tracker's ``on_print_complete`` consumes (and pops) it.
     """
     _active_sessions.pop(printer_id, None)
+    _completing.discard(printer_id)
     _tray_change_locks.pop(printer_id, None)
     await clear_persisted_session(db, printer_id)
 
@@ -550,6 +576,8 @@ async def on_print_start(
     (#880); registering a session the internal tracker will never complete
     would suppress a sync those users still need.
     """
+    # A new print: whatever the last completion left marked is over.
+    _completing.discard(printer_id)
     state = printer_manager.get_status(printer_id)
     if not state or not state.raw_data:
         logger.debug("[UsageTracker] No state for printer %d, skipping", printer_id)

backend/tests/integration/test_ams_remain_sync_while_printing.py

@@ -141,3 +141,14 @@ async def test_a_weight_set_by_hand_meanwhile_is_kept(test_engine, db_session, p
 
     assert weight == 300
     assert "inventory_changed" not in sent, "nothing changed, so nothing to announce"
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_no_sync_while_a_finished_print_is_being_charged(test_engine, db_session, printer_factory):
+    """WU-3: the printer reports FINISH and the tracker has taken the session,
+    but the usage is not booked yet."""
+    with patch("backend.app.services.usage_tracker.printer_is_charging", lambda printer_id: True):
+        weight = await _weight_after_ams_push(test_engine, db_session, printer_factory, "FINISH")
+
+    assert weight == 100

backend/tests/integration/test_completion_keeps_printer_charging.py

@@ -0,0 +1,129 @@
+"""A printer counts as printing until its finished print's usage is booked (WU-3, AS-5).
+
+The AMS remain% weight sync stays off while a print runs, because completion
+charges the print exactly from its 3MF (#880). The tracker takes the print's
+session first and only then works out and charges the usage, several awaits
+later. The printer already reports FINISH, so an AMS update in that window
+raised the spool's weight from remain% and the tracker then added the print
+on top: charged twice.
+
+A completion with neither file name nor subtask name returned before any of
+this, leaving the session open, which kept the weight sync off until the next
+print. It now closes the session; it charges nothing, having no print to
+charge (AS-5).
+"""
+
+from datetime import datetime, timezone
+from unittest.mock import AsyncMock, patch
+
+import pytest
+
+from backend.app.services import usage_tracker
+from backend.app.services.usage_tracker import PrintSession, _active_sessions, printer_is_charging
+from backend.tests.integration.test_print_complete_end_to_end import (  # noqa: F401
+    _clean,
+    _complete,
+    _no_finish_photo,
+    queued_print,
+)
+
+pytestmark = [pytest.mark.asyncio, pytest.mark.integration]
+
+
+@pytest.fixture(autouse=True)
+def _no_sessions_or_marks():
+    _active_sessions.clear()
+    usage_tracker._completing.clear()
+    yield
+    _active_sessions.clear()
+    usage_tracker._completing.clear()
+
+
+def _open_session(printer_id: int) -> None:
+    _active_sessions[printer_id] = PrintSession(
+        printer_id=printer_id, print_name="part", started_at=datetime.now(timezone.utc)
+    )
+
+
+async def _complete_watching(test_engine, printer_id: int, **extra) -> list:
+    """Complete the print; the tracker, as the real one, takes the session first.
+
+    Returns the archive each charge was made for; asserts the printer still
+    counted as printing when it was made."""
+    seen: list = []
+
+    async def tracker(pid, data, printer_manager, db, **kwargs):
+        _active_sessions.pop(pid, None)
+        assert printer_is_charging(pid), "the AMS sync could charge the print as well"
+        seen.append(kwargs.get("archive_id"))
+        return []
+
+    with patch("backend.app.services.usage_tracker.on_print_complete", tracker):
+        await _complete(test_engine, printer_id, "completed", extra=extra or None)
+    return seen
+
+
+async def test_the_printer_counts_as_printing_until_the_usage_is_booked(test_engine, queued_print):
+    _open_session(queued_print["printer"])
+
+    assert await _complete_watching(test_engine, queued_print["printer"]) == [queued_print["archive"]]
+    assert not printer_is_charging(queued_print["printer"])
+
+
+async def test_a_completion_without_a_file_name_closes_the_session_and_charges_nothing(
+    test_engine, db_session, queued_print
+):
+    """Which print ended can't be told: a printing archive is almost always an
+    earlier print's, which the reconnect reconcile closes and charges. Closing
+    the session is what ends the stuck weight sync."""
+    from backend.app.models.archive import PrintArchive
+
+    _open_session(queued_print["printer"])
+
+    charges = await _complete_watching(test_engine, queued_print["printer"], filename="", subtask_name="")
+
+    assert charges == []
+    assert not printer_is_charging(queued_print["printer"]), "the weight sync stayed off"
+    db_session.expire_all()
+    assert (await db_session.get(PrintArchive, queued_print["archive"])).status == "printing"
+
+
+async def test_a_completion_that_fails_does_not_leave_the_printer_printing(test_engine, queued_print):
+    with (
+        patch("backend.app.main._recover_fallback_from_cache_before_eviction", AsyncMock(side_effect=RuntimeError)),
+        pytest.raises(RuntimeError),
+    ):
+        await _complete(test_engine, queued_print["printer"], "completed")
+
+    assert not printer_is_charging(queued_print["printer"])
+
+
+async def test_a_new_print_clears_a_stale_mark():
+    from types import SimpleNamespace
+    from unittest.mock import MagicMock
+
+    usage_tracker._completing.add(5)
+    printer_manager = MagicMock()
+    printer_manager.get_status.return_value = SimpleNamespace(raw_data=None)
+
+    await usage_tracker.on_print_start(5, {}, printer_manager)
+
+    assert not printer_is_charging(5)
+
+
+async def test_booking_the_usage_ends_the_mark(db_session):
+    """The rest of the completion (SD cleanup, notifications) can take a while;
+    the sync need not wait for it once the print is charged."""
+    usage_tracker.mark_completing(5)
+
+    await usage_tracker.discard_session(db_session, 5)
+
+    assert not printer_is_charging(5)
+
+
+async def test_a_deleted_printer_is_forgotten():
+    usage_tracker.mark_completing(5)
+
+    usage_tracker.forget_printer(5)
+
+    assert not printer_is_charging(5)

backend/tests/integration/test_inventory_ams_weight_sync_lock.py

@@ -175,3 +175,22 @@ async def test_a_weighed_spool_is_announced(async_client: AsyncClient, db_sessio
         )
 
     assert "inventory_changed" in _broadcast_types(ws)
+
+
+@pytest.mark.asyncio
+@pytest.mark.integration
+async def test_a_print_whose_usage_is_being_booked_counts_as_printing(
+    async_client: AsyncClient, db_session, printer_factory
+):
+    """WU-3: the tracker has taken the session but not charged the print yet."""
+    from backend.app.services import usage_tracker
+
+    spool_id = await _assigned_spool(db_session, printer_factory, locked=False)
+    printer_id = await db_session.scalar(select(SpoolAssignment.printer_id).where(SpoolAssignment.spool_id == spool_id))
+    usage_tracker._completing.add(printer_id)
+    try:
+        response = await _sync(async_client, _printer("FINISH"))
+    finally:
+        usage_tracker._completing.discard(printer_id)
+
+    assert (response.json()["synced"], response.json()["printing"]) == (0, 1)