test_mqtt_client_retirement_3068.py 13 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331
  1. """Letting go of a paho client must never block the thread that let it go.
  2. #3068: a printer that had been offline 38 hours still answered on 8883. The
  3. connection watchdog rebuilt its session, which ended in paho's `loop_stop()`
  4. -- set a terminate flag, then `join()` the network thread with no timeout. The
  5. network thread was parked in `reconnect()`'s TLS handshake, where it cannot
  6. read that flag, so the join never returned. The join was running on the asyncio
  7. thread: the process stayed up, `/health` stopped being answered, and Docker's
  8. `restart: unless-stopped` never fired because nothing had exited.
  9. Four call paths reach that join from the event loop -- the connection watchdog,
  10. the queue dispatch deadline, `check_staleness()` on an ordinary status poll,
  11. and `disconnect()` from the printer routes. They all funnel through the two
  12. places tested here. The relay and smart-plug services had the same join on
  13. their shutdown path and now share the same teardown.
  14. """
  15. import asyncio
  16. import threading
  17. import time
  18. from unittest.mock import MagicMock, patch
  19. import pytest
  20. from backend.app.services.bambu_mqtt import BambuMQTTClient
  21. from backend.app.utils.paho_teardown import retire_paho_client
  22. class WedgedPahoClient:
  23. """A paho client whose network thread will not stop.
  24. `loop_stop()` blocks until `release()` is called, which is what a real one
  25. does while its thread sits in `do_handshake()` against a printer that
  26. answers TCP and then goes quiet.
  27. """
  28. def __init__(self):
  29. self.released = threading.Event()
  30. self.disconnect_called = threading.Event()
  31. self.loop_stop_returned = threading.Event()
  32. self.on_connect = "sentinel"
  33. self.on_disconnect = "sentinel"
  34. self.on_subscribe = "sentinel"
  35. self.on_message = "sentinel"
  36. def disconnect(self):
  37. self.disconnect_called.set()
  38. def loop_stop(self):
  39. self.released.wait(timeout=10)
  40. self.loop_stop_returned.set()
  41. def release(self):
  42. self.released.set()
  43. @pytest.fixture
  44. def client():
  45. return BambuMQTTClient(
  46. ip_address="192.168.1.100",
  47. serial_number="00M09A123456789",
  48. access_code="12345678",
  49. )
  50. class TestRetiringAClient:
  51. def test_it_returns_while_the_old_client_is_still_stopping(self):
  52. wedged = WedgedPahoClient()
  53. try:
  54. started = time.monotonic()
  55. retire_paho_client(wedged, "00M09A123456789")
  56. elapsed = time.monotonic() - started
  57. assert elapsed < 2.0, f"retirement blocked the caller for {elapsed:.2f}s (#3068)"
  58. assert not wedged.loop_stop_returned.is_set(), "loop_stop was joined, not handed off"
  59. finally:
  60. wedged.release()
  61. def test_the_callbacks_are_detached_before_the_caller_moves_on(self):
  62. # Blocking until the network thread was gone is what used to guarantee
  63. # a client we had let go of could no longer touch our state. With the
  64. # teardown detached, a zombie that finishes its handshake would
  65. # auto-reconnect and set connected=True behind its replacement's back,
  66. # so the detach has to happen inline.
  67. wedged = WedgedPahoClient()
  68. try:
  69. retire_paho_client(wedged, "00M09A123456789")
  70. assert wedged.on_connect is None
  71. assert wedged.on_disconnect is None
  72. assert wedged.on_subscribe is None
  73. assert wedged.on_message is None
  74. finally:
  75. wedged.release()
  76. def test_the_old_session_is_still_disconnected_and_stopped(self):
  77. # disconnect() is what stops paho's auto-reconnect, and with it the
  78. # chance of an unacked project_file replaying onto a revived session
  79. # (#1136). Handing it off must not mean skipping it.
  80. wedged = WedgedPahoClient()
  81. assert wedged.disconnect_called.wait(timeout=0) is False
  82. retire_paho_client(wedged, "00M09A123456789")
  83. assert wedged.disconnect_called.wait(timeout=5), "the old client was never disconnected"
  84. wedged.release()
  85. assert wedged.loop_stop_returned.wait(timeout=5), "the old client's loop was never stopped"
  86. def test_a_client_that_raises_on_teardown_is_still_let_go(self):
  87. exploding = MagicMock()
  88. exploding.disconnect.side_effect = RuntimeError("socket already gone")
  89. exploding.loop_stop.side_effect = RuntimeError("no thread")
  90. retire_paho_client(exploding, "00M09A123456789")
  91. deadline = time.monotonic() + 5
  92. while time.monotonic() < deadline and not exploding.loop_stop.called:
  93. time.sleep(0.01)
  94. assert exploding.loop_stop.called
  95. def test_the_retirement_thread_is_named_for_the_printer(self):
  96. # A support bundle's thread dump is how the next one of these gets
  97. # recognised; an anonymous Thread-7 says nothing.
  98. wedged = WedgedPahoClient()
  99. try:
  100. retire_paho_client(wedged, "00M09A123456789")
  101. names = [t.name for t in threading.enumerate()]
  102. assert "mqtt-retire-00M09A123456789" in names
  103. finally:
  104. wedged.release()
  105. class TestHardReset:
  106. def test_it_does_not_wait_for_the_old_network_thread(self, client):
  107. wedged = WedgedPahoClient()
  108. client._client = wedged
  109. client._loop = None # no rebuild, so only the teardown is measured
  110. try:
  111. started = time.monotonic()
  112. client._hard_reset_client()
  113. elapsed = time.monotonic() - started
  114. assert elapsed < 2.0, f"_hard_reset_client blocked for {elapsed:.2f}s (#3068)"
  115. assert client._client is None
  116. finally:
  117. wedged.release()
  118. def test_the_replacement_gets_a_fresh_client_id(self, client):
  119. # The #1136 property: the new session must not inherit paho's QoS 1
  120. # queue, which is what a new client_id buys.
  121. wedged = WedgedPahoClient()
  122. client._client = wedged
  123. client._loop = MagicMock()
  124. with patch("backend.app.services.bambu_mqtt.mqtt.Client") as MockClient:
  125. MockClient.return_value = MagicMock()
  126. try:
  127. client._hard_reset_client()
  128. finally:
  129. wedged.release()
  130. assert MockClient.call_count == 1
  131. new_id = MockClient.call_args.kwargs["client_id"]
  132. assert client.serial_number in new_id
  133. assert client._client is MockClient.return_value
  134. @pytest.mark.asyncio
  135. async def test_a_wedged_printer_does_not_stall_the_event_loop(self, client):
  136. # The reported failure, end to end: force_reconnect_stale_session is
  137. # what the connection watchdog and the queue dispatch deadline both
  138. # call, from a coroutine. A heartbeat has to keep ticking through it.
  139. wedged = WedgedPahoClient()
  140. client._client = wedged
  141. ticks = 0
  142. async def heartbeat():
  143. nonlocal ticks
  144. while True:
  145. await asyncio.sleep(0.02)
  146. ticks += 1
  147. beat = asyncio.create_task(heartbeat())
  148. try:
  149. with patch("backend.app.services.bambu_mqtt.mqtt.Client") as MockClient:
  150. MockClient.return_value = MagicMock()
  151. started = time.monotonic()
  152. client.force_reconnect_stale_session("offline for 900s, port still answering")
  153. elapsed = time.monotonic() - started
  154. await asyncio.sleep(0.1)
  155. finally:
  156. beat.cancel()
  157. wedged.release()
  158. try:
  159. await beat
  160. except asyncio.CancelledError:
  161. pass
  162. assert elapsed < 2.0, f"the forced reconnect held the event loop for {elapsed:.2f}s (#3068)"
  163. assert ticks > 0, "the event loop made no progress while the old client was stopping"
  164. assert client.state.connected is False
  165. class TestDisconnect:
  166. def test_it_does_not_wait_for_the_old_network_thread(self, client):
  167. # Reached from PUT/DELETE /printers/{id} and POST
  168. # /printers/{id}/disconnect, all on the asyncio thread.
  169. wedged = WedgedPahoClient()
  170. client._client = wedged
  171. client.state.connected = True
  172. try:
  173. started = time.monotonic()
  174. client.disconnect()
  175. elapsed = time.monotonic() - started
  176. assert elapsed < 2.0, f"disconnect() blocked for {elapsed:.2f}s (#3068)"
  177. assert client._client is None
  178. assert client.state.connected is False
  179. finally:
  180. wedged.release()
  181. def test_the_disconnect_callback_still_gets_its_window(self, client):
  182. # The callback that releases the timeout fires on paho's thread, so it
  183. # has to run before the retirement detaches it -- otherwise every
  184. # caller with a non-zero timeout waits the timeout out in full.
  185. class AnsweringClient(WedgedPahoClient):
  186. def disconnect(self):
  187. super().disconnect()
  188. if self.on_disconnect is not None:
  189. self.on_disconnect(self, None)
  190. answering = AnsweringClient()
  191. answering.on_disconnect = client._on_disconnect # as connect() wires it
  192. client._client = answering
  193. try:
  194. started = time.monotonic()
  195. client.disconnect(timeout=5)
  196. elapsed = time.monotonic() - started
  197. assert elapsed < 2.0, (
  198. f"disconnect(timeout=5) took {elapsed:.2f}s — the callback was detached "
  199. "before it could report the disconnect"
  200. )
  201. assert client._disconnection_event.is_set()
  202. finally:
  203. answering.release()
  204. def test_disconnecting_twice_is_harmless(self, client):
  205. wedged = WedgedPahoClient()
  206. client._client = wedged
  207. try:
  208. client.disconnect()
  209. client.disconnect()
  210. assert client._client is None
  211. finally:
  212. wedged.release()
  213. class TestTheOtherMqttServices:
  214. """The relay and the smart-plug service tear their brokers down the same
  215. way, at shutdown. A wedged broker there does not stop request serving --
  216. nothing is being served by then -- but it does stop the process exiting,
  217. which leaves the container to be killed rather than stopped."""
  218. @pytest.mark.asyncio
  219. async def test_the_relay_does_not_wait_for_its_network_thread(self):
  220. from backend.app.services.mqtt_relay import MQTTRelayService
  221. wedged = WedgedPahoClient()
  222. service = MQTTRelayService()
  223. service.client = wedged
  224. service.connected = True
  225. try:
  226. started = time.monotonic()
  227. await service.disconnect()
  228. elapsed = time.monotonic() - started
  229. assert elapsed < 2.0, f"relay shutdown blocked for {elapsed:.2f}s (#3068)"
  230. assert service.client is None
  231. # Only the retirement detaches callbacks, so this proves it ran
  232. # rather than the service's except-block swallowing it.
  233. assert wedged.on_disconnect is None
  234. finally:
  235. wedged.release()
  236. @pytest.mark.asyncio
  237. async def test_the_smart_plug_service_does_not_wait_for_its_network_thread(self):
  238. from backend.app.services.mqtt_smart_plug import MQTTSmartPlugService
  239. wedged = WedgedPahoClient()
  240. service = MQTTSmartPlugService()
  241. service.client = wedged
  242. service.connected = True
  243. try:
  244. started = time.monotonic()
  245. await service.disconnect()
  246. elapsed = time.monotonic() - started
  247. assert elapsed < 2.0, f"smart-plug shutdown blocked for {elapsed:.2f}s (#3068)"
  248. assert service.client is None
  249. # Only the retirement detaches callbacks, so this proves it ran
  250. # rather than the service's except-block swallowing it.
  251. assert wedged.on_disconnect is None
  252. finally:
  253. wedged.release()
  254. class TestDisconnectStaysQuiet:
  255. def test_a_hand_disconnected_printer_is_not_announced_as_offline(self, client):
  256. # paho's disconnect callback used to land during the join, but
  257. # `_on_disconnect` suppresses itself for a clean disconnect of a
  258. # printer that reported in the last 10s, so a healthy printer
  259. # disconnected on purpose never broadcast one. Announcing it here
  260. # instead would reach the connected→disconnected edge and notify the
  261. # user their printer went offline a minute later (#1752).
  262. seen = []
  263. client.on_state_change = seen.append
  264. client._last_message_time = time.time()
  265. wedged = WedgedPahoClient()
  266. client._client = wedged
  267. client.state.connected = True
  268. try:
  269. client.disconnect()
  270. finally:
  271. wedged.release()
  272. assert seen == [], "disconnecting a printer by hand announced it as offline"
  273. assert client.state.connected is False