| 1 | """Run the WSL TAEF tests in a loop, capturing per-iteration output and an ETL trace. |
| 2 | |
| 3 | Usage: |
| 4 | python loop-tests.py <iterations> [-- <test.bat args>...] |
| 5 | """ |
| 6 | |
| 7 | import atexit |
| 8 | import re |
| 9 | import shutil |
| 10 | import subprocess |
| 11 | import sys |
| 12 | import threading |
| 13 | import time |
| 14 | from contextlib import contextmanager |
| 15 | from datetime import datetime, timedelta |
| 16 | from pathlib import Path |
| 17 | |
| 18 | import click |
| 19 | |
| 20 | REPO_ROOT = Path(__file__).resolve().parents[2] |
| 21 | DEFAULT_WPRP = REPO_ROOT / "diagnostics" / "wsl.wprp" |
| 22 | |
| 23 | START_GROUP_RE = re.compile(r"StartGroup:\s+(\S+)") |
| 24 | END_GROUP_RE = re.compile(r"EndGroup:\s+(\S+)\s+\[(?P<verdict>\w+)\]") |
| 25 | PASS_VERDICTS = {"passed", "skipped"} |
| 26 | |
| 27 | # Terminal control sequences (CSI = Control Sequence Introducer, "ESC ["). |
| 28 | _CSI = "\x1b[" |
| 29 | _ERASE_LINE = f"{_CSI}2K" # EL - erase the entire current line |
| 30 | _CURSOR_COL_1 = f"{_CSI}G" # CHA - move cursor to column 1 (1-based) |
| 31 | _HIDE_CURSOR = f"{_CSI}?25l" # DECTCEM - hide the cursor |
| 32 | _SHOW_CURSOR = f"{_CSI}?25h" # DECTCEM - show the cursor |
| 33 | _SGR_RESET = f"{_CSI}0m" # SGR - reset all attributes (colors, bold, ...) |
| 34 | # Reset the current line: move cursor home then erase, so the next write |
| 35 | # starts from a clean slate regardless of what was there before. |
| 36 | _RESET_LINE = _CURSOR_COL_1 + _ERASE_LINE |
| 37 | |
| 38 | |
| 39 | class StatusLine: |
| 40 | """Single-line status display reused across iterations and refreshed once per second.""" |
| 41 | |
| 42 | def __init__(self, total: int): |
| 43 | self._total = total |
| 44 | self._iteration = 0 |
| 45 | self._iter_start = time.monotonic() |
| 46 | self._test = "(initializing)" |
| 47 | self._passed = 0 |
| 48 | self._failed = 0 |
| 49 | self._lock = threading.RLock() |
| 50 | self._stop_event = threading.Event() |
| 51 | # Only emit terminal control sequences when stdout is an interactive |
| 52 | # terminal; otherwise we'd garble redirected output (logs, CI, etc.). |
| 53 | self._enabled = sys.stdout.isatty() |
| 54 | self._cursor_hidden = False |
| 55 | self._thread = threading.Thread(target=self._loop, daemon=True) |
| 56 | atexit.register(self._safe_restore) |
| 57 | |
| 58 | def start(self) -> None: |
| 59 | self._thread.start() |
| 60 | |
| 61 | def stop(self) -> None: |
| 62 | self._stop_event.set() |
| 63 | self._thread.join() |
| 64 | with self._lock: |
| 65 | self._clear_locked() |
| 66 | self._restore_cursor_locked() |
| 67 | self._safe_restore() |
| 68 | |
| 69 | def begin_iteration(self, iteration: int) -> None: |
| 70 | with self._lock: |
| 71 | self._iteration = iteration |
| 72 | self._iter_start = time.monotonic() |
| 73 | self._test = "(initializing)" |
| 74 | self._render_locked() |
| 75 | |
| 76 | def update_test(self, name: str) -> None: |
| 77 | with self._lock: |
| 78 | self._test = name |
| 79 | |
| 80 | def record_result(self, passed: bool) -> None: |
| 81 | with self._lock: |
| 82 | if passed: |
| 83 | self._passed += 1 |
| 84 | else: |
| 85 | self._failed += 1 |
| 86 | |
| 87 | def iter_elapsed(self) -> timedelta: |
| 88 | with self._lock: |
| 89 | return timedelta(seconds=int(time.monotonic() - self._iter_start)) |
| 90 | |
| 91 | @contextmanager |
| 92 | def pause(self): |
| 93 | """Clear the status line and hold the refresh lock while the caller prints.""" |
| 94 | with self._lock: |
| 95 | self._clear_locked() |
| 96 | self._restore_cursor_locked() |
| 97 | yield |
| 98 | # Do not re-render here; the next 1-second tick will redraw below |
| 99 | # whatever the caller wrote to stdout. |
| 100 | |
| 101 | def _loop(self) -> None: |
| 102 | while not self._stop_event.is_set(): |
| 103 | with self._lock: |
| 104 | self._render_locked() |
| 105 | self._stop_event.wait(1.0) |
| 106 | |
| 107 | def _render_locked(self) -> None: |
| 108 | if not self._enabled: |
| 109 | return |
| 110 | elapsed = timedelta(seconds=int(time.monotonic() - self._iter_start)) |
| 111 | stats_parts: list[str] = [] |
| 112 | if self._passed: |
| 113 | stats_parts.append(click.style(f"{self._passed} passed", fg="green")) |
| 114 | if self._failed: |
| 115 | stats_parts.append(click.style(f"{self._failed} failed", fg="red")) |
| 116 | stats = (" [" + ", ".join(stats_parts) + "]") if stats_parts else "" |
| 117 | line = ( |
| 118 | f"Iteration {self._iteration}/{self._total}: " |
| 119 | f"{self._test}, runtime: {elapsed}{stats}" |
| 120 | ) |
| 121 | prefix = _RESET_LINE |
| 122 | if not self._cursor_hidden: |
| 123 | prefix = _HIDE_CURSOR + prefix |
| 124 | self._cursor_hidden = True |
| 125 | sys.stdout.write(prefix + line) |
| 126 | sys.stdout.flush() |
| 127 | |
| 128 | def _clear_locked(self) -> None: |
| 129 | if not self._enabled: |
| 130 | return |
| 131 | sys.stdout.write(_RESET_LINE) |
| 132 | sys.stdout.flush() |
| 133 | |
| 134 | def _restore_cursor_locked(self) -> None: |
| 135 | if self._cursor_hidden: |
| 136 | sys.stdout.write(_SHOW_CURSOR) |
| 137 | sys.stdout.flush() |
| 138 | self._cursor_hidden = False |
| 139 | |
| 140 | def _safe_restore(self) -> None: |
| 141 | if not self._enabled: |
| 142 | return |
| 143 | sys.stdout.write(_SHOW_CURSOR + _SGR_RESET) |
| 144 | sys.stdout.flush() |
| 145 | |
| 146 | |
| 147 | def _run_wpr(args: list[str]) -> None: |
| 148 | """Invoke wpr; raises subprocess.CalledProcessError on non-zero exit.""" |
| 149 | |
| 150 | si = subprocess.STARTUPINFO() |
| 151 | si.dwFlags |= subprocess.STARTF_USESHOWWINDOW |
| 152 | si.wShowWindow = subprocess.SW_HIDE # 0 |
| 153 | |
| 154 | subprocess.run( |
| 155 | ["wpr", *args], |
| 156 | creationflags=subprocess.CREATE_NEW_CONSOLE, |
| 157 | startupinfo=si, |
| 158 | check=True, |
| 159 | ) |
| 160 | |
| 161 | |
| 162 | def _timestamp_prefix() -> str: |
| 163 | """Return `[HH:MM:SS.mmm] ` for the current wall-clock time.""" |
| 164 | now = datetime.now() |
| 165 | return f"[{now.strftime('%H:%M:%S')}.{now.microsecond // 1000:03d}] " |
| 166 | |
| 167 | |
| 168 | def _print_failed_tests(failed_tests: list[tuple[str, str, list[str]]]) -> None: |
| 169 | """Print the captured output of every failed test in red.""" |
| 170 | for name, verdict, lines in failed_tests: |
| 171 | click.secho( |
| 172 | f"\n----- Failed test: {name} [{verdict}] -----", |
| 173 | fg="red", |
| 174 | bold=True, |
| 175 | ) |
| 176 | click.secho("".join(lines).rstrip("\n"), fg="red") |
| 177 | click.secho(f"----- end of {name} -----\n", fg="red", bold=True) |
| 178 | |
| 179 | |
| 180 | def _print_output_tail(output_file: Path, max_lines: int = 80) -> None: |
| 181 | """Fallback: dump the tail of the captured log when no test-level failure was parsed.""" |
| 182 | try: |
| 183 | lines = output_file.read_text(encoding="utf-8", errors="replace").splitlines() |
| 184 | except OSError as ex: |
| 185 | click.secho(f"Could not read {output_file}: {ex}", fg="red") |
| 186 | return |
| 187 | |
| 188 | tail = lines[-max_lines:] |
| 189 | click.secho( |
| 190 | f"\n----- Last {len(tail)} line(s) of {output_file.name} -----", |
| 191 | fg="red", |
| 192 | bold=True, |
| 193 | ) |
| 194 | click.secho("\n".join(tail), fg="red") |
| 195 | click.secho(f"----- end of {output_file.name} -----\n", fg="red", bold=True) |
| 196 | |
| 197 | |
| 198 | def _run_iteration( |
| 199 | iteration: int, |
| 200 | test_bat: Path, |
| 201 | test_args: tuple[str, ...], |
| 202 | iter_dir: Path, |
| 203 | wprp: Path | None, |
| 204 | status: StatusLine, |
| 205 | ) -> bool: |
| 206 | """Run one iteration. Returns True on success.""" |
| 207 | iter_dir.mkdir(parents=True, exist_ok=True) |
| 208 | output_file = iter_dir / "test-output.log" |
| 209 | etl_file = iter_dir / "trace.etl" |
| 210 | |
| 211 | status.begin_iteration(iteration) |
| 212 | |
| 213 | # Start ETL trace before launching tests. |
| 214 | etl_started = False |
| 215 | if wprp is not None: |
| 216 | _run_wpr(["-start", str(wprp), "-filemode"]) |
| 217 | etl_started = True |
| 218 | |
| 219 | cmd = [str(test_bat), *test_args] |
| 220 | return_code = 1 |
| 221 | current_test: str | None = None |
| 222 | current_buffer: list[str] = [] |
| 223 | failed_tests: list[tuple[str, str, list[str]]] = [] |
| 224 | try: |
| 225 | with output_file.open("w", encoding="utf-8", errors="replace") as out: |
| 226 | out.write(f"{_timestamp_prefix()}$ {subprocess.list2cmdline(cmd)}\n\n") |
| 227 | out.flush() |
| 228 | proc = subprocess.Popen( |
| 229 | cmd, |
| 230 | stdout=subprocess.PIPE, |
| 231 | stderr=subprocess.STDOUT, |
| 232 | text=True, |
| 233 | encoding="utf-8", |
| 234 | errors="replace", |
| 235 | bufsize=1, |
| 236 | cwd=str(REPO_ROOT), |
| 237 | ) |
| 238 | assert proc.stdout is not None |
| 239 | for line in proc.stdout: |
| 240 | # Strip embedded NULs (UTF-16 remnants, etc.) so the log stays valid text. |
| 241 | line = line.replace("\x00", "") |
| 242 | stamped = _timestamp_prefix() + line |
| 243 | out.write(stamped) |
| 244 | out.flush() |
| 245 | |
| 246 | start = START_GROUP_RE.search(stamped) |
| 247 | if start: |
| 248 | current_test = start.group(1) |
| 249 | current_buffer = [stamped] |
| 250 | status.update_test(current_test) |
| 251 | continue |
| 252 | |
| 253 | if current_test is not None: |
| 254 | current_buffer.append(stamped) |
| 255 | |
| 256 | end = END_GROUP_RE.search(stamped) |
| 257 | if end: |
| 258 | name = end.group(1) |
| 259 | verdict = end.group("verdict") |
| 260 | if verdict.lower() not in PASS_VERDICTS: |
| 261 | failed_tests.append((name, verdict, current_buffer)) |
| 262 | current_test = None |
| 263 | current_buffer = [] |
| 264 | return_code = proc.wait() |
| 265 | finally: |
| 266 | if etl_started: |
| 267 | _run_wpr(["-stop", str(etl_file)]) |
| 268 | |
| 269 | success = return_code == 0 and not failed_tests |
| 270 | status.record_result(success) |
| 271 | |
| 272 | if not success: |
| 273 | elapsed = status.iter_elapsed() |
| 274 | detail = f"exit {return_code}" |
| 275 | if failed_tests: |
| 276 | detail += f", {len(failed_tests)} failed test(s)" |
| 277 | verdict_str = click.style(f"FAILED ({detail})", fg="red", bold=True) |
| 278 | with status.pause(): |
| 279 | click.echo( |
| 280 | f"Iteration {iteration}: {verdict_str} in {elapsed} - logs at {iter_dir}" |
| 281 | ) |
| 282 | if failed_tests: |
| 283 | _print_failed_tests(failed_tests) |
| 284 | else: |
| 285 | _print_output_tail(output_file) |
| 286 | |
| 287 | return success |
| 288 | |
| 289 | |
| 290 | def _cancel_active_trace() -> None: |
| 291 | """Best-effort cancel of any leftover wpr session (e.g. from a crashed iteration).""" |
| 292 | subprocess.run( |
| 293 | ["wpr", "-cancel"], |
| 294 | stdout=subprocess.DEVNULL, |
| 295 | stderr=subprocess.DEVNULL, |
| 296 | ) |
| 297 | |
| 298 | |
| 299 | @click.command( |
| 300 | context_settings={"ignore_unknown_options": True, "allow_extra_args": True}, |
| 301 | help=( |
| 302 | "Run test.bat in a loop, capturing per-iteration output and an ETL trace. " |
| 303 | "Any TEST_ARGS are forwarded verbatim to test.bat." |
| 304 | ), |
| 305 | ) |
| 306 | @click.argument("iterations", type=click.IntRange(min=1)) |
| 307 | @click.argument("test_args", nargs=-1, type=click.UNPROCESSED) |
| 308 | @click.option( |
| 309 | "--output-dir", |
| 310 | "-o", |
| 311 | default="test-loop", |
| 312 | type=click.Path(file_okay=False), |
| 313 | show_default=True, |
| 314 | help="Parent directory; a timestamped subfolder is created for each run.", |
| 315 | ) |
| 316 | @click.option( |
| 317 | "--wprp", |
| 318 | default=str(DEFAULT_WPRP), |
| 319 | type=click.Path(dir_okay=False), |
| 320 | show_default=True, |
| 321 | help="ETL profile passed to `wpr -start` (passed verbatim; wpr validates it).", |
| 322 | ) |
| 323 | @click.option( |
| 324 | "--no-etl", |
| 325 | is_flag=True, |
| 326 | default=False, |
| 327 | help="Skip ETL tracing (useful when wpr is not available or not needed).", |
| 328 | ) |
| 329 | @click.option( |
| 330 | "--platform", |
| 331 | "platform_", |
| 332 | type=click.Choice(["x64", "arm64"], case_sensitive=False), |
| 333 | default="x64", |
| 334 | show_default=True, |
| 335 | help="Target platform subfolder under bin/ where test.bat lives.", |
| 336 | ) |
| 337 | @click.option( |
| 338 | "--target", |
| 339 | type=click.Choice(["Debug", "Release"], case_sensitive=False), |
| 340 | default="Debug", |
| 341 | show_default=True, |
| 342 | help="Build configuration subfolder under bin/<platform>/ where test.bat lives.", |
| 343 | ) |
| 344 | @click.option( |
| 345 | "--stop-on-failure/--continue-on-failure", |
| 346 | default=True, |
| 347 | show_default=True, |
| 348 | help="Stop the loop on the first failing iteration.", |
| 349 | ) |
| 350 | @click.option( |
| 351 | "--keep-success-logs", |
| 352 | is_flag=True, |
| 353 | default=False, |
| 354 | help="Keep per-iteration log folders even for successful iterations (by default they are deleted).", |
| 355 | ) |
| 356 | def main( |
| 357 | iterations: int, |
| 358 | test_args: tuple[str, ...], |
| 359 | output_dir: str, |
| 360 | wprp: str, |
| 361 | no_etl: bool, |
| 362 | platform_: str, |
| 363 | target: str, |
| 364 | stop_on_failure: bool, |
| 365 | keep_success_logs: bool, |
| 366 | ) -> None: |
| 367 | platform_ = platform_.lower() |
| 368 | target = target.capitalize() |
| 369 | test_bat_path = REPO_ROOT / "bin" / platform_ / target / "test.bat" |
| 370 | |
| 371 | if not test_bat_path.is_file(): |
| 372 | raise click.ClickException(f"test.bat not found at: {test_bat_path}") |
| 373 | |
| 374 | wprp_path: Path | None = None |
| 375 | if not no_etl: |
| 376 | wprp_path = Path(wprp).resolve() |
| 377 | |
| 378 | base_dir = Path(output_dir).resolve() |
| 379 | run_dir = base_dir / datetime.now().strftime("%Y-%m-%d_%H-%M-%S") |
| 380 | run_dir.mkdir(parents=True, exist_ok=True) |
| 381 | |
| 382 | digits = len(str(iterations)) |
| 383 | failed = 0 |
| 384 | print(f"Running {iterations} iteration(s) of: {subprocess.list2cmdline([str(test_bat_path), *test_args])}") |
| 385 | print(f"Output: {run_dir}") |
| 386 | if wprp_path is not None: |
| 387 | print(f"ETL profile: {wprp_path}") |
| 388 | else: |
| 389 | print("ETL tracing: disabled") |
| 390 | print() |
| 391 | |
| 392 | status = StatusLine(iterations) |
| 393 | status.start() |
| 394 | try: |
| 395 | for i in range(1, iterations + 1): |
| 396 | iter_dir = run_dir / f"iter-{i:0{digits}d}" |
| 397 | try: |
| 398 | ok = _run_iteration(i, test_bat_path, test_args, iter_dir, wprp_path, status) |
| 399 | except KeyboardInterrupt: |
| 400 | with status.pause(): |
| 401 | print("\nInterrupted by user.") |
| 402 | raise |
| 403 | |
| 404 | if ok and not keep_success_logs: |
| 405 | shutil.rmtree(iter_dir, ignore_errors=True) |
| 406 | |
| 407 | if not ok: |
| 408 | failed += 1 |
| 409 | if stop_on_failure: |
| 410 | with status.pause(): |
| 411 | print(f"Stopping after first failure (iteration {i}).") |
| 412 | break |
| 413 | finally: |
| 414 | status.stop() |
| 415 | # Make sure no ETL trace is left running from a crashed iteration. |
| 416 | if wprp_path is not None: |
| 417 | _cancel_active_trace() |
| 418 | |
| 419 | print() |
| 420 | if failed: |
| 421 | click.secho( |
| 422 | f"Done: {failed} iteration(s) failed.", fg="red", bold=True |
| 423 | ) |
| 424 | sys.exit(1) |
| 425 | click.secho("Done: all iterations passed.", fg="green", bold=True) |
| 426 | |
| 427 | |
| 428 | if __name__ == "__main__": |
| 429 | main() |