From 7e33cc9eda2f49c45be94f73469cbd4cc8b86f52 Mon Sep 17 00:00:00 2001 From: viewit Date: Tue, 4 Aug 2026 14:44:51 +0200 Subject: [PATCH] fix(mqtt): detect a dead printer connection promptly instead of hanging offline detection forever Discovered while testing the smart-plug power-switch feature: unplugging the printer left the dashboard stuck showing it as online/"ready" indefinitely. Live-tested against a real printer to isolate two independent, compounding causes: 1. The MQTT socket had no TCP keepalive. A connection killed without a clean TCP close (unplugged, not a graceful shutdown) looks alive to the OS for as long as its default dead-connection timeout - 15+ minutes on Linux - since a send on a half-open connection is buffered by the kernel and doesn't fail immediately. Fixed with SO_KEEPALIVE (short idle/interval/count) plus TCP_USER_TIMEOUT, since keepalive probes alone only fire on an idle connection - verified live that a printer disappearing while a send was still in flight (the common case, since the poll loop sends every few seconds) instead falls back to the far slower normal TCP retransmission timer, which keepalive settings don't affect at all. 2. Even after the socket was correctly detected as dead, the status poll loop could hang indefinitely inside publish() waiting for a reconnect attempt already running on the MQTT reader thread (the Issue #105 reconnect-lock serialization), and therefore never reached the is_connected() check that flips kobra_state to "offline". _reconnect() now takes wait_if_in_progress/persist flags so the poll loop's call returns immediately with at most one attempt instead of blocking through someone else's multi-minute backoff loop - persistent retrying stays the reader thread's job. A disconnected printer is now detected and reflected on the dashboard within about 15 seconds. Live-verified across repeated disconnect/ reconnect cycles that no sockets, threads, or file descriptors are left behind (checked via /proc//fd and /proc//task) - the transient FIN-WAIT-2 entries seen while the printer's TLS service is still booting belong to the kernel's own connection teardown, not to processes held by the bridge, and clear on their own. --- NIGHTLY_CHANGELOG.md | 1 + kobrax_client.py | 89 ++++++++++++++++++++++++++++++------ tests/test_mqtt_reconnect.py | 58 +++++++++++++++++++++++ tests/test_tcp_keepalive.py | 80 ++++++++++++++++++++++++++++++++ 4 files changed, 215 insertions(+), 13 deletions(-) create mode 100644 tests/test_tcp_keepalive.py diff --git a/NIGHTLY_CHANGELOG.md b/NIGHTLY_CHANGELOG.md index 90efd1a..2a9141e 100644 --- a/NIGHTLY_CHANGELOG.md +++ b/NIGHTLY_CHANGELOG.md @@ -2,3 +2,4 @@ - Fix: **combined ACE-RFID filament tags (e.g. "GEEETECH PLA Bas" from third-party RFID tools) still weren't auto-matching to imported OrcaSlicer profiles**, even after the first attempt at this in a previous nightly — the matching logic was only ever wired into the OrcaSlicer slicer-sync endpoint, never into the actual MQTT status path that feeds the dashboard and Happy-Hare gate data, so the dashboard kept showing the raw unmatched RFID string. Centralized the matching so all three places that resolve a slot's filament profile benefit identically. Also added variant-token disambiguation (e.g. "Bas" vs. "Matte") for when a vendor has multiple profiles of the same material, and fixed a related edge case where a manual per-slot override could be incorrectly treated as stale on an RFID-tagged spool (Issue #101, thanks @Blaim for the extensive debugging that pinpointed this). - Feat: new setting under Settings → Print — "Delete file from printer after successful print" — automatically removes a GCode file from the printer's own storage once it finishes printing successfully, keeping only the copy in the bridge's own GCode store. Off by default, and only ever applies to files that were uploaded through the bridge itself (so there's always a backup); files started directly from the printer or Anycubic Slicer are never touched. +- Fix: **the dashboard could stay stuck showing a printer as online/"ready" indefinitely after it was physically switched off or unplugged**, discovered while testing the new smart-plug power-switch feature. Root cause was two-fold: the MQTT socket had no TCP keepalive, so a connection killed without a clean close (unplugged, not a graceful shutdown) could look alive to the OS for 15+ minutes; and even once the dead connection was detected, the status poll loop could get stuck waiting on a reconnect attempt that was already running elsewhere, so it never reached the code that flips the dashboard to "offline". Live-tested against a real printer, including that no sockets, threads, or file descriptors are left behind across repeated disconnect/reconnect cycles — a disconnected printer is now detected and reflected on the dashboard within about 15 seconds. diff --git a/kobrax_client.py b/kobrax_client.py index 86cddc2..40230f6 100644 --- a/kobrax_client.py +++ b/kobrax_client.py @@ -101,6 +101,46 @@ def _parse_publish(pkt: bytes): return topic, payload +def _enable_tcp_keepalive(sock: socket.socket) -> None: + """Without this, a printer that goes dark without a clean TCP close (e.g. + unplugged, not gracefully shut down) leaves the socket looking alive to + is_connected() for as long as the OS's default dead-connection timeout + (often 15+ minutes on Linux) - sendall() on a half-open connection is + buffered by the kernel and doesn't fail immediately, so the poll loop's + is_connected() check (kobrax_moonraker_bridge.py's _poll_loop) never + sees the failure it needs to flip kobra_state to "offline". Short + keepalive probes make the OS notice and fail the socket within seconds + instead. Linux/macOS only (TCP_KEEPIDLE/INTVL/CNT); best-effort on other + platforms - not fatal if unsupported. + + SO_KEEPALIVE alone is NOT enough, verified live by unplugging a real + printer mid-connection: keepalive probes only fire while the connection + is idle (no unacknowledged data outstanding). If the printer disappears + while a send is still in flight - the common case, since the poll loop + sends a request roughly every poll_interval - the kernel instead retries + that specific send via the normal TCP retransmission timer + (tcp_retries2, default 15 attempts with exponential backoff = 13-30+ + minutes on Linux), which keepalive settings don't affect at all. + TCP_USER_TIMEOUT (Linux-specific) closes that gap: it caps how long ANY + unacknowledged data may sit in the send queue before the kernel gives up + on the connection outright, regardless of which mechanism (keepalive or + retransmission) would otherwise still be retrying.""" + try: + sock.setsockopt(socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1) + if hasattr(socket, "TCP_KEEPIDLE"): + sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPIDLE, 5) + elif hasattr(socket, "TCP_KEEPALIVE"): # macOS + sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPALIVE, 5) + if hasattr(socket, "TCP_KEEPINTVL"): + sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPINTVL, 3) + if hasattr(socket, "TCP_KEEPCNT"): + sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPCNT, 3) + if hasattr(socket, "TCP_USER_TIMEOUT"): + sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_USER_TIMEOUT, 15000) + except OSError as e: + log.debug("TCP keepalive not fully supported on this platform: %s", e) + + # --------------------------------------------------------------------------- # KobraXClient # --------------------------------------------------------------------------- @@ -189,6 +229,7 @@ class KobraXClient: # senders. Only the finished socket is swapped in under the lock (#53). _ai = socket.getaddrinfo(self.host, self.port, socket.AF_INET, socket.SOCK_STREAM) raw = socket.create_connection(_ai[0][4], timeout=5) + _enable_tcp_keepalive(raw) new_sock = ctx.wrap_socket(raw) log.info("TLS connected cipher=%s", new_sock.cipher()[0]) @@ -252,19 +293,31 @@ class KobraXClient: with self._lock: return self._sock is not None - def _reconnect(self): - """Persistent reconnect: keeps retrying forever until the printer is - responds or disconnect() was called. Backoff caps at 60 s. The - first 5 attempts log as WARNING (acute connection issue), afterwards - only DEBUG to avoid log spam during long printer outages (e.g. switched - ausgeschaltet) zu vermeiden. + def _reconnect(self, wait_if_in_progress: bool = True, persist: bool = True): + """Reconnect the MQTT/TLS session. With persist=True (the default, used + by the reader-thread keepalive path) it keeps retrying forever until + the printer responds or disconnect() was called, backoff capped at 60s. + The first 5 attempts log as WARNING (acute connection issue), afterwards + only DEBUG to avoid log spam during long printer outages (e.g. switched off). Guarded by _reconnect_lock (Issue #105): if another thread's reconnect - is already in flight, this call waits for it to finish instead of - starting a second, competing _do_connect() - the printer likely only + is already in flight, this call normally waits for it to finish instead + of starting a second, competing _do_connect() - the printer likely only accepts one mTLS session at a time, so two parallel handshakes would - just interfere with each other and neither converges.""" + just interfere with each other and neither converges. + + wait_if_in_progress=False + persist=False are used by the poll loop's + publish()/publish_web(): that thread MUST return promptly so the poll + loop can observe the dead session (via is_connected()) and flip + kobra_state to "offline". It must neither block on the lock waiting for + the reader thread's persistent reconnect (wait_if_in_progress=False), + nor run the multi-minute backoff loop itself (persist=False -> at most + one immediate attempt). Otherwise the poll loop hangs inside publish() + for the entire outage and the dashboard stays stuck on the last known + state - the exact bug seen when a printer was unplugged mid-connection.""" if not self._reconnect_lock.acquire(blocking=False): + if not wait_if_in_progress: + return self._sock is not None self._reconnect_lock.acquire() self._reconnect_lock.release() return self._sock is not None @@ -290,6 +343,12 @@ class KobraXClient: return True except Exception as e: attempt += 1 + if not persist: + # One-shot: don't block the caller (poll loop) in the + # backoff loop - leave persistent retrying to the + # reader thread's keepalive path. + log.debug("Reconnect (one-shot) failed: %s", e) + return False lvl = log.warning if attempt <= 5 else log.debug lvl("Reconnect fehlgeschlagen (%s, Versuch %d), warte %ss…", e, attempt, delay) # Split sleep so disconnect() breaks the loop faster. @@ -522,7 +581,10 @@ class KobraXClient: self._pending_msgid.pop(msgid, None) if report_registered: self._pending_report.pop(report_key, None) - if not self._reconnect(): + # Non-blocking: never hang the poll-loop thread inside publish() + # while a reconnect is running / during backoff (see _reconnect + # docstring) - it must return so kobra_state can flip to "offline". + if not self._reconnect(wait_if_in_progress=False, persist=False): return None # retry once after reconnect try: @@ -569,10 +631,11 @@ class KobraXClient: except Exception as e: log.error("web send error: %s, reconnecting…", e) # Trigger a reconnect (like publish()); no retry because it is - # fire-and-forget - the next call will hit the fresh socket - # treffen. + # fire-and-forget - the next call will hit the fresh socket. + # Non-blocking for the same reason as publish() (see _reconnect + # docstring) - never hang this thread through a backoff loop. try: - self._reconnect() + self._reconnect(wait_if_in_progress=False, persist=False) except Exception: pass diff --git a/tests/test_mqtt_reconnect.py b/tests/test_mqtt_reconnect.py index e7ab5f5..0242786 100644 --- a/tests/test_mqtt_reconnect.py +++ b/tests/test_mqtt_reconnect.py @@ -92,3 +92,61 @@ def test_reconnect_second_waiter_returns_after_first_completes(): assert result is True assert c._sock is not None + + +def test_reconnect_non_blocking_returns_immediately_while_reconnect_in_progress(): + """The poll-loop path (publish/publish_web) must NOT block while the reader + thread's persistent reconnect is running its multi-minute backoff loop - + it has to return so the poll loop can flip kobra_state to "offline". + A printer unplugged mid-connection otherwise left the dashboard stuck on + the last known state indefinitely (Issue #103 follow-up).""" + c = _client() + c._running = True + started = threading.Event() + release = threading.Event() + + def slow_persistent_do_connect(): + started.set() + # Simulate the printer still being gone: never succeeds until released. + release.wait(timeout=5.0) + raise OSError("still unreachable") + + c._do_connect = slow_persistent_do_connect + + # First reconnect (reader-thread style): persistent, holds the lock, stuck + # in backoff. + t1 = threading.Thread(target=lambda: c._reconnect(persist=True), daemon=True) + t1.start() + assert started.wait(timeout=2.0) + + # Poll-loop style call must return basically instantly, not block on t1. + t0 = time.time() + result = c._reconnect(wait_if_in_progress=False, persist=False) + elapsed = time.time() - t0 + + assert elapsed < 0.5, f"non-blocking reconnect blocked for {elapsed:.2f}s" + assert result is False # socket is down while the other reconnect churns + + release.set() # let the daemon thread unwind + + +def test_reconnect_one_shot_does_not_loop_on_failure(): + """persist=False must attempt the handshake at most once and return, + instead of entering the backoff loop (which would block the caller).""" + c = _client() + c._running = True + attempts = [] + + def failing_do_connect(): + attempts.append(1) + raise OSError("unreachable") + + c._do_connect = failing_do_connect + + t0 = time.time() + result = c._reconnect(persist=False) + elapsed = time.time() - t0 + + assert result is False + assert len(attempts) == 1 # exactly one attempt, no backoff retries + assert elapsed < 0.5 diff --git a/tests/test_tcp_keepalive.py b/tests/test_tcp_keepalive.py new file mode 100644 index 0000000..8a93dfd --- /dev/null +++ b/tests/test_tcp_keepalive.py @@ -0,0 +1,80 @@ +"""TCP keepalive + TCP_USER_TIMEOUT on the MQTT socket (Issue #103 follow-up). + +Without these, a printer that disappears without a clean TCP close +(unplugged, not gracefully shut down) leaves the socket looking alive to +is_connected() for as long as the OS's default dead-connection timeout - +often 15+ minutes on Linux - since sendall() on a half-open connection is +buffered by the kernel and doesn't fail immediately. This left the +dashboard's printer-state indicator stuck showing the last known state +(e.g. green "ready") long after the printer was actually unreachable, +reported when testing the smart-plug power-switch feature by physically +unplugging the printer. + +Verified live (real printer, physically unplugged) that SO_KEEPALIVE alone +is not sufficient: keepalive probes only fire on an idle connection, but if +the printer disappears while a send is still unacknowledged - the normal +case, since the poll loop is sending every few seconds - the kernel's +regular TCP retransmission timer takes over instead (tcp_retries2, 13-30+ +minutes on Linux), which keepalive settings don't affect. TCP_USER_TIMEOUT +closes that gap by capping how long ANY unacknowledged data may sit in the +send queue, regardless of which retry mechanism would otherwise still be +running. +""" +import socket +from unittest.mock import MagicMock + +import pytest + +from kobrax_client import _enable_tcp_keepalive + + +def test_enable_tcp_keepalive_sets_so_keepalive(): + s = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + try: + _enable_tcp_keepalive(s) + assert s.getsockopt(socket.SOL_SOCKET, socket.SO_KEEPALIVE) == 1 + finally: + s.close() + + +@pytest.mark.skipif(not hasattr(socket, "TCP_KEEPIDLE"), reason="Linux-specific option") +def test_enable_tcp_keepalive_sets_short_idle_and_interval(): + s = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + try: + _enable_tcp_keepalive(s) + idle = s.getsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPIDLE) + intvl = s.getsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPINTVL) + cnt = s.getsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPCNT) + # Short enough that a dead connection is detected within a couple of + # poll cycles (default poll_interval is 3s), not the OS default of + # minutes. + assert idle <= 10 + assert intvl <= 5 + assert cnt <= 5 + finally: + s.close() + + +@pytest.mark.skipif(not hasattr(socket, "TCP_USER_TIMEOUT"), reason="Linux-specific option") +def test_enable_tcp_keepalive_sets_user_timeout(): + """The critical fix, verified live against a real printer: without this, + a dead connection with unacknowledged data in flight is only detected + after the OS's normal TCP retransmission timeout (13-30+ minutes on + Linux), not the keepalive interval.""" + s = socket.socket(socket.AF_INET, socket.SOCK_STREAM) + try: + _enable_tcp_keepalive(s) + user_timeout_ms = s.getsockopt(socket.IPPROTO_TCP, socket.TCP_USER_TIMEOUT) + # Short enough that a dead connection with in-flight data is detected + # within a couple of poll cycles, not tens of minutes. + assert 0 < user_timeout_ms <= 20000 + finally: + s.close() + + +def test_enable_tcp_keepalive_does_not_raise_on_unsupported_platform(): + """A platform without TCP_KEEPIDLE/INTVL/CNT (e.g. some Windows builds) + must not crash the connection attempt - keepalive is best-effort.""" + s = MagicMock() + s.setsockopt.side_effect = OSError("unsupported") + _enable_tcp_keepalive(s) # must not raise