Read the printer's own slot mapping when Spoolman has none (#2768)

A sliced file numbers its filaments 1..4; which AMS tray each came from is
    a separate decision made when the job is sent. store_print_data learns it
    from one of two sources, both of which require the print command to pass
    through us: the mapping Bambuddy chose itself, or the one it intercepted
    on the printer's local request topic. A job dispatched from Bambu Studio
    while the printer is cloud-bound satisfies neither -- the command travels
    through Bambu's broker and never reaches the topic we subscribe to.

    slot_to_tray is then NULL and _resolve_global_tray_id guesses by position:
    filament 1 from the first loaded tray, filament 2 from the second. The
    reporter's X1C was loaded in the order 2, 4, 1, AMS-HT, so all four slots
    were charged to the wrong spool. Their log carries the printer's own
    answer, mapping=[1, 3, 0, 32768], sitting unread.

    usage_tracker has consulted that field since it started resolving mappings
    at completion, along with a colour match against the loaded trays for the
    models that never publish it (A1, A1 Mini, P1S, P2S). Only the Spoolman
    writer, which resolves at print start, never learned to -- and main.py
    gates usage_tracker behind Spoolman being off, so enabling Spoolman is
    what costs you the better resolver.

    _resolve_slot_to_tray_fallback gives it both, at completion rather than at
    print start: a printer keeps publishing the last job's mapping while it
    sits idle, so reading it early would risk stamping the previous print's
    mapping onto this one. A mapping we or the slicer actually recorded is
    never second-guessed.

    Applied in _report_partial_usage too. Cancelled and failed prints feed the
    same slot_to_tray to the same resolver and mis-charged just as readily.

    The resolved mapping and its source are now logged at print start and at
    completion. "source: none" at start is the signal that completion will
    have to fall back, and it was the one line that would have turned this
    report into a five-minute triage.

    Not addressed: editing the mapping after the fact, which the reporter also
    asked for. ArchiveUpdate exposes neither filament field and there is no way
    to re-run an attribution, so that is a feature rather than a fix.

backend/app/services/spoolman_tracking.py

@@ -150,6 +150,62 @@ def _resolve_global_tray_id(slot_id: int, slot_to_tray: list | None, ams_trays:
     return slot_id - 1
 
 
+def _resolve_slot_to_tray_fallback(printer_id: int, filament_usage: list[dict]) -> tuple[list[int] | None, str]:
+    """Recover a slot-to-tray mapping at completion when print start captured none.
+
+    ``store_print_data`` can only learn the mapping from two sources: the
+    ``ams_mapping`` Bambuddy intercepts on the printer's local request topic, and
+    a queue item's stored mapping. Neither exists for a print dispatched from
+    Bambu Studio while the printer is cloud-bound — the command travels through
+    Bambu's broker and never appears on the local topic we subscribe to. With
+    ``slot_to_tray`` left NULL, ``_resolve_global_tray_id`` guesses by position:
+    slicer slot 1 to the first loaded tray, slot 2 to the second, and so on. An
+    AMS that isn't loaded in slicer order then charges every slot to the wrong
+    spool, and the archive's filament is rewritten to match, so the print
+    silently changes colour when it finishes (#2768).
+
+    The printer knows the real answer. Its ``mapping`` field carries the actual
+    slot-to-tray assignment for the running job, and for the models that never
+    publish it (A1, P1S, P2S) the 3MF's per-slot colours can be matched against
+    the loaded trays instead. The built-in inventory writer has consulted both
+    for as long as it has resolved mappings at completion; this gives the
+    Spoolman writer the same two fallbacks at the same moment.
+
+    Deliberately at completion rather than inside ``store_print_data``: the
+    printer keeps publishing ``mapping`` long after a job ends — it is still in
+    the status payload while the printer sits idle — so reading it at print start
+    risks stamping the *previous* job's mapping onto this one before the printer
+    has pushed the update. At completion the field unambiguously describes the
+    job that just ran.
+
+    Args:
+        printer_id: Printer whose live state is consulted.
+        filament_usage: The 3MF's per-slot estimates, needed by the colour
+            match. Only the ``slot_id``/``color`` keys are read.
+
+    Returns:
+        ``(mapping, source)``, or ``(None, "none")`` when neither fallback
+        produced anything and the positional default stands.
+    """
+    from backend.app.services.printer_manager import printer_manager
+    from backend.app.services.usage_tracker import _decode_mqtt_mapping, _match_slots_by_color
+
+    state = printer_manager.get_status(printer_id)
+    raw_data = getattr(state, "raw_data", None) if state else None
+    if not raw_data:
+        return None, "none"
+
+    decoded = _decode_mqtt_mapping(raw_data.get("mapping"))
+    if decoded:
+        return decoded, "mqtt"
+
+    matched = _match_slots_by_color(filament_usage, raw_data.get("ams"))
+    if matched:
+        return matched, "color_match"
+
+    return None, "none"
+
+
 def build_ams_tray_lookup(raw_data: dict) -> dict[int, dict]:
     """Build lookup of global_tray_id -> tray info from printer state.
 
@@ -327,9 +383,11 @@ async def store_print_data(
     # Prefer the explicit mapping captured from the print command, then fall back
     # to any queue mapping stored for scheduled/reprint jobs.
     slot_to_tray = ams_mapping if ams_mapping is not None else None
+    mapping_source = "print_cmd" if slot_to_tray else None
     if not slot_to_tray and queue_item and queue_item.ams_mapping:
         try:
             slot_to_tray = json.loads(queue_item.ams_mapping)
+            mapping_source = "queue"
         except json.JSONDecodeError:
             pass  # Ignore malformed AMS mapping; fall back to default slot assignment
 
@@ -364,8 +422,15 @@ async def store_print_data(
     )
     logger.debug("[SPOOLMAN] Filament usage: %s", filament_usage)
     logger.debug("[SPOOLMAN] AMS trays: %s", list(ams_trays.keys()))
-    if slot_to_tray:
-        logger.debug("[SPOOLMAN] Custom slot mapping: %s", slot_to_tray)
+    # Logged at info even when there is no mapping: "source: none" here is the
+    # signal that completion will have to fall back, which is the single most
+    # useful line in the log when a print is charged to the wrong spool (#2768).
+    logger.info(
+        "[SPOOLMAN] Print start: archive %s slot_to_tray=%s (source: %s)",
+        archive_id,
+        slot_to_tray,
+        mapping_source or "none",
+    )
     if layer_usage_json:
         logger.debug("[SPOOLMAN] Layer usage data available for partial tracking")
 
@@ -819,6 +884,19 @@ async def _report_partial_usage(
         )
         return
 
+    # Same recovery the completion path does, for the same reason: a print
+    # dispatched from Studio over the cloud left print start with no mapping to
+    # store, and both paths below feed ``slot_to_tray`` to
+    # ``_resolve_global_tray_id`` (#2768). An aborted print charges the wrong
+    # spool just as readily as a finished one.
+    if not slot_to_tray:
+        slot_to_tray, _partial_mapping_source = _resolve_slot_to_tray_fallback(printer_id, filament_usage)
+        logger.info(
+            "[SPOOLMAN] Partial usage: slot_to_tray=%s (source: %s)",
+            slot_to_tray,
+            _partial_mapping_source,
+        )
+
     # Try to use accurate G-code parsed data
     if layer_usage:
         layer_usage_int = {
@@ -1000,6 +1078,20 @@ async def report_usage(printer_id: int, archive_id: int):
         # is the print's last valid layer.
         _layer_denom_hint = _total_layers or _current_layer
 
+        # Recover the mapping when print start had nothing to store — the
+        # cloud-dispatched Studio print of #2768. Only the 3MF path consumes
+        # ``slot_to_tray``; the remain-delta path below resolves spools from the
+        # AMS slot directly, so there is nothing to recover for it.
+        mapping_source = "stored" if slot_to_tray else "none"
+        if filament_usage and not slot_to_tray:
+            slot_to_tray, mapping_source = _resolve_slot_to_tray_fallback(printer_id, filament_usage)
+        logger.info(
+            "[SPOOLMAN] Archive %s: slot_to_tray=%s (source: %s)",
+            archive_id,
+            slot_to_tray,
+            mapping_source,
+        )
+
         slot_colors: dict[int, str] = {}
         slot_materials: dict[int, str] = {}
         handled_global_tray_ids: set[int] = set()

backend/tests/unit/services/test_spoolman_slot_mapping_fallback.py

@@ -0,0 +1,243 @@
+"""Slot-to-tray mapping fallbacks on the Spoolman path (#2768).
+
+Bambuddy only learns a print's slot-to-tray mapping at print start when it can
+intercept the command on the printer's local MQTT request topic, or when the
+print came from its own queue. A print dispatched from Bambu Studio while the
+printer is cloud-bound satisfies neither: the command travels through Bambu's
+broker, so ``ActivePrintSpoolman.slot_to_tray`` is NULL and every slot falls
+through to a positional guess (slicer slot 1 to the first loaded tray, and so
+on). The reporter's X1C was loaded out of slicer order, so all four slots were
+charged to the wrong spool and the archive's filament was rewritten to match.
+
+The internal-inventory writer never had this problem because it resolves the
+mapping at completion, where it can read the printer's own ``mapping`` field or
+colour-match the 3MF slots against the loaded trays. These tests cover giving
+the Spoolman writer the same two fallbacks.
+"""
+
+from types import SimpleNamespace
+from unittest.mock import AsyncMock, MagicMock, patch
+
+import pytest
+
+from backend.app.services.spoolman_tracking import _resolve_slot_to_tray_fallback
+
+
+class _AsyncCtx:
+    """Minimal async context manager yielding a stub db session."""
+
+    def __init__(self, db):
+        self._db = db
+
+    async def __aenter__(self):
+        return self._db
+
+    async def __aexit__(self, *exc):
+        return False
+
+
+def _state(**raw):
+    return SimpleNamespace(raw_data=raw, layer_num=0, total_layers=0, tray_change_log=[])
+
+
+def _patched_pm(state):
+    pm = MagicMock()
+    pm.get_status.return_value = state
+    return pm
+
+
+class TestResolveSlotToTrayFallback:
+    def test_decodes_the_printers_own_mapping_field(self):
+        """The reporter's X1C published mapping=[1, 3, 0, 32768] while their
+        AMS was loaded out of slicer order. Snow-encoded, that is AMS 0 slot 2,
+        AMS 0 slot 4, AMS 0 slot 1, and the AMS-HT — nothing like the
+        positional [0, 1, 2, 3] the fallback-free path assumed."""
+        pm = _patched_pm(_state(mapping=[1, 3, 0, 32768]))
+
+        with patch("backend.app.services.printer_manager.printer_manager", pm):
+            mapping, source = _resolve_slot_to_tray_fallback(1, [{"slot_id": 1, "color": "#FF0000"}])
+
+        assert mapping == [1, 3, 0, 128]
+        assert source == "mqtt"
+
+    def test_colour_matches_when_the_printer_publishes_no_mapping(self):
+        """A1/P1S/P2S never publish the mapping field. The 3MF's per-slot
+        colours still identify the trays when each one is unambiguous."""
+        pm = _patched_pm(
+            _state(
+                ams=[
+                    {
+                        "id": 0,
+                        "tray": [
+                            {"id": 0, "tray_color": "00FF00FF", "tray_type": "PLA"},
+                            {"id": 1, "tray_color": "FF0000FF", "tray_type": "PLA"},
+                        ],
+                    }
+                ]
+            )
+        )
+        usage = [{"slot_id": 1, "color": "#FF0000"}, {"slot_id": 2, "color": "#00FF00"}]
+
+        with patch("backend.app.services.printer_manager.printer_manager", pm):
+            mapping, source = _resolve_slot_to_tray_fallback(1, usage)
+
+        assert mapping == [1, 0]
+        assert source == "color_match"
+
+    def test_mapping_field_wins_over_colour_matching(self):
+        """The printer's own field is direct evidence; colour matching is
+        inference. When both are available the field decides."""
+        pm = _patched_pm(
+            _state(
+                mapping=[3],
+                ams=[{"id": 0, "tray": [{"id": 0, "tray_color": "FF0000FF", "tray_type": "PLA"}]}],
+            )
+        )
+
+        with patch("backend.app.services.printer_manager.printer_manager", pm):
+            mapping, source = _resolve_slot_to_tray_fallback(1, [{"slot_id": 1, "color": "#FF0000"}])
+
+        assert mapping == [3]
+        assert source == "mqtt"
+
+    def test_reports_none_when_neither_fallback_answers(self):
+        """Ambiguous colours and no mapping field: say so rather than invent
+        one. The caller keeps the positional default, which is no worse than
+        before, and the log names the reason."""
+        pm = _patched_pm(
+            _state(
+                ams=[
+                    {
+                        "id": 0,
+                        "tray": [
+                            {"id": 0, "tray_color": "FF0000FF", "tray_type": "PLA"},
+                            {"id": 1, "tray_color": "FF0000FF", "tray_type": "PLA"},
+                        ],
+                    }
+                ]
+            )
+        )
+
+        with patch("backend.app.services.printer_manager.printer_manager", pm):
+            mapping, source = _resolve_slot_to_tray_fallback(1, [{"slot_id": 1, "color": "#FF0000"}])
+
+        assert mapping is None
+        assert source == "none"
+
+    def test_reports_none_when_the_printer_is_offline(self):
+        """No live state at completion — the printer dropped off after the
+        print. Nothing to read, and no crash."""
+        with patch("backend.app.services.printer_manager.printer_manager", _patched_pm(None)):
+            mapping, source = _resolve_slot_to_tray_fallback(1, [{"slot_id": 1, "color": "#FF0000"}])
+
+        assert mapping is None
+        assert source == "none"
+
+
+class TestReportUsageUsesTheFallback:
+    """End-to-end through report_usage: the fallback has to reach
+    ``_resolve_global_tray_id`` and change which spool is charged."""
+
+    @staticmethod
+    def _run(tracking, state, spool_by_tag, archive):
+        # The first SELECT fetches the tracking row; every later one fetches the
+        # archive for the colour / type rewrites (#1494, #2563).
+        rows = iter([tracking])
+
+        def _next_row(*_args, **_kwargs):
+            result = MagicMock()
+            result.scalar_one_or_none.return_value = next(rows, archive)
+            return result
+
+        db = AsyncMock()
+        db.execute = AsyncMock(side_effect=_next_row)
+        db.delete = AsyncMock()
+        db.commit = AsyncMock()
+
+        client = AsyncMock()
+        client.find_spool_by_tag = AsyncMock(side_effect=lambda tag: spool_by_tag.get(tag))
+        client.use_spool = AsyncMock()
+
+        pm = _patched_pm(state)
+
+        async def _go():
+            from backend.app.services.spoolman_tracking import report_usage
+
+            with (
+                patch("backend.app.services.spoolman_tracking.async_session", lambda: _AsyncCtx(db)),
+                patch("backend.app.api.routes.settings.get_setting", AsyncMock(return_value="true")),
+                patch(
+                    "backend.app.services.spoolman_tracking._get_spoolman_client_with_fallback",
+                    AsyncMock(return_value=client),
+                ),
+                patch("backend.app.services.spoolman_tracking._get_printer_serial", AsyncMock(return_value="SER")),
+                patch(
+                    "backend.app.services.spoolman_tracking._resolve_spool_id_via_slot_assignment",
+                    AsyncMock(return_value=None),
+                ),
+                patch("backend.app.services.printer_manager.printer_manager", pm),
+            ):
+                await report_usage(printer_id=1, archive_id=42)
+
+        return _go, client
+
+    @pytest.mark.asyncio
+    async def test_mqtt_mapping_charges_the_tray_the_printer_named(self):
+        """One-slot print whose filament actually came from AMS slot 4
+        (global tray 3). With no stored mapping the positional default charges
+        global tray 0 — the wrong spool, and the archive is then rewritten to
+        that spool's colour. The printer's mapping field says otherwise."""
+        tracking = SimpleNamespace(
+            filament_usage=[{"slot_id": 1, "used_g": 25.0, "type": "PLA", "color": "#FF0000"}],
+            ams_trays={
+                "0": {"tray_uuid": "TRAY0UUID", "tag_uid": "", "tray_type": "PLA"},
+                "3": {"tray_uuid": "TRAY3UUID", "tag_uid": "", "tray_type": "PLA"},
+            },
+            slot_to_tray=None,
+            tray_remain_start=None,
+            layer_usage=None,
+            filament_properties=None,
+        )
+        state = _state(mapping=[3])
+        spools = {
+            "TRAY0UUID": {"id": 100, "filament": {"color_hex": "FFFFFF", "material": "PLA"}},
+            "TRAY3UUID": {"id": 300, "filament": {"color_hex": "FF0000", "material": "PLA"}},
+        }
+        archive = SimpleNamespace(filament_color="#FF0000", filament_type="PLA")
+
+        run, client = self._run(tracking, state, spools, archive)
+        await run()
+
+        client.use_spool.assert_awaited_once_with(300, 25.0)
+        # And the visible half of the bug: the archive keeps the red it was
+        # printed in instead of being rewritten to the wrong spool's white.
+        assert archive.filament_color == "#FF0000"
+
+    @pytest.mark.asyncio
+    async def test_a_stored_mapping_is_never_second_guessed(self):
+        """Print start captured the real ams_mapping (LAN print, or a Bambuddy
+        queue job). That is the slicer's own instruction and outranks anything
+        read back off the printer, whose mapping field may still describe an
+        earlier job."""
+        tracking = SimpleNamespace(
+            filament_usage=[{"slot_id": 1, "used_g": 25.0, "type": "PLA", "color": "#FF0000"}],
+            ams_trays={
+                "0": {"tray_uuid": "TRAY0UUID", "tag_uid": "", "tray_type": "PLA"},
+                "3": {"tray_uuid": "TRAY3UUID", "tag_uid": "", "tray_type": "PLA"},
+            },
+            slot_to_tray=[0],
+            tray_remain_start=None,
+            layer_usage=None,
+            filament_properties=None,
+        )
+        state = _state(mapping=[3])
+        spools = {
+            "TRAY0UUID": {"id": 100, "filament": {"color_hex": "FFFFFF", "material": "PLA"}},
+            "TRAY3UUID": {"id": 300, "filament": {"color_hex": "FF0000", "material": "PLA"}},
+        }
+        archive = SimpleNamespace(filament_color="#FF0000", filament_type="PLA")
+
+        run, client = self._run(tracking, state, spools, archive)
+        await run()
+
+        client.use_spool.assert_awaited_once_with(100, 25.0)