diff --git a/.github/workflows/telemetry-validation.yml b/.github/workflows/telemetry-validation.yml index 3f424a50a5..fc8b98efaf 100644 --- a/.github/workflows/telemetry-validation.yml +++ b/.github/workflows/telemetry-validation.yml @@ -333,8 +333,10 @@ jobs: fi # Publishes captured OTel timings + regression report to the Step Summary. - # When the committed baseline is a placeholder, emits a fenced JSON block - # that can be copy-pasted directly into baselines/baseline-timings.json. + # When the committed baseline is a placeholder AND the capture is + # complete, emits a fenced JSON block that can be copy-pasted directly + # into baselines/baseline-timings.json. An incomplete capture is named as + # such and its JSON withheld — see the comment on that branch below. # When the baseline is populated, summarises the top regressions so the # PR author sees the failure reason without downloading artifacts. - name: Print regression summary @@ -367,15 +369,62 @@ jobs: exit 1 } + # Whether the capture is usable as baseline material is the capture's + # own verdict, carried in the artifact by capture_timings.py, which + # computes it against --min-capture-ratio. It is READ here, never + # re-derived: a second copy of the ratio rule in shell would be a + # second source of truth and would drift from the producer. + # + # `// false` covers both an artifact written before the block existed + # and a truncated one. Neither can prove it is complete, so neither is + # offered — the whole point is that a degraded capture must not look + # like a good one. Same `jq -r` reasoning as the baseline parse above. + CAPTURE_COMPLETE=$(jq -r '.capture.complete // false' "$TIMINGS") || { + echo "::error::Failed to parse timings JSON" + exit 1 + } + if [ "$(jq -r 'has("capture")' "$TIMINGS")" = "true" ]; then + CAPTURE_COUNTS=$(jq -r '"\(.capture.captured)/\(.capture.declared)"' "$TIMINGS") + CAPTURE_SHORTFALL="only **$CAPTURE_COUNTS** declared metrics came back, below the capture's own minimum ratio" + else + CAPTURE_COUNTS="unknown" + CAPTURE_SHORTFALL="the artifact carries no \`capture\` block, so it predates completeness reporting and cannot state what it captured" + fi + echo "## OTel Timings Regression Gate" >>"$GITHUB_STEP_SUMMARY" echo "" >>"$GITHUB_STEP_SUMMARY" - if [ "$IS_PLACEHOLDER" = "true" ]; then + if [ "$IS_PLACEHOLDER" = "true" ] && [ "$CAPTURE_COMPLETE" != "true" ]; then + # The placeholder path is the ONLY route to a committed baseline, + # which makes it the one place an incomplete capture does lasting + # damage: pasted in, it silently narrows the gate to the keys that + # happened to come back. So the JSON is withheld rather than + # printed with a caveat — a warning above a copyable block is + # still a copyable block. The counts are shown so the reader knows + # how thin it was, and the artifact is still uploaded for anyone + # who needs to inspect it deliberately. + echo "### Baseline NOT refreshable from this run" >>"$GITHUB_STEP_SUMMARY" + echo "" >>"$GITHUB_STEP_SUMMARY" + echo "The committed baseline is a placeholder, so this run would" \ + "normally print a block to paste into" \ + "\`baselines/baseline-timings.json\`. It is withheld because" \ + "$CAPTURE_SHORTFALL, so the JSON may describe metrics that" \ + "were never measured. Pasting it would narrow the gate to" \ + "whichever keys were captured, with nothing reporting that" \ + "it had narrowed." >>"$GITHUB_STEP_SUMMARY" + echo "" >>"$GITHUB_STEP_SUMMARY" + echo "Fix the capture first — the usual cause is Prometheus not" \ + "being scraped for long enough, or nodes not reaching" \ + "consensus — then re-run. See the \`timings.json\` artifact's" \ + "\`capture\` block for the exact counts." >>"$GITHUB_STEP_SUMMARY" + echo "::error::Timing capture is incomplete ($CAPTURE_COUNTS metrics) — no baseline block printed. Do not refresh the baseline from this run." + elif [ "$IS_PLACEHOLDER" = "true" ]; then echo "### Paste into \`baselines/baseline-timings.json\`" >>"$GITHUB_STEP_SUMMARY" echo "" >>"$GITHUB_STEP_SUMMARY" echo "The committed baseline is a placeholder. Open a PR replacing" \ "its contents with the JSON block below to activate the" \ - "regression gate." >>"$GITHUB_STEP_SUMMARY" + "regression gate. The capture is complete" \ + "($CAPTURE_COUNTS declared metrics)." >>"$GITHUB_STEP_SUMMARY" echo "" >>"$GITHUB_STEP_SUMMARY" echo '```json' >>"$GITHUB_STEP_SUMMARY" cat "$TIMINGS" >>"$GITHUB_STEP_SUMMARY" diff --git a/docker/telemetry/workload/README.md b/docker/telemetry/workload/README.md index c11e812432..ff4528a574 100644 --- a/docker/telemetry/workload/README.md +++ b/docker/telemetry/workload/README.md @@ -240,12 +240,15 @@ How it runs inside the validation pipeline: 1. `run-full-validation.sh` executes the normal workload and validation suite. 2. After validation, `capture_timings.py` queries Prometheus for every metric `regression-metrics.json` declares and does not list in - `excluded_keys`, then writes `reports/timings.json`. + `excluded_keys`, then writes `reports/timings.json`. That file records + how much of the declared surface actually came back, in a `capture` + block alongside `metrics` — see [Capture completeness](#capture-completeness). 3. `compare_to_baseline.py` reads `timings.json`, `baselines/baseline-timings.json`, and `regression-thresholds.json`, then either: - Prints the paste-me JSON block (when the baseline is a placeholder - or empty) and exits 0. + or empty and the capture is complete) and exits 0. An incomplete + capture is refused instead, with exit 2 and nothing on stdout. - Prints a delta table, writes `reports/regression-report.json`, and exits non-zero if any metric breached both the percentage AND absolute bound. @@ -259,6 +262,27 @@ Bootstrapping a baseline: `baselines/baseline-timings.json`. Reviewer approval is the audit gate. 3. Subsequent runs compare against it; the gate fails on regression. +#### Capture completeness + +`capture_timings.py` writes `timings.json` and only then enforces +`--min-capture-ratio`, so a run that reached too little of Prometheus still +leaves a file behind — one that exists, parses, and carries every declared key, +some of them `null`. Nothing about it looks degraded. + +Every capture therefore states its own verdict: + +```json +"capture": { "declared": 20, "captured": 20, "min_ratio": 0.5, "complete": true } +``` + +`complete` is exactly the condition `capture_timings.py` exits 0 on. Both +paste-me paths — the workflow's Step Summary block and `compare_to_baseline.py` +— read that flag and withhold the JSON unless it is `true`, because the +placeholder path is the only route to a committed baseline and a thin capture +pasted into one narrows the gate silently. An absent `capture` block (an +artifact from before this existed) counts as not complete: completeness has to +be proven, not assumed. + Per-run tuning: - `--skip-regression` disables the gate (local exploration only). diff --git a/docker/telemetry/workload/baselines/README.md b/docker/telemetry/workload/baselines/README.md index 136683788a..91ede32e65 100644 --- a/docker/telemetry/workload/baselines/README.md +++ b/docker/telemetry/workload/baselines/README.md @@ -12,7 +12,9 @@ declared in [`../regression-metrics.json`](../regression-metrics.json) and write - **Placeholder baseline** (`"placeholder": true` or empty `metrics`): the comparator prints the captured timings JSON in exactly the format expected for this file, then - exits 0 without gating. This is how we bootstrap the baseline. + exits 0 without gating. This is how we bootstrap the baseline. It prints that block + only when the capture was complete — see + [An incomplete capture cannot seed a baseline](#an-incomplete-capture-cannot-seed-a-baseline). - **Populated baseline**: the comparator diffs per-metric, enforces the thresholds (regression = current exceeds baseline on BOTH the percentage AND absolute bound), and exits non-zero on any regression. The single exception is a baseline that is @@ -267,6 +269,31 @@ the design change these five exclusions are waiting on. 3. The committed baseline PR needs reviewer approval just like any other code change. This is the primary audit point for "who moved the performance bar." +### An incomplete capture cannot seed a baseline + +`capture_timings.py` writes `timings.json` **before** it enforces +`--min-capture-ratio`, so a run that reached too little of Prometheus still leaves a +file behind — one that exists, parses, and carries every declared key, some of them +`null`. Nothing about it reads as degraded, and the obvious reaction to a red gate is +to refresh the baseline, so this is exactly the file a person is most likely to paste. + +Every capture therefore records its own verdict in a `capture` block (see +[Schema](#schema)), and `complete` there is exactly the condition +`capture_timings.py` exits 0 on. Both routes to a baseline read that flag and print +nothing to paste unless it is `true`: + +- the workflow's Step Summary heading becomes "Baseline NOT refreshable from this run", + carrying the captured/declared counts and an `::error::` annotation; +- `compare_to_baseline.py` writes the same explanation to stderr, leaves stdout empty + so a `>` redirect cannot produce a plausible-looking file, and exits 2. + +An artifact with no `capture` block — one produced before this existed — counts as not +complete. Completeness has to be proven, not assumed. + +This only guards the paste. Against a populated baseline a thin capture still compares +normally and its uncaptured keys are reported as `not captured in current run`, which +is the pre-existing behaviour described under [Schema](#schema) below. + ## Refreshing the baseline Refresh when a legitimate performance change lands on `develop` (for example, a @@ -319,6 +346,12 @@ debug-level detail, enable it per partition **after** the baseline exists. "window": "3m", "git_sha": "", "profile": "", + "capture": { + "declared": 20, + "captured": 20, + "min_ratio": 0.5, + "complete": true + }, "metrics": { "span.tx.process.p99": { "value": 12.4, "unit": "ms" }, "job.transaction.queued.p95": { "value": 1500.0, "unit": "us" } @@ -326,6 +359,15 @@ debug-level detail, enable it per partition **after** the baseline exists. } ``` +`capture` describes the capture that produced the file, not the metrics in it: +`declared` is how many keys the surface asked for, `captured` how many came back with a +value, `min_ratio` the bar they were judged against, and `complete` the verdict. It is a +sibling of `metrics`, never an entry inside it, so it is neither a metric key nor a +gated entry — `check_regression_bounds.py` and `compare_to_baseline.py` both iterate +`metrics` alone and never see it. Because a committed baseline is a verbatim copy of a +capture, the block lands here too; it is metadata about provenance, exactly like +`git_sha`. Entries committed before it existed simply do not carry it. + Keys follow `{category}.{name}.p{quantile}`. Only two categories are actually produced today — `span.*` and `job.*` — because `build_query_plan()` in `prom_queries.py` reads the `spans` and `job_queue` groups of diff --git a/docker/telemetry/workload/capture_timings.py b/docker/telemetry/workload/capture_timings.py index 4558631cb4..3cd4bb8cd2 100644 --- a/docker/telemetry/workload/capture_timings.py +++ b/docker/telemetry/workload/capture_timings.py @@ -16,6 +16,12 @@ Output schema (stable — ``compare_to_baseline.py`` reads it verbatim):: "window": "3m", "git_sha": "", "profile": "full-validation", + "capture": { + "declared": 20, + "captured": 20, + "min_ratio": 0.5, + "complete": true + }, "metrics": { "span.tx.process.p99": {"value": 12.4, "unit": "ms"}, "job.transaction.queued.p95": {"value": 850.0, "unit": "us"}, @@ -23,6 +29,30 @@ Output schema (stable — ``compare_to_baseline.py`` reads it verbatim):: } } +The ``capture`` block is what makes this file safe to use as baseline material. +The output is written BEFORE ``--min-capture-ratio`` is enforced, so a run that +reached too little of Prometheus still leaves a ``timings.json`` behind. That +file exists, parses, and carries every declared key — some with ``value: null`` +— so a thin capture is indistinguishable from a good one to a reader who only +checks that the file is there. Pasted into +``baselines/baseline-timings.json`` it would narrow the gate to whichever keys +happened to come back, with nothing reporting that the gate had narrowed. + +``complete`` is exactly the condition this script exits 0 on. It is computed +once, in ``_capture_status``, and drives both the exit code and the block, so +the two cannot disagree. Consumers read the flag rather than re-deriving the +ratio rule for themselves: the workflow's "Print regression summary" step, the +paste-me path in ``compare_to_baseline.py``, and a human reading the artifact +all get the same answer from one place. ``declared``, ``captured`` and +``min_ratio`` sit alongside it so a rejected capture can be judged without +re-running it. + +The block is additive — a sibling of ``metrics``, never an entry inside it — so +it is neither a metric key nor a gated entry, and readers that predate it are +unaffected. Its ABSENCE means an artifact from before it existed, whose +completeness cannot be established; the paste-me paths treat that as not +complete rather than as complete. + Usage:: python3 capture_timings.py \\ @@ -59,21 +89,51 @@ async def capture( metrics_path: Path, window: str, profile: str, + min_capture_ratio: float, ) -> dict: - """Build and execute the query plan, return the full report dict.""" + """Build and execute the query plan, return the full report dict. + + ``min_capture_ratio`` is recorded in the report rather than only applied to + the exit code, so the artifact states the bar it was judged against. + """ plan = build_query_plan(metrics_path, window=window) logger.info("Capturing %d metrics from %s (window=%s)", len(plan), prom_url, window) async with aiohttp.ClientSession() as session: metrics = await run_query_plan(session, prom_url, plan) + metrics = dict(sorted(metrics.items())) return { "schema_version": SCHEMA_VERSION, "captured_at": datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%SZ"), "window": window, "git_sha": _detect_git_sha(), "profile": profile, - "metrics": dict(sorted(metrics.items())), + "capture": _capture_status(metrics, min_capture_ratio), + "metrics": metrics, + } + + +def _capture_status(metrics: dict, min_ratio: float) -> dict: + """Summarise how much of the declared surface this capture actually got. + + ``declared`` is every key the surface asked for; ``captured`` is how many + came back with a value. ``complete`` is the single fact every consumer + keys on, and it is the same predicate that decides this script's exit + code — see the module docstring for why it lives in the artifact. + + An empty surface is vacuously complete: there is nothing for the capture + to have fallen short of, and that is the case the exit-code check has + always passed. Defining it any other way here would make the flag and the + exit code disagree, which is the drift this block exists to remove. + """ + declared = len(metrics) + captured = sum(1 for entry in metrics.values() if entry["value"] is not None) + return { + "declared": declared, + "captured": captured, + "min_ratio": min_ratio, + "complete": declared == 0 or (captured / declared) >= min_ratio, } @@ -160,6 +220,7 @@ def main() -> int: metrics_path=args.metrics, window=args.window, profile=args.profile, + min_capture_ratio=args.min_capture_ratio, ) ) @@ -168,14 +229,17 @@ def main() -> int: json.dump(report, f, indent=2, sort_keys=True) f.write("\n") - captured = sum(1 for v in report["metrics"].values() if v["value"] is not None) - total = len(report["metrics"]) + # The exit code is read off the same flag the artifact carries, so a file + # marked complete is always one this script exited 0 on. + status = report["capture"] + captured, total = status["captured"], status["declared"] logger.info("Wrote %s (%d/%d metrics captured)", args.output, captured, total) - if total > 0 and (captured / total) < args.min_capture_ratio: + if not status["complete"]: logger.error( "Only %d/%d (%.0f%%) metrics captured — below the %.0f%% minimum. " - "Is Prometheus reachable at %s?", + "Is Prometheus reachable at %s? The file is marked " + "capture.complete=false and must not be pasted into the baseline.", captured, total, captured / total * 100, diff --git a/docker/telemetry/workload/compare_to_baseline.py b/docker/telemetry/workload/compare_to_baseline.py index 4b516c0ed9..5619400858 100644 --- a/docker/telemetry/workload/compare_to_baseline.py +++ b/docker/telemetry/workload/compare_to_baseline.py @@ -8,6 +8,13 @@ Operating modes (chosen automatically based on the baseline file contents): script is in "populate" mode. It prints the captured timings JSON in the exact format expected for pasting into ``baselines/baseline-timings.json``, then exits 0. No regression check. + An INCOMPLETE capture is refused here instead (exit 2): the timings file + states its own completeness in its ``capture`` block, and a capture that + fell short of ``--min-capture-ratio`` describes metrics that were never + measured. Pasted in, it would narrow the gate to whichever keys came back + with nothing reporting that it had narrowed. Refusing prints nothing on + stdout, so a caller redirecting stdout to the baseline file cannot end up + with a truncated one blessed by exit 0. 2. **Populated baseline** — per-metric percentage AND absolute deltas are computed against thresholds from ``regression-thresholds.json``. A @@ -26,7 +33,14 @@ Inputs: Exit codes: 0 — No baseline (paste-me emitted), OR baseline populated and no regression 1 — Regression detected (at least one metric breached both bounds) - 2 — Internal error (e.g. bad JSON, baseline/current key mismatch) + 2 — Internal error (e.g. bad JSON, baseline/current key mismatch), OR the + baseline is a placeholder and the capture is too incomplete to seed one + +Note that an incomplete capture is refused only on the paste-me path. Against a +POPULATED baseline the comparison still runs and still reports uncaptured keys +as ``not captured in current run``, exactly as before: there the thin capture +cannot corrupt anything, and reporting what is missing is more useful than +refusing to look. """ from __future__ import annotations @@ -85,6 +99,58 @@ def is_placeholder(baseline: dict) -> bool: return not baseline.get("metrics") +def capture_is_complete(timings: dict) -> bool: + """True only if the timings file states that its capture was complete. + + The flag is written by ``capture_timings.py``, which computes it against + ``--min-capture-ratio``; this reads it rather than re-deriving the rule, so + the two cannot disagree. Anything other than boolean ``true`` — the block + absent because the artifact predates it, a truncated file, a string + ``"true"`` from a hand edit — is treated as not complete. Completeness has + to be proven, not assumed, because assuming it is how a thin capture + reaches a committed baseline. + """ + capture = timings.get("capture") + if not isinstance(capture, dict): + return False + return capture.get("complete") is True + + +def print_incomplete_capture(timings: dict) -> None: + """Explain why no paste-me block was printed, naming the shortfall. + + Deliberately writes to stderr only. The paste-me path's stdout is the + baseline file's contents, so leaving stdout empty is what stops a + ``> baseline-timings.json`` redirect from producing a file that looks + captured. + """ + capture = timings.get("capture") + if isinstance(capture, dict): + detail = ( + f"only {capture.get('captured')} of {capture.get('declared')} declared " + f"metrics came back, below the minimum ratio " + f"{capture.get('min_ratio')}" + ) + else: + detail = ( + "the file carries no 'capture' block, so its completeness cannot be " + "established — recapture with the current capture_timings.py" + ) + + banner = "=" * 72 + print(banner, file=sys.stderr) + print(" CAPTURE INCOMPLETE — refusing to print a baseline block", file=sys.stderr) + print(f" {detail}.", file=sys.stderr) + print( + " These timings may describe metrics that were never measured. Pasting\n" + " them into baselines/baseline-timings.json would narrow the regression\n" + " gate to whichever keys were captured, with nothing reporting that it\n" + " had narrowed. Fix the capture and re-run.", + file=sys.stderr, + ) + print(banner, file=sys.stderr) + + def print_paste_me(timings: dict) -> None: """Print captured timings in the exact baseline-timings.json format. @@ -396,6 +462,9 @@ def main() -> int: return 2 if is_placeholder(baseline): + if not capture_is_complete(timings): + print_incomplete_capture(timings) + return 2 print_paste_me(timings) return 0 diff --git a/docker/telemetry/workload/expected_spans.json b/docker/telemetry/workload/expected_spans.json index 9ae59bf7cf..45cbad1867 100644 --- a/docker/telemetry/workload/expected_spans.json +++ b/docker/telemetry/workload/expected_spans.json @@ -572,14 +572,12 @@ "child": "txq.batch_clear", "description": "Queue admission contains the batch-clear pass that drops an account's superseded queued transactions.", "skip": true, - "skip_reason": "Real relationship, declared on the txq.batch_clear span entry but never listed here until 2026-08-26, so it was neither asserted nor accounted for -- the gap this entry closes. Skipped rather than asserted for two independent reasons. First the child is conditional and narrowly so: it is created in TxQ::tryClearAccountQueueUpThruTx (TxQ.cpp:550), which needs ONE account to be holding several queued transactions AND an arriving transaction that supersedes the whole batch. The txq-burst workload phase produces queueing, but nothing in it arranges that particular shape, and it has never been observed on a run. Second, even if it did occur it would meet the same sampling limit that forced the txq.accept -> txq.accept_tx skip: _validate_parent_child samples the 3 newest parent traces (validate_telemetry.py:803), txq.enqueue fires on every queued transaction, and the newest ones come from the quiet phases that follow the burst. Fixing the sampling -- preferring parent traces that contain the child over newest-N -- would address both entries at once and is the better investment than shaping the workload for this one path." + "skip_reason": "Real relationship, still skipped but for ONE reason now rather than two. The child never fires at all under this workload -- the run reports \"span.txq.batch_clear: optional span not emitted under this workload\" -- because it is created in TxQ::tryClearAccountQueueUpThruTx (TxQ.cpp:550), which needs one account holding several queued transactions AND an arriving transaction that supersedes the whole batch. Nothing in txq-burst arranges that shape. The second reason this entry used to carry, that newest-N parent sampling would miss it anyway, no longer applies: the hierarchy check now queries Tempo for traces containing both parent and child. So this is now purely a workload gap, and un-skipping it needs the workload to produce a supersedable batch -- nothing further from the validator." }, { "parent": "txq.accept", "child": "txq.accept_tx", - "description": "The queue's accept pass contains the per-transaction accept span.", - "skip": true, - "skip_reason": "Real relationship, but not assertable by this check as written -- a conditional child plus newest-N sampling. Asserted in c531ac569b and it failed on run 32990348089 with 'txq.accept_tx not found in txq.accept traces'; skipped rather than left red. Both ends DO emit, 5 traces each on that run, so this is not a missing span. The parent is created once per accept pass, every ledger close (TxQ.cpp:1499). The child is created inside the loop over queued transactions and behind `if (feeLevelPaid >= requiredFeeLevel)` (TxQ.cpp:1530), so it exists only for a close where the queue actually held a fee-clearing transaction. _validate_parent_child searches the parent with limit=3 (validate_telemetry.py:803), and queue pressure comes from workload phase 5 of 7, txq-burst, after which mixed-peak (60s) and cooldown (30s) run -- so the three newest txq.accept traces are from quiet closes with an empty queue and no child. Same shape as the rpc.command.* skips: the check samples the newest traces of the parent, which is wrong whenever the child is conditional on load that has since stopped. Two ways to un-skip, in preference order: make the search prefer parent traces that contain the child (a TraceQL child filter rather than newest-N), or move txq-burst to the final workload phase so the newest closes are the loaded ones. Raising the limit alone only shifts the odds and would make this flaky rather than fixed." + "description": "The queue's accept pass contains the per-transaction accept span. Un-skipped once the hierarchy check stopped sampling only the newest parent traces. The child is created inside the loop over queued transactions and behind `if (feeLevelPaid >= requiredFeeLevel)` (TxQ.cpp:1530), so it exists only for a close whose queue held a fee-clearing transaction, while the parent fires on every close (:1499) -- which is precisely the shape newest-N sampling gets wrong. The check now asks Tempo for traces containing both, so co-occurrence is found wherever it happened rather than only in the three most recent closes." }, { "parent": "consensus.round", diff --git a/docker/telemetry/workload/run-full-validation.sh b/docker/telemetry/workload/run-full-validation.sh index bc509837ef..a9b90c647f 100755 --- a/docker/telemetry/workload/run-full-validation.sh +++ b/docker/telemetry/workload/run-full-validation.sh @@ -953,9 +953,9 @@ fold_exit "$VALIDATION_EXIT" # Capture ALWAYS runs, so every run leaves a timings.json artifact — it is the # only route to a new committed baseline. The workflow's "Print regression # summary" step reads that file unconditionally and, when the committed baseline -# is still a placeholder, pastes it into the step summary for the author to copy. -# Suppressing the capture would remove the one way to bootstrap or refresh the -# baseline. +# is still a placeholder and the capture is complete, pastes it into the step +# summary for the author to copy. Suppressing the capture would remove the one +# way to bootstrap or refresh the baseline. # # A non-zero capture status does NOT mean the file is absent: capture_timings.py # writes its output and only then fails when too few metrics came back (its @@ -963,6 +963,11 @@ fold_exit "$VALIDATION_EXIT" # which is worse than none as baseline material — it would commit metrics that # were never measured. The messages below say incomplete, never missing. # +# That thin file also says so itself, in the "capture" block capture_timings.py +# writes into it, so the CAPTURE_EXIT below is no longer the only record of the +# capture's health: both paste-me paths read the flag and withhold the JSON +# rather than offering an artifact this run has already called unusable. +# # --skip-regression opts out of the comparison only (e.g. for ad-hoc local # exploration), and with it out of the gate's verdict: a capture failure is # reported loudly and shown in the step-status table, but does not fail a run diff --git a/docker/telemetry/workload/test_validate_telemetry.py b/docker/telemetry/workload/test_validate_telemetry.py new file mode 100644 index 0000000000..514a42b1df --- /dev/null +++ b/docker/telemetry/workload/test_validate_telemetry.py @@ -0,0 +1,236 @@ +#!/usr/bin/env python3 +"""Tests for validate_telemetry.py's hierarchy check. + +Run with plain python3 -- there is no pytest in the harness requirements, and +this file is deliberately runnable with nothing but the standard library plus +the aiohttp that validate_telemetry.py already imports: + + python3 docker/telemetry/workload/test_validate_telemetry.py + +Why a stub Tempo rather than the real one: the behaviour under test is which +traces the check ASKS FOR, which a live backend cannot demonstrate -- a passing +query against real data proves the data happened to co-operate, not that the +query was right. The stub records every request, so a test can assert on the +query itself and on the answer the check derives from a known corpus. +""" + +import asyncio +import json +import sys +from pathlib import Path +from typing import Any + +sys.path.insert(0, str(Path(__file__).parent)) + +import validate_telemetry as vt # noqa: E402 + + +class FakeResponse: + """Minimal stand-in for an aiohttp response used as an async context manager.""" + + def __init__(self, payload: dict[str, Any], status: int = 200) -> None: + self._payload = payload + self.status = status + + async def __aenter__(self) -> "FakeResponse": + return self + + async def __aexit__(self, *exc: object) -> bool: + return False + + async def json(self) -> dict[str, Any]: + return self._payload + + async def text(self) -> str: + return json.dumps(self._payload) + + +class FakeTempo: + """A Tempo whose corpus is fixed and whose queries are recorded. + + Args: + traces: Maps a trace id to the list of span names that trace contains, + ordered newest first, which is the order /api/search returns. + """ + + def __init__(self, traces: dict[str, list[str]]) -> None: + self.traces = traces + self.queries: list[tuple[str, int]] = [] + + def get(self, url: str, params: dict[str, str] | None = None) -> FakeResponse: + params = params or {} + if "/api/search" in url: + query, limit = params["q"], int(params.get("limit", 20)) + self.queries.append((query, limit)) + matched = [ + tid + for tid, names in self.traces.items() + if _query_matches_trace(query, names) + ] + return FakeResponse({"traces": [{"traceID": t} for t in matched[:limit]]}) + if "/api/traces/" in url: + tid = url.rsplit("/", 1)[-1] + spans = [{"name": n, "attributes": []} for n in self.traces.get(tid, [])] + return FakeResponse({"batches": [{"scopeSpans": [{"spans": spans}]}]}) + raise AssertionError(f"unexpected request: {url}") + + +def _query_matches_trace(query: str, names: list[str]) -> bool: + """Evaluate the subset of TraceQL this suite uses against one trace. + + Supports the trace-level conjunction of name predicates the hierarchy check + builds: every `name="X"` (or `name=~"X"`) term must be satisfied by some span + in the trace. That is the whole semantic the check relies on, so the stub + models exactly it and nothing more. + """ + import re + + # `name` only as a bare intrinsic. The lookbehind is load-bearing: without it + # this also matches the resource.service.name="xrpld" term every query + # carries, and then demands a span literally named "xrpld" -- which made the + # first run of these tests fail with "No traces" instead of the + # sampling failure they exist to demonstrate. + terms = re.findall(r'(? None: + self.results: list[Any] = [] + + def add(self, result: Any) -> None: + self.results.append(result) + + +def run(coro: Any) -> Any: + return asyncio.run(coro) + + +def test_child_found_in_a_trace_outside_the_newest_three() -> None: + """The check must find a child that co-occurs only in an older trace. + + This is the txq.accept_tx / ledger.acquire.txtree shape: the parent fires on + every ledger close, the child only when a rarely-met condition holds, so the + newest traces carry the parent alone. Sampling the newest N parent traces + reports "not found" on a corpus that plainly contains the relationship. + + The production change that makes this fail: reverting the hierarchy check to + search the parent alone and inspect only the first N results. + """ + tempo = FakeTempo( + { + # Newest first, as /api/search returns. The child is only in the oldest. + "t5": ["txq.accept"], + "t4": ["txq.accept"], + "t3": ["txq.accept"], + "t2": ["txq.accept"], + "t1": ["txq.accept", "txq.accept_tx"], + } + ) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "txq.accept", "child": "txq.accept_tx"}, + report, + ) + ) + assert len(report.results) == 1, report.results + result = report.results[0] + assert result.passed, f"expected PASS, got: {result.message}" + assert result.name == "span.hierarchy.txq.accept->txq.accept_tx" + + +def test_absent_child_still_fails() -> None: + """A child that co-occurs in no trace must still fail. + + Guards the obvious way to "fix" the test above -- making the check pass + whenever the parent exists. Without this, a harness that silently stopped + emitting a child would go green. + """ + tempo = FakeTempo({"t2": ["txq.accept"], "t1": ["txq.accept"]}) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "txq.accept", "child": "txq.accept_tx"}, + report, + ) + ) + assert len(report.results) == 1 + assert not report.results[0].passed + assert "txq.accept_tx" in report.results[0].message + + +def test_missing_parent_reports_the_parent_not_the_child() -> None: + """No parent traces at all is a distinct failure from a missing child. + + The two mean different things to whoever reads the report -- a missing parent + says the span stopped being emitted, a missing child says the relationship + broke -- so the messages must not collapse into one. + """ + tempo = FakeTempo({"t1": ["ledger.build"]}) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "txq.accept", "child": "txq.accept_tx"}, + report, + ) + ) + assert len(report.results) == 1 + assert not report.results[0].passed + assert "No txq.accept traces" in report.results[0].message + + +def test_wildcard_child_matches_any_family_member() -> None: + """A wildcard child must be satisfied by any concrete member. + + rpc.command.* names vary per request, so pinning one literal would make the + check depend on which command the sampled traces happened to carry. + """ + tempo = FakeTempo({"t1": ["rpc.ws_message", "rpc.command.fee"]}) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "rpc.ws_message", "child": "rpc.command.*"}, + report, + ) + ) + assert report.results[0].passed, report.results[0].message + + +def main() -> int: + tests = [v for k, v in sorted(globals().items()) if k.startswith("test_")] + failed = 0 + for test in tests: + try: + test() + except AssertionError as exc: + failed += 1 + print(f"FAIL {test.__name__}: {exc}") + except Exception as exc: # noqa: BLE001 - report any error as a failure + failed += 1 + print(f"ERROR {test.__name__}: {type(exc).__name__}: {exc}") + else: + print(f"PASS {test.__name__}") + print(f"\n{len(tests) - failed}/{len(tests)} passed") + return 1 if failed else 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/docker/telemetry/workload/validate_telemetry.py b/docker/telemetry/workload/validate_telemetry.py index 6e1f350785..4733af8dbc 100644 --- a/docker/telemetry/workload/validate_telemetry.py +++ b/docker/telemetry/workload/validate_telemetry.py @@ -417,6 +417,28 @@ def _otlp_span_attr_keys(span: dict[str, Any]) -> set[str]: return {a["key"] for a in span.get("attributes", []) if "key" in a} +def _traceql_name_predicate(expected_name: str) -> str: + """Build the TraceQL `name` predicate that selects a contract span name. + + A literal contract name becomes an equality test. A glob becomes a regex + test, because TraceQL has no glob operator: `rpc.command.*` must be sent as + `name=~"rpc\\.command\\..*"`, with the dots escaped so they match literal + dots rather than any character. Sending the glob unescaped would still match + the intended spans, but would also match names differing in those positions, + which is the looseness _span_name_matches exists to avoid. + + Args: + expected_name: Span name or glob from expected_spans.json. + + Returns: + A TraceQL predicate on the bare `name` intrinsic, without braces. + """ + if "*" not in expected_name: + return f'name="{expected_name}"' + pattern = "".join(".*" if ch == "*" else re.escape(ch) for ch in expected_name) + return f'name=~"{pattern}"' + + def _span_name_matches(emitted_name: str, expected_name: str) -> bool: """Test an emitted span name against a name from expected_spans.json. @@ -806,7 +828,10 @@ async def _validate_parent_child( child_name = relationship["child"] try: - # Query traces for the parent span. + # Query traces for the parent span. Kept as its own query so that "the + # parent stopped being emitted" stays distinguishable from "the parent is + # there but the child never co-occurs" — they mean different things to + # whoever reads the report. query = '{resource.service.name="xrpld" && name="' + parent_name + '"}' traces = await _tempo_search(session, tempo_url, query, limit=3) @@ -821,7 +846,29 @@ async def _validate_parent_child( ) return - # Check if child spans exist within parent traces. Names are matched + # Then ask Tempo for traces containing BOTH, and inspect those instead of + # the newest parent traces from the query above. + # + # Sampling the newest N parent traces is wrong whenever the child is + # conditional on a state the workload only sometimes reaches: the parent + # fires constantly, so the newest traces are the ones LEAST likely to + # carry a rare child. Three relationships were skipped as unassertable + # for exactly this and none of them was a missing span -- + # txq.accept -> txq.accept_tx (child needs a queue holding a fee-clearing + # transaction), txq.enqueue -> txq.batch_clear (needs a supersedable + # batch) and ledger.acquire -> ledger.acquire.txtree (opens only when the + # node lacks the tx set, which in a cluster building identical sets is the + # minority case). Each child emitted on its own; it simply was not in the + # three newest parent traces. `{A} && {B}` is a trace-level conjunction, + # so Tempo searches its whole retention for co-occurrence rather than + # leaving it to which traces happen to be newest. + both_query = query + " && {" + _traceql_name_predicate(child_name) + "}" + traces = await _tempo_search(session, tempo_url, both_query, limit=3) + + # Verify against the returned traces rather than trusting the query. + # Tempo has already guaranteed co-occurrence, but re-checking the span + # names keeps the glob semantics in one place (_span_name_matches) and + # means a query built wrongly cannot silently pass. Names are matched # exactly (globs for wildcard contracts) — a substring test let a # longer emitted name satisfy a shorter contract, so # consensus.round -> consensus.accept passed on a