소스 검색

Recognise our own print dispatch instead of guessing at a magic number
(#2843 follow-up)

Bambuddy records the project_file behind every print, because that command
names where the sliced file was put and so decides whether the archive can
have a thumbnail and slicer metadata at all. Its own dispatches were told
apart from a slicer's by testing sequence_id against "20000", on the
belief that 20000 was Bambuddy's alone.

It never was. 20000 is the slicer convention Bambuddy copied --
virtual_printer/bind_server documents the slicer sending exactly that
during detect -- and both slicers count up from it. Measured on the wire:
OrcaSlicer dispatched 20000 and then 20001, BambuStudio 20009 and 20010.
So whichever dispatch happened to land on the shared value was filed as
ours and never recorded, and after a slicer restart that is the first
print you send. The test was wrong in the other direction too: it called
every value above 20000 external, including ones we had sent ourselves,
which only stayed invisible because we always send exactly 20000.

Ownership is now established by remembering the job actually dispatched
-- sequence id, file, url and subtask name -- and consuming that marker
on the echo. One-shot deliberately: a slicer reprint of the same file a
moment later is somebody else's print and must not hide behind our last
one.

Nothing about printing or archiving changes. current_project_url and
ams_mapping are both captured before this branch and always were, so the
storage verdict that gates the FTPS sweep is untouched; two tests pin
that, because it is the part that would actually cost archives if it
drifted. What changes is that the diagnostic entry stops lying, and it is
the entry that tells an operator whether their printer stores files
somewhere Bambuddy can read -- which is the whole subject of #2780 and
would have to count, and an undercount there would have been silent.

maziggy 2 주 전
부모
커밋
89ea337612
3개의 변경된 파일148개의 추가작업 그리고 4개의 파일을 삭제
  1. 1 0
      CHANGELOG.md
  2. 31 4
      backend/app/services/bambu_mqtt.py
  3. 116 0
      backend/tests/unit/test_external_dispatch_detection.py

+ 1 - 0
CHANGELOG.md

@@ -5,6 +5,7 @@ All notable changes to Bambuddy will be documented in this file.
 ## [1.2.6b1] - Unreleased
 ## [1.2.6b1] - Unreleased
 
 
 ### Fixed
 ### Fixed
+- **Prints sent from a slicer were sometimes logged as though Bambuddy had sent them (#2843 follow-up)** — Bambuddy records the dispatch behind every print so a support bundle shows where the sliced file went, and it told its own dispatches apart from a slicer's by a sequence number it believed was unique to it. It is not: that number is the slicer convention Bambuddy adopted, and measured on the wire OrcaSlicer counts from it while Bambu Studio counts from the same base a few higher. Whichever dispatch happened to land on the shared value was filed as Bambuddy's own and never recorded — after a slicer restart, that is the first print you send. Bambuddy now recognises its own dispatch by the job it actually sent. Nothing about printing or archiving changed; the entry was diagnostic, but it is the entry that tells you whether a printer stores your files somewhere Bambuddy can read them. Covered by backend tests.
 - **A print with no 3MF could take its filament figures from an unrelated model (#2843, reported by @gyrene2083)** — H2-series and P2S firmware keeps a slicer-sent file on the printer's internal storage, which Bambuddy cannot read, so those prints archive without a 3MF. Bambuddy then looks for the same model in your Library or among earlier prints, which is how a reprint still gets its filament accounted for. The name it searched on was the wrong one. A running print reports the file it is executing — always `Metadata/plate_1.gcode` — and with no 3MF to correct it, that path became the archive's name and `plate_1` became the search term. Every Bambu print has a plate 1, so the search matched on nothing meaningful and took whatever came back: on the maintainer's H2D a 1.6 g Cube was costed from a 207 g four-colour ABS print whose file happened to be named `lid_plate_1.3mf`. The match now uses the model name the printer reports alongside the plate path, a plate name on its own is refused rather than searched for, and a name must match a whole filename instead of merely appearing inside one. A print that cannot be identified is left untracked, which is the honest answer — the previous behaviour was to charge your spools for a model you did not print. Covered by backend tests, including the exact collision measured on the H2D.
 - **A print with no 3MF could take its filament figures from an unrelated model (#2843, reported by @gyrene2083)** — H2-series and P2S firmware keeps a slicer-sent file on the printer's internal storage, which Bambuddy cannot read, so those prints archive without a 3MF. Bambuddy then looks for the same model in your Library or among earlier prints, which is how a reprint still gets its filament accounted for. The name it searched on was the wrong one. A running print reports the file it is executing — always `Metadata/plate_1.gcode` — and with no 3MF to correct it, that path became the archive's name and `plate_1` became the search term. Every Bambu print has a plate 1, so the search matched on nothing meaningful and took whatever came back: on the maintainer's H2D a 1.6 g Cube was costed from a 207 g four-colour ABS print whose file happened to be named `lid_plate_1.3mf`. The match now uses the model name the printer reports alongside the plate path, a plate name on its own is refused rather than searched for, and a name must match a whole filename instead of merely appearing inside one. A print that cannot be identified is left untracked, which is the honest answer — the previous behaviour was to charge your spools for a model you did not print. Covered by backend tests, including the exact collision measured on the H2D.
 - **Timelapses were lost, and written outside the data directory, for any print archived without a 3MF (#2843)** — Every H2-series and P2S print sent from the slicer, so not a rare case. The video downloaded from the printer correctly and was then written next to the data directory rather than inside it, because an archive with no 3MF has no directory of its own and the destination was derived from the missing file's path. In Docker that meant a permission error, retried and discarded twenty-five times over twelve minutes, roughly a hundred connections to the printer for a video that was thrown away each round. Where that location happened to be writable it was worse: the file landed beside the installation, the attach failed anyway, and the stray video stayed there. Bambuddy has had a shared helper for exactly this since #1820 and this was the one place still deriving the path by hand. Timelapses now land in the archive's own folder and attach normally. Covered by backend tests.
 - **Timelapses were lost, and written outside the data directory, for any print archived without a 3MF (#2843)** — Every H2-series and P2S print sent from the slicer, so not a rare case. The video downloaded from the printer correctly and was then written next to the data directory rather than inside it, because an archive with no 3MF has no directory of its own and the destination was derived from the missing file's path. In Docker that meant a permission error, retried and discarded twenty-five times over twelve minutes, roughly a hundred connections to the printer for a video that was thrown away each round. Where that location happened to be writable it was worse: the file landed beside the installation, the attach failed anyway, and the stray video stayed there. Bambuddy has had a shared helper for exactly this since #1820 and this was the one place still deriving the path by hand. Timelapses now land in the archive's own folder and attach normally. Covered by backend tests.
 - **A slot that could not be charged now says so (#2843)** — When a print's filament cannot be read from a 3MF, Bambuddy falls back to the drop in the AMS's own remaining-filament percentage. That needs a reading when the print starts, and a spool without RFID has none until you set a remaining amount by hand — so those slots were skipped in silence. Nothing was deducted and nothing said why, which is indistinguishable from having nothing to deduct. Every other reason for skipping a slot was already logged; this one now is too.
 - **A slot that could not be charged now says so (#2843)** — When a print's filament cannot be read from a 3MF, Bambuddy falls back to the drop in the AMS's own remaining-filament percentage. That needs a reading when the print starts, and a spool without RFID has none until you set a remaining amount by hand — so those slots were skipped in silence. Nothing was deducted and nothing said why, which is indistinguishable from having nothing to deduct. Every other reason for skipping a slot was already logged; this one now is too.

+ 31 - 4
backend/app/services/bambu_mqtt.py

@@ -1267,6 +1267,11 @@ class BambuMQTTClient:
         # by await_cali_ack.
         # by await_cali_ack.
         self._pending_cali_acks: dict[str, dict | None] = {}
         self._pending_cali_acks: dict[str, dict | None] = {}
 
 
+        # Identifies the one project_file *we* dispatched, so its echo on the
+        # topic can be told apart from a slicer's. One-shot: consumed by the
+        # first frame that matches. See _project_file_key.
+        self._own_project_file_key: str | None = None
+
         # Xcam hold timers - OrcaSlicer pattern: ignore incoming data for 3 seconds after command
         # Xcam hold timers - OrcaSlicer pattern: ignore incoming data for 3 seconds after command
         # Key: module_name, Value: timestamp when command was sent
         # Key: module_name, Value: timestamp when command was sent
         self._xcam_hold_start: dict[str, float] = {}
         self._xcam_hold_start: dict[str, float] = {}
@@ -1857,16 +1862,35 @@ class BambuMQTTClient:
             # Diagnostic for #1162 follow-up (X2D + FTS routing): when a
             # Diagnostic for #1162 follow-up (X2D + FTS routing): when a
             # slicer-launched project_file passes through the request topic,
             # slicer-launched project_file passes through the request topic,
             # log the full payload so we can diff Studio's field set against
             # log the full payload so we can diff Studio's field set against
-            # ours. We pin our own sequence_id to "20000" (line ~3195), so
-            # any other value means the command came from Studio/Orca, not
-            # from us.
-            if print_data.get("sequence_id") != "20000":
+            # ours.
+            #
+            # This used to read `sequence_id != "20000"`, on the belief that
+            # 20000 was ours alone. It is not: 20000 is the slicer convention
+            # Bambuddy adopted -- bind_server documents the slicer sending it
+            # during detect, and measured on the wire OrcaSlicer dispatched
+            # 20000 then 20001 while BambuStudio was on 20009/20010, both
+            # counting up from the same base. So the test swallowed whichever
+            # slicer dispatch happened to land on 20000, which on a fresh
+            # slicer start is the first one. Match our own dispatch instead.
+            if self._project_file_key(print_data) == self._own_project_file_key:
+                self._own_project_file_key = None
+            else:
                 logger.info(
                 logger.info(
                     "[%s] External project_file payload: %s",
                     "[%s] External project_file payload: %s",
                     self.serial_number,
                     self.serial_number,
                     json.dumps(print_data),
                     json.dumps(print_data),
                 )
                 )
 
 
+    @staticmethod
+    def _project_file_key(print_data: dict) -> str:
+        """Identity of a project_file dispatch, for telling ours from a slicer's.
+
+        Sequence id alone cannot do it -- every slicer counts up from the same
+        20000 -- so this also carries the file and its destination, which differ
+        between any two real dispatches.
+        """
+        return "|".join(str(print_data.get(field, "")) for field in ("sequence_id", "file", "url", "subtask_name"))
+
     def _debug_on_change(self, key: str, value: object, msg: str, *args: object) -> None:
     def _debug_on_change(self, key: str, value: object, msg: str, *args: object) -> None:
         """``logger.debug``, but only when ``value`` differs from the last call for ``key``.
         """``logger.debug``, but only when ``value`` differs from the last call for ``key``.
 
 
@@ -5844,6 +5868,9 @@ class BambuMQTTClient:
                         command["print"]["nozzle_mapping"] = resolved
                         command["print"]["nozzle_mapping"] = resolved
 
 
             logger.info("[%s] Sending print command: %s", self.serial_number, json.dumps(command))
             logger.info("[%s] Sending print command: %s", self.serial_number, json.dumps(command))
+            # Remember this dispatch so its echo on the topic is recognised as
+            # ours rather than logged as a slicer's.
+            self._own_project_file_key = self._project_file_key(command["print"])
             self._client.publish(self.topic_publish, json.dumps(command), qos=1)
             self._client.publish(self.topic_publish, json.dumps(command), qos=1)
             # Record what we dispatched so /cover can pick the right plate
             # Record what we dispatched so /cover can pick the right plate
             # thumbnail even when the printer's gcode_file echo is just the
             # thumbnail even when the printer's gcode_file echo is just the

+ 116 - 0
backend/tests/unit/test_external_dispatch_detection.py

@@ -0,0 +1,116 @@
+"""Telling our own print dispatch from a slicer's (#2843 follow-up).
+
+The old test was ``sequence_id != "20000"``, on the belief that 20000 was
+Bambuddy's alone. Measured on the wire 2026-08-17: OrcaSlicer dispatched
+``20000`` and then ``20001``, while BambuStudio was on ``20009`` / ``20010`` --
+both counting up from the same base, which is also the value
+``virtual_printer/bind_server`` documents the slicer sending during detect. So
+the check swallowed whichever slicer dispatch landed on 20000, which after a
+slicer restart is the first one.
+
+It matters beyond the log line: counting Studio-versus-Orca dispatches across
+support bundles is how the size of the internal-storage problem gets measured,
+and an undercount there is silent.
+"""
+
+import json
+import logging
+
+import pytest
+
+from backend.app.services.bambu_mqtt import BambuMQTTClient
+
+
+@pytest.fixture
+def client():
+    return BambuMQTTClient(ip_address="192.168.1.100", serial_number="TEST123", access_code="12345678")
+
+
+def _project_file(sequence_id, file="Cube.gcode.3mf", url="ftp://Cube.gcode.3mf", subtask="Cube"):
+    return {
+        "print": {
+            "sequence_id": sequence_id,
+            "command": "project_file",
+            "file": file,
+            "url": url,
+            "subtask_name": subtask,
+            "ams_mapping": [0],
+        }
+    }
+
+
+def _external_lines(caplog):
+    return [r for r in caplog.records if "External project_file payload" in r.getMessage()]
+
+
+class TestSlicerDispatchIsReported:
+    @pytest.mark.parametrize("seq", ["20000", "20001", "20009", "20010"])
+    def test_every_slicer_sequence_id_is_logged(self, client, caplog, seq):
+        """20000 included -- that is the one the old check threw away."""
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            client._handle_request_message(_project_file(seq))
+
+        assert len(_external_lines(caplog)) == 1
+
+    def test_the_payload_is_logged_verbatim(self, client, caplog):
+        """It exists to be diffed against ours, so it has to be complete."""
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            client._handle_request_message(_project_file("20000"))
+
+        logged = json.loads(_external_lines(caplog)[0].getMessage().split("payload: ", 1)[1])
+        assert logged["url"] == "ftp://Cube.gcode.3mf"
+        assert logged["sequence_id"] == "20000"
+
+
+class TestOwnDispatchIsNotReported:
+    def test_our_own_echo_is_recognised(self, client, caplog):
+        """Bambuddy publishes to the topic it subscribes to, so it sees its own
+        dispatch come back."""
+        ours = _project_file("20000", url="ftp://MyPrint.3mf", file="MyPrint.3mf", subtask="MyPrint")
+        client._own_project_file_key = client._project_file_key(ours["print"])
+
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            client._handle_request_message(ours)
+
+        assert _external_lines(caplog) == []
+
+    def test_the_marker_is_consumed(self, client, caplog):
+        """One-shot. A second identical dispatch is somebody else's -- a reprint
+        from the slicer of the same file must not hide behind our last one."""
+        ours = _project_file("20000")
+        client._own_project_file_key = client._project_file_key(ours["print"])
+
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            client._handle_request_message(ours)
+            client._handle_request_message(ours)
+
+        assert len(_external_lines(caplog)) == 1
+
+    def test_a_slicer_sharing_our_sequence_id_is_still_reported(self, client, caplog):
+        """The exact collision that motivated this: same 20000, different file."""
+        ours = _project_file("20000", file="Ours.3mf", url="ftp://Ours.3mf", subtask="Ours")
+        client._own_project_file_key = client._project_file_key(ours["print"])
+
+        with caplog.at_level(logging.INFO, logger="backend.app.services.bambu_mqtt"):
+            client._handle_request_message(_project_file("20000", file="Theirs.3mf", url="brtc://emmc/Theirs.3mf"))
+
+        assert len(_external_lines(caplog)) == 1
+
+
+class TestUnaffectedBehaviour:
+    def test_the_project_url_is_captured_either_way(self, client):
+        """The storage verdict must not depend on who dispatched -- it is read
+        before the ours/theirs test and drives whether the FTPS sweep runs."""
+        ours = _project_file("20000", url="ftp://Ours.3mf", file="Ours.3mf", subtask="Ours")
+        client._own_project_file_key = client._project_file_key(ours["print"])
+        client._handle_request_message(ours)
+        assert client.state.current_project_url == "ftp://Ours.3mf"
+
+        client._handle_request_message(_project_file("20009", url="brtc://emmc/Theirs.3mf"))
+        assert client.state.current_project_url == "brtc://emmc/Theirs.3mf"
+
+    def test_ams_mapping_is_captured_either_way(self, client):
+        ours = _project_file("20000")
+        client._own_project_file_key = client._project_file_key(ours["print"])
+        client._handle_request_message(ours)
+        assert client._captured_ams_mapping == [0]