diff --git a/.github/workflows/reusable-check-otel-naming.yml b/.github/workflows/reusable-check-otel-naming.yml index a92164572b..4f0e39bc3f 100644 --- a/.github/workflows/reusable-check-otel-naming.yml +++ b/.github/workflows/reusable-check-otel-naming.yml @@ -58,3 +58,20 @@ jobs: # regressions and exit 0. Every failure looked like a green build. # This asserts each bound is still the one its own baseline implies. run: python .github/scripts/telemetry/check_regression_bounds.py + - name: Install the workload harness dependencies + # Its own step so a PyPI outage is reported as an install failure rather + # than as a failing harness. Last in the job, because every check above + # is stdlib-only and stays reachable if this fails. + run: pip3 install -r docker/telemetry/workload/requirements.txt + - name: Test the telemetry workload harness + # Run here rather than in telemetry-validation.yml so a broken harness is + # reported in seconds instead of after a full xrpld build, and on every + # PR rather than only when that workflow's paths match. + # + # Plain scripts, not `unittest discover`: these files hold bare test + # functions, not TestCase subclasses, so discover would collect nothing + # and exit 0. Each file fails when it collects no tests, which is what + # makes running them this way safe. + run: | + python3 docker/telemetry/workload/test_validate_telemetry.py + python3 docker/telemetry/workload/test_capture_timings.py diff --git a/docker/telemetry/workload/expected_spans.json b/docker/telemetry/workload/expected_spans.json index 6414b02d57..18cba41b23 100644 --- a/docker/telemetry/workload/expected_spans.json +++ b/docker/telemetry/workload/expected_spans.json @@ -539,7 +539,7 @@ "child": "pathfind.request", "description": "The RPC command span contains the path-finding request span.", "skip": true, - "skip_reason": "Real relationship, and the one skip here caused by a WILDCARD PARENT rather than by a missing span. _validate_parent_child builds its Tempo query as name=\"\" with the contract string inserted literally (validate_telemetry.py:801), so a parent of rpc.command.* searches for a span literally named that and finds nothing. Note the asymmetry: the CHILD side does handle globs, through _span_name_matches (:826-828), which is why rpc.ws_message -> rpc.command.* is asserted. Only the parent side is literal. Asserting this needs the parent query to accept a glob -- a TraceQL name=~ regex, or resolving the glob to the concrete names Tempo reports first. Independently of that, both ends are absent today anyway: the harness issues no path-finding RPC, see the pathfind.compute entry above.", + "skip_reason": "Real relationship, and the one skip here caused by a WILDCARD PARENT rather than by a missing span. _validate_parent_child builds its Tempo query as name=\"\" with the contract string inserted literally (validate_telemetry.py:801), so a parent of rpc.command.* searches for a span literally named that and finds nothing. Note the asymmetry: the ancestry check globs both sides through _span_name_matches, which is why rpc.ws_message -> rpc.command.* is asserted, but the Tempo query that selects the candidate traces is literal on the parent, so no trace is ever fetched to run it on. Asserting this needs the parent query to accept a glob -- a TraceQL name=~ regex, or resolving the glob to the concrete names Tempo reports first. Independently of that, both ends are absent today anyway: the harness issues no path-finding RPC, see the pathfind.compute entry above.", "added": "2026-08-26 to close the declared-but-unlisted gap" }, { diff --git a/docker/telemetry/workload/test_capture_timings.py b/docker/telemetry/workload/test_capture_timings.py new file mode 100644 index 0000000000..93b4d5bcaa --- /dev/null +++ b/docker/telemetry/workload/test_capture_timings.py @@ -0,0 +1,276 @@ +#!/usr/bin/env python3 +"""Tests for capture_timings.py's completeness guard. + +Run with plain python3 -- there is no pytest in the harness requirements, and +this file needs nothing but the standard library plus the aiohttp that +capture_timings.py already imports: + + python3 docker/telemetry/workload/test_capture_timings.py + +What is under test is the rule that decides whether a captured timings file may +become a regression baseline. It is worth pinning because every way of getting +it wrong is silently green: a capture that asked Prometheus for nothing, or got +almost nothing back, still produces a well-formed JSON file. If such a file is +accepted, it is pasted in as a baseline, still reads as a placeholder, and the +regression gate stays off while the workflow reports it as activated. + +Both halves are covered: the predicate itself, and the exit code, because the +workflow keys on the exit code while the paste-me step keys on the flag in the +file. They must not be able to disagree. +""" + +import asyncio +import json +import sys +import tempfile +from pathlib import Path +from typing import Any + +sys.path.insert(0, str(Path(__file__).parent)) + +import capture_timings as ct # noqa: E402 + + +def _surface(*values: float | None) -> dict[str, dict[str, Any]]: + """A metrics dict of len(values) keys, None meaning nothing came back.""" + return {f"metric_{i}": {"value": v} for i, v in enumerate(values)} + + +def test_empty_surface_is_not_complete() -> None: + """A capture that declared nothing must never count as complete. + + This is the vacuous-truth trap: 0 of 0 keys is 100% by arithmetic, so a + plain ratio test calls an empty capture a perfect one. It happens for real + whenever --metrics points at the wrong or a truncated file, since + build_query_plan returns an empty plan for that without complaining. + + The production change that makes this fail: dropping the `declared > 0` + term from the `complete` predicate. + """ + status = ct._capture_status({}, min_ratio=0.5) + assert status["declared"] == 0 + assert status["captured"] == 0 + assert status["complete"] is False, status + + +def test_ratio_exactly_at_the_minimum_is_complete() -> None: + """The bar is inclusive, so a capture sitting exactly on it passes. + + The production change that makes this fail: using `>` instead of `>=`, + which would reject a run that met the stated minimum exactly. + """ + status = ct._capture_status(_surface(1.0, None), min_ratio=0.5) + assert (status["captured"], status["declared"]) == (1, 2) + assert status["complete"] is True, status + + +def test_ratio_just_below_the_minimum_is_not_complete() -> None: + """One captured key out of three is below half and must be rejected. + + The production change that makes this fail: comparing against a constant, + or ignoring min_ratio and accepting any non-zero capture. + """ + status = ct._capture_status(_surface(1.0, None, None), min_ratio=0.5) + assert (status["captured"], status["declared"]) == (1, 3) + assert status["complete"] is False, status + + +def test_null_values_are_declared_but_not_captured() -> None: + """A key Prometheus had no answer for counts against the ratio. + + Every declared key is present in the artifact, some with value null, so + counting keys rather than values would report a full capture on a run that + got nothing back. + + The production change that makes this fail: setting captured to + len(metrics). + """ + status = ct._capture_status(_surface(1.0, 2.0, None, None), min_ratio=0.5) + assert status["declared"] == 4 + assert status["captured"] == 2 + + +def test_the_bar_it_was_judged_against_is_recorded() -> None: + """The artifact must state its own threshold, not just the verdict. + + Without it a rejected capture cannot be judged after the fact -- 8 of 20 is + a pass at 0.4 and a failure at 0.5, and the file is the only record of + which was asked for. + """ + assert ct._capture_status(_surface(1.0), min_ratio=0.75)["min_ratio"] == 0.75 + + +def _run_main(monkey_report: dict[str, Any]) -> tuple[int, dict[str, Any]]: + """Run main() against a crafted report, returning (exit code, written file). + + capture() is replaced rather than mocked at the HTTP layer because what is + under test is what main() does with a report, not how the report is + obtained. + """ + original_capture, original_argv = ct.capture, sys.argv + + async def fake_capture(**_kwargs: Any) -> dict[str, Any]: + return monkey_report + + with tempfile.TemporaryDirectory() as tmp: + out = Path(tmp) / "timings.json" + ct.capture = fake_capture + sys.argv = ["capture_timings.py", "--output", str(out)] + try: + code = ct.main() + written = json.loads(out.read_text()) + finally: + ct.capture, sys.argv = original_capture, original_argv + return code, written + + +def _report(metrics: dict[str, Any], min_ratio: float = 0.5) -> dict[str, Any]: + """A report shaped like capture()'s, with a real status block.""" + return { + "schema_version": ct.SCHEMA_VERSION, + "captured_at": "2026-01-01T00:00:00Z", + "window": "3m", + "git_sha": "0" * 40, + "profile": "regression", + "capture": ct._capture_status(metrics, min_ratio), + "metrics": metrics, + } + + +def test_incomplete_capture_exits_nonzero_and_says_so_in_the_file() -> None: + """The exit code and the flag in the file must agree. + + The workflow gates on the exit code while the paste-me step reads the flag, + so a run where they disagreed would be refused by one and offered as + baseline material by the other. + + The production change that makes this fail: returning 0 regardless, or + computing the exit code from something other than status["complete"]. + """ + code, written = _run_main(_report(_surface(1.0, None, None))) + assert code == 1, f"incomplete capture exited {code}" + assert written["capture"]["complete"] is False + + +def test_complete_capture_exits_zero_and_says_so_in_the_file() -> None: + """The passing direction, so the guard cannot be satisfied by always failing.""" + code, written = _run_main(_report(_surface(1.0, 2.0))) + assert code == 0, f"complete capture exited {code}" + assert written["capture"]["complete"] is True + + +def test_empty_surface_exits_nonzero_without_dividing_by_zero() -> None: + """The empty case needs its own error path, not the percentage one. + + Reporting "0/0 (0%)" requires captured / total, which raises + ZeroDivisionError on an empty surface -- turning a clear rejection into a + traceback, and on some callers into a non-1 exit the workflow reads + differently. + + The production change that makes this fail: removing the `total == 0` + branch and letting the percentage message handle every shortfall. + """ + code, written = _run_main(_report({})) + assert code == 1, f"empty capture exited {code}" + assert written["capture"]["declared"] == 0 + assert written["capture"]["complete"] is False + + +def test_capture_records_a_status_block_carrying_the_requested_ratio() -> None: + """capture() itself must build the status block, from the ratio it was given. + + The other tests here hand main() a report built by this file, so none of them + runs the real capture(). Without this, capture() could ignore + --min-capture-ratio, or stop emitting the capture block at all, and the suite + would stay green while every downstream consumer lost the flag it keys on. + + Only the Prometheus call is replaced; the query plan is built from the real + regression-metrics.json. + + The production change that makes this fail: dropping the capture block from + the returned report, or hardcoding the ratio instead of using the argument. + """ + original = ct.run_query_plan + + async def fake_run_query_plan(_session: Any, _url: str, _plan: Any) -> dict: + return {"kept": {"value": 1.0}, "missing": {"value": None}} + + ct.run_query_plan = fake_run_query_plan + try: + report = asyncio.run( + ct.capture( + prom_url="http://prometheus.invalid", + metrics_path=Path(__file__).parent / "regression-metrics.json", + window="3m", + profile="regression", + min_capture_ratio=0.75, + ) + ) + finally: + ct.run_query_plan = original + + assert "capture" in report, sorted(report) + status = report["capture"] + assert status["min_ratio"] == 0.75, status + assert (status["declared"], status["captured"]) == (2, 1), status + # 1 of 2 is 0.5, below the 0.75 that was asked for. + assert status["complete"] is False, status + + +def test_the_exit_code_follows_the_flag_not_a_recomputed_ratio() -> None: + """main() must read capture.complete, not judge the counts itself. + + The workflow gates on the exit code and the paste-me step reads the flag, so + the flag has to be the single source of truth. Recomputing the ratio in + main() would work today and drift the moment the two rules differed. Both + directions are asserted, because a mutation that recomputes agrees with the + flag on every self-consistent report -- only a contradictory one separates + them. + + The production change that makes this fail: deriving the exit code from + captured/declared rather than from status["complete"]. + """ + complete_flag_says_no = _report(_surface(1.0, 2.0)) + complete_flag_says_no["capture"]["complete"] = False + code, _ = _run_main(complete_flag_says_no) + assert code == 1, "a report flagged incomplete must exit non-zero" + + complete_flag_says_yes = _report(_surface(1.0, None, None)) + complete_flag_says_yes["capture"]["complete"] = True + code, _ = _run_main(complete_flag_says_yes) + assert code == 0, "a report flagged complete must exit zero" + + +def main() -> int: + tests = [v for k, v in sorted(globals().items()) if k.startswith("test_")] + # Collecting nothing is a failure, not a pass. A rename of the test_ prefix, + # or running this file from a context where the globals are not populated, + # would otherwise print "0/0 passed" and exit 0 -- the silent green these + # tests exist to prevent, reproduced in the runner itself. + if not tests: + print("FAIL: no tests were collected") + return 1 + failed = 0 + for test in tests: + try: + test() + except AssertionError as exc: + failed += 1 + print(f"FAIL {test.__name__}: {exc}") + except SystemExit as exc: + # argparse and other sys.exit() paths raise SystemExit, which is NOT + # an Exception subclass. Uncaught it aborts the whole file, so the + # remaining tests never run and nothing prints a FAIL line. + failed += 1 + print(f"ERROR {test.__name__}: SystemExit({exc.code})") + 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/test_validate_telemetry.py b/docker/telemetry/workload/test_validate_telemetry.py index 84358e92a8..ac5f09a6ba 100644 --- a/docker/telemetry/workload/test_validate_telemetry.py +++ b/docker/telemetry/workload/test_validate_telemetry.py @@ -49,14 +49,47 @@ 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. + traces: Maps a trace id to the spans that trace contains, ordered newest + first, which is the order /api/search returns. Each entry is + either a bare span name (a root span, no parent) or a + ``(name, parent_name)`` pair. A parent_name that no span in the + trace carries yields a parentSpanId pointing at a span the trace + does not hold, which is how a dangling chain is expressed. + + Span ids are generated as ``-``. Their spelling does not + matter: the code under test compares parentSpanId to spanId as opaque + strings, exactly because Tempo's own encoding of those fields (hex or + base64) is not something the validator should depend on. """ - def __init__(self, traces: dict[str, list[str]]) -> None: + def __init__(self, traces: dict[str, list[Any]]) -> None: self.traces = traces self.queries: list[tuple[str, int]] = [] + def _spans_for(self, tid: str) -> list[dict[str, Any]]: + """Build the OTLP span dicts for one trace, resolving parents by name.""" + entries = self.traces.get(tid, []) + names = [_entry_name(e) for e in entries] + ids = [f"{tid}-{i}" for i in range(len(entries))] + spans = [] + for i, entry in enumerate(entries): + span: dict[str, Any] = { + "name": names[i], + "spanId": ids[i], + "attributes": [], + } + parent = entry[1] if isinstance(entry, tuple) else None + if parent is not None: + # An unknown parent name deliberately produces an id no span in + # this trace owns, so the walk up the chain hits a gap. + span["parentSpanId"] = ( + ids[names.index(parent)] + if parent in names + else f"{tid}-absent-{parent}" + ) + spans.append(span) + return spans + def get(self, url: str, params: dict[str, str] | None = None) -> FakeResponse: params = params or {} if "/api/search" in url: @@ -64,17 +97,23 @@ class FakeTempo: self.queries.append((query, limit)) matched = [ tid - for tid, names in self.traces.items() - if _query_matches_trace(query, names) + for tid, entries in self.traces.items() + if _query_matches_trace(query, [_entry_name(e) for e in entries]) ] 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}]}]}) + return FakeResponse( + {"batches": [{"scopeSpans": [{"spans": self._spans_for(tid)}]}]} + ) raise AssertionError(f"unexpected request: {url}") +def _entry_name(entry: Any) -> str: + """The span name of a corpus entry, whether bare or a (name, parent) pair.""" + return entry[0] if isinstance(entry, tuple) else entry + + def _query_matches_trace(query: str, names: list[str]) -> bool: """Evaluate the subset of TraceQL this suite uses against one trace. @@ -133,7 +172,7 @@ def test_child_found_in_a_trace_outside_the_newest_three() -> None: "t4": ["txq.accept"], "t3": ["txq.accept"], "t2": ["txq.accept"], - "t1": ["txq.accept", "txq.accept_tx"], + "t1": ["txq.accept", ("txq.accept_tx", "txq.accept")], } ) report = Report() @@ -201,7 +240,7 @@ def test_wildcard_child_matches_any_family_member() -> None: 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"]}) + tempo = FakeTempo({"t1": ["rpc.ws_message", ("rpc.command.fee", "rpc.ws_message")]}) report = Report() run( vt._validate_parent_child( @@ -251,17 +290,284 @@ def test_wildcard_predicate_matches_the_family_but_not_near_misses() -> None: assert not _re.fullmatch(pattern, "other.command.fee") +def test_co_occurring_child_that_is_not_a_descendant_fails() -> None: + """Sharing a trace is not a hierarchy -- the check must reject it. + + The whole point of a check named span.hierarchy.A->B is that B hangs under + A. Here both spans are in one trace but tx.apply hangs off an unrelated + root, so the relationship the report claims does not hold. Accepting this + would let the check pass on any trace wide enough to contain both names, + including two spans that merely happen to share a request. + + The production change that makes this fail: verifying co-occurrence only, + without walking parentSpanId up to the parent's spanId. + """ + tempo = FakeTempo( + { + "t1": [ + "ledger.build", + "unrelated.root", + ("tx.apply", "unrelated.root"), + ] + } + ) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "ledger.build", "child": "tx.apply"}, + report, + ) + ) + assert len(report.results) == 1, report.results + result = report.results[0] + assert ( + not result.passed + ), f"co-occurrence was accepted as hierarchy: {result.message}" + assert "not under" in result.message, result.message + + +def test_direct_child_passes() -> None: + """The ordinary case: the child's parent is the parent span itself.""" + tempo = FakeTempo({"t1": ["ledger.build", ("tx.apply", "ledger.build")]}) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "ledger.build", "child": "tx.apply"}, + report, + ) + ) + assert report.results[0].passed, report.results[0].message + + +def test_child_under_an_intermediate_span_still_passes() -> None: + """A grandchild satisfies "contains" -- the contract is ancestry, not an edge. + + Every relationship in expected_spans.json is worded as the parent + "containing" the child, so an extra span appearing in between is not a + broken relationship. Requiring a direct edge would turn a refactor that + introduces an intermediate scope into a false failure. + + The production change that makes this fail: comparing the child's + parentSpanId to the parent's spanId only, instead of walking the chain. + """ + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.establish", "consensus.round"), + ("consensus.check", "consensus.establish"), + ] + } + ) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "consensus.round", "child": "consensus.check"}, + report, + ) + ) + assert report.results[0].passed, report.results[0].message + + +def test_broken_chain_is_reported_as_such_not_as_a_missing_child() -> None: + """A chain that runs into a span the trace lacks is its own diagnosis. + + This is the dangling-parent shape: the child names a parent the trace does + not hold, so ancestry cannot be established either way. Reporting it as "not + under the parent" would send whoever reads it looking for a hierarchy bug in + the instrumentation, when the actual problem is a span that never reached + Tempo or a synthetic parent id. + + The production change that makes this fail: collapsing the broken-chain case + into the plain not-a-descendant message. + """ + tempo = FakeTempo( + { + "t1": [ + "consensus.establish", + ("consensus.check", "never.exported"), + ] + } + ) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "consensus.establish", "child": "consensus.check"}, + report, + ) + ) + result = report.results[0] + assert not result.passed, result.message + assert "chain" in result.message, result.message + # The id of the span the chain ran into is the whole diagnostic value here, + # so the message must name it. Without this the detail could be dropped and + # the message would still read "runs into span , which the trace..." + assert "t1-absent-never.exported" in result.message, result.message + + +def test_one_child_not_under_outranks_another_childs_broken_chain() -> None: + """A definite negative beats an unprovable one within the same trace. + + Two spans share the child's name: one dangles off a span the trace lacks, + the other is cleanly parented by an unrelated root. The second answers the + question -- the child really is not under the parent -- so that is what the + report must say, whichever order the spans arrive in. + + The production change that makes this fail: returning broken_chain whenever + any child hit a gap, without checking whether another child gave a definite + answer. + """ + tempo = FakeTempo( + { + "t1": [ + "ledger.build", + "unrelated.root", + ("tx.apply", "never.exported"), + ("tx.apply", "unrelated.root"), + ] + } + ) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "ledger.build", "child": "tx.apply"}, + report, + ) + ) + result = report.results[0] + assert not result.passed, result.message + assert "not under" in result.message, result.message + + +def test_a_later_trace_can_prove_what_an_earlier_one_disproved() -> None: + """Every candidate trace is examined, not just the first. + + The first trace carries the child parented elsewhere; the second has it + correctly nested. One trace proving the relationship is enough, so the + report must pass. This is the conditional-child shape: whether a given trace + nests the child depends on which branch the code took. + + The production change that makes this fail: reporting the first trace's + verdict, or breaking out of the loop on the first negative. + """ + tempo = FakeTempo( + { + "t2": ["ledger.build", "elsewhere", ("tx.apply", "elsewhere")], + "t1": ["ledger.build", ("tx.apply", "ledger.build")], + } + ) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "ledger.build", "child": "tx.apply"}, + report, + ) + ) + assert report.results[0].passed, report.results[0].message + + +def test_parent_without_a_span_id_is_not_reported_as_a_missing_child() -> None: + """An unusable parent span is its own diagnosis. + + A trace selected for containing the parent, whose parent span carries no + spanId, cannot be used to establish ancestry. Saying "child not found" would + send the reader after a child that is plainly present, which is the kind of + laundering this file's Tempo error handling exists to avoid. + + The production change that makes this fail: ranking no_parent below the + starting verdict, which makes it unreachable and falls back to the + missing-child message. + """ + tempo = FakeTempo({"t1": ["ledger.build", ("tx.apply", "ledger.build")]}) + # Drop the parent's id after the stub built the trace, which is the one thing + # the corpus format cannot express. + original = tempo._spans_for + + def without_parent_id(tid: str) -> list[dict[str, Any]]: + spans = original(tid) + for span in spans: + if span["name"] == "ledger.build": + del span["spanId"] + return spans + + tempo._spans_for = without_parent_id # type: ignore[method-assign] + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "ledger.build", "child": "tx.apply"}, + report, + ) + ) + result = report.results[0] + assert not result.passed, result.message + assert "ledger.build" in result.message, result.message + assert "not found" not in result.message, result.message + + +def test_a_cyclic_parent_chain_terminates() -> None: + """A chain that loops must fail rather than spin. + + Malformed data can point two spans at each other. The walk keeps a seen set + so it gives up instead of looping. Note the failure mode this guards is a + HANG, so removing the guard makes this test time out rather than report a + failure -- red either way, just slower. + """ + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.check", "loop.b"), + ("loop.b", "consensus.check"), + ] + } + ) + report = Report() + run( + vt._validate_parent_child( + tempo, + "http://tempo", + {"parent": "consensus.round", "child": "consensus.check"}, + report, + ) + ) + assert not report.results[0].passed, report.results[0].message + + def test_literal_predicate_uses_equality() -> None: """A non-glob child must use `=`, not a regex. - Equality is what makes a longer emitted name unable to satisfy a shorter - contract, the same guarantee _span_name_matches gives on the client side. + Equality is what stops a longer emitted name satisfying a shorter contract. + Both sides are asserted because both enforce it: the query Tempo runs, and + _span_name_matches when the fetched spans are re-checked. """ assert vt._traceql_name_predicate("txq.accept_tx") == 'name="txq.accept_tx"' + assert vt._span_name_matches("txq.accept_tx", "txq.accept_tx") + assert not vt._span_name_matches("txq.accept_tx_extra", "txq.accept_tx") def main() -> int: tests = [v for k, v in sorted(globals().items()) if k.startswith("test_")] + # Collecting nothing is a failure, not a pass. A rename of the test_ prefix, + # or running this file from a context where the globals are not populated, + # would otherwise print "0/0 passed" and exit 0 -- exactly the silent green + # these tests exist to prevent, reproduced in the runner itself. + if not tests: + print("FAIL: no tests were collected") + return 1 failed = 0 for test in tests: try: @@ -269,6 +575,12 @@ def main() -> int: except AssertionError as exc: failed += 1 print(f"FAIL {test.__name__}: {exc}") + except SystemExit as exc: + # argparse and other sys.exit() paths raise SystemExit, which is NOT + # an Exception subclass. Uncaught it aborts the whole file, so the + # remaining tests never run and nothing prints a FAIL line. + failed += 1 + print(f"ERROR {test.__name__}: SystemExit({exc.code})") except Exception as exc: # noqa: BLE001 - report any error as a failure failed += 1 print(f"ERROR {test.__name__}: {type(exc).__name__}: {exc}") diff --git a/docker/telemetry/workload/validate_telemetry.py b/docker/telemetry/workload/validate_telemetry.py index 821423df5f..71daecc9c6 100644 --- a/docker/telemetry/workload/validate_telemetry.py +++ b/docker/telemetry/workload/validate_telemetry.py @@ -387,8 +387,9 @@ async def _tempo_get_trace( TempoQueryError. Returns: - Flat list of span dicts with 'name' and 'attributes' keys. Empty when - Tempo has no trace with this id. + Flat list of span dicts as Tempo returned them, carrying at least + 'name', 'attributes', 'spanId' and, for non-root spans, 'parentSpanId'. + Empty when Tempo has no trace with this id. Raises: TempoQueryError: Tempo answered with a status other than 200 or 404. @@ -856,6 +857,151 @@ async def _validate_span_attributes_otlp( ) +# Verdicts _span_ancestry can return, most conclusive first. A single trace +# proving "under" settles the relationship, so it wins outright. A definite +# negative outranks an indefinite one: "not_under" means a chain was walked to a +# root and the parent was not on it, while "broken_chain" only means ancestry +# could not be established, which is a different thing to go and look at. +# "no_child" ranks last because it is the starting value: a relationship with no +# candidate trace at all reports it, and every other verdict must be able to +# replace it. +_ANCESTRY_PRIORITY = ("under", "not_under", "broken_chain", "no_parent", "no_child") + + +def _span_ancestry( + spans: list[dict[str, Any]], + parent_name: str, + child_name: str, +) -> tuple[str, str]: + """Decide whether a matching child hangs under a matching parent in one trace. + + Walks each candidate child's parentSpanId chain upwards. Ancestry rather + than a direct edge, because every relationship in expected_spans.json is + worded as the parent "containing" the child: a scope appearing in between is + a refactor, not a broken relationship. + + Span ids are compared as opaque strings and never decoded. Both fields come + from the same Tempo response and so share whatever encoding it uses, which + keeps this independent of whether that is hex or base64. + + Args: + spans: Every OTLP span dict in one fetched trace. + parent_name: Parent name from the contract; may be a glob. + child_name: Child name from the contract; may be a glob. + + Returns: + ``(verdict, detail)``. Verdict is one of ``_ANCESTRY_PRIORITY``. For + ``broken_chain`` the detail is the span id the chain ran into. + """ + by_id = {s["spanId"]: s for s in spans if s.get("spanId")} + parent_ids = { + s["spanId"] + for s in spans + if s.get("spanId") and _span_name_matches(s.get("name", ""), parent_name) + } + children = [s for s in spans if _span_name_matches(s.get("name", ""), child_name)] + if not children: + return "no_child", "" + if not parent_ids: + return "no_parent", "" + + broken = "" + walked_to_a_root = False + for child in children: + current = child.get("parentSpanId", "") + # Guards against a cycle in malformed data, which would otherwise spin + # here forever rather than failing the check. + seen: set[str] = set() + while current and current not in seen: + if current in parent_ids: + return "under", "" + seen.add(current) + if (next_span := by_id.get(current)) is None: + # This child proves nothing either way. Keep the first gap seen, + # in case no other child yields a definite answer. + broken = broken or current + break + current = next_span.get("parentSpanId", "") + else: + # Ran out of chain rather than hitting a gap, so this child really is + # not under the parent. One such child is a definite negative and + # outranks any other child's gap. + walked_to_a_root = True + if walked_to_a_root or not broken: + return "not_under", "" + return "broken_chain", broken + + +def _hierarchy_message( + parent_name: str, child_name: str, verdict: str, detail: str +) -> str: + """Phrase one ancestry verdict for the report. + + Each verdict gets its own wording because they send the reader somewhere + different: a missing child is a workload or instrumentation gap, a child + that is present but not under the parent is a hierarchy bug, and a broken + chain is a span that never reached Tempo. + """ + if verdict == "under": + return f"Found {child_name} under {parent_name}" + if verdict == "not_under": + return ( + f"{child_name} shares a trace with {parent_name} but is not under " + f"it -- co-occurrence is not a hierarchy" + ) + if verdict == "broken_chain": + return ( + f"{child_name}'s parent chain runs into span {detail}, which the " + f"trace does not contain, so ancestry under {parent_name} cannot " + f"be verified" + ) + if verdict == "no_parent": + return f"{parent_name} absent from traces selected for containing it" + return f"{child_name} not found in {parent_name} traces" + + +async def _best_ancestry_verdict( + session: aiohttp.ClientSession, + tempo_url: str, + traces: list[dict[str, Any]], + parent_name: str, + child_name: str, +) -> tuple[str, str]: + """Fetch each candidate trace and keep the most conclusive verdict. + + Every candidate is examined rather than stopping at the first negative, + because a conditional child may hang correctly in one trace while another + carries the parent alone. Stops early once one trace proves "under", which + nothing later can improve on. + + Names are re-checked per trace rather than trusted from the query that + selected it: it keeps the glob handling in one place, so a wrongly built + query cannot pass silently. + + Args: + session: aiohttp client session. + tempo_url: Base URL for the Tempo API. + traces: Trace summaries that matched parent and child. + parent_name: Parent name from the contract; may be a glob. + child_name: Child name from the contract; may be a glob. + + Returns: + The winning ``(verdict, detail)`` from _span_ancestry. + """ + verdict, detail = "no_child", "" + for trace_summary in traces: + trace_id = trace_summary.get("traceID", "") + if not trace_id: + continue + spans = await _tempo_get_trace(session, tempo_url, trace_id) + candidate, candidate_detail = _span_ancestry(spans, parent_name, child_name) + if _ANCESTRY_PRIORITY.index(candidate) < _ANCESTRY_PRIORITY.index(verdict): + verdict, detail = candidate, candidate_detail + if verdict == "under": + break + return verdict, detail + + async def _validate_parent_child( session: aiohttp.ClientSession, tempo_url: str, @@ -864,6 +1010,10 @@ async def _validate_parent_child( ) -> None: """Validate a parent-child span relationship in Tempo traces. + Co-occurrence in a trace is the search filter, not the assertion: the check + then walks the child's parentSpanId chain to confirm it really hangs under + the parent. See _span_ancestry. + Args: session: aiohttp client session. tempo_url: Base URL for Tempo API. @@ -899,32 +1049,15 @@ async def _validate_parent_child( both_query = query + " && {" + _traceql_name_predicate(child_name) + "}" traces = await _tempo_search(session, tempo_url, both_query, limit=3) - # Re-check the names even though Tempo already guaranteed co-occurrence: - # it keeps the glob handling in one place, and a wrongly built query - # cannot then pass silently. Matched exactly (globs for wildcard - # contracts) so a longer emitted name cannot satisfy a shorter contract. - found_child = False - for trace_summary in traces: - trace_id = trace_summary.get("traceID", "") - if not trace_id: - continue - spans = await _tempo_get_trace(session, tempo_url, trace_id) - if any( - _span_name_matches(span.get("name", ""), child_name) for span in spans - ): - found_child = True - break - + verdict, detail = await _best_ancestry_verdict( + session, tempo_url, traces, parent_name, child_name + ) report.add( CheckResult( name=f"span.hierarchy.{parent_name}->{child_name}", category="span", - passed=found_child, - message=( - f"Found {child_name} as child of {parent_name}" - if found_child - else f"{child_name} not found in {parent_name} traces" - ), + passed=verdict == "under", + message=_hierarchy_message(parent_name, child_name, verdict, detail), ) ) except Exception as exc: diff --git a/docs/build/telemetry.md b/docs/build/telemetry.md index 8735a652ca..14f7d1d5a9 100644 --- a/docs/build/telemetry.md +++ b/docs/build/telemetry.md @@ -15,11 +15,13 @@ This document explains how to build xrpld with OpenTelemetry distributed tracing - [Conan lockfile error](#conan-lockfile-error) - [CMake target not found](#cmake-target-not-found) - [Conditional compilation](#conditional-compilation) + - [Recording utilities](#recording-utilities) - [Span lifetime and cross-thread handling](#span-lifetime-and-cross-thread-handling) - [`SpanGuard` versus `ScopedSpanGuard`](#spanguard-versus-scopedspanguard) - [Coroutine-aware context storage](#coroutine-aware-context-storage) - [Handing a span to a job](#handing-a-span-to-a-job) - [Why are unrelated spans in my trace?](#why-are-unrelated-spans-in-my-trace) + - [Injecting trace context into a protobuf message](#injecting-trace-context-into-a-protobuf-message) ## Overview @@ -142,12 +144,54 @@ The Conan package provides a single umbrella target ## Conditional compilation -All OpenTelemetry SDK types are hidden behind the pimpl idiom in `SpanGuard.cpp`. -When `XRPL_ENABLE_TELEMETRY` is not defined, `SpanGuard.h` provides an all-inline -no-op stub class with zero overhead and zero OTel dependencies. -At runtime, if `enabled=0` is set in config (or the section is omitted), a -`NullTelemetry` implementation is used that returns no-op spans. -This two-layer approach ensures zero overhead when telemetry is not wanted. +All OpenTelemetry SDK types are hidden behind the pimpl idiom in `SpanGuard.cpp`. When `XRPL_ENABLE_TELEMETRY` is not defined, `SpanGuard.h` provides an all-inline no-op stub class with no OTel dependencies. At runtime, if `enabled=0` is set in config (or the section is omitted), a `NullTelemetry` implementation is used that returns no-op spans. + +Those two layers remove the span, but they do **not** remove the work that computes what you pass to it. The compiled-out guards are ordinary inline functions with ordinary parameters, so every argument is evaluated before the empty body is entered: + +```cpp +// to_string() allocates a 64-character string even in a build with telemetry +// compiled out. The call then does nothing with it. +span.setAttribute(attr::txHash, to_string(txID).c_str()); +``` + +Guard the work, not just the call. Testing the guard is enough: its `operator bool()` is a literal `false` when telemetry is compiled out, so the whole block is eliminated, and when telemetry is compiled in it also skips the work if tracing is switched off in config or the span's category is disabled. + +```cpp +if (span) + span.setAttribute(attr::txHash, to_string(txID).c_str()); +``` + +A span that exists but was sampled out still pays: there is no `isRecording()` to test. + +The `XRPL_METRIC_*` macros are the opposite case. They expand to `do { } while (false)` and discard their arguments, so anything named only inside a macro argument list disappears on its own and needs no guard. + +## Recording utilities + +Some state exists only to be reported: a timestamp read to measure something, a counter nothing outside telemetry reads, a value kept so that a change in it can be logged. Writing that with preprocessor branches puts `#ifdef` through business logic and leaves the class with a different member set in each build — a difference that has previously made a test mock abstract. + +`xrpl/telemetry/Recording.h` holds that state in types that carry a real member when telemetry is compiled in and are empty types with no-op methods when it is not. Declare the member unconditionally: its storage collapses to padding, and its work disappears. + +| Utility | Use it for | With telemetry compiled out | +| ------------ | ------------------------------------------------------------------------------------------- | ------------------------------------------------ | +| `kEnabled` | `if constexpr (telemetry::kEnabled)` around a telemetry-only block that has no span to test | `false`, so the block is discarded | +| `Stopwatch` | an elapsed time measured only in order to report it | holds nothing; `elapsedUs()` returns exactly `0` | +| `Counter` | a count with no reader outside telemetry | holds nothing; `load()` returns `T{}` | + +```cpp +// Times a loop with no preprocessor branch anywhere. The clock is not read at +// all in a build with telemetry compiled out. +telemetry::Stopwatch const timer; +for (auto const& obj : objects) + lookUp(obj); +recordLookupMetrics(timer.elapsedUs()); +``` + +Two constraints decide whether these are usable at a given site: + +- **A no-op method does not skip its arguments.** `counter.add(expensiveCount())` still calls `expensiveCount()`. Pass values that are cheap to produce, and put anything expensive inside `if constexpr (telemetry::kEnabled)`. +- **`if constexpr` still type-checks the branch it discards** in non-template code, so use it only where the block names no `opentelemetry::` type. `SpanGuard` exists to keep those types out of call sites, so that is the usual case; a block that does name them stays behind `#ifdef`. + +`Counter` declares copy and move deleted, matching the `std::atomic` it holds when telemetry is compiled in, so a class that owns one has the same copy semantics in both builds. ## Span lifetime and cross-thread handling @@ -244,3 +288,28 @@ root and never adopts whatever span happened to be active. To move a span across a store boundary, keep it in a thread-free `SpanGuard` (or convert via `operator SpanGuard() &&`) rather than holding a `ScopedSpanGuard` across the boundary. + +### Injecting trace context into a protobuf message + +Pass the **whole message** to the injection helpers, never `*msg.mutable_trace_context()`. + +On a protobuf `optional` submessage, `mutable_` allocates the submessage and sets its has-bit, and that happens at the call site before the helper runs. A caller that dereferences it therefore puts an empty `TraceContext` on the wire whenever nothing is recorded, and every receiving peer takes its `has_trace_context()` branch to extract nothing from it. `trace_context` is field 1001, so the wasted bytes are a 2-byte tag plus a zero length. + +```cpp +// Right: the helper decides whether the submessage is created at all. +telemetry::injectSpanContext(span, msg); + +// Wrong: the submessage exists before the helper can decide anything. +telemetry::injectSpanContext(span, *msg.mutable_trace_context()); +``` + +`injectCurrentContext(msg)` does the same for whichever span is active on the calling thread, deciding via `SpanGuard::hasCurrentContext()`. Four states have to come out right: + +| Build | Runtime | Result | +| ------------ | ---------------- | -------------------------------------------------------------------- | +| compiled out | n/a | no submessage; the bytes on the wire match a build without telemetry | +| compiled in | a span is active | `trace_id`, `span_id` and the trace flags are written | +| compiled in | no active span | no submessage, rather than an empty one | +| compiled in | `enabled=0` | no submessage | + +`hasCurrentContext()` reads the span straight out of the runtime context. `opentelemetry::trace::GetSpan()` would be shorter, but it returns a heap-allocated `DefaultSpan` when the context holds no span — an allocation in exactly the case the predicate exists to keep free. diff --git a/include/xrpl/telemetry/Recording.h b/include/xrpl/telemetry/Recording.h index 41d530dd71..24c18d418f 100644 --- a/include/xrpl/telemetry/Recording.h +++ b/include/xrpl/telemetry/Recording.h @@ -17,7 +17,6 @@ * | * +-- Stopwatch (a clock read nobody reads when off) * +-- Counter (an atomic nobody reads when off) - * +-- Mirror (a value kept only to be reported) * * @note A no-op method does NOT skip evaluation of its arguments. * `counter.add(expensiveCount())` still calls `expensiveCount()` when @@ -30,8 +29,8 @@ * to keep those types out of call sites. * * @note Thread safety: `Counter` is safe to update from any thread. - * `Stopwatch` and `Mirror` are not synchronized; guard them the same way - * you guard the state they sit beside. + * `Stopwatch` is not synchronized; guard it the same way you guard the state + * it sits beside. * * Usage: * @code diff --git a/src/tests/libxrpl/telemetry/NodeIdResource.cpp b/src/tests/libxrpl/telemetry/NodeIdResource.cpp index c0f4387b7e..f0b36c7966 100644 --- a/src/tests/libxrpl/telemetry/NodeIdResource.cpp +++ b/src/tests/libxrpl/telemetry/NodeIdResource.cpp @@ -42,17 +42,19 @@ using namespace xrpl::telemetry; TEST(NodeIdResource, attribute_key_is_dotted_resource_form) { // The literal the collector, TraceQL and the dashboards all name. - EXPECT_EQ(std::string_view(attr::nodeId), "xrpl.node.id"); + EXPECT_EQ(std::string_view(telemetry::attr::nodeId), "xrpl.node.id"); // Dotted, not the underscore form used for span attributes. - EXPECT_EQ(std::string_view(attr::nodeId).find('_'), std::string_view::npos); + EXPECT_EQ(std::string_view(telemetry::attr::nodeId).find('_'), std::string_view::npos); // Sibling of the other two xrpl.* resource attributes, and distinct // from both. - EXPECT_EQ(std::string_view(attr::networkId), "xrpl.network.id"); - EXPECT_EQ(std::string_view(attr::networkType), "xrpl.network.type"); - EXPECT_NE(std::string_view(attr::nodeId), std::string_view(attr::networkId)); - EXPECT_NE(std::string_view(attr::nodeId), std::string_view(attr::networkType)); + EXPECT_EQ(std::string_view(telemetry::attr::networkId), "xrpl.network.id"); + EXPECT_EQ(std::string_view(telemetry::attr::networkType), "xrpl.network.type"); + EXPECT_NE( + std::string_view(telemetry::attr::nodeId), std::string_view(telemetry::attr::networkId)); + EXPECT_NE( + std::string_view(telemetry::attr::nodeId), std::string_view(telemetry::attr::networkType)); // Built from the shared segments, so the segment additions are exercised // too rather than only the joined result. @@ -121,7 +123,7 @@ TEST(NodeIdResource, resource_carries_node_id_as_a_string) otel_resource::ResourceAttributes attrs; // std::string, never a string literal: the attribute variant's // char-const* overload binds to bool, which would record `true`. - attrs[std::string(attr::nodeId)] = nodeId; + attrs[std::string(telemetry::attr::nodeId)] = nodeId; auto const resource = otel_resource::Resource::Create(attrs); auto const& out = resource.GetAttributes(); @@ -147,7 +149,7 @@ TEST(NodeIdResource, resource_omits_node_id_when_it_was_never_set) otel_resource::ResourceAttributes attrs; if (!setup.nodeId.empty()) - attrs[std::string(attr::nodeId)] = setup.nodeId; + attrs[std::string(telemetry::attr::nodeId)] = setup.nodeId; auto const resource = otel_resource::Resource::Create(attrs); auto const& out = resource.GetAttributes(); diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index 5f0b327713..f981d52e52 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -2146,26 +2146,26 @@ PeerImp::onMessage(std::shared_ptr const& m) // out, so nothing is allocated on a path every inbound proposal takes. // The job body only carries the handle to hold the span alive, so an // empty handle is safe there. - std::shared_ptr span; + std::shared_ptr proposalSpan; #ifdef XRPL_ENABLE_TELEMETRY - span = std::make_shared(telemetry::proposalReceiveSpan(set)); + proposalSpan = std::make_shared(telemetry::proposalReceiveSpan(set)); #endif - // Every attribute below exists only for the span, so the block is guarded - // on the span being live. Unguarded, each inbound proposal — trusted or + // Every attribute below exists only for the proposalSpan, so the block is guarded + // on the proposalSpan being live. Unguarded, each inbound proposal — trusted or // not — builds two full hex strings and a substring of each, four string // allocations no one reads. - if (span && *span) + if (proposalSpan && *proposalSpan) { - span->setAttribute(telemetry::consensus::span::attr::proposalTrusted, isTrusted); - span->setAttribute( + proposalSpan->setAttribute(telemetry::consensus::span::attr::proposalTrusted, isTrusted); + proposalSpan->setAttribute( telemetry::consensus::span::attr::round, static_cast(set.proposeseq())); // First 16 hex chars (8 bytes) of each hash — enough to disambiguate // peer positions and prior ledgers without exporting full 32-byte // hashes on every receive event. - span->setAttribute( + proposalSpan->setAttribute( telemetry::consensus::span::attr::prevLedgerPrefix, to_string(prevLedger).substr(0, 16).c_str()); - span->setAttribute( + proposalSpan->setAttribute( telemetry::consensus::span::attr::positionHashPrefix, to_string(proposeHash).substr(0, 16).c_str()); } @@ -2174,7 +2174,7 @@ PeerImp::onMessage(std::shared_ptr const& m) app_.getJobQueue().addJob( isTrusted ? JtProposalT : JtProposalUt, "checkPropose", - [weak, isTrusted, m, proposal, sp = std::move(span)]() { + [weak, isTrusted, m, proposal, sp = std::move(proposalSpan)]() { if (auto peer = weak.lock()) peer->checkPropose(isTrusted, m, proposal); });