From 8521b96d8576934c096bb3801b86254323c5cfec Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Thu, 27 Aug 2026 09:52:48 +0100 Subject: [PATCH 1/2] fix(telemetry): stop an incomplete capture becoming the committed baseline The regression baseline is bootstrapped by copying a CI artifact. The workflow tested only that timings.json existed, then printed it verbatim under a heading inviting the reader to paste it in as the new baseline. capture_timings.py writes that file and only then enforces --min-capture-ratio, so an incomplete capture leaves a file that exists but covers fewer keys than the contract declares. The verdict lived in CAPTURE_EXIT, a shell variable local to run-full-validation.sh that no other program could read. So on a placeholder baseline plus a thin capture, CI offered an incomplete artifact as the next baseline, and pasting it narrowed the gate with nothing reporting that it had. That is the failure shape this harness keeps producing: a degraded result that looks exactly like a good one. The artifact now carries its own completeness, next to metrics: "capture": { "declared": 20, "captured": 20, "min_ratio": 0.5, "complete": true } complete is the same condition the producer exits 0 on, computed once with the exit code read off it, so the flag and the status cannot drift apart. Any consumer can now tell a complete capture from a thin one, not just CI. Both paste-me paths refuse rather than warn: the workflow prints the counts and an error annotation with no JSON, and the comparator explains on stderr while leaving stdout empty, so a redirect cannot produce a plausible-looking file. A warning above a copyable block is still a copyable block, and a reader who has just hit a red gate is already predisposed to re-baseline. A missing capture block fails closed. Refusal is scoped to bootstrapping a baseline, not to comparing against one, so artifacts captured before this change still replay: verified against the run the current baseline came from, which carries no capture block and still reports 0 regressions. An injected regression is still caught, and the gated surface is unchanged at 20 keys with 5 excluded. --- .github/workflows/telemetry-validation.yml | 57 +++++++++++++- docker/telemetry/workload/README.md | 28 ++++++- docker/telemetry/workload/baselines/README.md | 44 ++++++++++- docker/telemetry/workload/capture_timings.py | 76 +++++++++++++++++-- .../telemetry/workload/compare_to_baseline.py | 71 ++++++++++++++++- .../telemetry/workload/run-full-validation.sh | 11 ++- 6 files changed, 270 insertions(+), 17 deletions(-) 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 0c7aad9036..78fa2e2f89 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/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 From a87d772f4025755402aaedfe182e7f5769664ffb Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Thu, 27 Aug 2026 11:16:28 +0100 Subject: [PATCH 2/2] fix(telemetry): find a span hierarchy where it happened, not only where it is newest The hierarchy check searched the parent span and inspected the three newest traces it returned. That is wrong whenever the child is conditional on a state the workload only sometimes reaches: the parent fires constantly, so its newest traces are the ones LEAST likely to carry a rare child. Three relationships had been skipped as unassertable for exactly this, and in none of them was the child missing -- each emitted traces of its own and simply was not in the three most recent parent traces. The check now issues a second query, a TraceQL trace-level conjunction of the parent and child name predicates, and inspects those traces. Tempo searches its whole retention for co-occurrence instead of leaving the answer to which traces happen to be newest. The parent-only query is kept and still runs first, so "the parent stopped being emitted" stays a distinct failure from "the parent is there but the child never co-occurs" -- they mean different things to whoever reads the report, and collapsing them would lose that. The returned traces are still verified with _span_name_matches rather than the query result being trusted on its own. Tempo has already guaranteed co-occurrence, so this is redundant on the happy path; it is kept because it keeps the glob semantics in one place and means a wrongly built query cannot silently pass. _traceql_name_predicate handles the wildcard contracts. TraceQL has no glob operator, so `rpc.command.*` is sent as name=~"rpc\.command\..*" with the dots escaped -- unescaped they would match any character in those positions, which is the looseness _span_name_matches exists to avoid. Two entries follow from the fix. txq.accept -> txq.accept_tx is asserted again: its child is created inside the queued-transaction loop behind `if (feeLevelPaid >= requiredFeeLevel)` (TxQ.cpp:1530) while the parent fires on every close (:1499), which was the whole reason it failed. txq.enqueue -> txq.batch_clear stays skipped but for ONE reason now instead of two -- its child never fires at all under this workload, needing an account with a supersedable batch, so it is purely a workload gap and needs nothing further from the validator. The third, ledger.acquire -> ledger.acquire.txtree, lives on the sync-diagnostics branch and is un-skipped there once this merges forward. Written test-first, and the first test this module has had. The failing test reproduces the exact CI message, "txq.accept_tx not found in txq.accept traces", against a stubbed Tempo whose corpus holds the child only in a trace outside the newest three. Three sibling tests guard the ways this could be "fixed" wrongly: an absent child must still fail, a missing parent must still name the parent rather than the child, and a wildcard child must be satisfied by any family member. The stub records the queries issued, so the conjunction is asserted rather than assumed. A stub rather than a live Tempo because the behaviour under test is which traces the check ASKS FOR -- a passing query against real data proves the data co-operated, not that the query was right. The first run of those tests failed for the wrong reason: my stub's name-predicate regex also matched the resource.service.name="xrpld" term every query carries and so demanded a span literally named "xrpld". Fixed in the stub, with the lookbehind commented as load-bearing, before touching production code. Verification: 4/4 tests pass, and the failing one was watched failing first with the production message; the issued queries were printed and confirmed to contain the conjunction; validate_telemetry.py compiles; expected_spans.json parses; 21 relationships, 16 asserted and 5 skipped; counters still 41 span types; otel-naming exits 0. Three unrelated files in this worktree are another party's live work and were deliberately left unstaged. --- docker/telemetry/workload/expected_spans.json | 6 +- .../workload/test_validate_telemetry.py | 236 ++++++++++++++++++ .../telemetry/workload/validate_telemetry.py | 51 +++- 3 files changed, 287 insertions(+), 6 deletions(-) create mode 100644 docker/telemetry/workload/test_validate_telemetry.py diff --git a/docker/telemetry/workload/expected_spans.json b/docker/telemetry/workload/expected_spans.json index 0429c2bf7b..cd00478c16 100644 --- a/docker/telemetry/workload/expected_spans.json +++ b/docker/telemetry/workload/expected_spans.json @@ -460,14 +460,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/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 dc4abbafba..38c6c46904 100644 --- a/docker/telemetry/workload/validate_telemetry.py +++ b/docker/telemetry/workload/validate_telemetry.py @@ -409,6 +409,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. @@ -798,7 +820,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) @@ -813,7 +838,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