From 5a532190aa49b5ac723302170fab0d81be31b862 Mon Sep 17 00:00:00 2001 From: "augmentcode[bot]" <185243770+augmentcode[bot]@users.noreply.github.com> Date: Thu, 11 Jun 2026 18:41:12 +0530 Subject: [PATCH] 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> --- CI/tests_v2/conftest.py | 111 ++++++++++++++++++ CI/tests_v2/lib/kraken.py | 50 ++++++-- CI/tests_v2/lib/utils.py | 65 ++++++++++ .../test_application_outage.py | 5 + .../pod_disruption/test_pod_disruption.py | 4 + .../storage_throttle/test_storage_throttle.py | 10 ++ 6 files changed, 237 insertions(+), 8 deletions(-) diff --git a/CI/tests_v2/conftest.py b/CI/tests_v2/conftest.py index 98aec29b..c2ec3034 100644 --- a/CI/tests_v2/conftest.py +++ b/CI/tests_v2/conftest.py @@ -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 = ["
Krkn Execution Log
"] + 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"
Run {idx} (rc={out.get('returncode')})
") + if len(lines) > _KRAKEN_LOG_MAX_LINES: + parts.append( + f"
(showing last {_KRAKEN_LOG_MAX_LINES} of {len(lines)} lines)
" + ) + lines = lines[-_KRAKEN_LOG_MAX_LINES:] + parts.append( + '' + "" + "" + "" + ) + 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( + "" + f"" + f"" + f"" + "" + ) + parts.append("
TimestampLevelMessage
{html_lib.escape(ts)}{html_lib.escape(lvl)}{html_lib.escape(msg)}
") + if evidence is not None: + mark = "✓ Matched" if evidence["verified"] else "✗ No match for" + parts.append( + f"
Execution Evidence: {mark} " + f"{html_lib.escape(evidence['pattern'])}
" + ) + 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/).""" diff --git a/CI/tests_v2/lib/kraken.py b/CI/tests_v2/lib/kraken.py index 996128de..e9dadc18 100644 --- a/CI/tests_v2/lib/kraken.py +++ b/CI/tests_v2/lib/kraken.py @@ -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 diff --git a/CI/tests_v2/lib/utils.py b/CI/tests_v2/lib/utils.py index d2c542b3..9070a3ed 100644 --- a/CI/tests_v2/lib/utils.py +++ b/CI/tests_v2/lib/utils.py @@ -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}" + ) diff --git a/CI/tests_v2/scenarios/application_outage/test_application_outage.py b/CI/tests_v2/scenarios/application_outage/test_application_outage.py index 5a70a4de..f19e1792 100644 --- a/CI/tests_v2/scenarios/application_outage/test_application_outage.py +++ b/CI/tests_v2/scenarios/application_outage/test_application_outage.py @@ -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) diff --git a/CI/tests_v2/scenarios/pod_disruption/test_pod_disruption.py b/CI/tests_v2/scenarios/pod_disruption/test_pod_disruption.py index 5564bd5d..ecf00b26 100644 --- a/CI/tests_v2/scenarios/pod_disruption/test_pod_disruption.py +++ b/CI/tests_v2/scenarios/pod_disruption/test_pod_disruption.py @@ -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) diff --git a/CI/tests_v2/scenarios/storage_throttle/test_storage_throttle.py b/CI/tests_v2/scenarios/storage_throttle/test_storage_throttle.py index 0c019487..b94bf954 100644 --- a/CI/tests_v2/scenarios/storage_throttle/test_storage_throttle.py +++ b/CI/tests_v2/scenarios/storage_throttle/test_storage_throttle.py @@ -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)