fix tests

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
+      - delay: 1s  # Long enough that it won't complete before restart
-      - logger.log: "ERROR: First delay completed - this should NOT happen with restart mode!"
+      - logger.log: "Delay completed successfully"

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
+    # Track log messages with timestamps
-    log_lines: list[str] = []
+    log_entries: list[tuple[float, str]] = []
-    script_start_count = 0
+    script_starts: list[float] = []
-    first_delay_completed = False
+    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 \
+        nonlocal script_restart_logged, test_started_time
-            script_start_count, \
-            first_delay_completed, \
-            script_restart_logged, \
-            test_started
 
-        log_lines.append(line)
+        current_time = loop.time()
+        log_entries.append((current_time, line))
 
         if test_start_pattern.search(line):
-            test_started = True
+            test_started_time = current_time
-        elif script_start_pattern.search(line) and test_started:
+        elif script_start_pattern.search(line) and test_started_time:
-            script_start_count += 1
+            script_starts.append(current_time)
-            if script_start_count == 2 and not second_script_started.done():
+            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):
+        elif delay_complete_pattern.search(line):
-            first_delay_completed = True
+            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
+        # Wait for potential delay completion
-        await asyncio.sleep(6.0)  # Original delay was 5s
+        await asyncio.sleep(1.5)  # Original delay was 1s
 
         # Check results
-        assert script_start_count == 2, (
+        assert len(script_starts) == 2, (
-            f"Script should have started twice, but started {script_start_count} times"
+            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
+        # The key assertion: we should only see ONE delay completion (from the second script)
-        if first_delay_completed:
+        if len(delay_completions) > 1:
-            # Print relevant logs for debugging
+            # Print timing analysis
-            relevant_logs = [
+            timing_info = []
-                line
+            if len(script_starts) >= 2 and len(delay_completions) >= 1:
-                for line in log_lines
+                first_start = script_starts[0]
-                if any(
+                second_start = script_starts[1]
-                    pattern in line
+                timing_info.append(
-                    for pattern in ["Script", "delay", "ERROR", "Restart"]
+                    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! "
+                f"Found {len(delay_completions)} delay completions, but expected only 1!\n"
-                "This means DelayAction is not being cancelled properly.\n"
+                "The first delay should have been cancelled by the script restart.\n"
-                "Log output:\n" + "\n".join(relevant_logs[-20:])
+                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"
             )