Explorar o código

● fix(vp): stop enforcing MQTT keepalive 1.5x to match real Bambu firmware (#1548)

  Round 1 (b6636053 + 4ffefa60) shipped the keepalive parser, 1.5x idle
  disconnect per MQTT spec section 4.4, and a per-minute status-push
  diagnostic. Reporter's follow-up pcap showed the round-1 logic was
  correct as designed, but the actual root cause sits one layer down:
  the same OrcaSlicer install that stays connected to a real Bambu P1S
  indefinitely sends zero MQTT packets after the initial CONNECT /
  SUBSCRIBE / pushall / get_version burst - no PINGREQ at all - so any
  spec-compliant server disconnects it at keep_alive x 1.5.

  Real Bambu firmware does not enforce section 4.4. The reporter's
  identical Orca install holds idle sessions against real hardware on
  the same network. Spec compliance was itself the regression.

  Fix: after CONNECT/auth, drop the application-level read timeout
  entirely (read_timeout = None) and set SO_KEEPALIVE on the underlying
  socket so the OS TCP stack reaps dead connections within a few
  minutes. The 60s pre-CONNECT cap is preserved - a client that opens
  TCP but never sends CONNECT still gets reaped. Negotiated keepalive
  is still parsed and now logged at INFO ("MQTT client X authenticated
  (negotiated keepalive=Ys, idle disconnect disabled)") for support-
  bundle visibility.

  After this ships, OrcaSlicer should stay connected to the VP
  indefinitely while idle and reconnect cleanly on real network drops.
  The publish_json code -4 and -6010 errors reported in the original
  thread were downstream of this disconnect and should also clear.
maziggy hai 3 meses
pai
achega
7a9c78c32c

A diferenza do arquivo foi suprimida porque é demasiado grande
+ 0 - 0
CHANGELOG.md


+ 32 - 11
backend/app/services/virtual_printer/mqtt_server.py

@@ -9,6 +9,7 @@ import copy
 import hmac
 import json
 import logging
+import socket
 import ssl
 from collections.abc import Callable
 from pathlib import Path
@@ -519,10 +520,14 @@ class SimpleMQTTServer:
 
         authenticated = False
         # Per-packet read timeout. Before CONNECT we default to 60 s so a
-        # client that opens TCP but never sends anything still gets reaped;
-        # after CONNECT the value is updated to 1.5× the keepalive the
-        # client negotiated (MQTT spec §4.4). ``None`` means no timeout,
-        # which is what spec §3.1.2.10 mandates for keep_alive == 0.
+        # client that opens TCP but never sends anything still gets reaped.
+        # After CONNECT we drop the application-level read timeout entirely
+        # and rely on TCP keepalive (SO_KEEPALIVE) to detect dead connections
+        # — this matches real Bambu firmware, which does not enforce MQTT
+        # spec §4.4's 1.5× idle disconnect (#1548 round 2). OrcaSlicer's
+        # MQTT client on some platforms does not emit PINGREQ at all on idle
+        # connections; the same install that stays connected to a real P1S
+        # indefinitely was disconnecting from us at keepalive×1.5.
         read_timeout: float | None = 60.0
 
         try:
@@ -565,13 +570,29 @@ class SimpleMQTTServer:
                         self._record_auth_failure(source_ip)
                         break
                     self._clear_auth_failures(source_ip)
-                    # Honour the client's negotiated keepalive (#1548). Before
-                    # this fix, the hardcoded 60 s above would close
-                    # OrcaSlicer's idle connection at the keepalive boundary
-                    # instead of waiting 1.5× as the spec requires — Orca
-                    # sends PINGREQ within its own keepalive interval but
-                    # we'd already have closed the socket.
-                    read_timeout = keep_alive * 1.5 if keep_alive > 0 else None
+                    # Drop the application-level read timeout; rely on
+                    # SO_KEEPALIVE below for dead-connection detection.
+                    # Real Bambu firmware does the same — accept any
+                    # negotiated keepalive but never enforce §4.4's 1.5×
+                    # disconnect on the otherwise-idle MQTT session
+                    # (#1548 round 2). keep_alive is logged for support
+                    # bundles but no longer drives a disconnect.
+                    read_timeout = None
+                    logger.info(
+                        "%sMQTT client %s authenticated (negotiated keepalive=%ds, idle disconnect disabled)",
+                        self._log_prefix,
+                        client_id,
+                        keep_alive,
+                    )
+                    # Enable TCP keepalive so a hard network drop is detected
+                    # by the OS within a few minutes rather than waiting for
+                    # the next outbound write to ECONNRESET.
+                    sock = writer.get_extra_info("socket")
+                    if sock is not None:
+                        try:
+                            sock.setsockopt(socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1)
+                        except OSError as e:
+                            logger.debug("%sFailed to set SO_KEEPALIVE on %s: %s", self._log_prefix, client_id, e)
                     # Register client for periodic status pushes; start with
                     # self.serial as the fallback until we learn the slicer's
                     # preferred serial from the first SUBSCRIBE/PUBLISH.

+ 86 - 23
backend/tests/unit/test_vp_mqtt_server.py

@@ -276,16 +276,24 @@ class TestHandleConnectKeepalive:
         assert result == (False, 0)
 
 
-class TestHandleClientHonoursKeepalive:
-    """`_handle_client` must use the client-negotiated keepalive for its
-    read-loop timeout, not the hardcoded 60 s default (#1548)."""
+class TestHandleClientIdleConnection:
+    """`_handle_client` must NOT close idle authenticated clients on a
+    keepalive boundary (#1548 round 2).
+
+    Round 1 shipped the keepalive parser + 1.5× read timeout per MQTT spec
+    §4.4. The reporter then confirmed that the same OrcaSlicer install which
+    stays connected to a real Bambu P1S indefinitely was being disconnected
+    by Bambuddy at exactly ``keep_alive × 1.5`` — pcap showed Orca sends
+    zero MQTT packets after the initial burst (no PINGREQ at all). Real
+    Bambu firmware does not enforce §4.4; we now match that and rely on
+    TCP keepalive (SO_KEEPALIVE) for dead-connection detection.
+    """
 
     @pytest.mark.asyncio
     async def test_idle_client_kept_alive_beyond_60s_when_keepalive_is_long(self):
-        """The literal #1548 repro: a client negotiates keepalive=180 and
-        then sits idle. Pre-fix the read loop closed the connection after
-        60 s (hardcoded). Post-fix the timeout is 1.5×180=270 s — so the
-        connection is still open after the original 60 s boundary."""
+        """A client negotiates keepalive=180 and then sits idle. Pre-round-1
+        the read loop closed the connection after a hardcoded 60 s. Now the
+        connection stays open indefinitely."""
         server = _make_server()
         server._running = True
 
@@ -303,7 +311,7 @@ class TestHandleClientHonoursKeepalive:
         writer.drain = AsyncMock()
         writer.close = MagicMock()
         writer.wait_closed = AsyncMock()
-        writer.get_extra_info = MagicMock(return_value=("1.2.3.4", 12345))
+        writer.get_extra_info = MagicMock(side_effect=lambda name: ("1.2.3.4", 12345) if name == "peername" else None)
 
         # Patch the post-auth status-report send so the handler doesn't
         # depend on a real serial/payload path.
@@ -331,9 +339,12 @@ class TestHandleClientHonoursKeepalive:
             pass
 
     @pytest.mark.asyncio
-    async def test_idle_client_closed_after_one_and_a_half_times_keepalive(self):
-        """Tight verification: keepalive=2 must close the connection in
-        ~3 s (1.5×) of idle, well above the noise floor for an async test."""
+    async def test_idle_client_stays_open_past_one_and_a_half_times_keepalive(self):
+        """Round-2 regression guard: a client negotiates keepalive=2 and
+        then sits idle. Round 1 would have closed at ~3 s (1.5×). Now the
+        handler must still be running well past that boundary — the only
+        thing that ends the loop is a DISCONNECT, peer close, or server
+        shutdown."""
         server = _make_server()
         server._running = True
 
@@ -348,22 +359,74 @@ class TestHandleClientHonoursKeepalive:
         writer.drain = AsyncMock()
         writer.close = MagicMock()
         writer.wait_closed = AsyncMock()
-        writer.get_extra_info = MagicMock(return_value=("1.2.3.4", 12345))
+        writer.get_extra_info = MagicMock(side_effect=lambda name: ("1.2.3.4", 12345) if name == "peername" else None)
         server._send_status_report = AsyncMock()
 
-        start = asyncio.get_event_loop().time()
-        await server._handle_client(reader, writer)
-        elapsed = asyncio.get_event_loop().time() - start
+        task = asyncio.create_task(server._handle_client(reader, writer))
+
+        # Give the loop time to process CONNECT and settle into the idle
+        # read. 4 s is well past round-1's 3 s timeout and any conceivable
+        # async-scheduler drift.
+        await asyncio.sleep(4.0)
+
+        assert not task.done(), "handler must still be waiting on idle reader"
+        assert not writer.close.called, "connection must not be closed by keepalive timeout"
+
+        task.cancel()
+        try:
+            await task
+        except asyncio.CancelledError:
+            pass
+
+    @pytest.mark.asyncio
+    async def test_so_keepalive_set_on_socket_after_connect(self):
+        """The application-level read timeout was removed; TCP keepalive
+        replaces it for dead-connection detection. Verify the handler sets
+        SO_KEEPALIVE on the underlying socket the moment auth succeeds."""
+        import socket
+
+        server = _make_server()
+        server._running = True
+
+        reader = asyncio.StreamReader()
+        connect_payload = _build_connect_payload(keep_alive=60)
+        rl = len(connect_payload)
+        assert rl < 128
+        reader.feed_data(bytes([0x10, rl]) + connect_payload)
+
+        sock = MagicMock()
+        writer = MagicMock()
+        writer.write = MagicMock()
+        writer.drain = AsyncMock()
+        writer.close = MagicMock()
+        writer.wait_closed = AsyncMock()
+
+        def _get_extra_info(name):
+            if name == "socket":
+                return sock
+            if name == "peername":
+                return ("1.2.3.4", 12345)
+            return None
+
+        writer.get_extra_info = MagicMock(side_effect=_get_extra_info)
+        server._send_status_report = AsyncMock()
+
+        task = asyncio.create_task(server._handle_client(reader, writer))
+        await asyncio.sleep(0.2)
+        task.cancel()
+        try:
+            await task
+        except asyncio.CancelledError:
+            pass
 
-        # 1.5×2s = 3s expected. Allow ±1s slop for the read of CONNECT
-        # itself + scheduler jitter on a loaded CI box.
-        assert 2.0 < elapsed < 4.5, f"expected ~3s timeout, got {elapsed:.2f}s"
+        sock.setsockopt.assert_any_call(socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1)
 
     @pytest.mark.asyncio
-    async def test_pingreq_resets_idle_timeout(self):
-        """A PINGREQ within the keepalive window must keep the connection
-        open — the per-packet read timeout is restarted on every byte
-        delivered, so the next idle window is measured from the PINGREQ."""
+    async def test_pingreq_is_processed_and_does_not_close_connection(self):
+        """PINGREQ from a still-active client must be honoured (PINGRESP
+        sent, connection kept open). After round 2 there is no idle timeout
+        for PINGREQ to "reset" — the relevant invariant is that the packet
+        is parsed and routed without disconnecting."""
         server = _make_server()
         server._running = True
 
@@ -378,7 +441,7 @@ class TestHandleClientHonoursKeepalive:
         writer.drain = AsyncMock()
         writer.close = MagicMock()
         writer.wait_closed = AsyncMock()
-        writer.get_extra_info = MagicMock(return_value=("1.2.3.4", 12345))
+        writer.get_extra_info = MagicMock(side_effect=lambda name: ("1.2.3.4", 12345) if name == "peername" else None)
         server._send_status_report = AsyncMock()
 
         async def _drive():

Algúns arquivos non se mostraron porque demasiados arquivos cambiaron neste cambio