From 1d373ef621849ad7945f364c0ad45a73307a8391 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 17 Jul 2025 16:49:32 -1000 Subject: [PATCH] fix tests --- .../fixtures/delay_action_cancellation.yaml | 4 +- tests/integration/test_automations.py | 94 ++++++++++++------- 2 files changed, 61 insertions(+), 37 deletions(-) diff --git a/tests/integration/fixtures/delay_action_cancellation.yaml b/tests/integration/fixtures/delay_action_cancellation.yaml index 1646c8c910..0b42f9b12d 100644 --- a/tests/integration/fixtures/delay_action_cancellation.yaml +++ b/tests/integration/fixtures/delay_action_cancellation.yaml @@ -20,5 +20,5 @@ script: mode: restart then: - 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!" + - delay: 1s # Long enough that it won't complete before restart + - logger.log: "Delay completed successfully" diff --git a/tests/integration/test_automations.py b/tests/integration/test_automations.py index bd9ce9be9a..7307c9fa55 100644 --- a/tests/integration/test_automations.py +++ b/tests/integration/test_automations.py @@ -19,42 +19,39 @@ async def test_delay_action_cancellation( """Test that delay actions can be properly cancelled when script restarts.""" loop = asyncio.get_running_loop() - # Track log messages - log_lines: list[str] = [] - script_start_count = 0 - first_delay_completed = False + # 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 = 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\)") - error_pattern = re.compile(r"ERROR: First delay completed") + 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_start_count, \ - first_delay_completed, \ - script_restart_logged, \ - test_started + nonlocal script_restart_logged, test_started_time - log_lines.append(line) + current_time = loop.time() + log_entries.append((current_time, line)) 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(): + 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 error_pattern.search(line): - first_delay_completed = True + elif delay_complete_pattern.search(line): + delay_completions.append(current_time) async with ( run_compiled(yaml_config, line_callback=check_output), @@ -75,28 +72,55 @@ async def test_delay_action_cancellation( # 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 + # Wait for potential delay completion + await asyncio.sleep(1.5) # Original delay was 1s # Check results - assert script_start_count == 2, ( - f"Script should have started twice, but started {script_start_count} times" + 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" - # 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"] + # The key assertion: we should only see ONE delay completion (from the second script) + if len(delay_completions) > 1: + # Print timing analysis + timing_info = [] + if len(script_starts) >= 2 and len(delay_completions) >= 1: + first_start = script_starts[0] + second_start = script_starts[1] + timing_info.append( + f"First script started at: +{first_start - test_started_time:.3f}s" ) - ] + timing_info.append( + f"Second script started at: +{second_start - test_started_time:.3f}s" + ) + timing_info.append( + f"Time between starts: {second_start - first_start:.3f}s" + ) + for i, completion in enumerate(delay_completions): + timing_info.append( + f"Delay {i + 1} completed at: +{completion - test_started_time:.3f}s" + ) + if i == 0: + timing_info.append( + f" Time from first start: {completion - first_start:.3f}s" + ) + timing_info.append( + f" Time from second start: {completion - second_start:.3f}s" + ) + 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:]) + f"Found {len(delay_completions)} delay completions, but expected only 1!\n" + "The first delay should have been cancelled by the script restart.\n" + f"Timing analysis:\n" + "\n".join(timing_info) + ) + + # Verify we got exactly one completion and it happened ~5s after the second start + assert len(delay_completions) == 1, ( + f"Expected 1 delay completion, got {len(delay_completions)}" + ) + if len(script_starts) >= 2 and len(delay_completions) >= 1: + time_from_second_start = delay_completions[0] - script_starts[1] + assert 0.8 < time_from_second_start < 1.2, ( + f"Delay completed {time_from_second_start:.3f}s after second start, expected ~1s" )