From 5afb485c12da0fd10597e7aba8702dd4a8abf32b Mon Sep 17 00:00:00 2001 From: maziggy Date: Mon, 19 Oct 2026 17:36:53 +0200 Subject: [PATCH] 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 | 3 + backend/app/api/routes/inventory.py | 12 +- backend/app/main.py | 38 +++++- backend/app/services/usage_tracker.py | 28 ++++ .../test_ams_remain_sync_while_printing.py | 11 ++ .../test_completion_keeps_printer_charging.py | 129 ++++++++++++++++++ .../test_inventory_ams_weight_sync_lock.py | 19 +++ 7 files changed, 228 insertions(+), 12 deletions(-) create mode 100644 backend/tests/integration/test_completion_keeps_printer_charging.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 8a0f69b53..985813028 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/backend/app/api/routes/inventory.py b/backend/app/api/routes/inventory.py index 94e042c9c..67bf3ac42 100644 --- a/backend/app/api/routes/inventory.py +++ b/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 diff --git a/backend/app/main.py b/backend/app/main.py index 297f3b2c3..11b627f60 100644 --- a/backend/app/main.py +++ b/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")) diff --git a/backend/app/services/usage_tracker.py b/backend/app/services/usage_tracker.py index ca865450e..230c0f3df 100644 --- a/backend/app/services/usage_tracker.py +++ b/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) diff --git a/backend/tests/integration/test_ams_remain_sync_while_printing.py b/backend/tests/integration/test_ams_remain_sync_while_printing.py index 1054fe100..0aeddb91c 100644 --- a/backend/tests/integration/test_ams_remain_sync_while_printing.py +++ b/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 diff --git a/backend/tests/integration/test_completion_keeps_printer_charging.py b/backend/tests/integration/test_completion_keeps_printer_charging.py new file mode 100644 index 000000000..fc6296551 --- /dev/null +++ b/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) diff --git a/backend/tests/integration/test_inventory_ams_weight_sync_lock.py b/backend/tests/integration/test_inventory_ams_weight_sync_lock.py index 6dc3e99eb..23a9aa119 100644 --- a/backend/tests/integration/test_inventory_ams_weight_sync_lock.py +++ b/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)