[ota] Log why the upload switched to UDP (#20996)

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

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),