MQTT: a reconnect never re-sends the old connection's commands

- When a printer's connection dropped and came back on the same paho
  client, paho re-sent every QoS 1 publish still waiting for its
  PUBACK. Bambu printers often never PUBACK (#1164), so a stop from
  hours earlier cancelled the running print and an old project_file
  raised 0500_4004 (#3454).
- on_connect now empties paho's outbox first, before paho re-sends
  and before anything new is published; the log says how many were
  dropped. Covers paho's own reconnect, the socket-close fallback and
  a printer switched back on.
- A retired client empties its outbox too: one stuck in its handshake
  can still connect after it was replaced, with no on_connect left.
- discard_queued_publishes in paho_teardown uses paho 2.x internals;
  without them it warns once per reconnect and carries on.
- Tests drive a real paho client through reconnect() and CONNACK with
  only the socket stubbed, pinning paho's re-send order; CHANGELOG.

CHANGELOG.md

@@ -219,6 +219,7 @@ All notable changes to Bambuddy will be documented in this file.
 - **The frontend build no longer warns about `path` and `crypto` being externalized for the STEP previewer (#2976)** — `occt-import-js`, the Emscripten build behind STEP previews, requires both modules, but only inside its `ENVIRONMENT_IS_NODE` branches; in the browser it loads its `.wasm` from the URL the preview worker passes and draws randomness from `crypto.getRandomValues`. Vite still externalized both and printed two warnings on every build. `vite.config.ts` now drops exactly those two warnings for that one package through `build.rolldownOptions.onLog`, so an externalization anywhere else, or of any other module, still shows.
 
 ### Fixed
+- **A dropped printer connection no longer replays old commands and cancels the print (#3454, reported and diagnosed by @SaadShaya7)** — When the connection to a printer dropped and came back by itself, every command still waiting for the printer's acknowledgement was sent again. Bambu printers often don't acknowledge, so that could be a Stop or a print start from hours earlier: a print 4 hours in was cancelled seconds after the reconnect, and an old print start raised "Device is busy and cannot start new task". Commands from the previous connection are now dropped when it comes back, also when a printer that was switched off is turned on again, and the log says how many. A command sent in the seconds before a drop isn't sent again; click it once more.
 - **Finish photo: the plate is no longer driven to the bottom after a tall print** — With **Restore plate for finish photo** on, Bambuddy lowered the plate after the photo to the print's height + 100 mm, whatever the printer. On a 238 mm print on an H2C that is Z338, past the bottom of its travel: Bambu's own end G-code stops at the print's height + 2 mm when +100 doesn't fit, and the printer does not stop G-code sent over the network at its limits. The plate now goes back exactly where the print's end G-code left it, read from the archived file, and is only raised for the photo when the end G-code left it lower than just above the print (the H2C's doesn't, so its plate stays put). A file whose end position can't be read is not moved at all. Wiki updated.
 - **An archive card counts every print's video** — An archive printed more than once (each plate of a project, or a reprint) counted every print's finish photos on its card, but its video button knew only the latest print's video. The button now shows how many videos the prints have and, when there is more than one, opens the archive, where each print's video plays. A single video still plays in place. The list view and the card's menu do the same.
 - **"Change outcome" in an archive's print list changes it** — The button opened the outcome dialog, which for a print with a verdict only said "Already confirmed as a good part." under "How did your print come out?", with nothing to choose. It now opens as **Change outcome** with Good and Reject offered again, the current one marked, and Cancel to leave it as it was.

backend/app/services/bambu_mqtt.py

@@ -25,7 +25,7 @@ from backend.app.services.hms_actions import HMSAction, get_actions_for_error_co
 from backend.app.services.hms_errors import alert_level_from_print_error, describe_fault
 from backend.app.utils.ams_drying import ACTIVE_DRY_STATUSES, DRY_COUNTDOWN_STALL_SECONDS
 from backend.app.utils.ams_humidity import ams_humidity_percent
-from backend.app.utils.paho_teardown import retire_paho_client
+from backend.app.utils.paho_teardown import discard_queued_publishes, retire_paho_client
 
 logger = logging.getLogger(__name__)
 
@@ -1837,9 +1837,8 @@ class BambuMQTTClient:
         #   → socket-close fallback. There is no running loop on that thread to
         #     hand the rebuilt client, so close the socket and let paho's own
         #     loop detect the broken connection and auto-reconnect (same
-        #     instance, same client_id — queue replay is theoretically possible
-        #     here but those paths have always done socket-close and #1136 was
-        #     specifically triggered from the dispatch path).
+        #     instance, same client_id). paho would re-send its old outbox on
+        #     that reconnect; _on_connect empties it first (#3454).
         logger.warning("[%s] Forcing MQTT reconnect: %s", self.serial_number, reason)
         self._stale_reconnecting = True
         self.state.connected = False
@@ -1895,9 +1894,8 @@ class BambuMQTTClient:
         broken connection and triggers auto-reconnect on the SAME client
         instance. Safe to call from paho's own network thread (the loop
         polls the socket on every iteration and handles a closed socket
-        gracefully). Used as a fallback when hard-reset isn't safe; queue
-        replay remains theoretically possible here but #1136 specifically
-        traced through the dispatch-deadline path which now hard-resets."""
+        gracefully). Used as a fallback when hard-reset isn't safe. The old
+        outbox is not re-sent: _on_connect empties it first (#3454)."""
         if self._client:
             try:
                 sock = self._client.socket()
@@ -1906,8 +1904,30 @@ class BambuMQTTClient:
             except Exception:
                 pass
 
+    def _drop_previous_connection_commands(self, client) -> None:
+        """Forget every command queued on an earlier connection (#3454).
+
+        Called first in on_connect, which paho runs before it re-sends its
+        old outbox. Makes every printer command at most once per connection;
+        a command lost in the seconds before a drop is clicked again."""
+        dropped = discard_queued_publishes(client)
+        if dropped is None:
+            logger.warning(
+                "[%s] Cannot clear paho's outbox on reconnect (paho internals changed); "
+                "commands from the previous connection may be sent again",
+                self.serial_number,
+            )
+        elif dropped:
+            logger.info(
+                "[%s] Dropped %d command(s) queued on the previous MQTT connection",
+                self.serial_number,
+                dropped,
+            )
+
     def _on_connect(self, client, userdata, flags, rc, properties=None):
         if rc == 0:
+            # First, before anything here publishes on the new connection.
+            self._drop_previous_connection_commands(client)
             self.state.connected = True
             self.last_connect_error = None
             self.last_connect_error_name = None
@@ -6347,9 +6367,8 @@ class BambuMQTTClient:
         # busy and cannot start a new task"), and on an A1 mini that error
         # cancels the RUNNING job (#2598). IDLE / FINISH / FAILED are valid
         # start targets; only the active-print states are refused. (A
-        # transport-level QoS-1 replay on reconnect would bypass this guard,
-        # but the dispatch/watchdog reconnect path hard-resets the client with a
-        # fresh client_id, so paho has no inflight project_file to replay there.)
+        # transport-level QoS-1 replay on reconnect would bypass this guard;
+        # _on_connect empties paho's outbox before it can re-send (#3454).)
         if self.state.state in _ACTIVE_PRINT_STATES:
             logger.warning(
                 "[%s] start_print refused: printer busy (gcode_state=%s) — not publishing project_file for %s",

backend/app/utils/paho_teardown.py

@@ -33,6 +33,25 @@ _RETIRE_SLOW_SECONDS = 5.0
 _CALLBACKS = ("on_connect", "on_disconnect", "on_subscribe", "on_message")
 
 
+def discard_queued_publishes(client) -> int | None:
+    """Empty paho's outbox; returns how many publishes it held.
+
+    On a reconnect of the same client paho re-sends every QoS 1 publish still
+    waiting for its PUBACK, right after ``on_connect`` returns. Bambu printers
+    often never PUBACK (#1164), so that can be a ``stop`` from hours ago
+    cancelling the print running now (#3454). Uses paho 2.x internals
+    (``_out_messages`` under ``_out_message_mutex``; the reconnect has already
+    reset the in-flight count), pinned by test_mqtt_reconnect_replay_3454.py.
+    Returns None when paho no longer has them."""
+    try:
+        with client._out_message_mutex:
+            held = len(client._out_messages)
+            client._out_messages.clear()
+    except AttributeError:
+        return None
+    return held
+
+
 def retire_paho_client(client, label: str) -> None:
     """Shut *client* down on a thread of its own and return immediately.
 
@@ -61,6 +80,10 @@ def retire_paho_client(client, label: str) -> None:
 
     def _teardown() -> None:
         started = time.monotonic()
+        # A zombie whose handshake finishes after this would otherwise send its
+        # old outbox on the revived session; with on_connect cleared above,
+        # nothing else empties it (#3454).
+        discard_queued_publishes(client)
         try:
             client.disconnect()
         except Exception:

backend/tests/unit/test_mqtt_reconnect_replay_3454.py

@@ -0,0 +1,171 @@
+"""A printer command is never sent again on a later connection (#3454).
+
+When the connection to a printer dropped and paho reconnected the same client,
+paho re-sent every QoS 1 publish still in its outbox. Bambu's broker doesn't
+reliably PUBACK (#1164), so the outbox held commands from hours ago: a `stop`
+from 09:25 cancelled the print running at 13:29, and a `project_file` raised
+"Device is busy" (0500_4004). The client now empties the outbox in on_connect,
+which paho calls before it re-sends.
+
+These tests drive a real paho client through its own reconnect() and CONNACK
+handling, with only the socket stubbed, so a paho upgrade that changes either
+fails here instead of bringing the replay back.
+"""
+
+import json
+import struct
+import time
+from unittest.mock import MagicMock, patch
+
+import paho.mqtt.client as mqtt
+import pytest
+
+from backend.app.services.bambu_mqtt import BambuMQTTClient
+from backend.app.utils.paho_teardown import retire_paho_client
+
+STOP = json.dumps({"print": {"command": "stop", "sequence_id": "1"}})
+PROJECT_FILE = json.dumps({"print": {"command": "project_file", "sequence_id": "2"}})
+
+
+def _paho() -> mqtt.Client:
+    return mqtt.Client(
+        callback_api_version=mqtt.CallbackAPIVersion.VERSION2,
+        client_id="bambuddy_test_3454",
+        protocol=mqtt.MQTTv311,
+    )
+
+
+def _queue_unacked(client: mqtt.Client, topic: str, *payloads: str) -> None:
+    """Commands sent on the old connection whose PUBACK never came."""
+    for payload in payloads:
+        client.publish(topic, payload, qos=1)  # no socket: stays in the outbox
+    for message in client._out_messages.values():
+        message.state = mqtt.mqtt_ms_wait_for_puback
+        client._inflight_messages += 1
+
+
+def _reconnect(client: mqtt.Client) -> list[str]:
+    """paho's own reconnect() of the same client, then its CONNACK handling,
+    with only the socket stubbed; returns the payloads put on the wire."""
+    sent: list[str] = []
+
+    def send_publish(mid, topic, payload=b"", *args, **kwargs):
+        sent.append(payload.decode() if isinstance(payload, bytes) else payload)
+        return mqtt.MQTTErrorCode.MQTT_ERR_SUCCESS
+
+    sock = MagicMock()
+    sock.send.side_effect = len  # every write goes out whole
+    if not client._host:
+        client.connect_async("192.0.2.1", 8883)
+    with (
+        patch.object(client, "_create_socket", return_value=sock),
+        patch.object(client, "_send_connect", return_value=mqtt.MQTTErrorCode.MQTT_ERR_SUCCESS),
+        patch.object(client, "_send_publish", side_effect=send_publish),
+    ):
+        assert client.reconnect() == mqtt.MQTTErrorCode.MQTT_ERR_SUCCESS
+        client._in_packet = {"remaining_length": 2, "packet": struct.pack("!BB", 0, 0)}
+        client._handle_connack()
+    return sent
+
+
+@pytest.fixture
+def printer():
+    printer = BambuMQTTClient(
+        ip_address="192.168.1.100", serial_number="SN3454", access_code="12345678", model="A1 mini"
+    )
+    paho = _paho()
+    paho.on_connect = printer._on_connect
+    printer._client = paho
+    return printer
+
+
+def _commands(sent: list[str]) -> list[str]:
+    return [json.loads(p).get("print", json.loads(p).get("pushing", {})).get("command") for p in sent]
+
+
+def test_paho_re_sends_the_old_outbox_after_on_connect():
+    # paho's own behaviour, which the fix relies on: the outbox survives a
+    # reconnect and goes out again, only after on_connect has run, and the
+    # in-flight count has been reset to 0 by then.
+    client = _paho()
+    seen_by_on_connect: list[tuple[int, int]] = []
+    client.on_connect = lambda c, *a: seen_by_on_connect.append((len(c._out_messages), c._inflight_messages))
+    _queue_unacked(client, "device/SN3454/request", STOP, PROJECT_FILE)
+
+    sent = _reconnect(client)
+
+    assert seen_by_on_connect == [(2, 0)]
+    assert sent == [STOP, PROJECT_FILE]
+
+
+def test_a_stale_stop_and_project_file_are_not_sent_again(printer):
+    _queue_unacked(printer._client, printer.topic_publish, STOP, PROJECT_FILE)
+
+    sent = _reconnect(printer._client)
+
+    assert "stop" not in _commands(sent)
+    assert "project_file" not in _commands(sent)
+    assert printer.state.connected is True
+
+
+def test_commands_the_new_connection_sends_are_kept(printer):
+    _queue_unacked(printer._client, printer.topic_publish, STOP)
+
+    sent = _reconnect(printer._client)
+
+    # on_connect asks for a full status push on the new connection.
+    assert "pushall" in _commands(sent)
+    assert sent.count(STOP) == 0
+    # The outbox holds only the new connection's commands, each counted once
+    # as in flight, so paho's ceiling isn't eaten by dropped ones.
+    outbox = list(printer._client._out_messages.values())
+    assert outbox
+    assert STOP not in [m.payload.decode() for m in outbox]
+    assert printer._client._inflight_messages == len(outbox)
+
+
+def test_the_virtual_printer_bridges_commands_are_dropped_too(printer):
+    # Slicer commands forwarded by a virtual printer go through publish_raw.
+    printer.publish_raw(printer.topic_publish, PROJECT_FILE)
+    for message in printer._client._out_messages.values():
+        message.state = mqtt.mqtt_ms_wait_for_puback
+
+    assert PROJECT_FILE not in _reconnect(printer._client)
+
+
+def test_dropping_is_logged_with_the_count(printer, caplog):
+    _queue_unacked(printer._client, printer.topic_publish, STOP, PROJECT_FILE)
+
+    with caplog.at_level("INFO", logger="backend.app.services.bambu_mqtt"):
+        _reconnect(printer._client)
+
+    assert "Dropped 2 command(s) queued on the previous MQTT connection" in caplog.text
+
+
+def test_paho_without_those_internals_warns(printer, caplog):
+    class OtherPaho:
+        def subscribe(self, *a, **k):
+            return (mqtt.MQTT_ERR_SUCCESS, 1)
+
+        def publish(self, *a, **k):
+            return mqtt.MQTTMessageInfo(1)
+
+    with caplog.at_level("WARNING", logger="backend.app.services.bambu_mqtt"):
+        printer._drop_previous_connection_commands(OtherPaho())
+
+    assert "Cannot clear paho's outbox on reconnect" in caplog.text
+
+
+def test_a_retired_client_keeps_no_outbox_to_replay():
+    # A client retired while stuck in its TLS handshake can still finish it
+    # and connect; its on_connect is gone, so the outbox must be too.
+    client = _paho()
+    _queue_unacked(client, "device/SN3454/request", STOP)
+    with patch.object(client, "loop_stop"), patch.object(client, "disconnect"):
+        retire_paho_client(client, "SN3454")
+        for _ in range(200):
+            if not client._out_messages:
+                break
+            time.sleep(0.01)
+
+    assert STOP not in _reconnect(client)