Update E2E Tests v3

* Update E2E Tests v3

Author: abraunegg

ci/e2e/framework/utils.py

@@ -27,6 +27,7 @@ def ok(self) -> bool:
 STARTUP_DISCOVERY_FUNCTION_MARKERS = (
     "Calling Function:    syncEngine.getDefaultRootDetails()",
     "Calling Function:    syncEngine.getDefaultDriveDetails()",
+    "Calling Function:    syncEngine.fetchRealOnlineDriveIdentifier()",
 )
 STARTUP_TRANSIENT_HTTP_MARKERS = (
     "HTTP request returned status code 403 (Forbidden)",

ci/e2e/testcases/monitor_case_base.py

@@ -68,6 +68,58 @@ def _read_stdout_from_offset(self, stdout_file: Path, start_offset: int) -> str:
             return ""
         return content[start_offset:]
 
+    def _read_app_logs(self, app_log_dir: Path) -> str:
+        if not app_log_dir.exists():
+            return ""
+
+        segments: list[str] = []
+        for log_file in sorted(path for path in app_log_dir.rglob("*.log") if path.is_file()):
+            try:
+                segments.append(log_file.read_text(encoding="utf-8", errors="replace"))
+            except OSError:
+                continue
+        return "\n".join(segments)
+
+    def _read_app_logs_from_offset(self, app_log_dir: Path, start_offset: int) -> str:
+        content = self._read_app_logs(app_log_dir)
+        if start_offset <= 0:
+            return content
+        if start_offset >= len(content):
+            return ""
+        return content[start_offset:]
+
+    def _monitor_app_log_dir_for_stdout(self, stdout_file: Path) -> Path:
+        return stdout_file.parent / "app-logs"
+
+    def _remember_monitor_app_log_offset(self, stdout_file: Path, offset: int) -> None:
+        if not hasattr(self, "_monitor_app_log_start_offsets"):
+            self._monitor_app_log_start_offsets = {}
+        self._monitor_app_log_start_offsets[str(stdout_file)] = offset
+
+    def _monitor_app_log_start_offset(self, stdout_file: Path) -> int:
+        offsets = getattr(self, "_monitor_app_log_start_offsets", {})
+        return int(offsets.get(str(stdout_file), 0))
+
+    def _read_monitor_output_from_offsets(self, stdout_file: Path, stdout_start_offset: int) -> str:
+        """Read post-mutation monitor evidence from stdout and the app log.
+
+        Local monitor event processing does not always emit another global
+        sync-complete marker after an inotify wake.  The stable evidence is the
+        per-event upload/delete/move output, and that may be present in stdout,
+        the configured application log, or both depending on verbosity and CI
+        buffering.  Offset both streams so assertions only inspect activity that
+        happened after the test mutation.
+        """
+        stdout_segment = self._read_stdout_from_offset(stdout_file, stdout_start_offset)
+        app_log_dir = self._monitor_app_log_dir_for_stdout(stdout_file)
+        app_log_segment = self._read_app_logs_from_offset(
+            app_log_dir,
+            self._monitor_app_log_start_offset(stdout_file),
+        )
+        if stdout_segment and app_log_segment:
+            return stdout_segment + "\n" + app_log_segment
+        return stdout_segment or app_log_segment
+
     def _wait_for_initial_sync_complete(
         self,
         stdout_file: Path,
@@ -130,17 +182,21 @@ def _prepare_monitor_for_local_mutation(
         quiet_seconds: float = 3.0,
         timeout_seconds: int = 30,
     ) -> int:
-        """Wait for monitor readiness and return the post-mutation log offset."""
+        """Wait for monitor readiness and return the post-mutation stdout offset."""
         ready = self._wait_for_monitor_stdout_quiet(
             process,
             stdout_file,
             quiet_seconds=quiet_seconds,
             timeout_seconds=timeout_seconds,
         )
         content = self._read_stdout(stdout_file)
+        app_log_content = self._read_app_logs(self._monitor_app_log_dir_for_stdout(stdout_file))
+        self._remember_monitor_app_log_offset(stdout_file, len(app_log_content))
         details["monitor_ready_after_initial_sync"] = ready
         details["initial_sync_complete_count_before_mutation"] = content.count(self.SYNC_COMPLETE_PATTERN)
+        details["app_log_sync_complete_count_before_mutation"] = app_log_content.count(self.SYNC_COMPLETE_PATTERN)
         details["mutation_log_start_offset"] = len(content)
+        details["mutation_app_log_start_offset"] = len(app_log_content)
         return len(content)
 
     def _wait_for_monitor_patterns(
@@ -154,7 +210,7 @@ def _wait_for_monitor_patterns(
         deadline = time.time() + timeout_seconds
 
         while time.time() < deadline:
-            content = self._read_stdout_from_offset(stdout_file, start_offset)
+            content = self._read_monitor_output_from_offsets(stdout_file, start_offset)
             if all(pattern in content for pattern in required_patterns):
                 return True
             time.sleep(poll_interval)
@@ -174,7 +230,7 @@ def _wait_for_stdout_growth_patterns(
         latest_segment = ""
 
         while time.time() < deadline:
-            latest_segment = self._read_stdout_from_offset(stdout_file, start_offset)
+            latest_segment = self._read_monitor_output_from_offsets(stdout_file, start_offset)
             if all(pattern in latest_segment for pattern in required_patterns):
                 return True, latest_segment
             time.sleep(poll_interval)
@@ -192,7 +248,7 @@ def _wait_for_any_monitor_pattern_group(
         deadline = time.time() + timeout_seconds
 
         while time.time() < deadline:
-            content = self._read_stdout_from_offset(stdout_file, start_offset)
+            content = self._read_monitor_output_from_offsets(stdout_file, start_offset)
             for idx, group in enumerate(alternative_pattern_groups):
                 if all(pattern in content for pattern in group):
                     return True, idx
@@ -213,14 +269,50 @@ def _wait_for_any_stdout_growth_pattern_group(
         latest_segment = ""
 
         while time.time() < deadline:
-            latest_segment = self._read_stdout_from_offset(stdout_file, start_offset)
+            latest_segment = self._read_monitor_output_from_offsets(stdout_file, start_offset)
             for idx, group in enumerate(alternative_pattern_groups):
                 if all(pattern in latest_segment for pattern in group):
                     return True, idx, latest_segment
             time.sleep(poll_interval)
 
         return False, -1, latest_segment
 
+    def _wait_for_required_patterns_and_any_group(
+        self,
+        stdout_file: Path,
+        *,
+        start_offset: int,
+        required_patterns: list[str],
+        alternative_pattern_groups: list[list[str]],
+        timeout_seconds: int = 120,
+        poll_interval: float = 0.5,
+    ) -> tuple[bool, bool, int, str]:
+        """Wait until all fixed patterns and one alternative group are observed."""
+        deadline = time.time() + timeout_seconds
+        latest_segment = ""
+        matched_group = -1
+
+        while time.time() < deadline:
+            latest_segment = self._read_monitor_output_from_offsets(stdout_file, start_offset)
+            fixed_ok = all(pattern in latest_segment for pattern in required_patterns)
+            matched_group = -1
+            for idx, group in enumerate(alternative_pattern_groups):
+                if all(pattern in latest_segment for pattern in group):
+                    matched_group = idx
+                    break
+            group_ok = matched_group >= 0
+            if fixed_ok and group_ok:
+                return True, True, matched_group, latest_segment
+            time.sleep(poll_interval)
+
+        fixed_ok = all(pattern in latest_segment for pattern in required_patterns)
+        matched_group = -1
+        for idx, group in enumerate(alternative_pattern_groups):
+            if all(pattern in latest_segment for pattern in group):
+                matched_group = idx
+                break
+        return fixed_ok, matched_group >= 0, matched_group, latest_segment
+
     def _wait_for_post_mutation_sync_complete(
         self,
         stdout_file: Path,
@@ -230,14 +322,20 @@ def _wait_for_post_mutation_sync_complete(
         poll_interval: float = 0.5,
         quiet_seconds_after_marker: float = 3.0,
     ) -> tuple[bool, str]:
+        """Wait for a post-mutation global sync-complete marker when a test needs it.
+
+        Most local inotify tests should not use this helper.  Local event handling
+        can complete successfully without emitting another global sync-complete
+        line, so those tests should wait for their event-specific patterns instead.
+        """
         deadline = time.time() + timeout_seconds
         latest_segment = ""
         marker_seen = False
         last_length = -1
         quiet_started_at: float | None = None
 
         while time.time() < deadline:
-            latest_segment = self._read_stdout_from_offset(stdout_file, start_offset)
+            latest_segment = self._read_monitor_output_from_offsets(stdout_file, start_offset)
             now = time.time()
 
             if self.SYNC_COMPLETE_PATTERN in latest_segment:

ci/e2e/testcases/tc0002_sync_list_validation.py

@@ -4,6 +4,7 @@
 import os
 import re
 import shutil
+import time
 from dataclasses import dataclass, field
 from pathlib import Path
 
@@ -454,6 +455,58 @@ def _run_standard_scenario(
         diffs = self._validate_scenario(scenario, fixture_events)
         return diffs, artifacts, metadata
 
+    def _is_retryable_cleanup_seed_failure(self, stdout: str, stderr: str) -> bool:
+        content = f"{stdout}\n{stderr}"
+        retryable_markers = (
+            "HTTP request returned status code 408",
+            "HTTP request returned status code 429",
+            "HTTP request returned status code 500",
+            "HTTP request returned status code 502",
+            "HTTP request returned status code 503",
+            "HTTP request returned status code 504",
+            "Failed items to upload",
+            "Parent path is not in the database or online",
+            "Unable to upload this file",
+            "std.json.JSONException",
+        )
+        return any(marker in content for marker in retryable_markers)
+
+    def _run_cleanup_seed_command_with_retry(
+        self,
+        context: E2EContext,
+        command: list[str],
+        *,
+        max_attempts: int = 2,
+        retry_sleep_seconds: float = 3.0,
+    ) -> tuple[object, int, list[str], str, str]:
+        attempts = 0
+        retry_reasons: list[str] = []
+        stdout_segments: list[str] = []
+        stderr_segments: list[str] = []
+        last_result = None
+
+        for attempt in range(1, max_attempts + 1):
+            attempts = attempt
+            result = run_command(command, cwd=context.repo_root)
+            last_result = result
+            stdout_segments.append(f"\n===== cleanup seed attempt {attempt} stdout =====\n{result.stdout}")
+            stderr_segments.append(f"\n===== cleanup seed attempt {attempt} stderr =====\n{result.stderr}")
+
+            if result.returncode == 0:
+                break
+
+            if attempt >= max_attempts or not self._is_retryable_cleanup_seed_failure(result.stdout, result.stderr):
+                break
+
+            retry_reasons.append(f"attempt {attempt} returned {result.returncode}; retryable seed failure marker observed")
+            context.log(
+                f"Scenario cleanup seed returned {result.returncode}; retrying attempt {attempt + 1}/{max_attempts}"
+            )
+            time.sleep(retry_sleep_seconds)
+
+        assert last_result is not None
+        return last_result, attempts, retry_reasons, "".join(stdout_segments).lstrip("\n"), "".join(stderr_segments).lstrip("\n")
+
     def _run_cleanup_regression_scenario(
         self,
         context: E2EContext,
@@ -500,13 +553,21 @@ def _run_cleanup_regression_scenario(
             sync_list_path.unlink()
 
         phase1_command = self._build_sync_command(context, sync_root, config_dir)
-        phase1_result = run_command(phase1_command, cwd=context.repo_root)
-        write_text_file(phase1_stdout, phase1_result.stdout)
-        write_text_file(phase1_stderr, phase1_result.stderr)
+        (
+            phase1_result,
+            phase1_attempts,
+            phase1_retry_reasons,
+            phase1_stdout_text,
+            phase1_stderr_text,
+        ) = self._run_cleanup_seed_command_with_retry(context, phase1_command)
+        write_text_file(phase1_stdout, phase1_stdout_text)
+        write_text_file(phase1_stderr, phase1_stderr_text)
         metadata.extend(
             [
                 f"phase1_command={command_to_string(phase1_command)}",
                 f"phase1_returncode={phase1_result.returncode}",
+                f"phase1_attempts={phase1_attempts}",
+                f"phase1_retry_reasons={phase1_retry_reasons!r}",
             ]
         )
 

ci/e2e/testcases/tc0020_monitor_mode_validation.py

@@ -103,14 +103,19 @@ def run(self, context: E2EContext) -> TestResult:
                 )
 
             mutation_log_start_offset = self._prepare_monitor_for_local_mutation(process, stdout_file, details)
-            write_text_file(sync_root / root_name / "monitor-added.txt", "added while monitor mode was running\n")
-            post_mutation_sync_complete, post_mutation_log_segment = self._wait_for_post_mutation_sync_complete(
+            monitor_added_relative = f"{root_name}/monitor-added.txt"
+            write_text_file(sync_root / monitor_added_relative, "added while monitor mode was running\n")
+            required_patterns = [f"Uploading new file: {monitor_added_relative} ... done"]
+            mutation_processed, post_mutation_log_segment = self._wait_for_stdout_growth_patterns(
                 stdout_file,
                 start_offset=mutation_log_start_offset,
+                required_patterns=required_patterns,
                 timeout_seconds=180,
             )
-            details["post_mutation_sync_complete"] = post_mutation_sync_complete
+            details["post_mutation_sync_complete"] = self.SYNC_COMPLETE_PATTERN in post_mutation_log_segment
+            details["mutation_processed"] = mutation_processed
             details["post_mutation_log_segment_length"] = len(post_mutation_log_segment)
+            details["mutation_required_patterns"] = required_patterns
         finally:
             self._shutdown_monitor_process(process, details)
 

ci/e2e/testcases/tc0041_monitor_mode_local_create_upload.py

@@ -194,12 +194,13 @@ def run(self, context: E2EContext) -> TestResult:
             required_patterns = [
                 f"Uploading new file: {created_relative} ... done",
             ]
-            post_mutation_sync_complete, post_mutation_log_segment = self._wait_for_post_mutation_sync_complete(
+            mutation_processed, post_mutation_log_segment = self._wait_for_stdout_growth_patterns(
                 monitor_stdout,
                 start_offset=mutation_log_start_offset,
+                required_patterns=required_patterns,
                 timeout_seconds=180,
             )
-            mutation_processed = all(pattern in post_mutation_log_segment for pattern in required_patterns)
+            post_mutation_sync_complete = self.SYNC_COMPLETE_PATTERN in post_mutation_log_segment
             details["post_mutation_sync_complete"] = post_mutation_sync_complete
             details["mutation_processed"] = mutation_processed
             details["post_mutation_log_segment_length"] = len(post_mutation_log_segment)

ci/e2e/testcases/tc0042_monitor_mode_local_modify_upload.py

@@ -226,12 +226,13 @@ def run(self, context: E2EContext) -> TestResult:
             required_patterns = [
                 f"Uploading modified file: {relative_path} ... done",
             ]
-            post_mutation_sync_complete, post_mutation_log_segment = self._wait_for_post_mutation_sync_complete(
+            mutation_processed, post_mutation_log_segment = self._wait_for_stdout_growth_patterns(
                 monitor_stdout,
                 start_offset=mutation_log_start_offset,
+                required_patterns=required_patterns,
                 timeout_seconds=180,
             )
-            mutation_processed = all(pattern in post_mutation_log_segment for pattern in required_patterns)
+            post_mutation_sync_complete = self.SYNC_COMPLETE_PATTERN in post_mutation_log_segment
             details["post_mutation_sync_complete"] = post_mutation_sync_complete
             details["mutation_processed"] = mutation_processed
             details["post_mutation_log_segment_length"] = len(post_mutation_log_segment)

ci/e2e/testcases/tc0043_monitor_mode_local_delete_propagation.py

@@ -229,12 +229,13 @@ def run(self, context: E2EContext) -> TestResult:
             required_patterns = [
                 f"Deleting item from Microsoft OneDrive: {delete_relative}",
             ]
-            post_mutation_sync_complete, post_mutation_log_segment = self._wait_for_post_mutation_sync_complete(
+            mutation_processed, post_mutation_log_segment = self._wait_for_stdout_growth_patterns(
                 monitor_stdout,
                 start_offset=mutation_log_start_offset,
+                required_patterns=required_patterns,
                 timeout_seconds=180,
             )
-            mutation_processed = all(pattern in post_mutation_log_segment for pattern in required_patterns)
+            post_mutation_sync_complete = self.SYNC_COMPLETE_PATTERN in post_mutation_log_segment
             details["post_mutation_sync_complete"] = post_mutation_sync_complete
             details["mutation_processed"] = mutation_processed
             details["post_mutation_log_segment_length"] = len(post_mutation_log_segment)

ci/e2e/testcases/tc0044_monitor_mode_local_rename_propagation.py

@@ -231,18 +231,13 @@ def run(self, context: E2EContext) -> TestResult:
                     f"Uploading new file: {new_relative} ... done",
                 ],
             ]
-            post_mutation_sync_complete, post_mutation_log_segment = self._wait_for_post_mutation_sync_complete(
+            mutation_processed, matched_group, post_mutation_log_segment = self._wait_for_any_stdout_growth_pattern_group(
                 monitor_stdout,
                 start_offset=mutation_log_start_offset,
+                alternative_pattern_groups=pattern_groups,
                 timeout_seconds=180,
             )
-            mutation_processed = False
-            matched_group = -1
-            for idx, group in enumerate(pattern_groups):
-                if all(pattern in post_mutation_log_segment for pattern in group):
-                    mutation_processed = True
-                    matched_group = idx
-                    break
+            post_mutation_sync_complete = self.SYNC_COMPLETE_PATTERN in post_mutation_log_segment
             details["post_mutation_sync_complete"] = post_mutation_sync_complete
             details["mutation_processed"] = mutation_processed
             details["matched_pattern_group_index"] = matched_group

ci/e2e/testcases/tc0045_monitor_mode_local_directory_create_propagation.py

@@ -114,12 +114,13 @@ def run(self, context: E2EContext) -> TestResult:
             required_patterns = [
                 f"Uploading new file: {created_file_relative} ... done",
             ]
-            post_mutation_sync_complete, post_mutation_log_segment = self._wait_for_post_mutation_sync_complete(
+            mutation_processed, post_mutation_log_segment = self._wait_for_stdout_growth_patterns(
                 monitor_stdout,
                 start_offset=mutation_log_start_offset,
+                required_patterns=required_patterns,
                 timeout_seconds=180,
             )
-            mutation_processed = all(pattern in post_mutation_log_segment for pattern in required_patterns)
+            post_mutation_sync_complete = self.SYNC_COMPLETE_PATTERN in post_mutation_log_segment
             details["post_mutation_sync_complete"] = post_mutation_sync_complete
             details["mutation_processed"] = mutation_processed
             details["post_mutation_log_segment_length"] = len(post_mutation_log_segment)