Files
rippled/docker/telemetry/workload/test_validate_telemetry.py
Pratik Mankawde a87d772f40 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.
2026-08-27 11:16:28 +01:00

237 lines
8.1 KiB
Python

#!/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 <parent> traces" instead of the
# sampling failure they exist to demonstrate.
terms = re.findall(r'(?<![.\w])name\s*(=~|=)\s*"([^"]+)"', query)
assert terms, f"no name predicate found in query: {query}"
for op, value in terms:
if op == "=~":
if not any(re.fullmatch(value, n) for n in names):
return False
elif not any(n == value for n in names):
return False
return True
class Report:
"""Collects CheckResults the way ValidationReport does, without the logging."""
def __init__(self) -> 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())