diff --git a/esphome/core/application.h b/esphome/core/application.h index 76af5145115..a12cdc4ac88 100644 --- a/esphome/core/application.h +++ b/esphome/core/application.h @@ -612,6 +612,8 @@ class LoopBlockingGuard { uint32_t blocking_time = curr_time - App.get_loop_component_start_time(); if (blocking_time > WARN_IF_BLOCKING_OVER_MS) [[unlikely]] { warn_blocking(blocking_time); + // Exclude synchronous warning-log time from the next operation. + curr_time = MillisInternal::get(); } #endif return curr_time; diff --git a/tests/integration/fixtures/blocking_warning_log_time_not_charged_to_next_operation.yaml b/tests/integration/fixtures/blocking_warning_log_time_not_charged_to_next_operation.yaml new file mode 100644 index 00000000000..2f30a07d0d8 --- /dev/null +++ b/tests/integration/fixtures/blocking_warning_log_time_not_charged_to_next_operation.yaml @@ -0,0 +1,66 @@ +esphome: + name: blocking-warning-cascade + on_boot: + then: + - script.execute: blocking_60 + - script.execute: blocking_90 + - script.execute: blocking_120 + +host: + +api: + +logger: + level: DEBUG + on_message: + level: WARN + then: + - lambda: |- + uint32_t injected_delay = 0; + if (strstr(message, "blocking_60 took a long time") != nullptr) { + injected_delay = 60; + } else if (strstr(message, "blocking_90 took a long time") != nullptr) { + injected_delay = 90; + } else if (strstr(message, "blocking_120 took a long time") != nullptr) { + injected_delay = 120; + } + if (injected_delay != 0) { + id(injected_delay_total) += injected_delay; + const uint32_t start = millis(); + while (millis() - start < injected_delay) { + } + } + +globals: + - id: injected_delay_total + type: uint32_t + initial_value: "0" + +script: + - id: blocking_60 + then: + - delay: 20ms + - lambda: |- + const uint32_t start = millis(); + while (millis() - start < 80) { + } + + - id: blocking_90 + then: + - delay: 300ms + - lambda: |- + const uint32_t start = millis(); + while (millis() - start < 80) { + } + + - id: blocking_120 + then: + - delay: 600ms + - lambda: |- + const uint32_t start = millis(); + while (millis() - start < 80) { + } + - delay: 200ms + - logger.log: + format: "BLOCKING_WARNING_CASCADE_TEST_COMPLETE total=%u" + args: [id(injected_delay_total)] diff --git a/tests/integration/test_blocking_warning_log_time_not_charged_to_next_operation.py b/tests/integration/test_blocking_warning_log_time_not_charged_to_next_operation.py new file mode 100644 index 00000000000..e8b08f2265a --- /dev/null +++ b/tests/integration/test_blocking_warning_log_time_not_charged_to_next_operation.py @@ -0,0 +1,63 @@ +"""Regression test for blocking-warning log time attribution.""" + +from __future__ import annotations + +import asyncio +import re + +import pytest + +from .types import APIClientConnectedFactory, RunCompiledFunction + +WARN_PATTERN = re.compile( + r"(\S+) took a long time for an operation \((\d+) ms\), max is (\d+) ms" +) +COMPLETE_PATTERN = re.compile(r"BLOCKING_WARNING_CASCADE_TEST_COMPLETE total=(\d+)") +PRIMARY_SOURCES = {"blocking_60", "blocking_90", "blocking_120"} + + +@pytest.mark.asyncio +async def test_blocking_warning_log_time_not_charged_to_next_operation( + yaml_config: str, + run_compiled: RunCompiledFunction, + api_client_connected: APIClientConnectedFactory, +) -> None: + """Synchronous warning-log delays must not be charged to the next operation.""" + loop = asyncio.get_running_loop() + complete = asyncio.Event() + warnings: list[tuple[str, int, int]] = [] + injected_delay_total = 0 + + def check_output(line: str) -> None: + nonlocal injected_delay_total + if match := WARN_PATTERN.search(line): + warnings.append((match.group(1), int(match.group(2)), int(match.group(3)))) + if match := COMPLETE_PATTERN.search(line): + injected_delay_total = int(match.group(1)) + loop.call_soon_threadsafe(complete.set) + + async with ( + run_compiled(yaml_config, line_callback=check_output), + api_client_connected() as client, + ): + assert await client.device_info() is not None + await asyncio.wait_for(complete.wait(), timeout=10.0) + + assert injected_delay_total == 270, ( + f"Expected 270 ms of injected warning-log delay, got {injected_delay_total} ms" + ) + + primary_warnings = [ + warning for warning in warnings if warning[0] in PRIMARY_SOURCES + ] + assert {warning[0] for warning in primary_warnings} == PRIMARY_SOURCES, ( + f"Expected one real blocking warning from each test script, got: {warnings}" + ) + + secondary_warnings = [ + warning for warning in warnings if warning[0] not in PRIMARY_SOURCES + ] + assert not secondary_warnings, ( + "Warning-handler time was incorrectly charged to the next operation: " + f"{secondary_warnings}" + )