diff --git a/.github/workflows/generate_reference_results_workflow.yml b/.github/workflows/generate_reference_results_workflow.yml index 4665d8e2a..30983dd7e 100644 --- a/.github/workflows/generate_reference_results_workflow.yml +++ b/.github/workflows/generate_reference_results_workflow.yml @@ -92,7 +92,7 @@ jobs: fi git commit -m "${{inputs.commit_msg}}" git push - - name: Archive main log files + - name: Archive system test logs if: ${{ always() }} uses: actions/upload-artifact@v7 with: @@ -100,6 +100,9 @@ jobs: path: | runs/*/system-tests-stdout.log runs/*/system-tests-stderr.log + runs/*/system-tests-build.log + runs/*/system-tests-run.log + runs/*/system-tests-compare.log runs/*/*/system-tests_*.log - name: Archive run files if: failure() diff --git a/.github/workflows/run_testsuite_workflow.yml b/.github/workflows/run_testsuite_workflow.yml index fde53977f..c3178fd65 100644 --- a/.github/workflows/run_testsuite_workflow.yml +++ b/.github/workflows/run_testsuite_workflow.yml @@ -78,7 +78,7 @@ jobs: cd tools/tests python systemtests.py --build_args=${{ inputs.build_args}} --suites=${{ inputs.suites}} --log-level=${{ inputs.log_level}} cd ../../ - - name: Archive main log files + - name: Archive system test logs if: ${{ always() }} uses: actions/upload-artifact@v7 with: @@ -86,6 +86,9 @@ jobs: path: | runs/*/system-tests-stdout.log runs/*/system-tests-stderr.log + runs/*/system-tests-build.log + runs/*/system-tests-run.log + runs/*/system-tests-compare.log runs/*/*/system-tests_*.log - name: Archive run files if: ${{ failure() || inputs.upload_artifacts == 'TRUE' }} diff --git a/changelog-entries/801.md b/changelog-entries/801.md new file mode 100644 index 000000000..745806f4a --- /dev/null +++ b/changelog-entries/801.md @@ -0,0 +1 @@ +- System tests now write logs during each run (build, run, compare), including `system-tests-build.log`, `system-tests-run.log`, and `system-tests-compare.log` [#801](https://github.com/precice/tutorials/pull/801). diff --git a/tools/tests/README.md b/tools/tests/README.md index 8a7df6e20..6f7e6cabf 100644 --- a/tools/tests/README.md +++ b/tools/tests/README.md @@ -36,7 +36,7 @@ Workflow for the preCICE v3 release testing: 6. Download the build artifacts from Summary > runs. - - In there, you may want to check the `system-tests-stdout.log` and `system-tests-stderr.log` files. + - In there, inspect the combined logs (`system-tests-stdout.log`, `system-tests-stderr.log`) and the per-stage logs (`system-tests-build.log`, `system-tests-run.log`, `system-tests-compare.log`). - The produced results are in `precice-exports/`, the reference results in `reference-results-unpacked`. - Compare using, e.g., ParaView or [fieldcompare](https://gitlab.com/dglaeser/fieldcompare): `fieldcompare dir precice-exports/ reference/`. The `--diff` option will give you `precice-exports/diff_*.vtu` files, while you can also try different tolerances with `-rtol` and `-atol`. @@ -105,7 +105,7 @@ In this case, building and running seems to work out, but the tests fail because The easiest way to debug a systemtest run is first to have a look at the output written into the action on GitHub. If this does not provide enough hints, the next step is to download the generated `system_tests_run__` artifact. Note that by default this will only be generated if the systemtests fail. -Inside the archive, a test-specific subfolder like `flow-over-heated-plate_fluid-openfoam-solid-fenics_2023-11-19-211723` contains two log files: `system-tests-stderr.log` and `system-tests-stdout.log`. This can be a starting point for a further investigation. When fieldcompare runs with `--diff`, it writes VTK (.vtu) diff files under `precice-exports/`; if the comparison fails, those files are copied into a `diff-results/` subfolder in the same run directory (mirroring any subpaths under `precice-exports/`) so you can open them (e.g. in ParaView) to see where results differ from the reference. On successful comparisons, `diff-results/` is therefore absent. +Inside the archive, a test-specific subfolder like `flow-over-heated-plate_fluid-openfoam-solid-fenics_2023-11-19-211723` contains combined logs (`system-tests-stderr.log`, `system-tests-stdout.log`) and per-stage logs (`system-tests-build.log`, `system-tests-run.log`, `system-tests-compare.log`). These are a good starting point for further investigation. When fieldcompare runs with `--diff`, it writes VTK (.vtu) diff files under `precice-exports/`; if the comparison fails, those files are copied into a `diff-results/` subfolder in the same run directory (mirroring any subpaths under `precice-exports/`) so you can open them (e.g. in ParaView) to see where results differ from the reference. On successful comparisons, `diff-results/` is therefore absent. ## Adding new tests diff --git a/tools/tests/systemtests.py b/tools/tests/systemtests.py index 6debe18d0..42d695a84 100644 --- a/tools/tests/systemtests.py +++ b/tools/tests/systemtests.py @@ -7,9 +7,20 @@ from metadata_parser.metdata import Tutorials, Case import logging import time +import os +import sys from paths import PRECICE_TUTORIAL_DIR, PRECICE_TESTS_RUN_DIR, PRECICE_TESTS_DIR +class _ConsoleLogFormatter(logging.Formatter): + """Omit level prefix for INFO/DEBUG; keep it for warnings and errors.""" + + def format(self, record: logging.LogRecord) -> str: + if record.levelno >= logging.WARNING: + return f"{record.levelname}: {record.getMessage()}" + return record.getMessage() + + def main(): parser = argparse.ArgumentParser(description='systemtest') @@ -29,12 +40,30 @@ def main(): # Parse the command-line arguments args = parser.parse_args() - # Configure logging based on the provided log level - logging.basicConfig(level=args.log_level, format='%(levelname)s: %(message)s') + # Configure logging + handler = logging.StreamHandler() + handler.setFormatter(_ConsoleLogFormatter()) + logging.basicConfig(level=args.log_level, handlers=[handler]) + + gh_actions = os.environ.get("GITHUB_ACTIONS", "").lower() == "true" + # Skip ANSI colors when TERM is unset or "dumb" (minimal terminal, common in CI). + ansi_colors = sys.stdout.isatty() and os.environ.get("TERM", "") not in {"", "dumb"} + + def _style(text: str, color_code: int | None) -> str: + if not ansi_colors or color_code is None: + return text + return f"\x1b[{color_code}m{text}\x1b[0m" + + def _group_start(title: str) -> None: + if gh_actions: + print(f"::group::{title}", flush=True) - print(f"Using log-level: {args.log_level}") + def _group_end() -> None: + if gh_actions: + print("::endgroup::", flush=True) systemtests_to_run = [] + test_suites_to_execute = [] available_tutorials = Tutorials.from_path(PRECICE_TUTORIAL_DIR) build_args = SystemtestArguments.from_args(args.build_args) @@ -43,7 +72,6 @@ def main(): test_suites_requested = args.suites.split(',') available_testsuites = TestSuites.from_yaml( PRECICE_TESTS_DIR / "tests.yaml", available_tutorials) - test_suites_to_execute = [] for test_suite_requested in test_suites_requested: test_suite_found = available_testsuites.get_by_name( test_suite_requested) @@ -72,17 +100,47 @@ def main(): if not systemtests_to_run: raise RuntimeError("Did not find any Systemtests to execute.") - logging.info(f"About to run the following systemtest in the directory {run_directory}:\n {systemtests_to_run}") + total = len(systemtests_to_run) + + if test_suites_to_execute: + print("Selected test suite(s):", flush=True) + print(flush=True) + for test_suite in test_suites_to_execute: + print(f"- {test_suite.name}", flush=True) + print(flush=True) + + print(f"About to run {total} test(s) in the directory {run_directory}:", flush=True) + print(flush=True) + for number, systemtest in enumerate(systemtests_to_run, start=1): + print(f"{number}. {systemtest}", flush=True) + print(flush=True) + print(f"Using log-level: {args.log_level}", flush=True) results = [] for number, systemtest in enumerate(systemtests_to_run, start=1): - logging.info(f"Started running {systemtest}, {number}/{len(systemtests_to_run)}") - t = time.perf_counter() - result = systemtest.run(run_directory) - elapsed_time = time.perf_counter() - t - logging.info(f"Running {systemtest} took {elapsed_time:^.1f} seconds") + print(flush=True) + started_header = f"[{number}/{total}] Started {systemtest}" + _group_start(started_header) + try: + if not gh_actions: + logging.info(started_header) + t = time.perf_counter() + result = systemtest.run(run_directory) + elapsed_time = time.perf_counter() - t + + if result.success: + status_label = _style("✅ PASS", 32) + else: + status_label = _style("❌ FAIL", 31) + finally: + _group_end() + + print(f"{status_label} Finished {systemtest} in {elapsed_time:.1f}s", flush=True) + print(f"[{number}/{total}] {systemtest}", flush=True) + print(flush=True) results.append(result) + print(flush=True) system_test_success = True for result in results: if not result.success: diff --git a/tools/tests/systemtests/Systemtest.py b/tools/tests/systemtests/Systemtest.py index de9fab864..cbee71c4e 100644 --- a/tools/tests/systemtests/Systemtest.py +++ b/tools/tests/systemtests/Systemtest.py @@ -1,4 +1,5 @@ import subprocess +import threading from typing import List, Dict, Optional, Tuple from jinja2 import Environment, FileSystemLoader from dataclasses import dataclass, field @@ -24,6 +25,46 @@ DIFF_RESULTS_DIR = "diff-results" +COMBINED_STDOUT_LOG = "system-tests-stdout.log" +COMBINED_STDERR_LOG = "system-tests-stderr.log" +STAGE_LOG_FILES = { + "build": "system-tests-build.log", + "run": "system-tests-run.log", + "compare": "system-tests-compare.log", +} + + +class _SystemtestLogSink: + """Writes subprocess output incrementally to combined and stage log files.""" + + def __init__(self, system_test_dir: Path): + self._system_test_dir = system_test_dir + self._lock = threading.Lock() + self._stdout_path = system_test_dir / COMBINED_STDOUT_LOG + self._stderr_path = system_test_dir / COMBINED_STDERR_LOG + self._stdout_path.write_text("", encoding="utf-8") + self._stderr_path.write_text("", encoding="utf-8") + + def begin_stage(self, stage: str) -> None: + stage_path = self._system_test_dir / STAGE_LOG_FILES[stage] + stage_path.write_text(f"=== {stage} ===\n", encoding="utf-8") + + def append_stdout(self, line: str, stage: str) -> None: + with self._lock: + with self._stdout_path.open("a", encoding="utf-8") as log_file: + log_file.write(line + "\n") + stage_path = self._system_test_dir / STAGE_LOG_FILES[stage] + with stage_path.open("a", encoding="utf-8") as log_file: + log_file.write(line + "\n") + + def append_stderr(self, line: str, stage: str) -> None: + with self._lock: + with self._stderr_path.open("a", encoding="utf-8") as log_file: + log_file.write(line + "\n") + stage_path = self._system_test_dir / STAGE_LOG_FILES[stage] + with stage_path.open("a", encoding="utf-8") as log_file: + log_file.write(f"[stderr] {line}\n") + def slugify(value, allow_unicode=False): """ @@ -76,17 +117,23 @@ class SystemtestResult: fieldcompare_time: float # in seconds +def _success_status_symbol(success: bool) -> str: + return "✅" if success else "❌" + + def display_systemtestresults_as_table(results: List[SystemtestResult]): """ Prints the result in a nice tabluated way to get an easy overview """ + print() + def _get_length_of_name(results: List[SystemtestResult]) -> int: return max(len(str(result.systemtest)) for result in results) max_name_length = _get_length_of_name(results) header = f"| {'systemtest':<{max_name_length + 2}} "\ - f"| {'success':^7} "\ + f"| {'status':^7} "\ f"| {'building time [s]':^17} "\ f"| {'solver time [s]':^15} "\ f"| {'fieldcompare time [s]':^21} |" @@ -105,7 +152,7 @@ def _get_length_of_name(results: List[SystemtestResult]) -> int: for result in results: row = f"| {str(result.systemtest):<{max_name_length + 2}} "\ - f"| {result.success:^7} "\ + f"| {_success_status_symbol(result.success):^7} "\ f"| {result.build_time:^17.1f} "\ f"| {result.solver_time:^15.1f} "\ f"| {result.fieldcompare_time:^21.1f} |" @@ -119,7 +166,7 @@ def _get_length_of_name(results: List[SystemtestResult]) -> int: with open(os.environ["GITHUB_STEP_SUMMARY"], "a") as f: print("\n\n", file=f) print( - "In case a test fails, download the archive from the bottom of this page and look into each `system-tests-stdout.log` and `system-tests-stderr.log`. The time spent in each step might already give useful hints.", + "In case a test fails, download the archive from the bottom of this page and inspect the combined logs (`system-tests-stdout.log`, `system-tests-stderr.log`) and the per-stage logs (`system-tests-build.log`, `system-tests-run.log`, `system-tests-compare.log`). The stage runtimes might already give useful hints.", file=f) print( "See the [documentation](https://precice.org/dev-docs-system-tests.html#understanding-what-went-wrong).", @@ -399,6 +446,94 @@ def __unpack_reference_results(self) -> Tuple[bool, str]: logging.error(error_message) return False, error_message + def __init_run_logs(self) -> None: + self._log_sink = _SystemtestLogSink(self.system_test_dir) + + def _run_docker_compose_subprocess( + self, + command: List[str], + stage: str, + timeout: int, + ) -> Tuple[int, List[str], List[str]]: + """ + Run a docker compose command, streaming stdout/stderr to log files as they arrive. + """ + stdout_data: List[str] = [] + stderr_data: List[str] = [] + log_sink = getattr(self, "_log_sink", None) + if log_sink is not None: + log_sink.begin_stage(stage) + logging.info(f"Docker compose {stage} for {self}") + + try: + process = subprocess.Popen( + command, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + text=True, + bufsize=1, + start_new_session=True, + cwd=self.system_test_dir, + ) + except Exception as e: + logging.critical(f"Error starting docker compose {stage} command: {e}") + return 1, stdout_data, stderr_data + + def read_stream(stream, is_stderr: bool) -> None: + if stream is None: + return + for line in stream: + line = line.rstrip("\n\r") + if is_stderr: + stderr_data.append(line) + if log_sink is not None: + log_sink.append_stderr(line, stage) + else: + stdout_data.append(line) + if log_sink is not None: + log_sink.append_stdout(line, stage) + stream.close() + + stdout_thread = threading.Thread( + target=read_stream, args=(process.stdout, False), daemon=True) + stderr_thread = threading.Thread( + target=read_stream, args=(process.stderr, True), daemon=True) + stdout_thread.start() + stderr_thread.start() + + try: + exit_code = process.wait(timeout=timeout) + except KeyboardInterrupt as k: + process.kill() + stdout_thread.join(timeout=SHORT_TIMEOUT) + stderr_thread.join(timeout=SHORT_TIMEOUT) + raise KeyboardInterrupt from k + except subprocess.TimeoutExpired: + logging.critical( + f"Systemtest {self} timed out during docker compose {stage} " + f"after {timeout}s. Killing the process.") + process.kill() + try: + process.wait(timeout=SHORT_TIMEOUT) + except subprocess.TimeoutExpired: + pass + exit_code = process.returncode if process.returncode is not None else 1 + except Exception as e: + logging.critical( + f"Systemtest {self} had serious issues during docker compose {stage}: {e}") + process.kill() + try: + process.wait(timeout=SHORT_TIMEOUT) + except subprocess.TimeoutExpired: + pass + exit_code = process.returncode if process.returncode is not None else 1 + + stdout_thread.join(timeout=SHORT_TIMEOUT) + stderr_thread.join(timeout=SHORT_TIMEOUT) + if exit_code is None: + exit_code = process.poll() or 1 + return exit_code, stdout_data, stderr_data + def _cleanup_docker_networks(self): """ Prunes the unused Docker networks, since there is an upper limit on the number of custom networks defined. @@ -439,47 +574,31 @@ def _run_field_compare(self): time_start = time.perf_counter() unpack_success, unpack_error_message = self.__unpack_reference_results() if not unpack_success: + log_sink = getattr(self, "_log_sink", None) + if log_sink is not None: + log_sink.begin_stage("compare") + log_sink.append_stderr(unpack_error_message, "compare") elapsed_time = time.perf_counter() - time_start return FieldCompareResult(1, [], [unpack_error_message], self, elapsed_time) docker_compose_content = self.__get_field_compare_compose_file() - stdout_data = [] - stderr_data = [] with open(self.system_test_dir / "docker-compose.field_compare.yaml", 'w') as file: file.write(docker_compose_content) - try: - # Execute docker-compose command - process = subprocess.Popen(['docker', - 'compose', - '--file', - 'docker-compose.field_compare.yaml', - 'up', - '--exit-code-from', - 'field-compare'], - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - start_new_session=True, - cwd=self.system_test_dir) - - try: - stdout, stderr = process.communicate(timeout=self.timeout) - except KeyboardInterrupt as k: - process.kill() - raise KeyboardInterrupt from k - except Exception as e: - logging.critical( - f"Systemtest {self} had serious issues executing the docker compose command about to kill the docker compose command. Please check the logs! {e}") - process.kill() - process.communicate(timeout=SHORT_TIMEOUT) - stdout_data.extend(stdout.decode().splitlines()) - stderr_data.extend(stderr.decode().splitlines()) - process.poll() - elapsed_time = time.perf_counter() - time_start - return FieldCompareResult(process.returncode, stdout_data, stderr_data, self, elapsed_time) - except Exception as e: - logging.CRITICAL("Error executing docker compose command:", e) - elapsed_time = time.perf_counter() - time_start - return FieldCompareResult(1, stdout_data, stderr_data, self, elapsed_time) + exit_code, stdout_data, stderr_data = self._run_docker_compose_subprocess( + [ + 'docker', + 'compose', + '--file', + 'docker-compose.field_compare.yaml', + 'up', + '--exit-code-from', + 'field-compare', + ], + "compare", + self.timeout, + ) + elapsed_time = time.perf_counter() - time_start + return FieldCompareResult(exit_code, stdout_data, stderr_data, self, elapsed_time) def __archive_fieldcompare_diffs(self) -> None: """ @@ -531,41 +650,20 @@ def _build_docker(self): with open(self.system_test_dir / "docker-compose.tutorial.yaml", 'w') as file: file.write(docker_compose_content) - stdout_data = [] - stderr_data = [] - - try: - # Execute docker-compose command - process = subprocess.Popen(['docker', - 'compose', - '--file', - 'docker-compose.tutorial.yaml', - 'build'], - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - start_new_session=True, - cwd=self.system_test_dir) - - try: - stdout, stderr = process.communicate(timeout=GLOBAL_TIMEOUT) - except KeyboardInterrupt as k: - process.kill() - # process.send_signal(9) - raise KeyboardInterrupt from k - except Exception as e: - logging.critical( - f"systemtest {self} had serious issues building the docker images via the `docker compose build` command. About to kill the docker compose command. Please check the logs! {e}") - process.communicate(timeout=SHORT_TIMEOUT) - process.kill() - - stdout_data.extend(stdout.decode().splitlines()) - stderr_data.extend(stderr.decode().splitlines()) - elapsed_time = time.perf_counter() - time_start - return DockerComposeResult(process.returncode, stdout_data, stderr_data, self, elapsed_time) - except Exception as e: - logging.critical(f"Error executing docker compose build command: {e}") - elapsed_time = time.perf_counter() - time_start - return DockerComposeResult(1, stdout_data, stderr_data, self, elapsed_time) + exit_code, stdout_data, stderr_data = self._run_docker_compose_subprocess( + [ + 'docker', + 'compose', + '--progress=plain', + '--file', + 'docker-compose.tutorial.yaml', + 'build', + ], + "build", + GLOBAL_TIMEOUT, + ) + elapsed_time = time.perf_counter() - time_start + return DockerComposeResult(exit_code, stdout_data, stderr_data, self, elapsed_time) def _run_tutorial(self): """ @@ -576,49 +674,27 @@ def _run_tutorial(self): """ logging.debug(f"Running tutorial {self}") time_start = time.perf_counter() - stdout_data = [] - stderr_data = [] - try: - # Execute docker-compose command - process = subprocess.Popen(['docker', - 'compose', - '--file', - 'docker-compose.tutorial.yaml', - 'up'], - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - start_new_session=True, - cwd=self.system_test_dir) - - try: - stdout, stderr = process.communicate(timeout=self.timeout) - except KeyboardInterrupt as k: - process.kill() - # process.send_signal(9) - raise KeyboardInterrupt from k - except Exception as e: - logging.critical( - f"Systemtest {self} had serious issues executing the docker compose command about to kill the docker compose command. Please check the logs! {e}") - process.kill() - stdout, stderr = process.communicate(timeout=SHORT_TIMEOUT) - process.kill() - - stdout_data.extend(stdout.decode().splitlines()) - stderr_data.extend(stderr.decode().splitlines()) - elapsed_time = time.perf_counter() - time_start - return DockerComposeResult(process.returncode, stdout_data, stderr_data, self, elapsed_time) - except Exception as e: - logging.critical(f"Error executing docker compose up command: {e}") - elapsed_time = time.perf_counter() - time_start - return DockerComposeResult(1, stdout_data, stderr_data, self, elapsed_time) + exit_code, stdout_data, stderr_data = self._run_docker_compose_subprocess( + [ + 'docker', + 'compose', + '--file', + 'docker-compose.tutorial.yaml', + 'up', + ], + "run", + self.timeout, + ) + elapsed_time = time.perf_counter() - time_start + return DockerComposeResult(exit_code, stdout_data, stderr_data, self, elapsed_time) def __repr__(self): return f"{self.tutorial.name} {self.case_combination}" def __write_logs(self, stdout_data: List[str], stderr_data: List[str]): - with open(self.system_test_dir / "system-tests-stdout.log", 'w') as stdout_file: + with open(self.system_test_dir / COMBINED_STDOUT_LOG, 'w', encoding="utf-8") as stdout_file: stdout_file.write("\n".join(stdout_data)) - with open(self.system_test_dir / "system-tests-stderr.log", 'w') as stderr_file: + with open(self.system_test_dir / COMBINED_STDERR_LOG, 'w', encoding="utf-8") as stderr_file: stderr_file.write("\n".join(stderr_data)) def __apply_max_time_override(self): @@ -661,6 +737,7 @@ def run(self, run_directory: Path): Runs the system test by generating the Docker Compose file, copying everything into a run folder, and executing docker-compose up. """ self.__prepare_for_run(run_directory) + self.__init_run_logs() std_out: List[str] = [] std_err: List[str] = [] @@ -728,6 +805,7 @@ def run_for_reference_results(self, run_directory: Path): Runs the system test by generating the Docker Compose files to generate the reference results """ self.__prepare_for_run(run_directory) + self.__init_run_logs() std_out: List[str] = [] std_err: List[str] = [] self._cleanup_docker_networks() @@ -777,6 +855,7 @@ def run_only_build(self, run_directory: Path): Runs only the build commmand, for example to preheat the caches of the docker builder. """ self.__prepare_for_run(run_directory) + self.__init_run_logs() std_out: List[str] = [] std_err: List[str] = [] docker_build_result = self._build_docker()