@samitouri / QOSAMI-WSL-2 / commits / 84c1baa2

Create a script to run the tests in a loop and capture logs + output on failure (#40665)

* Create a script to run the tests in a loop and capture logs + output on failure * Apply PR feedback

Blue committed May 29, 2026 at 12:10 UTC 84c1baa20bd50302cfdc3d413c62491b81c27f44
2 files changed +430
.gitignore
+1
@@ -72,3 +72,4 @@ test-storage/
72 *.tar
73 *.etl
74 *.lscache
75 +__pycache__
\ No newline at end of file
tools/test/loop-tests.py new
+429
@@ -0,0 +1,429 @@
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()