diff --git a/sev_verify/README.md b/sev_verify/README.md index 95026c61..04a1aa7d 100644 --- a/sev_verify/README.md +++ b/sev_verify/README.md @@ -28,6 +28,12 @@ python3 -m sev_verify /path/to/guest.efi --artifacts-dir /data/sev-artifacts -v # Put results somewhere other than results/ python3 -m sev_verify /path/to/guest.efi --output-dir /data/sev-artifacts -v 3.0 + +# Enable debug logging (steps.log, guest logs, QEMU boot logs) +python3 -m sev_verify /path/to/guest.efi --debug -v 3.0 + +# Combine debug logging with custom artifacts directory +python3 -m sev_verify /path/to/guest.efi --debug --artifacts-dir /data/sev-artifacts -v 3.0 ``` ## How it works @@ -60,6 +66,36 @@ Prerequisite tests (no certification) use ``/prereqs// The harness creates the directory before the first step and prints ``Artifacts: …``. Callable steps use ``ctx.artifact_dir``; host shell steps get ``$SEV_VERIFY_ARTIFACT_DIR``. For ``guest_pull``, a *relative* ``host_dest`` is resolved under ``artifact_dir``; absolute paths are unchanged. +## Debug logging + +When ``--debug`` is enabled, the harness creates detailed logs for debugging test execution and guest behavior. These are written to the test's artifact directory (respects ``--artifacts-dir`` if specified): + +**Test-level logs:** +- ``steps.log`` — Step-by-step execution log with commands, exit codes, stdout/stderr, and timing + +**Per-guest logs** (under ``/``): +- ``qemu-command.log`` — Full QEMU command line used to launch the guest +- ``qemu-boot.log`` — Guest serial console output (kernel dmesg logs from boot through shutdown) +- ``qemu-error.log`` — QEMU stderr output for debugging launch failures +- ``guest-journal.log`` — Guest journald logs pulled via vsock before VM stop + +The ``guest_id`` defaults to a generated UUID, but can be set explicitly via ``Step.for_vm_launch(..., guest_id="vm-1")``. + +The boot log is written at both ``vm_launch`` (to capture logs if the guest crashes during boot) and ``vm_stop`` (to capture the complete dmesg including shutdown). The journal log is fetched via vsock just before stopping the VM. + +Example artifact structure with ``--debug`` (assuming ``guest_id="vm-1"``): +``` +artifacts/3.0/3.0.0-0/attestation_test/ +├── steps.log +├── vm-1/ +│ ├── steps.log +│ ├── qemu-command.log +│ ├── qemu-boot.log +│ ├── qemu-error.log +│ └── guest-journal.log +└── report.bin +``` + ## Layout ``` @@ -69,6 +105,7 @@ sev_verify/ Harness package runner.py load_test_execution_plan, run_step, run_vm_launch_step, … vm_profile.py VMProfile, QEMU argv, vm_launch / stop_vm guest_vsock.py vsock command channel to the guest + step_log.py Debug logging for steps and guest artifacts cert_tests/ Certification levels common/ Shared test modules snp_ok.py Example host-only test @@ -97,3 +134,5 @@ Invoke as `python3 -m sev_verify [flags]`. There are no subcomma | `--ovmf PATH` | test `VMProfile`, then host search paths | Override the OVMF firmware `.fd` for every test that launches a VM. Path must exist. | | `--allow-host-changes` | off | Allow tests to make host-level changes, such as firmware TCB settings (e.g. `snphost commit` advancing the committed TCB floor). These are boot-session-only and reset on reboot. Tests that may change host state are declared with `host_changes = true` in the manifest and listed at startup (grouped by level) along with whether this flag is active. | +`--output-dir` stores the final certification reports (JSON/Markdown summaries) generated after all tests complete, while `--artifacts-dir` stores per-test working files created during execution such as pulled binaries, logs, and intermediate data. + diff --git a/sev_verify/cert_tests/c3_0/c3_0_0_0/attestation_test.py b/sev_verify/cert_tests/c3_0/c3_0_0_0/attestation_test.py index 4dc18888..510b57be 100644 --- a/sev_verify/cert_tests/c3_0/c3_0_0_0/attestation_test.py +++ b/sev_verify/cert_tests/c3_0/c3_0_0_0/attestation_test.py @@ -47,15 +47,17 @@ def calculate_measurement(ctx: StepContext) -> StepHandlerResult: stderr=str(e), ) + cmd = [ + "snpguest", "generate", "measurement", + "--vcpu-type", "EPYC-v4", + "--ovmf", str(ovmf_path), + "--kernel", str(ctx.guest_path), + "--output-format", "hex", + "--measurement-file", str(measurement_file) + ] + cmd_str = " ".join(cmd) result = subprocess.run( - [ - "snpguest", "generate", "measurement", - "--vcpu-type", "EPYC-v4", - "--ovmf", str(ovmf_path), - "--kernel", str(ctx.guest_path), - "--output-format", "hex", - "--measurement-file", str(measurement_file), - ], + cmd, capture_output=True, text=True, check=False, @@ -65,12 +67,14 @@ def calculate_measurement(ctx: StepContext) -> StepHandlerResult: exit_code=result.returncode, stdout=result.stdout, stderr=result.stderr, + command=cmd_str, ) expected_measurement = measurement_file.read_text().strip() return StepHandlerResult( exit_code=0, stdout=f"Calculated expected measurement: {expected_measurement}", + command=cmd_str, ) @@ -87,13 +91,15 @@ def verify_report_fields(ctx: StepContext) -> StepHandlerResult: expected_measurement = measurement_file.read_text().strip() request_data = "0x" + str(request_file.read_bytes().hex()) + cmd = [ + "snpguest", "verify", "attestation", + str(ctx.artifact_dir), str(report_file), + "--measurement", str(expected_measurement), + "--report-data", str(request_data), + ] + cmd_str = " ".join(cmd) result = subprocess.run( - [ - "snpguest", "verify", "attestation", - str(ctx.artifact_dir), str(report_file), - "--measurement", str(expected_measurement), - "--report-data", str(request_data), - ], + cmd, capture_output=True, text=True, check=False, @@ -103,11 +109,13 @@ def verify_report_fields(ctx: StepContext) -> StepHandlerResult: exit_code=result.returncode, stdout=result.stdout, stderr=result.stderr, + command=cmd_str, ) return StepHandlerResult( exit_code=0, stdout="Successfully verified report data and measurement", + command=cmd_str, ) @@ -132,6 +140,7 @@ def steps() -> list[BaseStep]: ), Step.for_vm_launch( name="Launch SEV-SNP guest", + guest_id="vm-1", type="setup", timeout=300, ).add_hint( @@ -194,4 +203,5 @@ def steps() -> list[BaseStep]: type="info", timeout=60, ), + ] diff --git a/sev_verify/cert_tests/c3_0/c3_0_0_1/snphost_config_commit.py b/sev_verify/cert_tests/c3_0/c3_0_0_1/snphost_config_commit.py index 1b16532c..abaafcc7 100644 --- a/sev_verify/cert_tests/c3_0/c3_0_0_1/snphost_config_commit.py +++ b/sev_verify/cert_tests/c3_0/c3_0_0_1/snphost_config_commit.py @@ -125,11 +125,13 @@ def _parse_report_tcb_sections(report_path: str) -> dict[str, dict[str, str]]: def _verify_result(mode: str) -> StepHandlerResult: """Compare Reported vs Platform TCB; used by callable steps and the CLI.""" + cmd = "snphost show tcb" proc = _run_snphost_tcb() if proc.returncode != 0: return StepHandlerResult( exit_code=1, stderr=f"snphost show tcb failed: {proc.stderr.strip()}", + command=cmd, ) sections = _parse_tcb_sections(proc.stdout) @@ -144,13 +146,14 @@ def _verify_result(mode: str) -> StepHandlerResult: f" Reported: {reported}", f" Platform: {platform}", ] - return StepHandlerResult(exit_code=1, stderr="\n".join(lines)) + return StepHandlerResult(exit_code=1, stderr="\n".join(lines), command=cmd) if mode == "verify-differ" and match: return StepHandlerResult( exit_code=1, stderr="FAIL: Reported should differ from Platform after config set", + command=cmd, ) - return StepHandlerResult(exit_code=0) + return StepHandlerResult(exit_code=0, command=cmd) def verify_match(_ctx: StepContext) -> StepHandlerResult: @@ -433,6 +436,7 @@ def steps() -> list[BaseStep]: # 4. Boot a fresh VM (TCB was lowered before boot) Step.for_vm_launch( name="Launch SEV-SNP guest", + guest_id="vm-1", type="required", timeout=300, ).add_hint( diff --git a/sev_verify/cli.py b/sev_verify/cli.py index b523e814..f4e876a4 100644 --- a/sev_verify/cli.py +++ b/sev_verify/cli.py @@ -32,6 +32,7 @@ run_vm_stop_step, test_artifact_dir, ) +from .step_log import StepLogger from .vm_profile import ( DEFAULT_QEMU_BINARY, find_ovmf_path, @@ -39,6 +40,7 @@ VMProfileError, stop_vm, ) +from .guest_vsock import fetch_guest_journal, GuestVsockError _LINE_WIDTH = 80 @@ -123,6 +125,13 @@ def parse_args(argv: list[str] | None = None) -> argparse.Namespace: default=False, help="Allow making host-level changes, such as changing FW TCB settings.", ) + parser.add_argument( + "--debug", + action="store_true", + default=False, + help="Enable debug logging: create steps.log and per-guest log directories " + "with qemu-boot.log, qemu-error.log, qemu-command.log, and guest-journal.log", + ) return parser.parse_args(argv) @@ -361,6 +370,7 @@ def execute_test( ovmf_path: str | None = None, environment: dict[str, str | None] | None = None, allow_host_changes: bool = False, + debug: bool = False, ) -> TestResult: """Run a test, printing each step live as it executes.""" started_at = datetime.now(timezone.utc).isoformat() @@ -389,6 +399,8 @@ def execute_test( artifact_dir.mkdir(parents=True, exist_ok=True) _flush(f" Artifacts: {artifact_dir}") + step_logger = StepLogger(artifact_dir) if debug else None + profile = None if test.requires_vm: profile = effective_vm_profile( @@ -396,6 +408,7 @@ def execute_test( guest_path, qemu_binary=qemu_binary, ovmf_path=ovmf_path, + artifact_dir=artifact_dir, ) mod = import_test_module(test) @@ -449,6 +462,8 @@ def execute_test( if launch is not None and launch.ok and environment is not None: update_environment_with_guest_os(environment, launch.profile) elif step.kind == "vm_stop": + stopped_launch: VMLaunchResult | None = None + guest_journal_output: str | None = None if launch is None: sr = StepResult( step=step, @@ -457,8 +472,16 @@ def execute_test( duration_ms=0, ) else: + # Fetch guest journald logs before stopping the VM + try: + journal_result = fetch_guest_journal(launch.profile) + guest_journal_output = journal_result.stdout + except GuestVsockError: + # Guest may have already halted or vsock unavailable + guest_journal_output = None sr = run_vm_stop_step(step, launch) if sr.result != "error": + stopped_launch = launch launch = None elif step.kind == "host": sr = run_step(step, guest_path, artifact_dir) @@ -502,6 +525,20 @@ def execute_test( stderr=f"Unsupported step kind {step.kind!r}", ) step_results.append(sr) + # Log step details when debug is enabled + if step_logger is not None: + # For vm_stop, use the stopped_launch to get log paths and journal + active_launch = stopped_launch if step.kind == "vm_stop" and stopped_launch else launch + qemu_cmd = active_launch.command_line if active_launch is not None else None + guest_id = active_launch.guest_id if active_launch is not None else None + guest_error_log = active_launch.profile.guest_error_log if active_launch is not None else None + guest_boot_log = active_launch.profile.guest_boot_log if active_launch is not None else None + journal_for_log = guest_journal_output if step.kind == "vm_stop" else None + step_logger.log_step( + step, sr, command=qemu_cmd, guest_id=guest_id, + guest_error_log_path=guest_error_log, guest_boot_log_path=guest_boot_log, + guest_journal=journal_for_log, + ) _flush(_step_result_line(sr, is_last)) @@ -572,6 +609,7 @@ def execute_certification( ovmf_path: str | None = None, environment: dict[str, str | None] | None = None, allow_host_changes: bool = False, + debug: bool = False, ) -> CertificationResult: """Run all tests in a certification with live output.""" started_at = datetime.now(timezone.utc).isoformat() @@ -600,6 +638,7 @@ def execute_certification( ovmf_path=ovmf_path, environment=environment, allow_host_changes=allow_host_changes, + debug=debug, ) test_results.append(tr) overall = _worse_result(overall, tr.result) @@ -736,6 +775,7 @@ def main(argv: list[str] | None = None) -> int: ovmf_path=ovmf_override, environment=environment, allow_host_changes=args.allow_host_changes, + debug=args.debug, ) prereq_results.append(tr) _flush("") @@ -772,6 +812,7 @@ def main(argv: list[str] | None = None) -> int: ovmf_path=ovmf_override, environment=environment, allow_host_changes=args.allow_host_changes, + debug=args.debug, ) cert_results.append(cr) total_tests += len(cr.test_results) diff --git a/sev_verify/guest_vsock.py b/sev_verify/guest_vsock.py index c8cf6464..5589b84a 100644 --- a/sev_verify/guest_vsock.py +++ b/sev_verify/guest_vsock.py @@ -268,3 +268,17 @@ def pull_guest_file_to_host( host_path = Path(host_path) host_path.parent.mkdir(parents=True, exist_ok=True) host_path.write_bytes(data) + + +def fetch_guest_journal( + profile: VMProfile, + *, + timeout: float | None = None, +) -> GuestCommandResult: + """ + Fetch the guest's journald logs via vsock. + + Runs ``journalctl --no-pager -b`` on the guest to get all logs from current boot. + """ + cmd = "journalctl --no-pager -b" + return run_guest_command(profile, cmd, timeout=timeout) diff --git a/sev_verify/models.py b/sev_verify/models.py index 853451fb..ec840269 100644 --- a/sev_verify/models.py +++ b/sev_verify/models.py @@ -50,6 +50,9 @@ class BaseStep: handler: str = "" guest_src: str = "" host_dest: str = "" + # Guest identifier for vm_launch steps (used in debug log directory names). + # If not set, defaults to a generated UUID. + guest_id: str = "" # Diagnostic hints shown on failure: list of (grep_pattern, message) pairs. # If *grep_pattern* appears in stderr or stdout, *message* is printed as a hint. hints: list[tuple[str, str]] = field(default_factory=list) @@ -72,32 +75,49 @@ def __post_init__(self) -> None: f"Step {self.name!r}: timeout must be positive, got {self.timeout}" ) - if self.kind in ("vm_launch", "vm_stop"): + if self.kind == "vm_launch": if self.command: raise ValueError( - f"Step {self.name!r}: {self.kind} steps must use an empty command" + f"Step {self.name!r}: vm_launch steps must use an empty command" ) if self.guest_src or self.host_dest: raise ValueError( - f"Step {self.name!r}: {self.kind} steps must not set guest_src/host_dest" + f"Step {self.name!r}: vm_launch steps must not set guest_src/host_dest" ) if self.handler: raise ValueError( - f"Step {self.name!r}: {self.kind} steps must not set handler" + f"Step {self.name!r}: vm_launch steps must not set handler" + ) + elif self.kind == "vm_stop": + if self.command: + raise ValueError( + f"Step {self.name!r}: vm_stop steps must use an empty command" + ) + if self.guest_src or self.host_dest: + raise ValueError( + f"Step {self.name!r}: vm_stop steps must not set guest_src/host_dest" + ) + if self.handler: + raise ValueError( + f"Step {self.name!r}: vm_stop steps must not set handler" + ) + if self.guest_id: + raise ValueError( + f"Step {self.name!r}: vm_stop steps must not set guest_id (use it on vm_launch)" ) elif self.kind == "host": if not self.command: raise ValueError(f"Step {self.name!r}: host steps require a non-empty command") - if self.guest_src or self.host_dest or self.handler: + if self.guest_src or self.host_dest or self.handler or self.guest_id: raise ValueError( - f"Step {self.name!r}: host steps must only set command (not handler/paths)" + f"Step {self.name!r}: host steps must only set command (not handler/paths/guest_id)" ) elif self.kind == "guest": if not self.command: raise ValueError(f"Step {self.name!r}: guest steps require a non-empty command") - if self.guest_src or self.host_dest or self.handler: + if self.guest_src or self.host_dest or self.handler or self.guest_id: raise ValueError( - f"Step {self.name!r}: guest steps must only set command (not handler/paths)" + f"Step {self.name!r}: guest steps must only set command (not handler/paths/guest_id)" ) elif self.kind == "guest_pull": if not self.guest_src: @@ -108,9 +128,9 @@ def __post_init__(self) -> None: raise ValueError( f"Step {self.name!r}: guest_pull steps require host_dest (path on host)" ) - if self.command or self.handler: + if self.command or self.handler or self.guest_id: raise ValueError( - f"Step {self.name!r}: guest_pull steps must not set command or handler" + f"Step {self.name!r}: guest_pull steps must not set command, handler, or guest_id" ) elif self.kind == "callable": if not self.handler: @@ -118,9 +138,9 @@ def __post_init__(self) -> None: f"Step {self.name!r}: callable steps require a non-empty handler " f"(function name on the test module)" ) - if self.command or self.guest_src or self.host_dest: + if self.command or self.guest_src or self.host_dest or self.guest_id: raise ValueError( - f"Step {self.name!r}: callable steps must not set command, guest_src, or host_dest" + f"Step {self.name!r}: callable steps must not set command, guest_src, host_dest, or guest_id" ) _validate_expected_result_format(self.name, self.expected_result) @@ -166,8 +186,8 @@ def host(self, command: str) -> BaseStep: def guest(self, command: str) -> BaseStep: return BaseStep(kind="guest", command=command, **self._common()) - def vm_launch(self) -> BaseStep: - return BaseStep(kind="vm_launch", **self._common()) + def vm_launch(self, guest_id: str = "") -> BaseStep: + return BaseStep(kind="vm_launch", guest_id=guest_id, **self._common()) def vm_stop(self) -> BaseStep: return BaseStep(kind="vm_stop", **self._common()) @@ -219,10 +239,11 @@ def for_vm_launch( *, expected_result: str = "exit_code:0", timeout: int = 10, + guest_id: str = "", ) -> BaseStep: return cls( name=name, type=type, expected_result=expected_result, timeout=timeout - ).vm_launch() + ).vm_launch(guest_id=guest_id) @classmethod def for_vm_stop( @@ -343,6 +364,7 @@ class StepResult: stdout: str | None = None stderr: str | None = None duration_ms: int | None = None + command: str | None = None @dataclass @@ -352,6 +374,7 @@ class StepHandlerResult: exit_code: int = 0 stdout: str = "" stderr: str = "" + command: str | None = None @dataclass diff --git a/sev_verify/runner.py b/sev_verify/runner.py index e4f9321d..514a2174 100644 --- a/sev_verify/runner.py +++ b/sev_verify/runner.py @@ -3,6 +3,7 @@ from __future__ import annotations import os +import shlex import subprocess import time from importlib import import_module @@ -169,8 +170,14 @@ def run_step(step: BaseStep, guest_path: Path, artifact_dir: Path | None = None) def run_vm_launch_step( step: BaseStep, profile: VMProfile, ) -> tuple[StepResult, VMLaunchResult | None]: - """Start the guest described by ``profile``. Returns ``(StepResult, launch or None)``.""" + """Start the guest described by ``profile``. Returns ``(StepResult, launch or None)``. + + If the step has a ``guest_id`` set, it overrides the profile's guest_id. + """ start = time.monotonic() + # Override profile's guest_id if the step specifies one + if step.guest_id: + profile = replace(profile, guest_id=step.guest_id) try: launch = profile.vm_launch() except VMProfileError as exc: @@ -209,6 +216,7 @@ def run_vm_launch_step( def run_vm_stop_step(step: BaseStep, launch: VMLaunchResult) -> StepResult: """Terminate QEMU for ``launch`` (``stop_vm``; ``step.timeout`` is the wait/kill window).""" start = time.monotonic() + stop_cmd = f"kill -15 {launch.pid}" try: stop_vm(launch, timeout=float(step.timeout)) except OSError as exc: @@ -218,6 +226,7 @@ def run_vm_stop_step(step: BaseStep, launch: VMLaunchResult) -> StepResult: result="error", stderr=str(exc), duration_ms=duration_ms, + command=stop_cmd, ) duration_ms = int((time.monotonic() - start) * 1000) msg = "Guest VM stopped" @@ -228,6 +237,7 @@ def run_vm_stop_step(step: BaseStep, launch: VMLaunchResult) -> StepResult: exit_code=0 if passed else 1, stdout=msg, duration_ms=duration_ms, + command=stop_cmd, ) @@ -269,6 +279,7 @@ def run_guest_pull_step( host_path = Path(step.host_dest) if artifact_dir is not None and not host_path.is_absolute(): host_path = artifact_dir / host_path + guest_cmd = f"base64 {shlex.quote(step.guest_src)}" try: pull_guest_file_to_host( profile, @@ -283,6 +294,7 @@ def run_guest_pull_step( result="error", stderr=str(exc), duration_ms=duration_ms, + command=guest_cmd, ) duration_ms = int((time.monotonic() - start) * 1000) passed = _check_expected_values(step, 0, "") @@ -290,7 +302,9 @@ def run_guest_pull_step( step=step, result="pass" if passed else "fail", exit_code=0, + stdout=f"Pulled {step.guest_src} -> {host_path}", duration_ms=duration_ms, + command=guest_cmd, ) @@ -357,6 +371,7 @@ def run_callable_step(step: BaseStep, ctx: StepContext) -> StepResult: stdout=hr.stdout or None, stderr=hr.stderr or None, duration_ms=duration_ms, + command=hr.command, ) @@ -366,6 +381,7 @@ def effective_vm_profile( *, qemu_binary: str | None = None, ovmf_path: str | None = None, + artifact_dir: Path | None = None, ) -> VMProfile: """ Merge CLI guest path (and optional QEMU / OVMF overrides) into a profile. @@ -373,6 +389,9 @@ def effective_vm_profile( The ``path_to_guest`` argument always supplies the bootable guest image; ``declared`` supplies QEMU, vsock, and SEV-SNP options from the test module. Non-``None`` ``qemu_binary`` / ``ovmf_path`` override the merged profile. + + When ``artifact_dir`` is provided, guest log files are written there instead + of /tmp to avoid conflicts with concurrent test runs. """ if declared is None: @@ -384,4 +403,10 @@ def effective_vm_profile( base = replace(base, qemu_binary=qemu_binary) if ovmf_path is not None: base = replace(base, ovmf_path=ovmf_path) + if artifact_dir is not None: + base = replace( + base, + guest_error_log=str(artifact_dir / "qemu-error.log"), + guest_boot_log=str(artifact_dir / "qemu-boot.log"), + ) return base diff --git a/sev_verify/step_log.py b/sev_verify/step_log.py new file mode 100644 index 00000000..9ef55c2f --- /dev/null +++ b/sev_verify/step_log.py @@ -0,0 +1,249 @@ +"""Step execution logging for debugging.""" + +from __future__ import annotations + +import shutil +from datetime import datetime, timezone +from pathlib import Path +from typing import TYPE_CHECKING, TextIO + +if TYPE_CHECKING: + from .models import BaseStep, StepResult + + +class StepLogger: + """Writes step execution details to the artifact directory. + + Maintains both a main steps.log and per-guest logs under /steps.log + for easier debugging when multiple guests are launched. The guest_id defaults + to a generated UUID if not explicitly set on the vm_launch step. + + Per-guest directories also contain: + - qemu-command.log: The full QEMU command line used to launch the guest + - qemu-boot.log: Guest serial console output (dmesg logs) + - qemu-error.log: QEMU stderr output for debugging launch failures + - guest-journal.log: Guest journald logs (pulled via vsock before vm_stop) + """ + + def __init__(self, artifact_dir: Path) -> None: + self.artifact_dir = artifact_dir + self.log_path = artifact_dir / "steps.log" + self._current_guest_id: str | None = None + self._current_guest_dir: Path | None = None + self._guest_log_path: Path | None = None + + def _ts(self) -> str: + return datetime.now(timezone.utc).isoformat(timespec="milliseconds") + + def _set_guest_context(self, guest_id: str | None) -> None: + """Update the current guest context and create guest directory if needed.""" + if guest_id and guest_id != self._current_guest_id: + self._current_guest_id = guest_id + guest_dir = self.artifact_dir / guest_id + guest_dir.mkdir(parents=True, exist_ok=True) + self._current_guest_dir = guest_dir + self._guest_log_path = guest_dir / "steps.log" + elif guest_id is None: + self._current_guest_id = None + self._current_guest_dir = None + self._guest_log_path = None + + def _write_qemu_command_log(self, command: str) -> None: + """Write the QEMU command to qemu-command.log in the guest directory.""" + if self._current_guest_dir is None: + return + cmd_log = self._current_guest_dir / "qemu-command.log" + with open(cmd_log, "w") as f: + f.write(f"# QEMU command for guest {self._current_guest_id}\n") + f.write(f"# Timestamp: {self._ts()}\n\n") + f.write(command) + f.write("\n") + + def _write_qemu_boot_log(self, stdout: str | None) -> None: + """Write boot messages to qemu-boot.log in the guest directory.""" + if self._current_guest_dir is None: + return + boot_log = self._current_guest_dir / "qemu-boot.log" + with open(boot_log, "w") as f: + f.write(f"# Boot log for guest {self._current_guest_id}\n") + f.write(f"# Timestamp: {self._ts()}\n\n") + if stdout: + f.write(stdout) + if not stdout.endswith("\n"): + f.write("\n") + else: + f.write("(no boot output captured)\n") + + def _write_qemu_error_log(self, stderr: str | None) -> None: + """Write QEMU errors to qemu-error.log in the guest directory.""" + if self._current_guest_dir is None: + return + error_log = self._current_guest_dir / "qemu-error.log" + with open(error_log, "w") as f: + f.write(f"# Error log for guest {self._current_guest_id}\n") + f.write(f"# Timestamp: {self._ts()}\n\n") + if stderr: + f.write(stderr) + if not stderr.endswith("\n"): + f.write("\n") + else: + f.write("(no errors)\n") + + def _copy_guest_error_log(self, error_log_path: str) -> None: + """Copy the QEMU guest error log to the guest directory.""" + if self._current_guest_dir is None: + return + src = Path(error_log_path) + if src.is_file(): + dest = self._current_guest_dir / "qemu-error.log" + shutil.copy2(src, dest) + + def _copy_guest_boot_log(self, boot_log_path: str) -> None: + """Copy the QEMU guest boot log (serial console output) to the guest directory.""" + if self._current_guest_dir is None: + return + src = Path(boot_log_path) + if src.is_file(): + dest = self._current_guest_dir / "qemu-boot.log" + shutil.copy2(src, dest) + + def _write_guest_journal_log(self, journal_output: str | None) -> None: + """Write guest journald logs to guest-journal.log in the guest directory.""" + if self._current_guest_dir is None: + return + journal_log = self._current_guest_dir / "guest-journal.log" + with open(journal_log, "w") as f: + f.write(f"# Guest journal log for guest {self._current_guest_id}\n") + f.write(f"# Timestamp: {self._ts()}\n\n") + if journal_output: + f.write(journal_output) + if not journal_output.endswith("\n"): + f.write("\n") + else: + f.write("(no journal output captured)\n") + + def _write_step_entry( + self, + f: TextIO, + step: "BaseStep", + result: "StepResult", + *, + command: str | None = None, + guest_id: str | None = None, + ) -> None: + """Write a single step entry to a file handle.""" + f.write(f"Step: {step.name}\n") + f.write(f"Kind: {step.kind}\n") + f.write(f"Type: {step.type}\n") + f.write(f"Timestamp: {self._ts()}\n") + if step.kind == "host": + f.write(f"Command: {step.command}\n") + elif step.kind == "guest": + if guest_id: + f.write(f"Guest ID: {guest_id}\n") + f.write(f"Command: {step.command}\n") + elif step.kind == "callable": + f.write(f"Handler: {step.handler}\n") + if result.command: + f.write(f"Command: {result.command}\n") + elif step.kind == "guest_pull": + if guest_id: + f.write(f"Guest ID: {guest_id}\n") + f.write(f"Pull: {step.guest_src} -> {step.host_dest}\n") + if result.command: + f.write(f"Command to read the guest file {step.guest_src}: {result.command}\n") + elif step.kind == "vm_launch": + if guest_id: + f.write(f"Guest ID: {guest_id}\n") + if command: + f.write(f"Command: {command}\n") + elif step.kind == "vm_stop": + if guest_id: + f.write(f"Guest ID: {guest_id}\n") + if result.command: + f.write(f"Command: {result.command}\n") + f.write(f"Duration: {result.duration_ms}ms\n") + f.write(f"Status: {result.result.upper()}") + if result.exit_code is not None: + f.write(f" (exit={result.exit_code})") + f.write("\n") + if result.stdout: + f.write(f"[stdout]\n{result.stdout}") + if not result.stdout.endswith("\n"): + f.write("\n") + if result.stderr: + f.write(f"[stderr]\n{result.stderr}") + if not result.stderr.endswith("\n"): + f.write("\n") + f.write("-" * 60 + "\n") + + def log_step( + self, + step: "BaseStep", + result: "StepResult", + *, + command: str | None = None, + guest_id: str | None = None, + guest_error_log_path: str | None = None, + guest_boot_log_path: str | None = None, + guest_journal: str | None = None, + ) -> None: + """Log a step to the main log and optionally to a guest-specific log. + + When a guest_id is provided (typically for vm_launch, guest, guest_pull, + and vm_stop steps), the step is also logged to /steps.log. + + For vm_launch steps, creates: + - qemu-command.log: The full QEMU command line + - qemu-boot.log: Guest serial console output (initial dmesg logs) + - qemu-error.log: QEMU stderr + + For vm_stop steps, updates: + - qemu-boot.log: Complete serial console output (full dmesg) + - qemu-error.log: QEMU stderr + - guest-journal.log: Guest journald logs (pulled via vsock) + """ + # Update guest context on vm_launch or when guest_id changes + if step.kind == "vm_launch" and guest_id: + self._set_guest_context(guest_id) + # Write QEMU command log at launch time + if command: + self._write_qemu_command_log(command) + # Copy initial boot log at launch (captures logs if guest crashes mid-boot) + if guest_boot_log_path: + self._copy_guest_boot_log(guest_boot_log_path) + else: + self._write_qemu_boot_log(result.stdout) + if guest_error_log_path: + self._copy_guest_error_log(guest_error_log_path) + else: + self._write_qemu_error_log(result.stderr) + elif step.kind in ("guest", "guest_pull") and guest_id and self._current_guest_id != guest_id: + # Update guest context if it changed (e.g., switching between multiple guests) + self._set_guest_context(guest_id) + elif step.kind == "vm_stop": + # Copy complete boot and error logs at vm_stop (overwrites with full dmesg) + if guest_boot_log_path: + self._copy_guest_boot_log(guest_boot_log_path) + else: + self._write_qemu_boot_log(result.stdout) + if guest_error_log_path: + self._copy_guest_error_log(guest_error_log_path) + else: + self._write_qemu_error_log(result.stderr) + # Write guest journald logs + if guest_journal: + self._write_guest_journal_log(guest_journal) + + # Always write to the main log + with open(self.log_path, "a") as f: + self._write_step_entry(f, step, result, command=command, guest_id=guest_id) + + # Write to guest-specific log if we have a guest context + if self._guest_log_path is not None: + with open(self._guest_log_path, "a") as f: + self._write_step_entry(f, step, result, command=command, guest_id=guest_id) + + # Clear guest context after vm_stop + if step.kind == "vm_stop": + self._set_guest_context(None) diff --git a/sev_verify/vm_profile.py b/sev_verify/vm_profile.py index d042efb3..d45a8964 100644 --- a/sev_verify/vm_profile.py +++ b/sev_verify/vm_profile.py @@ -13,6 +13,7 @@ import subprocess import sys import time +import uuid from dataclasses import dataclass, field, fields from pathlib import Path from typing import Any, TextIO @@ -33,6 +34,7 @@ def find_ovmf_path() -> str | None: DEFAULT_GUEST_ERROR_LOG = "/tmp/guest-error.log" +DEFAULT_GUEST_BOOT_LOG = "/tmp/guest-boot.log" DEFAULT_QEMU_BINARY = "qemu-system-x86_64" DEFAULT_MEMORY_MB = 4096 DEFAULT_VSOCK_CID = 3 @@ -89,11 +91,15 @@ class VMProfile: """Launch-time configuration for an SEV-SNP guest.""" # QEMU variables with non-default values image_path: str + # Unique identifier for this guest launch (auto-generated if not provided). + # Useful when multiple guests are launched within the same test run. + guest_id: str | None = None # QEMU variables qemu_binary: str = DEFAULT_QEMU_BINARY ovmf_path: str | None = None memory_mb: int = DEFAULT_MEMORY_MB guest_error_log: str = DEFAULT_GUEST_ERROR_LOG + guest_boot_log: str = DEFAULT_GUEST_BOOT_LOG # QEMU user-mode NAT: guest outbound Internet (e.g. certificate downloads). network_enabled: bool = True # Host↔guest command channel over AF_VSOCK (see :mod:`guest_vsock`). @@ -202,6 +208,10 @@ def vm_launch( error_log = Path(self.guest_error_log) error_log.parent.mkdir(parents=True, exist_ok=True) + boot_log = Path(self.guest_boot_log) + boot_log.parent.mkdir(parents=True, exist_ok=True) + # Truncate boot log to avoid stale data from previous runs + boot_log.write_bytes(b"") with open(error_log, "wb") as err_file: process = subprocess.Popen( @@ -245,6 +255,7 @@ def vm_launch( elif message == "VM launch verified": message = "VM launched and guest booted" + effective_guest_id = self.guest_id if self.guest_id else str(uuid.uuid4()) return VMLaunchResult( pid=process.pid, command=command, @@ -252,6 +263,7 @@ def vm_launch( process=process, ok=ok, message=message, + guest_id=effective_guest_id, ) @@ -264,6 +276,7 @@ class VMLaunchResult: profile: VMProfile ok: bool message: str + guest_id: str checks: dict[str, bool] = field(default_factory=dict) process: subprocess.Popen[bytes] | None = None @@ -271,6 +284,16 @@ class VMLaunchResult: def command_line(self) -> str: return " ".join(shlex.quote(part) for part in self.command) + @property + def boot_log_path(self) -> str: + """Path to the guest boot log (serial console output).""" + return self.profile.guest_boot_log + + @property + def error_log_path(self) -> str: + """Path to the QEMU error log (stderr).""" + return self.profile.guest_error_log + def _format_policy(policy: str | int) -> str: if isinstance(policy, int): @@ -333,6 +356,11 @@ def build_qemu_command(profile: VMProfile) -> list[str]: profile.image_path, "-device", _build_vsock_device(profile), + # Serial console to capture guest boot logs (dmesg output) + "-chardev", + f"file,id=serial0,path={profile.guest_boot_log}", + "-serial", + "chardev:serial0", ] if profile.network_enabled: