diff --git a/esphome/components/esp32/__init__.py b/esphome/components/esp32/__init__.py index fdc469e419..c772a3438c 100644 --- a/esphome/components/esp32/__init__.py +++ b/esphome/components/esp32/__init__.py @@ -39,7 +39,7 @@ import esphome.final_validate as fv from esphome.helpers import copy_file_if_changed, mkdir_p, write_file_if_changed from esphome.types import ConfigType -from .boards import BOARDS +from .boards import BOARDS, STANDARD_BOARDS from .const import ( # noqa KEY_BOARD, KEY_COMPONENTS, @@ -487,25 +487,32 @@ def _platform_is_platformio(value): def _detect_variant(value): - board = value[CONF_BOARD] - if board in BOARDS: - variant = BOARDS[board][KEY_VARIANT] - if CONF_VARIANT in value and variant != value[CONF_VARIANT]: + board = value.get(CONF_BOARD) + variant = value.get(CONF_VARIANT) + if variant and board is None: + # If variant is set, we can derive the board from it + # variant has already been validated against the known set + value = value.copy() + value[CONF_BOARD] = STANDARD_BOARDS[variant] + elif board in BOARDS: + variant = variant or BOARDS[board][KEY_VARIANT] + if variant != BOARDS[board][KEY_VARIANT]: raise cv.Invalid( f"Option '{CONF_VARIANT}' does not match selected board.", path=[CONF_VARIANT], ) value = value.copy() value[CONF_VARIANT] = variant + elif not variant: + raise cv.Invalid( + "This board is unknown, if you are sure you want to compile with this board selection, " + f"override with option '{CONF_VARIANT}'", + path=[CONF_BOARD], + ) else: - if CONF_VARIANT not in value: - raise cv.Invalid( - "This board is unknown, if you are sure you want to compile with this board selection, " - f"override with option '{CONF_VARIANT}'", - path=[CONF_BOARD], - ) _LOGGER.warning( - "This board is unknown. Make sure the chosen chip component is correct.", + "This board is unknown; the specified variant '%s' will be used but this may not work as expected.", + variant, ) return value @@ -676,7 +683,7 @@ CONF_PARTITIONS = "partitions" CONFIG_SCHEMA = cv.All( cv.Schema( { - cv.Required(CONF_BOARD): cv.string_strict, + cv.Optional(CONF_BOARD): cv.string_strict, cv.Optional(CONF_CPU_FREQUENCY): cv.one_of( *FULL_CPU_FREQUENCIES, upper=True ), @@ -691,6 +698,7 @@ CONFIG_SCHEMA = cv.All( _detect_variant, _set_default_framework, set_core_data, + cv.has_at_least_one_key(CONF_BOARD, CONF_VARIANT), ) diff --git a/esphome/components/esp32/boards.py b/esphome/components/esp32/boards.py index 68fee48830..cf6cf8cbe5 100644 --- a/esphome/components/esp32/boards.py +++ b/esphome/components/esp32/boards.py @@ -2,13 +2,30 @@ from .const import ( VARIANT_ESP32, VARIANT_ESP32C2, VARIANT_ESP32C3, + VARIANT_ESP32C5, VARIANT_ESP32C6, VARIANT_ESP32H2, VARIANT_ESP32P4, VARIANT_ESP32S2, VARIANT_ESP32S3, + VARIANTS, ) +STANDARD_BOARDS = { + VARIANT_ESP32: "esp32dev", + VARIANT_ESP32C2: "esp32-c2-devkitm-1", + VARIANT_ESP32C3: "esp32-c3-devkitm-1", + VARIANT_ESP32C5: "esp32-c5-devkitc-1", + VARIANT_ESP32C6: "esp32-c6-devkitm-1", + VARIANT_ESP32H2: "esp32-h2-devkitm-1", + VARIANT_ESP32P4: "esp32-p4-evboard", + VARIANT_ESP32S2: "esp32-s2-kaluga-1", + VARIANT_ESP32S3: "esp32-s3-devkitc-1", +} + +# Make sure not missed here if a new variant added. +assert all(v in STANDARD_BOARDS for v in VARIANTS) + ESP32_BASE_PINS = { "TX": 1, "RX": 3, diff --git a/esphome/components/esp32_camera/__init__.py b/esphome/components/esp32_camera/__init__.py index 6e36f7d5a7..a99ec34087 100644 --- a/esphome/components/esp32_camera/__init__.py +++ b/esphome/components/esp32_camera/__init__.py @@ -1,3 +1,5 @@ +import logging + from esphome import automation, pins import esphome.codegen as cg from esphome.components import i2c @@ -8,6 +10,7 @@ from esphome.const import ( CONF_CONTRAST, CONF_DATA_PINS, CONF_FREQUENCY, + CONF_I2C, CONF_I2C_ID, CONF_ID, CONF_PIN, @@ -20,6 +23,9 @@ from esphome.const import ( ) from esphome.core import CORE from esphome.core.entity_helpers import setup_entity +import esphome.final_validate as fv + +_LOGGER = logging.getLogger(__name__) DEPENDENCIES = ["esp32"] @@ -250,6 +256,22 @@ CONFIG_SCHEMA = cv.All( cv.has_exactly_one_key(CONF_I2C_PINS, CONF_I2C_ID), ) + +def _final_validate(config): + if CONF_I2C_PINS not in config: + return + fconf = fv.full_config.get() + if fconf.get(CONF_I2C): + raise cv.Invalid( + "The `i2c_pins:` config option is incompatible with an dedicated `i2c:` block, use `i2c_id` instead" + ) + _LOGGER.warning( + "The `i2c_pins:` config option is deprecated. Use `i2c_id:` with a dedicated `i2c:` definition instead." + ) + + +FINAL_VALIDATE_SCHEMA = _final_validate + SETTERS = { # pin assignment CONF_DATA_PINS: "set_data_pins", diff --git a/esphome/components/logger/__init__.py b/esphome/components/logger/__init__.py index c055facd6c..e79396da04 100644 --- a/esphome/components/logger/__init__.py +++ b/esphome/components/logger/__init__.py @@ -193,7 +193,7 @@ def validate_local_no_higher_than_global(value): Logger = logger_ns.class_("Logger", cg.Component) LoggerMessageTrigger = logger_ns.class_( "LoggerMessageTrigger", - automation.Trigger.template(cg.int_, cg.const_char_ptr, cg.const_char_ptr), + automation.Trigger.template(cg.uint8, cg.const_char_ptr, cg.const_char_ptr), ) @@ -390,7 +390,7 @@ async def to_code(config): await automation.build_automation( trigger, [ - (cg.int_, "level"), + (cg.uint8, "level"), (cg.const_char_ptr, "tag"), (cg.const_char_ptr, "message"), ], diff --git a/esphome/components/lvgl/widgets/meter.py b/esphome/components/lvgl/widgets/meter.py index 04de195e3c..acec986f99 100644 --- a/esphome/components/lvgl/widgets/meter.py +++ b/esphome/components/lvgl/widgets/meter.py @@ -14,6 +14,7 @@ from esphome.const import ( CONF_VALUE, CONF_WIDTH, ) +from esphome.cpp_generator import IntLiteral from ..automation import action_to_code from ..defines import ( @@ -188,6 +189,8 @@ class MeterType(WidgetType): rotation = 90 + (360 - scale_conf[CONF_ANGLE_RANGE]) / 2 if CONF_ROTATION in scale_conf: rotation = await lv_angle.process(scale_conf[CONF_ROTATION]) + if isinstance(rotation, IntLiteral): + rotation = int(str(rotation)) // 10 with LocalVariable( "meter_var", "lv_meter_scale_t", lv_expr.meter_add_scale(var) ) as meter_var: diff --git a/esphome/core/base_automation.h b/esphome/core/base_automation.h index 13179b90bb..740e10700b 100644 --- a/esphome/core/base_automation.h +++ b/esphome/core/base_automation.h @@ -158,14 +158,14 @@ template class DelayAction : public Action, public Compon void play_complex(Ts... x) override { auto f = std::bind(&DelayAction::play_next_, this, x...); this->num_running_++; - this->set_timeout(this->delay_.value(x...), f); + this->set_timeout("delay", this->delay_.value(x...), f); } float get_setup_priority() const override { return setup_priority::HARDWARE; } void play(Ts... x) override { /* ignore - see play_complex */ } - void stop() override { this->cancel_timeout(""); } + void stop() override { this->cancel_timeout("delay"); } }; template class LambdaAction : public Action { diff --git a/esphome/core/component.cpp b/esphome/core/component.cpp index 623b521026..aec6c17786 100644 --- a/esphome/core/component.cpp +++ b/esphome/core/component.cpp @@ -255,10 +255,10 @@ void Component::defer(const char *name, std::function &&f) { // NOLINT App.scheduler.set_timeout(this, name, 0, std::move(f)); } void Component::set_timeout(uint32_t timeout, std::function &&f) { // NOLINT - App.scheduler.set_timeout(this, "", timeout, std::move(f)); + App.scheduler.set_timeout(this, static_cast(nullptr), timeout, std::move(f)); } void Component::set_interval(uint32_t interval, std::function &&f) { // NOLINT - App.scheduler.set_interval(this, "", interval, std::move(f)); + App.scheduler.set_interval(this, static_cast(nullptr), interval, std::move(f)); } void Component::set_retry(uint32_t initial_wait_time, uint8_t max_attempts, std::function &&f, float backoff_increase_factor) { // NOLINT diff --git a/esphome/core/event_pool.h b/esphome/core/event_pool.h index 69e03bafac..928a4e7dee 100644 --- a/esphome/core/event_pool.h +++ b/esphome/core/event_pool.h @@ -1,6 +1,6 @@ #pragma once -#if defined(USE_ESP32) || defined(USE_LIBRETINY) +#if defined(USE_ESP32) #include #include @@ -78,4 +78,4 @@ template class EventPool { } // namespace esphome -#endif // defined(USE_ESP32) || defined(USE_LIBRETINY) +#endif // defined(USE_ESP32) diff --git a/esphome/core/lock_free_queue.h b/esphome/core/lock_free_queue.h index f35cfa5af9..de07b0ebba 100644 --- a/esphome/core/lock_free_queue.h +++ b/esphome/core/lock_free_queue.h @@ -1,17 +1,12 @@ #pragma once -#if defined(USE_ESP32) || defined(USE_LIBRETINY) +#if defined(USE_ESP32) #include #include -#if defined(USE_ESP32) #include #include -#elif defined(USE_LIBRETINY) -#include -#include -#endif /* * Lock-free queue for single-producer single-consumer scenarios. @@ -148,4 +143,4 @@ template class NotifyingLockFreeQueue : public LockFreeQu } // namespace esphome -#endif // defined(USE_ESP32) || defined(USE_LIBRETINY) +#endif // defined(USE_ESP32) diff --git a/esphome/core/scheduler.cpp b/esphome/core/scheduler.cpp index ddf11e5b16..7a0c08e1f0 100644 --- a/esphome/core/scheduler.cpp +++ b/esphome/core/scheduler.cpp @@ -8,6 +8,7 @@ #include #include #include +#include namespace esphome { @@ -15,7 +16,7 @@ static const char *const TAG = "scheduler"; static const uint32_t MAX_LOGICALLY_DELETED_ITEMS = 10; // Half the 32-bit range - used to detect rollovers vs normal time progression -static const uint32_t HALF_MAX_UINT32 = 0x80000000UL; +static constexpr uint32_t HALF_MAX_UINT32 = std::numeric_limits::max() / 2; // Uncomment to debug scheduler // #define ESPHOME_DEBUG_SCHEDULER @@ -452,7 +453,7 @@ bool HOT Scheduler::cancel_item_(Component *component, bool is_static_string, co // Helper to cancel items by name - must be called with lock held bool HOT Scheduler::cancel_item_locked_(Component *component, const char *name_cstr, SchedulerItem::Type type) { // Early return if name is invalid - no items to cancel - if (name_cstr == nullptr || name_cstr[0] == '\0') { + if (name_cstr == nullptr) { return false; } @@ -518,8 +519,8 @@ uint64_t Scheduler::millis_64_(uint32_t now) { // This covers any reasonable scheduler delays or thread preemption static const uint32_t ROLLOVER_WINDOW = 10000; // 10 seconds in milliseconds - // Check if we're near the rollover boundary (close to 0xFFFFFFFF or just past 0) - bool near_rollover = (last > (0xFFFFFFFF - ROLLOVER_WINDOW)) || (now < ROLLOVER_WINDOW); + // Check if we're near the rollover boundary (close to std::numeric_limits::max() or just past 0) + bool near_rollover = (last > (std::numeric_limits::max() - ROLLOVER_WINDOW)) || (now < ROLLOVER_WINDOW); if (near_rollover || (now < last && (last - now) > HALF_MAX_UINT32)) { // Near rollover or detected a rollover - need lock for safety diff --git a/esphome/core/scheduler.h b/esphome/core/scheduler.h index 1fc2006697..64df2f2bb0 100644 --- a/esphome/core/scheduler.h +++ b/esphome/core/scheduler.h @@ -121,16 +121,17 @@ class Scheduler { name_is_dynamic = false; } - if (!name || !name[0]) { + if (!name) { + // nullptr case - no name provided name_.static_name = nullptr; } else if (make_copy) { - // Make a copy for dynamic strings + // Make a copy for dynamic strings (including empty strings) size_t len = strlen(name); name_.dynamic_name = new char[len + 1]; memcpy(name_.dynamic_name, name, len + 1); name_is_dynamic = true; } else { - // Use static string directly + // Use static string directly (including empty strings) name_.static_name = name; } } @@ -217,8 +218,7 @@ class Scheduler { // Platforms without atomic support or single-threaded platforms uint32_t last_millis_{0}; #endif - // millis_major_ is protected by lock when incrementing, volatile ensures - // reads outside the lock see fresh values (not cached in registers) + // millis_major_ is protected by lock when incrementing uint16_t millis_major_{0}; uint32_t to_remove_{0}; }; diff --git a/tests/component_tests/esp32/test_esp32.py b/tests/component_tests/esp32/test_esp32.py new file mode 100644 index 0000000000..fe031c653f --- /dev/null +++ b/tests/component_tests/esp32/test_esp32.py @@ -0,0 +1,73 @@ +""" +Test ESP32 configuration +""" + +from typing import Any + +import pytest + +from esphome.components.esp32 import VARIANTS +import esphome.config_validation as cv +from esphome.const import PlatformFramework + + +def test_esp32_config(set_core_config) -> None: + set_core_config(PlatformFramework.ESP32_IDF) + + from esphome.components.esp32 import CONFIG_SCHEMA + from esphome.components.esp32.const import VARIANT_ESP32, VARIANT_FRIENDLY + + # Example ESP32 configuration + config = { + "board": "esp32dev", + "variant": VARIANT_ESP32, + "cpu_frequency": "240MHz", + "flash_size": "4MB", + "framework": { + "type": "esp-idf", + }, + } + + # Check if the variant is valid + config = CONFIG_SCHEMA(config) + assert config["variant"] == VARIANT_ESP32 + + # Check that defining a variant sets the board name correctly + for variant in VARIANTS: + config = CONFIG_SCHEMA( + { + "variant": variant, + } + ) + assert VARIANT_FRIENDLY[variant].lower() in config["board"] + + +@pytest.mark.parametrize( + ("config", "error_match"), + [ + pytest.param( + {"flash_size": "4MB"}, + r"This board is unknown, if you are sure you want to compile with this board selection, override with option 'variant' @ data\['board'\]", + id="unknown_board_config", + ), + pytest.param( + {"variant": "esp32xx"}, + r"Unknown value 'ESP32XX', did you mean 'ESP32', 'ESP32S3', 'ESP32S2'\? for dictionary value @ data\['variant'\]", + id="unknown_variant_config", + ), + pytest.param( + {"variant": "esp32s3", "board": "esp32dev"}, + r"Option 'variant' does not match selected board. @ data\['variant'\]", + id="mismatched_board_variant_config", + ), + ], +) +def test_esp32_configuration_errors( + config: Any, + error_match: str, +) -> None: + """Test detection of invalid configuration.""" + from esphome.components.esp32 import CONFIG_SCHEMA + + with pytest.raises(cv.Invalid, match=error_match): + CONFIG_SCHEMA(config) diff --git a/tests/components/logger/test-on_message.host.yaml b/tests/components/logger/test-on_message.host.yaml new file mode 100644 index 0000000000..12211a257b --- /dev/null +++ b/tests/components/logger/test-on_message.host.yaml @@ -0,0 +1,18 @@ +logger: + id: logger_id + level: DEBUG + on_message: + - level: DEBUG + then: + - lambda: |- + ESP_LOGD("test", "Got message level %d: %s - %s", level, tag, message); + - level: WARN + then: + - lambda: |- + ESP_LOGW("test", "Warning level %d from %s", level, tag); + - level: ERROR + then: + - lambda: |- + // Test that level is uint8_t by using it in calculations + uint8_t adjusted_level = level + 1; + ESP_LOGE("test", "Error with adjusted level %d", adjusted_level); diff --git a/tests/integration/fixtures/delay_action_cancellation.yaml b/tests/integration/fixtures/delay_action_cancellation.yaml new file mode 100644 index 0000000000..e0dd427c2d --- /dev/null +++ b/tests/integration/fixtures/delay_action_cancellation.yaml @@ -0,0 +1,24 @@ +esphome: + name: test-delay-action + +host: +api: + actions: + - action: start_delay_then_restart + then: + - logger.log: "Starting first script execution" + - script.execute: test_delay_script + - delay: 250ms # Give first script time to start delay + - logger.log: "Restarting script (should cancel first delay)" + - script.execute: test_delay_script + +logger: + level: DEBUG + +script: + - id: test_delay_script + mode: restart + then: + - logger.log: "Script started, beginning delay" + - delay: 500ms # Long enough that it won't complete before restart + - logger.log: "Delay completed successfully" diff --git a/tests/integration/fixtures/scheduler_string_test.yaml b/tests/integration/fixtures/scheduler_string_test.yaml index 3dfe891370..c53ec392df 100644 --- a/tests/integration/fixtures/scheduler_string_test.yaml +++ b/tests/integration/fixtures/scheduler_string_test.yaml @@ -4,9 +4,7 @@ esphome: priority: -100 then: - logger.log: "Starting scheduler string tests" - platformio_options: - build_flags: - - "-DESPHOME_DEBUG_SCHEDULER" # Enable scheduler debug logging + debug_scheduler: true # Enable scheduler debug logging host: api: @@ -32,6 +30,12 @@ globals: - id: results_reported type: bool initial_value: 'false' + - id: edge_tests_done + type: bool + initial_value: 'false' + - id: empty_cancel_failed + type: bool + initial_value: 'false' script: - id: test_static_strings @@ -147,12 +151,106 @@ script: static TestDynamicDeferComponent test_dynamic_defer_component; test_dynamic_defer_component.test_dynamic_defer(); + - id: test_cancellation_edge_cases + then: + - logger.log: "Testing cancellation edge cases" + - lambda: |- + auto *component1 = id(test_sensor1); + // Use a different component for empty string tests to avoid interference + auto *component2 = id(test_sensor2); + + // Test 12: Cancel with empty string - regression test for issue #9599 + // First create a timeout with empty name on component2 to avoid interference + App.scheduler.set_timeout(component2, "", 500, []() { + ESP_LOGE("test", "ERROR: Empty name timeout fired - it should have been cancelled!"); + id(empty_cancel_failed) = true; + }); + + // Now cancel it - this should work after our fix + bool cancelled_empty = App.scheduler.cancel_timeout(component2, ""); + ESP_LOGI("test", "Cancel empty string result: %s (should be true)", cancelled_empty ? "true" : "false"); + if (!cancelled_empty) { + ESP_LOGE("test", "ERROR: Failed to cancel empty string timeout!"); + id(empty_cancel_failed) = true; + } + + // Test 13: Cancel non-existent timeout + bool cancelled_nonexistent = App.scheduler.cancel_timeout(component1, "does_not_exist"); + ESP_LOGI("test", "Cancel non-existent timeout result: %s", + cancelled_nonexistent ? "true (unexpected!)" : "false (expected)"); + + // Test 14: Multiple timeouts with same name - only last should execute + for (int i = 0; i < 5; i++) { + App.scheduler.set_timeout(component1, "duplicate_timeout", 200 + i*10, [i]() { + ESP_LOGI("test", "Duplicate timeout %d fired", i); + id(timeout_counter) += 1; + }); + } + ESP_LOGI("test", "Created 5 timeouts with same name 'duplicate_timeout'"); + + // Test 15: Multiple intervals with same name - only last should run + for (int i = 0; i < 3; i++) { + App.scheduler.set_interval(component1, "duplicate_interval", 300, [i]() { + ESP_LOGI("test", "Duplicate interval %d fired", i); + id(interval_counter) += 10; // Large increment to detect multiple + // Cancel after first execution + App.scheduler.cancel_interval(id(test_sensor1), "duplicate_interval"); + }); + } + ESP_LOGI("test", "Created 3 intervals with same name 'duplicate_interval'"); + + // Test 16: Cancel with nullptr protection (via empty const char*) + const char* null_name = ""; + App.scheduler.set_timeout(component2, null_name, 600, []() { + ESP_LOGE("test", "ERROR: Const char* empty timeout fired - should have been cancelled!"); + id(empty_cancel_failed) = true; + }); + bool cancelled_const_empty = App.scheduler.cancel_timeout(component2, null_name); + ESP_LOGI("test", "Cancel const char* empty result: %s (should be true)", + cancelled_const_empty ? "true" : "false"); + if (!cancelled_const_empty) { + ESP_LOGE("test", "ERROR: Failed to cancel const char* empty timeout!"); + id(empty_cancel_failed) = true; + } + + // Test 17: Rapid create/cancel/create with same name + App.scheduler.set_timeout(component1, "rapid_test", 5000, []() { + ESP_LOGI("test", "First rapid timeout - should not fire"); + id(timeout_counter) += 100; + }); + App.scheduler.cancel_timeout(component1, "rapid_test"); + App.scheduler.set_timeout(component1, "rapid_test", 250, []() { + ESP_LOGI("test", "Second rapid timeout - should fire"); + id(timeout_counter) += 1; + }); + + // Test 18: Cancel all with a specific name (multiple instances) + // Create multiple with same name + App.scheduler.set_timeout(component1, "multi_cancel", 300, []() { + ESP_LOGI("test", "Multi-cancel timeout 1"); + }); + App.scheduler.set_timeout(component1, "multi_cancel", 350, []() { + ESP_LOGI("test", "Multi-cancel timeout 2"); + }); + App.scheduler.set_timeout(component1, "multi_cancel", 400, []() { + ESP_LOGI("test", "Multi-cancel timeout 3 - only this should fire"); + id(timeout_counter) += 1; + }); + // Note: Each set_timeout with same name cancels the previous one automatically + - id: report_results then: - lambda: |- ESP_LOGI("test", "Final results - Timeouts: %d, Intervals: %d", id(timeout_counter), id(interval_counter)); + // Check if empty string cancellation test passed + if (id(empty_cancel_failed)) { + ESP_LOGE("test", "ERROR: Empty string cancellation test FAILED!"); + } else { + ESP_LOGI("test", "Empty string cancellation test PASSED"); + } + sensor: - platform: template name: Test Sensor 1 @@ -189,12 +287,23 @@ interval: - delay: 0.2s - script.execute: test_dynamic_strings + # Run cancellation edge case tests after dynamic tests + - interval: 0.2s + then: + - if: + condition: + lambda: 'return id(dynamic_tests_done) && !id(edge_tests_done);' + then: + - lambda: 'id(edge_tests_done) = true;' + - delay: 0.5s + - script.execute: test_cancellation_edge_cases + # Report results after all tests - interval: 0.2s then: - if: condition: - lambda: 'return id(dynamic_tests_done) && !id(results_reported);' + lambda: 'return id(edge_tests_done) && !id(results_reported);' then: - lambda: 'id(results_reported) = true;' - delay: 1s diff --git a/tests/integration/test_automations.py b/tests/integration/test_automations.py new file mode 100644 index 0000000000..bd2082e86b --- /dev/null +++ b/tests/integration/test_automations.py @@ -0,0 +1,91 @@ +"""Test ESPHome automations functionality.""" + +from __future__ import annotations + +import asyncio +import re + +import pytest + +from .types import APIClientConnectedFactory, RunCompiledFunction + + +@pytest.mark.asyncio +async def test_delay_action_cancellation( + yaml_config: str, + run_compiled: RunCompiledFunction, + api_client_connected: APIClientConnectedFactory, +) -> None: + """Test that delay actions can be properly cancelled when script restarts.""" + loop = asyncio.get_running_loop() + + # Track log messages with timestamps + log_entries: list[tuple[float, str]] = [] + script_starts: list[float] = [] + delay_completions: list[float] = [] + script_restart_logged = False + test_started_time = None + + # Patterns to match + test_start_pattern = re.compile(r"Starting first script execution") + script_start_pattern = re.compile(r"Script started, beginning delay") + restart_pattern = re.compile(r"Restarting script \(should cancel first delay\)") + delay_complete_pattern = re.compile(r"Delay completed successfully") + + # Future to track when we can check results + second_script_started = loop.create_future() + + def check_output(line: str) -> None: + """Check log output for expected messages.""" + nonlocal script_restart_logged, test_started_time + + current_time = loop.time() + log_entries.append((current_time, line)) + + if test_start_pattern.search(line): + test_started_time = current_time + elif script_start_pattern.search(line) and test_started_time: + script_starts.append(current_time) + if len(script_starts) == 2 and not second_script_started.done(): + second_script_started.set_result(True) + elif restart_pattern.search(line): + script_restart_logged = True + elif delay_complete_pattern.search(line): + delay_completions.append(current_time) + + async with ( + run_compiled(yaml_config, line_callback=check_output), + api_client_connected() as client, + ): + # Get services + entities, services = await client.list_entities_services() + + # Find our test service + test_service = next( + (s for s in services if s.name == "start_delay_then_restart"), None + ) + assert test_service is not None, "start_delay_then_restart service not found" + + # Execute the test sequence + client.execute_service(test_service, {}) + + # Wait for the second script to start + await asyncio.wait_for(second_script_started, timeout=5.0) + + # Wait for potential delay completion + await asyncio.sleep(0.75) # Original delay was 500ms + + # Check results + assert len(script_starts) == 2, ( + f"Script should have started twice, but started {len(script_starts)} times" + ) + assert script_restart_logged, "Script restart was not logged" + + # Verify we got exactly one completion and it happened ~500ms after the second start + assert len(delay_completions) == 1, ( + f"Expected 1 delay completion, got {len(delay_completions)}" + ) + time_from_second_start = delay_completions[0] - script_starts[1] + assert 0.4 < time_from_second_start < 0.6, ( + f"Delay completed {time_from_second_start:.3f}s after second start, expected ~0.5s" + ) diff --git a/tests/integration/test_scheduler_heap_stress.py b/tests/integration/test_scheduler_heap_stress.py index 1d6e1ec31e..2d55b8ae89 100644 --- a/tests/integration/test_scheduler_heap_stress.py +++ b/tests/integration/test_scheduler_heap_stress.py @@ -103,13 +103,14 @@ async def test_scheduler_heap_stress( # Wait for all callbacks to execute (should be quick, but give more time for scheduling) try: - await asyncio.wait_for(test_complete_future, timeout=60.0) + await asyncio.wait_for(test_complete_future, timeout=10.0) except TimeoutError: # Report how many we got + missing_ids = sorted(set(range(1000)) - executed_callbacks) pytest.fail( f"Stress test timed out. Only {len(executed_callbacks)} of " f"1000 callbacks executed. Missing IDs: " - f"{sorted(set(range(1000)) - executed_callbacks)[:10]}..." + f"{missing_ids[:20]}... (total missing: {len(missing_ids)})" ) # Verify all callbacks executed