From 6500aeb8e1fa4fe3a6cb331fbb2d56a6b6cfd68c Mon Sep 17 00:00:00 2001 From: bneradt Date: Wed, 12 Aug 2026 17:13:00 -0500 Subject: [PATCH] AuTest timing improvements Parallel AuTest runs were repeating similarly named tests, while timing collection reset shared port allocation by starting a process per test. Several tests also waited on client defaults, retries, and log buffering rather than behavior under verification. Exact test selection -------------------- The runner now anchors worker filters to test paths. This avoids suffix collisions, duplicate runs, and parallel execution of serial tests. Batch timing collection ----------------------- The runner now measures completions from persistent worker batches. This preserves shared port allocation and removes per-test process startup. Rate-limit expiration --------------------- The rate-limit test bounds the queued client wait and requires the ATS expiration diagnostic, retaining queue-expiration coverage. Server-abort timeouts --------------------- The server-abort test disables retries and shortens connection and inactivity timeouts that are unrelated to the expected abort. JAX fingerprint log flushing ---------------------------- The JAX fingerprint test flushes log buffers once per second so its existing log assertions do not wait on production buffering defaults. Stale-response log flushing --------------------------- The stale-response test similarly flushes logs once per second while retaining its existing traffic and log assertions. --- tests/README.md | 2 +- tests/autest-parallel.py.in | 310 ++++++++++-------- .../jax_fingerprint/jax_fingerprint.test.py | 2 + .../rate_limit/rate_limit_sni.test.py | 4 +- .../stale_response/stale_response.test.py | 1 + .../gold_tests/slow_post/server_abort.test.py | 4 + 6 files changed, 181 insertions(+), 142 deletions(-) diff --git a/tests/README.md b/tests/README.md index cbeda199083..e718d676d73 100644 --- a/tests/README.md +++ b/tests/README.md @@ -55,7 +55,7 @@ Key options: * `--build-root` - Path to the build directory (for test plugins) * `--sandbox` - Directory for test sandboxes (default: `/tmp/autest-parallel`) * `-v` - Verbose output with real-time test progress per worker -* `--collect-timings` - Run tests individually to collect per-test timing data +* `--collect-timings` - Collect per-test timing data from each worker batch * `--list` - List all tests and exit (useful for checking test discovery) The parallel runner uses port offsets to ensure each worker gets a unique port diff --git a/tests/autest-parallel.py.in b/tests/autest-parallel.py.in index 1f7f1eedea4..d73fdad8253 100755 --- a/tests/autest-parallel.py.in +++ b/tests/autest-parallel.py.in @@ -227,6 +227,37 @@ def strip_ansi(text: str) -> str: return ansi_escape.sub('', text) +def parse_test_completion(line: str) -> Optional[Tuple[str, str]]: + """Extract a completed test name and status from an autest progress line.""" + clean = strip_ansi(line).strip() + marker = 'Running Test ' + marker_pos = clean.rfind(marker) + + if marker_pos < 0: + return None + + completion = clean[marker_pos + len(marker):] + match = re.match(r'([^:\s]+):.*\b(Passed|Failed|Skipped)\s*$', completion, re.IGNORECASE) + if not match: + return None + + return match.group(1), match.group(2).upper() + + +def parse_test_start(line: str) -> Optional[str]: + """Extract the test name from an autest progress line.""" + clean = strip_ansi(line) + matches = re.findall(r'Running Test ([^:\s]+):', clean) + return matches[-1] if matches else None + + +def parse_detached_test_status(line: str) -> Optional[str]: + """Extract a status that autest printed separately from its test name.""" + clean = strip_ansi(line).strip() + match = re.fullmatch(r'[.FWE]*\s*(Passed|Failed|Skipped)', clean, re.IGNORECASE) + return match.group(1).upper() if match else None + + def parse_autest_output(output: str) -> dict: """ Parse autest output to extract pass/fail counts and per-test timings. @@ -433,7 +464,7 @@ def run_single_test(test: str, script_dir: Path, sandbox: Path, ats_bin: str, bu cmd = [ 'uv', 'run', 'autest', 'run', '--directory', '${CMAKE_GOLD_DIR}', '--ats-bin', ats_bin, '--proxy-verifier-bin', '${PROXY_VERIFIER_PATH}', '--build-root', build_root, '--sandbox', - str(sandbox / test), '--filters', test + str(sandbox / test), '--filters', f'/{test}' ] cmd.extend(extra_args) @@ -492,7 +523,7 @@ def run_worker( extra_args: Additional arguments to pass to autest port_offset_step: Port offset between workers verbose: Whether to print verbose output - collect_timings: If True, run tests one at a time to collect accurate timing + collect_timings: If True, time test completions within the worker batch Returns: TestResult with pass/fail counts and per-test timings @@ -517,151 +548,150 @@ def run_worker( existing = env.get('PYTHONPATH', '') env['PYTHONPATH'] = ':'.join(pythonpath_dirs + ([existing] if existing else [])) - if collect_timings: - # Run tests one at a time to collect accurate timing - all_output = [] - total_tests = len(tests) - try: - for idx, test in enumerate(tests, 1): - test_name, duration, status, output = run_single_test( - test, script_dir, sandbox, ats_bin, build_root, extra_args, env) - result.test_timings[test_name] = duration - all_output.append(output) - - if status == "PASS": - result.passed += 1 - elif status == "SKIP": - result.skipped += 1 - else: - result.failed += 1 - result.failed_tests.append(test_name) + # Keep all tests in one autest process so its shared port queue is not + # reset between tests. This is both faster and avoids reusing ports that a + # recently completed test may still hold. + cmd = [ + 'uv', + 'run', + 'autest', + 'run', + '--directory', + '${CMAKE_GOLD_DIR}', + '--ats-bin', + ats_bin, + '--proxy-verifier-bin', + '${PROXY_VERIFIER_PATH}', + '--build-root', + build_root, + '--sandbox', + str(sandbox), + '--filters', + ] + cmd.extend(f'/{test}' for test in tests) + cmd.extend(extra_args) - timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S") - # Fixed-width format: date time status duration worker progress test_name - print( - f"{timestamp} {status:4s} {duration:6.1f}s Worker:{worker_id:2d} {idx:2d}/{total_tests:2d} {test}", flush=True) - except KeyboardInterrupt: - result.return_code = 130 + timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S") + print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True) + if verbose: + print( + f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}" + f"{'...' if len(tests) > 5 else ''}", + flush=True) - result.output = "\n".join(all_output) - if result.return_code != 130: - result.return_code = 0 if result.failed == 0 else 1 - else: - # Run all tests in batch (faster but no per-test timing) - cmd = [ - 'uv', - 'run', - 'autest', - 'run', - '--directory', - '${CMAKE_GOLD_DIR}', - '--ats-bin', - ats_bin, - '--proxy-verifier-bin', - '${PROXY_VERIFIER_PATH}', - '--build-root', - build_root, - '--sandbox', - str(sandbox), - ] - - # Add test filters - cmd.append('--filters') - cmd.extend(tests) - - # Add any extra arguments - cmd.extend(extra_args) - - timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S") - print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True) - if verbose: - print( - f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}" - f"{'...' if len(tests) > 5 else ''}", - flush=True) + try: + if verbose or collect_timings: + # Autest flushes each completed test line. Observe those lines to + # collect timings without changing how autest executes the batch. + proc = subprocess.Popen( + cmd, + cwd=script_dir, + stdout=subprocess.PIPE, + stderr=subprocess.STDOUT, + text=True, + env=env, + ) + output_lines = [] + last_completion = time.monotonic() + completed_count = 0 + pending_test = None + try: + for line in proc.stdout: + output_lines.append(line) + started_test = parse_test_start(line) + if started_test is not None: + pending_test = started_test + completion = parse_test_completion(line) + if completion is None and pending_test is not None: + status = parse_detached_test_status(line) + if status is not None: + completion = pending_test, status + if completion is None: + continue + + test_name, status = completion + pending_test = None + now = time.monotonic() + duration = now - last_completion + last_completion = now + completed_count += 1 + result.test_timings[test_name] = duration + + ts = datetime.now().strftime("%H:%M:%S") + if collect_timings: + short_status = {'PASSED': 'PASS', 'FAILED': 'FAIL', 'SKIPPED': 'SKIP'}[status] + print( + f" [{ts}] {short_status:4s} {duration:6.1f}s Worker:{worker_id:2d} " + f"{completed_count:2d}/{len(tests):2d} {test_name}", + flush=True) + elif verbose: + print(f" [{ts}] Worker:{worker_id:2d} {strip_ansi(line).strip()}", flush=True) - try: - if verbose: - # Stream output in real-time so the user sees test progress. - # We use Popen + line-by-line read so partial results are visible - # even if the overall run takes a long time. - proc = subprocess.Popen( - cmd, - cwd=script_dir, - stdout=subprocess.PIPE, - stderr=subprocess.STDOUT, - text=True, - env=env, - ) - output_lines = [] try: - for line in proc.stdout: - output_lines.append(line) - # Print lines that show test progress - clean = strip_ansi(line).strip() - if clean.startswith('Running Test') or 'Passed' in clean or 'Failed' in clean: - if clean.startswith('Running Test'): - ts = datetime.now().strftime("%H:%M:%S") - print(f" [{ts}] Worker:{worker_id:2d} {clean}", flush=True) - # stdout is exhausted, wait for process to finish + proc.wait(timeout=60) + except subprocess.TimeoutExpired: + proc.kill() + proc.wait() + finally: + if proc.poll() is None: + proc.terminate() try: - proc.wait(timeout=60) + proc.wait(timeout=5) except subprocess.TimeoutExpired: proc.kill() proc.wait() - finally: - # Ensure the subprocess is always cleaned up. - if proc.poll() is None: - proc.terminate() - try: - proc.wait(timeout=5) - except subprocess.TimeoutExpired: - proc.kill() - proc.wait() - result.output = ''.join(output_lines) - result.return_code = proc.returncode - else: - proc = subprocess.run( - cmd, - cwd=script_dir, - capture_output=True, - text=True, - env=env, - timeout=3600 # 1 hour timeout per worker - ) - result.output = proc.stdout + proc.stderr - result.return_code = proc.returncode - - # Parse results - parsed = parse_autest_output(result.output) - result.passed = parsed['passed'] - result.failed = parsed['failed'] - result.skipped = parsed['skipped'] - result.warnings = parsed['warnings'] - result.exceptions = parsed['exceptions'] - result.unknown = parsed['unknown'] - result.failed_tests = parsed['failed_tests'] - - # If no tests ran at all (passed + failed + skipped == 0), - # autest likely errored at setup (e.g., missing proxy verifier). - # Count all tests as failed to avoid false positives. - total_ran = result.passed + result.failed + result.skipped - if total_ran == 0 and (hasattr(proc, 'returncode') and proc.returncode != 0): - result.failed = len(tests) - result.failed_tests = list(tests) - - except KeyboardInterrupt: - result.output = "INTERRUPTED by user" - result.return_code = 130 - result.failed = len(tests) - except subprocess.TimeoutExpired: - result.output = "TIMEOUT: Worker exceeded 1 hour timeout" - result.return_code = -1 - result.failed = len(tests) - except Exception as e: - result.output = f"ERROR: {str(e)}" - result.return_code = -1 + result.output = ''.join(output_lines) + result.return_code = proc.returncode + else: + proc = subprocess.run( + cmd, + cwd=script_dir, + capture_output=True, + text=True, + env=env, + timeout=3600 # 1 hour timeout per worker + ) + result.output = proc.stdout + proc.stderr + result.return_code = proc.returncode + + # Parse results + parsed = parse_autest_output(result.output) + result.passed = parsed['passed'] + result.failed = parsed['failed'] + result.skipped = parsed['skipped'] + result.warnings = parsed['warnings'] + result.exceptions = parsed['exceptions'] + result.unknown = parsed['unknown'] + result.failed_tests = parsed['failed_tests'] + + # If no tests ran at all (passed + failed + skipped == 0), + # autest likely errored at setup (e.g., missing proxy verifier). + # Count all tests as failed to avoid false positives. + total_ran = result.passed + result.failed + result.skipped + if total_ran == 0 and proc.returncode != 0: result.failed = len(tests) + result.failed_tests = list(tests) + + if collect_timings: + missing_timings = sorted(set(tests) - result.test_timings.keys()) + if missing_timings: + print( + f"Warning: Worker {worker_id} did not report timings for: {', '.join(missing_timings)}", + file=sys.stderr, + flush=True) + + except KeyboardInterrupt: + result.output = "INTERRUPTED by user" + result.return_code = 130 + result.failed = len(tests) + except subprocess.TimeoutExpired: + result.output = "TIMEOUT: Worker exceeded 1 hour timeout" + result.return_code = -1 + result.failed = len(tests) + except Exception as e: + result.output = f"ERROR: {str(e)}" + result.return_code = -1 + result.failed = len(tests) result.duration = time.time() - start_time return result @@ -831,7 +861,7 @@ Examples: parser.add_argument('-v', '--verbose', action='store_true', help='Verbose output') parser.add_argument('--test-dir', default='${CMAKE_GOLD_DIR}', help='Path to gold_tests directory (default: ${CMAKE_GOLD_DIR})') parser.add_argument( - '--collect-timings', action='store_true', help='Run tests one at a time to collect accurate per-test timing data') + '--collect-timings', action='store_true', help='Collect per-test timing data from each worker batch') parser.add_argument( '--timings-file', type=Path, default=None, help='Path to timing data JSON file (default: /test-timings.json)') parser.add_argument( @@ -941,7 +971,7 @@ Examples: print(f"Port offset step: {args.port_offset_step}") print(f"Sandbox: {args.sandbox}") if args.collect_timings: - print("Collecting per-test timing data (tests run sequentially per worker)") + print("Collecting per-test timing data from worker batches") print() # Create sandbox base directory diff --git a/tests/gold_tests/pluginTest/jax_fingerprint/jax_fingerprint.test.py b/tests/gold_tests/pluginTest/jax_fingerprint/jax_fingerprint.test.py index 906667f93b4..24c3b1673d8 100644 --- a/tests/gold_tests/pluginTest/jax_fingerprint/jax_fingerprint.test.py +++ b/tests/gold_tests/pluginTest/jax_fingerprint/jax_fingerprint.test.py @@ -226,6 +226,7 @@ def _configure_trafficserver(self) -> None: 'proxy.config.proxy_name': 'test.proxy.test', 'proxy.config.diags.debug.enabled': 1, 'proxy.config.diags.debug.tags': 'jax_fingerprint|http', + 'proxy.config.log.max_secs_per_buffer': 1, }) log_path = os.path.join(self._ts.Variables.LOGDIR, 'jax_fingerprint.log') @@ -452,6 +453,7 @@ def _configure_trafficserver(self) -> None: 'proxy.config.proxy_name': 'test.proxy.test', 'proxy.config.diags.debug.enabled': 1, 'proxy.config.diags.debug.tags': 'jax_fingerprint', + 'proxy.config.log.max_secs_per_buffer': 1, }) # Each of the following pairs makes sure that the expression exists diff --git a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni.test.py b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni.test.py index c531bd94507..d275490b09f 100644 --- a/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni.test.py +++ b/tests/gold_tests/pluginTest/rate_limit/rate_limit_sni.test.py @@ -109,7 +109,7 @@ tr.Processes.Default.Command = ( f"curl -sk -o /dev/null '{BASE_URL}/slow' {RESOLVE} & " f"sleep 0.5; " - f"curl -sk -o /dev/null '{BASE_URL}/queued' {RESOLVE} 2>/dev/null; " + f"curl -sk --max-time 2 -o /dev/null '{BASE_URL}/queued' {RESOLVE} 2>/dev/null; " f"wait; sleep 0.5; " f"curl -sk -o /dev/null -w '%{{http_code}}' '{BASE_URL}/test' {RESOLVE}") tr.Processes.Default.ReturnCode = 0 @@ -119,3 +119,5 @@ # Verify ATS didn't crash ts.Disk.diags_log.Content = Testers.ExcludesExpression("FATAL", "ATS should not crash from active counter underflow") ts.Disk.diags_log.Content += Testers.ExcludesExpression("ink_release_assert", "No assertion failure from _active underflow") +ts.Disk.traffic_out.Content += Testers.ContainsExpression( + "Queued VC is too old", "The queued connection should expire before the client disconnects") diff --git a/tests/gold_tests/pluginTest/stale_response/stale_response.test.py b/tests/gold_tests/pluginTest/stale_response/stale_response.test.py index 246b55daccd..8a2501693de 100644 --- a/tests/gold_tests/pluginTest/stale_response/stale_response.test.py +++ b/tests/gold_tests/pluginTest/stale_response/stale_response.test.py @@ -136,6 +136,7 @@ def setupTS(self) -> None: "proxy.config.http.negative_revalidating_enabled": 0, # Keep the active log filename available for the final content check if the test spans UTC midnight. "proxy.config.log.rolling_enabled": 0, + "proxy.config.log.max_secs_per_buffer": 1, }) ts.Disk.remap_config.AddLine(f"map / http://127.0.0.1:{self._server.Variables.http_port}/ {remap_plugin_config}") diff --git a/tests/gold_tests/slow_post/server_abort.test.py b/tests/gold_tests/slow_post/server_abort.test.py index 394e7b350e3..a8059888093 100644 --- a/tests/gold_tests/slow_post/server_abort.test.py +++ b/tests/gold_tests/slow_post/server_abort.test.py @@ -41,6 +41,10 @@ { 'proxy.config.diags.debug.tags': 'http|dns', 'proxy.config.diags.debug.enabled': 1, + 'proxy.config.http.connect_attempts_max_retries': 0, + 'proxy.config.http.connect_attempts_rr_retries': 0, + 'proxy.config.http.connect_attempts_timeout': 2, + 'proxy.config.http.transaction_no_activity_timeout_out': 2, 'proxy.config.ssl.server.cert.path': f'{Test.TestDirectory}/test_secrets', 'proxy.config.ssl.server.private_key.path': f'{Test.TestDirectory}/test_secrets', })