test_cleartext_probe_2780.py 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390
  1. """Ask the printer what it actually said (#2780).
  2. ``[SSL: WRONG_VERSION_NUMBER]`` on port 990 means the printer's first bytes
  3. were not a TLS record. That is measured rather than assumed, and the two tests
  4. at the top of this file are the measurement: a cleartext banner reproduces the
  5. exact error the field reports, while a genuine TLS version mismatch produces a
  6. different one. Both matter, because the profile registry used to explain this
  7. failure as a TLS 1.3 problem and prescribe a version cap for it -- which cannot
  8. work, since the error was never about the negotiated version.
  9. What the error does not say is *which* cleartext message, and that is the part
  10. that would identify the fault. OpenSSL has consumed those bytes by the time the
  11. exception surfaces, so the client now opens one plain connection and reads them.
  12. The reporter with the affected farm offered a packet capture; this gets the same
  13. answer from every affected install instead of one.
  14. """
  15. import logging
  16. import socket
  17. import ssl
  18. import threading
  19. import time
  20. from unittest.mock import MagicMock, patch
  21. import pytest
  22. from backend.app.services import bambu_ftp
  23. from backend.app.services.bambu_ftp import BambuFTPClient
  24. pytestmark = pytest.mark.unit
  25. LOGGER = "backend.app.services.bambu_ftp"
  26. REFUSAL = b"421 Too many connections. Try again later.\r\n"
  27. @pytest.fixture(autouse=True)
  28. def _clean_state():
  29. BambuFTPClient._handshake_blocked_until.clear()
  30. BambuFTPClient._handshake_skip_logged.clear()
  31. BambuFTPClient._mode_cache.clear()
  32. yield
  33. BambuFTPClient._handshake_blocked_until.clear()
  34. BambuFTPClient._handshake_skip_logged.clear()
  35. BambuFTPClient._mode_cache.clear()
  36. class _Listener:
  37. """A socket on an ephemeral port that answers however the test says.
  38. ``mode="cleartext"`` sends an FTP refusal in the clear, the way a vsFTPd
  39. that is turning connections away does. ``mode="silent"`` accepts and says
  40. nothing, which is what a healthy implicit-FTPS service does while it waits
  41. for a ClientHello.
  42. """
  43. def __init__(self, mode: str):
  44. self.mode = mode
  45. self.accepts = 0
  46. self._sock = socket.socket()
  47. self._sock.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
  48. self._sock.bind(("127.0.0.1", 0))
  49. self._sock.listen(8)
  50. self.port = self._sock.getsockname()[1]
  51. self._stop = threading.Event()
  52. self._conns: list[socket.socket] = []
  53. self._thread = threading.Thread(target=self._serve, daemon=True)
  54. self._thread.start()
  55. def _serve(self):
  56. # A blocking accept() is not reliably woken by closing the socket from
  57. # another thread, which left every teardown here waiting out its join.
  58. self._sock.settimeout(0.1)
  59. while not self._stop.is_set():
  60. try:
  61. conn, _ = self._sock.accept()
  62. except TimeoutError:
  63. continue
  64. except OSError:
  65. return
  66. self.accepts += 1
  67. if self.mode == "cleartext":
  68. try:
  69. conn.sendall(REFUSAL)
  70. except OSError:
  71. pass
  72. conn.close()
  73. else:
  74. # Hold it open and stay quiet, so the probe has to time out.
  75. self._conns.append(conn)
  76. def stop(self):
  77. self._stop.set()
  78. self._sock.close()
  79. for c in self._conns:
  80. try:
  81. c.close()
  82. except OSError:
  83. pass
  84. self._thread.join(timeout=2)
  85. @pytest.fixture()
  86. def cleartext_printer():
  87. server = _Listener("cleartext")
  88. yield server
  89. server.stop()
  90. @pytest.fixture()
  91. def silent_printer():
  92. server = _Listener("silent")
  93. yield server
  94. server.stop()
  95. @pytest.fixture(autouse=True)
  96. def _fast_probe(monkeypatch):
  97. """A real timeout would make the silent case a two-second test."""
  98. monkeypatch.setattr(bambu_ftp, "_CLEARTEXT_PROBE_TIMEOUT", 0.25)
  99. # ---------------------------------------------------------------------------
  100. # The measurement the rest of this rests on
  101. # ---------------------------------------------------------------------------
  102. def test_a_cleartext_banner_is_what_produces_wrong_version_number(cleartext_printer):
  103. """The exact error the affected farm logs, from a non-TLS answer."""
  104. ctx = ssl.create_default_context()
  105. # `create_default_context()` leaves `minimum_version` at MINIMUM_SUPPORTED,
  106. # which is the build's floor rather than a guarantee -- the same reason
  107. # every context in `backend/app` pins it, and the reason the TLS-13 case
  108. # further down this file already does. The listener answers with a plain
  109. # FTP banner and speaks no TLS at all, so the floor cannot change what this
  110. # measures; it only stops the file asking for a protocol we would refuse.
  111. ctx.minimum_version = ssl.TLSVersion.TLSv1_2
  112. ctx.check_hostname = False
  113. ctx.verify_mode = ssl.CERT_NONE
  114. raw = socket.create_connection(("127.0.0.1", cleartext_printer.port), 5)
  115. with pytest.raises(ssl.SSLError) as caught:
  116. ctx.wrap_socket(raw, server_hostname="printer").do_handshake()
  117. assert caught.value.reason == "WRONG_VERSION_NUMBER"
  118. def test_a_version_mismatch_produces_a_different_error(tmp_path):
  119. """So "cap the TLS version" cannot be the fix for WRONG_VERSION_NUMBER.
  120. Two of the cap_tls_v1_2 profile entries were written on the belief that it
  121. was. A real mismatch reports itself as a protocol-version alert, and a
  122. server that only speaks 1.2 negotiates fine against our own context without
  123. any cap -- so neither half of that reasoning holds.
  124. """
  125. import subprocess # nosec B404 -- generating a throwaway cert for a local server
  126. subprocess.run( # nosec B603 B607
  127. [
  128. "openssl",
  129. "req",
  130. "-x509",
  131. "-newkey",
  132. "rsa:2048",
  133. "-keyout",
  134. str(tmp_path / "k.pem"),
  135. "-out",
  136. str(tmp_path / "c.pem"),
  137. "-days",
  138. "1",
  139. "-nodes",
  140. "-subj",
  141. "/CN=printer",
  142. ],
  143. check=True,
  144. capture_output=True,
  145. )
  146. server_ctx = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
  147. server_ctx.load_cert_chain(str(tmp_path / "c.pem"), str(tmp_path / "k.pem"))
  148. server_ctx.maximum_version = ssl.TLSVersion.TLSv1_2
  149. listener = socket.socket()
  150. listener.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1)
  151. listener.bind(("127.0.0.1", 0))
  152. listener.listen(4)
  153. port = listener.getsockname()[1]
  154. def serve():
  155. for _ in range(2):
  156. try:
  157. conn, _addr = listener.accept()
  158. except OSError:
  159. return
  160. try:
  161. server_ctx.wrap_socket(conn, server_side=True).close()
  162. except (ssl.SSLError, OSError):
  163. try:
  164. conn.close()
  165. except OSError:
  166. pass
  167. thread = threading.Thread(target=serve, daemon=True)
  168. thread.start()
  169. try:
  170. def attempt(*, force_tls13: bool):
  171. ctx = ssl.create_default_context()
  172. ctx.check_hostname = False
  173. ctx.verify_mode = ssl.CERT_NONE
  174. ctx.minimum_version = ssl.TLSVersion.TLSv1_3 if force_tls13 else ssl.TLSVersion.TLSv1_2
  175. if force_tls13:
  176. ctx.maximum_version = ssl.TLSVersion.TLSv1_3
  177. raw = socket.create_connection(("127.0.0.1", port), 5)
  178. try:
  179. ctx.wrap_socket(raw, server_hostname="printer").do_handshake()
  180. return None
  181. finally:
  182. try:
  183. raw.close()
  184. except OSError:
  185. pass
  186. with pytest.raises(ssl.SSLError) as caught:
  187. attempt(force_tls13=True)
  188. assert caught.value.reason != "WRONG_VERSION_NUMBER"
  189. assert "PROTOCOL_VERSION" in caught.value.reason
  190. # And the half that makes the caps no-ops: a 1.2-only peer needs no help.
  191. assert attempt(force_tls13=False) is None
  192. finally:
  193. listener.close()
  194. thread.join(timeout=2)
  195. # ---------------------------------------------------------------------------
  196. # The probe
  197. # ---------------------------------------------------------------------------
  198. class TestTheProbe:
  199. def _client(self, server):
  200. client = BambuFTPClient("127.0.0.1", "12345678", timeout=5.0, printer_model="P2S")
  201. client.FTP_PORT = server.port
  202. return client
  203. def test_it_puts_the_printers_own_words_in_the_log(self, cleartext_printer, caplog):
  204. with caplog.at_level(logging.WARNING, logger=LOGGER):
  205. assert self._client(cleartext_printer).connect() is False
  206. messages = [r.getMessage() for r in caplog.records]
  207. assert any("421 Too many connections" in m for m in messages), messages
  208. # And it has to be findable by someone filing a report.
  209. assert any("include this line if you report it" in m for m in messages), messages
  210. def test_the_reason_carries_it_too(self, cleartext_printer):
  211. """So the failure reaches the user's message, not only the log."""
  212. client = self._client(cleartext_printer)
  213. client.connect()
  214. assert client.last_failure is not None
  215. assert "421 Too many connections" in client.last_failure.detail
  216. def test_silence_is_reported_as_the_fault_having_passed(self, caplog):
  217. """The printer sent non-TLS bytes, then had recovered a moment later.
  218. Driven through a stubbed probe rather than a silent server, because a
  219. server that accepts and stays quiet never reaches this branch at all --
  220. it produces a handshake *timeout*, not WRONG_VERSION_NUMBER, and the
  221. TimeoutError branch handles that one. Reading nothing here means the
  222. refusal passed between the handshake and the question, which is worth
  223. saying rather than logging nothing at all.
  224. """
  225. transport = MagicMock()
  226. error = ssl.SSLError(1, "[SSL: WRONG_VERSION_NUMBER] wrong version number")
  227. error.reason = "WRONG_VERSION_NUMBER"
  228. transport.connect.side_effect = error
  229. with (
  230. patch("backend.app.services.bambu_ftp.ImplicitFTP_TLS", return_value=transport),
  231. patch("backend.app.services.bambu_ftp._read_cleartext_reply", return_value=None),
  232. caplog.at_level(logging.WARNING, logger=LOGGER),
  233. ):
  234. assert BambuFTPClient("192.0.2.10", "12345678").connect() is False
  235. assert any("nothing readable in cleartext" in r.getMessage() for r in caplog.records)
  236. # And a probe that finds nothing must not cost the cool-off: the
  237. # handshake still failed, whatever the printer said a moment later.
  238. assert BambuFTPClient.handshake_blocked("192.0.2.10") is True
  239. def test_an_accept_and_stay_quiet_printer_is_a_timeout_not_this(self, silent_printer):
  240. """The other half of #2780's theory, and it lands somewhere else.
  241. A vsFTPd answering its global connection limit by accepting and never
  242. speaking produces a handshake timeout. Probing that would read nothing
  243. by definition, so this branch is deliberately not reached.
  244. """
  245. client = self._client(silent_printer)
  246. client.timeout = 0.5
  247. with patch("backend.app.services.bambu_ftp._read_cleartext_reply") as probe:
  248. assert client.connect() is False
  249. probe.assert_not_called()
  250. assert client.last_failure is not None
  251. assert client.last_failure.kind.value == "timeout"
  252. def test_it_asks_once_per_cooloff_not_once_per_attempt(self, cleartext_printer):
  253. """A dispatch ignores the cool-off, so it reaches this branch four times.
  254. Probing each time would add a connection per attempt to a printer whose
  255. suspected fault is having too many -- the opposite of what #2780's
  256. socket-leak fix was for.
  257. """
  258. for _ in range(4):
  259. client = self._client(cleartext_printer)
  260. client.respect_handshake_cooloff = False
  261. client.connect()
  262. # Four handshakes, and exactly one probe on top of them.
  263. assert cleartext_printer.accepts == 5
  264. def test_a_fresh_cooloff_window_asks_again(self, cleartext_printer):
  265. """A printer that recovers and fails later is a new event to diagnose."""
  266. self._client(cleartext_printer).connect()
  267. before = cleartext_printer.accepts
  268. BambuFTPClient._handshake_blocked_until.clear()
  269. self._client(cleartext_printer).connect()
  270. assert cleartext_printer.accepts == before + 2 # handshake + probe
  271. def test_a_real_version_mismatch_is_not_probed(self):
  272. """Nothing to read: that peer spoke TLS, it just would not agree on one.
  273. Without this check the probe would connect and sit out its whole
  274. timeout on every such failure.
  275. """
  276. transport = MagicMock()
  277. error = ssl.SSLError(1, "[SSL: TLSV1_ALERT_PROTOCOL_VERSION] tlsv1 alert protocol version")
  278. error.reason = "TLSV1_ALERT_PROTOCOL_VERSION"
  279. transport.connect.side_effect = error
  280. with (
  281. patch("backend.app.services.bambu_ftp.ImplicitFTP_TLS", return_value=transport),
  282. patch("backend.app.services.bambu_ftp._read_cleartext_reply") as probe,
  283. ):
  284. assert BambuFTPClient("192.0.2.10", "12345678").connect() is False
  285. probe.assert_not_called()
  286. def test_a_refused_probe_reads_as_nothing_rather_than_raising(self):
  287. """Nothing is listening, so it must come back None, not blow up.
  288. Uses a port that was just released rather than patching
  289. ``socket.create_connection``, which is process-wide and would sit under
  290. anything else running in this worker.
  291. """
  292. released = socket.socket()
  293. released.bind(("127.0.0.1", 0))
  294. port = released.getsockname()[1]
  295. released.close()
  296. assert bambu_ftp._read_cleartext_reply("127.0.0.1", port) is None
  297. def test_the_dead_socket_is_closed_before_the_printer_is_asked_again(self):
  298. """Ordering, and it is the whole reason this is safe to do at all.
  299. The probe opens a second connection to a printer whose suspected fault
  300. is having no connection slots left. Holding the failed handshake open
  301. across that would be the leak #2780's cleanup was added to stop, with
  302. an extra connection layered on top.
  303. """
  304. transport = MagicMock()
  305. error = ssl.SSLError(1, "[SSL: WRONG_VERSION_NUMBER] wrong version number")
  306. error.reason = "WRONG_VERSION_NUMBER"
  307. transport.connect.side_effect = error
  308. client = BambuFTPClient("192.0.2.10", "12345678")
  309. observed = {}
  310. def _probe(*_args):
  311. observed["still_open"] = client._ftp is not None
  312. observed["closed"] = transport.close.called
  313. return "421 Too many connections."
  314. with (
  315. patch("backend.app.services.bambu_ftp.ImplicitFTP_TLS", return_value=transport),
  316. patch("backend.app.services.bambu_ftp._read_cleartext_reply", _probe),
  317. ):
  318. assert client.connect() is False
  319. assert observed == {"still_open": False, "closed": True}
  320. def test_the_probe_does_not_outlive_its_timeout(self, silent_printer):
  321. started = time.monotonic()
  322. assert bambu_ftp._read_cleartext_reply("127.0.0.1", silent_printer.port) is None
  323. assert time.monotonic() - started < 2.0