Log commit window, relabel timing summary, assert timing output in tests

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:

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: