diff --git a/.github/workflows/run-nvx-microvm-tests.yml b/.github/workflows/run-nvx-microvm-tests.yml index 7bc311d93..10a8241f1 100644 --- a/.github/workflows/run-nvx-microvm-tests.yml +++ b/.github/workflows/run-nvx-microvm-tests.yml @@ -1214,3 +1214,15 @@ jobs: build/test-results/azurelinux-${{ inputs.backend }} build/test-results/aci-edge-sandboxes-${{ inputs.backend }} if-no-files-found: warn + + # Each attempt keeps the scenario duration report of every test-microvm + # step (doc/usage.md#scenario-duration-report), whether the job passes, + # fails, or is cancelled. + - name: Upload NVX microVM scenario durations + if: always() + uses: actions/upload-artifact@v7 + with: + name: nvx-microvm-durations-${{ runner.os }}-${{ inputs.backend }}-${{ inputs.debug-kernel && 'debug' || 'default' }}-${{ github.run_id }}-${{ github.run_attempt }} + path: build/test-results/*/scenario-durations.jsonl + if-no-files-found: warn + retention-days: 30 diff --git a/doc/ci.md b/doc/ci.md index 45f0102af..988e178ed 100644 --- a/doc/ci.md +++ b/doc/ci.md @@ -37,7 +37,12 @@ CLI. Alpine-control-only scenarios remain explicit and are rejected for the Ubuntu initramfs. Each job also boots the Azure Linux initramfs through its one-vCPU smoke set, under the same time ABI checks; the debug-kernel jobs skip it, as they skip the Ubuntu tests. Failure logs from the NVX layer are uploaded -per backend. +per backend. Every `nvx-microvm-tests-*` and `nvx-microvm-debug-*` job also +uploads the [scenario duration report](usage.md#scenario-duration-report) of +each `test-microvm` step, whether the job passes, fails, or is cancelled, as +the 30-day `nvx-microvm-durations-----` +artifact, where `` is `default` or `debug`, so that each attempt keeps +its own. Every harness launch, in the tests and the benchmarks, scans the OpenVMM console for the guest's [time ABI](design/3.2-clock-and-time.md) output, and the tests scan every virtio console they read over TCP the same way, to its end. An diff --git a/doc/project-structure.md b/doc/project-structure.md index f22c3914f..d07e656c2 100644 --- a/doc/project-structure.md +++ b/doc/project-structure.md @@ -137,6 +137,7 @@ nvx/ | | |-- host_telemetry.py Benchmark host provenance and Windows capture storage telemetry | | |-- host_time_probe.rs Host TSC probe that doctor builds and runs | | |-- managed_exec_tests.py Managed workload environment, directory, and timeout tests +| | |-- microvm_durations.py Scenario duration report of the microVM tests | | |-- microvm_test_scripts/ Guest workloads for the microVM tests | | |-- microvm_tests.py NVX microVM correctness tests | | |-- nvx_rs.py Finds, builds, and runs nvx-rs, to which nvx.py delegates diff --git a/doc/usage.md b/doc/usage.md index 7e3e62765..f0709ec42 100644 --- a/doc/usage.md +++ b/doc/usage.md @@ -477,6 +477,48 @@ command requires `build/vmlinux` (with `--debug-kernel`, `build/vmlinux-debug` and its `build/vmlinux-debug.config`), the selected initramfs, and `openvmm/target/release/openvmm[.exe]`. +#### Scenario duration report + +`test-microvm` prints each scenario's progress line as the scenario starts, +so that a log's timestamps follow the scenarios. It also records how long each +scenario takes in `scenario-durations.jsonl` in `--output-dir`, replacing the +previous run's report, and [CI](ci.md) uploads the reports of its microVM +jobs. The report is JSON Lines: one JSON object per line, whose `record` field +names its kind. The first line, `run`, describes the run: + +| Field | Value | +| --- | --- | +| `schema`, `schema_version` | `nvx-microvm-durations` and `1`. The version changes only when a reader of the previous version would misread a report, not when a field is added. | +| `started_at` | When the run and its `setup` started, in UTC, such as `2026-10-21T13:50:00.123Z` | +| `guest`, `backend` | The `--guest` and the `--backend` | +| `kernel` | `debug` with `--debug-kernel`, otherwise `default` | +| `processors` | The `--processors` counts, without repeats | +| `scenarios` | The selected scenarios | +| `github` | In GitHub Actions, the job's `repository`, `workflow`, `run_id`, `run_attempt`, `job`, `event_name`, `ref`, `sha`, `runner_name`, and `runner_os`, as strings from the `GITHUB_` and `RUNNER_` variables of those names; otherwise `null` | + +Each later line records a span of the run as soon as the span ends, so that a +run that fails or is interrupted keeps every span that it completed. The spans +follow one another without gaps, so they add up to the run's time: + +- `setup`, from the start of the Python process, or from the report's creation + where the OS doesn't report that start, until the first scenario starts; +- a `scenario` for each scenario execution, until the next one starts. + `console-exit`, `smp`, and `smp-lapic` execute once per processor count; +- `teardown`, which sums up the time ABI evidence and records the run's + outcome. + +Every span has its `started_at`, its `seconds`, rounded to the millisecond, its +`outcome`, `passed`, `failed`, or `interrupted`, for example by `SIGINT`, and +an `error`: for a failure, the exception's type and message, cut to 1,000 +characters, and otherwise `null`. A `scenario` record also has the +`scenario`, the `guest`, `backend`, and `kernel`, and its `processors`: the +`--processors` counts that the execution covers, such as `[4]` for `smp` on 4 +vCPUs, the largest count for `time-abi-conformance`, all of them for +`smp-snapshot` and `restore-processors`, or `null` for a scenario that doesn't +take them. A failed run ends with the failed scenario's record and the +`teardown`; a run that is killed keeps every record that it completed and has +no `teardown`. + ### `doctor` ```text diff --git a/scripts/nvx_tools/microvm_durations.py b/scripts/nvx_tools/microvm_durations.py new file mode 100644 index 000000000..0d933d777 --- /dev/null +++ b/scripts/nvx_tools/microvm_durations.py @@ -0,0 +1,241 @@ +"""The scenario duration report of `nvx.py test-microvm`. + +doc/usage.md#scenario-duration-report describes the format. +""" + +from __future__ import annotations + +import ctypes +import json +import os +import sys +import time +from collections.abc import Callable, Mapping, Sequence +from datetime import datetime, timezone +from pathlib import Path +from types import TracebackType +from typing import Literal + +# The report's name in test-microvm's output directory. +REPORT_NAME = "scenario-durations.jsonl" +SCHEMA = "nvx-microvm-durations" +# Changes only when a reader of the previous version would misread a report; +# added fields keep it. +SCHEMA_VERSION = 1 +# The GitHub Actions variables that identify the job that wrote a report, +# under the names that the report's header gives them. +GITHUB_VARIABLES = ( + ("repository", "GITHUB_REPOSITORY"), + ("workflow", "GITHUB_WORKFLOW"), + ("run_id", "GITHUB_RUN_ID"), + ("run_attempt", "GITHUB_RUN_ATTEMPT"), + ("job", "GITHUB_JOB"), + ("event_name", "GITHUB_EVENT_NAME"), + ("ref", "GITHUB_REF"), + ("sha", "GITHUB_SHA"), + ("runner_name", "RUNNER_NAME"), + ("runner_os", "RUNNER_OS"), +) +# A record keeps this much of a failure's message; the logs keep all of it. +ERROR_CHARACTERS = 1000 +# Seconds from the FILETIME epoch, 1601-01-01, to the Unix epoch. +FILETIME_UNIX_EPOCH_SECONDS = 11_644_473_600 + + +def proc_start_seconds(stat: str, ticks_per_second: int) -> float: + """Return when a Linux process started, in seconds after boot, from its + /proc/PID/stat.""" + # The fields after the command name, which may hold spaces and + # parentheses, start with the 3rd; starttime is the 22nd. + return int(stat.rpartition(")")[2].split()[19]) / ticks_per_second + + +def process_age_seconds() -> float | None: + """Return how long ago this process started, or None if the OS doesn't + tell.""" + try: + if sys.platform == "linux": + started = proc_start_seconds( + Path("/proc/self/stat").read_text(encoding="utf-8", errors="replace"), + os.sysconf("SC_CLK_TCK"), + ) + return time.clock_gettime(time.CLOCK_BOOTTIME) - started + if sys.platform == "win32": + kernel32 = ctypes.WinDLL("kernel32", use_last_error=True) + kernel32.GetCurrentProcess.restype = ctypes.c_void_p + filetime = ctypes.POINTER(ctypes.c_uint64) + kernel32.GetProcessTimes.argtypes = ( + ctypes.c_void_p, + filetime, + filetime, + filetime, + filetime, + ) + kernel32.GetProcessTimes.restype = ctypes.c_int + created, exited, kernel, user = (ctypes.c_uint64() for _ in range(4)) + if not kernel32.GetProcessTimes( + kernel32.GetCurrentProcess(), + ctypes.byref(created), + ctypes.byref(exited), + ctypes.byref(kernel), + ctypes.byref(user), + ): + raise ctypes.WinError(ctypes.get_last_error()) + # FILETIME counts 100 ns intervals. + return time.time() - ( + created.value / 10_000_000 - FILETIME_UNIX_EPOCH_SECONDS + ) + except (OSError, ValueError, IndexError): + pass + return None + + +def github_job(environment: Mapping[str, str]) -> dict[str, str | None] | None: + """Return the GitHub Actions job that an environment describes, or None + outside GitHub Actions.""" + if environment.get("GITHUB_ACTIONS") != "true": + return None + return {name: environment.get(variable) for name, variable in GITHUB_VARIABLES} + + +def _outcome(error: BaseException | None) -> str: + if error is None: + return "passed" + return "interrupted" if isinstance(error, KeyboardInterrupt) else "failed" + + +def _error(error: BaseException | None) -> str | None: + if error is None or isinstance(error, KeyboardInterrupt): + return None + message = str(error) + name = type(error).__name__ + return (f"{name}: {message}" if message else name)[:ERROR_CHARACTERS] + + +class DurationReport: + """The scenario duration report of one test-microvm run. + + The report is JSON Lines. A header comes first, and then one record for + each span of the run, which the report appends as soon as the span ends, + so that a run that fails or is interrupted keeps every span that it + completed. The spans follow one another without gaps from the start of + the process: the setup, one span for each scenario execution, which ends + when the next one starts, and the teardown, which finish() starts and + which ends with the with block, with the run's outcome. + """ + + def __init__( + self, + path: Path, + *, + backend: str, + guest: str, + kernel: str, + processors: Sequence[int], + scenarios: Sequence[str], + clock: Callable[[], float] = time.monotonic, + wall_clock: Callable[[], float] = time.time, + started: float | None = None, + ) -> None: + """Write the header of a report on a run that started at `started` + on `clock`, by default when this process started.""" + self.path = path + self._clock = clock + now = clock() + # Every timestamp is a reading of `clock` plus this one offset, so + # that each span starts exactly where the previous one ended. + self._offset = wall_clock() - now + if started is None: + started = now - max(0.0, process_age_seconds() or 0.0) + self._dimensions = {"guest": guest, "backend": backend, "kernel": kernel} + self._span: dict[str, object] = {"record": "setup"} + self._span_started = started + self._write( + { + "record": "run", + "schema": SCHEMA, + "schema_version": SCHEMA_VERSION, + "started_at": self._timestamp(started), + **self._dimensions, + "processors": [*dict.fromkeys(processors)], + "scenarios": list(scenarios), + "github": github_job(os.environ), + }, + mode="w", + ) + + def start( + self, + scenario: str, + message: str, + *, + processors: Sequence[int] | None = None, + ) -> None: + """End the open span, print `message` at once, and time `scenario`, + which runs on `processors` if it takes processor counts.""" + ended = self._end_span(None) + self._span = { + "record": "scenario", + "scenario": scenario, + **self._dimensions, + "processors": None if processors is None else [*dict.fromkeys(processors)], + } + self._write(ended) + print(message, flush=True) + + def finish(self) -> None: + """End the last scenario, or the setup if none ran, and start the + teardown.""" + ended = self._end_span(None) + self._span = {"record": "teardown"} + self._write(ended) + + def __enter__(self) -> DurationReport: + return self + + def __exit__( + self, + kind: type[BaseException] | None, + error: BaseException | None, + traceback: TracebackType | None, + ) -> None: + """End the open span, and then the teardown, with the run's outcome.""" + try: + if self._span["record"] != "teardown": + # The span that raised `error`, or the last scenario if + # finish() was not called. + ended = self._end_span(error) + self._span = {"record": "teardown"} + self._write(ended) + self._write(self._end_span(error)) + except OSError as failure: + if error is None: + raise + # Keep the run's own error; the report then lacks its end. + print( + f"warning: could not complete {self.path}: {failure}", + file=sys.stderr, + flush=True, + ) + + def _end_span(self, error: BaseException | None) -> dict[str, object]: + now = self._clock() + record = { + **self._span, + "started_at": self._timestamp(self._span_started), + "seconds": round(now - self._span_started, 3), + "outcome": _outcome(error), + "error": _error(error), + } + self._span_started = now + return record + + def _timestamp(self, value: float) -> str: + moment = datetime.fromtimestamp(self._offset + value, timezone.utc) + return moment.isoformat(timespec="milliseconds").replace("+00:00", "Z") + + def _write( + self, record: Mapping[str, object], mode: Literal["a", "w"] = "a" + ) -> None: + with self.path.open(mode, encoding="utf-8", newline="\n") as stream: + stream.write(json.dumps(record, separators=(",", ":")) + "\n") diff --git a/scripts/nvx_tools/microvm_tests.py b/scripts/nvx_tools/microvm_tests.py index 81fc0656a..3b04ebbb2 100644 --- a/scripts/nvx_tools/microvm_tests.py +++ b/scripts/nvx_tools/microvm_tests.py @@ -20,7 +20,7 @@ import threading import time import uuid -from collections.abc import Callable, Sequence +from collections.abc import Callable, Collection, Sequence from contextlib import ExitStack, suppress from dataclasses import dataclass from pathlib import Path @@ -65,6 +65,7 @@ ) from .guests import GUEST_NAMES, GuestDescriptor, guest_descriptor from .managed_exec_tests import run_managed_exec_configuration +from .microvm_durations import REPORT_NAME, DurationReport from .nvx_rs import EgressRules, compile_egress_policy from .openvmm_process import OpenvmmProcess, TcpConsole from .sandbox_lifecycle_tests import run_sandbox_lifecycle @@ -409,7 +410,10 @@ def configure_parser(parser: argparse.ArgumentParser) -> None: "--output-dir", type=Path, default=BuildConstants.BUILD_DIR / "test-results" / "microvm", - help="directory for complete per-scenario OpenVMM logs", + help=( + "directory for complete per-scenario OpenVMM logs and the scenario " + "duration report" + ), ) parser.set_defaults(handler=run) @@ -7553,10 +7557,53 @@ def run(args: argparse.Namespace) -> int: + ", ".join(sorted(unsupported)) ) + with DurationReport( + output_dir / REPORT_NAME, + backend=args.backend, + guest=descriptor.name, + kernel="debug" if debug_kernel else "default", + processors=args.processors, + scenarios=scenarios, + ) as report: + _run_scenarios( + report, + args, + scenarios, + descriptor=descriptor, + executable=executable, + kernel=kernel, + initrd=initrd, + output_dir=output_dir, + ) + report.finish() + report_time_abi_evidence( + output_dir, + backend=args.backend, + guest=descriptor.name, + debug_kernel=debug_kernel, + ) + print(f"Wrote microVM correctness logs to {output_dir}") + return 0 + + +def _run_scenarios( + report: DurationReport, + args: argparse.Namespace, + scenarios: Collection[str], + *, + descriptor: GuestDescriptor, + executable: Path, + kernel: Path, + initrd: Path, + output_dir: Path, +) -> None: + """Run the selected scenarios in their fixed order, and time each + execution in `report`.""" if "guest-boot" in scenarios: - print( + report.start( + "guest-boot", f"Running {descriptor.distribution} initramfs boot correctness " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_guest_boot( executable, @@ -7569,9 +7616,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / f"{descriptor.name}-guest-boot.log", ) if "guest-identity" in scenarios: - print( + report.start( + "guest-identity", f"Running {descriptor.distribution} identity correctness " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_guest_identity( executable, @@ -7585,9 +7633,11 @@ def run(args: argparse.Namespace) -> int: ) if "console-exit" in scenarios: for processors in dict.fromkeys(args.processors): - print( + report.start( + "console-exit", f"Running microVM console exit correctness ({processors} vCPU) " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + processors=[processors], ) run_console_exit( executable, @@ -7600,7 +7650,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "console-snapshot" in scenarios: - print(f"Running microVM console snapshot correctness on OpenVMM/{args.backend}") + report.start( + "console-snapshot", + f"Running microVM console snapshot correctness on OpenVMM/{args.backend}", + ) run_console_snapshot( executable, kernel, @@ -7611,9 +7664,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "cpu-profile-fallback" in scenarios: - print( + report.start( + "cpu-profile-fallback", "Running microVM CPU profile fallback correctness on " - f"OpenVMM/{args.backend}" + f"OpenVMM/{args.backend}", ) run_cpu_profile_fallback( executable, @@ -7625,9 +7679,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "endpoint-policy-snapshot" in scenarios: - print( + report.start( + "endpoint-policy-snapshot", "Running microVM endpoint-policy snapshot correctness on " - f"OpenVMM/{args.backend}" + f"OpenVMM/{args.backend}", ) run_endpoint_policy_snapshot( executable, @@ -7639,9 +7694,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-shares" in scenarios: - print( + report.start( + "filesystem-shares", "Running read-write, read-only, and hidden-root microVM shares " - f"through one aggregate on OpenVMM/{args.backend}" + f"through one aggregate on OpenVMM/{args.backend}", ) run_filesystem_shares( executable, @@ -7653,9 +7709,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-policy" in scenarios: - print( + report.start( + "filesystem-policy", "Running microVM share write narrowing and read masking " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_filesystem_policy( executable, @@ -7667,9 +7724,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-comma-paths" in scenarios: - print( + report.start( + "filesystem-comma-paths", "Running public nvx.py shares of host paths with commas " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_filesystem_comma_paths( args.backend, @@ -7679,8 +7737,9 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "filesystem-snapshot" in scenarios: - print( - f"Running microVM filesystem snapshot correctness on OpenVMM/{args.backend}" + report.start( + "filesystem-snapshot", + f"Running microVM filesystem snapshot correctness on OpenVMM/{args.backend}", ) run_filesystem_snapshot( executable, @@ -7692,7 +7751,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "lifecycle" in scenarios: - print(f"Running microVM lifecycle correctness on OpenVMM/{args.backend}") + report.start( + "lifecycle", + f"Running microVM lifecycle correctness on OpenVMM/{args.backend}", + ) run_lifecycle( executable, kernel, @@ -7703,8 +7765,9 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "lifecycle.log", ) if "workload-identity" in scenarios: - print( - f"Running microVM workload identity correctness on OpenVMM/{args.backend}" + report.start( + "workload-identity", + f"Running microVM workload identity correctness on OpenVMM/{args.backend}", ) run_workload_identity( executable, @@ -7716,17 +7779,24 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "managed-exec-config" in scenarios: - print( - f"Running public managed execution configuration on OpenVMM/{args.backend}" + report.start( + "managed-exec-config", + f"Running public managed execution configuration on OpenVMM/{args.backend}", ) run_managed_exec_configuration( args.backend, timeout=args.timeout, output_dir=output_dir ) if "sandbox-lifecycle" in scenarios: - print(f"Running public managed sandbox lifecycle on OpenVMM/{args.backend}") + report.start( + "sandbox-lifecycle", + f"Running public managed sandbox lifecycle on OpenVMM/{args.backend}", + ) run_sandbox_lifecycle(args.backend, timeout=args.timeout, output_dir=output_dir) if "managed-lifecycle" in scenarios: - print(f"Running managed microVM lifecycle on OpenVMM/{args.backend}") + report.start( + "managed-lifecycle", + f"Running managed microVM lifecycle on OpenVMM/{args.backend}", + ) run_managed_lifecycle( executable, kernel, @@ -7737,7 +7807,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "structured-outcome" in scenarios: - print(f"Running structured microVM outcomes on OpenVMM/{args.backend}") + report.start( + "structured-outcome", + f"Running structured microVM outcomes on OpenVMM/{args.backend}", + ) run_structured_outcome( executable, kernel, @@ -7748,9 +7821,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "l3-l4-egress-policy" in scenarios: - print( + report.start( + "l3-l4-egress-policy", "Running public nvx.py L3/L4 egress policy acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_l3_l4_egress_policy( executable, @@ -7763,9 +7837,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "l3-l4-egress-protocols" in scenarios: - print( + report.start( + "l3-l4-egress-protocols", "Running public nvx.py L3/L4 egress protocol acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_l3_l4_egress_protocols( executable, @@ -7778,9 +7853,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "l3-l4-egress-port-ranges" in scenarios: - print( + report.start( + "l3-l4-egress-port-ranges", "Running public nvx.py L3/L4 egress port-range acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_l3_l4_egress_port_ranges( executable, @@ -7793,9 +7869,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "ipv6-egress-policy" in scenarios: - print( + report.start( + "ipv6-egress-policy", "Running public nvx.py IPv6 egress policy acceptance " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_ipv6_egress_policy( executable, @@ -7808,7 +7885,10 @@ def run(args: argparse.Namespace) -> int: guest=descriptor.name, ) if "host-loopback-policy" in scenarios: - print(f"Running microVM host-loopback policy on OpenVMM/{args.backend}") + report.start( + "host-loopback-policy", + f"Running microVM host-loopback policy on OpenVMM/{args.backend}", + ) run_host_loopback_policy( executable, kernel, @@ -7819,7 +7899,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "private-network-ingress" in scenarios: - print(f"Running microVM private-network ingress on OpenVMM/{args.backend}") + report.start( + "private-network-ingress", + f"Running microVM private-network ingress on OpenVMM/{args.backend}", + ) run_private_network_ingress( executable, kernel, @@ -7830,7 +7913,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "denied-filesystem-paths" in scenarios: - print(f"Running microVM denied filesystem paths on OpenVMM/{args.backend}") + report.start( + "denied-filesystem-paths", + f"Running microVM denied filesystem paths on OpenVMM/{args.backend}", + ) run_denied_filesystem_paths( executable, kernel, @@ -7841,7 +7927,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "filesystem-owner" in scenarios: - print(f"Running microVM filesystem caller ownership on OpenVMM/{args.backend}") + report.start( + "filesystem-owner", + f"Running microVM filesystem caller ownership on OpenVMM/{args.backend}", + ) run_filesystem_owner( executable, kernel, @@ -7852,7 +7941,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "network-snapshot" in scenarios: - print(f"Running microVM network snapshot correctness on OpenVMM/{args.backend}") + report.start( + "network-snapshot", + f"Running microVM network snapshot correctness on OpenVMM/{args.backend}", + ) run_network_snapshot( executable, kernel, @@ -7866,9 +7958,11 @@ def run(args: argparse.Namespace) -> int: if scenario not in scenarios: continue for processors in dict.fromkeys(args.processors): - print( + report.start( + scenario, f"Running microVM {scenario} correctness ({processors} vCPU) " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + processors=[processors], ) run_smp( executable, @@ -7882,7 +7976,10 @@ def run(args: argparse.Namespace) -> int: counting_lapic=counting_lapic, ) if "sandbox-blocks" in scenarios: - print(f"Running microVM sandbox-block correctness on OpenVMM/{args.backend}") + report.start( + "sandbox-blocks", + f"Running microVM sandbox-block correctness on OpenVMM/{args.backend}", + ) run_sandbox_blocks( executable, kernel, @@ -7893,7 +7990,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "sandbox-blocks.log", ) if "scratch-snapshot" in scenarios: - print(f"Running microVM scratch snapshot correctness on OpenVMM/{args.backend}") + report.start( + "scratch-snapshot", + f"Running microVM scratch snapshot correctness on OpenVMM/{args.backend}", + ) run_scratch_snapshot( executable, kernel, @@ -7904,7 +8004,11 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "smp-snapshot" in scenarios: - print(f"Running microVM SMP snapshot correctness on OpenVMM/{args.backend}") + report.start( + "smp-snapshot", + f"Running microVM SMP snapshot correctness on OpenVMM/{args.backend}", + processors=args.processors, + ) run_smp_snapshot( executable, kernel, @@ -7916,8 +8020,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "restore-processors" in scenarios: - print( - f"Running microVM restore-processor correctness on OpenVMM/{args.backend}" + report.start( + "restore-processors", + f"Running microVM restore-processor correctness on OpenVMM/{args.backend}", + processors=args.processors, ) run_restore_processors( executable, @@ -7930,9 +8036,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "restore-downtime" in scenarios: - print( + report.start( + "restore-downtime", "Running microVM long-downtime restore correctness on " - f"OpenVMM/{args.backend}" + f"OpenVMM/{args.backend}", ) run_restore_downtime( executable, @@ -7944,7 +8051,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "restore-memory" in scenarios: - print(f"Running microVM restore-memory correctness on OpenVMM/{args.backend}") + report.start( + "restore-memory", + f"Running microVM restore-memory correctness on OpenVMM/{args.backend}", + ) run_restore_memory( executable, kernel, @@ -7954,7 +8064,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "snapshot-core" in scenarios: - print(f"Running microVM snapshot-core correctness on OpenVMM/{args.backend}") + report.start( + "snapshot-core", + f"Running microVM snapshot-core correctness on OpenVMM/{args.backend}", + ) run_snapshot_core( executable, kernel, @@ -7965,7 +8078,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "snapshot-tiers" in scenarios: - print(f"Running microVM snapshot-tier correctness on OpenVMM/{args.backend}") + report.start( + "snapshot-tiers", + f"Running microVM snapshot-tier correctness on OpenVMM/{args.backend}", + ) run_snapshot_tiers( executable, kernel, @@ -7976,7 +8092,10 @@ def run(args: argparse.Namespace) -> int: output_dir=output_dir, ) if "directional-network-policy" in scenarios: - print(f"Running microVM directional network policy on OpenVMM/{args.backend}") + report.start( + "directional-network-policy", + f"Running microVM directional network policy on OpenVMM/{args.backend}", + ) run_directional_network_policy( executable, kernel, @@ -7988,9 +8107,11 @@ def run(args: argparse.Namespace) -> int: ) if "time-abi-conformance" in scenarios: processors = max(args.processors) - print( + report.start( + "time-abi-conformance", f"Running microVM time ABI conformance ({processors} vCPU) " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", + processors=[processors], ) run_time_abi_conformance( executable, @@ -8003,7 +8124,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "time-abi-conformance.log", ) if "virtio-net" in scenarios: - print(f"Running microVM virtio-net correctness on OpenVMM/{args.backend}") + report.start( + "virtio-net", + f"Running microVM virtio-net correctness on OpenVMM/{args.backend}", + ) run_virtio_net( executable, kernel, @@ -8014,9 +8138,10 @@ def run(args: argparse.Namespace) -> int: log_path=output_dir / "virtio-net.log", ) if "command-line-limit" in scenarios: - print( + report.start( + "command-line-limit", "Running a microVM kernel command line at the guest kernel's limit " - f"on OpenVMM/{args.backend}" + f"on OpenVMM/{args.backend}", ) run_command_line_limit( executable, @@ -8027,12 +8152,3 @@ def run(args: argparse.Namespace) -> int: timeout=args.timeout, output_dir=output_dir, ) - - report_time_abi_evidence( - output_dir, - backend=args.backend, - guest=descriptor.name, - debug_kernel=debug_kernel, - ) - print(f"Wrote microVM correctness logs to {output_dir}") - return 0 diff --git a/scripts/test_microvm_tests.py b/scripts/test_microvm_tests.py index dbb7a8421..5ffbae90d 100644 --- a/scripts/test_microvm_tests.py +++ b/scripts/test_microvm_tests.py @@ -8,6 +8,7 @@ import inspect import io import ipaddress +import itertools import json import os import queue @@ -22,6 +23,7 @@ import unittest from collections.abc import Callable, Collection from contextlib import ExitStack, nullcontext, redirect_stdout +from datetime import datetime from pathlib import Path from typing import Any, cast from unittest.mock import MagicMock, patch @@ -33,6 +35,7 @@ benchmark, common, managed_exec_tests, + microvm_durations, microvm_tests, nvx_rs, openvmm_process, @@ -43,6 +46,9 @@ BuildConstants, ) +# When this process loaded the tests, on the monotonic clock. +_LOADED = time.monotonic() + def _compile(policy: dict[str, object]) -> nvx_rs.EgressRules: """Compiles an egress policy with nvx-rs, as nvx.py run compiles its @@ -109,6 +115,21 @@ def _restore_target(command: list[str]) -> int | None: return int(command[command.index("--restore-processors") + 1]) +def _scenario_runners() -> list[str]: + """Return the names of the microVM test module's run_* functions, among + them every scenario function that its runner calls.""" + return [ + name + for name, value in vars(microvm_tests).items() + if name.startswith("run_") and callable(value) + ] + + +def _read_report(path: Path) -> list[dict[str, Any]]: + """Return the records of a scenario duration report, in order.""" + return [json.loads(line) for line in path.read_text(encoding="utf-8").splitlines()] + + # OpenVMM's warning of a cold boot whose --cpu-profile auto falls back to a # host profile (openvmm_core's time_abi host_profile_warning), on stderr. FALLBACK_WARNING = ( @@ -9806,6 +9827,11 @@ def require(path: Path, _description: str) -> Path: with self.subTest(scenario=scenario): run.assert_called() self.assertEqual(run.call_args.args[1], build / "vmlinux-debug") + header = _read_report(build / "logs" / microvm_durations.REPORT_NAME)[0] + self.assertEqual( + (header["kernel"], header["scenarios"]), + ("debug", list(microvm_tests.DEBUG_KERNEL_SCENARIOS)), + ) config.write_text("CONFIG_DETECT_HUNG_TASK=y\n", encoding="utf-8") with self.assertRaisesRegex( common.ScriptError, "lacks CONFIG_SOFTLOCKUP_DETECTOR=y" @@ -9878,6 +9904,194 @@ def require(path: Path, _description: str) -> Path: self.assertEqual(microvm_tests.run(args), 0) self.assertEqual([call.args[4] for call in run.call_args_list], [1, 2, 4, 8]) + def test_runner_flushes_each_progress_line_before_its_scenario(self): + # CI timestamps each log line when it leaves the process, so every + # scenario's progress line must leave stdout's buffer before the + # scenario starts (#694). + class FlushRecorder(io.StringIO): + flushed = "" + + def flush(self) -> None: + super().flush() + self.flushed = self.getvalue() + + def require(path: Path, _description: str) -> Path: + return path + + stdout = FlushRecorder() + progress: list[str] = [] + + def scenario(*_args: object, **_kwargs: object) -> None: + self.assertEqual(stdout.flushed, stdout.getvalue()) + progress.append(stdout.flushed.splitlines()[-1]) + + scenarios = ( + *microvm_tests.MICROVM_TEST_SCENARIOS, + *microvm_tests.MICROVM_EXPLICIT_SCENARIOS, + ) + with tempfile.TemporaryDirectory() as temporary, ExitStack() as stack: + args = nvx.parse_args( + [ + "test-microvm", + "--backend", + "kvm", + *(f"--scenario={scenario}" for scenario in scenarios), + "--processors", + "1", + "2", + "--output-dir", + temporary, + ] + ) + stack.enter_context( + patch.object(microvm_tests, "validate_openvmm_test_backend") + ) + stack.enter_context( + patch.object(microvm_tests, "require_file", side_effect=require) + ) + for name in _scenario_runners(): + stack.enter_context( + patch.object(microvm_tests, name, side_effect=scenario) + ) + stack.enter_context(redirect_stdout(stdout)) + self.assertEqual(microvm_tests.run(args), 0) + + # console-exit, smp, and smp-lapic run once per processor count. + self.assertEqual(len(progress), len(scenarios) + 3) + for line in progress: + self.assertRegex(line, r"^Running .+ on OpenVMM/kvm$") + + def test_runner_reports_every_scenario_execution(self): + def require(path: Path, _description: str) -> Path: + return path + + scenarios = ( + *microvm_tests.MICROVM_TEST_SCENARIOS, + *microvm_tests.MICROVM_EXPLICIT_SCENARIOS, + ) + with tempfile.TemporaryDirectory() as temporary, ExitStack() as stack: + args = nvx.parse_args( + [ + "test-microvm", + "--backend", + "whp", + *(f"--scenario={scenario}" for scenario in scenarios), + "--processors", + "2", + "1", + "2", + "--output-dir", + temporary, + ] + ) + stack.enter_context( + patch.object(microvm_tests, "validate_openvmm_test_backend") + ) + stack.enter_context( + patch.object(microvm_tests, "require_file", side_effect=require) + ) + for name in _scenario_runners(): + stack.enter_context(patch.object(microvm_tests, name)) + stack.enter_context(redirect_stdout(io.StringIO())) + self.assertEqual(microvm_tests.run(args), 0) + records = _read_report(Path(temporary) / microvm_durations.REPORT_NAME) + + header, setup, *executions, teardown = records + self.assertEqual(header["record"], "run") + self.assertEqual( + (header["guest"], header["backend"], header["kernel"]), + ("alpine", "whp", "default"), + ) + self.assertEqual(header["processors"], [2, 1]) + self.assertEqual(header["scenarios"], list(scenarios)) + self.assertEqual((setup["record"], setup["outcome"]), ("setup", "passed")) + self.assertEqual( + (teardown["record"], teardown["outcome"]), ("teardown", "passed") + ) + # Each execution names the processor counts that it covers, if any. + expected: list[tuple[str, list[int] | None]] = [] + for scenario in scenarios: + if scenario in ("console-exit", "smp", "smp-lapic"): + expected.extend((scenario, [processors]) for processors in (2, 1)) + elif scenario in ("smp-snapshot", "restore-processors"): + expected.append((scenario, [2, 1])) + elif scenario == "time-abi-conformance": + expected.append((scenario, [2])) + else: + expected.append((scenario, None)) + self.assertCountEqual( + [(record["scenario"], record["processors"]) for record in executions], + expected, + ) + for record in executions: + self.assertEqual( + (record["record"], record["guest"], record["backend"]), + ("scenario", "alpine", "whp"), + ) + self.assertEqual( + (record["kernel"], record["outcome"], record["error"]), + ("default", "passed", None), + ) + # The spans follow one another, so they add up to the run's time. + for record, following in itertools.pairwise(records[1:]): + started = datetime.fromisoformat(record["started_at"][:-1]) + ended = datetime.fromisoformat(following["started_at"][:-1]) + self.assertAlmostEqual( + (ended - started).total_seconds(), record["seconds"], delta=0.002 + ) + + def test_runner_report_keeps_the_executions_before_a_failure(self): + def require(path: Path, _description: str) -> Path: + return path + + with tempfile.TemporaryDirectory() as temporary: + args = nvx.parse_args( + [ + "test-microvm", + "--backend", + "mshv", + "--scenario", + "virtio-net", + "--scenario", + "lifecycle", + "--output-dir", + temporary, + ] + ) + with ( + patch.object(microvm_tests, "validate_openvmm_test_backend"), + patch.object(microvm_tests, "require_file", side_effect=require), + patch.object(microvm_tests, "run_lifecycle"), + patch.object( + microvm_tests, + "run_virtio_net", + side_effect=RuntimeError("no virtio-net marker"), + ), + redirect_stdout(io.StringIO()), + self.assertRaisesRegex(RuntimeError, "no virtio-net marker"), + ): + microvm_tests.run(args) + records = _read_report(Path(temporary) / microvm_durations.REPORT_NAME) + + error = "RuntimeError: no virtio-net marker" + self.assertEqual( + [ + (record["record"], record.get("scenario"), record.get("outcome")) + for record in records + ], + [ + ("run", None, None), + ("setup", None, "passed"), + ("scenario", "lifecycle", "passed"), + ("scenario", "virtio-net", "failed"), + ("teardown", None, "failed"), + ], + ) + self.assertEqual( + [record.get("error") for record in records], + [None, None, None, error, error], + ) + def test_guest_runner_persists_full_output_on_failure(self): class FakeProcess: pid = 123 @@ -9924,5 +10138,270 @@ def close(self) -> None: self.assertEqual(log_path.read_bytes(), b"complete raw output\n") +class DurationReportTests(unittest.TestCase): + # 2027-01-15T08:00:00Z on the wall clock, which the tests' monotonic + # clock reads as 100. + EPOCH = 1_800_000_000.0 + GITHUB = { + "GITHUB_ACTIONS": "true", + "GITHUB_REPOSITORY": "microsoft/nvx", + "GITHUB_WORKFLOW": "CI", + "GITHUB_RUN_ID": "39585909588", + "GITHUB_RUN_ATTEMPT": "2", + "GITHUB_JOB": "test", + "GITHUB_EVENT_NAME": "pull_request", + "GITHUB_REF": "refs/pull/694/merge", + "GITHUB_SHA": "919a774c6" + "0" * 31, + "RUNNER_NAME": "azure-kvm-2", + "RUNNER_OS": "Linux", + } + + def _report( + self, path: Path, readings: list[float] + ) -> microvm_durations.DurationReport: + """Open a report on a run that started at 100 on a clock that + returns `readings`, the first when the report opens.""" + return microvm_durations.DurationReport( + path, + backend="kvm", + guest="alpine", + kernel="debug", + processors=[1, 8, 1], + scenarios=("smp", "lifecycle"), + clock=iter(readings).__next__, + wall_clock=lambda: self.EPOCH + readings[0] - 100, + started=100.0, + ) + + def test_spans_cover_the_run_from_the_process_start_without_gaps(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + written: list[int] = [] + with ( + patch.dict(os.environ, self.GITHUB), + redirect_stdout(io.StringIO()) as stdout, + ): + with self._report(path, [101.5, 102, 105.25, 110, 110.5]) as report: + # Each record is on disk as soon as its span ends. + written.append(len(_read_report(path))) + report.start("smp", "Running smp", processors=[8, 8]) + written.append(len(_read_report(path))) + report.start("lifecycle", "Running lifecycle") + written.append(len(_read_report(path))) + report.finish() + written.append(len(_read_report(path))) + records = _read_report(path) + raw = path.read_bytes() + + self.assertEqual(written, [1, 2, 3, 4]) + self.assertNotIn(b"\r", raw) + self.assertEqual(stdout.getvalue(), "Running smp\nRunning lifecycle\n") + dimensions = {"guest": "alpine", "backend": "kvm", "kernel": "debug"} + passed = {"outcome": "passed", "error": None} + self.assertEqual( + records, + [ + { + "record": "run", + "schema": "nvx-microvm-durations", + "schema_version": 1, + "started_at": "2027-01-15T08:00:00.000Z", + **dimensions, + "processors": [1, 8], + "scenarios": ["smp", "lifecycle"], + "github": { + "repository": "microsoft/nvx", + "workflow": "CI", + "run_id": "39585909588", + "run_attempt": "2", + "job": "test", + "event_name": "pull_request", + "ref": "refs/pull/694/merge", + "sha": self.GITHUB["GITHUB_SHA"], + "runner_name": "azure-kvm-2", + "runner_os": "Linux", + }, + }, + { + "record": "setup", + "started_at": "2027-01-15T08:00:00.000Z", + "seconds": 2.0, + **passed, + }, + { + "record": "scenario", + "scenario": "smp", + **dimensions, + "processors": [8], + "started_at": "2027-01-15T08:00:02.000Z", + "seconds": 3.25, + **passed, + }, + { + "record": "scenario", + "scenario": "lifecycle", + **dimensions, + "processors": None, + "started_at": "2027-01-15T08:00:05.250Z", + "seconds": 4.75, + **passed, + }, + { + "record": "teardown", + "started_at": "2027-01-15T08:00:10.000Z", + "seconds": 0.5, + **passed, + }, + ], + ) + self.assertEqual(sum(record["seconds"] for record in records[1:]), 10.5) + + def test_a_failure_ends_its_scenario_and_the_run(self): + for error, outcome, message in ( + (RuntimeError("no marker\nin the log"), "failed", None), + (TimeoutError(), "failed", "TimeoutError"), + (RuntimeError("x" * 5000), "failed", "RuntimeError: " + "x" * 986), + (KeyboardInterrupt(), "interrupted", None), + ): + with ( + self.subTest(error=type(error).__name__), + tempfile.TemporaryDirectory() as temporary, + ): + path = Path(temporary) / microvm_durations.REPORT_NAME + with ( + redirect_stdout(io.StringIO()), + self.assertRaises(type(error)) as raised, + self._report(path, [101, 102, 103, 104, 105]) as report, + ): + report.start("smp", "Running smp", processors=[1]) + report.start("lifecycle", "Running lifecycle") + raise error + records = _read_report(path) + self.assertIs(raised.exception, error) + if message is None and outcome == "failed": + message = f"RuntimeError: {error}" + self.assertEqual( + [ + (record["record"], record.get("scenario"), record["seconds"]) + for record in records[1:] + ], + [ + ("setup", None, 2), + ("scenario", "smp", 1), + ("scenario", "lifecycle", 1), + ("teardown", None, 1), + ], + ) + self.assertEqual( + [(record["outcome"], record["error"]) for record in records[1:]], + [ + ("passed", None), + ("passed", None), + (outcome, message), + (outcome, message), + ], + ) + self.assertLessEqual( + len(records[-1]["error"] or ""), + microvm_durations.ERROR_CHARACTERS, + ) + + def test_a_failure_before_the_first_scenario_ends_the_setup(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + with ( + self.assertRaisesRegex(ValueError, "no counts"), + self._report(path, [101, 102, 103]), + ): + raise ValueError("no counts") + records = _read_report(path) + self.assertEqual( + [ + (record["record"], record["seconds"], record["outcome"]) + for record in records[1:] + ], + [("setup", 2, "failed"), ("teardown", 1, "failed")], + ) + + def test_a_run_without_scenarios_has_only_setup_and_teardown(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + with self._report(path, [101, 102, 103]) as report: + report.finish() + records = _read_report(path) + self.assertEqual( + [ + (record["record"], record["seconds"], record["outcome"]) + for record in records[1:] + ], + [("setup", 2, "passed"), ("teardown", 1, "passed")], + ) + + def test_a_report_replaces_the_previous_runs_report(self): + with tempfile.TemporaryDirectory() as temporary: + path = Path(temporary) / microvm_durations.REPORT_NAME + path.write_text('{"record":"stale"}\n' * 3, encoding="utf-8") + with self._report(path, [101, 102, 103]) as report: + report.finish() + records = _read_report(path) + self.assertEqual( + [record["record"] for record in records], ["run", "setup", "teardown"] + ) + + def test_a_report_that_cannot_end_keeps_the_runs_own_error(self): + with tempfile.TemporaryDirectory() as temporary: + directory = Path(temporary) / "logs" + directory.mkdir() + path = directory / microvm_durations.REPORT_NAME + with ( + redirect_stdout(io.StringIO()), + patch("sys.stderr", new_callable=io.StringIO) as stderr, + self.assertRaisesRegex(RuntimeError, "no marker"), + self._report(path, [101, 102, 103, 104]) as report, + ): + report.start("smp", "Running smp") + shutil.rmtree(directory) + raise RuntimeError("no marker") + self.assertIn(f"warning: could not complete {path}: ", stderr.getvalue()) + # Without an error of the run's own, the report's error stands. + directory.mkdir() + with ( + self.assertRaises(OSError), + self._report(path, [101, 102]), + ): + shutil.rmtree(directory) + + def test_github_identifies_the_job_only_in_github_actions(self): + self.assertIsNone(microvm_durations.github_job({})) + self.assertIsNone( + microvm_durations.github_job({**self.GITHUB, "GITHUB_ACTIONS": "false"}) + ) + self.assertEqual( + microvm_durations.github_job( + {"GITHUB_ACTIONS": "true", "GITHUB_RUN_ID": "39585909588"} + ), + { + name: "39585909588" if name == "run_id" else None + for name, _ in microvm_durations.GITHUB_VARIABLES + }, + ) + + def test_proc_start_follows_any_command_name(self): + # The command name may hold spaces and parentheses; starttime is the + # 22nd field. + fields = ["S", *map(str, range(4, 22)), "4321", *["0"] * 30] + stat = "1234 (nvx) (python 3) " + " ".join(fields) + "\n" + self.assertEqual(microvm_durations.proc_start_seconds(stat, 100), 43.21) + + @unittest.skipUnless(sys.platform in ("linux", "win32"), "needs Linux or Windows") + def test_process_age_counts_from_the_process_start(self): + loaded = time.monotonic() - _LOADED + age = microvm_durations.process_age_seconds() + assert age is not None + # The process started before it loaded the tests, and not long ago. + self.assertGreaterEqual(age, loaded) + self.assertLess(age, 24 * 3600) + + if __name__ == "__main__": unittest.main() diff --git a/scripts/test_nvx_tools.py b/scripts/test_nvx_tools.py index 7a553f8c4..79c1e0a89 100644 --- a/scripts/test_nvx_tools.py +++ b/scripts/test_nvx_tools.py @@ -53,6 +53,7 @@ elf, guest_binaries, guests, + microvm_durations, nvx_rs, release, sandbox, @@ -7430,6 +7431,82 @@ def test_ci_runs_the_public_sandbox_acceptance_on_every_backend(self): ) self.assertIn("build/test-results/public-exec-${{ inputs.backend }}", upload) + def test_every_microvm_job_uploads_its_scenario_durations(self): + # Each microVM job, the debug-kernel ones too, keeps the duration + # report of every test-microvm step whether it passes, fails, or is + # cancelled, under a name of its own in each attempt (#694). + workflows = BuildConstants.REPO_ROOT / ".github" / "workflows" + steps = { + step["name"]: step + for step in yaml.safe_load( + (workflows / "run-nvx-microvm-tests.yml").read_text(encoding="utf-8") + )["jobs"]["test"]["steps"] + } + upload = steps["Upload NVX microVM scenario durations"] + self.assertEqual(upload["if"], "always()") + self.assertEqual(upload["uses"], "actions/upload-artifact@v7") + self.assertEqual( + upload["with"]["path"], + f"build/test-results/*/{microvm_durations.REPORT_NAME}", + ) + # The path's pattern finds the report of every test-microvm step. + microvm_runs = [ + step["run"] + for step in steps.values() + if "nvx.py test-microvm" in step.get("run", "") + ] + self.assertTrue(microvm_runs) + for run in microvm_runs: + with self.subTest(run=run): + self.assertEqual( + len(re.findall(r'--output-dir "build/test-results/[^"/*]+"', run)), + 1, + ) + # The failure logs keep their upload, only when a step fails. + self.assertEqual(steps["Upload NVX microVM failure logs"]["if"], "failure()") + + kernel = "${{ inputs.debug-kernel && 'debug' || 'default' }}" + name = upload["with"]["name"] + self.assertEqual( + name, + "nvx-microvm-durations-${{ runner.os }}-${{ inputs.backend }}-" + + kernel + + "-${{ github.run_id }}-${{ github.run_attempt }}", + ) + jobs = { + job_name: job["with"] + for job_name, job in yaml.safe_load( + (workflows / "ci.yml").read_text(encoding="utf-8") + )["jobs"].items() + if job.get("uses") == "./.github/workflows/run-nvx-microvm-tests.yml" + } + self.assertEqual( + set(jobs), + { + *ci.REQUIRED_CI_MICROVM_TEST_JOBS, + *ci.REQUIRED_CI_MICROVM_DEBUG_JOBS, + *ci.REQUIRED_CI_MICROVM_DEBUG_PUSH_JOBS, + }, + ) + artifacts: set[str] = set() + for job_name, inputs in jobs.items(): + system = "Windows" if "windows" in json.loads(inputs["runner"]) else "Linux" + debug = inputs.get("debug-kernel", False) is True + for attempt in (1, 2): + artifact = ( + name.replace("${{ runner.os }}", system) + .replace("${{ inputs.backend }}", inputs["backend"]) + .replace(kernel, "debug" if debug else "default") + .replace("${{ github.run_id }}", "39585909588") + .replace("${{ github.run_attempt }}", str(attempt)) + ) + with self.subTest(job=job_name, attempt=attempt): + self.assertNotIn("${{", artifact) + self.assertNotIn(artifact, artifacts) + artifacts.add(artifact) + self.assertIn("nvx-microvm-durations-Linux-kvm-debug-39585909588-2", artifacts) + self.assertEqual(len(artifacts), 2 * len(jobs)) + @unittest.skipUnless(os.name == "nt", "requires Windows PowerShell") def test_windows_cli_validation_stops_at_each_failed_command(self): action = (