From 490d4723ca1ea23bccb557fb371f7356c12a4be6 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 18 Oct 2026 15:08:46 -1000 Subject: [PATCH] [ota] Log why the upload switched to UDP (#20996) --- esphome/espota2.py | 33 ++++++++++++++++----------- tests/unit_tests/test_espota2.py | 39 ++++++++++++++++++-------------- 2 files changed, 42 insertions(+), 30 deletions(-) diff --git a/esphome/espota2.py b/esphome/espota2.py index aaef178753a..340722206ce 100644 --- a/esphome/espota2.py +++ b/esphome/espota2.py @@ -918,29 +918,36 @@ def _tcp_retransmits(sock: socket.socket) -> int | None: return struct.unpack_from(fmt, info, offset)[0] -def _link_lossy( +def _loss_reason( tcp_sock: socket.socket, slowest_exchange: float, prefer_udp: bool -) -> bool: - """Whether the handshake showed loss, so the data phase should use UDP.""" - return ( - prefer_udp - or slowest_exchange > UDP_SLOW_EXCHANGE - or bool(_tcp_retransmits(tcp_sock)) - ) +) -> str | None: + """Why the link looks lossy, so the data phase should use UDP; None if clean.""" + if prefer_udp: + return "an earlier attempt failed" + if slowest_exchange > UDP_SLOW_EXCHANGE: + return f"a handshake reply took {slowest_exchange:.1f}s" + if _tcp_retransmits(tcp_sock): + return "TCP resent data during the handshake" + return None def _start_udp( - sock: socket.socket | NoiseSocketWrapper, tcp_sock: socket.socket, lossy: bool + sock: socket.socket | NoiseSocketWrapper, + tcp_sock: socket.socket, + loss_reason: str | None, ) -> UdpChannel | None: """Move the data phase to UDP; None keeps it on TCP.""" # A clean link asks to stay on TCP - send_check(sock, UDP_REQUEST if lossy else UDP_FALLBACK, "UDP request") + send_check( + sock, UDP_FALLBACK if loss_reason is None else UDP_REQUEST, "UDP request" + ) token = receive_exactly(sock, 4, "UDP token", None, decode=False) - if not lossy: + if loss_reason is None: _LOGGER.debug("Link looks clean, staying on TCP") return None + _LOGGER.info("Link is lossy (%s), trying UDP", loss_reason) if token == bytes(4): - _LOGGER.debug("Device declined UDP") + _LOGGER.info("Device declined UDP, using TCP") return None udp_sock = socket.socket(tcp_sock.family, socket.SOCK_DGRAM) try: @@ -1192,7 +1199,7 @@ def perform_ota( # Still under SETUP_TIMEOUT, which the device's commit wait is sized for if extended_proto and features & SERVER_FEATURE_SUPPORTS_UDP: udp = _start_udp( - sock, tcp_sock, _link_lossy(tcp_sock, slowest_exchange, prefer_udp) + sock, tcp_sock, _loss_reason(tcp_sock, slowest_exchange, prefer_udp) ) if udp is not None: # The device drops TCP once it hears the committed channel diff --git a/tests/unit_tests/test_espota2.py b/tests/unit_tests/test_espota2.py index 04b09b4d542..c28944024bc 100644 --- a/tests/unit_tests/test_espota2.py +++ b/tests/unit_tests/test_espota2.py @@ -1695,45 +1695,50 @@ def test_start_udp_falls_back_when_blocked(mock_socket: Mock) -> None: mock_socket.getpeername.return_value = device.sock.getsockname() mock_socket.recv.side_effect = [b"\x05", b"\x06\x07\x08"] with patch.object(espota2, "UDP_PROBE_TIMEOUT", 0.3): - assert espota2._start_udp(mock_socket, mock_socket, True) is None + assert espota2._start_udp(mock_socket, mock_socket, "lossy") is None assert mock_socket.sendall.call_args_list == [ call(espota2.UDP_REQUEST), call(espota2.UDP_FALLBACK), # raw on the TCP socket ] -def test_start_udp_declined(mock_socket: Mock) -> None: +def test_start_udp_declined( + mock_socket: Mock, caplog: pytest.LogCaptureFixture +) -> None: """A zero token means the device could not open UDP; nothing is probed.""" mock_socket.recv.side_effect = [b"\x00", b"\x00\x00\x00"] - assert espota2._start_udp(mock_socket, mock_socket, True) is None + with caplog.at_level(logging.INFO, logger=espota2.__name__): + assert espota2._start_udp(mock_socket, mock_socket, "lossy") is None assert mock_socket.sendall.call_args_list == [call(espota2.UDP_REQUEST)] + assert "Link is lossy (lossy), trying UDP" in caplog.text + assert "Device declined UDP, using TCP" in caplog.text def test_start_udp_clean_link_stays_on_tcp(mock_socket: Mock) -> None: """A clean handshake asks to stay on TCP and opens no UDP socket.""" mock_socket.recv.side_effect = [b"\x00", b"\x00\x00\x00"] with patch.object(espota2.socket, "socket") as udp_socket: - assert espota2._start_udp(mock_socket, mock_socket, False) is None + assert espota2._start_udp(mock_socket, mock_socket, None) is None udp_socket.assert_not_called() assert mock_socket.sendall.call_args_list == [call(espota2.UDP_FALLBACK)] @pytest.mark.parametrize( - ("slowest", "prefer_udp", "retransmits", "lossy"), + ("slowest", "prefer_udp", "retransmits", "reason"), [ - (0.01, False, 0, False), - (0.01, False, None, False), - (espota2.UDP_SLOW_EXCHANGE + 0.1, False, 0, True), - (0.01, True, 0, True), - (0.01, False, 2, True), + (0.01, False, 0, None), + (0.01, False, None, None), + (1.5, False, 0, "a handshake reply took 1.5s"), + (0.01, True, 0, "an earlier attempt failed"), + (0.01, False, 2, "TCP resent data during the handshake"), ], ) -def test_link_lossy( - slowest: float, prefer_udp: bool, retransmits: int | None, lossy: bool +def test_loss_reason( + slowest: float, prefer_udp: bool, retransmits: int | None, reason: str | None ) -> None: - """A slow exchange, a retransmit or an earlier failure means UDP.""" + """A slow exchange, a retransmit or an earlier failure means UDP, with the reason.""" with patch.object(espota2, "_tcp_retransmits", return_value=retransmits): - assert espota2._link_lossy(Mock(), slowest, prefer_udp) is lossy + assert espota2._loss_reason(Mock(), slowest, prefer_udp) == reason @pytest.mark.parametrize( @@ -1825,7 +1830,7 @@ def test_perform_ota_over_udp(mock_socket: Mock) -> None: espota2.perform_ota( mock_socket, None, io.BytesIO(bytes(20000)), "test.bin", prefer_udp=True ) - assert start.call_args.args[2] is True # an earlier failure means lossy + assert start.call_args.args[2] == "an earlier attempt failed" assert udp.recv.call_count == 4 # no chunk acks udp.flush.assert_called_once() udp.close.assert_called_once() @@ -1887,7 +1892,7 @@ def test_start_udp_probe_succeeds(mock_socket: Mock) -> None: mock_socket.family = socket.AF_INET mock_socket.getpeername.return_value = device.sock.getsockname() mock_socket.recv.side_effect = [b"\x05", b"\x06\x07\x09"] - channel = espota2._start_udp(mock_socket, mock_socket, True) + channel = espota2._start_udp(mock_socket, mock_socket, "lossy") assert channel is not None channel.close() assert mock_socket.sendall.call_args_list == [call(espota2.UDP_REQUEST)] @@ -1971,7 +1976,7 @@ def test_start_udp_socket_error_falls_back(mock_socket: Mock) -> None: mock_socket.family = socket.AF_INET mock_socket.getpeername.side_effect = OSError("not connected") mock_socket.recv.side_effect = [b"\x05", b"\x06\x07\x08"] - assert espota2._start_udp(mock_socket, mock_socket, True) is None + assert espota2._start_udp(mock_socket, mock_socket, "lossy") is None assert mock_socket.sendall.call_args_list == [ call(espota2.UDP_REQUEST), call(espota2.UDP_FALLBACK),