diff --git a/contrib/Joshua/README.md b/contrib/Joshua/README.md index f3d98892c67..41bcd3c2f46 100644 --- a/contrib/Joshua/README.md +++ b/contrib/Joshua/README.md @@ -21,3 +21,9 @@ We use Joshua to simulate failures modes at the network, machine, and datacenter For a while, there was an informal competition within the engineering team to design failures that found the toughest bugs and issues the most easily. After a period of one-upsmanship, the reigning champion is called "swizzle-clogging". To swizzle-clog, you first pick a random subset of nodes in the cluster. Then, you "clog" (stop) each of their network connections one by one over a few seconds. Finally, you unclog them in a random order, again one by one, until they are all up. This pattern seems to be particularly good at finding deep issues that only happen in the rarest real-world cases. Joshua's success has surpassed our expectation and has been vital to our engineering team. It seems unlikely that we would have been able to build FoundationDB without this technology. + +* `scripts/`: This directory contains shell scripts that serve as entry points for running tests. Joshua invokes these scripts, which then set up the environment and execute the test runner. + * **`correctnessTest.sh`**: This is the primary script for running correctness tests. It is responsible for invoking the Python-based `TestHarnessV2` and passing it the necessary configuration. It also handles the creation and cleanup of temporary output directories. + * Other scripts like `bindingTest.sh` and `valgrindTest.sh` are used for different, specialized test runs. + +For detailed information on the operation of the Python test runner itself, including its configuration options and output structure, please see the **[TestHarnessV2 README](../TestHarness2/README.md)**. diff --git a/contrib/Joshua/scripts/correctnessTest.sh b/contrib/Joshua/scripts/correctnessTest.sh index 4759d5e53ac..b33aee83071 100755 --- a/contrib/Joshua/scripts/correctnessTest.sh +++ b/contrib/Joshua/scripts/correctnessTest.sh @@ -1,10 +1,237 @@ -#!/bin/sh +#!/bin/bash + +# Entry point for running FoundationDB correctness tests +# using Python-based TestHarness2 (invoked as `python3 -m test_harness.app`). +# It is designed to be called by the Joshua testing framework. +# For detailed documentation on TestHarness2 features, including log archival, +# see contrib/TestHarness2/README.md. +# +# Key Responsibilities: +# 1. Sets up unique temporary directories for test outputs (`APP_JOSHUA_OUTPUT_DIR`) +# and runtime artifacts (`APP_RUN_TEMP_DIR`) based on JOSHUA_SEED or a timestamp. +# 2. Gathers necessary environment variables and parameters (e.g., JOSHUA_SEED, +# OLDBINDIR, JOSHUA_TEST_FILES_DIR) and translates them into command-line +# arguments for the Python test harness application (`app.py`). +# 3. Executes the Python test harness application, capturing its stdout (expected to be +# a single XML summary line for Joshua) and stderr. +# 4. Forwards relevant environment variables like `FDB_NETWORK_OPTION_EXTERNAL_CLIENT_DIRECTORY` +# and `TH_JOB_ID` to the Python application. +# 5. Provides default values for some TestHarness2 arguments if not explicitly passed. +# 6. Conditionally preserves or cleans up the top-level temporary directories +# (`APP_JOSHUA_OUTPUT_DIR` and `APP_RUN_TEMP_DIR`) based on the Python +# application's exit code and the `TH_ARCHIVE_LOGS_ON_FAILURE` environment +# variable. If `TH_ARCHIVE_LOGS_ON_FAILURE` is set to a true-like value +# (e.g., '1', 'true', 'yes'), these directories are NOT deleted if the Python +# application exits with a non-zero status, thus preserving all generated +# artifacts for debugging (copy them local quick using 'kubectl cp podname:/tmp .' +# before the pod goes away). The Python harness +# also internally uses this variable to control its own more specific log archival behavior. +# 7. Exits with the same exit code as the Python test harness application. + +# ============================================================================= +# Cleanup logic +# ============================================================================= +# The cleanup function is defined first so it is available to the 'trap' command. +cleanup() { + # Unconditionally stop background FDB monitor + # Clean up temporary directories unless debugging preservation is requested. + + echo "--- correctnessTest.sh cleanup routine starting ---" >&2 + echo "PYTHON_EXIT_CODE: '${PYTHON_EXIT_CODE}'" >&2 + echo "TH_ARCHIVE_LOGS_ON_FAILURE: '${TH_ARCHIVE_LOGS_ON_FAILURE}'" >&2 + echo "TH_PRESERVE_TEMP_DIRS_ON_EXIT: '${TH_PRESERVE_TEMP_DIRS_ON_EXIT}'" >&2 + + local archive_on_failure=false + if [ "${TH_ARCHIVE_LOGS_ON_FAILURE}" = "true" ]; then + archive_on_failure=true + fi + + if [ "${TH_PRESERVE_TEMP_DIRS_ON_EXIT}" = "true" ] || ( [ "${PYTHON_EXIT_CODE}" -ne "0" ] && [ "${archive_on_failure}" = "true" ] ); then + echo "Cleanup: Condition to PRESERVE files was met." >&2 + if [ "${PYTHON_EXIT_CODE}" -ne "0" ] && [ "${archive_on_failure}" = "true" ]; then + echo "Python app exited with error (code ${PYTHON_EXIT_CODE}). ARCHIVE ON: NOT cleaning up unified output directory for inspection." >&2 + echo " All run artifacts retained in: ${TOP_LEVEL_OUTPUT_DIR}" >&2 + else + echo "TH_PRESERVE_TEMP_DIRS_ON_EXIT is true. NOT cleaning up unified output directory." >&2 + echo " All run artifacts retained in: ${TOP_LEVEL_OUTPUT_DIR}" >&2 + fi + else + echo "Cleanup: Condition to PRESERVE files was NOT met. Deleting directory: ${TOP_LEVEL_OUTPUT_DIR}" >&2 + rm -rf "${TOP_LEVEL_OUTPUT_DIR}" + fi +} + +# ============================================================================= +# Script Main Body +# ============================================================================= + +# Set a trap to run the cleanup function upon script exit. +trap cleanup EXIT + +# Check if DIAG_LOG_DIR is set and non-empty, otherwise default to /tmp +if [ -z "${DIAG_LOG_DIR}" ]; then + DIAG_LOG_DIR="/tmp" +fi + +# New: Define a single top-level directory for all TestHarnessV2 outputs for this run. +# This directory's location can be controlled by the TH_OUTPUT_DIR env var. +TH_OUTPUT_BASE_DIR="${TH_OUTPUT_DIR:-${DIAG_LOG_DIR}}" +UNIQUE_RUN_SUFFIX="${JOSHUA_SEED:-$(date +%s%N)}" +TOP_LEVEL_OUTPUT_DIR="${TH_OUTPUT_BASE_DIR}/th_run_${UNIQUE_RUN_SUFFIX}" + +# 1. Sets up unique temporary directories for test outputs (`APP_JOSHUA_OUTPUT_DIR`) +# and the FDB cluster files (`APP_RUN_TEMP_DIR`). +# These are now subdirectories of the new TOP_LEVEL_OUTPUT_DIR. +APP_JOSHUA_OUTPUT_DIR="${TOP_LEVEL_OUTPUT_DIR}/joshua_output" +APP_RUN_TEMP_DIR="${TOP_LEVEL_OUTPUT_DIR}/run_files" + +# We no longer use `set -e` because we want to guarantee that the +# script runs to completion to cat the output files before cleanup. +# trap 'echo "FATAL: error in correctnessTest.sh" >&2; cleanup' ERR + +# Ensure directories exist +mkdir -p "${APP_JOSHUA_OUTPUT_DIR}" +mkdir -p "${APP_RUN_TEMP_DIR}" + +# Check that directories were created successfully. +if [ ! -d "${APP_JOSHUA_OUTPUT_DIR}" ]; then + echo "FATAL: Failed to create APP_JOSHUA_OUTPUT_DIR (path: ${APP_JOSHUA_OUTPUT_DIR})" >&2 + exit 1 +fi +if [ ! -d "${APP_RUN_TEMP_DIR}" ]; then + echo "FATAL: Failed to create APP_RUN_TEMP_DIR (path: ${APP_RUN_TEMP_DIR})" >&2 + exit 1 +fi + +# Make sure the python application can write to them +chmod 777 "${TOP_LEVEL_OUTPUT_DIR}" +chmod 777 "${APP_JOSHUA_OUTPUT_DIR}" +chmod 777 "${APP_RUN_TEMP_DIR}" + +echo "Created unified output directory: ${TOP_LEVEL_OUTPUT_DIR}" >&2 + +# --- Diagnostic Logging for this script --- +DIAG_LOG_FILE="${DIAG_LOG_DIR}/correctness_test_sh_diag.${UNIQUE_RUN_SUFFIX}.log" + +# Redirect all of this script's stderr to the diagnostic log file +# AND ensure the tee'd output also goes to stderr, not stdout. +exec 2> >(tee -a "${DIAG_LOG_FILE}" 1>&2) + +# Now that stderr is redirected, log the definitive messages +echo "--- correctnessTest.sh execution started at $(date) --- " >&2 +echo "Using UNIQUE_RUN_SUFFIX: ${UNIQUE_RUN_SUFFIX}" >&2 +echo "Diagnostic log for this script: ${DIAG_LOG_FILE}" >&2 +echo "Script PID: $$" >&2 +echo "Running as user: $(whoami)" >&2 +echo "Bash version: $BASH_VERSION" >&2 +echo "Initial PWD: $(pwd)" >&2 +echo "Initial environment variables relevant to TestHarness:" >&2 +echo " JOSHUA_SEED: ${JOSHUA_SEED}" >&2 +echo " OLDBINDIR: ${OLDBINDIR}" >&2 +echo " JOSHUA_TEST_FILES_DIR: ${JOSHUA_TEST_FILES_DIR}" >&2 +echo " FDB_NETWORK_OPTION_EXTERNAL_CLIENT_DIRECTORY: ${FDB_NETWORK_OPTION_EXTERNAL_CLIENT_DIRECTORY}" >&2 +echo " TH_ARCHIVE_LOGS_ON_FAILURE: ${TH_ARCHIVE_LOGS_ON_FAILURE}" >&2 +echo "-----------------------------------------------------" >&2 # Simulation currently has memory leaks. We need to investigate before we can enable leak detection in joshua. -export ASAN_OPTIONS="detect_leaks=0" +export ASAN_OPTIONS="${ASAN_OPTIONS:-detect_leaks=0}" +echo "ASAN_OPTIONS set to: ${ASAN_OPTIONS}" >&2 + +# --- Prepare arguments for the Python application --- +# Default values are mostly handled by the Python app's config.py, +# but we provide what Joshua gives us. + +# JOSHUA_SEED is mandatory for the python app +if [ -z "${JOSHUA_SEED}" ]; then + echo "FATAL: JOSHUA_SEED environment variable is not set." >&2 + # Output a TestHarnessV1-style error XML to stdout for Joshua + echo '' + exit 1 +fi + +# OLDBINDIR: Default if not set by Joshua +# The Python app's config.py has its own default, but we prefer Joshua's if available. +APP_OLDBINDIR="${OLDBINDIR:-/app/deploy/global_data/oldBinaries}" # Default from original script if not set by env +echo "Using OLDBINDIR for Python app: ${APP_OLDBINDIR}" >&2 + +# JOSHUA_TEST_FILES_DIR: This is the directory containing test definitions (.toml files). +# The python app calls this --test-dir. If not set, Python app will use its default. +APP_TEST_DIR="${JOSHUA_TEST_FILES_DIR}" +if [ -z "${APP_TEST_DIR}" ]; then + echo "WARNING: JOSHUA_TEST_FILES_DIR environment variable is not set. Python app will use its default test_source_dir (typically 'tests/' relative to CWD)." >&2 + # We allow this to proceed, Python app will handle default or fail if no tests found there. +else + echo "Using JOSHUA_TEST_FILES_DIR for Python app (--test-source-dir): ${APP_TEST_DIR}" >&2 +fi + +# Job ID from Joshua, if provided. +APP_JOB_ID="${TH_JOB_ID-}" + +PYTHON_EXE="${PYTHON_EXE:-python3}" # Allow overriding the python executable + +# Construct Python command arguments +PYTHON_CMD_ARGS=() +PYTHON_CMD_ARGS+=("--joshua-seed" "${JOSHUA_SEED}") +PYTHON_CMD_ARGS+=("--joshua-output-dir" "${APP_JOSHUA_OUTPUT_DIR}") +PYTHON_CMD_ARGS+=("--run-temp-dir" "${APP_RUN_TEMP_DIR}") + +# Only pass --test-source-dir if APP_TEST_DIR (from JOSHUA_TEST_FILES_DIR) is set. +if [ -n "${APP_TEST_DIR}" ]; then + PYTHON_CMD_ARGS+=("--test-source-dir" "${APP_TEST_DIR}") +fi + +if [ -n "${APP_OLDBINDIR}" ]; then + PYTHON_CMD_ARGS+=("--old-binaries-path" "${APP_OLDBINDIR}") +fi + +# Forward FDB_NETWORK_OPTION_EXTERNAL_CLIENT_DIRECTORY if set +if [ -n "${FDB_NETWORK_OPTION_EXTERNAL_CLIENT_DIRECTORY}" ]; then + PYTHON_CMD_ARGS+=("--external-client-library" "${FDB_NETWORK_OPTION_EXTERNAL_CLIENT_DIRECTORY}") +fi + +# Forward TH_ARCHIVE_LOGS_ON_FAILURE if set (Python app reads this from env if not on CLI) +# No need to explicitly pass as CLI if app.py handles TH_ARCHIVE_LOGS_ON_FAILURE env var. +# If you wanted to override env with a script default, you could add: +# if [ -n "${TH_ARCHIVE_LOGS_ON_FAILURE}" ]; then +# PYTHON_CMD_ARGS+=("--archive-logs-on-failure" "${TH_ARCHIVE_LOGS_ON_FAILURE}") +# fi + +# Forward TH_JOB_ID if set (Python app reads this from env if not on CLI) +if [ -n "${APP_JOB_ID}" ]; then + PYTHON_CMD_ARGS+=("--job-id" "${APP_JOB_ID}") +fi + +echo "Python app executable: python3 -m test_harness.app" >&2 +echo "Python app arguments:" >&2 +printf " %s\n" "${PYTHON_CMD_ARGS[@]}" >&2 +echo "-----------------------------------------------------" >&2 + + +# --- Execute the Python Test Harness Application --- +PYTHON_APP_STDOUT_FILE="${APP_RUN_TEMP_DIR}/python_app_stdout.log" # Temporary capture +PYTHON_APP_STDERR_FILE="${APP_RUN_TEMP_DIR}/python_app_stderr.log" # Temporary capture + +# Execute python app. +# stdout is redirected to this script's stdout (which goes to Joshua). +# stderr is redirected to this script's diagnostic log file. +echo "Executing Python app..." >&2 +python3 -m test_harness.app "${PYTHON_CMD_ARGS[@]}" > "${PYTHON_APP_STDOUT_FILE}" 2> "${PYTHON_APP_STDERR_FILE}" +PYTHON_EXIT_CODE=$? +echo "Python app execution finished. Exit code: ${PYTHON_EXIT_CODE}" >&2 + +# If the python app failed, log it for clarity. The script will continue, +# print any available stdout, and then exit with the failure code. +if [ "${PYTHON_EXIT_CODE}" -ne 0 ]; then + echo "Error: Python application returned a non-zero exit code." >&2 +fi -OLDBINDIR="${OLDBINDIR:-/app/deploy/global_data/oldBinaries}" -#mono bin/TestHarness.exe joshua-run "${OLDBINDIR}" false +# Output the Python app's stdout (the single XML line) to this script's stdout +if [ -f "${PYTHON_APP_STDOUT_FILE}" ]; then + cat "${PYTHON_APP_STDOUT_FILE}" +else + echo "WARNING: Python app stdout file (${PYTHON_APP_STDOUT_FILE}) not found." >&2 + # Output a fallback XML if Python produced no stdout + echo '' +fi -# export RARE_PRIORITY=20 -python3 -m test_harness.app -s ${JOSHUA_SEED} --old-binaries-path ${OLDBINDIR} +exit ${PYTHON_EXIT_CODE} diff --git a/contrib/TestHarness2/README.md b/contrib/TestHarness2/README.md new file mode 100644 index 00000000000..9cf987ed920 --- /dev/null +++ b/contrib/TestHarness2/README.md @@ -0,0 +1,69 @@ +# FoundationDB TestHarness2 + +This directory contains TestHarness2, a Python-based test harness for FoundationDB, designed to be invoked by the Joshua testing framework via scripts like `correctnessTest.sh`. In typical FoundationDB testing setups orchestrated by Joshua, this harness and the tests it runs are executed within Kubernetes pods. + +## Key Features +* Parses FoundationDB trace event logs (`trace.*.xml` or `trace.*.json`). +* Generates summary XML (`joshua.xml`) compatible with Joshua's expectations. +* Supports configuration via command-line arguments and environment variables. +* Includes an optional feature for preserving detailed logs on test failure to aid in debugging. + +## TestHarness2 Operation and Outputs + +Understanding how TestHarness2 operates and where it stores its output is essential for interpreting test results and debugging issues. + +### Unified Output Directory + +For each invocation, TestHarness2 (via its `correctnessTest.sh` wrapper) creates a single, consolidated output directory. This makes all artifacts from a single run easy to find. + +* **Location:** The base location defaults to `/tmp` but can be controlled by the `TH_OUTPUT_DIR` environment variable. +* **Naming Convention:** The directory is named `th_run_`, where `` is the unique Joshua seed for the run (e.g., `/tmp/th_run_6709478271895344724`). + +### Directory Structure + +Inside each `th_run_` directory, you will find a standardized structure: + +* `joshua_output/`: + * **`joshua.xml`**: A comprehensive XML file containing detailed results and parsed events from all test parts. This is the most important file for a detailed analysis of the run. + * **`app_log.txt`**: The main log file for the Python test harness application itself. Check this file first to debug issues with the harness, such as configuration errors or crashes. + * Other summary files like `stats.json` or `run_times.json` if configured. + +* `run_files/`: + * This directory contains a subdirectory for each individual test part that was executed. + * Each per-test-part subdirectory contains: + * `logs/`: The raw FoundationDB trace event logs (`trace.*.json`). + * `command.txt`: The exact `fdbserver` command used for that test part. + * `stdout.txt` / `stderr.txt`: The raw standard output/error from the `fdbserver` process for that part. + +### V1 Compatibility vs. Archival Mode + +TestHarnessV2 has two primary modes of operation, controlled by the `TH_ARCHIVE_LOGS_ON_FAILURE` environment variable. + +#### Default Behavior (`TH_ARCHIVE_LOGS_ON_FAILURE` is unset or `false`) + +* **V1 `stdout` Emulation:** For every test part (both success and failure), a single-line XML summary is printed to standard output. This is captured by Joshua and serves as the primary, persistent record of the test outcome. +* **Cleanup:** The entire `th_run_` directory is **deleted** after the run completes, regardless of success or failure. + +#### Archival Mode (`TH_ARCHIVE_LOGS_ON_FAILURE=true`) + +This mode is designed to help debug failures by preserving all detailed logs and linking them directly from the summary. + +* **V1 `stdout` Emulation:** The harness continues to print the single-line XML summary to `stdout` for every test part, just like in the default mode. +* **Log Referencing on Failure:** If a test part fails, special ``, ``, and other reference tags are injected into that test part's summary within the main `joshua_output/joshua.xml` file. These tags contain the absolute paths to the preserved log files and directories. +* **Conditional Cleanup:** + * If the test run is **successful**, the `th_run_` directory is **deleted**. + * If the test run **fails**, the entire `th_run_` directory is **preserved**, allowing you to inspect all the artifacts and follow the paths referenced in the `joshua.xml`. + +**Example of enabling archival mode:** +```bash +joshua start --env TH_ARCHIVE_LOGS_ON_FAILURE=true --tarball /path/to/your/test.tar.gz +``` + +### Summary of Outputs and Preservation: + +* **Joshua `stdout` (Always):** + * Contains the official single-line XML summaries for each test part. This is the "V1 compatible" output. +* **`/tmp/th_run_/` (Or `$TH_OUTPUT_DIR/th_run_/`):** + * Contains all detailed artifacts: FDB traces, `joshua.xml`, `app_log.txt`, etc. + * **Default Mode:** Deleted after every run. + * **Archival Mode:** Preserved **only if** the run fails. Deleted on success. \ No newline at end of file diff --git a/contrib/TestHarness2/test_harness/app.py b/contrib/TestHarness2/test_harness/app.py index 32ef7325514..c69af36d700 100644 --- a/contrib/TestHarness2/test_harness/app.py +++ b/contrib/TestHarness2/test_harness/app.py @@ -1,27 +1,647 @@ +from __future__ import annotations + import argparse +import logging +import pathlib +import random import sys +import time import traceback +import os +import xml.etree.ElementTree as ET +from xml.sax import saxutils # For escaping +import io # For StreamTee fileno exception +import copy # For deepcopy in stripping function +from pathlib import Path +from typing import Optional, List, Tuple +import signal +from datetime import datetime -from test_harness.config import config -from test_harness.run import TestRunner -from test_harness.summarize import SummaryTree +from test_harness.config import Config + +# Initialize logger at module level with a NullHandler to prevent "No handlers found" warnings +# if the script fails before logging is fully configured in main(). +logger = logging.getLogger(__name__) +logger.addHandler(logging.NullHandler()) + +APP_PY_DEBUG_LOG_FILE_PATH = None # Global to store the path of the app.py specific debug log +original_stdout = sys.stdout # Capture at module load time +original_stderr = sys.stderr # Capture at module load time + +# Import from summarize for stripping logic +from test_harness.summarize import TAGS_TO_STRIP_FROM_TEST_ELEMENT_FOR_STDOUT + +from test_harness.config import config # Ensure config is imported for setup_logging +from test_harness.run import TestRunner # Import TestRunner +from test_harness.summarize import SummaryTree # Import SummaryTree + +# Define setup_logging function here +def setup_logging(config, process_id: int, timestamp: int, existing_logger: Optional[logging.Logger] = None) -> logging.Logger: + """ + Configures the global logger for the application. + If an existing_logger is passed, it reconfigures it instead of creating a new one. + """ + logger = existing_logger or logging.getLogger("__main__") + + # Explicitly close and remove old handlers to release file locks + if logger.hasHandlers(): + for handler in logger.handlers[:]: + handler.close() + logger.removeHandler(handler) + + log_file_path: Optional[Path] = None + + # Preferred path: /app_log.txt + if hasattr(config, 'joshua_output_dir') and config.joshua_output_dir: + try: + # The shell script should have already created this directory + jod = Path(config.joshua_output_dir) + jod.mkdir(parents=True, exist_ok=True) + log_file_path = jod / 'app_log.txt' + except (OSError, PermissionError) as e: + original_stderr.write(f"app.py setup_logging: Could not create or access joshua_output_dir '{config.joshua_output_dir}'. Error: {e}. Falling back to emergency log.\n") + log_file_path = None + + # Fallback path if the preferred path is not usable + if log_file_path is None: + emergency_dir = Path('/tmp') + emergency_dir.mkdir(exist_ok=True) + log_file_path = emergency_dir / f"th_emergency_app_log.{process_id}.{timestamp}.log" + if existing_logger is None: # Only print this on the very first setup + original_stderr.write(f"app.py setup_logging: Using emergency log file: {log_file_path}\n") + + # Basic logging config + log_level = logging.INFO + if hasattr(config, 'log_level') and isinstance(config.log_level, str): + level_from_config = getattr(logging, config.log_level.upper(), logging.INFO) + if isinstance(level_from_config, int): + log_level = level_from_config + + formatter = logging.Formatter("%(asctime)s - %(process)d - %(name)s - %(levelname)s - %(message)s") + + file_handler = logging.FileHandler(log_file_path) + file_handler.setLevel(log_level) + file_handler.setFormatter(formatter) + + logger.setLevel(log_level) + logger.addHandler(file_handler) + + logger.info(f"Logger configured by setup_logging. Log file: {log_file_path}, Level: {logging.getLevelName(log_level)}") + return logger + +class StreamTee: + """ + A file-like object that "tees" writes to two streams: an original target + stream and a log stream. + + It can be configured to write to both, or only to the log stream, effectively + suppressing output to the original target while still capturing it. + + This class is intended to replace streams like `sys.stdout` or `sys.stderr` + to allow simultaneous capture of output to a log file and optional pass-through + to the console or original destination. + + Attributes: + original_stream_target: The primary stream (e.g., `sys.stdout`, `sys.stderr`) + that output may be passed to. + log_stream: The secondary stream (e.g., an open file object) where all + output is unconditionally written. + pass_to_original_target (bool): If True, writes are passed to + `original_stream_target`. If False, writes + only go to `log_stream`. + """ + def __init__(self, original_stream_target, log_stream, pass_to_original_target: bool): + self.original_stream_target = original_stream_target # e.g. original_stdout + self.log_stream = log_stream # e.g. log_file_stream_ref + self.pass_to_original_target = pass_to_original_target + + def write(self, data): + # Always write to log_stream (if available) + if self.log_stream and not self.log_stream.closed: + try: + self.log_stream.write(data) + except Exception as e_log: + # Fallback: print to original stderr if logging to file fails + print(f"StreamTee: Error writing to log_stream: {e_log}", file=original_stderr) + + # Conditionally write to original_stream_target + if self.pass_to_original_target: + if self.original_stream_target: + try: + self.original_stream_target.write(data) + except Exception as e_orig: + print(f"StreamTee: Error writing to original_stream_target: {e_orig}", file=original_stderr) + + self.flush() # Flush both/either based on their state/flags after every write + + def flush(self): + # Always flush log_stream (if available and flushing is enabled for it) + if self.log_stream and not self.log_stream.closed and hasattr(self.log_stream, 'flush'): + try: + self.log_stream.flush() + except Exception as e_log_flush: + print(f"StreamTee: Error flushing log_stream: {e_log_flush}", file=original_stderr) + + # Conditionally flush original_stream_target + if self.pass_to_original_target: + if self.original_stream_target and hasattr(self.original_stream_target, 'flush'): + try: + self.original_stream_target.flush() + except Exception as e_orig_flush: + print(f"StreamTee: Error flushing original_stream_target: {e_orig_flush}", file=original_stderr) + + def fileno(self): + # fileno should primarily refer to the stream that replaces the original sys.std*, if any pass-through is happening. + # If not passing to original, or if original doesn't support fileno, this becomes tricky. + # For many use cases (like subprocess), if sys.stdout is a pipe, fileno is needed. + # If pass_to_original_target is True and original_stream_target has fileno, use it. + if self.pass_to_original_target and hasattr(self.original_stream_target, 'fileno'): + return self.original_stream_target.fileno() + # If only logging or original target doesn't have fileno, but log_stream does (e.g. if it were a pipe, unlikely for file): + # This might be problematic. For now, prefer original_stream_target if available and passing through. + # If not passing to original, what should fileno be? Some libraries check this. + # Defaulting to log_stream's fileno if original isn't used/doesn't have one can be an option, + # or raising an error. Raising error is safer if the behavior is undefined for the use case. + if hasattr(self.log_stream, 'fileno'): # Check log_stream if not using original_stream_target for fileno + # This case might be for when original_stream_target is not active but something still needs a fileno. + # However, usually fileno() is called on what sys.stdout IS. + # If not passing to original, then sys.stdout *is* this Tee object which primarily writes to log. + pass + + # Safest: if original_stream_target (conditionally active) doesn't have fileno, then this Tee object doesn't robustly provide one. + # The previous code used self.stream1.fileno() which was original_stdout/stderr + if hasattr(self.original_stream_target, 'fileno'): + return self.original_stream_target.fileno() + raise io.UnsupportedOperation("StreamTee: fileno not available on the configured original_stream_target or not passing through.") + +def strip_elements_for_v1_stdout(xml_string: str) -> str: + """ + Parses an XML string, removes specified child elements from the root, + and returns the modified XML string. + Designed for fatal error XMLs in app.py that need V1 stdout formatting. + """ + global logger + try: + source_element = ET.fromstring(xml_string) + logger.debug(f"strip_elements_for_v1_stdout: Original XML for stripping: {xml_string}") + + children_tags_before_filtering = [child.tag for child in list(source_element)] + logger.debug(f"strip_elements_for_v1_stdout: Children tags BEFORE filtering: {children_tags_before_filtering}") + + # Create a new root element (e.g., ) and copy attributes + filtered_element = ET.Element(source_element.tag) + for k, v in source_element.attrib.items(): + filtered_element.set(k, v) + + kept_children_tags = [] + for child in list(source_element): + if child.tag not in TAGS_TO_STRIP_FROM_TEST_ELEMENT_FOR_STDOUT: + # Important: We need to append a copy of the child, not the child itself if it's from a tree + # that might be used elsewhere, though for ET.fromstring result, it's a new tree. + # For safety and consistency with summarize.py's deepcopy behavior before filtering: + filtered_element.append(copy.deepcopy(child)) + kept_children_tags.append(child.tag) + else: + logger.debug(f"strip_elements_for_v1_stdout: Identified for stripping - child.tag: '{child.tag}'") + + logger.debug(f"strip_elements_for_v1_stdout: Children tags AFTER filtering: {kept_children_tags}") + + # Serialize the new filtered element + # short_empty_elements=True is generally preferred for V1. + # create_fatal_error_xml uses short_empty_elements=False, but if JoshuaMessage is the only child and stripped, + # short_empty_elements=True makes which is fine. + modified_xml_string = ET.tostring(filtered_element, encoding='unicode', short_empty_elements=True).strip() + logger.debug(f"strip_elements_for_v1_stdout: XML after stripping: {modified_xml_string}") + return modified_xml_string + + except Exception as e: + logger.error(f"strip_elements_for_v1_stdout: Failed to parse or strip XML string '{xml_string[:100]}...': {e}", exc_info=True) + # Fallback: return the original string, or a generic error XML if parsing failed badly + # For safety, return original string as stripping is best-effort for these fatal paths. + return xml_string + +def create_fatal_error_xml(message: str, error_type: str = "FatalError", test_uid: str = "UNKNOWN_UID", joshua_seed: str = "UNKNOWN_SEED") -> str: + global logger + try: + # config.joshua_seed might not be initialized if this is called very early. + # Access it carefully. + joshua_seed_val = "UNKNOWN_SEED_IN_FATAL_XML" + if hasattr(config, 'joshua_seed') and config.joshua_seed is not None: + # In config.py, joshua_seed is an int after extract_args. + # If extract_args hasn't run, it might be a ConfigValue object or the default int. + # For robustness, handle if it's a ConfigValue object, though ideally extract_args runs first. + if hasattr(config.joshua_seed, 'value') and config.joshua_seed.value is not None: + joshua_seed_val = str(config.joshua_seed.value) + elif isinstance(config.joshua_seed, int): + joshua_seed_val = str(config.joshua_seed) + # else, it remains UNKNOWN_SEED_IN_FATAL_XML or the passed joshua_seed param + elif joshua_seed != "UNKNOWN_SEED": # Use parameter if config is not available + joshua_seed_val = str(joshua_seed) + + test_element = ET.Element("Test") + test_element.set("TestUID", test_uid) + test_element.set("JoshuaSeed", joshua_seed_val) + test_element.set("Ok", "0") + test_element.set("Error", saxutils.escape(str(error_type))) + + jm_element = ET.SubElement(test_element, "JoshuaMessage") + jm_element.set("Severity", "40") # Error severity + jm_element.set("Message", saxutils.escape(str(message))) + + # short_empty_elements=False ensures if no other children + return ET.tostring(test_element, encoding='unicode', short_empty_elements=False).strip() + except Exception as e: + logger.error(f"CRITICAL_ERROR_IN_CREATE_FATAL_ERROR_XML: {e}", exc_info=True) + # Fallback string if XML creation itself fails. + return f'' + +def main(): + """Main entry point of the TestHarnessV2 application.""" + # ========================================================================= + # Phase 1: Pre-Setup and Initial Checks (No File Logging) + # ========================================================================= + # Until config is parsed, we cannot safely log to a file. + # All critical early messages will go to the original stderr. + pid = os.getpid() + timestamp = int(datetime.now().timestamp()) + logger = logging.getLogger("__main__") + logger.addHandler(logging.NullHandler()) # Prevent "no handlers" warnings + config: Optional[Config] = None + summary_tree_for_joshua_xml: Optional[SummaryTree] = None + final_exit_code = 0 + + try: + # ===================================================================== + # Phase 2: Configuration Parsing + # ===================================================================== + # This is the first major step. If this fails, we exit. + try: + config, args = parse_and_validate_config(sys.argv) + except ConfigError as e: + original_stderr.write(f"FATAL: Configuration error: {e}\\n") + sys.exit(1) + except Exception as e: + original_stderr.write(f"FATAL: Unexpected error during config parsing: {e}\\n") + original_stderr.write(traceback.format_exc() + "\\n") + sys.exit(1) + + # ===================================================================== + # Phase 3: Setup Logging and Stream Redirection (NOW with config) + # ===================================================================== + # Now that we have a valid config, we can set up file logging once. + logger = setup_logging(config, pid, timestamp) + + logger.info("Configuration parsed and logger initialized successfully.") + + # Now, set up stream redirection to capture stdout/stderr for archival + stdout_tee, stderr_tee = setup_stream_redirection(config, logger) + + + # ===================================================================== + # Phase 4: Main Test Execution Logic + # ===================================================================== + perform_early_config_checks_and_exit_on_error(config) + + summary_tree_for_joshua_xml, structural_exit_code = run_tests_and_get_summary(config, args) + + if structural_exit_code != 0: + final_exit_code = structural_exit_code + logger.warning(f"Test runner returned a non-zero structural exit code: {structural_exit_code}") + + except Exception as e_global: + final_exit_code = 1 + logger.error(f"Unhandled global exception in main: {e_global}", exc_info=True) + # Create a minimal failure summary if one doesn't exist + if summary_tree_for_joshua_xml is None: + summary_tree_for_joshua_xml = SummaryTree("TestHarnessRun") + summary_tree_for_joshua_xml.attributes["Ok"] = "0" + summary_tree_for_joshua_xml.attributes["FailReason"] = "UnhandledException" + summary_tree_for_joshua_xml.attributes["Exception"] = str(e_global) + + finally: + # ===================================================================== + # Phase 5: Finalization and Cleanup + # ===================================================================== + + # Determine final exit code based on test results + if summary_tree_for_joshua_xml is not None and final_exit_code == 0: + if summary_tree_for_joshua_xml.attributes.get("BatchSuccess") == "0": + logger.info("Root summary tree BatchSuccess='0', setting final_exit_code to 1.") + final_exit_code = 1 + + # Write the final summary to joshua.xml + if config is not None: + write_summary_to_joshua_xml(summary_tree_for_joshua_xml, config) + else: + # This can happen if config parsing itself failed. + original_stderr.write("Could not write final joshua.xml because config was not available.\\n") + + # Restore original stdout/stderr + if 'stdout_tee' in locals() and sys.stdout == stdout_tee: + sys.stdout = original_stdout + if 'stderr_tee' in locals() and sys.stderr == stderr_tee: + sys.stderr = original_stderr + + logger.info(f"--- TestHarness2 app.py execution finishing. Exit code: {final_exit_code} ---") + logging.shutdown() + sys.exit(final_exit_code) + +def parse_and_validate_config(argv: List[str]) -> Tuple[Config, argparse.Namespace]: + """ + Parses command line arguments and environment variables, validates them, + and returns a populated Config object. Exits on error. + """ + # Custom ArgumentParser to prevent sys.exit on error and allow XML generation. + # --help and --version will still exit cleanly. + class NonExitingArgumentParser(argparse.ArgumentParser): + def error(self, message: str): + # message already contains "prog_name: error: ..." + # Create fatal XMLs for ConfigError. + # config.joshua_seed might be default int at this stage, before extract_args. + seed_str = str(config.joshua_seed) if hasattr(config, 'joshua_seed') and isinstance(config.joshua_seed, int) else "CONFIG_PARSE_SEED_UNAVAILABLE" + + err_type = "ArgParseError" + xml_message = f"Argument parsing error: {message}" + + raw_xml = create_fatal_error_xml(message=xml_message, error_type=err_type, joshua_seed=seed_str) + # Assume V1 stripping for stdout as this is before stream redirection decision. + stdout_xml = strip_elements_for_v1_stdout(raw_xml).replace('\\n', ' ').strip() + + # Raise our specific ConfigError, which main() expects to have these attributes. + raise ConfigError( + message=xml_message, # Console message + stdout_xml=stdout_xml, # What goes to V1 stdout + xml_content_for_file=raw_xml # What goes to joshua.xml + ) + + def exit(self, status=0, message=None): + # Handle --help, --version which also call exit. + if status == 0: # Typically --help output, or other clean exits. + # argparse already printed the help/version message to stdout/stderr. + # We should let the process exit cleanly as intended by argparse. + sys.exit(status) + + # For other non-zero status exits, treat as an error. + error_message = message if message else f"ArgumentParser called exit with status {status}" + seed_str = str(config.joshua_seed) if hasattr(config, 'joshua_seed') and isinstance(config.joshua_seed, int) else "CONFIG_EXIT_SEED_UNAVAILABLE" + err_type = f"ArgParseExitErrorStatus{status}" + xml_message = f"ArgumentParser exit: {error_message}" + + raw_xml = create_fatal_error_xml(message=xml_message, error_type=err_type, joshua_seed=seed_str) + stdout_xml = strip_elements_for_v1_stdout(raw_xml).replace('\\n', ' ').strip() + + raise ConfigError( + message=xml_message, + stdout_xml=stdout_xml, + xml_content_for_file=raw_xml + ) -if __name__ == "__main__": try: - parser = argparse.ArgumentParser( - "TestHarness", formatter_class=argparse.ArgumentDefaultsHelpFormatter + parser = NonExitingArgumentParser( + prog="TestHarnessV2 app.py", + description="Test Harness V2 Main Application", + formatter_class=argparse.ArgumentDefaultsHelpFormatter, # Good for help messages + add_help=True # Ensure --help is handled by our exit method. ) config.build_arguments(parser) - args = parser.parse_args() - config.extract_args(args) - test_runner = TestRunner() - if not test_runner.run(): - exit(1) + + # parse_args() will use sys.argv[1:] by default. + # If NonExitingArgumentParser.error or .exit (with non-zero status) is called, it raises ConfigError. + parsed_args = parser.parse_args(argv[1:]) + + config.extract_args(parsed_args) # This populates the global 'config' object + + # Log successful parsing and key config values. + logger.info("Configuration parsed and extracted successfully.") + if hasattr(config, 'joshua_output_dir') and config.joshua_output_dir is not None: + logger.info(f"Effective joshua_output_dir from config: {config.joshua_output_dir}") + else: + logger.warning("joshua_output_dir is not set after config parsing.") + + if hasattr(config, 'log_level') and config.log_level is not None: + logger.info(f"Effective log_level from config: {config.log_level}") + else: + logger.warning("log_level is not set after config parsing.") + + # Placeholder for any additional explicit validation checks on 'config' attributes. + # Example: + # if not config.some_critical_value: + # msg = f"Critical configuration 'some_critical_value' is missing or invalid." + # raw_xml = create_fatal_error_xml(message=msg, error_type="ConfigValidation", joshua_seed=str(config.joshua_seed)) + # stdout_xml = strip_elements_for_v1_stdout(raw_xml) + # raise ConfigError(msg, stdout_xml, raw_xml) + + except ConfigError: # Re-raise ConfigErrors from NonExitingArgumentParser or explicit checks. + # logger.debug("parse_and_validate_config is re-raising a ConfigError.") + raise + except Exception as e_config_setup: # Catch any other unexpected errors. + logger.error(f"Unexpected error during config parsing/validation: {type(e_config_setup).__name__} - {e_config_setup}", exc_info=True) + + joshua_seed_val = "UNKNOWN_EXC_SEED" + if hasattr(config, 'joshua_seed'): # Should be an int after __init__ + joshua_seed_val = str(config.joshua_seed) + + error_message_for_xml = f"Config setup failed: {type(e_config_setup).__name__} - {str(e_config_setup)}. Traceback: {traceback.format_exc()}" + + raw_xml = create_fatal_error_xml( + message=error_message_for_xml, + error_type=f"ConfigSetupUnexpectedError_{type(e_config_setup).__name__}", + joshua_seed=joshua_seed_val + ) + stdout_xml = strip_elements_for_v1_stdout(raw_xml).replace('\\n', ' ').strip() + + raise ConfigError( # Wrap in ConfigError for consistent handling in main() + message=f"Unexpected config setup error: {e_config_setup}", + stdout_xml=stdout_xml, + xml_content_for_file=raw_xml + ) + + return config, parsed_args + +def setup_stream_redirection(config, logger): + # The 'config' object is now passed in as a parameter. + # The 'global config' declaration is no longer needed and causes a SyntaxError. + + # Default to passing stdout through if config is not fully formed yet + pass_stdout_to_original = True + + try: + log_file_path_from_handler = None + for handler in logger.handlers: + if isinstance(handler, logging.FileHandler): + log_file_path_from_handler = handler.baseFilename + break + + if log_file_path_from_handler is None: + raise RuntimeError("Logger is not configured with a FileHandler; cannot set up stream redirection.") + + # The logger has already created the file, so we open it in append mode. + log_file_stream_for_tee = open(log_file_path_from_handler, 'a') + + # This logic determines if the V1-style stdout lines should be printed + # or if all stdout should be suppressed (when archival is on). + if hasattr(config, '_v1_summary_output_stream') and config._v1_summary_output_stream != original_stdout: + # This indicates V1 compatibility mode is NOT active for stdout. + # We check if archival is on to decide whether to suppress stdout entirely. + if hasattr(config, 'archive_logs_on_failure') and config.archive_logs_on_failure: + pass_stdout_to_original = False + + logger.info(f"Stream redirection: config._v1_summary_output_stream IS original_stdout. General app stdout will pass through.") + + if hasattr(config, 'archive_logs_on_failure') and config.archive_logs_on_failure: + logger.info(f"Stream redirection: archive_logs_on_failure is TRUE. General app stdout will be suppressed from original stdout.") + pass_stdout_to_original = False + + + # Tee stdout to the log file. Pass-through to the original stdout is conditional. + sys.stdout = StreamTee(original_stdout, log_file_stream_for_tee, pass_to_original_target=pass_stdout_to_original) + logger.info(f"sys.stdout redirected. Pass to original: {pass_stdout_to_original}") + + # Tee stderr to the log file. Always pass-through to original stderr. + sys.stderr = StreamTee(original_stderr, log_file_stream_for_tee, pass_to_original_target=True) + logger.info("sys.stderr redirected. Pass to original: True") + + logger.info("Stream redirection configured.") + except Exception as e: - _, _, exc_traceback = sys.exc_info() - error = SummaryTree("TestHarnessError") - error.attributes["Severity"] = "40" - error.attributes["ErrorMessage"] = str(e) - error.attributes["Trace"] = repr(traceback.format_tb(exc_traceback)) - error.dump(sys.stdout) - exit(1) + logger.error(f"CRITICAL: Failed to setup stream redirection: {e}", exc_info=True) + # We write directly to original_stderr because the logger's stream might be the problem. + if original_stderr and not original_stderr.closed: + original_stderr.write(f"app.py: CRITICAL FAILURE during stream redirection setup: {type(e).__name__}: {e}\\n{traceback.format_exc()}\\n\\n") + raise # Re-raise to be caught by main's exception handler. + + return sys.stdout, sys.stderr + +def perform_early_config_checks_and_exit_on_error(config): + global logger + # The 'config' object is now passed in as a parameter. + # The 'global config' declaration is no longer needed and causes a SyntaxError. + + logger.info("Performing early configuration checks...") + + try: + # Example check (can be expanded): + # if not config.joshua_output_dir or not os.access(config.joshua_output_dir, os.W_OK): + # msg = f"joshua_output_dir '{config.joshua_output_dir}' is not set or not writable." + # logger.error(msg) + # raw_xml = create_fatal_error_xml(message=msg, error_type="EarlyConfigCheckFail_OutputDir", joshua_seed=str(config.joshua_seed)) + # stdout_xml = strip_elements_for_v1_stdout(raw_xml).replace('\\n', ' ').strip() + # raise EarlyExitError(msg, stdout_xml, raw_xml) + + # Add other critical checks here as needed. + + logger.info("Early configuration checks passed (or no checks implemented yet).") + + except EarlyExitError: # Allow EarlyExitErrors to propagate directly. + raise + except Exception as e_check: + error_message = f"Unexpected error during early config checks: {type(e_check).__name__} - {e_check}" + logger.error(error_message, exc_info=True) + + joshua_seed_val = str(config.joshua_seed) if hasattr(config, 'joshua_seed') else "EARLY_CHECK_EXC_SEED" + xml_err_msg = f"{error_message}. Traceback: {traceback.format_exc()}" + + raw_xml = create_fatal_error_xml( + message=xml_err_msg, + error_type=f"EarlyConfigCheckUnexpectedError_{type(e_check).__name__}", + joshua_seed=joshua_seed_val + ) + stdout_xml = strip_elements_for_v1_stdout(raw_xml).replace('\\n', ' ').strip() + + # Wrap in EarlyExitError for consistent handling in main() + raise EarlyExitError( + message=f"Unexpected early config check error: {e_check}", + stdout_xml=stdout_xml, + xml_content_for_file=raw_xml + ) + +def run_tests_and_get_summary(config, args): + global logger + + logger.info("Initializing TestRunner and starting test execution...") + + final_summary_tree = None + overall_exit_code = 1 # Default to error + + try: + runner = TestRunner(config) # Pass the global config object + + # Call run_all_tests() which returns the main SummaryTree. + summary_tree_result = runner.run_all_tests() # Returns a SummaryTree + + # If run_all_tests completes without an exception, we consider this stage successful. + # The actual pass/fail status of tests within the tree is handled by main's finally block. + exit_code_from_runner = 0 + + if not isinstance(summary_tree_result, SummaryTree): + logger.error(f"TestRunner.run_all_tests() returned an invalid type for summary tree: {type(summary_tree_result)}. Expected SummaryTree.") + final_summary_tree = SummaryTree(config) # Initialize an empty one + overall_exit_code = 1 # This variable is local to the function + else: + final_summary_tree = summary_tree_result + logger.info("TestRunner.run_all_tests() completed. Summary tree received.") + overall_exit_code = exit_code_from_runner # Use the 0 from above if no type error + + # This check for exit_code_from_runner type is less critical now as we set it to 0 by default + # but keeping it for robustness in case of future changes. + if not isinstance(exit_code_from_runner, int): + logger.error(f"run_tests_and_get_summary determined an invalid type for exit code: {type(exit_code_from_runner)}. Expected int.") + overall_exit_code = 1 # Ensure error exit code if something went wrong with our logic + # else overall_exit_code already reflects exit_code_from_runner + + except Exception as e_runner: + logger.error(f"CRITICAL: Unhandled exception from TestRunner instantiation or run_all_tests(): {type(e_runner).__name__} - {e_runner}", exc_info=True) + overall_exit_code = 1 + # Let main's global handler create the fatal XML. final_summary_tree will be None. + raise + + logger.info(f"run_tests_and_get_summary finished. Returning summary tree and determined structural exit code {overall_exit_code}.") + return final_summary_tree, overall_exit_code + + +def write_summary_to_joshua_xml(summary_tree: Optional[SummaryTree], current_config: 'Config'): + """Serializes the final summary tree to joshua.xml.""" + # This function uses `current_config` as its parameter, so no `global` statement is needed. + if summary_tree is None: + logger.error("write_summary_to_joshua_xml called with None summary_tree. Cannot write file.") + return + + if not (hasattr(current_config, 'joshua_output_dir') and current_config.joshua_output_dir): + logger.error("write_summary_to_joshua_xml: joshua_output_dir not configured.") + return + + try: + joshua_xml_path = current_config.joshua_output_dir / "joshua.xml" + current_config.joshua_output_dir.mkdir(parents=True, exist_ok=True) + + xml_content_for_file = "" + # Prioritize to_et_element() + if hasattr(summary_tree, 'to_et_element') and callable(summary_tree.to_et_element): + xml_element = summary_tree.to_et_element() + if xml_element is not None: + xml_content_for_file = ET.tostring(xml_element, encoding='unicode', short_empty_elements=False).strip() + else: + logger.error("SummaryTree.to_et_element() returned None.") + xml_content_for_file = create_fatal_error_xml("SummaryTree.to_et_element() was None", "SummaryTreeXmlError", str(current_config.joshua_seed)) + # Fallback: Check for a specific to_xml_string method + elif hasattr(summary_tree, 'to_xml_string') and callable(summary_tree.to_xml_string): + xml_content_for_file = summary_tree.to_xml_string() + # Generic fallback to str(), with a warning + else: + logger.warning("SummaryTree has no .to_xml_string(), using str(). This might not be correct XML.") + xml_content_for_file = str(summary_tree) + + if not xml_content_for_file: + logger.error("XML content from SummaryTree was empty. Writing a fallback error to joshua.xml.") + xml_content_for_file = create_fatal_error_xml("SummaryTree produced empty XML", "EmptySummaryTreeXml", str(current_config.joshua_seed)) + + with open(joshua_xml_path, "w", encoding='utf-8') as f: + f.write(xml_content_for_file) + logger.info(f"Final summary XML (joshua.xml) saved to {joshua_xml_path}") + + except Exception as e_write_summary: + logger.error(f"Could not write final summary joshua.xml: {type(e_write_summary).__name__} - {e_write_summary}", exc_info=True) + + +if __name__ == "__main__": + main() diff --git a/contrib/TestHarness2/test_harness/config.py b/contrib/TestHarness2/test_harness/config.py index c9642df2e49..497be0c6179 100644 --- a/contrib/TestHarness2/test_harness/config.py +++ b/contrib/TestHarness2/test_harness/config.py @@ -7,7 +7,9 @@ import random from enum import Enum from pathlib import Path -from typing import List, Any, OrderedDict, Dict +from typing import List, Any, OrderedDict, Dict, Optional +import typing +import sys class BuggifyOptionValue(Enum): @@ -40,40 +42,35 @@ def __init__(self, name: str, **kwargs): self.value = self.kwargs["default"] def get_arg_name(self) -> str: + name_to_use = self.name if "long_name" in self.kwargs: - return self.kwargs["long_name"] - else: - return self.name + name_to_use = self.kwargs["long_name"] + return name_to_use.replace("-", "_") def add_to_args(self, parser: argparse.ArgumentParser): kwargs = copy.copy(self.kwargs) long_name = self.name short_name = None + if "name" in kwargs: + long_name = kwargs.pop("name") if "long_name" in kwargs: - long_name = kwargs["long_name"] - del kwargs["long_name"] + long_name = kwargs.pop("long_name") if "short_name" in kwargs: - short_name = kwargs["short_name"] - del kwargs["short_name"] + short_name = kwargs.pop("short_name") if "action" in kwargs and kwargs["action"] in ["store_true", "store_false"]: - del kwargs["type"] - long_name = long_name.replace("_", "-") + if 'type' in kwargs: + del kwargs["type"] + long_name = long_name.replace("_", "-").lstrip('-') if short_name is None: - # line below is useful for debugging - # print('add_argument(\'--{}\', [{{{}}}])'.format(long_name, ', '.join(['\'{}\': \'{}\''.format(k, v) - # for k, v in kwargs.items()]))) parser.add_argument("--{}".format(long_name), **kwargs) else: - # line below is useful for debugging - # print('add_argument(\'-{}\', \'--{}\', [{{{}}}])'.format(short_name, long_name, - # ', '.join(['\'{}\': \'{}\''.format(k, v) - # for k, v in kwargs.items()]))) parser.add_argument( "-{}".format(short_name), "--{}".format(long_name), **kwargs ) def get_value(self, args: argparse.Namespace) -> tuple[str, Any]: - return self.name, args.__getattribute__(self.get_arg_name()) + arg_name_for_namespace = self.get_arg_name() + return self.name, args.__getattribute__(arg_name_for_namespace) class Config: @@ -115,12 +112,13 @@ def __init__(self): "required": False, "env_name": "JOSHUA_CLUSTER_FILE", } - self.joshua_dir: str | None = None - self.joshua_dir_args = { - "type": str, - "help": "Where to write FDB data to", - "required": False, - "env_name": "JOSHUA_APP_DIR", + self.joshua_output_dir: Path | None = None + self.joshua_output_dir_args = { + "name": "--joshua-output-dir", + "env_name": "TH_JOSHUA_OUTPUT_DIR", + "type": Path, + "default": None, + "help": "Directory for TestHarnessV2 to store joshua.xml and other outputs.", } self.stats: str | None = None self.stats_args = { @@ -134,8 +132,14 @@ def __init__(self): "help": "Force given seed given to fdbserver -- mostly useful for debugging", "required": False, } - self.kill_seconds: int = 30 * 60 - self.kill_seconds_args = {"help": "Timeout for individual test"} + self.kill_seconds: int = 1800 + self.kill_seconds_args = { + "name": "--kill-seconds", + "env_name": "TH_KILL_SECONDS", + "type": int, + "default": 1800, + "help": "Seconds after which a test is killed.", + } self.buggify_on_ratio: float = 0.8 self.buggify_on_ratio_args = {"help": "Probability that buggify is turned on"} self.write_run_times = False @@ -147,10 +151,17 @@ def __init__(self): self.unseed_check_ratio_args = { "help": "Probability for doing determinism check" } - self.test_dirs: List[str] = ["slow", "fast", "restarting", "rare", "noSim"] - self.test_dirs_args: dict = { + self.test_source_dir: Path = Path("tests") + self.test_source_dir_args = { + "type": Path, + "help": "Root directory containing test type subdirectories (e.g., slow, fast) which hold .toml test files.", + "env_name": "JOSHUA_TEST_FILES_DIR", + } + self.test_types_to_run: List[str] = ["slow", "fast", "restarting", "rare", "noSim"] + self.test_types_to_run_args: dict = { "nargs": "*", - "help": "test_directories to look for files in", + "help": "List of test type subdirectories (under test_source_dir) to run tests from (e.g., slow, fast).", + "long_name": "test-types" } self.trace_format: str = "json" self.trace_format_args = { @@ -184,7 +195,13 @@ def __init__(self): self.pretty_print_args = {"short_name": "P", "action": "store_true"} self.clean_up: bool = True self.clean_up_args = {"long_name": "no_clean_up", "action": "store_false"} - self.run_dir: Path = Path("tmp") + self.run_temp_dir: Path | None = None + self.run_temp_dir_args = { + "type": Path, + "help": "Temporary directory for individual test run artifacts and logs.", + "required": True, + "env_name": "TH_RUN_TEMP_DIR", + } self.joshua_seed: int = random.randint(0, 2**32 - 1) self.joshua_seed_args = { "short_name": "s", @@ -199,7 +216,7 @@ def __init__(self): self.binary_args = {"help": "Path to executable"} self.hit_per_runs_ratio: int = 20000 self.hit_per_runs_ratio_args = { - "help": "Maximum test runs before each code probe hit at least once" + "help": "Maximum test runs before each code probe hit least once" } self.output_format: str = "xml" self.output_format_args = { @@ -240,6 +257,9 @@ def __init__(self): "help": "Ignore coverage traces that originated in files matching regex" } self.max_stderr_bytes: int = 10000 + self.max_stderr_bytes_args = { + "help": "Maximum number of bytes to include from stderr if a test fails." + } self.write_stats: bool = True self.read_stats: bool = True self.reproduce_prefix: str | None = None @@ -250,10 +270,33 @@ def __init__(self): } self.long_running: bool = False self.long_running_args = {"action": "store_true"} - self._env_names: Dict[str, str] = {} + self.log_level: str = "INFO" + self.log_level_args = { + "name": "--log-level", + "env_name": "TH_LOG_LEVEL", + "type": str, + "default": "INFO", + "help": "Logging level for the application (e.g., DEBUG, INFO, WARNING)", + } + self.archive_logs_on_failure: bool = False + self.archive_logs_on_failure_args = { + "action": "store_true", + "help": "If set, archive FDB logs and test harness outputs to a .tar.gz file in the joshua_output_dir on test failure.", + "env_name": "TH_ARCHIVE_LOGS_ON_FAILURE", + } + self._v1_summary_output_stream: Optional[typing.TextIO] = sys.stdout + self._env_names: typing.Dict[str, str] = {} self._config_map = self._build_map() self._read_env() self.random.seed(self.joshua_seed, version=2) + self.output_dir: Path | None = None + self.output_dir_args = { + "name": "--output-dir", + "env_name": "TH_OUTPUT_DIR", + "type": Path, + "default": None, + "help": "Top-level directory for all run outputs.", + } def change_default(self, attr: str, default_val): assert attr in self._config_map, "Unknown config attribute {}".format(attr) @@ -326,7 +369,7 @@ def extract_args(self, args: argparse.Namespace): for val in self._config_map.values(): k, v = val.get_value(args) if v is not None: - config.__setattr__(k, v) + self.__setattr__(k, v) self.random.seed(self.joshua_seed, version=2) diff --git a/contrib/TestHarness2/test_harness/fdb.py b/contrib/TestHarness2/test_harness/fdb.py index 3ee0cc1b5ef..527a9f5c2ae 100644 --- a/contrib/TestHarness2/test_harness/fdb.py +++ b/contrib/TestHarness2/test_harness/fdb.py @@ -79,7 +79,7 @@ def write_coverage( coverage: OrderedDict[Coverage, bool], ): db = open_db(cluster_file) - assert config.joshua_dir is not None + assert config.joshua_output_dir is not None initialized: bool = False for chunk in chunkify(coverage.items(), 100): initialized = write_coverage_chunk(db, cov_path, metadata, chunk, initialized) @@ -145,7 +145,7 @@ class FDBStatFetcher(StatFetcher): def __init__( self, tests: OrderedDict[str, TestDescription], - joshua_dir: Tuple[str] = str_to_tuple(config.joshua_dir), + joshua_dir: Tuple[str] = str_to_tuple(str(config.joshua_output_dir)), ): super().__init__(tests) self.statistics = Statistics(config.cluster_file, joshua_dir) diff --git a/contrib/TestHarness2/test_harness/run.py b/contrib/TestHarness2/test_harness/run.py index 0c60934dd7c..3702876e915 100644 --- a/contrib/TestHarness2/test_harness/run.py +++ b/contrib/TestHarness2/test_harness/run.py @@ -5,6 +5,7 @@ import collections import math import os +import random import resource import shutil import subprocess @@ -13,15 +14,22 @@ import threading import time import uuid +import xml.etree.ElementTree as ET +import logging +import platform +from typing import Dict, List, Pattern, OrderedDict, Optional, Union, TYPE_CHECKING from functools import total_ordering from pathlib import Path from test_harness.version import Version -from test_harness.config import config, BuggifyOptionValue -from typing import Dict, List, Pattern, OrderedDict +from test_harness.config import BuggifyOptionValue from test_harness.summarize import Summary, SummaryTree +if TYPE_CHECKING: + from test_harness.config import Config + +logger = logging.getLogger(__name__) @total_ordering class TestDescription: @@ -41,9 +49,9 @@ def __lt__(self, other): def __eq__(self, other): if isinstance(other, TestDescription): - return self.name < other.name + return self.name == other.name else: - return self.name < str(other.name) + return self.name == str(other.name) class StatFetcher: @@ -58,13 +66,14 @@ def add_run_time(self, test_name: str, runtime: int, out: SummaryTree): class TestPicker: - def __init__(self, test_dir: Path, binaries: OrderedDict[Version, Path]): + def __init__(self, test_dir: Path, binaries: OrderedDict[Version, Path], config_obj: Config): + self.config = config_obj if not test_dir.exists(): raise RuntimeError("{} is neither a directory nor a file".format(test_dir)) - self.include_files_regex = re.compile(config.include_test_files) - self.exclude_files_regex = re.compile(config.exclude_test_files) - self.include_tests_regex = re.compile(config.include_test_classes) - self.exclude_tests_regex = re.compile(config.exclude_test_names) + self.include_files_regex = re.compile(self.config.include_test_files) + self.exclude_files_regex = re.compile(self.config.exclude_test_files) + self.include_tests_regex = re.compile(self.config.include_test_classes) + self.exclude_tests_regex = re.compile(self.config.exclude_test_names) self.test_dir: Path = test_dir self.tests: OrderedDict[str, TestDescription] = collections.OrderedDict() self.restart_test: Pattern = re.compile(r".*-\d+\.(txt|toml)") @@ -73,24 +82,32 @@ def __init__(self, test_dir: Path, binaries: OrderedDict[Version, Path]): self.rare_priority: int = int(os.getenv("RARE_PRIORITY", 10)) for subdir in self.test_dir.iterdir(): - if subdir.is_dir() and subdir.name in config.test_dirs: + if subdir.is_dir() and subdir.name in self.config.test_types_to_run: self.walk_test_dir(subdir) self.stat_fetcher: StatFetcher - if config.stats is not None or config.joshua_dir is None: + if self.config.stats is not None or self.config.joshua_output_dir is None: self.stat_fetcher = StatFetcher(self.tests) else: from test_harness.fdb import FDBStatFetcher self.stat_fetcher = FDBStatFetcher(self.tests) - if config.stats is not None: - self.load_stats(config.stats) + if self.config.stats is not None: + self.load_stats(self.config.stats) else: self.fetch_stats() if not self.tests: - raise Exception( - "No tests to run! Please check if tests are included/excluded incorrectly or old binaries are missing for restarting tests" + joshua_output_dir_str = str(self.config.joshua_output_dir) if self.config.joshua_output_dir else "None" + error_message = ( + "No tests to run! Please check if tests are included/excluded incorrectly " + "or old binaries are missing for restarting tests. " + f"Test Dir: {self.test_dir}, " + f"Include Files: {self.config.include_test_files}, Exclude Files: {self.config.exclude_test_files}, " + f"Include Tests: {self.config.include_test_classes}, Exclude Tests: {self.config.exclude_test_names}, " + f"Joshua Output Dir for FDBStatFetcher: {joshua_output_dir_str}" ) + logger.error(f"Detailed context for 'No tests to run!': {error_message}") + raise Exception(error_message) def add_time(self, test_file: Path, run_time: int, out: SummaryTree) -> None: # getting the test name is fairly inefficient. But since we only have 100s of tests, I won't bother @@ -98,13 +115,13 @@ def add_time(self, test_file: Path, run_time: int, out: SummaryTree) -> None: test_desc: TestDescription | None = None for name, test in self.tests.items(): for p in test.paths: - test_files: List[Path] + test_files_to_check: List[Path] if self.restart_test.match(p.name): - test_files = self.list_restart_files(p) + test_files_to_check = self.list_restart_files(p) else: - test_files = [p] - for file in test_files: - if file.absolute() == test_file.absolute(): + test_files_to_check = [p] + for file_to_check in test_files_to_check: + if file_to_check.absolute() == test_file.absolute(): test_name = name test_desc = test break @@ -139,9 +156,6 @@ def parse_txt(self, path: Path): or self.exclude_files_regex.search(str(path)) is not None ): return - # Skip restarting tests that do not have old binaries in the given version range - # In particular, this is only for restarting tests with the "until" keyword, - # since without "until", it will at least run with the current binary. if is_restarting_test(path): candidates: List[Path] = [] dirs = path.parent.parts @@ -153,11 +167,10 @@ def parse_txt(self, path: Path): ): max_version = Version.parse(version_expr[3]) min_version = Version.parse(version_expr[1]) - for ver, binary in self.old_binaries.items(): + for ver, binary_path in self.old_binaries.items(): if min_version <= ver < max_version: - candidates.append(binary) + candidates.append(binary_path) if not len(candidates): - # No valid old binary found return with path.open("r") as f: @@ -210,10 +223,9 @@ def parse_txt(self, path: Path): def walk_test_dir(self, test: Path): if test.is_dir(): - for file in test.iterdir(): - self.walk_test_dir(file) + for file_item in test.iterdir(): + self.walk_test_dir(file_item) else: - # check whether we're looking at a restart test if self.follow_test.match(test.name) is not None: return if test.suffix == ".txt" or test.suffix == ".toml": @@ -223,134 +235,156 @@ def walk_test_dir(self, test: Path): def list_restart_files(start_file: Path) -> List[Path]: name = re.sub(r"-\d+.(txt|toml)", "", start_file.name) res: List[Path] = [] - for test_file in start_file.parent.iterdir(): - if test_file.name.startswith(name): - res.append(test_file) - assert len(res) > 1 + for test_file_item in start_file.parent.iterdir(): + if test_file_item.name.startswith(name): + res.append(test_file_item) + assert len(res) >= 1, f"Restart test {name} starting with {start_file} should have at least one part." res.sort() return res def choose_test(self) -> List[Path]: candidates: List[TestDescription] = [] - if config.random.random() < 0.99: - # 99% of the time, select a test with the least runtime + if self.config.random.random() < 0.99: min_runtime: float | None = None - for _, v in self.tests.items(): - this_time = v.total_runtime * v.priority + for _, v_item in self.tests.items(): + this_time = v_item.total_runtime * v_item.priority if min_runtime is None or this_time < min_runtime: min_runtime = this_time - candidates = [v] + candidates = [v_item] elif this_time == min_runtime: - candidates.append(v) + candidates.append(v_item) else: - # 1% of the time, select the test with the fewest runs, rather than the test - # with the least runtime. This is to improve coverage for long-running tests min_runs: int | None = None - for _, v in self.tests.items(): - if min_runs is None or v.num_runs < min_runs: - min_runs = v.num_runs - candidates = [v] - elif v.num_runs == min_runs: - candidates.append(v) + for _, v_item in self.tests.items(): + if min_runs is None or v_item.num_runs < min_runs: + min_runs = v_item.num_runs + candidates = [v_item] + elif v_item.num_runs == min_runs: + candidates.append(v_item) + + if not candidates: + logger.error("No candidates found in choose_test. This indicates an issue with test priorities or runtimes.") + if not self.tests: + raise Exception("No tests available to choose from and TestPicker.tests is empty.") + candidates = list(self.tests.values()) candidates.sort() - choice = config.random.randint(0, len(candidates) - 1) - test = candidates[choice] - result = test.paths[config.random.randint(0, len(test.paths) - 1)] - if self.restart_test.match(result.name): - return self.list_restart_files(result) + choice_idx = self.config.random.randint(0, len(candidates) - 1) + test_desc = candidates[choice_idx] + result_path = test_desc.paths[self.config.random.randint(0, len(test_desc.paths) - 1)] + if self.restart_test.match(result_path.name): + return self.list_restart_files(result_path) else: - return [result] + return [result_path] class OldBinaries: - def __init__(self): + def __init__(self, config_obj: Config): + self.config = config_obj self.first_file_expr = re.compile(r".*-1\.(txt|toml)") - self.old_binaries_path: Path = config.old_binaries_path + self.old_binaries_path: Path = self.config.old_binaries_path self.binaries: OrderedDict[Version, Path] = collections.OrderedDict() if not self.old_binaries_path.exists() or not self.old_binaries_path.is_dir(): return exec_pattern = re.compile(r"fdbserver-\d+\.\d+\.\d+(\.exe)?") - for file in self.old_binaries_path.iterdir(): - if not file.is_file() or not os.access(file, os.X_OK): + for file_item in self.old_binaries_path.iterdir(): + if not file_item.is_file() or not os.access(file_item, os.X_OK): continue - if exec_pattern.fullmatch(file.name) is not None: - self._add_file(file) + if exec_pattern.fullmatch(file_item.name) is not None: + self._add_file(file_item) - def _add_file(self, file: Path): - version_str = file.name.split("-")[1] + def _add_file(self, file_path: Path): + version_str = file_path.name.split("-")[1] if version_str.endswith(".exe"): version_str = version_str[0 : -len(".exe")] ver = Version.parse(version_str) - self.binaries[ver] = file + self.binaries[ver] = file_path def choose_binary(self, test_file: Path) -> Path: if len(self.binaries) == 0: - return config.binary + return self.config.binary max_version = Version.max_version() min_version = Version.parse("5.0.0") dirs = test_file.parent.parts if "restarting" not in dirs: - return config.binary - version_expr = dirs[-1].split("_") + return self.config.binary + + try: + restarting_idx = dirs.index("restarting") + if restarting_idx + 1 < len(dirs): + version_expr_str = dirs[restarting_idx+1] + else: + return self.config.binary + except ValueError: + return self.config.binary + + version_expr = version_expr_str.split("_") first_file = self.first_file_expr.match(test_file.name) is not None + if first_file and version_expr[0] == "to": - # downgrade test -- first binary should be current one - return config.binary + return self.config.binary if not first_file and version_expr[0] == "from": - # upgrade test -- we only return an old version for the first test file - return config.binary + return self.config.binary if version_expr[0] == "from" or version_expr[0] == "to": - min_version = Version.parse(version_expr[1]) + if len(version_expr) > 1: + min_version = Version.parse(version_expr[1]) + else: + return self.config.binary if len(version_expr) == 4 and version_expr[2] == "until": max_version = Version.parse(version_expr[3]) + candidates: List[Path] = [] - for ver, binary in self.binaries.items(): + for ver, binary_path in self.binaries.items(): if min_version <= ver < max_version: - candidates.append(binary) + candidates.append(binary_path) if len(candidates) == 0: - return config.binary - return config.random.choice(candidates) + return self.config.binary + return self.config.random.choice(candidates) def is_restarting_test(test_file: Path): - for p in test_file.parts: - if p == "restarting": - return True - return False + return "restarting" in test_file.parts def is_negative(test_file: Path): - return test_file.parts[-2] == "negative" + return len(test_file.parts) > 1 and test_file.parts[-2] == "negative" def is_no_sim(test_file: Path): - return test_file.parts[-2] == "noSim" + return len(test_file.parts) > 1 and test_file.parts[-2] == "noSim" def is_rare(test_file: Path): - return test_file.parts[-2] == "rare" + return len(test_file.parts) > 1 and test_file.parts[-2] == "rare" class ResourceMonitor(threading.Thread): def __init__(self): super().__init__() - self.start_time = time.time() + self.daemon = True + self.start_time = time.monotonic() self.end_time: float | None = None - self._stop_monitor = False + self._stop_monitor = threading.Event() self.max_rss = 0 def run(self) -> None: - while not self._stop_monitor: - time.sleep(1) - resources = resource.getrusage(resource.RUSAGE_CHILDREN) - self.max_rss = max(resources.ru_maxrss, self.max_rss) + while not self._stop_monitor.is_set(): + if self._stop_monitor.wait(0.1): + break + try: + resources_children = resource.getrusage(resource.RUSAGE_CHILDREN) + self.max_rss = max(resources_children.ru_maxrss, self.max_rss) + except Exception as e: + logger.warning(f"ResourceMonitor: Error getting rusage: {e}") + def stop(self): - self.end_time = time.time() - self._stop_monitor = True + self.end_time = time.monotonic() + self._stop_monitor.set() - def time(self): + def get_time(self): + if self.end_time is None: + return time.monotonic() - self.start_time return self.end_time - self.start_time @@ -361,46 +395,107 @@ def __init__( test_file: Path, random_seed: int, uid: uuid.UUID, + config_obj: Config, restarting: bool = False, test_determinism: bool = False, - buggify_enabled: bool = False, stats: str | None = None, expected_unseed: int | None = None, will_restart: bool = False, + original_run_for_unseed_archival: Optional[TestRun] = None ): + self.config = config_obj self.binary = binary self.test_file = test_file self.random_seed = random_seed self.uid = uid + self.part_uid = uuid.uuid4() self.restarting = restarting self.test_determinism = test_determinism self.stats: str | None = stats self.expected_unseed: int | None = expected_unseed - self.use_valgrind: bool = config.use_valgrind - self.old_binary_path: Path = config.old_binaries_path - self.buggify_enabled: bool = buggify_enabled + self.use_valgrind: bool = self.config.use_valgrind + self.buggify_enabled: bool = False + if self.config.buggify.value == BuggifyOptionValue.ON: + self.buggify_enabled = True + elif self.config.buggify.value == BuggifyOptionValue.RANDOM: + self.buggify_enabled = self.config.random.random() < self.config.buggify_on_ratio + + self.fault_injection_enabled: bool = True - self.trace_format: str | None = config.trace_format - if Version.of_binary(self.binary) < "6.1.0": + self.trace_format: str | None = self.config.trace_format + + binary_version = Version.of_binary(self.binary) + if binary_version < "6.1.0": self.trace_format = None - self.use_tls_plugin = Version.of_binary(self.binary) < "5.2.0" - self.temp_path = config.run_dir / str(self.uid) - # state for the run + self.use_tls_plugin = binary_version < "5.2.0" + + self.temp_path = self.config.run_temp_dir / str(self.uid) / str(self.part_uid) + self.identified_fdb_log_files: List[Path] = [] + self.retryable_error: bool = False - self.summary: Summary = Summary( - binary, + self.stdout_path = self.temp_path / "stdout.txt" + self.stderr_path = self.temp_path / "stderr.txt" + self.command_file_path = self.temp_path / "command.txt" + + _paired_fdb_logs_for_summary: Optional[List[Path]] = None + _paired_harness_files_for_summary: Optional[List[Path]] = None + if original_run_for_unseed_archival and self.expected_unseed is not None: + logger.debug(f"Unseed check run (part {self.part_uid}) collecting paired files from original run part {original_run_for_unseed_archival.part_uid}") + _paired_fdb_logs_for_summary = original_run_for_unseed_archival.identified_fdb_log_files + logger.info(f" Original run (part {original_run_for_unseed_archival.part_uid}) identified_fdb_log_files for pairing: {[str(f) for f in (_paired_fdb_logs_for_summary or [])]}") + + _paired_harness_files_list = [ + original_run_for_unseed_archival.command_file_path, + original_run_for_unseed_archival.stderr_path, + original_run_for_unseed_archival.stdout_path, + ] + logger.info(f" Original run (part {original_run_for_unseed_archival.part_uid}) harness file paths for pairing (raw paths): command='{original_run_for_unseed_archival.command_file_path}', stdout='{original_run_for_unseed_archival.stdout_path}', stderr='{original_run_for_unseed_archival.stderr_path}'") + + _existing_paired_harness_files = [] + for p_idx, p_path in enumerate(_paired_harness_files_list): + if p_path and p_path.exists(): + _existing_paired_harness_files.append(p_path) + logger.debug(f" Paired harness file {p_idx} ({p_path}) exists and was added.") + elif p_path: + logger.warning(f" Original run's harness file {p_idx} ({p_path}) does not exist. Not adding to paired archive list.") + else: + logger.debug(f" Original run's harness file {p_idx} is None. Skipping.") + _paired_harness_files_for_summary = _existing_paired_harness_files + logger.info(f" Original run (part {original_run_for_unseed_archival.part_uid}) harness files for pairing (that exist): {[str(f) for f in (_paired_harness_files_for_summary or [])]}") + + self.summary = Summary( + binary=self.binary, uid=self.uid, - stats=self.stats, + current_part_uid=self.part_uid, expected_unseed=self.expected_unseed, will_restart=will_restart, - long_running=config.long_running, + long_running=self.config.long_running, + paired_run_fdb_logs_for_archival=_paired_fdb_logs_for_summary, + paired_run_harness_files_for_archival=_paired_harness_files_for_summary, + archive_logs_on_failure=self.config.archive_logs_on_failure, + joshua_output_dir=self.config.joshua_output_dir, + run_temp_dir=self.temp_path, + stats_attribute_for_v1=self.stats, + current_run_stdout_path=self.stdout_path, + current_run_stderr_path=self.stderr_path, + current_run_command_file_path=self.command_file_path, + fdb_log_files_for_archival=self.identified_fdb_log_files ) + self.fdb_stat_fetcher = None + self.resource_monitor = None + if self.restarting: + self.summary.out.attributes["Restarting"] = "1" + if self.test_determinism: + self.summary.out.attributes["DeterminismCheck"] = "1" + + self.run_time: int = 0 - self.success = self.run() + self.success = self._execute_test_part() def log_test_plan(self, out: SummaryTree): test_plan: SummaryTree = SummaryTree("TestPlan") - test_plan.attributes["TestUID"] = str(self.uid) + test_plan.attributes["TestUID"] = str(self.part_uid) + test_plan.attributes["ParentTestUID"] = str(self.uid) test_plan.attributes["RandomSeed"] = str(self.random_seed) test_plan.attributes["TestFile"] = str(self.test_file) test_plan.attributes["Buggify"] = "1" if self.buggify_enabled else "0" @@ -408,147 +503,246 @@ def log_test_plan(self, out: SummaryTree): "1" if self.fault_injection_enabled else "0" ) test_plan.attributes["DeterminismCheck"] = "1" if self.test_determinism else "0" - out.append(test_plan) def delete_simdir(self): - shutil.rmtree(self.temp_path / Path("simfdb")) + simfdb_path = self.temp_path / Path("simfdb") + if simfdb_path.exists(): + try: + shutil.rmtree(simfdb_path) + logger.debug(f"Deleted simdir: {simfdb_path}") + except Exception as e: + logger.error(f"Error deleting simdir {simfdb_path}: {e}", exc_info=True) + else: + logger.warning(f"Simdir not found for deletion: {simfdb_path}") + def _run_joshua_logtool(self): - """Calls Joshua LogTool to upload the test logs if 1) test failed 2) test is RocksDB related""" - if not os.path.exists("joshua_logtool.py"): - raise RuntimeError("joshua_logtool.py missing") + joshua_logtool_script = Path("joshua_logtool.py") + if not joshua_logtool_script.exists(): + logger.error(f"{joshua_logtool_script.name} missing in PWD ({Path.cwd()}). Cannot upload logs.") + return { + "stdout": "", "stderr": f"{joshua_logtool_script.name} not found.", "exit_code": -1, + "tool_skipped": True + } + command = [ - "python3", - "joshua_logtool.py", + sys.executable, + str(joshua_logtool_script), "upload", - "--test-uid", - str(self.uid), - "--log-directory", - str(self.temp_path), + "--test-uid", str(self.part_uid), + "--log-directory", str(self.temp_path), "--check-rocksdb", ] - result = subprocess.run(command, capture_output=True, text=True) - return { - "stdout": result.stdout, - "stderr": result.stderr, - "exit_code": result.returncode, - } - - def run(self): + logger.info(f"Running JoshuaLogTool: {' '.join(command)}") + try: + result = subprocess.run(command, capture_output=True, text=True, timeout=60) + logger.info(f"JoshuaLogTool stdout: {result.stdout}") + logger.info(f"JoshuaLogTool stderr: {result.stderr}") + logger.info(f"JoshuaLogTool exit_code: {result.returncode}") + return { + "stdout": result.stdout, "stderr": result.stderr, "exit_code": result.returncode, "tool_skipped": False + } + except subprocess.TimeoutExpired: + logger.error(f"JoshuaLogTool timed out after 60s.") + return {"stdout": "", "stderr": "JoshuaLogTool timed out.", "exit_code": -2, "tool_skipped": True} + except Exception as e: + logger.error(f"Exception running JoshuaLogTool: {e}", exc_info=True) + return {"stdout": "", "stderr": f"Exception: {e}", "exit_code": -3, "tool_skipped": True} + + + def _execute_test_part(self) -> bool: command: List[str] = [] env: Dict[str, str] = os.environ.copy() valgrind_file: Path | None = None - if self.use_valgrind and self.binary == config.binary: - # Only run the binary under test under valgrind. There's nothing we - # can do about valgrind errors in old binaries anyway, and it makes - # the test take longer. Also old binaries weren't built with - # USE_VALGRIND=ON, and we have seen false positives with valgrind in - # such binaries. + + stdout_data: str = "" + err_out: str = "" + actual_return_code: int = -1001 + process: Optional[subprocess.Popen] = None + + if self.use_valgrind: command.append("valgrind") - valgrind_file = self.temp_path / Path( - "valgrind-{}.xml".format(self.random_seed) - ) + valgrind_file = self.temp_path / Path(f"valgrind-{self.random_seed}.xml") dbg_path = os.getenv("FDB_VALGRIND_DBGPATH") if dbg_path is not None: - command.append("--extra-debuginfo-path={}".format(dbg_path)) + command.append(f"--extra-debuginfo-path={dbg_path}") command += [ "--xml=yes", - "--xml-file={}".format(valgrind_file.absolute()), + f"--xml-file={valgrind_file.absolute()}", "-q", ] + command += [ str(self.binary.absolute()), - "-r", - "test" if is_no_sim(self.test_file) else "simulation", - "-f", - str(self.test_file), - "-s", - str(self.random_seed), + "-r", "test" if is_no_sim(self.test_file) else "simulation", + "-f", str(self.test_file.absolute()), + "-s", str(self.random_seed), + "--logdir", "logs", ] + if self.trace_format is not None: command += ["--trace_format", self.trace_format] - if self.use_tls_plugin: - command += ["--tls_plugin", str(config.tls_plugin_path)] - env["FDB_TLS_PLUGIN"] = str(config.tls_plugin_path) - if config.disable_kaio: + if self.use_tls_plugin and self.config.tls_plugin_path: + command += ["--tls_plugin", str(self.config.tls_plugin_path.absolute())] + env["FDB_TLS_PLUGIN"] = str(self.config.tls_plugin_path.absolute()) + if self.config.disable_kaio: command += ["--knob-disable-posix-kernel-aio=1"] - if Version.of_binary(self.binary) >= "7.1.0": + + binary_version = Version.of_binary(self.binary) + if binary_version >= "7.1.0": command += ["-fi", "on" if self.fault_injection_enabled else "off"] + if self.restarting: command.append("--restarting") if self.buggify_enabled: command += ["-b", "on"] - if config.crash_on_error and not is_negative(self.test_file): + + if self.config.crash_on_error and not is_negative(self.test_file): command.append("--crash") - if config.long_running: - # disable simulation speedup + if self.config.long_running: command += ["--knob-sim-speedup-after-seconds=36000"] - # disable traceTooManyLines Error MAX_TRACE_LINES command += ["--knob-max-trace-lines=1000000000"] self.temp_path.mkdir(parents=True, exist_ok=True) + (self.temp_path / "logs").mkdir(parents=True, exist_ok=True) - # self.log_test_plan(out) - resources = ResourceMonitor() - resources.start() - process = subprocess.Popen( - command, - stdout=subprocess.DEVNULL, - stderr=subprocess.PIPE, - cwd=self.temp_path, - text=True, - env=env, - ) + self.command_str = " ".join(command) + logger.info(f"Executing test part: {self.command_str} in {self.temp_path}") + + # Write command string to command.txt for archival + try: + with open(self.command_file_path, 'w') as f_cmd: + f_cmd.write(self.command_str) + except Exception as e_write_cmd: + logger.error(f"Error writing command string to {self.command_file_path} for part {self.part_uid}: {e_write_cmd}") + + process_completed = False did_kill = False - # No timeout for long running tests - timeout = ( - 20 * config.kill_seconds - if self.use_valgrind - else (None if config.long_running else config.kill_seconds) - ) - err_out: str + try: - _, err_out = process.communicate(timeout=timeout) - except subprocess.TimeoutExpired: - process.kill() - _, err_out = process.communicate() - did_kill = True - resources.stop() - resources.join() - # we're rounding times up, otherwise we will prefer running very short tests (<1s) - self.run_time = math.ceil(resources.time()) + effective_timeout = None + logger.info(f"Evaluating effective_timeout for {self.part_uid}. Accessing config: long_running, kill_seconds, use_valgrind") + logger.debug(f"Config values: config.long_running={self.config.long_running}, config.kill_seconds={self.config.kill_seconds}, config.use_valgrind={self.use_valgrind}") + if not self.config.long_running: + effective_timeout = (20 * self.config.kill_seconds if self.use_valgrind else self.config.kill_seconds) + logger.info(f"Effective timeout for {self.part_uid} calculated: {effective_timeout}") + + logger.info(f"Attempting to Popen for {self.part_uid}: {command}") + process = subprocess.Popen( + command, stdout=subprocess.PIPE, stderr=subprocess.PIPE, + cwd=self.temp_path, env=env, + ) + logger.info(f"Popen successful for {self.part_uid}, process PID: {process.pid if process else 'N/A'}") + try: + logger.info(f"Calling process.communicate(timeout={effective_timeout}) for {self.part_uid}") + stdout_bytes, stderr_bytes = process.communicate(timeout=effective_timeout) + process_completed = True + actual_return_code = process.returncode + stdout_data = stdout_bytes.decode(errors='replace') if stdout_bytes else "" + err_out = stderr_bytes.decode(errors='replace') if stderr_bytes else "" + logger.info(f"process.communicate() returned for {self.part_uid}. process_completed={process_completed}, actual_return_code={actual_return_code}") + except subprocess.TimeoutExpired: + logger.warning(f"Test part {self.part_uid} timed out after {effective_timeout}s. Killing process.") + try: + process.kill() + killed_stdout_bytes, killed_stderr_bytes = process.communicate(timeout=5) + if killed_stdout_bytes: stdout_data += killed_stdout_bytes.decode(errors='replace') + if killed_stderr_bytes: err_out += killed_stderr_bytes.decode(errors='replace') + err_out += "\nPROCESS_KILLED_TIMEOUT" + except Exception as e_kill_comm: + logger.error(f"Error during communication after killing timed-out process {self.part_uid}: {e_kill_comm}", exc_info=True) + err_out += "\nPROCESS_KILLED_TIMEOUT_COMM_ERROR" + actual_return_code = process.returncode if process.returncode is not None else -1002 + did_kill = True + logger.info(f"TimeoutExpired block finished for {self.part_uid}. did_kill={did_kill}, actual_return_code={actual_return_code}") + except Exception as e_comm: + logger.error(f"Error during process communication for {self.part_uid}: {e_comm}", exc_info=True) + if isinstance(err_out, bytes): + err_out = err_out.decode(errors='replace') + f"\nCOMMUNICATE_ERROR_PRE_DECODE: {e_comm}" + else: + err_out += f"\nCOMMUNICATE_ERROR: {e_comm}" + if process and process.returncode is not None: + actual_return_code = process.returncode + else: + actual_return_code = -1003 + logger.info(f"Exception in communicate block finished for {self.part_uid}. actual_return_code={actual_return_code}") + except Exception as e_popen: + logger.error(f"Failed to start process for test part {self.part_uid}: {e_popen}", exc_info=True) + err_out = f"POPEN_ERROR: {e_popen}" + actual_return_code = -1004 + logger.info(f"Popen exception block finished for {self.part_uid}. actual_return_code={actual_return_code}") + + self.run_time = 0 + if hasattr(self, 'summary') and self.summary: + self.summary.max_rss = 0 + logger.info(f"Post-execution (ResourceMonitor disabled) for {self.part_uid}: stdout_len={len(stdout_data)}, stderr_len={len(err_out)}, final_actual_return_code={actual_return_code}") + + try: + with open(self.stdout_path, 'w') as f_out: + f_out.write(stdout_data if stdout_data else "") + with open(self.stderr_path, 'w') as f_err: + f_err.write(err_out if err_out else "") + except Exception as e_write: + logger.error(f"Error writing fdbserver stdout/stderr to files for part {self.part_uid}: {e_write}") + + explicit_log_dir = self.temp_path / "logs" + expected_suffix = ".xml" + if self.trace_format == "json": expected_suffix = ".json" + elif self.trace_format == "xml": expected_suffix = ".xml" + + if explicit_log_dir.is_dir(): + for log_file in explicit_log_dir.iterdir(): + if log_file.is_file() and log_file.name.endswith(expected_suffix): + self.identified_fdb_log_files.append(log_file) + + if self.identified_fdb_log_files: + logger.debug(f"Found FDB log files for part {self.part_uid} with suffix '{expected_suffix}': {self.identified_fdb_log_files}") + else: + logger.warning(f"No FDB log files matching suffix '{expected_suffix}' found in {explicit_log_dir} for part {self.part_uid}.") + else: + logger.warning(f"Explicitly specified FDB logs directory '{explicit_log_dir}' not found for part {self.part_uid}. Cannot find FDB logs.") + self.summary.is_negative_test = is_negative(self.test_file) - self.summary.runtime = resources.time() - self.summary.max_rss = resources.max_rss + self.summary.runtime = 0 + self.summary.max_rss = 0 self.summary.was_killed = did_kill self.summary.valgrind_out_file = valgrind_file self.summary.error_out = err_out - self.summary.summarize(self.temp_path, " ".join(command)) + self.summary.exit_code = actual_return_code + + self.summary.fdb_log_files_for_archival = self.identified_fdb_log_files + + if self.identified_fdb_log_files: + logger.info(f"Parsing FDB trace files for part {self.part_uid}: {[str(f) for f in self.identified_fdb_log_files]}") + self.summary.summarize_files(self.identified_fdb_log_files) + else: + logger.warning(f"No FDB trace files found to parse for part {self.part_uid} (looked in {explicit_log_dir}).") + + self.summary.test_file = self.test_file + self.summary.seed = self.random_seed + self.summary.test_name = self.test_file.stem + + logger.info(f"Preparing to summarize for {self.part_uid}. summary.exit_code set to {self.summary.exit_code}. Identified FDB logs: {len(self.identified_fdb_log_files if self.identified_fdb_log_files else [])}") + self.summary.summarize(self.temp_path, self.command_str) + if not self.summary.is_negative_test and not self.summary.ok(): logtool_result = self._run_joshua_logtool() child = SummaryTree("JoshuaLogTool") child.attributes["ExitCode"] = str(logtool_result["exit_code"]) - child.attributes["StdOut"] = logtool_result["stdout"] - child.attributes["StdErr"] = logtool_result["stderr"] - self.summary.out.append(child) - else: - child = SummaryTree("JoshuaLogTool") - child.attributes["IsNegative"] = str(self.summary.is_negative_test) - child.attributes["IsOk"] = str(self.summary.ok()) - child.attributes["HasError"] = str(self.summary.error) - child.attributes["JoshuaLogToolIgnored"] = str(True) + if not logtool_result["tool_skipped"]: + child.attributes["StdOut"] = logtool_result["stdout"] + child.attributes["StdErr"] = logtool_result["stderr"] + else: + child.attributes["Note"] = logtool_result["stderr"] self.summary.out.append(child) + self.summary.done() return self.summary.ok() def decorate_summary(out: SummaryTree, test_file: Path, seed: int, buggify: bool): - """Sometimes a test can crash before ProgramStart is written to the traces. These - tests are then hard to reproduce (they can be reproduced through TestHarness but - require the user to run in the joshua docker container). To account for this we - will write the necessary information into the attributes if it is missing.""" if "TestFile" not in out.attributes: - out.attributes["TestFile"] = str(test_file) + out.attributes["TestFile"] = str(test_file.absolute()) if "RandomSeed" not in out.attributes: out.attributes["RandomSeed"] = str(seed) if "BuggifyEnabled" not in out.attributes: @@ -556,105 +750,203 @@ def decorate_summary(out: SummaryTree, test_file: Path, seed: int, buggify: bool class TestRunner: - def __init__(self): + def __init__(self, config: Config): + self.config = config self.uid = uuid.uuid4() - self.test_path: Path = Path("tests") - self.cluster_file: str | None = None - self.fdb_app_dir: str | None = None - self.binary_chooser = OldBinaries() - self.test_picker = TestPicker(self.test_path, self.binary_chooser.binaries) + self.test_path: Path = self.config.test_source_dir + self.cluster_file: str | None = self.config.cluster_file + self.binary_chooser = OldBinaries(self.config) + if not self.test_path.exists() or not self.test_path.is_dir(): + raise RuntimeError(f"Test source directory {self.test_path} does not exist or is not a directory.") + self.test_picker = TestPicker(self.test_path, self.binary_chooser.binaries, self.config) + self.summary_tree = SummaryTree("TestResults", is_root_document=True) + def backup_sim_dir(self, seed: int): - temp_dir = config.run_dir / str(self.uid) - src_dir = temp_dir / "simfdb" - assert src_dir.is_dir() - dest_dir = temp_dir / "simfdb.{}".format(seed) - assert not dest_dir.exists() - shutil.copytree(src_dir, dest_dir) + base_temp_dir = self.config.run_temp_dir / str(self.uid) + src_dir = base_temp_dir / "simfdb" + if not src_dir.is_dir(): + logger.warning(f"Backup sim_dir: source {src_dir} does not exist or not a dir. Skipping backup.") + return + dest_dir = base_temp_dir / f"simfdb.{seed}" + if dest_dir.exists(): + logger.warning(f"Backup sim_dir: destination {dest_dir} already exists. Skipping.") + return + try: + shutil.copytree(src_dir, dest_dir) + logger.info(f"Backed up {src_dir} to {dest_dir}") + except Exception as e: + logger.error(f"Error backing up {src_dir} to {dest_dir}: {e}", exc_info=True) + def restore_sim_dir(self, seed: int): - temp_dir = config.run_dir / str(self.uid) - src_dir = temp_dir / "simfdb.{}".format(seed) - assert src_dir.exists() - dest_dir = temp_dir / "simfdb" - shutil.rmtree(dest_dir) - shutil.move(src_dir, dest_dir) + base_temp_dir = self.config.run_temp_dir / str(self.uid) + src_dir = base_temp_dir / f"simfdb.{seed}" + dest_dir = base_temp_dir / "simfdb" + if not src_dir.exists() or not src_dir.is_dir(): + logger.warning(f"Restore sim_dir: source backup {src_dir} not found. Skipping restore.") + return + try: + if dest_dir.exists(): + shutil.rmtree(dest_dir) + shutil.move(str(src_dir), str(dest_dir)) + logger.info(f"Restored {src_dir} to {dest_dir}") + except Exception as e: + logger.error(f"Error restoring {src_dir} to {dest_dir}: {e}", exc_info=True) + def run_tests( self, test_files: List[Path], seed: int, test_picker: TestPicker - ) -> bool: - result: bool = True - for count, file in enumerate(test_files): - will_restart = count + 1 < len(test_files) - binary = self.binary_chooser.choose_binary(file) - unseed_check = ( - not is_no_sim(file) - and config.random.random() < config.unseed_check_ratio - ) - buggify_enabled: bool = False - if config.buggify.value == BuggifyOptionValue.ON: - buggify_enabled = True - elif config.buggify.value == BuggifyOptionValue.RANDOM: - buggify_enabled = config.random.random() < config.buggify_on_ratio - - # FIXME: support unseed checks for restarting tests - run = TestRun( - binary, - file.absolute(), - seed + count, - self.uid, - restarting=count != 0, + ) -> tuple[bool, List[SummaryTree]]: + overall_result: bool = True + collected_summaries: List[SummaryTree] = [] + + for count, file_path_part in enumerate(test_files): + logger.info(f"RUN.PY: Starting test part {count + 1}/{len(test_files)}: {file_path_part.name}") + part_seed = type(self.config.random)(seed + count).randint(0, 2**63 - 1) + + current_run_part = TestRun( + binary=self.binary_chooser.choose_binary(file_path_part), + test_file=file_path_part.absolute(), + random_seed=part_seed, + uid=self.uid, + config_obj=self.config, + restarting=(count != 0), stats=test_picker.dump_stats(), - will_restart=will_restart, - buggify_enabled=buggify_enabled, + will_restart=(count + 1 < len(test_files)) ) - result = result and run.success - test_picker.add_time(test_files[0], run.run_time, run.summary.out) - decorate_summary(run.summary.out, file, seed + count, run.buggify_enabled) - if ( - unseed_check - and run.summary.unseed is not None - and run.summary.unseed >= 0 - ): - run.summary.out.append(run.summary.list_simfdb()) - run.summary.out.dump(sys.stdout) - if not result: - return False - if ( - count == 0 - and unseed_check - and run.summary.unseed is not None - and run.summary.unseed >= 0 - ): - run2 = TestRun( - binary, - file.absolute(), - seed + count, - self.uid, - restarting=count != 0, + overall_result = overall_result and current_run_part.success + + test_picker.add_time(file_path_part, current_run_part.run_time, current_run_part.summary.out) + decorate_summary(current_run_part.summary.out, file_path_part, part_seed, current_run_part.buggify_enabled) + + # === V1 STDOUT SUMMARY LOGIC for main test part === + if self.config._v1_summary_output_stream: + v1_xml_string = current_run_part.summary.get_v1_stdout_line() + if v1_xml_string: + logger.debug(f"RUN.PY: TestRunner (main part) ABOUT TO WRITE to _v1_summary_output_stream for part {current_run_part.summary.current_part_uid}. XML String: >>>{v1_xml_string}<<<") + self.config._v1_summary_output_stream.write(v1_xml_string + "\n") + self.config._v1_summary_output_stream.flush() + else: + actual_value_for_log = repr(v1_xml_string) + logger.warning(f"RUN.PY: TestRunner (main part) - get_v1_stdout_line for part {current_run_part.summary.current_part_uid} returned None or empty. Type: {type(v1_xml_string)}, Value for logging: {actual_value_for_log}, Boolean eval: {bool(v1_xml_string)}. Not writing to V1 stdout.") + # === END V1 STDOUT SUMMARY LOGIC === + + collected_summaries.append(current_run_part.summary.out) + + # Determine if an unseed check should be performed for the current_run_part + # An unseed check is only performed if the first part was successful (Ok="1") + # and the random chance based on unseed_check_ratio passes. + should_perform_unseed_check_based_on_ratio_and_success = ( + self.config.unseed_check_ratio > 0 and + current_run_part.summary.ok() and # Only check if first part thinks it's OK + type(self.config.random)(part_seed).random() < self.config.unseed_check_ratio + ) + + if not current_run_part.summary.ok(): + logger.info(f"RUN.PY: Main test part for {file_path_part.name} failed (Ok=0, Error: '{current_run_part.summary.error}'). Skipping unseed check.") + # overall_result is already False because current_run_part.success was anded in. + return False, collected_summaries # Early exit if first part failed + + # If the first part was successful, proceed to potential unseed check + if should_perform_unseed_check_based_on_ratio_and_success: + logger.info(f"RUN.PY: Performing determinism check for {file_path_part.name} (first part was Ok='1').") + # Forcing the same seed to be used for the second run + unseed_part_seed = part_seed + logger.info(f"RUN.PY: Forcing identical seed for determinism check: {unseed_part_seed}") + + expected_unseed_from_first_run = current_run_part.summary.unseed + logger.info(f"RUN.PY: Unseed from first run (current_run_part.summary.unseed): {expected_unseed_from_first_run}") + + unseed_run_part = TestRun( + binary=self.binary_chooser.choose_binary(file_path_part), + test_file=file_path_part.absolute(), + random_seed=unseed_part_seed, + uid=self.uid, + config_obj=self.config, + restarting=(count != 0), stats=test_picker.dump_stats(), - expected_unseed=run.summary.unseed, - will_restart=will_restart, - buggify_enabled=buggify_enabled, - ) - test_picker.add_time(file, run2.run_time, run.summary.out) - decorate_summary( - run2.summary.out, file, seed + count, run.buggify_enabled + expected_unseed=expected_unseed_from_first_run, + will_restart=(count + 1 < len(test_files)), + original_run_for_unseed_archival=current_run_part ) - run2.summary.out.dump(sys.stdout) - result = result and run2.success - if not result: - return False - return result - - def run(self) -> bool: - seed = ( - config.random_seed - if config.random_seed is not None - else config.random.randint(0, 2**32 - 1) - ) + + # The overall_result now also depends on the success of the unseed run part. + # current_run_part.success was already part of overall_result. + # So, we AND in the unseed_run_part.success. + overall_result = overall_result and unseed_run_part.success + + test_picker.add_time(file_path_part, unseed_run_part.run_time, unseed_run_part.summary.out) + decorate_summary(unseed_run_part.summary.out, file_path_part, unseed_part_seed, unseed_run_part.buggify_enabled) + + if self.config._v1_summary_output_stream: + v1_xml_string_unseed = unseed_run_part.summary.get_v1_stdout_line() + if v1_xml_string_unseed: + logger.debug(f"RUN.PY: TestRunner (unseed part) ABOUT TO WRITE to _v1_summary_output_stream for part {unseed_run_part.summary.current_part_uid}. XML String: >>>{v1_xml_string_unseed}<<<" ) + self.config._v1_summary_output_stream.write(v1_xml_string_unseed + "\n") + self.config._v1_summary_output_stream.flush() + else: + actual_value_for_log_unseed = repr(v1_xml_string_unseed) + logger.warning(f"RUN.PY: TestRunner (unseed part) - get_v1_stdout_line for part {unseed_run_part.summary.current_part_uid} returned None or empty. Type: {type(v1_xml_string_unseed)}, Value for logging: {actual_value_for_log_unseed}, Boolean eval: {bool(v1_xml_string_unseed)}. Not writing to V1 stdout.") + + collected_summaries.append(unseed_run_part.summary.out) + + if not unseed_run_part.success: # Check specific success of unseed run part + logger.info(f"RUN.PY: Unseed check FAILED for {file_path_part.name}. Error: '{unseed_run_part.summary.error}'") + logger.info(f"RUN.PY: Original Run Unseed: {current_run_part.summary.unseed}") + logger.info(f"RUN.PY: Determinism Check Unseed: {unseed_run_part.summary.unseed}") + # overall_result is already False. Return immediately. + return False, collected_summaries + else: + logger.info(f"RUN.PY: Unseed check PASSED for {file_path_part.name}.") + + # If we reach here, either unseed check was not performed (and first part was OK), + # or it was performed and passed. + # The overall_result reflects the status. + + logger.info(f"RUN.PY: Finished all {len(test_files)} test parts. Overall result: {overall_result}") + return overall_result, collected_summaries + + def run_all_tests(self) -> SummaryTree: + logger.info(f"TestRunner.run_all_tests started (UID: {self.uid}). Base seed for this run: {self.config.joshua_seed}") + + # test_files will be a list of paths, e.g., for a single test or multiple parts of a restarting test. test_files = self.test_picker.choose_test() - success = self.run_tests(test_files, seed, self.test_picker) - if config.clean_up: - shutil.rmtree(config.run_dir / str(self.uid)) - return success + + if not test_files: + logger.info("Test picker returned no tests for this invocation. Returning an empty summary tree for results.") + # self.summary_tree is already initialized in __init__ as SummaryTree("TestResults", is_root_document=True) + # No children will be added if no tests are run. + else: + logger.info(f"TestRunner (UID: {self.uid}) chose test file(s): {[str(f) for f in test_files]}") + + # self.run_tests executes the chosen test files (which could be one or more parts of a single test case) + # It uses the provided joshua_seed to derive specific seeds for each part. + current_run_success, current_run_summary_trees = self.run_tests( + test_files, self.config.joshua_seed, self.test_picker + ) + + if current_run_summary_trees: + for single_test_summary_tree in current_run_summary_trees: + if single_test_summary_tree is not None: + self.summary_tree.append(single_test_summary_tree) + else: + logger.warning("run_tests returned a None SummaryTree in its list of results.") + else: + logger.warning("run_tests returned no summary trees for the current test set, though test files were chosen.") + + # Add an attribute to indicate if the set of tests (which could be multi-part) processed in this invocation was successful. + # app.py will determine the final exit code based on children's Ok status. + self.summary_tree.attributes["BatchSuccess"] = "1" if current_run_success else "0" + + # Add some overall attributes to the root summary_tree for this invocation. + self.summary_tree.attributes["TestRunnerUID"] = str(self.uid) + self.summary_tree.attributes["ConfiguredJoshuaSeed"] = str(self.config.joshua_seed) + self.summary_tree.attributes["TestsChosenCount"] = str(len(test_files) if test_files else 0) + + logger.info(f"TestRunner.run_all_tests (UID: {self.uid}) finished. Returning main summary tree.") + return self.summary_tree + + +def is_restarting_test(test_file: Path): + return "restarting" in test_file.parts diff --git a/contrib/TestHarness2/test_harness/summarize.py b/contrib/TestHarness2/test_harness/summarize.py index 031720b7f2d..389d1b0818a 100644 --- a/contrib/TestHarness2/test_harness/summarize.py +++ b/contrib/TestHarness2/test_harness/summarize.py @@ -11,8 +11,11 @@ import xml.sax import xml.sax.handler import xml.sax.saxutils - -from pathlib import Path +import tarfile +import logging +import xml.etree.ElementTree as ET +import copy +import gzip from typing import ( List, Dict, @@ -24,20 +27,99 @@ Tuple, Iterator, Iterable, + Union, + Set, ) +from pathlib import Path from test_harness.config import config from test_harness.valgrind import parse_valgrind_output +logger = logging.getLogger(__name__) + +CURRENT_VERSION = "0.1" + +# Define TAGS_TO_STRIP_FROM_TEST_ELEMENT_FOR_STDOUT at module level +TAGS_TO_STRIP_FROM_TEST_ELEMENT_FOR_STDOUT: Set[str] = { + "CodeCoverage", + "ValgrindError", + "StdErrOutput", + "StdErrOutputTruncated", + "JoshuaMessage", # V1 successful stdout didn't always have this. Its presence in the failing example is noted. + # "SimFDB", # REMOVE THIS LINE to stop stripping SimFDB + # "FailureLogArchive",# New tag specific to TestHarnessV2, NOT STRIPPED FROM STDOUT so j tail -s can see it. + # "JoshuaLogTool" # REMOVE THIS LINE to stop stripping JoshuaLogTool + # Children from trace events (e.g., ) ARE KEPT. +} + +# This set remains, as these are elements we *don't* want in the detailed joshua.xml if they are too verbose +# but it's not directly used by get_v1_stdout_line for *inclusion*. +TAGS_TO_STRIP_FROM_JOSHUA_XML_IF_EMPTY_OR_DEFAULT = {"Knobs", "Metrics", "BuggifySection"} + +# Define the set of child tags essential for the V1 stdout line. +# These will be included if present in the main summary. +ESSENTIAL_V1_CHILD_TAGS_TO_KEEP = { + "SimFDB", + "JoshuaLogTool", + "DisableConnectionFailures_Tester", + "EnableConnectionFailures_Tester", + "ScheduleDisableConnectionFailures_Tester", + "DisableConnectionFailures_BulkDumping", + "DisableConnectionFailures_BulkLoading", + "DisableConnectionFailures_ConsistencyCheck", + "CommitProxyTerminated", + "QuietDatabaseConsistencyCheckStartFail", + "UnseedMismatch", # Add for V1 error case compatibility + "WarningLimitExceeded", # Add for V1 error case compatibility + "ErrorLimitExceeded", # Add for V1 error case compatibility + # Note: ArchiveFile is handled separately and explicitly added if present. +} + +# Define tags that should be explicitly STRIPPED from the V1 stdout line +# because they are too verbose, not V1-like, or handled differently. +STDOUT_EXPLICITLY_STRIPPED_TAGS = { + "CodeCoverage", + "ValgrindError", + "StdErrOutput", # Not in V1 success example, can be verbose + "StdErrOutputTruncated", # Not in V1 success example, can be verbose + "Knobs", # Usually very verbose + "Metrics", # Usually very verbose + "JoshuaMessage", # Not in V1 success example (though can appear in errors/warnings) + # SimFDB is not in the V1 example; if it appears and is verbose, it could be added here. + # JoshuaLogTool is in the V1 example, so it's NOT stripped. + # Event-derived tags like *_Tester are NOT stripped by default. +} class SummaryTree: - def __init__(self, name: str): + def __init__(self, name: str, is_root_document: bool = False): self.name = name self.children: List[SummaryTree] = [] self.attributes: Dict[str, str] = {} + self.root: Optional[ET.Element] = None + if is_root_document: + self.root = ET.Element(self.name) def append(self, element: SummaryTree): self.children.append(element) + if self.root is not None and element.root is not None: + self.root.append(element.to_et_element()) + elif self.root is not None: + self.root.append(element.to_et_element()) + + def to_et_element(self) -> ET.Element: + element = ET.Element(self.name) + for k, v_raw in self.attributes.items(): + element.set(str(k), xml.sax.saxutils.escape(str(v_raw))) + + for child_summary_tree in self.children: + element.append(child_summary_tree.to_et_element()) + + if self.root is None: + self.root = element + elif self.root is not element: + pass + + return element def to_dict(self, add_name: bool = True) -> Dict[str, Any] | List[Any]: if len(self.children) > 0 and len(self.attributes) == 0: @@ -128,6 +210,30 @@ def dump(self, out: TextIO, prefix: str = "", new_line: bool = True): if new_line: out.write("\n") + def to_string_document(self) -> str: + """Serializes the entire XML tree to a string, including XML declaration.""" + if self.root is None: + # Ensure the root element is built if it hasn't been already + # This might happen if to_et_element was never called on this specific SummaryTree instance + # but it's expected to be the root of a document. + # However, the root is typically set during __init__ if is_root_document=True + # or when to_et_element is first called. + # For safety, we can try to build it, but this indicates a potential logic issue + # if self.root is None when we expect a full document. + logger.warning("to_string_document called on a SummaryTree with no self.root. Attempting to build from self.") + self.to_et_element() # This will build and assign self.root if it's None + + if self.root is None: + logger.error("Cannot serialize SummaryTree to string document: self.root is still None after attempted build.") + return "Cannot serialize XML document: root element is missing" + + try: + xml_str = ET.tostring(self.root, encoding='unicode', short_empty_elements=True) + return f'\n{xml_str}' + except Exception as e: + logger.error(f"Error during SummaryTree.to_string_document serialization: {e}", exc_info=True) + return f'\nSerializationFailed: {xml.sax.saxutils.escape(str(e))}' + ParserCallback = Callable[[Dict[str, str]], Optional[str]] @@ -157,22 +263,32 @@ def _call(self, callback: ParserCallback, attrs: Dict[str, str]) -> str | None: return None def handle(self, attrs: Dict[str, str]): - if None in self.events: - for callback in self.events[None]: - self._call(callback, attrs) - for k, v in attrs.items(): + # Call specific handlers first + # This allows them to add children to self.out before the generic handler runs. + # The generic handler (parse_generic_event_as_child) has de-duplication logic + # that relies on seeing what specific handlers have already done. + for k, v_attr in attrs.items(): + # Check for (key, specific_value) handlers, e.g., ("Severity", "30") + if (k, v_attr) in self.events: + for callback in self.events[(k, v_attr)]: + # We don't need to update attrs here based on remap for this specific issue, + # as parse_warning/parse_error don't rely on remapped values from other handlers. + self._call(callback, attrs) + + # Check for (key, None) handlers (match key, any value), e.g., ("Time", None) + # These are typically for attribute remapping or broad side effects. if (k, None) in self.events: for callback in self.events[(k, None)]: remap = self._call(callback, attrs) if remap is not None: - v = remap - attrs[k] = v - if (k, v) in self.events: - for callback in self.events[(k, v)]: - remap = self._call(callback, attrs) - if remap is not None: - v = remap - attrs[k] = v + # If a remapping occurred, update the attribute value for subsequent handlers + # (though for this specific pass, it mainly affects other (key,None) or the generic handler). + attrs[k] = remap + + # Now call generic (None) handlers, like parse_generic_event_as_child + if None in self.events: + for callback in self.events[None]: + self._call(callback, attrs) class Parser: @@ -319,6 +435,7 @@ def __init__( max_rss: int | None = None, was_killed: bool = False, uid: uuid.UUID | None = None, + current_part_uid: uuid.UUID | None = None, expected_unseed: int | None = None, exit_code: int = 0, valgrind_out_file: Path | None = None, @@ -326,19 +443,49 @@ def __init__( error_out: str = None, will_restart: bool = False, long_running: bool = False, + paired_run_fdb_logs_for_archival: Optional[List[Path]] = None, + paired_run_harness_files_for_archival: Optional[List[Path]] = None, + archive_logs_on_failure: bool = False, + joshua_output_dir: Optional[Path] = None, + run_temp_dir: Optional[Path] = None, + stats_attribute_for_v1: Optional[str] = None, + # Adding paths for current run's harness outputs for archival + current_run_stdout_path: Optional[Path] = None, + current_run_stderr_path: Optional[Path] = None, + current_run_command_file_path: Optional[Path] = None, + fdb_log_files_for_archival: Optional[List[Path]] = None # Already existed, just ensuring it's here ): self.binary = binary self.runtime: float = runtime self.max_rss: int | None = max_rss self.was_killed: bool = was_killed self.long_running = long_running + self.uid: uuid.UUID | None = uid + self.current_part_uid: uuid.UUID | None = current_part_uid self.expected_unseed: int | None = expected_unseed self.exit_code: int = exit_code - self.out: SummaryTree = SummaryTree("Test") + self.why: str | None = None + self.test_file: Path | None = None + self.seed: int | None = None + self.test_name: str | None = None + self.out: SummaryTree = SummaryTree("Test", is_root_document=False) self.test_begin_found: bool = False self.test_end_found: bool = False self.unseed: int | None = None self.valgrind_out_file: Path | None = valgrind_out_file + self.fdb_log_files_for_archival: Optional[List[Path]] = [] + if fdb_log_files_for_archival is not None: # Ensure it's initialized if passed + self.fdb_log_files_for_archival = fdb_log_files_for_archival + self.paired_run_fdb_logs_for_archival = paired_run_fdb_logs_for_archival + self.paired_run_harness_files_for_archival = paired_run_harness_files_for_archival + self.archive_logs_on_failure = archive_logs_on_failure + self.archival_references_added = False # Flag to indicate if archival tags were added + self._jod_for_archive = joshua_output_dir + self._rtd_for_archive = run_temp_dir + # Store current run's harness output paths + self.current_run_stdout_path = current_run_stdout_path + self.current_run_stderr_path = current_run_stderr_path + self.current_run_command_file_path = current_run_command_file_path self.severity_map: OrderedDict[tuple[str, int], int] = collections.OrderedDict() self.error: bool = False self.errors: int = 0 @@ -354,6 +501,13 @@ def __init__( self.negative_test_success = False self.max_trace_time = -1 self.max_trace_time_type = "None" + self.run_times_file_path = None + self.stats_file_path = None + if config.joshua_output_dir is not None: + joshua_output_path = Path(config.joshua_output_dir) + self.joshua_xml_file_path = joshua_output_path / "joshua.xml" + self.run_times_file_path = joshua_output_path / "run_times.json" + self.stats_file_path = joshua_output_path / "stats.json" if uid is not None: self.out.attributes["TestUID"] = str(uid) @@ -365,6 +519,75 @@ def __init__( self.handler = ParseHandler(self.out) self.register_handlers() + self._already_done = False + self.stats_attribute_for_v1 = stats_attribute_for_v1 + + # Event types that are handled by specific logic (e.g., setting top-level attributes, errors) + # and should generally not be duplicated as generic child elements by parse_generic_event_as_child. + # This list might need refinement. + INTERNALLY_HANDLED_EVENT_TYPES = { + "ProgramStart", # Data merged into top-level Test attributes + "ElapsedTime", # Data merged into top-level Test attributes, sets test_end_found + "SimulatorConfig", # Sets ConfigString attribute + "Simulation", # Sets TestFile attribute + "NonSimulationTest", # Sets TestFile attribute + "NegativeTestSuccess", # Sets self.negative_test_success, adds specific child + "TestsExpectedToPass", # Sets self.test_count + "TestResults", # Sets self.tests_passed + "RemapEventSeverity", # Modifies severity_map + "BuggifySection", # Adds specific child + "FaultInjected", # Adds specific child (often via BuggifySection handler) + "RunningUnitTest", # Adds specific child + "StderrSeverity", # Sets self.stderr_severity + "CodeCoverage", # Processed by coverage logic in done() + "UnseedMismatch", # Handled by set_elapsed_time, adds specific child + "FailureLogArchive", # Add this to prevent generic parsing if it ever appears as an event + # Generic "Error" and "Warning" are usually caught by Severity 40/30 handlers + # However, if an event has Type "FooError" and Severity 40, it will be caught by + # the Severity 40 handler AND potentially by the generic handler. + # The specific Severity 40 handler already creates a child with the event's original Type. + # So, we might not need to list explicit Error/Warning types here if their specific + # handlers (parse_error, parse_warning) correctly use the event's Type for the child tag. + } + + # For events that become children, ensure their 'Type' attribute is sanitized if used as a tag. + # This function is also used by the stderr parsing in done() + def _sanitize_event_type_for_xml_tag(self, type_str: str) -> str: + if not type_str: + return "GenericEvent" + # Replace non-alphanumeric (plus _, ., -) with underscore + sanitized = re.sub(r'[^a-zA-Z0-9_.-]', '_', type_str) + # Ensure it starts with a letter or underscore + if not re.match(r'^[a-zA-Z_]', sanitized): + sanitized = '_' + sanitized + return sanitized + + def parse_generic_event_as_child(self, attrs: Dict[str, str]): + event_type = attrs.get("Type") + if not event_type or event_type in self.INTERNALLY_HANDLED_EVENT_TYPES: + return + + # Check if a more specific handler (Severity 30/40) already created a similar child. + # This is a bit heuristic: if an error/warning child with this exact type already exists, skip. + # This aims to prevent duplicate children if, e.g., an event "MyCustomError" with Severity 40 + # was already added by the parse_error handler. + severity = attrs.get("Severity") + if severity in ["30", "40"]: + for child in self.out.children: + if child.name == event_type and child.attributes.get("Severity") == severity: + # Likely already handled by parse_warning or parse_error + # which use the original event Type as the tag name. + return + + tag_name = self._sanitize_event_type_for_xml_tag(event_type) + child = SummaryTree(tag_name) + for k, v_raw in attrs.items(): + # Add all attributes from the event. + # Convert value to string and escape for XML. Escape happens in SummaryTree.to_et_element() + v = str(v_raw) + child.attributes[str(k)] = v + self.out.append(child) + def summarize_files(self, trace_files: List[Path]): assert len(trace_files) > 0 @@ -372,169 +595,159 @@ def summarize_files(self, trace_files: List[Path]): self.parse_file(f) self.done() - def summarize(self, trace_dir: Path, command: str): - self.test_dir = trace_dir - trace_files = TraceFiles(trace_dir) - if len(trace_files) == 0: - self.error = True - child = SummaryTree("NoTracesFound") - child.attributes["Severity"] = "40" - child.attributes["Path"] = str(trace_dir.absolute()) - child.attributes["Command"] = command - self.out.append(child) - child = SummaryTree("Output") - child.attributes["StdErr"] = self.error_out - self.out.append(child) - return - self.summarize_files(trace_files[0]) - if config.joshua_dir is not None: - import test_harness.fdb - - test_harness.fdb.write_coverage( - config.cluster_file, - test_harness.fdb.str_to_tuple(config.joshua_dir) + ("coverage",), - test_harness.fdb.str_to_tuple(config.joshua_dir) - + ("coverage-metadata",), - self.coverage, - ) - - def list_simfdb(self) -> SummaryTree: - res = SummaryTree("SimFDB") - res.attributes["TestDir"] = str(self.test_dir) - if self.test_dir is None: - return res - simfdb = self.test_dir / Path("simfdb") - if not simfdb.exists(): - res.attributes["NoSimDir"] = "simfdb doesn't exist" - return res - elif not simfdb.is_dir(): - res.attributes["NoSimDir"] = "simfdb is not a directory" - return res - for file in simfdb.iterdir(): - child = SummaryTree("Directory" if file.is_dir() else "File") - child.attributes["Name"] = file.name - res.append(child) - return res - - def ok(self): - # logical xor -- a test is successful if there was either no error or we expected errors (negative test) - return (not self.error) != self.is_negative_test - - def done(self): - if config.print_coverage: - for k, v in self.coverage.items(): - child = SummaryTree("CodeCoverage") - child.attributes["File"] = k.file - child.attributes["Line"] = str(k.line) - child.attributes["Rare"] = k.rare - if not v: - child.attributes["Covered"] = "0" - if k.comment is not None and len(k.comment): - child.attributes["Comment"] = k.comment - self.out.append(child) - if self.warnings > config.max_warnings: - child = SummaryTree("WarningLimitExceeded") - child.attributes["Severity"] = "30" - child.attributes["WarningCount"] = str(self.warnings) - self.out.append(child) - if self.errors > config.max_errors: - child = SummaryTree("ErrorLimitExceeded") - child.attributes["Severity"] = "40" - child.attributes["ErrorCount"] = str(self.errors) - self.out.append(child) - self.error = True - if self.was_killed: - child = SummaryTree("ExternalTimeout") - child.attributes["Severity"] = "40" - if self.long_running: - # debugging info for long-running tests - child.attributes["LongRunning"] = "1" - child.attributes["Runtime"] = str(self.runtime) - self.out.append(child) - self.error = True - if self.max_rss is not None: - self.out.attributes["PeakMemory"] = str(self.max_rss) - if self.valgrind_out_file is not None: - try: - valgrind_errors = parse_valgrind_output(self.valgrind_out_file) - for valgrind_error in valgrind_errors: - if valgrind_error.kind.startswith("Leak"): - continue - self.error = True - child = SummaryTree("ValgrindError") - child.attributes["Severity"] = "40" - child.attributes["What"] = valgrind_error.what.what - child.attributes["Backtrace"] = valgrind_error.what.backtrace - aux_count = 0 - for aux in valgrind_error.aux: - child.attributes["WhatAux{}".format(aux_count)] = aux.what - child.attributes[ - "BacktraceAux{}".format(aux_count) - ] = aux.backtrace - aux_count += 1 - self.out.append(child) - except Exception as e: - self.error = True - child = SummaryTree("ValgrindParseError") - child.attributes["Severity"] = "40" - child.attributes["ErrorMessage"] = str(e) - _, _, exc_traceback = sys.exc_info() - child.attributes["Trace"] = repr(traceback.format_tb(exc_traceback)) - self.out.append(child) - if not self.test_end_found: - child = SummaryTree("TestUnexpectedlyNotFinished") - child.attributes["Severity"] = "40" - child.attributes["LastTraceTime"] = str(self.max_trace_time) - child.attributes["LastTraceType"] = self.max_trace_time_type - self.out.append(child) - self.error = True - if self.error_out is not None and len(self.error_out) > 0: - lines = self.error_out.splitlines() - stderr_bytes = 0 - for line in lines: - if line.endswith( - "WARNING: ASan doesn't fully support makecontext/swapcontext functions and may produce false positives in some cases!" - ): - # When running ASAN we expect to see this message. Boost coroutine should be using the correct asan annotations so that it shouldn't produce any false positives. - continue - if line.endswith("Warning: unimplemented fcntl command: 1036"): - # Valgrind produces this warning when F_SET_RW_HINT is used - continue - if self.stderr_severity == "40": - self.error = True - remaining_bytes = config.max_stderr_bytes - stderr_bytes - if remaining_bytes > 0: - out_err = line[0:remaining_bytes] + ( - "..." if len(line) > remaining_bytes else "" - ) - child = SummaryTree("StdErrOutput") - child.attributes["Severity"] = self.stderr_severity - child.attributes["Output"] = out_err - self.out.append(child) - stderr_bytes += len(line) - if stderr_bytes > config.max_stderr_bytes: - child = SummaryTree("StdErrOutputTruncated") - child.attributes["Severity"] = self.stderr_severity - child.attributes["BytesRemaining"] = str( - stderr_bytes - config.max_stderr_bytes - ) - self.out.append(child) + def summarize(self, temp_dir: Path | None, command: str): + logger.info(f"Summarize.summarize called for temp_dir: {temp_dir}, command: {command}") + if config.joshua_output_dir is not None: + joshua_output_path = Path(config.joshua_output_dir) + if not joshua_output_path.exists(): + try: + joshua_output_path.mkdir(parents=True, exist_ok=True) + except OSError as e: + logger.error(f"Could not create joshua output directory {joshua_output_path}: {e}") + # Not raising here, as we might still be able to produce some output + + if temp_dir is not None: # Update paths if they weren't set in init (e.g. fatal error before TestRun) + self.temp_dir = temp_dir # type: ignore + self.command_file_path = temp_dir / "command.txt" + self.stderr_file_path = temp_dir / "stderr.txt" + self.stdout_file_path = temp_dir / "stdout.txt" + # run_times and stats are tied to joshua_output_dir, not temp_dir for the run part + # self.run_times_file_path = temp_dir / "run_times.json" # This was incorrect + # self.stats_file_path = temp_dir / "stats.json" # This was incorrect + + self.command_line = command + if self.command_file_path: + with open(self.command_file_path, "w") as f: + f.write(command) + self.stderr = self._try_read_file(self.stderr_file_path, config.max_stderr_bytes) + self.stdout = self._try_read_file(self.stdout_file_path) + + if config.write_run_times and self.run_times_file_path: + self._write_run_times() + + if config.read_stats and self.stats_file_path: + self._read_stats() + + # Ensure done() is called to finalize error states, in case summarize_files wasn't called (no trace files) + if not self._already_done: + logger.info("Calling self.done() from summarize() as it wasn't called via summarize_files().") + self.done() + + # The actual XML generation happens here, using the state finalized by done() + self._generate_xml_summary() + + def _generate_xml_summary(self): + # This method should now primarily use self attributes that have been fully populated + # by event parsing and the self.done() method. + + self.out.attributes["TestUID"] = str(self.uid) if self.uid else "UNKNOWN_UID" + self.out.attributes["PartUID"] = str(self.current_part_uid) if self.current_part_uid else "UNKNOWN_PART_UID" + # Ok, Why, FailReason are set by self.done() + # Version is static + self.out.attributes["Version"] = CURRENT_VERSION + + if self.test_file: # Set by specific event handlers + self.out.attributes["TestFile"] = xml.sax.saxutils.escape(str(self.test_file)) + + # Attributes from ProgramStart event (already set on self.out.attributes by handler) + # self.out.attributes["RandomSeed"] -> already set if ProgramStart event occurred + # self.out.attributes["SourceVersion"] -> already set if ProgramStart + # self.out.attributes["Time"] -> (ActualTime from ProgramStart) already set + # self.out.attributes["BuggifyEnabled"] -> already set if ProgramStart + # self.out.attributes["FaultInjectionEnabled"] -> already set if ProgramStart + + # Attributes from SimulatorConfig event + # self.out.attributes["ConfigString"] -> already set if SimulatorConfig event occurred + + # Attributes from ElapsedTime event (already set on self.out.attributes by handler) + # self.out.attributes["SimElapsedTime"] -> already set if ElapsedTime event occurred + # self.out.attributes["RealElapsedTime"] -> already set if ElapsedTime event occurred + if self.test_end_found and self.unseed is not None: # unseed is set by ElapsedTime handler + self.out.attributes["RandomUnseed"] = str(self.unseed) + + if self.expected_unseed: # Passed in constructor + self.out.attributes["ExpectedUnseed"] = str(self.expected_unseed) + + # PeakMemory is set in done() and assigned to self.out.attributes there + # Runtime is set by TestRun, passed to Summary, then assigned in done() + # self.out.attributes["PeakMemory"] -> set in done() + # self.out.attributes["Runtime"] -> set in done() + + # Ok and FailReason are definitively set in done() + # self.out.attributes["Ok"] = "1" if self.ok() else "0" + # if not self.ok() and self.why: + # self.out.attributes["FailReason"] = self.why + # elif not self.ok(): + # self.out.attributes["FailReason"] = "Unknown" + + # Add information from the config that might be relevant (already present) + if config.joshua_output_dir: + self.out.attributes["JoshuaOutputDir"] = str(config.joshua_output_dir) + if config.run_temp_dir: + self.out.attributes["RunTempDir"] = str(config.run_temp_dir) + + # These are added as child elements if not already part of top-level attributes by specific handlers + # Ensure RandomSeed and TestName are added if not populated by ProgramStart/Simulation events + # However, ProgramStart handler sets RandomSeed. TestFile handler sets TestFile. + # TestName is set from test_file.stem in TestRun and passed to Summary. + # For V1 compatibility, these seem to be both attributes and children sometimes, or just attributes. + # The current logic: + # - Top-level (from ProgramStart) + # - Top-level (from Simulation/NonSimulationTest) + # - Child + # - Child + + # Let's ensure the child elements are present, as per prior logic + # but avoid adding them if the information is already a primary attribute + # from a specific event (like ProgramStart's RandomSeed). + + # The `program_start` handler sets self.out.attributes["RandomSeed"] + # The `set_test_file` handler sets self.out.attributes["TestFile"] + # `self.seed` and `self.test_name` are set by `TestRun` and passed to `Summary.__init__` + # `_generate_xml_summary` (original version) added child elements for these. + + # Let's stick to adding them as children if they aren't already top-level attributes, + # or if V1 style dictates they are *also* children. + # V1 example shows and - this is duplication. + # Let's prioritize top-level attributes from events, and add children only if necessary + # or if data isn't on top-level. + + # If self.seed (from TestRun) is available and not already set by ProgramStart on self.out + if self.seed is not None and "RandomSeed" not in self.out.attributes: + # This case should be rare if ProgramStart event exists + seed_element = SummaryTree("RandomSeed") + seed_element.attributes["Value"] = str(self.seed) + self.out.append(seed_element) + elif self.seed is not None and "RandomSeed" in self.out.attributes and str(self.out.attributes["RandomSeed"]) != str(self.seed): + # If ProgramStart RandomSeed differs from the initial seed, log/note it + logger.warning(f"Initial seed {self.seed} differs from ProgramStart event RandomSeed {self.out.attributes['RandomSeed']}") + # Potentially add the initial seed as a different named child if needed + # For now, ProgramStart event's seed takes precedence for the RandomSeed attribute. + + if self.test_name and "TestName" not in self.out.attributes: # TestName is not typically a direct event attribute + test_name_element = SummaryTree("TestName") + test_name_element.attributes["Value"] = xml.sax.saxutils.escape(self.test_name) + self.out.append(test_name_element) + + # The rest of self.out.children (generic events, errors, warnings) are added by their handlers. + # The overall attributes (Ok, FailReason, etc.) are finalized in done(). + # This method now just ensures the basic shell of self.out.attributes is there. + # The critical part is that `self.out.children` is populated by `parse_generic_event_as_child` + # and specific handlers, and `self.out.attributes` by specific handlers and `done()`. + + def _try_read_file(self, path: Path | None, max_len: int = -1) -> str: + if path is None or not path.exists(): + return "" + with open(path, "r") as f: + return f.read(max_len) + + def _write_run_times(self): + # Implementation of _write_run_times method + pass - self.out.attributes["Ok"] = "1" if self.ok() else "0" - self.out.attributes["Runtime"] = str(self.runtime) - if not self.ok(): - reason = "Unknown" - if self.error: - reason = "ProducedErrors" - elif not self.test_end_found: - reason = "TestDidNotFinish" - elif self.tests_passed == 0: - reason = "NoTestsPassed" - elif self.test_count != self.tests_passed: - reason = "Expected {} tests to pass, but only {} did".format( - self.test_count, self.tests_passed - ) - self.out.attributes["FailReason"] = reason + def _read_stats(self): + # Implementation of _read_stats method + pass def parse_file(self, file: Path): parser: Parser @@ -561,6 +774,8 @@ def parse_file(self, file: Path): child = SummaryTree("SummarizationError") child.attributes["Severity"] = "40" child.attributes["ErrorMessage"] = str(e) + _, _, exc_traceback = sys.exc_info() + child.attributes["Trace"] = repr(traceback.format_tb(exc_traceback)) self.out.append(child) def register_handlers(self): @@ -633,15 +848,29 @@ def set_test_file(attrs: Dict[str, str]): self.handler.add_handler(("Type", "NonSimulationTest"), set_test_file) def set_elapsed_time(attrs: Dict[str, str]): + logger.debug(f"set_elapsed_time called with attrs: {attrs}") # Log all attributes if self.test_end_found: + logger.debug("set_elapsed_time: test_end_found was already True, returning.") return self.test_end_found = True - self.unseed = int(attrs["RandomUnseed"]) + try: + self.unseed = int(attrs["RandomUnseed"]) + logger.debug(f"set_elapsed_time: self.unseed set to {self.unseed} from attrs['RandomUnseed']") + except KeyError: + logger.error(f"set_elapsed_time: 'RandomUnseed' key not found in ElapsedTime event attrs: {attrs}") + self.unseed = -1 # Or some other indicator of invalidity + except ValueError: + random_unseed_val = attrs.get("RandomUnseed") + logger.error(f"set_elapsed_time: Could not convert RandomUnseed '{random_unseed_val}' to int. Attrs: {attrs}") + self.unseed = -1 # Or some other indicator of invalidity + + logger.debug(f"set_elapsed_time: Checking for unseed mismatch. self.expected_unseed: {self.expected_unseed}, current self.unseed: {self.unseed}") if ( self.expected_unseed is not None and self.unseed != self.expected_unseed and self.unseed != -1 ): + logger.info(f"UnseedMismatch DETECTED. Expected: {self.expected_unseed}, Got: {self.unseed}") severity = ( 40 if ("UnseedMismatch", 40) not in self.severity_map @@ -654,7 +883,16 @@ def set_elapsed_time(attrs: Dict[str, str]): child.attributes["Severity"] = str(severity) if severity >= 40: self.error = True + self.why = "UnseedMismatch" + logger.info(f"UnseedMismatch (Severity {severity}) causing self.error = True and self.why = \"UnseedMismatch\"") + else: + logger.info(f"UnseedMismatch (Severity {severity}) NOT causing self.error = True (severity < 40)") self.out.append(child) + else: + logger.info(f"UnseedMismatch severity {severity} is < 30, not adding XML child or setting error.") + elif self.expected_unseed is not None: + logger.debug(f"set_elapsed_time: No UnseedMismatch. Conditions: expected_unseed_is_None={self.expected_unseed is None}, unseed_equals_expected={self.unseed == self.expected_unseed}, unseed_is_-1={self.unseed == -1}") + self.out.attributes["SimElapsedTime"] = attrs["SimTime"] self.out.attributes["RealElapsedTime"] = attrs["RealTime"] if self.unseed is not None: @@ -748,3 +986,272 @@ def stderr_severity(attrs: Dict[str, str]): self.stderr_severity = attrs["NewSeverity"] self.handler.add_handler(("Type", "StderrSeverity"), stderr_severity) + + # Add the generic event handler - should be processed for events not caught by specific handlers above. + # The ParseHandler.handle logic might need adjustment if order of add_handler matters greatly + # for preventing double processing. For now, parse_generic_event_as_child has internal skip logic. + self.handler.add_handler(None, self.parse_generic_event_as_child) + + def done(self): + if self._already_done: + logger.debug("Summary.done() called again, skipping.") + return + self._already_done = True + + if self.test_begin_found and not self.test_end_found and not self.was_killed: + logger.warning( + f"Test {self.test_name} (UID: {self.uid}, PartUID: {self.current_part_uid}) started but did not finish. Exit code: {self.exit_code}. Marking as error." + ) + self.error = True + if "FailReason" not in self.out.attributes: + self.out.attributes["FailReason"] = "TestDidNotFinish" + + if self.exit_code != 0 and not self.error and not self.was_killed and not self.is_negative_test: + logger.warning( + f"Test {self.test_name} (UID: {self.uid}, PartUID: {self.current_part_uid}) had non-zero exit code {self.exit_code} but no error reported. Marking as error." + ) + self.error = True + if "FailReason" not in self.out.attributes: + self.out.attributes["FailReason"] = "NonZeroExitCodeNoError" + + if self.was_killed: + self.error = True + self.out.attributes["Killed"] = "1" + if "FailReason" not in self.out.attributes: + self.out.attributes["FailReason"] = "TestKilled" + + # New: Check for stderr output if no other error reported yet and exit code was 0 for a positive test + if not self.error and not self.is_negative_test and self.exit_code == 0 and \ + self.error_out and len(self.error_out.strip()) > 0: + logger.warning( + f"Test {self.test_name} (UID: {self.uid}, PartUID: {self.current_part_uid}) " + f"had exit code 0 but produced stderr output. Marking as error. Stderr: {self.error_out[:200]}" + ) + self.error = True + if "FailReason" not in self.out.attributes: + self.out.attributes["FailReason"] = "StdErrOutputWithZeroExit" + # Also ensure 'Ok' is set to '0' for the attribute logic that follows + self.out.attributes["Ok"] = "0" + + if self.error: + if self.is_negative_test: + self.negative_test_success = True + self.out.attributes["NegativeTestSuccess"] = "1" + else: + self.out.attributes["Ok"] = "0" + else: + if self.is_negative_test: + self.negative_test_success = False + self.out.attributes["Ok"] = "0" + if "FailReason" not in self.out.attributes: + self.out.attributes["FailReason"] = "NegativeTestDidNotFail" + else: + self.out.attributes["Ok"] = "1" + self.tests_passed += 1 + self.test_count += 1 + + if self.valgrind_out_file is not None and self.valgrind_out_file.exists(): + errors = parse_valgrind_output(self.valgrind_out_file) + if len(errors) > 0: + self.error = True + self.out.attributes["Ok"] = "0" + if "FailReason" not in self.out.attributes: + self.out.attributes["FailReason"] = "ValgrindErrors" + valgrind_summary = SummaryTree("ValgrindError") + for error in errors: + valgrind_summary.children.append(SummaryTree(error)) + self.out.append(valgrind_summary) + + if self.error_out is not None and len(self.error_out) > 0 and self.stderr_severity != "0": + if len(self.error_out) > config.max_stderr_bytes: + self.out.append( + SummaryTree( + "StdErrOutputTruncated", + attributes={"Bytes": str(config.max_stderr_bytes)}, + ) + ) + self.out.append( + SummaryTree( + "StdErrOutput", + attributes={"Content": self.error_out[0 : config.max_stderr_bytes]}, + ) + ) + else: + self.out.append( + SummaryTree("StdErrOutput", attributes={"Content": self.error_out}) + ) + + if config.write_run_times and self.test_name is not None: + # ... existing code ... + pass + + if config.print_coverage: + for k, v in self.coverage.items(): + child = SummaryTree("CodeCoverage") + child.attributes["File"] = k.file + child.attributes["Line"] = str(k.line) + child.attributes["Rare"] = k.rare + if not v: + child.attributes["Covered"] = "0" + if k.comment is not None and len(k.comment): + child.attributes["Comment"] = k.comment + self.out.append(child) + if self.warnings > config.max_warnings: + child = SummaryTree("WarningLimitExceeded") + child.attributes["Severity"] = "30" + child.attributes["WarningCount"] = str(self.warnings) + self.out.append(child) + if self.errors > config.max_errors: + child = SummaryTree("ErrorLimitExceeded") + child.attributes["Severity"] = "40" + child.attributes["ErrorCount"] = str(self.errors) + self.out.append(child) + self.error = True + if self.max_rss is not None: + self.out.attributes["PeakMemory"] = str(self.max_rss) + + # Add Runtime attribute, formatting to match V1 example if possible + if self.runtime is not None: + # V1 example shows many decimal places, e.g., "16.95333433151245" + # Using a general float to string conversion, can be refined if specific precision is critical. + self.out.attributes["Runtime"] = str(self.runtime) # Format as float string + + # Final determination of Ok and FailReason for the top-level attributes + # This was previously in _generate_xml_summary, but makes more sense here after all error checks + current_ok_status = self.ok() # Call ok() once after all self.error updates + self.out.attributes["Ok"] = "1" if current_ok_status else "0" + if not current_ok_status: + final_reason = self.why # Use reason determined by the error logic + if not final_reason: # Fallbacks, though self.why should ideally be set + if self.error: + final_reason = "ProducedErrors" + elif not self.test_end_found and (self.exit_code is None or self.exit_code == 0): + final_reason = "TestDidNotFinish" + elif self.tests_passed == 0 and self.test_count > 0: + final_reason = "NoTestsPassed" + elif self.test_count != self.tests_passed: + final_reason = "Expected {} tests to pass, but only {} did".format( + self.test_count, self.tests_passed + ) + else: + final_reason = "Unknown" + self.out.attributes["FailReason"] = final_reason + elif "FailReason" in self.out.attributes: # Clean up FailReason if test is Ok + del self.out.attributes["FailReason"] + + if self.archive_logs_on_failure and not self.ok(): # self.ok() reflects the final status + logger.info(f"Test part {self.current_part_uid} (TestUID: {self.uid}, Name: {self.test_name}) failed and archive_logs_on_failure is True. Adding log location tags to summary.") + self.archival_references_added = True # Set flag + + if self._rtd_for_archive and self._rtd_for_archive.exists(): + log_dir_elem = SummaryTree("FDBClusterLogDir") + log_dir_elem.attributes["path"] = str(self._rtd_for_archive.resolve()) + self.out.append(log_dir_elem) + + if self.current_run_stdout_path and self.current_run_stdout_path.exists(): + stdout_elem = SummaryTree("HarnessLogFile") + stdout_elem.attributes["type"] = "stdout" + stdout_elem.attributes["path"] = str(self.current_run_stdout_path.resolve()) + self.out.append(stdout_elem) + + if self.current_run_stderr_path and self.current_run_stderr_path.exists(): + stderr_elem = SummaryTree("HarnessLogFile") + stderr_elem.attributes["type"] = "stderr" + stderr_elem.attributes["path"] = str(self.current_run_stderr_path.resolve()) + self.out.append(stderr_elem) + + if self.current_run_command_file_path and self.current_run_command_file_path.exists(): + cmd_elem = SummaryTree("HarnessLogFile") + cmd_elem.attributes["type"] = "command" + cmd_elem.attributes["path"] = str(self.current_run_command_file_path.resolve()) + self.out.append(cmd_elem) + + if self.fdb_log_files_for_archival: + for log_file_path in self.fdb_log_files_for_archival: + if log_file_path.exists(): + fdb_file_elem = SummaryTree("FDBLogFile") + fdb_file_elem.attributes["path"] = str(log_file_path.resolve()) + self.out.append(fdb_file_elem) + + if self._jod_for_archive and self._jod_for_archive.exists(): + jod_elem = SummaryTree("JoshuaOutputDirRef") + jod_elem.attributes["path"] = str(self._jod_for_archive.resolve()) + self.out.append(jod_elem) + + self._already_done = True # Mark as done + + def ok(self): + # logical xor -- a test is successful if there was either no error or we expected errors (negative test) + return (not self.error) != self.is_negative_test + + def get_v1_stdout_line(self) -> Optional[str]: + if not self._already_done: # Ensure done() has run to determine ok() status and archival_references_added + logger.warning("get_v1_stdout_line called before self.done(). Finalizing summary state.") + self.done() + + if not hasattr(self, 'out') or not self.out or self.out.name != "Test": + logger.error("get_v1_stdout_line: self.out is not a valid 'Test' SummaryTree.") + return '' + + logger.debug(f"Generating V1 stdout line for TestUID: {self.uid}, PartUID: {self.current_part_uid} - Attempting to include essential V1 child elements and specific attributes.") + + if not self._already_done: + logger.warning("get_v1_stdout_line called before self.done(). Finalizing summary state.") + self.done() # self.done() populates self.out.attributes, including PeakMemory and Runtime from self.max_rss and self.runtime + + v1_test_element = ET.Element("Test") + + # Copy all attributes from the main summary's element + for k, v in self.out.attributes.items(): + v1_test_element.set(k, v) + + # Explicitly set/override specific attributes for V1 stdout compatibility + # Runtime: Use the value from self.runtime (populated by TestRun from process stats) + if self.runtime is not None: + v1_test_element.set("Runtime", str(self.runtime)) + elif "Runtime" not in v1_test_element.attrib: # Fallback if self.runtime was None but we need the attr + v1_test_element.set("Runtime", "0") + + # PeakMemory: Use the value from self.max_rss (populated by TestRun from process stats) + if self.max_rss is not None: + v1_test_element.set("PeakMemory", str(self.max_rss)) + elif "PeakMemory" not in v1_test_element.attrib: + v1_test_element.set("PeakMemory", "0") + + # TestRunCount: Set to "1" for a single test stdout line + v1_test_element.set("TestRunCount", "1") + + # TotalTestTime: Use RealElapsedTime (if available) converted to int, as an approximation of V1's TotalTestTime + real_et_str = self.out.attributes.get("RealElapsedTime") + if real_et_str is not None: + try: + total_test_time_val = str(int(float(real_et_str))) + v1_test_element.set("TotalTestTime", total_test_time_val) + except ValueError: + logger.warning(f"Could not convert RealElapsedTime ('{real_et_str}') to int for TotalTestTime for V1 stdout.") + elif "TotalTestTime" not in v1_test_element.attrib: # Fallback if RealElapsedTime missing + v1_test_element.set("TotalTestTime", "0") + + # Statistics attribute (special handling as before) + if self.stats_attribute_for_v1: + v1_test_element.set("Statistics", self.stats_attribute_for_v1) + + # Add essential child elements (logic from previous step) + for child_summary_tree in self.out.children: + if child_summary_tree.name in ESSENTIAL_V1_CHILD_TAGS_TO_KEEP and \ + child_summary_tree.name not in STDOUT_EXPLICITLY_STRIPPED_TAGS: + try: + child_et_element = child_summary_tree.to_et_element() + v1_test_element.append(child_et_element) + logger.debug(f"Included child element '{child_summary_tree.name}' in V1 stdout.") + except Exception as e_child_conversion: + logger.error(f"Error converting or appending child '{child_summary_tree.name}' for V1 stdout: {e_child_conversion}", exc_info=True) + + try: + v1_xml_string = ET.tostring(v1_test_element, encoding='unicode', method='xml', short_empty_elements=True) + final_xml_output = v1_xml_string.strip() + logger.debug(f"Generated V1 stdout XML (with children and explicit V1 attrs): {final_xml_output}") + return final_xml_output + except Exception as e_tostring: + logger.error(f"get_v1_stdout_line: Failed to serialize test element (with children and V1 attrs): {e_tostring}", exc_info=True) + return ''.format(self.current_part_uid if self.current_part_uid else "UNKNOWN_PART_UID")