From b44c9021a014b1b3fe23a6e7d6912d160281ea61 Mon Sep 17 00:00:00 2001 From: viewit Date: Mon, 24 Aug 2026 19:15:18 +0200 Subject: [PATCH] fix(spoolman): stop deducting filament from spools not used in the print User report: with 4 spools mapped, every print deducted the same several-gram amount from ALL 4 spools regardless of which one was actually printing with, adding up to ~150g of drift over time on an unused spool. Root cause: _spoolman_last_sync was reset to 0.0 (epoch) at print start instead of the current time. The poll loop calls _spoolman_sync_midprint() before _spoolman_attribute_tick() in the same iteration, so with last_sync=0.0 the sync-due check was true on the very first tick after print start - before any per-slot attribution existed yet. _spoolman_unreported() then fell back to splitting the printer's full (possibly already nonzero) supplies_usage equally across every mapped spool, matching the reported log (identical mm reported to all 4 spools, right after upload before the purge even started). Fixes: - _on_print() now resets _spoolman_last_sync to time.time(), not 0.0, so the first sync check is only due after a real interval has passed with attribution data available. - _spoolman_unreported()'s fallback now only applies with exactly one mapped slot (single-extruder, no ambiguity) - with multiple slots and no attribution data it reports nothing instead of guessing, since a wrong equal-split is worse than a temporarily-missed report. Added tests/test_spoolman_unreported.py covering both fixes. --- bridge_mqtt.py | 13 ++++- bridge_spoolman.py | 19 ++++--- tests/test_spoolman_unreported.py | 87 +++++++++++++++++++++++++++++++ 3 files changed, 112 insertions(+), 7 deletions(-) create mode 100644 tests/test_spoolman_unreported.py diff --git a/bridge_mqtt.py b/bridge_mqtt.py index 50fbc3a..74e257e 100644 --- a/bridge_mqtt.py +++ b/bridge_mqtt.py @@ -98,7 +98,18 @@ class MqttCallbacksMixin: self._spoolman_slot_usage = {} self._spoolman_slot_reported = {} self._spoolman_last_usage = 0.0 - self._spoolman_last_sync = 0.0 + # Must be "now", not 0.0/epoch: _spoolman_sync_midprint() checks + # time.time() - _spoolman_last_sync >= sync_rate in the poll loop, + # and runs BEFORE _spoolman_attribute_tick() in the same iteration + # (see run_bridge's poll loop). With last_sync=0.0 that condition + # is true on the very first tick after print start, before any + # per-slot usage has been attributed yet - _spoolman_unreported() + # then falls back to splitting the printer's full (possibly + # already nonzero/carried-over) supplies_usage equally across + # every mapped spool, silently deducting filament from spools not + # even used in this print (reported live, several grams per spool + # per print). + self._spoolman_last_sync = time.time() # Job-History: Druckende erkennen if kobra_state in ("finished",) and self._current_job_id: diff --git a/bridge_spoolman.py b/bridge_spoolman.py index 9f6aaae..c093247 100644 --- a/bridge_spoolman.py +++ b/bridge_spoolman.py @@ -57,8 +57,14 @@ class SpoolmanMixin: def _spoolman_unreported(self) -> dict[int, float]: """Return {slot_idx: mm} of usage not yet reported to Spoolman. - Falls back to equal split of total supplies_usage when per-slot - attribution data is absent (e.g. single-extruder with no AMS).""" + Falls back to crediting the single mapped slot with the full + supplies_usage when per-slot attribution data is absent (single- + extruder setup with no AMS - there's only ever one spool it could be). + With more than one mapped slot, splitting unattributed usage equally + across all of them would silently deduct filament from spools not + even used in the current print (Issue: filament removed from spools + not part of the print) - safer to report nothing for those slots and + wait for real attribution data than to guess wrong.""" total_used = self._state.get("supplies_usage", 0) if self._spoolman_slot_usage: return { @@ -66,10 +72,11 @@ class SpoolmanMixin: - self._spoolman_slot_reported.get(slot, 0.0) for slot in self._spoolman_slot_spools } - n = len(self._spoolman_slot_spools) - already = sum(self._spoolman_slot_reported.values()) - per = (total_used - already) / n if n else 0.0 - return {slot: per for slot in self._spoolman_slot_spools} + if len(self._spoolman_slot_spools) == 1: + slot = next(iter(self._spoolman_slot_spools)) + already = self._spoolman_slot_reported.get(slot, 0.0) + return {slot: total_used - already} + return {} def _spoolman_report(self, unreported: dict[int, float], min_mm: float = 0.1) -> None: """Fire-and-forget report of unreported mm to each mapped spool.""" diff --git a/tests/test_spoolman_unreported.py b/tests/test_spoolman_unreported.py new file mode 100644 index 0000000..1142367 --- /dev/null +++ b/tests/test_spoolman_unreported.py @@ -0,0 +1,87 @@ +"""Regression test: Spoolman fallback split silently deducted filament from +spools not used in the current print. + +_spoolman_unreported() falls back to an equal split across every mapped +AMS slot when per-slot attribution data (_spoolman_slot_usage) is still +empty - previously true right after print start, because +_spoolman_sync_midprint() ran (in the poll loop) before the first +_spoolman_attribute_tick() had a chance to populate any per-slot data, +since _spoolman_last_sync was reset to 0.0 (== "due immediately") instead +of the current time. With 4 spools mapped, that meant the full +(possibly already nonzero) supplies_usage got reported equally to all 4 +spools regardless of which one was actually printing with. + +The fix: only fall back to a full-credit report when there is exactly +one mapped slot (single-extruder, no ambiguity possible) - otherwise +report nothing until real attribution data exists. Additionally, +_on_print() now resets _spoolman_last_sync to the current time (not 0.0) +at print start, so the first mid-print sync check is due only after a +real sync_rate interval has passed. +""" +import time + + +def _configure(bridge, slot_spools): + bridge._spoolman_slot_spools = dict(slot_spools) + bridge._spoolman_slot_usage = {} + bridge._spoolman_slot_reported = {} + + +async def test_unreported_reports_nothing_for_multiple_slots_without_attribution(client): + _, bridge = client + _configure(bridge, {0: 11, 1: 15, 2: 17, 3: 23}) + bridge._state["supplies_usage"] = 4369 + + result = bridge._spoolman_unreported() + + assert result == {} + + +async def test_unreported_credits_the_single_slot_without_attribution(client): + _, bridge = client + _configure(bridge, {0: 42}) + bridge._state["supplies_usage"] = 500 + + result = bridge._spoolman_unreported() + + assert result == {0: 500} + + +async def test_unreported_single_slot_subtracts_already_reported(client): + _, bridge = client + _configure(bridge, {0: 42}) + bridge._spoolman_slot_reported = {0: 200.0} + bridge._state["supplies_usage"] = 500 + + result = bridge._spoolman_unreported() + + assert result == {0: 300.0} + + +async def test_unreported_uses_real_attribution_once_available(client): + _, bridge = client + _configure(bridge, {0: 11, 1: 15}) + bridge._spoolman_slot_usage = {0: 120.0} + bridge._state["supplies_usage"] = 120 + + result = bridge._spoolman_unreported() + + # Only the slot that was actually attributed usage gets a nonzero report; + # the untouched slot must not receive any share of it. + assert result[0] == 120.0 + assert result[1] == 0.0 + + +async def test_print_start_resets_last_sync_to_now_not_epoch(client): + """_spoolman_last_sync=0.0 at print start meant the poll loop's mid-print + sync check (time.time() - last_sync >= sync_rate) was true on the very + first tick, before _spoolman_attribute_tick() ever ran once - triggering + the fallback-split bug above immediately after print start, before any + real per-slot usage existed yet.""" + _, bridge = client + before = time.time() + + bridge._on_print({"state": "printing", "data": {"filename": "test.gcode"}}) + + assert bridge._spoolman_last_sync >= before + assert bridge._spoolman_last_sync <= time.time()