From 7fda52c584cccd632819e8a31db1b818deba8edd Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Fri, 21 Aug 2026 00:53:10 -0500 Subject: [PATCH] Log commit window, relabel timing summary, assert timing output in tests --- esphome/espota2.py | 7 ++++++- tests/unit_tests/test_espota2.py | 13 +++++++++++-- 2 files changed, 17 insertions(+), 3 deletions(-) diff --git a/esphome/espota2.py b/esphome/espota2.py index adcfde9e2a..f354115a4e 100644 --- a/esphome/espota2.py +++ b/esphome/espota2.py @@ -534,17 +534,22 @@ def perform_ota( # reboots on its own; the exact commit point is not observable from # here, so treat everything past the data phase as non-retryable. A # re-upload could flash a device that already updated successfully. + commit_start = time.perf_counter() try: receive_exactly(sock, 1, "update receive result", RESPONSE_RECEIVE_OK) receive_exactly(sock, 1, "update end result", RESPONSE_UPDATE_END_OK) except OTANetworkError as err: raise _committed_error(err) from err + commit_duration = time.perf_counter() - commit_start + # Spans the binary size send through the commit ack; connect, handshake, + # and auth are not included _LOGGER.info( - "OTA took %.2f seconds total (prepare %.2f, upload %.2f)", + "Update took %.2f seconds (prepare %.2f, upload %.2f, commit %.2f)", time.perf_counter() - prepare_start, prepare_duration, duration, + commit_duration, ) try: diff --git a/tests/unit_tests/test_espota2.py b/tests/unit_tests/test_espota2.py index 6db1e70593..0b4a698d4b 100644 --- a/tests/unit_tests/test_espota2.py +++ b/tests/unit_tests/test_espota2.py @@ -7,6 +7,7 @@ import gzip import hashlib import io import itertools +import logging from pathlib import Path import socket import struct @@ -374,7 +375,9 @@ def test_perform_ota_successful_md5_auth( @pytest.mark.usefixtures("mock_time") -def test_perform_ota_no_auth(mock_socket: Mock, mock_file: io.BytesIO) -> None: +def test_perform_ota_no_auth( + mock_socket: Mock, mock_file: io.BytesIO, caplog: pytest.LogCaptureFixture +) -> None: """Test OTA without authentication.""" recv_responses = [ bytes([espota2.RESPONSE_OK]), # First byte of version response @@ -389,7 +392,8 @@ def test_perform_ota_no_auth(mock_socket: Mock, mock_file: io.BytesIO) -> None: mock_socket.recv.side_effect = recv_responses - espota2.perform_ota(mock_socket, None, mock_file, "test.bin") + with caplog.at_level(logging.INFO): + espota2.perform_ota(mock_socket, None, mock_file, "test.bin") # Should not send any auth-related data auth_calls = [ @@ -399,6 +403,11 @@ def test_perform_ota_no_auth(mock_socket: Mock, mock_file: io.BytesIO) -> None: ] assert len(auth_calls) == 0 + # The timing summary is the observable output of the upload + assert "Preparing for upload took" in caplog.text + assert "Update took" in caplog.text + assert "commit" in caplog.text + @pytest.mark.usefixtures("mock_time") def test_perform_ota_with_compression(mock_socket: Mock) -> None: