test: attach krkn execution logs to HTML report and assert scenario executed (#1395)

* test: attach krkn execution logs to HTML report and assert scenario executed

CI/tests_v2 enhancements for observability and false-positive guarding:

- run_kraken fixture stashes stdout/stderr/returncode on request.node so the
  report hook can attach them.
- conftest pytest_runtest_makereport renders the krkn log as a timestamp/level/
  message table via pytest_html.extras for every test (pass or fail).
- conftest pytest_terminal_summary prints an execution-evidence table and writes
  a markdown summary to $GITHUB_STEP_SUMMARY when running in GitHub Actions.
- utils adds SCENARIO_EXECUTION_MARKERS, an EXECUTION_EVIDENCE registry, and
  assert_scenario_executed() that fails happy-path tests when krkn exits 0 but
  no scenario-specific marker is present. Skipped under KRKN_TEST_DRY_RUN=1.
- pod_disruption, storage_throttle, and application_outage happy-path tests now
  call assert_scenario_executed. Negative tests remain exempt.

Closes #1394

* test: stash krkn logs on timeout and add log-path hint to evidence assert

Address Deep Code Review feedback on PR #1395:
- run_kraken now catches subprocess.TimeoutExpired, stashes partial
  stdout/stderr with a synthetic rc=124 so timed-out runs still attach
  logs to the HTML report.
- assert_scenario_executed failure message now includes the
  'Full logs:' tmp_path hint, matching assert_kraken_success/failure.

---------

Co-authored-by: augmentcode[bot] <185243770+augmentcode[bot]@users.noreply.github.com>
This commit is contained in:
augmentcode[bot]
2026-06-11 18:41:12 +05:30
committed by GitHub
co-authored by lnx01
parent f8c0766ebc
commit 5a532190aa
6 changed files with 237 additions and 8 deletions
+111
View File
@@ -3,11 +3,23 @@ Shared fixtures for pytest functional tests (CI/tests_v2).
Tests must be run from the repository root so run_kraken.py and config paths resolve.
"""
import html as html_lib
import logging
import os
import re
from pathlib import Path
import pytest
# Matches Krkn's log format "%(asctime)s [%(levelname)s] %(message)s" so each line can be
# rendered as a Timestamp/Level/Message row in the HTML report; non-matching lines (banner,
# tracebacks) fall back to a single Message cell.
_KRAKEN_LOG_LINE_RE = re.compile(
r"^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}(?:[,.]\d+)?)\s+\[(\w+)\]\s+(.*)$"
)
# Cap rows per run so a chatty scenario can't bloat the HTML report.
_KRAKEN_LOG_MAX_LINES = 1000
def pytest_addoption(parser):
parser.addoption(
@@ -24,12 +36,111 @@ def pytest_addoption(parser):
)
def _kraken_log_html(outputs, evidence):
"""Render stashed Krkn stdout/stderr (and the evidence verdict) as an HTML block for the report."""
parts = ["<div><strong>Krkn Execution Log</strong></div>"]
for idx, out in enumerate(outputs, 1):
combined = ((out.get("stdout") or "") + "\n" + (out.get("stderr") or "")).strip("\n")
lines = combined.splitlines() if combined else []
if len(outputs) > 1:
parts.append(f"<div><em>Run {idx} (rc={out.get('returncode')})</em></div>")
if len(lines) > _KRAKEN_LOG_MAX_LINES:
parts.append(
f"<div><em>(showing last {_KRAKEN_LOG_MAX_LINES} of {len(lines)} lines)</em></div>"
)
lines = lines[-_KRAKEN_LOG_MAX_LINES:]
parts.append(
'<table style="border-collapse:collapse;font-family:monospace;font-size:12px">'
"<tr><th style='text-align:left;padding:2px 8px'>Timestamp</th>"
"<th style='text-align:left;padding:2px 8px'>Level</th>"
"<th style='text-align:left;padding:2px 8px'>Message</th></tr>"
)
for line in lines:
m = _KRAKEN_LOG_LINE_RE.match(line)
ts, lvl, msg = (m.group(1), m.group(2), m.group(3)) if m else ("", "", line)
parts.append(
"<tr>"
f"<td style='padding:2px 8px;white-space:nowrap'>{html_lib.escape(ts)}</td>"
f"<td style='padding:2px 8px'>{html_lib.escape(lvl)}</td>"
f"<td style='padding:2px 8px'>{html_lib.escape(msg)}</td>"
"</tr>"
)
parts.append("</table>")
if evidence is not None:
mark = "✓ Matched" if evidence["verified"] else "✗ No match for"
parts.append(
f"<div><strong>Execution Evidence:</strong> {mark} "
f"<code>{html_lib.escape(evidence['pattern'])}</code></div>"
)
return "".join(parts)
@pytest.hookimpl(tryfirst=True, hookwrapper=True)
def pytest_runtest_makereport(item, call):
pytest_html = item.config.pluginmanager.getplugin("html")
outcome = yield
rep = outcome.get_result()
setattr(item, f"rep_{rep.when}", rep)
if rep.when != "call":
return
from lib.utils import EXECUTION_EVIDENCE # local import: lib is on path at runtime
evidence = EXECUTION_EVIDENCE.get(item.nodeid)
if evidence is not None:
# user_properties survive pytest-xdist worker -> controller transport so the
# terminal-summary hook (running on the controller) can build the table.
rep.user_properties.append(
("kraken_evidence", "verified" if evidence["verified"] else "missing")
)
outputs = getattr(item, "_kraken_outputs", None)
if pytest_html is not None and outputs:
extras = getattr(rep, "extras", [])
extras.append(pytest_html.extras.html(_kraken_log_html(outputs, evidence)))
rep.extras = extras
def pytest_terminal_summary(terminalreporter, exitstatus, config):
"""Print and (in GitHub Actions) write the execution-evidence summary table."""
reports = terminalreporter.stats.get("passed", []) + terminalreporter.stats.get("failed", [])
rows = []
for rep in reports:
if getattr(rep, "when", None) != "call":
continue
evidence = None
for name, value in getattr(rep, "user_properties", []):
if name == "kraken_evidence":
evidence = value
if evidence == "verified":
ev = "✓ Verified"
elif evidence == "missing":
ev = "✗ No evidence"
else:
ev = ""
result = "PASSED" if rep.passed else "FAILED"
rows.append((rep.nodeid, result, ev))
if not rows:
return
rows.sort()
terminalreporter.write_sep("=", "Execution Evidence Summary")
for nodeid, result, ev in rows:
terminalreporter.write_line(f"{result:<6} {ev:<14} {nodeid}")
summary_path = os.environ.get("GITHUB_STEP_SUMMARY")
if summary_path:
try:
with open(summary_path, "a") as f:
f.write("\n### Execution Evidence Summary\n\n")
f.write("| Test | Result | Execution Evidence |\n")
f.write("|------|--------|--------------------|\n")
for nodeid, result, ev in rows:
f.write(f"| `{nodeid}` | {result} | {ev} |\n")
except Exception as e:
logging.getLogger(__name__).warning(
"Could not write GITHUB_STEP_SUMMARY: %s", e
)
def _repo_root() -> Path:
"""Repository root (directory containing run_kraken.py and CI/)."""
+42 -8
View File
@@ -22,21 +22,55 @@ def _kraken_cmd(config_path: str, repo_root: Path):
return [python, "run_kraken.py", "-c", str(config_path)]
def _as_text(value):
"""Coerce subprocess output (str/bytes/None) to text for the HTML report."""
if value is None:
return ""
if isinstance(value, bytes):
return value.decode("utf-8", "replace")
return value
def _stash_kraken_output(request, result):
"""Stash a Kraken run's stdout/stderr on the test node so the HTML report hook can attach it."""
outputs = getattr(request.node, "_kraken_outputs", None)
if outputs is None:
outputs = []
request.node._kraken_outputs = outputs
outputs.append(
{
"returncode": result.returncode,
"stdout": result.stdout or "",
"stderr": result.stderr or "",
}
)
@pytest.fixture
def run_kraken(repo_root):
def run_kraken(repo_root, request):
"""Run Kraken with the given config path. Returns CompletedProcess. Default timeout 300s."""
def run(config_path, timeout=300, extra_args=None):
cmd = _kraken_cmd(config_path, repo_root)
if extra_args:
cmd.extend(extra_args)
return subprocess.run(
cmd,
cwd=repo_root,
capture_output=True,
text=True,
timeout=timeout,
)
try:
result = subprocess.run(
cmd,
cwd=repo_root,
capture_output=True,
text=True,
timeout=timeout,
)
except subprocess.TimeoutExpired as exc:
# Stash partial output (rc=124 = timeout) so timed-out runs still attach logs.
timed_out = subprocess.CompletedProcess(
cmd, 124, _as_text(exc.stdout), _as_text(exc.stderr)
)
_stash_kraken_output(request, timed_out)
raise
_stash_kraken_output(request, result)
return result
return run
+65
View File
@@ -3,6 +3,8 @@ Shared helpers for CI/tests_v2 functional tests.
"""
import logging
import os
import re
import time
from pathlib import Path
from typing import List, Optional, Union
@@ -13,6 +15,31 @@ from kubernetes.client import V1NetworkPolicy, V1NetworkPolicyList, V1Pod, V1Pod
logger = logging.getLogger(__name__)
# Per-scenario regex markers that prove the scenario actually executed its core logic.
# A scenario exiting rc=0 without one of these lines in its stdout/stderr is a silent
# no-op (e.g. a selector matched nothing) and the happy-path test should fail.
SCENARIO_EXECUTION_MARKERS = {
"pod_disruption": r"Deleting pod |waiting up to .* seconds for pod recovery",
"application_outage": r"Creating the network policy|Deleting the network policy",
"storage_throttle": r"Setting io\.max|Verified blkio settings|Privileged pod deployed",
}
# nodeid -> {"scenario", "pattern", "verified"}; consumed by conftest to build the
# HTML report evidence line and the GitHub Actions execution-evidence summary table.
# Last-write-wins per nodeid so multi-run tests and reruns report their final state.
EXECUTION_EVIDENCE = {}
def _record_execution_evidence(scenario_name: str, pattern: str, verified: bool) -> None:
"""Record evidence result keyed by the current test nodeid (from PYTEST_CURRENT_TEST)."""
nodeid = os.environ.get("PYTEST_CURRENT_TEST", "").split(" (")[0]
if nodeid:
EXECUTION_EVIDENCE[nodeid] = {
"scenario": scenario_name,
"pattern": pattern,
"verified": verified,
}
def _pods(pod_list: Union[V1PodList, List[V1Pod]]) -> List[V1Pod]:
"""Normalize V1PodList or list of V1Pod to list of V1Pod."""
@@ -210,3 +237,41 @@ def assert_kraken_failure(result, context: str = "", tmp_path=None) -> None:
f"--- stderr ---\n{result.stderr or '(empty)'}\n"
f"--- stdout (last 20 lines) ---\n{tail_stdout}"
)
def assert_scenario_executed(result, scenario_name: str, context: str = "", tmp_path=None) -> None:
"""
Assert that Krkn actually executed the scenario's core logic by matching a
scenario-specific marker in stdout/stderr. Guards against false positives where
Krkn exits 0 but silently did nothing (e.g. a selector that matches no targets).
Skipped when KRKN_TEST_DRY_RUN=1. Negative tests must not call this helper.
"""
if os.environ.get("KRKN_TEST_DRY_RUN", "0") == "1":
return
pattern = SCENARIO_EXECUTION_MARKERS.get(scenario_name)
if pattern is None:
raise AssertionError(
f"No execution-evidence marker defined for scenario {scenario_name!r}. "
"Add one to SCENARIO_EXECUTION_MARKERS in CI/tests_v2/lib/utils.py."
)
combined = f"{result.stdout or ''}\n{result.stderr or ''}"
found = re.search(pattern, combined) is not None
_record_execution_evidence(scenario_name, pattern, found)
if found:
return
if tmp_path is not None:
try:
(tmp_path / "kraken_stdout.log").write_text(result.stdout or "")
(tmp_path / "kraken_stderr.log").write_text(result.stderr or "")
except Exception as e:
logger.warning("Could not write Kraken logs to tmp_path: %s", e)
lines = combined.splitlines()
tail = "\n".join(lines[-30:]) if lines else "(empty)"
context_str = f" {context}" if context else ""
path_hint = f"\nFull logs: {tmp_path}/kraken_stdout.log, {tmp_path}/kraken_stderr.log" if tmp_path else ""
raise AssertionError(
f"Scenario {scenario_name!r} exited {result.returncode} but no execution evidence found"
f"{context_str}.{path_hint}\nExpected pattern: {pattern}\n"
f"--- krkn output (last 30 lines) ---\n{tail}"
)
@@ -18,6 +18,7 @@ from lib.utils import (
assert_kraken_failure,
assert_kraken_success,
assert_pod_count_unchanged,
assert_scenario_executed,
find_network_policy_by_prefix,
get_network_policies_list,
get_pods_list,
@@ -82,6 +83,10 @@ class TestApplicationOutage(BaseScenarioTest):
assert_kraken_success(
result, context=f"{context_name} namespace={ns}", tmp_path=self.tmp_path
)
assert_scenario_executed(
result, self.SCENARIO_NAME,
context=f"{context_name} namespace={ns}", tmp_path=self.tmp_path,
)
after = get_pods_list(self.k8s_core, ns, self.LABEL_SELECTOR)
assert_pod_count_unchanged(before, after, namespace=ns)
assert_all_pods_running_and_ready(after, namespace=ns)
@@ -11,6 +11,7 @@ from lib.utils import (
assert_all_pods_running_and_ready,
assert_kraken_success,
assert_pod_count_unchanged,
assert_scenario_executed,
get_pods_list,
pod_uids,
restart_counts,
@@ -39,6 +40,9 @@ class TestPodDisruption(BaseScenarioTest):
result = self.run_scenario(self.tmp_path, ns)
assert_kraken_success(result, context=f"namespace={ns}", tmp_path=self.tmp_path)
assert_scenario_executed(
result, self.SCENARIO_NAME, context=f"namespace={ns}", tmp_path=self.tmp_path
)
after = get_pods_list(self.k8s_core, ns, self.LABEL_SELECTOR)
after_uids = pod_uids(after)
@@ -18,6 +18,7 @@ from lib.utils import (
assert_kraken_failure,
assert_kraken_success,
assert_pod_count_unchanged,
assert_scenario_executed,
get_pods_list,
)
@@ -49,6 +50,9 @@ class TestStorageThrottle(BaseScenarioTest):
"duration": 15,
})
assert_kraken_success(result, context=f"bandwidth namespace={ns}", tmp_path=self.tmp_path)
assert_scenario_executed(
result, self.SCENARIO_NAME, context=f"bandwidth namespace={ns}", tmp_path=self.tmp_path
)
wait_for_pods_running(ns, self.LABEL_SELECTOR, timeout=READINESS_TIMEOUT)
after = get_pods_list(self.k8s_core, ns, self.LABEL_SELECTOR)
@@ -72,6 +76,9 @@ class TestStorageThrottle(BaseScenarioTest):
config_filename="test_iops_config.yaml",
)
assert_kraken_success(result, context=f"iops namespace={ns}", tmp_path=self.tmp_path)
assert_scenario_executed(
result, self.SCENARIO_NAME, context=f"iops namespace={ns}", tmp_path=self.tmp_path
)
wait_for_pods_running(ns, self.LABEL_SELECTOR, timeout=READINESS_TIMEOUT)
after = get_pods_list(self.k8s_core, ns, self.LABEL_SELECTOR)
@@ -97,6 +104,9 @@ class TestStorageThrottle(BaseScenarioTest):
config_filename="test_both_config.yaml",
)
assert_kraken_success(result, context=f"both namespace={ns}", tmp_path=self.tmp_path)
assert_scenario_executed(
result, self.SCENARIO_NAME, context=f"both namespace={ns}", tmp_path=self.tmp_path
)
wait_for_pods_running(ns, self.LABEL_SELECTOR, timeout=READINESS_TIMEOUT)
after = get_pods_list(self.k8s_core, ns, self.LABEL_SELECTOR)