Add --debug flag for step-level execution logging

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 ``<artifacts-dir>/prereqs/<test_name>/
 
 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 ``<guest_id>/``):
+- ``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 <path_to_guest> [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.
+

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,
         ),
+
     ]

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(

sev_verify/cli.py

@@ -32,13 +32,15 @@
     run_vm_stop_step,
     test_artifact_dir,
 )
+from .step_log import StepLogger
 from .vm_profile import (
     DEFAULT_QEMU_BINARY,
     find_ovmf_path,
     VMLaunchResult,
     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,13 +399,16 @@ 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(
                 declared_profile,
                 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)

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)