Browse Source

fix(mqtt): fail-safe request topic subscription for ams_mapping capture (#405)

Some printer MQTT brokers (e.g. P1S) reject subscriptions to the request
topic by killing the TCP connection, causing a disconnect loop. The request
topic subscription for ams_mapping capture is now fail-safe with two
detection paths:

- SUBACK rejection: on_subscribe callback detects failure code 0x80
- Broker kills connection: on_disconnect detects disconnect within 10s of
  unconfirmed subscription attempt

After detection, the request topic is disabled for that printer and
reconnection succeeds with only the report topic. Printers that support
the request topic (e.g. X1E, H2D) get ams_mapping capture; printers that
don't (e.g. P1S) gracefully degrade to tray_now-based tracking.
maziggy 3 months ago
parent
commit
a4fad2d2f5
3 changed files with 174 additions and 2 deletions
  1. 1 1
      CHANGELOG.md
  2. 62 1
      backend/app/services/bambu_mqtt.py
  3. 111 0
      backend/tests/unit/services/test_bambu_mqtt.py

+ 1 - 1
CHANGELOG.md

@@ -49,7 +49,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **Printer Queue Widget Shows "Archive #null" for File Manager Prints** ([#364](https://github.com/maziggy/bambuddy/issues/364)) — The "Next in queue" widget on the printer card only checked `archive_name` and `archive_id` when displaying the queued item name. Queue items from the file manager have `library_file_name` and `library_file_id` instead, so the widget displayed "Archive #null". Now falls back to `library_file_name` and `library_file_id`, matching the Queue page display logic.
 - **Inventory Usage Not Tracked for Remapped AMS Slots** ([#364](https://github.com/maziggy/bambuddy/issues/364)) — When reprinting an archive with a different AMS slot mapping (e.g. changing from slot A1 to C4 in the mapping modal), the usage tracker used the default 3MF slot-to-tray mapping instead of the actual mapping from the print command. The `ams_mapping` from reprint, library print, and queue print commands is now stored and used as the highest-priority mapping source for usage tracking.
 - **Inventory Usage Not Tracked for Slicer-Initiated Prints on H2D** ([#364](https://github.com/maziggy/bambuddy/issues/364)) — On H2D printers, the AMS `tray_now` field is always 255 in MQTT data. The actual tray is resolved via the snow field ~44 seconds after print start, but reverts to "unloaded" when the AMS retracts filament at completion. The usage tracker now tracks `last_loaded_tray` — the last valid tray seen during printing — as a fallback when both `tray_now` at start and at completion are invalid. Also captures `tray_now` at print start for printers that report a valid value before the RUNNING state.
-- **Inventory Usage Wrong Tray for Slicer-Initiated Prints** ([#364](https://github.com/maziggy/bambuddy/issues/364)) — When a print was started from an external slicer (BambuStudio, OrcaSlicer, Bambu Handy), Bambuddy never saw the `ams_mapping` the slicer sent, because it only subscribed to the printer's report topic. The usage tracker fell back to `tray_now` which could resolve to the wrong AMS tray (e.g., Black PLA at A2 instead of Green PLA at A4 on H2D Pro). Now subscribes to the MQTT request topic to intercept print commands from any source, capturing the `ams_mapping` universally — regardless of who starts the print.
+- **Inventory Usage Wrong Tray for Slicer-Initiated Prints** ([#364](https://github.com/maziggy/bambuddy/issues/364)) — When a print was started from an external slicer (BambuStudio, OrcaSlicer, Bambu Handy), Bambuddy never saw the `ams_mapping` the slicer sent, because it only subscribed to the printer's report topic. The usage tracker fell back to `tray_now` which could resolve to the wrong AMS tray (e.g., Black PLA at A2 instead of Green PLA at A4 on H2D Pro). Now subscribes to the MQTT request topic to intercept print commands from any source, capturing the `ams_mapping` universally — regardless of who starts the print. The request topic subscription is fail-safe: if the printer's MQTT broker rejects it (e.g., P1S), Bambuddy detects the rejection via SUBACK or disconnect timing and gracefully disables the subscription for that printer, falling back to the existing `tray_now`-based tracking without breaking the MQTT connection.
 - **P1S Timelapse Not Detected — AVI Format Support** ([#405](https://github.com/maziggy/bambuddy/issues/405)) — P1-series printers save timelapse videos as `.avi` (MJPEG), but the timelapse scanner only looked for `.mp4` files — so P1S timelapses were never found or attached to archives. Now discovers both `.mp4` and `.avi` timelapse files across all FTP directories (`/timelapse`, `/timelapse/video`, `/record`, `/recording`). AVI files are saved immediately and converted to MP4 in a non-blocking background task using FFmpeg with `-threads 1` and `nice -n 19` to minimize CPU impact on Raspberry Pi. If FFmpeg is unavailable, the AVI is served as-is with the correct MIME type. The manual "Scan for Timelapse" route also searches the additional directories used by P1-series printers.
 - **Timelapse Upload & Remove** ([#406](https://github.com/maziggy/bambuddy/issues/406)) — When the auto-scan attaches the wrong timelapse (e.g., from a different print), there was no way to remove it or attach the correct one. Added "Upload Timelapse" and "Remove Timelapse" context menu items. Upload accepts `.mp4`, `.avi`, and `.mkv` files (non-MP4 auto-converted in background). Remove deletes the file and clears the database reference. Both actions are permission-gated and available in grid and list views.
 - **Spool Assignments Falsely Unlinked After Print Due to Color Variation** — The auto-unlink logic compared AMS tray colors against saved fingerprints using exact hex match. RFID sensors report slightly different color values across reads (e.g. `7CC4D5FF` vs `56B7E6FF` for the same spool, Euclidean distance ~43.6). Now uses a color similarity function with a tolerance threshold of 50, preventing false unlinks from minor RFID/firmware color variations while still detecting genuinely different spools.

+ 62 - 1
backend/app/services/bambu_mqtt.py

@@ -304,6 +304,14 @@ class BambuMQTTClient:
         # Intercepts slicer/Bambuddy print commands to get the slot-to-tray mapping
         self._captured_ams_mapping: list[int] | None = None
 
+        # Request topic subscription tracking
+        # Some printer MQTT brokers (e.g. P1S) reject subscriptions to the request
+        # topic by killing the TCP connection. We detect this and gracefully degrade.
+        self._request_topic_supported: bool = True
+        self._request_topic_sub_mid: int | None = None
+        self._request_topic_sub_time: float = 0.0
+        self._request_topic_confirmed: bool = False
+
     @property
     def topic_subscribe(self) -> str:
         return f"device/{self.serial_number}/report"
@@ -337,7 +345,19 @@ class BambuMQTTClient:
         if rc == 0:
             self.state.connected = True
             client.subscribe(self.topic_subscribe)
-            client.subscribe(self.topic_publish)  # Intercept print commands for ams_mapping
+            # Subscribe to request topic for ams_mapping capture (if supported by broker)
+            if self._request_topic_supported:
+                result, mid = client.subscribe(self.topic_publish)
+                if result == mqtt.MQTT_ERR_SUCCESS:
+                    self._request_topic_sub_mid = mid
+                    self._request_topic_sub_time = time.time()
+                    self._request_topic_confirmed = False
+                else:
+                    logger.warning(
+                        "[%s] Failed to send request topic subscription",
+                        self.serial_number,
+                    )
+                    self._request_topic_supported = False
             # Request full status update (includes nozzle info in push_status response)
             self._request_push_all()
             # Request firmware version info
@@ -352,6 +372,29 @@ class BambuMQTTClient:
         else:
             self.state.connected = False
 
+    def _on_subscribe(self, client, userdata, mid, reason_code_list, properties=None):
+        """Handle SUBACK responses to detect request topic subscription rejection."""
+        if mid == self._request_topic_sub_mid:
+            for rc in reason_code_list:
+                if rc.is_failure:
+                    logger.warning(
+                        "[%s] Request topic subscription rejected (code=%d: %s). "
+                        "ams_mapping capture from slicer-initiated prints unavailable.",
+                        self.serial_number,
+                        rc.value,
+                        rc.getName(),
+                    )
+                    self._request_topic_supported = False
+                else:
+                    logger.info(
+                        "[%s] Request topic subscription accepted. "
+                        "ams_mapping capture enabled for slicer-initiated prints.",
+                        self.serial_number,
+                    )
+                    self._request_topic_confirmed = True
+            self._request_topic_sub_mid = None
+            self._request_topic_sub_time = 0.0
+
     def _on_disconnect(self, client, userdata, disconnect_flags=None, rc=None, properties=None):
         # Ignore spurious disconnect callbacks if we've received a message recently
         # Paho-mqtt sometimes fires disconnect callbacks while the connection is still active
@@ -363,6 +406,23 @@ class BambuMQTTClient:
             return
 
         logger.warning("[%s] MQTT disconnected: rc=%s, flags=%s", self.serial_number, rc, disconnect_flags)
+
+        # Detect if request topic subscription caused the disconnect.
+        # If we just subscribed and got disconnected before any SUBACK confirmation,
+        # the broker likely killed the connection due to the unauthorized subscription.
+        if (
+            self._request_topic_sub_time > 0
+            and not self._request_topic_confirmed
+            and time.time() - self._request_topic_sub_time < 10.0
+        ):
+            logger.warning(
+                "[%s] Disconnected shortly after request topic subscription. Disabling request topic for this printer.",
+                self.serial_number,
+            )
+            self._request_topic_supported = False
+        self._request_topic_sub_mid = None
+        self._request_topic_sub_time = 0.0
+
         self.state.connected = False
         if self.on_state_change:
             self.on_state_change(self.state)
@@ -2105,6 +2165,7 @@ class BambuMQTTClient:
         self._client.username_pw_set("bblp", self.access_code)
         self._client.on_connect = self._on_connect
         self._client.on_disconnect = self._on_disconnect
+        self._client.on_subscribe = self._on_subscribe
         self._client.on_message = self._on_message
 
         # TLS setup - Bambu uses self-signed certs

+ 111 - 0
backend/tests/unit/services/test_bambu_mqtt.py

@@ -860,6 +860,117 @@ class TestNozzleRackData:
         assert mqtt_client.state.nozzles[1].nozzle_diameter == "0.6"
 
 
+class TestRequestTopicFailSafe:
+    """Tests for graceful degradation when broker rejects request topic subscription."""
+
+    @pytest.fixture
+    def mqtt_client(self):
+        from backend.app.services.bambu_mqtt import BambuMQTTClient
+
+        client = BambuMQTTClient(
+            ip_address="192.168.1.100",
+            serial_number="TEST123",
+            access_code="12345678",
+        )
+        return client
+
+    def test_request_topic_supported_by_default(self, mqtt_client):
+        """Request topic subscription is attempted by default."""
+        assert mqtt_client._request_topic_supported is True
+        assert mqtt_client._request_topic_confirmed is False
+
+    def test_on_subscribe_confirms_success(self, mqtt_client):
+        """Successful SUBACK marks request topic as confirmed."""
+        from paho.mqtt.reasoncodes import ReasonCode
+
+        mqtt_client._request_topic_sub_mid = 42
+        rc = ReasonCode(9, identifier=0)  # SUBACK packetType=9, QoS 0 = success
+        mqtt_client._on_subscribe(None, None, 42, [rc], None)
+
+        assert mqtt_client._request_topic_confirmed is True
+        assert mqtt_client._request_topic_supported is True
+        assert mqtt_client._request_topic_sub_mid is None
+        assert mqtt_client._request_topic_sub_time == 0.0
+
+    def test_on_subscribe_detects_rejection(self, mqtt_client):
+        """SUBACK with failure code disables request topic."""
+        from paho.mqtt.reasoncodes import ReasonCode
+
+        mqtt_client._request_topic_sub_mid = 42
+        rc = ReasonCode(9, identifier=0x80)  # SUBACK packetType=9, 0x80 = failure
+        mqtt_client._on_subscribe(None, None, 42, [rc], None)
+
+        assert mqtt_client._request_topic_supported is False
+        assert mqtt_client._request_topic_confirmed is False
+
+    def test_on_subscribe_ignores_other_mids(self, mqtt_client):
+        """SUBACK for other subscriptions (e.g. report topic) is ignored."""
+        from paho.mqtt.reasoncodes import ReasonCode
+
+        mqtt_client._request_topic_sub_mid = 42
+        rc = ReasonCode(9, identifier=0x80)
+        mqtt_client._on_subscribe(None, None, 99, [rc], None)
+
+        # Not affected — mid doesn't match
+        assert mqtt_client._request_topic_supported is True
+
+    def test_disconnect_after_subscription_disables_topic(self, mqtt_client):
+        """Disconnect within 10s of subscription attempt disables request topic."""
+        import time
+
+        mqtt_client._request_topic_sub_time = time.time()
+        mqtt_client._request_topic_confirmed = False
+        mqtt_client._last_message_time = 0.0
+
+        mqtt_client._on_disconnect(None, None)
+
+        assert mqtt_client._request_topic_supported is False
+        assert mqtt_client._request_topic_sub_time == 0.0
+
+    def test_disconnect_after_confirmation_does_not_disable(self, mqtt_client):
+        """Disconnect after SUBACK confirmation keeps request topic enabled."""
+        import time
+
+        mqtt_client._request_topic_sub_time = time.time()
+        mqtt_client._request_topic_confirmed = True
+        mqtt_client._last_message_time = 0.0
+
+        mqtt_client._on_disconnect(None, None)
+
+        assert mqtt_client._request_topic_supported is True
+
+    def test_late_disconnect_does_not_disable(self, mqtt_client):
+        """Disconnect long after subscription (>10s) doesn't blame request topic."""
+        import time
+
+        mqtt_client._request_topic_sub_time = time.time() - 30.0
+        mqtt_client._request_topic_confirmed = False
+        mqtt_client._last_message_time = 0.0
+
+        mqtt_client._on_disconnect(None, None)
+
+        assert mqtt_client._request_topic_supported is True
+
+    def test_on_connect_skips_request_topic_when_unsupported(self, mqtt_client):
+        """After marking unsupported, reconnect skips request topic subscription."""
+        mqtt_client._request_topic_supported = False
+
+        subscribe_calls = []
+        mock_client = type(
+            "MockClient",
+            (),
+            {
+                "subscribe": lambda self, topic: subscribe_calls.append(topic) or (0, 1),
+            },
+        )()
+
+        mqtt_client._on_connect(mock_client, None, None, 0)
+
+        # Only report topic subscribed, not request topic
+        assert len(subscribe_calls) == 1
+        assert subscribe_calls[0] == mqtt_client.topic_subscribe
+
+
 class TestRequestTopicAmsMapping:
     """Tests for capturing ams_mapping from the MQTT request topic."""