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.

(Same fix as testing branch commit b44c902, applied manually here
since nightly still has the pre-mixin-split monolithic
kobrax_moonraker_bridge.py layout - bridge_mqtt.py/bridge_spoolman.py
don't exist on this branch yet.)
This commit is contained in:
2026-08-24 19:17:02 +02:00
parent e70720bc27
commit ef1956f423
2 changed files with 112 additions and 7 deletions

View File

@ -1195,8 +1195,14 @@ class KobraXBridge:
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 {
@ -1204,10 +1210,11 @@ class KobraXBridge:
- 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."""
@ -1420,7 +1427,18 @@ class KobraXBridge:
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:

View File

@ -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()