fix(usage-tracker): split filament weight when AMS auto-falls-back mid-print (issue 957)

  When one spool ran out and the AMS transparently switched to a sibling
  slot of the same material, the usage tracker credited the originally-
  mapped spool with the full 3MF estimate AND added the fallback spool's
  remain%-delta on top — so a 78g print could record as 138g across two
  spools, leaving the empty spool's recorded weight beyond its label.

  Two interacting bugs:

  1. bambu_mqtt.py: the tray-change recorder gated on
     `state in ("RUNNING", "PAUSE")`, but P2S firmware briefly transitions
     out of RUNNING during the AMS swap (into LOADING etc.), so the
     literal-string gate missed the switch entirely and tray_change_log
     stayed empty. Re-key on the print-lifecycle flags
     (_was_running and not _completion_triggered) so any tray change
     between print start and completion is captured regardless of the
     momentary gcode_state.

  2. usage_tracker.py: the splitting branch was gated on
     `not slot_to_tray`, so the splitting code only ran for prints where
     the slicer mapping hadn't been captured — i.e. never on the actual
     fallback case (slot_to_tray is populated by every print_cmd). Drop
     the gate: when tray_change_log has > 1 entries, splitting takes
     over and per-segment per-layer gcode usage replaces the stale
     mapping. Path 2 (AMS remain%-delta) then naturally skips both trays
     because they're already in handled_trays after splitting,
     eliminating the double-credit.

backend/app/services/bambu_mqtt.py

@@ -1569,8 +1569,14 @@ class BambuMQTTClient:
                 # Valid physical trays: 0-15 (regular AMS), 128-135 (AMS-HT), 254 (external spool)
                 tn = self.state.tray_now
                 if (0 <= tn <= 15) or (128 <= tn <= 135) or tn == 254:
-                    # Log tray change for mid-print usage splitting
-                    if tn != self.state.last_loaded_tray and self.state.state in ("RUNNING", "PAUSE"):
+                    # Log tray change for mid-print usage splitting. Gate on the
+                    # print-lifecycle flags (`_was_running` set on first RUNNING /
+                    # new print, `_completion_triggered` set when on_print_complete
+                    # fires) instead of `state in ("RUNNING", "PAUSE")` — P2S
+                    # firmware briefly transitions out of RUNNING during AMS
+                    # auto-fallback (#957), so a literal-string gate misses the
+                    # switch and the usage tracker double-credits at completion.
+                    if tn != self.state.last_loaded_tray and self._was_running and not self._completion_triggered:
                         self.state.tray_change_log.append((tn, self.state.layer_num))
                         logger.info(
                             "[%s] Tray change during print: tray=%d at layer=%d",

backend/app/services/usage_tracker.py

@@ -846,26 +846,29 @@ async def _track_from_3mf(
     # 5. For single-filament non-queue prints, use tray_now from printer state
     #    Priority: tray_change_log (multi-tray split) > tray_now_at_start > current tray_now
     #              > last_loaded_tray > vt_tray check
+    #
+    # tray_change_log evidence wins over slot_to_tray when present: if the
+    # printer fed from multiple trays mid-print (AMS auto-fallback when one
+    # spool runs out, #957), the slicer's mapping captured at print start
+    # is stale and needs to be replaced with per-layer split attribution.
     nonzero_slots = [u for u in filament_usage if u.get("used_g", 0) > 0]
     tray_now_override: int | None = None
     tray_changes: list[tuple[int, int]] = []  # [(global_tray_id, layer_num), ...]
-    if not slot_to_tray and len(nonzero_slots) == 1:
-        state = printer_manager.get_status(printer_id)
-        tray_changes = getattr(state, "tray_change_log", []) if state else []
-
-        if len(tray_changes) > 1:
-            # Multi-tray usage detected — will split in per-slot loop using per-layer gcode
-            logger.info("[UsageTracker] 3MF: tray change log: %s (will split weight)", tray_changes)
-        elif 0 <= tray_now_at_start <= 254:
-            # Try tray_now_at_start first (captured at print start)
+    state = printer_manager.get_status(printer_id) if len(nonzero_slots) == 1 else None
+    if state is not None:
+        tray_changes = getattr(state, "tray_change_log", []) or []
+
+    if len(tray_changes) > 1:
+        # Multi-tray usage detected — splitting takes over regardless of slot_to_tray.
+        logger.info("[UsageTracker] 3MF: tray change log: %s (will split weight)", tray_changes)
+    elif not slot_to_tray and len(nonzero_slots) == 1:
+        if 0 <= tray_now_at_start <= 254:
             tray_now_override = tray_now_at_start
             logger.info("[UsageTracker] 3MF: using tray_now_at_start=%d (single-filament fallback)", tray_now_at_start)
         elif state and 0 <= state.tray_now <= 254:
-            # Current state is valid (printer didn't retract yet)
             tray_now_override = state.tray_now
             logger.info("[UsageTracker] 3MF: using current tray_now=%d", state.tray_now)
         elif state and 0 <= state.last_loaded_tray <= 253:
-            # Last valid tray before retract (H2D retracts before completion callback)
             tray_now_override = state.last_loaded_tray
             logger.info("[UsageTracker] 3MF: using last_loaded_tray=%d (post-retract fallback)", state.last_loaded_tray)
         elif state and state.tray_now == 255:
@@ -874,7 +877,7 @@ async def _track_from_3mf(
             if any(int(vt.get("id", 0)) == 255 for vt in vt_tray if isinstance(vt, dict)):
                 tray_now_override = state.tray_now
                 logger.info("[UsageTracker] 3MF: using tray_now=255 (H2-series external spool)")
-        if tray_now_override is None and len(tray_changes) <= 1:
+        if tray_now_override is None:
             logger.info(
                 "[UsageTracker] 3MF: no valid tray_now (at_start=%d, current=%s, last_loaded=%s)",
                 tray_now_at_start,

backend/tests/unit/services/test_bambu_mqtt.py

@@ -2731,83 +2731,129 @@ class TestTrayChangeLog:
 
         assert mqtt_client.state.tray_change_log == [(1, 0)]
 
+    # Helper that mirrors the production gate at bambu_mqtt.py:1571 — tests
+    # below replicate the gate so they validate the *contract* without needing
+    # to feed a synthetic AMS push through the full _process_message path.
+    @staticmethod
+    def _record_if_change(client, tn: int) -> None:
+        if (0 <= tn <= 15) or (128 <= tn <= 135) or tn == 254:
+            if tn != client.state.last_loaded_tray and client._was_running and not client._completion_triggered:
+                client.state.tray_change_log.append((tn, client.state.layer_num))
+            client.state.last_loaded_tray = tn
+
     def test_tray_change_recorded_during_running(self, mqtt_client):
         """Tray change while RUNNING is appended to the log."""
         mqtt_client.state.state = "RUNNING"
+        mqtt_client._was_running = True
+        mqtt_client._completion_triggered = False
         mqtt_client.state.layer_num = 50
         mqtt_client.state.last_loaded_tray = 0
         mqtt_client.state.tray_change_log = [(0, 0)]
 
-        # Simulate tray_now update via AMS data
         mqtt_client.state.tray_now = 1
-        # Trigger the tracking code path
-        tn = mqtt_client.state.tray_now
-        if tn != mqtt_client.state.last_loaded_tray and mqtt_client.state.state in ("RUNNING", "PAUSE"):
-            mqtt_client.state.tray_change_log.append((tn, mqtt_client.state.layer_num))
-        mqtt_client.state.last_loaded_tray = tn
+        self._record_if_change(mqtt_client, mqtt_client.state.tray_now)
 
         assert mqtt_client.state.tray_change_log == [(0, 0), (1, 50)]
 
     def test_tray_change_not_recorded_when_idle(self, mqtt_client):
-        """Tray changes while IDLE are NOT logged."""
+        """Tray changes outside an active print are NOT logged."""
+        # IDLE between prints — both lifecycle flags in the cleared state.
         mqtt_client.state.state = "IDLE"
+        mqtt_client._was_running = False
+        mqtt_client._completion_triggered = False
         mqtt_client.state.layer_num = 0
         mqtt_client.state.last_loaded_tray = 0
         mqtt_client.state.tray_change_log = []
 
         mqtt_client.state.tray_now = 3
-        tn = mqtt_client.state.tray_now
-        if tn != mqtt_client.state.last_loaded_tray and mqtt_client.state.state in ("RUNNING", "PAUSE"):
-            mqtt_client.state.tray_change_log.append((tn, mqtt_client.state.layer_num))
-        mqtt_client.state.last_loaded_tray = tn
+        self._record_if_change(mqtt_client, mqtt_client.state.tray_now)
 
         assert mqtt_client.state.tray_change_log == []
 
     def test_tray_change_recorded_during_pause(self, mqtt_client):
         """Tray change while PAUSE is also logged (AMS can swap during pause)."""
         mqtt_client.state.state = "PAUSE"
+        mqtt_client._was_running = True
+        mqtt_client._completion_triggered = False
         mqtt_client.state.layer_num = 75
         mqtt_client.state.last_loaded_tray = 2
         mqtt_client.state.tray_change_log = [(2, 0)]
 
         mqtt_client.state.tray_now = 5
-        tn = mqtt_client.state.tray_now
-        if tn != mqtt_client.state.last_loaded_tray and mqtt_client.state.state in ("RUNNING", "PAUSE"):
-            mqtt_client.state.tray_change_log.append((tn, mqtt_client.state.layer_num))
-        mqtt_client.state.last_loaded_tray = tn
+        self._record_if_change(mqtt_client, mqtt_client.state.tray_now)
 
         assert mqtt_client.state.tray_change_log == [(2, 0), (5, 75)]
 
+    def test_tray_change_recorded_during_intermediate_state(self, mqtt_client):
+        """Tray change during a transient non-RUNNING state mid-print is logged.
+
+        Regression for #957: P2S firmware briefly transitions out of RUNNING
+        (e.g. into LOADING) when the AMS auto-falls-back from an empty spool to
+        a same-material sibling. The previous gate ``state in ("RUNNING",
+        "PAUSE")`` missed this transition entirely, so the usage tracker had no
+        evidence of the switch and double-credited the original tray with the
+        full 3MF estimate while the remain%-delta path added the fallback
+        weight on top. The new gate keys on the print-lifecycle flags
+        (``_was_running and not _completion_triggered``) so any tray change
+        between print start and completion is captured regardless of the
+        momentary gcode_state string.
+        """
+        mqtt_client.state.state = "LOADING"  # not RUNNING/PAUSE — old gate would skip
+        mqtt_client._was_running = True
+        mqtt_client._completion_triggered = False
+        mqtt_client.state.layer_num = 42
+        mqtt_client.state.last_loaded_tray = 0
+        mqtt_client.state.tray_change_log = [(0, 0)]
+
+        # AMS auto-fallback: T0 ran out, swapped to T1 of same material
+        mqtt_client.state.tray_now = 1
+        self._record_if_change(mqtt_client, mqtt_client.state.tray_now)
+
+        assert mqtt_client.state.tray_change_log == [(0, 0), (1, 42)]
+
+    def test_tray_change_not_recorded_after_completion(self, mqtt_client):
+        """Once on_print_complete has fired, further tray changes don't pollute the log."""
+        mqtt_client.state.state = "FINISH"
+        mqtt_client._was_running = True
+        mqtt_client._completion_triggered = True  # completion already triggered
+        mqtt_client.state.layer_num = 0
+        mqtt_client.state.last_loaded_tray = 1
+        mqtt_client.state.tray_change_log = [(0, 0), (1, 50)]
+
+        mqtt_client.state.tray_now = 2
+        self._record_if_change(mqtt_client, mqtt_client.state.tray_now)
+
+        # Log unchanged — completion already triggered so post-print tray
+        # movement (e.g. printer self-cleaning) doesn't bleed into the next
+        # print's attribution.
+        assert mqtt_client.state.tray_change_log == [(0, 0), (1, 50)]
+
     def test_same_tray_not_logged_twice(self, mqtt_client):
         """Same tray value doesn't create duplicate log entries."""
         mqtt_client.state.state = "RUNNING"
+        mqtt_client._was_running = True
+        mqtt_client._completion_triggered = False
         mqtt_client.state.layer_num = 30
         mqtt_client.state.last_loaded_tray = 2
         mqtt_client.state.tray_change_log = [(2, 0)]
 
-        # Same tray again
         mqtt_client.state.tray_now = 2
-        tn = mqtt_client.state.tray_now
-        if tn != mqtt_client.state.last_loaded_tray and mqtt_client.state.state in ("RUNNING", "PAUSE"):
-            mqtt_client.state.tray_change_log.append((tn, mqtt_client.state.layer_num))
-        mqtt_client.state.last_loaded_tray = tn
+        self._record_if_change(mqtt_client, mqtt_client.state.tray_now)
 
         assert mqtt_client.state.tray_change_log == [(2, 0)]
 
     def test_multiple_tray_changes(self, mqtt_client):
         """Multiple tray changes create a full history."""
         mqtt_client.state.state = "RUNNING"
+        mqtt_client._was_running = True
+        mqtt_client._completion_triggered = False
         mqtt_client.state.last_loaded_tray = 0
         mqtt_client.state.tray_change_log = [(0, 0)]
 
-        changes = [(1, 50), (3, 120), (0, 200)]
-        for tray, layer in changes:
+        for tray, layer in [(1, 50), (3, 120), (0, 200)]:
             mqtt_client.state.tray_now = tray
             mqtt_client.state.layer_num = layer
-            tn = mqtt_client.state.tray_now
-            if tn != mqtt_client.state.last_loaded_tray and mqtt_client.state.state in ("RUNNING", "PAUSE"):
-                mqtt_client.state.tray_change_log.append((tn, mqtt_client.state.layer_num))
-            mqtt_client.state.last_loaded_tray = tn
+            self._record_if_change(mqtt_client, tray)
 
         assert mqtt_client.state.tray_change_log == [(0, 0), (1, 50), (3, 120), (0, 200)]
 

backend/tests/unit/test_usage_tracker.py

@@ -1101,6 +1101,84 @@ class TestTrayChangeSplit:
         assert results[1]["tray_id"] == 1
         assert results[1]["weight_used"] == 30.0
 
+    @pytest.mark.asyncio
+    async def test_tray_switch_overrides_print_cmd_mapping(self):
+        """tray_change_log evidence overrides slot_to_tray captured at print start.
+
+        Regression for #957: when AMS auto-falls-back from an empty spool to a
+        same-material sibling, the print_cmd's mapping (which named the
+        original tray) is stale by the time the print finishes. Before this
+        fix, the splitting branch was gated on ``not slot_to_tray`` so the
+        slicer mapping was preferred even when the printer actually fed from
+        a different tray — Path 1 credited the original tray with the full
+        3MF estimate and Path 2 layered the AMS-fallback delta on top, so
+        spool consumption double-counted (e.g. 78 g print credited as 78 g
+        + 60 g = 138 g). This test pins the new behavior: when
+        tray_change_log has > 1 entries, splitting takes over regardless of
+        whether ams_mapping was provided.
+        """
+        spool_a = _make_spool(spool_id=10, label_weight=1000)
+        spool_b = _make_spool(spool_id=20, label_weight=1000)
+        assign_a = _make_assignment(spool_id=10, ams_id=0, tray_id=0)
+        assign_b = _make_assignment(spool_id=20, ams_id=0, tray_id=1)
+        archive = _make_archive(archive_id=200)
+
+        # No queue_item placeholder: passing ams_mapping bypasses the queue lookup
+        # at usage_tracker.py:816 (`if not slot_to_tray and archive_id`).
+        db = _mock_db_sequential([archive, assign_a, spool_a, assign_b, spool_b])
+
+        # Slicer mapping says slot 1 -> tray 0; printer actually swapped to tray 1 at layer 30
+        printer_manager = MagicMock()
+        printer_manager.get_status.return_value = SimpleNamespace(
+            progress=100,
+            layer_num=100,
+            tray_now=1,
+            last_loaded_tray=1,
+            total_layers=100,
+            tray_change_log=[(0, 0), (1, 30)],
+        )
+
+        filament_usage = [{"slot_id": 1, "used_g": 78.0, "type": "PLA", "color": ""}]
+        handled_trays: set[tuple[int, int]] = set()
+
+        with (
+            patch("backend.app.core.config.settings") as mock_settings,
+            patch(
+                "backend.app.utils.threemf_tools.extract_filament_usage_from_3mf",
+                return_value=filament_usage,
+            ),
+            patch(
+                "backend.app.utils.threemf_tools.extract_layer_filament_usage_from_3mf",
+                return_value=None,  # No per-layer data — exercises linear fallback
+            ),
+        ):
+            mock_settings.base_dir = MagicMock()
+            mock_path = MagicMock()
+            mock_path.exists.return_value = True
+            mock_settings.base_dir.__truediv__ = MagicMock(return_value=mock_path)
+
+            results = await _track_from_3mf(
+                printer_id=1,
+                archive_id=200,
+                status="completed",
+                print_name="Runout w/ slicer mapping",
+                handled_trays=handled_trays,
+                printer_manager=printer_manager,
+                db=db,
+                # ams_mapping captured at print start — slicer told us slot 0 -> tray 0
+                # (1-based slot_id=1 -> 0-based slot index 0).
+                ams_mapping=[0],
+            )
+
+        # Splitting branch ran despite ams_mapping being set: two segments,
+        # one per tray, total weight matches the 3MF estimate (no double-count).
+        assert len(results) == 2
+        total = sum(r["weight_used"] for r in results)
+        assert total == pytest.approx(78.0, abs=0.1)
+        # Both trays now in handled_trays so Path 2 (remain%-delta) skips them.
+        assert (0, 0) in handled_trays
+        assert (0, 1) in handled_trays
+
     @pytest.mark.asyncio
     async def test_no_tray_change_uses_normal_path(self):
         """Single-entry tray_change_log falls through to normal tray_now_at_start logic."""