mirror of
https://github.com/maziggy/bambuddy.git
synced 2026-10-17 19:36:28 +02:00
The reporter's A1 had been offline 38 hours and still answered on 8883, so the connection watchdog did exactly what it exists for: rebuild the session with a fresh client, since anything left in the old one's QoS 1 queue would otherwise replay onto the next print (#1136). The rebuild ended in paho's loop_stop(), which sets a terminate flag and then joins the network thread with no timeout. That thread only reads the flag between iterations of loop_forever, so it cannot read it while parked inside reconnect() -> _ssl_wrap_socket() -> do_handshake(). paho gives that handshake the keepalive as its socket timeout -- 30s here -- and a socket timeout is per operation, renewed by every byte the peer sends. A printer that answers TCP and then trickles holds the join open for as long as it likes. The join ran on the asyncio thread. Bambuddy stopped answering anything -- UI, API, /health -- while the process stayed up, which is why a restart: unless-stopped container never restarted. Retiring a client no longer waits for it. The replacement is built at once and the old one is shut down on a thread of its own that nobody joins. Its callbacks are detached first, inline: blocking until the network thread was gone is what used to guarantee a client we had let go of could no longer touch our state, and with the teardown detached a zombie that finishes its handshake would otherwise auto-reconnect and report itself connected behind its replacement's back. disconnect() still goes out, still promptly, because that is what stops paho's auto-reconnect and the replay with it. The reported watchdog is one of six callers. The queue's dispatch recovery and check_staleness -- reached from an ordinary status poll -- share _hard_reset_client; editing, deleting and hand-disconnecting a printer share disconnect(); the relay and smart-plug services had the same join on their shutdown path, where a wedged broker stopped the process from exiting at all. #1445 was this join too, from the add-printer probe, and its off-loop teardown stays as it is. disconnect() stays quiet on the way out, as it always effectively did. paho's callback used to land during the join, but it suppresses itself for a clean disconnect of a printer that reported in the last ten seconds, so a healthy printer disconnected by hand never announced itself offline. Announcing it now would tell the user their printer had gone offline a minute after they disconnected it on purpose (#1752). A retirement that takes more than five seconds logs which printer it was. The whole point is that the next one of these should not have to be diagnosed from a thread dump.
332 lines
13 KiB
Python
332 lines
13 KiB
Python
"""Letting go of a paho client must never block the thread that let it go.
|
|
|
|
#3068: a printer that had been offline 38 hours still answered on 8883. The
|
|
connection watchdog rebuilt its session, which ended in paho's `loop_stop()`
|
|
-- set a terminate flag, then `join()` the network thread with no timeout. The
|
|
network thread was parked in `reconnect()`'s TLS handshake, where it cannot
|
|
read that flag, so the join never returned. The join was running on the asyncio
|
|
thread: the process stayed up, `/health` stopped being answered, and Docker's
|
|
`restart: unless-stopped` never fired because nothing had exited.
|
|
|
|
Four call paths reach that join from the event loop -- the connection watchdog,
|
|
the queue dispatch deadline, `check_staleness()` on an ordinary status poll,
|
|
and `disconnect()` from the printer routes. They all funnel through the two
|
|
places tested here. The relay and smart-plug services had the same join on
|
|
their shutdown path and now share the same teardown.
|
|
"""
|
|
|
|
import asyncio
|
|
import threading
|
|
import time
|
|
from unittest.mock import MagicMock, patch
|
|
|
|
import pytest
|
|
|
|
from backend.app.services.bambu_mqtt import BambuMQTTClient
|
|
from backend.app.utils.paho_teardown import retire_paho_client
|
|
|
|
|
|
class WedgedPahoClient:
|
|
"""A paho client whose network thread will not stop.
|
|
|
|
`loop_stop()` blocks until `release()` is called, which is what a real one
|
|
does while its thread sits in `do_handshake()` against a printer that
|
|
answers TCP and then goes quiet.
|
|
"""
|
|
|
|
def __init__(self):
|
|
self.released = threading.Event()
|
|
self.disconnect_called = threading.Event()
|
|
self.loop_stop_returned = threading.Event()
|
|
self.on_connect = "sentinel"
|
|
self.on_disconnect = "sentinel"
|
|
self.on_subscribe = "sentinel"
|
|
self.on_message = "sentinel"
|
|
|
|
def disconnect(self):
|
|
self.disconnect_called.set()
|
|
|
|
def loop_stop(self):
|
|
self.released.wait(timeout=10)
|
|
self.loop_stop_returned.set()
|
|
|
|
def release(self):
|
|
self.released.set()
|
|
|
|
|
|
@pytest.fixture
|
|
def client():
|
|
return BambuMQTTClient(
|
|
ip_address="192.168.1.100",
|
|
serial_number="00M09A123456789",
|
|
access_code="12345678",
|
|
)
|
|
|
|
|
|
class TestRetiringAClient:
|
|
def test_it_returns_while_the_old_client_is_still_stopping(self):
|
|
wedged = WedgedPahoClient()
|
|
try:
|
|
started = time.monotonic()
|
|
retire_paho_client(wedged, "00M09A123456789")
|
|
elapsed = time.monotonic() - started
|
|
|
|
assert elapsed < 2.0, f"retirement blocked the caller for {elapsed:.2f}s (#3068)"
|
|
assert not wedged.loop_stop_returned.is_set(), "loop_stop was joined, not handed off"
|
|
finally:
|
|
wedged.release()
|
|
|
|
def test_the_callbacks_are_detached_before_the_caller_moves_on(self):
|
|
# Blocking until the network thread was gone is what used to guarantee
|
|
# a client we had let go of could no longer touch our state. With the
|
|
# teardown detached, a zombie that finishes its handshake would
|
|
# auto-reconnect and set connected=True behind its replacement's back,
|
|
# so the detach has to happen inline.
|
|
wedged = WedgedPahoClient()
|
|
try:
|
|
retire_paho_client(wedged, "00M09A123456789")
|
|
assert wedged.on_connect is None
|
|
assert wedged.on_disconnect is None
|
|
assert wedged.on_subscribe is None
|
|
assert wedged.on_message is None
|
|
finally:
|
|
wedged.release()
|
|
|
|
def test_the_old_session_is_still_disconnected_and_stopped(self):
|
|
# disconnect() is what stops paho's auto-reconnect, and with it the
|
|
# chance of an unacked project_file replaying onto a revived session
|
|
# (#1136). Handing it off must not mean skipping it.
|
|
wedged = WedgedPahoClient()
|
|
assert wedged.disconnect_called.wait(timeout=0) is False
|
|
retire_paho_client(wedged, "00M09A123456789")
|
|
assert wedged.disconnect_called.wait(timeout=5), "the old client was never disconnected"
|
|
wedged.release()
|
|
assert wedged.loop_stop_returned.wait(timeout=5), "the old client's loop was never stopped"
|
|
|
|
def test_a_client_that_raises_on_teardown_is_still_let_go(self):
|
|
exploding = MagicMock()
|
|
exploding.disconnect.side_effect = RuntimeError("socket already gone")
|
|
exploding.loop_stop.side_effect = RuntimeError("no thread")
|
|
|
|
retire_paho_client(exploding, "00M09A123456789")
|
|
|
|
deadline = time.monotonic() + 5
|
|
while time.monotonic() < deadline and not exploding.loop_stop.called:
|
|
time.sleep(0.01)
|
|
assert exploding.loop_stop.called
|
|
|
|
def test_the_retirement_thread_is_named_for_the_printer(self):
|
|
# A support bundle's thread dump is how the next one of these gets
|
|
# recognised; an anonymous Thread-7 says nothing.
|
|
wedged = WedgedPahoClient()
|
|
try:
|
|
retire_paho_client(wedged, "00M09A123456789")
|
|
names = [t.name for t in threading.enumerate()]
|
|
assert "mqtt-retire-00M09A123456789" in names
|
|
finally:
|
|
wedged.release()
|
|
|
|
|
|
class TestHardReset:
|
|
def test_it_does_not_wait_for_the_old_network_thread(self, client):
|
|
wedged = WedgedPahoClient()
|
|
client._client = wedged
|
|
client._loop = None # no rebuild, so only the teardown is measured
|
|
|
|
try:
|
|
started = time.monotonic()
|
|
client._hard_reset_client()
|
|
elapsed = time.monotonic() - started
|
|
|
|
assert elapsed < 2.0, f"_hard_reset_client blocked for {elapsed:.2f}s (#3068)"
|
|
assert client._client is None
|
|
finally:
|
|
wedged.release()
|
|
|
|
def test_the_replacement_gets_a_fresh_client_id(self, client):
|
|
# The #1136 property: the new session must not inherit paho's QoS 1
|
|
# queue, which is what a new client_id buys.
|
|
wedged = WedgedPahoClient()
|
|
client._client = wedged
|
|
client._loop = MagicMock()
|
|
|
|
with patch("backend.app.services.bambu_mqtt.mqtt.Client") as MockClient:
|
|
MockClient.return_value = MagicMock()
|
|
try:
|
|
client._hard_reset_client()
|
|
finally:
|
|
wedged.release()
|
|
|
|
assert MockClient.call_count == 1
|
|
new_id = MockClient.call_args.kwargs["client_id"]
|
|
assert client.serial_number in new_id
|
|
assert client._client is MockClient.return_value
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_a_wedged_printer_does_not_stall_the_event_loop(self, client):
|
|
# The reported failure, end to end: force_reconnect_stale_session is
|
|
# what the connection watchdog and the queue dispatch deadline both
|
|
# call, from a coroutine. A heartbeat has to keep ticking through it.
|
|
wedged = WedgedPahoClient()
|
|
client._client = wedged
|
|
|
|
ticks = 0
|
|
|
|
async def heartbeat():
|
|
nonlocal ticks
|
|
while True:
|
|
await asyncio.sleep(0.02)
|
|
ticks += 1
|
|
|
|
beat = asyncio.create_task(heartbeat())
|
|
try:
|
|
with patch("backend.app.services.bambu_mqtt.mqtt.Client") as MockClient:
|
|
MockClient.return_value = MagicMock()
|
|
started = time.monotonic()
|
|
client.force_reconnect_stale_session("offline for 900s, port still answering")
|
|
elapsed = time.monotonic() - started
|
|
await asyncio.sleep(0.1)
|
|
finally:
|
|
beat.cancel()
|
|
wedged.release()
|
|
try:
|
|
await beat
|
|
except asyncio.CancelledError:
|
|
pass
|
|
|
|
assert elapsed < 2.0, f"the forced reconnect held the event loop for {elapsed:.2f}s (#3068)"
|
|
assert ticks > 0, "the event loop made no progress while the old client was stopping"
|
|
assert client.state.connected is False
|
|
|
|
|
|
class TestDisconnect:
|
|
def test_it_does_not_wait_for_the_old_network_thread(self, client):
|
|
# Reached from PUT/DELETE /printers/{id} and POST
|
|
# /printers/{id}/disconnect, all on the asyncio thread.
|
|
wedged = WedgedPahoClient()
|
|
client._client = wedged
|
|
client.state.connected = True
|
|
|
|
try:
|
|
started = time.monotonic()
|
|
client.disconnect()
|
|
elapsed = time.monotonic() - started
|
|
|
|
assert elapsed < 2.0, f"disconnect() blocked for {elapsed:.2f}s (#3068)"
|
|
assert client._client is None
|
|
assert client.state.connected is False
|
|
finally:
|
|
wedged.release()
|
|
|
|
def test_the_disconnect_callback_still_gets_its_window(self, client):
|
|
# The callback that releases the timeout fires on paho's thread, so it
|
|
# has to run before the retirement detaches it -- otherwise every
|
|
# caller with a non-zero timeout waits the timeout out in full.
|
|
class AnsweringClient(WedgedPahoClient):
|
|
def disconnect(self):
|
|
super().disconnect()
|
|
if self.on_disconnect is not None:
|
|
self.on_disconnect(self, None)
|
|
|
|
answering = AnsweringClient()
|
|
answering.on_disconnect = client._on_disconnect # as connect() wires it
|
|
client._client = answering
|
|
|
|
try:
|
|
started = time.monotonic()
|
|
client.disconnect(timeout=5)
|
|
elapsed = time.monotonic() - started
|
|
|
|
assert elapsed < 2.0, (
|
|
f"disconnect(timeout=5) took {elapsed:.2f}s — the callback was detached "
|
|
"before it could report the disconnect"
|
|
)
|
|
assert client._disconnection_event.is_set()
|
|
finally:
|
|
answering.release()
|
|
|
|
def test_disconnecting_twice_is_harmless(self, client):
|
|
wedged = WedgedPahoClient()
|
|
client._client = wedged
|
|
try:
|
|
client.disconnect()
|
|
client.disconnect()
|
|
assert client._client is None
|
|
finally:
|
|
wedged.release()
|
|
|
|
|
|
class TestTheOtherMqttServices:
|
|
"""The relay and the smart-plug service tear their brokers down the same
|
|
way, at shutdown. A wedged broker there does not stop request serving --
|
|
nothing is being served by then -- but it does stop the process exiting,
|
|
which leaves the container to be killed rather than stopped."""
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_the_relay_does_not_wait_for_its_network_thread(self):
|
|
from backend.app.services.mqtt_relay import MQTTRelayService
|
|
|
|
wedged = WedgedPahoClient()
|
|
service = MQTTRelayService()
|
|
service.client = wedged
|
|
service.connected = True
|
|
|
|
try:
|
|
started = time.monotonic()
|
|
await service.disconnect()
|
|
elapsed = time.monotonic() - started
|
|
|
|
assert elapsed < 2.0, f"relay shutdown blocked for {elapsed:.2f}s (#3068)"
|
|
assert service.client is None
|
|
# Only the retirement detaches callbacks, so this proves it ran
|
|
# rather than the service's except-block swallowing it.
|
|
assert wedged.on_disconnect is None
|
|
finally:
|
|
wedged.release()
|
|
|
|
@pytest.mark.asyncio
|
|
async def test_the_smart_plug_service_does_not_wait_for_its_network_thread(self):
|
|
from backend.app.services.mqtt_smart_plug import MQTTSmartPlugService
|
|
|
|
wedged = WedgedPahoClient()
|
|
service = MQTTSmartPlugService()
|
|
service.client = wedged
|
|
service.connected = True
|
|
|
|
try:
|
|
started = time.monotonic()
|
|
await service.disconnect()
|
|
elapsed = time.monotonic() - started
|
|
|
|
assert elapsed < 2.0, f"smart-plug shutdown blocked for {elapsed:.2f}s (#3068)"
|
|
assert service.client is None
|
|
# Only the retirement detaches callbacks, so this proves it ran
|
|
# rather than the service's except-block swallowing it.
|
|
assert wedged.on_disconnect is None
|
|
finally:
|
|
wedged.release()
|
|
|
|
|
|
class TestDisconnectStaysQuiet:
|
|
def test_a_hand_disconnected_printer_is_not_announced_as_offline(self, client):
|
|
# paho's disconnect callback used to land during the join, but
|
|
# `_on_disconnect` suppresses itself for a clean disconnect of a
|
|
# printer that reported in the last 10s, so a healthy printer
|
|
# disconnected on purpose never broadcast one. Announcing it here
|
|
# instead would reach the connected→disconnected edge and notify the
|
|
# user their printer went offline a minute later (#1752).
|
|
seen = []
|
|
client.on_state_change = seen.append
|
|
client._last_message_time = time.time()
|
|
wedged = WedgedPahoClient()
|
|
client._client = wedged
|
|
client.state.connected = True
|
|
|
|
try:
|
|
client.disconnect()
|
|
finally:
|
|
wedged.release()
|
|
|
|
assert seen == [], "disconnecting a printer by hand announced it as offline"
|
|
assert client.state.connected is False
|