From 4f3515192842e1b31f0f28958882d8ec84266db3 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 17 Jul 2025 16:35:53 -1000 Subject: [PATCH] fixes --- .../fixtures/delay_action_cancellation.yaml | 31 +--- tests/integration/test_automations.py | 136 ++++++++---------- 2 files changed, 70 insertions(+), 97 deletions(-) diff --git a/tests/integration/fixtures/delay_action_cancellation.yaml b/tests/integration/fixtures/delay_action_cancellation.yaml index 1ef964509b..1646c8c910 100644 --- a/tests/integration/fixtures/delay_action_cancellation.yaml +++ b/tests/integration/fixtures/delay_action_cancellation.yaml @@ -4,38 +4,21 @@ esphome: host: api: actions: - - action: start_script + - action: start_delay_then_restart then: + - logger.log: "Starting first script execution" - script.execute: test_delay_script - - - action: restart_script - then: + - delay: 500ms # Give first script time to start delay + - logger.log: "Restarting script (should cancel first delay)" - script.execute: test_delay_script - - action: check_result - then: - - logger.log: - format: "Test completed with %d delay completions" - args: ['id(delay_completed_count)'] - logger: level: DEBUG -globals: - - id: delay_completed_count - type: int - initial_value: "0" - script: - id: test_delay_script mode: restart then: - - logger.log: - format: "Script execution started (run number %d)" - args: ['id(delay_completed_count) + 1'] - - delay: 150ms - - lambda: |- - id(delay_completed_count)++; - - logger.log: - format: "Delay completed! Total completions: %d" - args: ['id(delay_completed_count)'] + - logger.log: "Script started, beginning delay" + - delay: 5s # Long enough that it won't complete before restart + - logger.log: "ERROR: First delay completed - this should NOT happen with restart mode!" diff --git a/tests/integration/test_automations.py b/tests/integration/test_automations.py index d43ae1d842..bd9ce9be9a 100644 --- a/tests/integration/test_automations.py +++ b/tests/integration/test_automations.py @@ -19,51 +19,42 @@ async def test_delay_action_cancellation( """Test that delay actions can be properly cancelled when script restarts.""" loop = asyncio.get_running_loop() - # Track events via futures - script_started_future = loop.create_future() - script_restarted_future = loop.create_future() - delay_completed_future = loop.create_future() - test_complete_future = loop.create_future() - - # Track counts - script_started_count = 0 - delay_completed_count = 0 + # Track log messages + log_lines: list[str] = [] + script_start_count = 0 + first_delay_completed = False + script_restart_logged = False + test_started = False # Patterns to match - script_start_pattern = re.compile(r"Script execution started \(run number (\d+)\)") - script_restart_pattern = re.compile(r"restarting \(mode: restart\)") - delay_complete_pattern = re.compile(r"Delay completed! Total completions: (\d+)") - test_complete_pattern = re.compile(r"Test completed with (\d+) delay completions") + 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\)") + error_pattern = re.compile(r"ERROR: First delay completed") + + # 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_started_count, delay_completed_count + nonlocal \ + script_start_count, \ + first_delay_completed, \ + script_restart_logged, \ + test_started - # Check for script start - start_match = script_start_pattern.search(line) - if start_match: - script_started_count += 1 - if not script_started_future.done(): - script_started_future.set_result(True) + log_lines.append(line) - # Check for script restart - if script_restart_pattern.search(line): - if not script_restarted_future.done(): - script_restarted_future.set_result(True) - - # Check for delay completion - complete_match = delay_complete_pattern.search(line) - if complete_match: - delay_completed_count = int(complete_match.group(1)) - if not delay_completed_future.done(): - delay_completed_future.set_result(delay_completed_count) - - # Check for test completion - test_match = test_complete_pattern.search(line) - if test_match: - final_count = int(test_match.group(1)) - if not test_complete_future.done(): - test_complete_future.set_result(final_count) + if test_start_pattern.search(line): + test_started = True + elif script_start_pattern.search(line) and test_started: + script_start_count += 1 + if script_start_count == 2 and not second_script_started.done(): + second_script_started.set_result(True) + elif restart_pattern.search(line): + script_restart_logged = True + elif error_pattern.search(line): + first_delay_completed = True async with ( run_compiled(yaml_config, line_callback=check_output), @@ -72,41 +63,40 @@ async def test_delay_action_cancellation( # Get services entities, services = await client.list_entities_services() - # Find our test services - start_service = next((s for s in services if s.name == "start_script"), None) - restart_service = next( - (s for s in services if s.name == "restart_script"), None + # Find our test service + test_service = next( + (s for s in services if s.name == "start_delay_then_restart"), None ) - check_result_service = next( - (s for s in services if s.name == "check_result"), 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 a bit more to ensure first delay would have completed if not cancelled + await asyncio.sleep(6.0) # Original delay was 5s + + # Check results + assert script_start_count == 2, ( + f"Script should have started twice, but started {script_start_count} times" ) + assert script_restart_logged, "Script restart was not logged" - assert start_service is not None, "start_script service not found" - assert restart_service is not None, "restart_script service not found" - assert check_result_service is not None, "check_result service not found" - - # Start the script - client.execute_service(start_service, {}) - - # Wait for script to start - await asyncio.wait_for(script_started_future, timeout=5.0) - assert script_started_count == 1, "Script should have started once" - - # Restart the script - client.execute_service(restart_service, {}) - - # Wait for restart confirmation - await asyncio.wait_for(script_restarted_future, timeout=2.0) - - # Wait for the restarted script to complete its delay - await asyncio.wait_for(delay_completed_future, timeout=1.0) - - # Check the final result - client.execute_service(check_result_service, {}) - final_count = await asyncio.wait_for(test_complete_future, timeout=5.0) - - # If DelayAction cancellation works correctly, we should only have 1 completion - # (from the restarted script). If it doesn't work, we'd have 2 completions. - assert final_count == 1, ( - f"Expected 1 delay completion after restart, but got {final_count}" - ) + # This is the key assertion - the first delay should NOT have completed + if first_delay_completed: + # Print relevant logs for debugging + relevant_logs = [ + line + for line in log_lines + if any( + pattern in line + for pattern in ["Script", "delay", "ERROR", "Restart"] + ) + ] + pytest.fail( + "First delay completed even though script was restarted! " + "This means DelayAction is not being cancelled properly.\n" + "Log output:\n" + "\n".join(relevant_logs[-20:]) + )