diff --git a/docker/telemetry/grafana/provisioning/alerting/contactpoints.yaml b/docker/telemetry/grafana/provisioning/alerting/contactpoints.yaml index 06407f904e..0083b584d4 100644 --- a/docker/telemetry/grafana/provisioning/alerting/contactpoints.yaml +++ b/docker/telemetry/grafana/provisioning/alerting/contactpoints.yaml @@ -61,12 +61,12 @@ contactPoints: # selects Slack webhook mode (no recipient/token required) and keeps # provisioning valid. Replace with a real webhook to enable delivery. url: https://hooks.slack.invalid/disabled - # `rulename` is used rather than CommonLabels.service_instance_id - # because on NoData/Error evaluations Grafana replaces the query's - # label set with only {datasource_uid, ref_id}, so the node label is - # absent and the title would render blank — and several rules are - # deliberately configured to fire that way. - title: "{{ .CommonLabels.rulename }}" + # Title and body both come from templates.yaml. `alertname` is the + # label Grafana sets on every alert; `service_instance_id` is a query + # label and is absent on NoData/Error evaluations, so the templates + # guard it rather than referencing it bare. + title: '{{ template "xrpld.title" . }}' + text: '{{ template "xrpld.body" . }}' disableResolveMessage: false # --- Critical tier: Slack + email --- @@ -78,7 +78,10 @@ contactPoints: settings: # Disabled placeholder — see xrpld-slack-default above. url: https://hooks.slack.invalid/disabled - title: "[CRITICAL] {{ .CommonLabels.rulename }}" + # The title template already carries the severity label, so this tier + # needs no separate "[CRITICAL]" prefix. + title: '{{ template "xrpld.title" . }}' + text: '{{ template "xrpld.body" . }}' disableResolveMessage: false - uid: xrpld-email-critical type: email @@ -90,6 +93,12 @@ contactPoints: addresses: alerts-disabled@xrpld.invalid # One message listing all recipients, rather than one message each. singleEmail: true + # Setting `message` replaces Grafana's default email body, which is + # what removes the raw value dump and the label list. Grafana's own + # header ("N firing alert instances", "Grouped by") and footer are + # fixed chrome and stay. + subject: '{{ template "xrpld.title" . }}' + message: '{{ template "xrpld.body" . }}' disableResolveMessage: false # To retire a receiver that a running Grafana has already stored, uncomment diff --git a/docker/telemetry/grafana/provisioning/alerting/rules.yaml b/docker/telemetry/grafana/provisioning/alerting/rules.yaml index 0f0f8223a3..e6adaa7ee9 100644 --- a/docker/telemetry/grafana/provisioning/alerting/rules.yaml +++ b/docker/telemetry/grafana/provisioning/alerting/rules.yaml @@ -67,9 +67,11 @@ groups: annotations: summary: "Ledger history mismatch on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} recorded - {{ $values.B.Value }} ledger history mismatch(es) in the last 15m. - The node's built ledger diverges from the validated network chain. + Ledger history mismatches on {{ $labels.service_instance_id }} in the last + 15m: {{ printf "%.0f" $values.B.Value }} (threshold: more than 0). + action: >- + A built ledger diverged from the validated network chain, which can mean + corrupt local history. Check byzantine ledger jumps and the node-store. data: - refId: A relativeTimeRange: @@ -131,9 +133,11 @@ groups: annotations: summary: "Ledger closing stalled on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} has closed no ledgers for - several minutes (5m rate has decayed to zero). Consensus or ledger - advancement is stuck, or the process is gone. + Ledger close rate on {{ $labels.service_instance_id }} over 5m: {{ printf + "%.4f" $values.B.Value }} ledgers/s (threshold: below 0.001). + action: >- + Consensus or ledger advancement is stuck, or the process is gone. Check + consensus round duration, worker pool saturation and peer supply. data: - refId: A relativeTimeRange: @@ -206,9 +210,11 @@ groups: annotations: summary: "Validated ledger stale on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} has a validated ledger age of - {{ $values.B.Value }}s (>60s). The node is not keeping up with the - validated network chain. + Validated ledger age on {{ $labels.service_instance_id }}: {{ printf "%.0f" + $values.B.Value }}s (threshold: over 60s). + action: >- + The node is no longer tracking the network. Check peer connectivity, node- + store IO latency and consensus rounds. data: - refId: A relativeTimeRange: @@ -285,9 +291,10 @@ groups: annotations: summary: "Validations missed on {{ $labels.service_instance_id }}" description: >- - Validator {{ $labels.service_instance_id }} is missing - {{ $values.B.Value }} (fraction) of its validations over 15m. Its - validations are not agreeing with the validated ledger, which risks + Missed-validation fraction on {{ $labels.service_instance_id }} over 15m: {{ + printf "%.3f" $values.B.Value }} (threshold: over 0.1). + action: >- + Its validations are not agreeing with the validated ledger, which risks removal from UNLs. data: - refId: A @@ -358,9 +365,11 @@ groups: annotations: summary: "No validations checked on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} has checked no incoming - validations for several minutes (5m rate has decayed to zero). The - validation stream from peers may have stopped. + Validations-checked rate on {{ $labels.service_instance_id }} over 5m: {{ + printf "%.4f" $values.B.Value }} per s (threshold: below 0.001). + action: >- + The validation stream from peers may have stopped. Check peer count and the + overlay. data: - refId: A relativeTimeRange: @@ -431,9 +440,11 @@ groups: annotations: summary: "Job queue transaction overflow on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} overflowed its transaction - job queue {{ $values.B.Value }} time(s) in the last 15m. - Transactions are being dropped under load. + Transaction job-queue overflows on {{ $labels.service_instance_id }} in the + last 15m: {{ printf "%.0f" $values.B.Value }} (threshold: more than 0). + action: >- + Transactions are being dropped under load. Check job-queue depth and worker + saturation. data: - refId: A relativeTimeRange: @@ -502,9 +513,10 @@ groups: annotations: summary: "Job queue latency high on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} has a p99 job-queue wait of - {{ $values.B.Value }}µs (>1s) over 5m. The node is saturated and jobs are - backing up. + p99 job-queue wait on {{ $labels.service_instance_id }} over 5m: {{ printf + "%.0f" $values.B.Value }}us (threshold: over 1000000us, i.e. 1s). + action: >- + The node is saturated and jobs are backing up. Check worker pool saturation. data: - refId: A relativeTimeRange: @@ -572,9 +584,10 @@ groups: annotations: summary: "Node store IO latency high on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} has a p95 node-store IO - latency of {{ $values.B.Value }}ms (>1s) over 10m. Check disk - utilisation and whether the store is on a slow volume. + p95 node-store IO latency on {{ $labels.service_instance_id }} over 10m: {{ + printf "%.0f" $values.B.Value }}ms (threshold: over 1000ms). + action: >- + Check disk utilisation and whether the store is on a slow volume. data: - refId: A relativeTimeRange: @@ -655,11 +668,13 @@ groups: annotations: summary: "Node state flapping on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} re-entered the FULL state - {{ $values.B.Value }} time(s) in the last hour past its first hour - of uptime. It is flapping out of sync rather than holding FULL. - Likely the online-delete rotation cache-freshen; check the rotation - spans and cache lock-hold peak. + FULL-state re-entries on {{ $labels.service_instance_id }} in the last hour: + {{ printf "%.0f" $values.B.Value }} (threshold: more than 0, past the first + hour of uptime). + action: >- + The node is flapping out of sync rather than holding FULL. A likely cause is + the online-delete rotation cache-freshen; check the rotation spans and the + cache lock-hold peak. data: - refId: A relativeTimeRange: @@ -724,9 +739,12 @@ groups: annotations: summary: "Node not in FULL state on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} has been below FULL - (state={{ $values.B.Value }}; 0=disconnected 1=connected 2=syncing - 3=tracking 4=full) for 15m. It is not fully synced with the network. + Server state on {{ $labels.service_instance_id }} for the last 15m: {{ + printf "%.0f" $values.B.Value }} (threshold: below 4; 0=disconnected + 1=connected 2=syncing 3=tracking 4=full). + action: >- + The node is not fully synced with the network. Check peer supply and sync + progress. data: - refId: A relativeTimeRange: @@ -807,9 +825,11 @@ groups: annotations: summary: "Manifest job convoy on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} has {{ $values.B.Value }} - manifest jobs waiting (>3) for 10m. Peer manifest dumps are - saturating the job pool and convoying on the manifest cache lock. + Manifest jobs waiting on {{ $labels.service_instance_id }} over 10m: {{ + printf "%.0f" $values.B.Value }} (threshold: more than 3). + action: >- + Peer manifest dumps are saturating the job pool and convoying on the + manifest cache lock. data: - refId: A relativeTimeRange: @@ -884,9 +904,10 @@ groups: annotations: summary: "Inbound manifest flood on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} is receiving - {{ $values.B.Value }} B/s of manifest traffic over 10m, above the - 512 KiB/s (524288 B/s) threshold. + Inbound manifest traffic on {{ $labels.service_instance_id }} over 10m: {{ + printf "%.0f" $values.B.Value }} B/s (threshold: over 524288 B/s, i.e. 512 + KiB/s). + action: >- A peer is flooding oversized TMManifests dumps. data: - refId: A @@ -955,9 +976,10 @@ groups: annotations: summary: "Resource-driven peer disconnects on {{ $labels.service_instance_id }}" description: >- - Node {{ $labels.service_instance_id }} disconnected - {{ $values.B.Value }} peer(s) for resource-budget violations in the - last 30m. Sustained disconnects can starve the node of peers. + Resource-budget peer disconnects on {{ $labels.service_instance_id }} in the + last 30m: {{ printf "%.0f" $values.B.Value }} (threshold: more than 5). + action: >- + Sustained disconnects can starve the node of peers. data: - refId: A relativeTimeRange: diff --git a/docker/telemetry/grafana/provisioning/alerting/templates.yaml b/docker/telemetry/grafana/provisioning/alerting/templates.yaml new file mode 100644 index 0000000000..0e533aee9b --- /dev/null +++ b/docker/telemetry/grafana/provisioning/alerting/templates.yaml @@ -0,0 +1,75 @@ +# Notification templates for the xrpld OTel alerts. +# +# Why these exist: Grafana's built-in message body appends a raw dump of every +# expression node's value and every label, so a notification reads +# `Value: A=0, B=0, C=1` followed by five `key = value` lines. The refIds carry +# no meaning to a reader, and the label dump repeats what the title already +# says. These templates replace that body with the rule's own prose. +# +# --------------------------------------------------------------------------- +# What a template may and may not use +# --------------------------------------------------------------------------- +# The function set here is much smaller than Go's text/template plus sprig. +# Available and used below: `match` (regexp), `reReplaceAll`, `title`, `printf`, +# `len`, `index`, `eq`. NOT available — each fails the whole template with +# `function "X" not defined`, which silently ships the raw template text in the +# notification instead: `hasPrefix`, `hasSuffix`, `contains`, `humanize`, +# `humanizeDuration`, `humanizePercentage`. +# +# A template error does NOT mark the rule unhealthy. Rules keep reporting +# `health=ok` and the broken text is only visible in the delivered message, so +# any change here must be checked against a real notification, not against rule +# state. +# +# --------------------------------------------------------------------------- +# Two label traps +# --------------------------------------------------------------------------- +# * `service_instance_id` is a QUERY label, so it is absent whenever Grafana +# evaluates NoData or Error — those evaluations carry only +# {datasource_uid, ref_id}. Two rules set `noDataState: Alerting` and so +# fire that way deliberately. `xrpld.node` below falls back rather than +# rendering an empty string. +# * `alertname` is set by Grafana on every alert. There is no `rulename` +# label, so referencing one renders blank. +# +# Values are deliberately NOT printed. Each rule's `description` already states +# its own measurement, formatted and with its threshold, which is the readable +# form of what the raw value dump was trying to say. + +apiVersion: 1 + +templates: + - orgId: 1 + name: xrpld.notifications + template: | + {{- /* Node identity, or a marker when the query label is absent. */ -}} + {{ define "xrpld.node" -}} + {{ if .Labels.service_instance_id }}{{ .Labels.service_instance_id }}{{ else }}unknown node (NoData/Error evaluation){{ end }} + {{- end }} + + {{- /* One line, used as the Slack title and the email subject. */ -}} + {{ define "xrpld.title" -}} + {{ if .Alerts.Firing }}🔥 FIRING{{ else }}✅ RESOLVED{{ end }} + {{- with .CommonLabels.alertname }} · {{ . }}{{ end }} + {{- with .CommonLabels.severity }} ({{ . }}){{ end }} + {{- with .CommonLabels.service_instance_id }} · {{ . }}{{ end }} + {{- end }} + + {{- /* Message body: one block per alert, prose only. */ -}} + {{ define "xrpld.body" -}} + {{ with .Alerts.Firing }}{{ range . }} + :rotating_light: *FIRING* · *{{ .Labels.alertname }}* on `{{ template "xrpld.node" . }}` + {{ .Annotations.description }} + {{- with .Annotations.action }} + *Why it matters:* {{ . }} + {{- end }} + {{- range $key, $url := .Annotations }} + {{- if match "^panel_" $key }} + :chart_with_upwards_trend: <{{ $url }}|{{ title (reReplaceAll "_" " " (reReplaceAll "^panel_" "" $key)) }}> + {{- end }}{{ end }} + {{ end }}{{ end }} + {{- with .Alerts.Resolved }}{{ range . }} + :white_check_mark: *RESOLVED* · *{{ .Labels.alertname }}* on `{{ template "xrpld.node" . }}` + {{ .Annotations.description }} + {{ end }}{{ end }} + {{- end }} diff --git a/docker/telemetry/workload/README.md b/docker/telemetry/workload/README.md index 4777dd9cde..6d944bfa91 100644 --- a/docker/telemetry/workload/README.md +++ b/docker/telemetry/workload/README.md @@ -638,21 +638,34 @@ needs: a pattern that swallows unrelated names defeats the check. ### expected_spans.json Format -Each span entry defines its name, category, parent (for hierarchy validation), -required attributes, and the `config_flag` that must be enabled. A trailing `*` -in `name` is a wildcard. The optional `"optional": true` field marks a span whose -absence is a skip rather than a failure: +Each span entry defines its name, category, `allowed_parents`, required +attributes, and the `config_flag` that must be enabled. A trailing `*` in `name` +is a wildcard. The optional `"optional": true` field marks a span whose absence +is a skip rather than a failure: ```json { "name": "rpc.command.*", "category": "rpc", - "parent": "rpc.process", + "allowed_parents": ["rpc.ws_message", "rpc.process", "ROOT"], "required_attributes": ["command", "version", "rpc_role", "rpc_status"], "config_flag": "trace_rpc" } ``` +`allowed_parents` is asserted, by `validate_span_parents`: every emitted instance +of the span must be parented to one of the names listed, so a span declared a +root that is emitted as somebody's child fails a check instead of passing +silently. The list is derived from the span's creation factory plus every call +path that reaches it — `SpanGuard::span(...)` and a plain `ScopedSpanGuard` +inherit the ambient scope, so they take one entry per ambient scope their callers +can be under; `freshRoot`, `linkedSpan` and the standalone `hashSpan` are roots; +`childSpan(name, ctx)` names its parent exactly. `ROOT` means "no parent from +this node", which covers a genuine root and a span whose parent was created on a +different node, since a cross-node parent is the design for the receive spans and +is never a violation. An entry may itself be a glob, matched the same way span +names are. + ## Node Configuration Notes The orchestrator (`run-full-validation.sh`) generates node configs with: diff --git a/docker/telemetry/workload/expected_spans.json b/docker/telemetry/workload/expected_spans.json index 13fc50279e..b91d7c3b12 100644 --- a/docker/telemetry/workload/expected_spans.json +++ b/docker/telemetry/workload/expected_spans.json @@ -1,10 +1,10 @@ { - "description": "Expected span inventory for xrpld telemetry validation. Attribute keys follow the 2026-05-13 span-attr naming redesign (bare/underscore form; dotted xrpl.* reserved for resource attributes). Sourced from the *SpanNames.h headers and verified against the emitting call sites. Spans marked \"optional\": true are conditional \u2014 they only fire under traffic the harness may not produce (e.g. gRPC client, path-finding RPC, missing-ledger fetch, mode transitions) and are not failed when absent. \"parent\" is documentation only (validate_telemetry.py asserts hierarchy from parent_child_relationships, not from this field) and records the parent as the code actually produces it: null means the span is a root or an explicit freshRoot. required_attributes lists only attributes set on EVERY code path that creates the span \u2014 attributes set after an early return are described in the span's note instead, because _validate_span_attributes_otlp samples a single trace and would fail on a legitimate short-circuit path. total_unique_attributes is the size of the union of all required_attributes; total_span_types is len(spans). Span EVENTS (consensus.round phase.*/outcome.*, consensus.update_positions dispute.resolve, consensus.accept.apply tx.included) are NOT represented: validate_telemetry.py reads only span name, attributes and timestamps from Tempo, so an \"events\" key would be silently ignored. They are documented in the relevant span notes until the validator gains event support.", + "description": "Expected span inventory for xrpld telemetry validation. Attribute keys follow the 2026-05-13 span-attr naming redesign (bare/underscore form; dotted xrpl.* reserved for resource attributes). Sourced from the *SpanNames.h headers and verified against the emitting call sites. Spans marked \"optional\": true are conditional — they only fire under traffic the harness may not produce (e.g. gRPC client, path-finding RPC, missing-ledger fetch, mode transitions) and are not failed when absent. \"allowed_parents\" is asserted, by validate_span_parents in validate_telemetry.py: every emitted instance of the span must be parented to one of the names listed, so a span declared a root that is emitted as somebody's child now fails a check instead of passing silently. \"ROOT\" means \"no parent from this node\" — a genuine root, an explicit freshRoot, or a span whose parent was created on a different node, because a cross-node parent is the design for the receive spans and is never a violation. A span reachable by two call paths lists every parent either path can give it, and a listed parent may itself be a glob (pathfind.request is declared under rpc.command.*), matched the same way the span names in this file are. Each list is derived from the span's creation factory plus every call path that reaches it — README.md, section \"expected_spans.json Format\", has the rule — so a span note that lists fewer parents than the code can produce is a bug in this file, not a reason to widen the gate at the call site. Three spans list ROOT even though their factory inherits the ambient scope (ledger.acquire, pathfind.update_all, grpc.*): they are created at a boundary or outlive the creating scope, so an observed parent there is an ambient leak to fix in the C++, not an edge to add here. required_attributes lists only attributes set on EVERY code path that creates the span — attributes set after an early return are described in the span's note instead, because _validate_span_attributes_otlp samples a single trace and would fail on a legitimate short-circuit path. total_unique_attributes is the size of the union of all required_attributes; total_span_types is len(spans). Span EVENTS (consensus.round phase.*/outcome.*, consensus.update_positions dispute.resolve, consensus.accept.apply tx.included) are NOT represented: validate_telemetry.py reads only span name, attributes and timestamps from Tempo, so an \"events\" key would be silently ignored. They are documented in the relevant span notes until the validator gains event support.", "spans": [ { "name": "rpc.ws_message", "category": "rpc", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["command"], "config_flag": "trace_rpc", "note": "WebSocket RPC root span. The load generator uses WS, so this is the RPC entry span (not rpc.http_request, which needs an HTTP/JSON-RPC client)." @@ -12,33 +12,33 @@ { "name": "rpc.ws_upgrade", "category": "rpc", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [], "config_flag": "trace_rpc", "optional": true, - "note": "WebSocket handshake span (ServerHandler::onHandoff, ServerHandler.cpp:272-273). A freshRoot with no attributes \u2014 only setOk() on success or recordException() on an upgrade failure. Fires once per WS connection, so the load generator produces only a handful of these at connect time; by the time validation runs after the propagation wait they may fall outside the Tempo search window. Optional for that reason, not because the code path is conditional." + "note": "WebSocket handshake span (ServerHandler::onHandoff, ServerHandler.cpp:272-273). A freshRoot with no attributes — only setOk() on success or recordException() on an upgrade failure. Fires once per WS connection, so the load generator produces only a handful of these at connect time; by the time validation runs after the propagation wait they may fall outside the Tempo search window. Optional for that reason, not because the code path is conditional." }, { "name": "rpc.process", "category": "rpc", - "parent": "rpc.http_request", + "allowed_parents": ["rpc.http_request"], "required_attributes": [], "config_flag": "trace_rpc", "optional": true, - "note": "HTTP-only. Created solely in ServerHandler::processRequest() (ServerHandler.cpp:718), which is reached only from processSession(Session, coro) (ServerHandler.cpp:646) \u2014 the HTTP/JSON-RPC path that roots rpc.http_request at ServerHandler.cpp:640-641. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so this span never appears under a WebSocket request. It does still appear under this harness, 5 traces on a normal run, because run-full-validation.sh polls each node over HTTP with curl (:449, :502) and those requests take the HTTP path. Note that the harness does speak HTTP: a reader concluding this span is unreachable here would go looking for a way to add HTTP traffic that already exists." + "note": "HTTP-only. Created solely in ServerHandler::processRequest() (ServerHandler.cpp:718), which is reached only from processSession(Session, coro) (ServerHandler.cpp:646) — the HTTP/JSON-RPC path that roots rpc.http_request at ServerHandler.cpp:640-641. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so this span never appears under a WebSocket request. It does still appear under this harness, 5 traces on a normal run, because run-full-validation.sh polls each node over HTTP with curl (:449, :502) and those requests take the HTTP path. Note that the harness does speak HTTP: a reader concluding this span is unreachable here would go looking for a way to add HTTP traffic that already exists." }, { "name": "rpc.command.*", "category": "rpc", - "parent": "rpc.ws_message", + "allowed_parents": ["rpc.ws_message", "rpc.process", "ROOT"], "required_attributes": ["command", "version", "rpc_role", "rpc_status"], "config_flag": "trace_rpc", - "note": "Wildcard \u2014 matches rpc.command.server_info, rpc.command.ledger, etc. Created as an ambient (scoped) child in rpc::doCommand / rpc::callMethod (RPCHandler.cpp:168, :271), so its parent is whichever transport span is active on the thread: rpc.ws_message on the WebSocket path (the harness workload) and rpc.process on the HTTP/JSON-RPC path." + "note": "Wildcard — matches rpc.command.server_info, rpc.command.ledger, etc. Created as a plain ScopedSpanGuard in rpc::callMethod (RPCHandler.cpp:204-205) and, on the fillHandler-rejection path, in rpc::doCommand (:340-341), so its parent is whichever transport span is ambient on the thread. Three call paths, all three exercised by this harness: rpc::doCommand from the WebSocket handler inside the rpc.ws_message scope (ServerHandler.cpp:589 under the freshRoot at :495); from ServerHandler::processRequest inside the rpc.process scope (:1037 under the guard at :734); and from ApplicationImp::setup's [rpc_startup] loop (Application.cpp:1786) on the main thread with no ambient scope, which makes it a ROOT. The third is why ROOT is listed: startTelemetry() runs at Application.cpp:1511, well before that loop, so the startup command really does emit a rooted rpc.command span — run-full-validation.sh writes a [rpc_startup] log_level command for every node, so there are five of them per run." }, { "name": "rpc.http_request", "category": "rpc", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["request_payload_size"], "config_flag": "trace_rpc", "optional": true, @@ -47,14 +47,14 @@ { "name": "tx.process", "category": "transaction", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["tx_hash", "local", "path"], "config_flag": "trace_transactions" }, { "name": "tx.receive", "category": "transaction", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["tx_hash", "peer_id"], "config_flag": "trace_transactions", "note": "Cross-node span: parent context propagated from the sender's tx.process via protobuf. Also carries tx_type and peer_version. The span is created only after the node decides to process the transaction, so a relayed duplicate produces no span at all; how many were dropped is the transactions_duplicate traffic category. tx_status is set only on the paths that drop a transaction after that point, so it is not a required attribute." @@ -62,15 +62,15 @@ { "name": "tx.apply", "category": "transaction", - "parent": "ledger.build", + "allowed_parents": ["ledger.build"], "required_attributes": ["tx_count", "tx_failed"], "config_flag": "trace_transactions", - "note": "Apply-step span inside BuildLedger. Carries tx_count/tx_failed (ledger_seq lives on the parent ledger.build span)." + "note": "Apply-step span inside BuildLedger. Sets its own ledger_seq next to tx_count and tx_failed (BuildLedger.cpp:197-199), so do not re-add the earlier claim that ledger_seq lives on the parent ledger.build span — it does not, and ledger.build sets it independently." }, { "name": "tx.preflight", "category": "transaction", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["stage", "tx_type", "ter_result"], "config_flag": "trace_transactions", "note": "Apply-pipeline stage span (stage=preflight). Shares a deterministic trace_id (txID[0:16]) with tx.preclaim/tx.transactor." @@ -78,7 +78,7 @@ { "name": "tx.preclaim", "category": "transaction", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["stage", "tx_type", "ter_result"], "config_flag": "trace_transactions", "note": "Apply-pipeline stage span (stage=preclaim)." @@ -86,7 +86,7 @@ { "name": "tx.transactor", "category": "transaction", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["stage", "tx_type"], "config_flag": "trace_transactions", "note": "Apply-pipeline stage span (stage=apply). Also carries applied." @@ -94,16 +94,21 @@ { "name": "txq.enqueue", "category": "transaction", - "parent": "tx.process", + "allowed_parents": [ + "tx.process", + "consensus.accept.apply", + "rpc.command.*", + "ROOT" + ], "required_attributes": ["tx_hash", "tx_type", "txq_status"], "config_flag": "trace_transactions", "optional": true, - "note": "Only fires when a tx is queued (fee below open-ledger level). Requires fee escalation \u2014 driven by the txq-burst workload phase. tx_hash/tx_type/txq_status are set on every code path; fee_level_paid/required_fee_level are conditional (TxQ.cpp ~895-898, after the rejected and applied_direct early exits), so they are NOT guaranteed on every txq.enqueue span and cannot be required." + "note": "Only fires when a tx is queued (fee below open-ledger level). Requires fee escalation — driven by the txq-burst workload phase. tx_hash/tx_type/txq_status are set on every code path; fee_level_paid/required_fee_level are conditional (TxQ.cpp ~895-898, after the rejected and applied_direct early exits), so they are NOT guaranteed on every txq.enqueue span and cannot be required. Four parents, because TxQ::apply (TxQ.cpp:770) takes an OPTIONAL parent context (:790-795): with a context it is an explicit childSpan, without one it is a plain ScopedSpanGuard that inherits whatever is ambient. tx.process comes from the submission path, which passes the captured context (NetworkOPs.cpp:1803-1810). consensus.accept.apply comes from the open-ledger rebuild, which passes none: OpenLedger.cpp:121 replays local transactions, and OpenLedger::accept is called from inside doAccept (RCLConsensus.cpp:871) where the consensus span is ambient. ROOT comes from that same rebuild reached by the switchLastClosedLedger jump path instead (NetworkOPs.cpp:2313), which has no ambient scope, and from the submission path when the tx.process context is invalid. rpc.command.* comes from the simulate RPC (Simulate.cpp:249), which passes no context and runs inside the command span's scope; the harness never issues simulate, so that parent is unreachable here but is still lawful." }, { "name": "txq.apply_direct", "category": "transaction", - "parent": "txq.enqueue", + "allowed_parents": ["txq.enqueue"], "required_attributes": [], "config_flag": "trace_transactions", "optional": true, @@ -112,24 +117,25 @@ { "name": "txq.batch_clear", "category": "transaction", - "parent": "txq.enqueue", - "required_attributes": ["num_cleared"], + "allowed_parents": ["txq.enqueue"], + "required_attributes": [], "config_flag": "trace_transactions", - "optional": true + "optional": true, + "note": "TxQ::tryClearAccountQueueUpThruTx (TxQ.cpp:571-572). num_cleared is NOT required: it is written only once the batch has actually cleared, inside the `if (txResult.applied)` branch at TxQ.cpp:646. Three earlier returns leave the span without it — a fee-level overflow (:589-590), a batch that did not pay enough (:598-599), and a queued transaction that failed to apply (:632-635) — as does the final doApply failing, which falls past the branch. The span is opened before any of those decisions, so a required num_cleared would fail the check on a legitimate fall-back-to-normal-processing path rather than on a defect." }, { "name": "txq.accept", "category": "transaction", - "parent": null, + "allowed_parents": ["consensus.accept.apply", "ROOT"], "required_attributes": ["queue_size", "ledger_changed"], "config_flag": "trace_transactions", "optional": true, - "note": "Ledger-close accept loop (TxQ::accept, TxQ.cpp:1499). Only meaningful when the queue is non-empty. Root on BOTH call paths, verified: the consensus path (RCLConsensus.cpp:823, inside doAccept) and the switchLastClosedLedger jump path (NetworkOPs.cpp:2150). The span is a ScopedSpanGuard, so it adopts whatever OTel context is ambient \u2014 but consensus.accept and consensus.accept.apply are unscoped thread-free SpanGuards and activate() is never called outside unit tests, so no consensus span is ever the ambient parent on the JtAccept worker. ledger.build's ScopedSpanGuard has already been destroyed by the time OpenLedger::accept runs." + "note": "Ledger-close accept loop (TxQ::accept, TxQ.cpp:1499). Only meaningful when the queue is non-empty. Two call paths, and they give it two different parents. On the consensus path (RCLConsensus.cpp:823, inside doAccept) consensus.accept.apply is the ambient scope for the whole of doAccept, so this span is its child. On the switchLastClosedLedger jump path (NetworkOPs.cpp:2150) no consensus span is open on that thread, so the span is a root. The span is a ScopedSpanGuard and adopts whatever OTel context is ambient, which is what makes the parent a property of the caller rather than of this span." }, { "name": "txq.accept_tx", "category": "transaction", - "parent": "txq.accept", + "allowed_parents": ["txq.accept"], "required_attributes": [ "tx_hash", "ter_code", @@ -142,16 +148,16 @@ { "name": "txq.cleanup", "category": "transaction", - "parent": null, + "allowed_parents": ["consensus.accept.apply", "ROOT"], "required_attributes": ["ledger_seq", "expired_count"], "config_flag": "trace_transactions", "optional": true, - "note": "TxQ::processClosedLedger (TxQ.cpp:1403). Root on BOTH call paths for the same reason as txq.accept: the consensus path (RCLConsensus.cpp:950) and the switchLastClosedLedger jump path (NetworkOPs.cpp:2121) both run with no consensus span activated as ambient context." + "note": "TxQ::processClosedLedger (TxQ.cpp:1403). The same two call paths as txq.accept, with the same split: the consensus path (RCLConsensus.cpp:950) runs inside the consensus.accept.apply scope and nests under it, while the switchLastClosedLedger jump path (NetworkOPs.cpp:2121) has no consensus span open and leaves it a root." }, { "name": "consensus.round", "category": "consensus", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [ "consensus_ledger_id", "ledger_seq", @@ -160,19 +166,19 @@ "consensus_phase" ], "config_flag": "trace_consensus", - "note": "Root consensus span created per round. Also carries trace_strategy, previous_ledger_seq, previous_proposers, previous_round_time_ms. Emits seven span EVENTS that this manifest cannot assert: phase.open, phase.recovery, phase.establish, phase.accepted, outcome.yes, outcome.moved_on, outcome.expired (declared ConsensusSpanNames.h:265-277; emitted RCLConsensus.cpp:1344 and via onPhaseEvent/onOutcomeEvent from Consensus.h:764, 793, 1047, 1517-1525, 1530, 1566), plus a `view.change` event emitted from RCLConsensus::Adaptor::getPrevLedger when the network's preferred ledger differs from this node's (carries prev_ledger_prefix and net_ledger_prefix). validate_telemetry.py reads only span name, attributes and start/end timestamps from the Tempo OTLP payload \u2014 it has no event assertion support \u2014 so adding an \"events\" key here would be silently ignored. Recorded as a note instead; asserting events needs validator support first." + "note": "Root consensus span created per round. Also carries trace_strategy, previous_ledger_seq, previous_proposers, previous_round_time_ms. Emits seven span EVENTS that this manifest cannot assert: phase.open, phase.recovery, phase.establish, phase.accepted, outcome.yes, outcome.moved_on, outcome.expired (declared ConsensusSpanNames.h:265-277; emitted RCLConsensus.cpp:1344 and via onPhaseEvent/onOutcomeEvent from Consensus.h:764, 793, 1047, 1517-1525, 1530, 1566), plus a `view.change` event emitted from RCLConsensus::Adaptor::getPrevLedger when the network's preferred ledger differs from this node's (carries prev_ledger_prefix and net_ledger_prefix). validate_telemetry.py reads only span name, attributes and start/end timestamps from the Tempo OTLP payload — it has no event assertion support — so adding an \"events\" key here would be silently ignored. Recorded as a note instead; asserting events needs validator support first." }, { "name": "consensus.phase.open", "category": "consensus", - "parent": "consensus.round", + "allowed_parents": ["consensus.round"], "required_attributes": [], "config_flag": "trace_consensus" }, { "name": "consensus.proposal.send", "category": "consensus", - "parent": "consensus.round", + "allowed_parents": ["consensus.round"], "required_attributes": ["consensus_round"], "config_flag": "trace_consensus", "note": "Also carries is_bow_out." @@ -180,7 +186,7 @@ { "name": "consensus.ledger_close", "category": "consensus", - "parent": "consensus.round", + "allowed_parents": ["consensus.round"], "required_attributes": ["ledger_seq", "consensus_mode"], "config_flag": "trace_consensus", "note": "Also carries tx_count_open, close_time_resolution_ms." @@ -188,7 +194,7 @@ { "name": "consensus.establish", "category": "consensus", - "parent": "consensus.round", + "allowed_parents": ["consensus.round"], "required_attributes": [ "converge_percent", "establish_count", @@ -200,19 +206,19 @@ { "name": "consensus.update_positions", "category": "consensus", - "parent": "consensus.establish", + "allowed_parents": ["consensus.establish"], "required_attributes": [ "converge_percent", "proposers", "disputes_count" ], "config_flag": "trace_consensus", - "note": "childSpan of establishSpanContext_ (Consensus.h:1628), so the parent is consensus.establish \u2014 not consensus.round. Also emits a dispute.resolve span EVENT per resolved dispute (Consensus.h:1697-1698), which validate_telemetry.py cannot assert (no event support)." + "note": "childSpan of establishSpanContext_ (Consensus.h:1628), so the parent is consensus.establish — not consensus.round. Also emits a dispute.resolve span EVENT per resolved dispute (Consensus.h:1697-1698), which validate_telemetry.py cannot assert (no event support)." }, { "name": "consensus.check", "category": "consensus", - "parent": "consensus.establish", + "allowed_parents": ["consensus.establish"], "required_attributes": [ "agree_count", "disagree_count", @@ -220,19 +226,19 @@ "consensus_result" ], "config_flag": "trace_consensus", - "note": "childSpan of establishSpanContext_ (Consensus.h:1837), so the parent is consensus.establish \u2014 not consensus.round." + "note": "childSpan of establishSpanContext_ (Consensus.h:1837), so the parent is consensus.establish — not consensus.round." }, { "name": "consensus.accept", "category": "consensus", - "parent": "consensus.round", + "allowed_parents": ["consensus.round"], "required_attributes": ["proposers", "round_time_ms", "quorum"], "config_flag": "trace_consensus" }, { "name": "consensus.accept.apply", "category": "consensus", - "parent": "consensus.accept", + "allowed_parents": ["consensus.accept"], "required_attributes": [ "ledger_seq", "close_time_ripple_epoch_s", @@ -242,12 +248,12 @@ "resolution_direction" ], "config_flag": "trace_consensus", - "note": "Also carries close_time_correct, close_resolution_ms, consensus_state, proposing, round_time_ms, tx_count. Emits a tx.included span EVENT per transaction in the accepted set (RCLConsensus.cpp:720, with a tx_id attribute), which validate_telemetry.py cannot assert (no event support)." + "note": "Also carries close_time_correct, close_resolution_ms, consensus_state, proposing, round_time_ms, tx_count. Emits a tx.included span EVENT per transaction in the accepted set (RCLConsensus.cpp:720, with a tx_id attribute), which validate_telemetry.py cannot assert (no event support). One parent: a scoped childSpan of the captured accept context (RCLConsensus.cpp doAccept). The context is valid whenever the accept span is live; when it is not, the factory returns a null guard and no span is emitted at all. Scoped, so the txq spans doAccept creates after it are its children." }, { "name": "consensus.validation.send", "category": "consensus", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [ "ledger_seq", "proposing", @@ -260,7 +266,7 @@ { "name": "consensus.proposal.receive", "category": "consensus", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [], "config_flag": "trace_consensus", "note": "Context-propagated from the sending peer. No required local attributes." @@ -268,7 +274,7 @@ { "name": "consensus.validation.receive", "category": "consensus", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [], "config_flag": "trace_consensus", "note": "Context-propagated from the sending peer. No required local attributes." @@ -276,7 +282,7 @@ { "name": "consensus.validation.accept", "category": "consensus", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [ "ledger_hash", "ledger_seq", @@ -290,16 +296,16 @@ { "name": "consensus.mode_change", "category": "consensus", - "parent": "consensus.round", + "allowed_parents": ["consensus.round"], "required_attributes": ["mode_old", "mode_new"], "config_flag": "trace_consensus", "optional": true, - "note": "childSpan of roundSpanContext_ (RCLConsensus.cpp:1101), so the parent is consensus.round. Only fires on an operating-mode transition; a steady cluster rarely changes mode after warmup. A mode change outside a round leaves roundSpanContext_ invalid, which yields a null (no-op) guard rather than a root span." + "note": "childSpan of roundSpanContext_ (RCLConsensus.cpp:1101), so the parent is consensus.round. Only fires on an operating-mode transition; a steady cluster rarely changes mode after warmup. Note the handler itself is called at the start of EVERY round, with the before and after mode equal on almost all of them, so the guard on before != after is the whole reason this span is conditional rather than per-round — without it the span records no change and span.mode_change.records_a_real_change fails. A mode change outside a round leaves roundSpanContext_ invalid, which yields a null (no-op) guard rather than a root span." }, { "name": "ledger.build", "category": "ledger", - "parent": null, + "allowed_parents": ["consensus.accept.apply", "ROOT"], "required_attributes": [ "ledger_seq", "close_time_ripple_epoch_s", @@ -307,28 +313,28 @@ "close_resolution_ms" ], "config_flag": "trace_ledger", - "note": "tx_count/tx_failed live on the child tx.apply span, not here." + "note": "tx_count/tx_failed live on the child tx.apply span, not here. Two call paths give it two parents. The consensus path (RCLConsensus.cpp:983-985, inside doAccept) builds the ledger inside the consensus.accept.apply scope, so the span nests under it. The LedgerDeltaAcquire replay path (LedgerDeltaAcquire.cpp:208) rebuilds a historical ledger with no consensus span open on that thread, so the span is a root there." }, { "name": "ledger.validate", "category": "ledger", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["ledger_hash", "ledger_seq", "validations"], "config_flag": "trace_ledger", - "note": "ledger_hash is required because it is the trace-join key, not merely a descriptive attribute: this span is the anchor of the per_ledger group in trace_join_groups, and the join is computed by hashing that value. Both it and ledger_seq are stamped unconditionally by LedgerMaster::makeLedgerTraceSpan (LedgerMaster.cpp:186-190, called at :1089), so requiring it costs nothing on a healthy run. Without this the only symptom of a lost join key would be assert_trace_join_groups reporting that spans landed in separate traces, which names the consequence rather than the cause." + "note": "Created in LedgerMaster::checkAccept (LedgerMaster.cpp:1002-1003) with the ambient-inheriting span() factory, so its parent is whatever scope is open on the calling thread. The consensus path reaches it inside doAccept — consensusBuilt (RCLConsensus.cpp:803) calls checkAccept at LedgerMaster.cpp:1149, and the node's own validation takes the same route through handleNewValidation (RCLConsensus.cpp:1115) — so there it nests under the consensus span. ROOT covers the two paths with no ambient scope: an inbound peer validation, which PeerImp defers to a JtValidationT/JtValidationUt job (PeerImp.cpp:2751-2757) carrying only a never-activated SpanGuard handle, and the InboundLedger completion path (InboundLedger.cpp:168, :583). allowed_parents is ROOT alone on this branch: the span is a hashSpan (a true root on the ledger-hash trace), so it never inherits the consensus.accept.apply scope the upstream branches document." }, { "name": "ledger.store", "category": "ledger", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["ledger_hash", "ledger_seq"], "config_flag": "trace_ledger", - "note": "ledger_hash is required for the same reason as on ledger.validate: it is the per_ledger trace-join key, stamped unconditionally by LedgerMaster::makeLedgerTraceSpan (called at LedgerMaster.cpp:511). This span is the required_member of that join group, so a missing key here breaks the join from the other end." + "note": "Created in LedgerMaster::storeLedger (LedgerMaster.cpp:470) with the ambient-inheriting span() factory. The consensus path reaches it from RCLConsensus.cpp:1001, inside doAccept, so there it nests under the consensus span. ROOT covers every other caller, none of which has an ambient scope: InboundLedger.cpp:164 and :574, LedgerDeltaAcquire.cpp:243, and the genesis/startup stores at Application.cpp:2028 and :2037. allowed_parents is ROOT alone on this branch: the span is a hashSpan (a true root on the ledger-hash trace), so it never inherits the consensus.accept.apply scope the upstream branches document." }, { "name": "ledger.acquire", "category": "ledger", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [ "ledger_seq", "acquire_reason", @@ -338,12 +344,12 @@ ], "config_flag": "trace_ledger", "optional": true, - "note": "Only fires when a node must fetch a missing ledger (InboundLedger). A healthy local cluster rarely back-fills history. outcome is one of complete|failed|abandoned and is stamped on every exit path, including the sweep/shutdown path where the fetch never finished (abandoned). ledger_hash identifies the target ledger from the first moment, since a by-hash acquire starts with ledger_seq 0. peer_count is not required: the destructor path deliberately skips the peer lookup to avoid taking the Overlay lock under the InboundLedgers collection lock." + "note": "Only fires when a node must fetch a missing ledger (InboundLedger). A healthy local cluster rarely back-fills history. outcome is one of complete|failed|abandoned and is stamped on every exit path, including the sweep/shutdown path where the fetch never finished (abandoned). ledger_hash identifies the target ledger from the first moment, since a by-hash acquire starts with ledger_seq 0. peer_count is not required: the destructor path deliberately skips the peer lookup to avoid taking the Overlay lock under the InboundLedgers collection lock. allowed_parents is ROOT alone on this branch: the span is a hashSpan (a true root on the ledger-hash trace), so it never inherits the consensus.accept.apply scope the upstream branches document." }, { "name": "ledger.acquire.header", "category": "ledger", - "parent": "ledger.acquire", + "allowed_parents": ["ledger.acquire"], "required_attributes": ["ledger_hash", "outcome", "timed_out"], "config_flag": "trace_ledger", "optional": true, @@ -352,7 +358,7 @@ { "name": "ledger.acquire.astree", "category": "ledger", - "parent": "ledger.acquire", + "allowed_parents": ["ledger.acquire"], "required_attributes": [ "ledger_hash", "outcome", @@ -366,7 +372,7 @@ { "name": "ledger.acquire.txtree", "category": "ledger", - "parent": "ledger.acquire", + "allowed_parents": ["ledger.acquire"], "required_attributes": [ "ledger_hash", "outcome", @@ -380,7 +386,7 @@ { "name": "ledger.serve", "category": "ledger", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [ "object_type", "peer_id", @@ -394,7 +400,7 @@ { "name": "txset.acquire", "category": "ledger", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": [ "txset_hash", "outcome", @@ -409,7 +415,7 @@ { "name": "peer.dial", "category": "peer", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["remote_endpoint"], "config_flag": "trace_peer", "note": "One outbound connect attempt (ConnectAttempt), a fresh trace root because a dial is the first thing a starting node does and there is nothing to parent it to. Required: run-full-validation.sh lists the other four nodes in each node's [ips], so every node dials and the span always fires. Telemetry is live in time to catch it -- ApplicationImp::setup() calls startTelemetry() before start() calls overlay_->start(). outcome carries the same six values as the overlay_connect_total counter (connected|tcp_fail|tls_fail|self_connection|upgrade_fail|timeout) and is set from the same reportOutcome() funnel, so span and counter cannot disagree. remote_endpoint is the span-only dimension the counter cannot carry, since one series per peer address would be unbounded cardinality. Among its attributes only remote_endpoint is required. outcome and duration_ms are set on every terminal path, both inside reportOutcome(), but NOT on the teardown path: an attempt destroyed during overlay shutdown, or one whose connect was aborted, ends its span in ~ConnectAttempt with neither, deliberately -- the destructor's own comment records that a span ending with no outcome is the honest record of a dial that never concluded. Because peer.dial is a freshRoot, each dial is its own trace holding exactly one instance of the span, and the validator inspects only the most recent trace; a single newly-aborted dial would therefore fail CI on healthy behaviour. That single-trace sampling of a one-instance span is what makes requiring them unsafe -- not any doubt about the terminal paths setting them." @@ -417,44 +423,44 @@ { "name": "peer.proposal.receive", "category": "peer", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["peer_id"], "config_flag": "trace_peer", - "note": "peer_id is set immediately after the freshRoot (PeerImp.cpp:1925) and is the only unconditional attribute. proposal_trusted is set at PeerImp.cpp:1953, after several early returns (stale/duplicate/self-originated proposal checks), so a single rejected proposal in the sampled trace would fail the check \u2014 it is therefore not required." + "note": "peer_id is set immediately after the freshRoot (PeerImp.cpp:1925) and is the only unconditional attribute. proposal_trusted is set at PeerImp.cpp:1953, after several early returns (stale/duplicate/self-originated proposal checks), so a single rejected proposal in the sampled trace would fail the check — it is therefore not required." }, { "name": "peer.validation.receive", "category": "peer", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["peer_id", "ledger_hash", "full_validation"], "config_flag": "trace_peer", - "note": "ledger_hash and full_validation are shared with consensus.validation.send (same keys, told apart by span name). Both are set at PeerImp.cpp:2573-2574, BEFORE the isCurrent() gate, so only a too-small or unparseable validation skips them \u2014 they stay required (and validate_telemetry.py's PARITY_SPAN_ATTRS already asserts them independently). validation_trusted is set at PeerImp.cpp:2591, after the isCurrent() early return at :2576-2584, so a single not-current validation in the sampled trace would fail the check \u2014 it is therefore not required." + "note": "ledger_hash and full_validation are shared with consensus.validation.send (same keys, told apart by span name). Both are set at PeerImp.cpp:2573-2574, BEFORE the isCurrent() gate, so only a too-small or unparseable validation skips them — they stay required (and validate_telemetry.py's PARITY_SPAN_ATTRS already asserts them independently). validation_trusted is set at PeerImp.cpp:2591, after the isCurrent() early return at :2576-2584, so a single not-current validation in the sampled trace would fail the check — it is therefore not required." }, { "name": "pathfind.request", "category": "pathfind", - "parent": "rpc.command.*", + "allowed_parents": ["rpc.command.*"], "required_attributes": [ "pathfind_source_account", "pathfind_dest_account" ], "config_flag": "trace_rpc", "optional": true, - "note": "Fires on ripple_path_find / path_find RPC. Optional because the harness issues neither: rpc_load_generator.py's DEFAULT_WEIGHTS carries no ripple_path_find entry, and no workload-profiles.json phase names a path-finding command in a weights override, so no such RPC reaches a node at all. Created as an ambient (scoped) child inside the RPC command handler (RipplePathFind.cpp:35-36, PathFind.cpp:26-27), so its parent is the enclosing rpc.command.* span \u2014 RipplePathFind.cpp:30 states this explicitly. Note the span does NOT need pathfinding to be ENABLED, only the RPC to be issued: the ScopedSpanGuard is constructed at RipplePathFind.cpp:35, above the 'if (pathSearchMax == 0) return rpcError(RpcNotSupported)' guard at :48-49, so even a refused call opens and closes it. That positional accident means the load alone would satisfy this entry while pathfind.compute and pathfind.discover below stayed unasserted, and it is why such refusals would also drive a steady ~3% STATUS_CODE_ERROR floor in span_calls_total. Adding the load alone would make this span required and introduce that error floor; covering the whole family needs pathfinding actually enabled (a [path_search_max] override in run-full-validation.sh \u2014 see the pathfind.compute entry below). The workload README section 'Pathfinding is not exercised' carries the full recipe for enabling it." + "note": "Fires on ripple_path_find / path_find RPC. Optional because the harness issues neither: rpc_load_generator.py's DEFAULT_WEIGHTS carries no ripple_path_find entry, and no workload-profiles.json phase names a path-finding command in a weights override, so no such RPC reaches a node at all. Created as an ambient (scoped) child inside the RPC command handler (RipplePathFind.cpp:35-36, PathFind.cpp:26-27), so its parent is the enclosing rpc.command.* span — RipplePathFind.cpp:30 states this explicitly. Note the span does NOT need pathfinding to be ENABLED, only the RPC to be issued: the ScopedSpanGuard is constructed at RipplePathFind.cpp:35, above the 'if (pathSearchMax == 0) return rpcError(RpcNotSupported)' guard at :48-49, so even a refused call opens and closes it. That positional accident means the load alone would satisfy this entry while pathfind.compute and pathfind.discover below stayed unasserted, and it is why such refusals would also drive a steady ~3% STATUS_CODE_ERROR floor in span_calls_total. Adding the load alone would make this span required and introduce that error floor; covering the whole family needs pathfinding actually enabled (a [path_search_max] override in run-full-validation.sh — see the pathfind.compute entry below). The workload README section 'Pathfinding is not exercised' carries the full recipe for enabling it." }, { "name": "pathfind.compute", "category": "pathfind", - "parent": "pathfind.request", + "allowed_parents": ["pathfind.request", "pathfind.update_all"], "required_attributes": ["pathfind_fast"], "config_flag": "trace_rpc", "optional": true, - "note": "Created by PathRequest::doUpdate (PathRequest.cpp:749-750), which the harness never reaches: pathfinding is disabled on every harness node, so no PathRequest is ever constructed. Config.cpp:725-726 sets pathSearchMax to 0 when a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for every node and has no [path_search*] override, and doRipplePathFind then returns RpcNotSupported at RipplePathFind.cpp:59-60 \u2014 above the request-construction branches and below the pathfind.request span guard at :35. Liquidity is not the reason and never was: the call is refused before any path search is attempted, so the outcome does not depend on what the ledger holds. There is a second, independent reason: the harness sends no path-finding RPC at all, since rpc_load_generator.py carries no ripple_path_find weight. Enabling this span therefore needs BOTH a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND the load restored \u2014 see the workload README section 'Pathfinding is not exercised'." + "note": "Created by PathRequest::doUpdate (PathRequest.cpp:749-750), which the harness never reaches: pathfinding is disabled on every harness node, so no PathRequest is ever constructed. Config.cpp:725-726 sets pathSearchMax to 0 when a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for every node and has no [path_search*] override, and doRipplePathFind then returns RpcNotSupported at RipplePathFind.cpp:59-60 — above the request-construction branches and below the pathfind.request span guard at :35. Liquidity is not the reason and never was: the call is refused before any path search is attempted, so the outcome does not depend on what the ledger holds. There is a second, independent reason: the harness sends no path-finding RPC at all, since rpc_load_generator.py carries no ripple_path_find weight. Enabling this span therefore needs BOTH a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND the load restored — see the workload README section 'Pathfinding is not exercised'. Two parents: doUpdate's plain ScopedSpanGuard (PathRequest.cpp:788-789) inherits the ambient scope, and doUpdate has callers under both of them — under pathfind.request via PathRequest.cpp:272 and PathRequestManager.cpp:334, and under pathfind.update_all via PathRequestManager.cpp:161 and :176, where updateAll's own scoped guard is open." }, { "name": "pathfind.discover", "category": "pathfind", - "parent": "pathfind.compute", + "allowed_parents": ["pathfind.compute"], "required_attributes": ["pathfind_search_level", "pathfind_num_paths"], "config_flag": "trace_rpc", "optional": true, @@ -463,25 +469,25 @@ { "name": "pathfind.update_all", "category": "pathfind", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["pathfind_ledger_index", "pathfind_num_requests"], "config_flag": "trace_rpc", "optional": true, - "note": "Async recomputation at ledger close. PathRequestManager::updateAll emits the span only when requests_ is non-empty (PathRequestManager.cpp:88-95), so it needs a live path_find subscription. On the harness requests_ can never become non-empty at all: the only two insertPathRequest call sites are makePathRequest (:268) and makeLegacyPathRequest (:296), and both handlers return RpcNotSupported first because pathfinding is disabled on every node (PathFind.cpp:50-51, RipplePathFind.cpp:59; see the pathfind.compute entry above for the config chain)." + "note": "Async recomputation at ledger close. PathRequestManager::updateAll emits the span only when requests_ is non-empty (PathRequestManager.cpp:88-95), so it needs a live path_find subscription. On the harness requests_ can never become non-empty at all: the only two insertPathRequest call sites are makePathRequest (:268) and makeLegacyPathRequest (:296), and both handlers return RpcNotSupported first because pathfinding is disabled on every node (PathFind.cpp:50-51, RipplePathFind.cpp:59; see the pathfind.compute entry above for the config chain). ROOT despite the ambient-inheriting ScopedSpanGuard, because the one caller is LedgerMaster's advance thread (LedgerMaster.cpp:1491) with no scope open. An observed parent is an ambient leak into that thread, not a lawful edge." }, { "name": "grpc.*", "category": "grpc", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["method", "grpc_role", "grpc_status"], "config_flag": "trace_rpc", "optional": true, - "note": "Wildcard \u2014 grpc.. The harness has no gRPC client, so these do not fire. Tracked for completeness." + "note": "Wildcard — grpc.. The harness has no gRPC client, so these do not fire. Tracked for completeness. ROOT despite the ambient-inheriting span() factory (GRPCServer.cpp:174), because the span is created at the inbound boundary on a gRPC handler thread that runs no other instrumented work. An observed parent is an ambient leak onto that thread, not a lawful edge." }, { "name": "nodestore.rotate", "category": "ledger", - "parent": null, + "allowed_parents": ["ROOT"], "required_attributes": ["ledger_seq", "last_rotated", "outcome"], "config_flag": "trace_ledger", "optional": true, @@ -490,7 +496,7 @@ { "name": "nodestore.rotate.clear_prior", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": ["nodestore.rotate"], "required_attributes": [], "config_flag": "trace_ledger", "optional": true, @@ -499,7 +505,7 @@ { "name": "nodestore.rotate.copy", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": ["nodestore.rotate"], "required_attributes": ["node_count"], "config_flag": "trace_ledger", "optional": true, @@ -508,7 +514,7 @@ { "name": "nodestore.rotate.freshen.keys", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": ["nodestore.rotate"], "required_attributes": ["key_count"], "config_flag": "trace_ledger", "optional": true, @@ -517,7 +523,7 @@ { "name": "nodestore.rotate.freshen.fetch", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": ["nodestore.rotate"], "required_attributes": ["key_count"], "config_flag": "trace_ledger", "optional": true, @@ -526,7 +532,7 @@ { "name": "nodestore.rotate.new_backend", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": ["nodestore.rotate"], "required_attributes": [], "config_flag": "trace_ledger", "optional": true, @@ -535,7 +541,7 @@ { "name": "nodestore.rotate.clear_caches", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": ["nodestore.rotate"], "required_attributes": [], "config_flag": "trace_ledger", "optional": true, @@ -544,7 +550,7 @@ { "name": "nodestore.rotate.swap", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": ["nodestore.rotate"], "required_attributes": ["copy_forwards"], "config_flag": "trace_ledger", "optional": true, @@ -553,7 +559,16 @@ { "name": "nodestore.rotate.health_wait", "category": "ledger", - "parent": "nodestore.rotate", + "allowed_parents": [ + "nodestore.rotate", + "nodestore.rotate.clear_prior", + "nodestore.rotate.copy", + "nodestore.rotate.freshen.keys", + "nodestore.rotate.freshen.fetch", + "nodestore.rotate.new_backend", + "nodestore.rotate.clear_caches", + "nodestore.rotate.swap" + ], "required_attributes": ["server_mode", "missing_ledgers"], "config_flag": "trace_ledger", "optional": true, @@ -566,12 +581,12 @@ "child": "rpc.process", "description": "WebSocket message contains processing span", "skip": true, - "skip_reason": "This relationship does not exist in the code: rpc.process is created only in ServerHandler::processRequest() (ServerHandler.cpp:718), reached only from processSession(Session, coro) (ServerHandler.cpp:646) \u2014 the HTTP/JSON-RPC path. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so rpc.process is never emitted at all under the WebSocket-only harness. The earlier diagnosis (cross-thread context loss needing a C++ fix) was wrong: rpc.ws_message is a deliberate freshRoot (ServerHandler.cpp:473-474) so each WS message is its own trace rather than nesting under a span leaked on a reused coroutine worker. Nothing to fix." + "skip_reason": "This relationship does not exist in the code: rpc.process is created only in ServerHandler::processRequest() (ServerHandler.cpp:718), reached only from processSession(Session, coro) (ServerHandler.cpp:646) — the HTTP/JSON-RPC path. The WebSocket path (processSession(WSSession, coro, jv), ServerHandler.cpp:467) never calls processRequest, so rpc.process is never emitted at all under the WebSocket-only harness. The earlier diagnosis (cross-thread context loss needing a C++ fix) was wrong: rpc.ws_message is a deliberate freshRoot (ServerHandler.cpp:473-474) so each WS message is its own trace rather than nesting under a span leaked on a reused coroutine worker. Nothing to fix." }, { "parent": "rpc.ws_message", "child": "rpc.command.*", - "description": "WebSocket message contains the per-command span \u2014 the real relationship on the harness WS path (rpc::doCommand at RPCHandler.cpp:271 creates an ambient child of the rpc.ws_message scope inside the same coroutine). Not skipped, because the validator globs the wildcard child: _span_name_matches() matches via fnmatch.fnmatchcase, so any rpc.command. under the parent satisfies the contract and the command mix does not matter. A validator that instead collapsed the wildcard to one literal name -- child_name.replace(\"*\", \"server_info\") -- would make this check depend on which command the sampled traces happened to carry: server_info is 25/100 of rpc_load_generator.py's DEFAULT_WEIGHTS, so a healthy run could sample three non-server_info traces and fail." + "description": "WebSocket message contains the per-command span — the real relationship on the harness WS path (rpc::doCommand at RPCHandler.cpp:271 creates an ambient child of the rpc.ws_message scope inside the same coroutine). Not skipped, because the validator globs the wildcard child: _span_name_matches() matches via fnmatch.fnmatchcase, so any rpc.command. under the parent satisfies the contract and the command mix does not matter. A validator that instead collapsed the wildcard to one literal name -- child_name.replace(\"*\", \"server_info\") -- would make this check depend on which command the sampled traces happened to carry: server_info is 25/100 of rpc_load_generator.py's DEFAULT_WEIGHTS, so a healthy run could sample three non-server_info traces and fail." }, { "parent": "rpc.process", @@ -598,7 +613,7 @@ "child": "pathfind.compute", "description": "Pathfind request contains the compute sub-span", "skip": true, - "skip_reason": "Real relationship (pathfind.compute is created inside PathRequest::doUpdate at PathRequest.cpp:749-750, under the pathfind.request scope), but the child never exists on the harness because pathfinding is disabled on every node: Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for all five nodes with no [path_search*] override, and doRipplePathFind returns RpcNotSupported at RipplePathFind.cpp:59-60 before constructing a PathRequest. The parent would appear anyway if the RPC were issued, because its ScopedSpanGuard is created at RipplePathFind.cpp:35, above that guard; but rpc_load_generator.py carries no ripple_path_find weight, so not even the parent appears and both ends of this relationship are absent. Liquidity has nothing to do with it \u2014 the earlier 'no liquidity, returns before computing' reason was wrong, because no path search is attempted at all. Asserting this relationship needs the load restored AND a [path_search_max] override (or a non-validator node) in run-full-validation.sh." + "skip_reason": "Real relationship (pathfind.compute is created inside PathRequest::doUpdate at PathRequest.cpp:749-750, under the pathfind.request scope), but the child never exists on the harness because pathfinding is disabled on every node: Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] or [validator_token] section is present, run-full-validation.sh writes [validation_seed] for all five nodes with no [path_search*] override, and doRipplePathFind returns RpcNotSupported at RipplePathFind.cpp:59-60 before constructing a PathRequest. The parent would appear anyway if the RPC were issued, because its ScopedSpanGuard is created at RipplePathFind.cpp:35, above that guard; but rpc_load_generator.py carries no ripple_path_find weight, so not even the parent appears and both ends of this relationship are absent. Liquidity has nothing to do with it — the earlier 'no liquidity, returns before computing' reason was wrong, because no path search is attempted at all. Asserting this relationship needs the load restored AND a [path_search_max] override (or a non-validator node) in run-full-validation.sh." }, { "parent": "ledger.acquire", @@ -780,5 +795,5 @@ }, "_conditional_attributes_note": "Five attributes documented in the 'Fresh-node sync diagnostics' table of docs/telemetry-glossary.md are deliberately absent from required_attributes above, because each is emitted only when its value is known and _validate_span_attributes_otlp() has no per-attribute optional flag -- listing one would fail CI red on a healthy run. ledger.acquire/peer_count is set only when finalizeAcquireSpan() is passed a peer count (InboundLedger.cpp), which the sweep and shutdown paths cannot supply. ledger_seq on the three ledger.acquire.header/.astree/.txtree phase spans is set only when seq_ != 0 (InboundLedger.cpp startPhaseSpan), and a by-hash acquire starts with seq_ == 0 and learns the sequence only when the header arrives -- so a phase that opens before the header legitimately carries no sequence. ledger_seq on ledger.serve is set only when the reply carries one (PeerImp.cpp), which an object-by-hash request does not. All five ARE indexed in the glossary table and rendered by the Ledger Sync Health board; the honest encoding is to document them here rather than assert a conditional attribute as required.", "total_span_types": 57, - "total_unique_attributes": 80 + "total_unique_attributes": 78 } diff --git a/docker/telemetry/workload/test_validate_telemetry.py b/docker/telemetry/workload/test_validate_telemetry.py index ac5f09a6ba..08c97e8b22 100644 --- a/docker/telemetry/workload/test_validate_telemetry.py +++ b/docker/telemetry/workload/test_validate_telemetry.py @@ -17,6 +17,7 @@ query itself and on the answer the check derives from a known corpus. import asyncio import json import sys +import tempfile from pathlib import Path from typing import Any @@ -24,6 +25,22 @@ sys.path.insert(0, str(Path(__file__).parent)) import validate_telemetry as vt # noqa: E402 +# The node a corpus entry belongs to unless it says otherwise. Named rather than +# repeated, because a test that writes it out for one span and relies on the +# default for another is asserting the two are the same node. +DEFAULT_INSTANCE = "node-1" + +# Arbitrary, and only the relative order matters. Non-zero so that a span whose +# start time went missing somewhere reads as earlier than every real one rather +# than tying with them. +START_TIME_BASE_NANOS = 1_000_000_000 + +# A corpus entry naming this as its parent gets the all-zero span id written out +# as its parentSpanId, instead of an id resolved from another span's name. That is +# OTLP's second spelling of "no parent": Tempo omits the field, but the field is +# optional rather than forbidden, so a root can arrive spelled this way. +ROOT_PARENT_SPAN_ID = "AAAAAAAAAAA=" + class FakeResponse: """Minimal stand-in for an aiohttp response used as an async context manager.""" @@ -51,15 +68,25 @@ class FakeTempo: Args: 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. + either a bare span name (a root span, no parent) or a tuple + ``(name, parent_name[, instance[, attributes]])``. 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, and the sentinel ROOT_PARENT_SPAN_ID writes OTLP's + all-zero "no parent" id verbatim. ``instance`` is the exporting + node's service.instance.id and defaults to DEFAULT_INSTANCE, so + a cross-node parent is written by giving the two spans different + ones. ``attributes`` is a plain str-to-str mapping, emitted in + OTLP stringValue form. 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. + + Start times follow the corpus order, one nanosecond apart, so listing spans + in the order they ran is how a test states that order. That is what lets the + round-shape check's phase-order assertion be exercised at all. """ def __init__(self, traces: dict[str, list[Any]]) -> None: @@ -76,10 +103,16 @@ class FakeTempo: span: dict[str, Any] = { "name": names[i], "spanId": ids[i], - "attributes": [], + "attributes": [ + {"key": k, "value": {"stringValue": v}} + for k, v in _entry_attributes(entry).items() + ], + "startTimeUnixNano": str(START_TIME_BASE_NANOS + i), } parent = entry[1] if isinstance(entry, tuple) else None - if parent is not None: + if parent == ROOT_PARENT_SPAN_ID: + span["parentSpanId"] = ROOT_PARENT_SPAN_ID + elif 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"] = ( @@ -90,6 +123,36 @@ class FakeTempo: spans.append(span) return spans + def _batches_for(self, tid: str) -> list[dict[str, Any]]: + """Group one trace's spans into one OTLP batch per exporting node. + + Tempo carries service.instance.id on the batch resource, not on the + span, so a trace that spans two nodes genuinely arrives as two batches. + The parent gate reads that field to tell a same-node parent from a + cross-node one, and a single batch could not express the difference -- + every span would claim the same node and a cross-node parent would read + as a mis-parenting. + """ + spans = self._spans_for(tid) + instances = [_entry_instance(e) for e in self.traces.get(tid, [])] + grouped: dict[str, list[dict[str, Any]]] = {} + for span, instance in zip(spans, instances): + grouped.setdefault(instance, []).append(span) + return [ + { + "resource": { + "attributes": [ + { + "key": "service.instance.id", + "value": {"stringValue": instance}, + } + ] + }, + "scopeSpans": [{"spans": batch}], + } + for instance, batch in grouped.items() + ] + def get(self, url: str, params: dict[str, str] | None = None) -> FakeResponse: params = params or {} if "/api/search" in url: @@ -103,17 +166,29 @@ class FakeTempo: return FakeResponse({"traces": [{"traceID": t} for t in matched[:limit]]}) if "/api/traces/" in url: tid = url.rsplit("/", 1)[-1] - return FakeResponse( - {"batches": [{"scopeSpans": [{"spans": self._spans_for(tid)}]}]} - ) + return FakeResponse({"batches": self._batches_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.""" + """The span name of a corpus entry, whether bare or a tuple.""" return entry[0] if isinstance(entry, tuple) else entry +def _entry_instance(entry: Any) -> str: + """The exporting node of a corpus entry, defaulting to DEFAULT_INSTANCE.""" + if isinstance(entry, tuple) and len(entry) > 2 and entry[2] is not None: + return str(entry[2]) + return DEFAULT_INSTANCE + + +def _entry_attributes(entry: Any) -> dict[str, str]: + """The span attributes of a corpus entry, defaulting to none.""" + if isinstance(entry, tuple) and len(entry) > 3 and entry[3] is not None: + return dict(entry[3]) + return {} + + def _query_matches_trace(query: str, names: list[str]) -> bool: """Evaluate the subset of TraceQL this suite uses against one trace. @@ -559,6 +634,514 @@ def test_literal_predicate_uses_equality() -> None: assert not vt._span_name_matches("txq.accept_tx_extra", "txq.accept_tx") +def test_span_declared_root_that_is_a_same_node_child_fails() -> None: + """The audit finding: ledger.build declared ROOT, emitted under accept.""" + tempo = FakeTempo( + {"t1": ["consensus.accept", ("ledger.build", "consensus.accept")]} + ) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + {"name": "ledger.build", "allowed_parents": ["ROOT"]}, + report, + ) + ) + assert len(report.results) == 1, report.results + assert not report.results[0].passed, report.results[0].message + assert "consensus.accept" in report.results[0].message + + +def test_cross_node_parent_is_not_a_violation() -> None: + """Review Focus 1: tx.receive's parent is the sender's span, on another node.""" + tempo = FakeTempo( + {"t1": [("tx.process", None, "node-2"), ("tx.receive", "tx.process", "node-1")]} + ) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + {"name": "tx.receive", "allowed_parents": ["ROOT"]}, + report, + ) + ) + assert len(report.results) == 1, report.results + assert report.results[0].passed, report.results[0].message + + +def test_same_node_parent_of_a_receive_span_is_a_violation() -> None: + """The control for the test above: the node id is what excuses the parent. + + Identical corpus except that both spans came from one node, which is the + shape a genuine mis-parenting of tx.receive would have. Without this, the + cross-node test passes just as happily against a gate that never reads + _instance at all and treats every in-trace parent as unprovable. + """ + tempo = FakeTempo( + {"t1": [("tx.process", None, "node-1"), ("tx.receive", "tx.process", "node-1")]} + ) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + {"name": "tx.receive", "allowed_parents": ["ROOT"]}, + report, + ) + ) + assert len(report.results) == 1, report.results + assert not report.results[0].passed, report.results[0].message + assert "tx.process" in report.results[0].message + + +def test_second_call_path_parent_is_allowed_when_listed() -> None: + """Review Focus 2: txq.accept is a child on one path and a root on the other.""" + tempo = FakeTempo( + { + "t1": ["consensus.accept.apply", ("txq.accept", "consensus.accept.apply")], + "t2": ["txq.accept"], + } + ) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + { + "name": "txq.accept", + "allowed_parents": ["consensus.accept.apply", "ROOT"], + }, + report, + ) + ) + assert len(report.results) == 1, report.results + assert report.results[0].passed, report.results[0].message + + +def test_absent_optional_span_skips_rather_than_fails() -> None: + """Review Focus 3: a span the harness never emits has nothing to judge.""" + tempo = FakeTempo({"t1": ["consensus.round"]}) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + { + "name": "nodestore.rotate.swap", + "allowed_parents": ["nodestore.rotate"], + "optional": True, + }, + report, + ) + ) + assert len(report.results) == 1, report.results + assert report.results[0].passed, report.results[0].message + assert "not emitted" in report.results[0].message + + +def test_absent_required_span_fails_rather_than_skips() -> None: + """A span the contract does NOT mark optional must fail when absent. + + The control for the skip above. A gate that returned passed=True for every + absent span would report green on a node that stopped emitting consensus + spans entirely, which is the loudest failure the harness exists to catch. + """ + tempo = FakeTempo({"t1": ["consensus.round"]}) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + {"name": "ledger.build", "allowed_parents": ["ROOT"]}, + report, + ) + ) + assert len(report.results) == 1, report.results + assert not report.results[0].passed, report.results[0].message + assert "not emitted" in report.results[0].message + + +def test_parent_id_absent_from_the_trace_is_inconclusive() -> None: + """Review Focus 4: a rotation still in flight has not exported its root.""" + tempo = FakeTempo({"t1": [("nodestore.rotate.copy", "nodestore.rotate")]}) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + { + "name": "nodestore.rotate.copy", + "allowed_parents": ["nodestore.rotate"], + "optional": True, + }, + report, + ) + ) + assert len(report.results) == 1, report.results + assert report.results[0].passed, report.results[0].message + assert "nothing was provable" in report.results[0].message + + +def test_a_glob_in_allowed_parents_matches_the_family() -> None: + """pathfind.request's only lawful parent is written as rpc.command.*. + + The contract allows a glob on the parent side as well as on the span's own + name, and the concrete command varies per request, so plain set membership + would read every real parent as a violation. Asserted here because the + pathfinding family is never emitted on the harness, so a live run cannot + reach this path and would not notice it being wrong. + """ + tempo = FakeTempo( + {"t1": ["rpc.command.fee", ("pathfind.request", "rpc.command.fee")]} + ) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + {"name": "pathfind.request", "allowed_parents": ["rpc.command.*"]}, + report, + ) + ) + assert len(report.results) == 1, report.results + assert report.results[0].passed, report.results[0].message + + +def test_round_missing_a_required_child_fails() -> None: + """A round whose phases are incomplete must fail, naming the phase. + + consensus.accept is present on purpose: it is the trace-selection predicate, + so a corpus without it exercises the "no trace holds both" path instead and + the test would be red for the wrong reason. The genuinely missing phase here + is consensus.ledger_close. + """ + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.phase.open", "consensus.round"), + ("consensus.establish", "consensus.round"), + ("consensus.accept", "consensus.round"), + ] + } + ) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + children = next(r for r in report.results if r.name == "span.round.children") + assert not children.passed, children.message + assert "consensus.ledger_close" in children.message + # The node id is the whole point of a red here: a five-node cluster gives no + # way to act on "1 of 5 rounds" without it. + assert DEFAULT_INSTANCE in children.message, children.message + + +def test_round_without_accept_in_the_newest_trace_is_not_a_missing_child() -> None: + """Item 3: a round exported before its accept span must not read as broken. + + The accept span always outlives the round span, and with a two-second export + batch delay the newest round can reach Tempo while its consensus.accept child + is still in the exporter. Selecting the newest rounds reports a missing child + on a healthy cluster; selecting traces that hold both does not. + + The production change that makes this fail: dropping the + `&& {name="consensus.accept"}` term from the search query. + """ + tempo = FakeTempo( + { + # Newest first, as /api/search returns. The newest round has not had + # its accept exported yet. + "t2": ["consensus.round", ("consensus.phase.open", "consensus.round")], + "t1": [ + "consensus.round", + ("consensus.phase.open", "consensus.round"), + ("consensus.ledger_close", "consensus.round"), + ("consensus.establish", "consensus.round"), + ("consensus.accept", "consensus.round"), + ], + } + ) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + assert all(r.passed for r in report.results), [r.message for r in report.results] + + +def test_no_trace_holding_both_round_and_accept_is_its_own_message() -> None: + """Nothing to judge is a distinct failure from a badly shaped round. + + Reporting it as a missing child would send whoever reads it looking for a + consensus bug when the real state is that Tempo holds no usable trace. + """ + tempo = FakeTempo({"t1": ["ledger.build"]}) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + assert len(report.results) == 1, report.results + assert not report.results[0].passed + assert "No trace holds both" in report.results[0].message + + +def test_a_round_is_not_shaped_from_another_nodes_phase_spans() -> None: + """A round's children are its OWN node's children, not the trace's. + + The deterministic trace strategy derives the trace_id from the previous + ledger hash, so all five validators' round spans arrive in one trace. Here + node-1's round span has no phases of its own and every phase span in the + trace was exported by node-2 while naming node-1's round as its parent -- + which is precisely the case a parentSpanId-only filter cannot tell apart from + a healthy round. node-1's round is missing all four phases, and that is what + the gate must report. + + The production change that makes this fail: dropping the _instance + comparison from the child filter, which makes node-1's round look complete. + """ + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.phase.open", "consensus.round", "node-2"), + ("consensus.ledger_close", "consensus.round", "node-2"), + ("consensus.establish", "consensus.round", "node-2"), + ("consensus.accept", "consensus.round", "node-2"), + ] + } + ) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + children = next(r for r in report.results if r.name == "span.round.children") + assert not children.passed, children.message + assert children.details["missing"] == { + "consensus.phase.open": 1, + "consensus.ledger_close": 1, + "consensus.establish": 1, + "consensus.accept": 1, + }, children.details + assert DEFAULT_INSTANCE in children.message, children.message + + +def test_round_with_all_children_in_order_passes() -> None: + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.phase.open", "consensus.round"), + ("consensus.ledger_close", "consensus.round"), + ("consensus.establish", "consensus.round"), + ("consensus.accept", "consensus.round"), + ] + } + ) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + assert all(r.passed for r in report.results), [r.message for r in report.results] + + +def test_round_with_phases_out_of_order_fails() -> None: + """The control for the pass above: the order has to be read, not assumed. + + Every required child is present, so span.round.children passes; only + span.round.phase_order can catch accept having started before open. Without + this test the positive case above passes against a gate that never compares + start times at all. + """ + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.accept", "consensus.round"), + ("consensus.phase.open", "consensus.round"), + ("consensus.ledger_close", "consensus.round"), + ("consensus.establish", "consensus.round"), + ] + } + ) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + children = next(r for r in report.results if r.name == "span.round.children") + assert children.passed, children.message + order = next(r for r in report.results if r.name == "span.round.phase_order") + assert not order.passed, order.message + assert "out of order" in order.message + + +def test_mode_change_with_equal_modes_fails() -> None: + """Finding 2: a mode_change span that records no change.""" + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.phase.open", "consensus.round"), + ("consensus.ledger_close", "consensus.round"), + ("consensus.establish", "consensus.round"), + ("consensus.accept", "consensus.round"), + ( + "consensus.mode_change", + "consensus.round", + "node-1", + {"mode_old": "Observing", "mode_new": "Observing"}, + ), + ] + } + ) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + mc = next( + r for r in report.results if r.name == "span.mode_change.records_a_real_change" + ) + assert not mc.passed, mc.message + + +def test_mode_change_recording_a_real_change_passes() -> None: + """The control: a transition must not be reported as a defect. + + Same corpus as the failing case with one mode differing, so the gate is + shown to be reading the two attributes rather than failing on the span's + mere presence -- which would make every real mode transition red. + """ + tempo = FakeTempo( + { + "t1": [ + "consensus.round", + ("consensus.phase.open", "consensus.round"), + ("consensus.ledger_close", "consensus.round"), + ("consensus.establish", "consensus.round"), + ("consensus.accept", "consensus.round"), + ( + "consensus.mode_change", + "consensus.round", + "node-1", + {"mode_old": "Observing", "mode_new": "Proposing"}, + ), + ] + } + ) + report = Report() + run(vt.validate_consensus_round_shape(tempo, "http://tempo", report)) + mc = next( + r for r in report.results if r.name == "span.mode_change.records_a_real_change" + ) + assert mc.passed, mc.message + assert "1 mode_change span(s)" in mc.message + + +def test_root_written_as_the_all_zero_span_id_still_counts_as_root() -> None: + """OTLP's other spelling of "no parent" must not read as unprovable. + + Tempo omits parentSpanId for a root, so this shape does not occur against it + today. An exporter or backend that writes the all-zero id instead would make + EVERY root unprovable, and an unprovable parent passes -- so the gate would + go quietly fail-open on exactly the spans it exists to judge. + + The message is asserted, not just the verdict: without the all-zero handling + this test still sees passed=True, because the id matches no span in the trace + and the span is counted as unprovable instead. + """ + tempo = FakeTempo({"t1": [("ledger.build", ROOT_PARENT_SPAN_ID)]}) + report = Report() + run( + vt._validate_span_parents_for( + tempo, + "http://tempo", + {"name": "ledger.build", "allowed_parents": ["ROOT"]}, + report, + ) + ) + assert len(report.results) == 1, report.results + assert report.results[0].passed, report.results[0].message + message = report.results[0].message + assert "every provable parent" in message, message + assert report.results[0].details["observed"] == {"ROOT": 1}, report.results[ + 0 + ].details + assert report.results[0].details["unprovable"] == 0, report.results[0].details + + +def test_validate_span_parents_checks_every_contract_entry() -> None: + """The sweep must visit the whole inventory, one result per entry. + + _validate_span_parents_for is well covered on its own, but nothing proved + that the caller iterates -- a loop that returned after the first entry, or + read a different key than 'spans', would leave 40 spans unchecked while the + report still looked healthy. Driven through a real file so the loader is + exercised too, rather than by stubbing _load_expected_spans. + """ + contract = { + "spans": [ + {"name": "consensus.round", "allowed_parents": ["ROOT"]}, + { + "name": "consensus.accept", + "allowed_parents": ["consensus.round"], + }, + ] + } + tempo = FakeTempo( + {"t1": ["consensus.round", ("consensus.accept", "consensus.round")]} + ) + report = Report() + original = vt.EXPECTED_SPANS_FILE + with tempfile.TemporaryDirectory() as tmp: + scratch = Path(tmp) / "expected_spans.json" + scratch.write_text(json.dumps(contract)) + vt.EXPECTED_SPANS_FILE = scratch + try: + run(vt.validate_span_parents(tempo, "http://tempo", report)) + finally: + vt.EXPECTED_SPANS_FILE = original + assert [r.name for r in report.results] == [ + "span.parent.consensus.round", + "span.parent.consensus.accept", + ], [r.name for r in report.results] + assert all(r.passed for r in report.results), [r.message for r in report.results] + + +def test_a_contract_entry_with_no_name_fails_only_itself() -> None: + """A malformed entry must not abort the sweep over the rest. + + Reading span_def["name"] outside the try raised KeyError out of the loop, so + one bad entry silently cost every later span its check. Now it is one failed + result and the sweep continues. + """ + contract = { + "spans": [ + {"allowed_parents": ["ROOT"]}, + {"name": "consensus.round", "allowed_parents": ["ROOT"]}, + ] + } + tempo = FakeTempo({"t1": ["consensus.round"]}) + report = Report() + original = vt.EXPECTED_SPANS_FILE + with tempfile.TemporaryDirectory() as tmp: + scratch = Path(tmp) / "expected_spans.json" + scratch.write_text(json.dumps(contract)) + vt.EXPECTED_SPANS_FILE = scratch + try: + run(vt.validate_span_parents(tempo, "http://tempo", report)) + finally: + vt.EXPECTED_SPANS_FILE = original + assert len(report.results) == 2, [r.name for r in report.results] + assert not report.results[0].passed, report.results[0].message + assert report.results[0].name == "span.parent." + assert report.results[1].passed, report.results[1].message + + +def test_every_contract_span_declares_allowed_parents() -> None: + """The contract itself: no entry may be left without the new key. + + validate_span_parents returns early on an entry with an empty or missing + allowed_parents, so a span that kept the old `parent` key would be silently + unchecked -- the exact failure mode this change exists to remove. Asserted + against the real file rather than a fixture, because the file is the thing + that can drift. + """ + contract = vt._load_expected_spans() + spans = contract["spans"] + assert spans, "expected_spans.json declares no spans" + missing = [s["name"] for s in spans if not s.get("allowed_parents")] + assert not missing, f"entries with no allowed_parents: {missing}" + stale = [s["name"] for s in spans if "parent" in s] + assert not stale, f"entries still carrying the old parent key: {stale}" + + 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, diff --git a/docker/telemetry/workload/validate_telemetry.py b/docker/telemetry/workload/validate_telemetry.py index 6fcb60896a..76fcf72842 100644 --- a/docker/telemetry/workload/validate_telemetry.py +++ b/docker/telemetry/workload/validate_telemetry.py @@ -33,6 +33,7 @@ Usage: import argparse import asyncio +import collections import fnmatch import json import logging @@ -389,6 +390,9 @@ async def _tempo_get_trace( Returns: Flat list of span dicts as Tempo returned them, carrying at least 'name', 'attributes', 'spanId' and, for non-root spans, 'parentSpanId'. + Each span also gains '_instance', the service.instance.id of the batch + resource it arrived under, or '' when that resource carries none. The + leading underscore marks it as added here rather than sent by Tempo. Empty when Tempo has no trace with this id. Raises: @@ -416,8 +420,18 @@ async def _tempo_get_trace( data = await resp.json() spans: list[dict[str, Any]] = [] for batch in data.get("batches", []): + # The resource is per batch and flattening drops it, but which node + # a span came from is the difference between a mis-parented span and + # an ordinary cross-node parent. Stamp it onto each span. + instance = "" + for attr in batch.get("resource", {}).get("attributes", []): + if attr.get("key") == "service.instance.id": + instance = str(attr.get("value", {}).get("stringValue", "")) + break for scope_spans in batch.get("scopeSpans", []): - spans.extend(scope_spans.get("spans", [])) + for span in scope_spans.get("spans", []): + span["_instance"] = instance + spans.append(span) return spans @@ -519,6 +533,23 @@ def _unaccounted_span_names(emitted: list[str], expected: dict[str, Any]) -> lis # --------------------------------------------------------------------------- +def _load_expected_spans() -> dict[str, Any]: + """Parse expected_spans.json. + + Every span check reads the contract through this one function so that two + checks cannot end up disagreeing about it -- an inline open() in each would + let one of them be pointed at a different file or key during a refactor + while the other kept passing. + + Returns: + The parsed contract: a dict with 'spans' and + 'parent_child_relationships' keys. + """ + with open(EXPECTED_SPANS_FILE) as f: + contract: dict[str, Any] = json.load(f) + return contract + + async def validate_spans( session: aiohttp.ClientSession, tempo_url: str, @@ -538,8 +569,7 @@ async def validate_spans( logger.info("--- Span Validation (Tempo) ---") # Load expected spans. - with open(EXPECTED_SPANS_FILE) as f: - expected = json.load(f) + expected = _load_expected_spans() # Check service registration. try: @@ -1071,6 +1101,353 @@ async def _validate_parent_child( ) +_ALLOWED_PARENT_ROOT = "ROOT" + +# A parent span id of eight zero bytes is OTLP's "no parent". Tempo 2.9.4 omits +# the field entirely for a root instead -- measured on a 114-span trace, 80 spans +# with no parentSpanId, 34 with one, none empty and none all-zero -- but OTLP +# permits the all-zero id, so an exporter or backend that writes it must not turn +# every root into an unprovable parent. That would make this gate fail open on +# exactly the spans it exists to judge, and silently: "nothing was provable" +# passes. Both encodings a JSON OTLP payload can carry are listed, base64 (what +# Tempo emits for a real id) and lowercase hex. +_ROOT_PARENT_SPAN_IDS = frozenset({"AAAAAAAAAAA=", "0000000000000000"}) + + +def _observed_parent_label( + span: dict[str, Any], + by_id: dict[str, dict[str, Any]], +) -> str | None: + """Classify one span's parent as a label, or None when nothing is provable. + + Returns the parent span's name when the parent is in the trace and came from + the same node, _ALLOWED_PARENT_ROOT when the span has no parent at all + (either because the field is absent or because it holds the all-zero id), + and None when the parent is on another node or is not in the trace. + + None is deliberately not a verdict. A cross-node parent is the design for + the receive spans, and a parent id the trace does not hold means the parent + has not been exported yet, which a rotation in flight produces routinely. + + Args: + span: One OTLP span dict as _tempo_get_trace returned it, so carrying + the '_instance' key that function stamps on. + by_id: Every span in the same trace, keyed by its spanId. + + Returns: + The parent's name, _ALLOWED_PARENT_ROOT, or None. + """ + parent_id = span.get("parentSpanId", "") + if not parent_id or parent_id in _ROOT_PARENT_SPAN_IDS: + return _ALLOWED_PARENT_ROOT + parent = by_id.get(parent_id) + if parent is None: + return None + if parent.get("_instance", "") != span.get("_instance", ""): + return None + return str(parent.get("name", "")) + + +async def _validate_span_parents_for( + session: aiohttp.ClientSession, + tempo_url: str, + span_def: dict[str, Any], + report: ValidationReport, +) -> None: + """Check that every emitted instance of one span has an allowed parent. + + Driven by the span's own allowed_parents list rather than by the declared + relationship rows, so it covers every span in the inventory instead of the + pairs somebody remembered to declare -- and it is the only check that can + fail a span for being parented when it should be a root. + + Args: + session: aiohttp client session. + tempo_url: Base URL for Tempo API. + span_def: One entry from expected_spans.json's 'spans' array. + report: ValidationReport to accumulate results. + """ + # Read inside the try, so a contract entry missing its name is reported as + # one failed check rather than raised out of validate_span_parents' loop and + # taking every remaining span's check with it. + name = "" + check = "span.parent." + try: + name = str(span_def["name"]) + check = f"span.parent.{name}" + allowed = set(span_def.get("allowed_parents", [])) + if not allowed: + return + query = ( + '{resource.service.name="xrpld" && ' + _traceql_name_predicate(name) + "}" + ) + traces = await _tempo_search(session, tempo_url, query, limit=5) + if not traces: + optional = bool(span_def.get("optional", False)) + report.add( + CheckResult( + name=check, + category="span", + passed=optional, + message=f"{name}: not emitted under this workload, parent not checked", + details={"optional": optional}, + ) + ) + return + observed: collections.Counter[str] = collections.Counter() + unprovable = 0 + for summary in traces: + trace_id = summary.get("traceID", "") + if not trace_id: + continue + spans = await _tempo_get_trace(session, tempo_url, trace_id) + by_id = {s["spanId"]: s for s in spans if s.get("spanId")} + for span in spans: + if not _span_name_matches(span.get("name", ""), name): + continue + label = _observed_parent_label(span, by_id) + if label is None: + unprovable += 1 + else: + observed[label] += 1 + # An allowed_parents entry may itself be a glob -- pathfind.request is + # declared under rpc.command.* -- so membership goes through the same + # matcher the contract's span names use rather than a set lookup, which + # would read every concrete rpc.command. as a violation. + violations = { + lbl: n + for lbl, n in observed.items() + if not any(_span_name_matches(lbl, pattern) for pattern in allowed) + } + total = sum(observed.values()) + unprovable + if violations: + worst = max(violations.items(), key=lambda kv: kv[1]) + message = ( + f"{name}: parented to {worst[0]} on {worst[1]} of {total} " + f"instance(s); allowed: {sorted(allowed)}" + ) + elif observed: + message = f"{name}: every provable parent is one of {sorted(allowed)}" + else: + message = ( + f"{name}: {unprovable} instance(s), every parent on another node or " + "absent from the trace, so nothing was provable" + ) + report.add( + CheckResult( + name=check, + category="span", + passed=not violations, + message=message, + details={ + "observed": dict(observed), + "unprovable": unprovable, + "allowed": sorted(allowed), + }, + ) + ) + except Exception as exc: # noqa: BLE001 - a backend fault is a check failure + report.add( + CheckResult( + name=check, + category="span", + passed=False, + message=f"{name}: parent check failed ({exc})", + ) + ) + + +async def validate_span_parents( + session: aiohttp.ClientSession, + tempo_url: str, + report: ValidationReport, +) -> None: + """Run the parent gate over every span in the inventory. + + Args: + session: aiohttp client session. + tempo_url: Base URL for Tempo API. + report: ValidationReport to accumulate results. + """ + logger.info("--- Span Parent Validation (Tempo) ---") + for span_def in _load_expected_spans().get("spans", []): + await _validate_span_parents_for(session, tempo_url, span_def, report) + + +_ROUND_REQUIRED_CHILDREN = ( + "consensus.phase.open", + "consensus.ledger_close", + "consensus.establish", + "consensus.accept", +) + + +async def validate_consensus_round_shape( + session: aiohttp.ClientSession, + tempo_url: str, + report: ValidationReport, +) -> None: + """Check a consensus round's child set, their order, and mode_change. + + The presence and hierarchy checks judge one span at a time, so a round + missing a phase, or running its phases out of order, passes them both. The + shape of a round is what an operator reads a trace for, so it is asserted + directly: every required child under the same round span, on the same node, + and their start times in protocol order. Candidate traces are selected by + co-occurrence rather than recency -- see the comment on the query. + + mode_change rides along because it is a child of the same span. Its whole + purpose is to record a transition, so mode_old == mode_new is a defect + rather than a data point. + + Args: + session: aiohttp client session. + tempo_url: Base URL for Tempo API. + report: ValidationReport to accumulate results. + """ + logger.info("--- Consensus Round Shape (Tempo) ---") + try: + # Select traces holding the round AND its last phase, the way + # _validate_parent_child does, rather than the newest rounds. The accept + # span always outlives the round span -- the round guard is reset inside + # doAccept while the accept span's shared_ptr dies with the JtAccept + # lambda -- so with batch_delay_ms=2000 the two can leave in different + # export batches and the newest round becomes searchable before its + # consensus.accept child arrives. Sampling the newest rounds therefore + # reports a missing child on a perfectly shaped round, periodically. + query = '{resource.service.name="xrpld" && name="consensus.round"}' + traces = await _tempo_search( + session, + tempo_url, + query + ' && {name="consensus.accept"}', + limit=5, + ) + if not traces: + report.add( + CheckResult( + name="span.round.children", + category="span", + passed=False, + message=( + "No trace holds both consensus.round and consensus.accept, " + "so round shape could not be checked" + ), + ) + ) + return + missing: collections.Counter[str] = collections.Counter() + # Node ids are collected per failing check, not per round: a red here is + # only actionable if it says which node produced the bad shape, and on a + # five-node cluster "1 of 5 rounds" does not. + missing_nodes: set[str] = set() + disordered_nodes: set[str] = set() + equal_mode_nodes: set[str] = set() + rounds = out_of_order = mode_changes = equal_modes = 0 + for summary in traces: + trace_id = summary.get("traceID", "") + if not trace_id: + continue + spans = await _tempo_get_trace(session, tempo_url, trace_id) + for parent in [s for s in spans if s.get("name") == "consensus.round"]: + rounds += 1 + node = str(parent.get("_instance", "")) or "(unknown node)" + # Same node as well as same parent id: one trace carries every + # validator's view of the round, so a round span from node A and + # a phase span from node B must not be read as one round. + kids = [ + s + for s in spans + if s.get("parentSpanId") == parent.get("spanId") + and s.get("_instance", "") == parent.get("_instance", "") + ] + by_name = {s.get("name", ""): s for s in kids} + for required in _ROUND_REQUIRED_CHILDREN: + if required not in by_name: + missing[required] += 1 + missing_nodes.add(node) + starts = [ + int(by_name[n].get("startTimeUnixNano", "0")) + for n in _ROUND_REQUIRED_CHILDREN + if n in by_name + ] + if starts != sorted(starts): + out_of_order += 1 + disordered_nodes.add(node) + for mc in [s for s in kids if s.get("name") == "consensus.mode_change"]: + mode_changes += 1 + attrs = { + a["key"]: a.get("value", {}) for a in mc.get("attributes", []) + } + old = attrs.get("mode_old", {}).get("stringValue") + new = attrs.get("mode_new", {}).get("stringValue") + if old is not None and old == new: + equal_modes += 1 + equal_mode_nodes.add(node) + report.add( + CheckResult( + name="span.round.children", + category="span", + passed=not missing, + message=( + f"{rounds} round(s): every required child present" + if not missing + else f"{rounds} round(s) missing children: {dict(missing)} " + f"on {sorted(missing_nodes)}" + ), + details={ + "rounds": rounds, + "missing": dict(missing), + "nodes": sorted(missing_nodes), + }, + ) + ) + report.add( + CheckResult( + name="span.round.phase_order", + category="span", + passed=out_of_order == 0, + message=( + f"{rounds} round(s): phases start in protocol order" + if out_of_order == 0 + else f"{out_of_order} of {rounds} round(s) started their phases " + f"out of order on {sorted(disordered_nodes)}" + ), + details={ + "rounds": rounds, + "out_of_order": out_of_order, + "nodes": sorted(disordered_nodes), + }, + ) + ) + report.add( + CheckResult( + name="span.mode_change.records_a_real_change", + category="span", + passed=equal_modes == 0, + message=( + f"{mode_changes} mode_change span(s), none with mode_old == mode_new" + if equal_modes == 0 + else f"{equal_modes} of {mode_changes} mode_change span(s) recorded " + f"no change (mode_old == mode_new) on {sorted(equal_mode_nodes)}" + ), + details={ + "mode_changes": mode_changes, + "equal": equal_modes, + "nodes": sorted(equal_mode_nodes), + }, + ) + ) + except Exception as exc: # noqa: BLE001 - a backend fault is a check failure + report.add( + CheckResult( + name="span.round.children", + category="span", + passed=False, + message=f"Round shape check failed ({exc})", + ) + ) + + # --------------------------------------------------------------------------- # Trace-join Validation (Tempo API) # --------------------------------------------------------------------------- @@ -2733,6 +3110,8 @@ async def run_validation( async with aiohttp.ClientSession(timeout=REQUEST_TIMEOUT) as session: await validate_spans(session, tempo_url, report) + await validate_span_parents(session, tempo_url, report) + await validate_consensus_round_shape(session, tempo_url, report) await validate_span_durations(session, tempo_url, report) await assert_trace_join_groups(session, tempo_url, report) await validate_metrics(session, prometheus_url, report) diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 9438c52181..cc04dfaa92 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -303,10 +303,11 @@ txID-keyed spans can be joined to the ledger trace it targeted `tx.transactor`) also carry `current_ledger_hash` (the current ledger's parent hash); `tx.preflight` is stateless and omits both. -`tx.apply` carries **no** `ledger_seq` of its own — the sequence is set on its -parent `ledger.build` +`tx.apply` carries its own `ledger_seq`, written beside `tx_count` and `tx_failed` +([BuildLedger.cpp:197](../src/xrpld/app/ledger/detail/BuildLedger.cpp#L197)). Its +parent `ledger.build` carries the same sequence ([BuildLedger.cpp:90](../src/xrpld/app/ledger/detail/BuildLedger.cpp#L90)), so -read it from the parent rather than filtering `tx.apply` on it. +either span can be filtered on it. ### Transaction Queue Spans @@ -1137,7 +1138,7 @@ call edge. Read a trace with these in mind: | `tx.process` is a `hashSpan` root from `txID` — an independent trace root ([TxTracing.h:63](../src/xrpld/telemetry/TxTracing.h#L63)). | The real edge is the synchronous `doSubmit → processTransaction` call; it is **not** a child of `rpc.command.submit`. | | `tx.preflight` / `tx.preclaim` / `tx.transactor` share one `txID`-derived trace ID. | That shared ID is a correlation trick, not a call edge. The real order is the composed `apply()` at [apply.cpp:118](../src/libxrpl/tx/apply.cpp#L118). They are **not** children of `tx.process` or `tx.apply`. Because nothing else nests under it either, `tx.apply` is **always a leaf** — the stage spans for the transactions it applied sit in the txID-keyed trace, not beneath it. | | `consensus.round` uses a deterministic trace ID from the previous ledger hash. | This makes **all validators share one trace ID** (a cross-node shared root), not a per-node parent. The real round-to-round edge is `endConsensus → beginConsensus`. | -| `consensus.accept` (main thread) and `consensus.accept.apply` (JtAccept worker) are wired via a captured context. | The real edge is the queued `JtAccept` job, a thread hand-off ([RCLConsensus.cpp:483](../src/xrpld/app/consensus/RCLConsensus.cpp#L483)). | +| `consensus.accept` (main thread) and `consensus.accept.apply` (JtAccept worker) are wired via a captured context. | The real edge is the queued `JtAccept` job, a thread hand-off ([RCLConsensus.cpp:483](../src/xrpld/app/consensus/RCLConsensus.cpp#L483)). `consensus.accept.apply` is a scoped guard, so the spans `doAccept` creates after it (`ledger.build`, `txq.cleanup`, `txq.accept`, `ledger.store`, `ledger.validate`) nest under it; those are real containment edges. | | `pathfind.update_all` parents nothing from the original `pathfind.request`. | The causal link is the ledger-close job on `JtUpdatePf`, not span nesting. | | `ledger.acquire` and its downstream `ledger.store` / `ledger.validate`. | Reached via the `AcqDone` job, not parent inheritance. All three are non-scoped `SpanGuard::span` spans, so none of them parents the others; each takes whatever ambient span its own caller happens to have active. See the `ledger.*` known issue below. | | `peer.*.receive` (fresh `kConsumer` root) and `consensus.*.receive` on the same message. | Two **sequential stages of one synchronous handler**, not parent/child; on a duplicate/untrusted drop the `consensus.*.receive` is never created. | @@ -1192,21 +1193,26 @@ are pending a code fix: [168](../src/xrpld/app/ledger/detail/InboundLedger.cpp#L168)) land there as siblings. A ledger acquisition nested under an `rpc.command.*` trace is this bug, not a real call edge. + - **Nested under `consensus.accept.apply`, by design.** On the consensus path + `buildLCL → storeLedger` ([RCLConsensus.cpp:997](../src/xrpld/app/consensus/RCLConsensus.cpp#L997)) + and `consensusBuilt → checkAccept` ([RCLConsensus.cpp:799](../src/xrpld/app/consensus/RCLConsensus.cpp#L799)) + run inside `doAccept`, whose `consensus.accept.apply` span is a scoped guard + ([RCLConsensus.cpp:634](../src/xrpld/app/consensus/RCLConsensus.cpp#L634)), so the + `ledger.store` and `ledger.validate` created there are its children. That is a + real containment edge. A `ledger.store` under `consensus.accept.apply` and a + second one as a root for the same ledger is the normal shape when a node both + builds a ledger and fetches it. - **`ledger.build` and `tx.apply` use the same ambient-parent construct but are - safe.** `ledger.build` is a plain `ScopedSpanGuard` - ([BuildLedger.cpp:55](../src/xrpld/app/ledger/detail/BuildLedger.cpp#L55)): its - only callers are `RCLConsensus::doAccept` - ([RCLConsensus.cpp:935-937](../src/xrpld/app/consensus/RCLConsensus.cpp#L935)) - on the `JtAccept` worker and the replay path - ([LedgerDeltaAcquire.cpp:208](../src/xrpld/app/ledger/detail/LedgerDeltaAcquire.cpp#L208)), - and every consensus accept span is a non-scoped `SpanGuard` - ([RCLConsensus.cpp:598-599](../src/xrpld/app/consensus/RCLConsensus.cpp#L598)), - so no ambient span exists to be inherited there. `tx.apply` + **`ledger.build` and `tx.apply` use the same ambient-parent construct and land + on the intended edges.** `ledger.build` is a plain `ScopedSpanGuard` + ([BuildLedger.cpp:55](../src/xrpld/app/ledger/detail/BuildLedger.cpp#L55)): on the + consensus path it is created inside `doAccept` after `consensus.accept.apply` + opens, so it nests under that span; on the replay path + ([LedgerDeltaAcquire.cpp:208](../src/xrpld/app/ledger/detail/LedgerDeltaAcquire.cpp#L208)) + nothing is ambient and it is a root. `tx.apply` ([BuildLedger.cpp:123](../src/xrpld/app/ledger/detail/BuildLedger.cpp#L123)) is reached only synchronously from `buildLedgerImpl` while `ledger.build`'s scope is - live, so its ambient parent is always `ledger.build` — which is exactly the - intended edge. + live, so its ambient parent is always `ledger.build`. - **`consensus.round` is not always a root.** The `consensus_trace_strategy=attribute` path has two creation branches; the fallback branch — taken on the first traced @@ -1328,8 +1334,9 @@ sum by (stage) (rate(span_calls_total{span_name=~"tx.preflight|tx.preclaim|tx.tr # Per-stage p95 latency histogram_quantile(0.95, sum by (le, stage) (rate(span_duration_milliseconds_bucket{span_name=~"tx.preflight|tx.preclaim|tx.transactor"}[5m]))) -# Per-stage failure rate (ter_result != tesSUCCESS; a failing ter completes the -# span normally, so filter on the attribute, not status_code which only flags exceptions) +# Per-stage failure rate (ter_result != tesSUCCESS). All three stage spans also set +# status_code="ERROR" on a failing ter, so status_code counts failures too; the +# attribute is used here because it names which failure. sum by (stage) (rate(span_calls_total{span_name=~"tx.preflight|tx.preclaim|tx.transactor", ter_result!~"tesSUCCESS|"}[5m])) ``` @@ -2873,7 +2880,7 @@ A plain `SpanGuard` that is **never activated** makes no span current — it "ne Severity does not affect injection, but `JLOG` filters on severity **before** `format()` runs, so the configured log level decides whether a qualifying line is emitted at all. -**The dependably correlated line at `info`** is the consensus accept pair at [RCLConsensus.cpp:736/740](../src/xrpld/app/consensus/RCLConsensus.cpp#L736) — an `if`/`else`, so exactly one of the two fires on every accepted round. `doAccept` activates the accept span as ambient over its whole body at [:565](../src/xrpld/app/consensus/RCLConsensus.cpp#L565) (`activateIfLive(acceptSpan)`, commented "Make the accept span ambient for the whole accept so doAccept's log lines ... correlate to it"), and the activation lives to the end of the function, so both branches are inside it. At roughly one round every 4 s this yields dozens of correlated lines per run. +**The dependably correlated line at `info`** is the consensus accept pair at [RCLConsensus.cpp:736/740](../src/xrpld/app/consensus/RCLConsensus.cpp#L736) — an `if`/`else`, so exactly one of the two fires on every accepted round. `doAccept` activates the accept span as ambient (`activateIfLive(acceptSpan)`) and then opens `consensus.accept.apply` as a scoped guard ([RCLConsensus.cpp:634](../src/xrpld/app/consensus/RCLConsensus.cpp#L634)), which stays ambient to the end of the function. Both branches of the pair sit inside it, so their lines carry the round's `trace_id` and `consensus.accept.apply`'s `span_id`. At roughly one round every 4 s this yields dozens of correlated lines per run. That is a dependable pair rather than an unconditional one: `info` severity is necessary but not sufficient. Four preconditions must all hold, and each has its own bail-out that silently yields an uncorrelated line rather than an error: diff --git a/include/xrpl/consensus/ConsensusSpanNames.h b/include/xrpl/consensus/ConsensusSpanNames.h index d14c1dd5cd..3ad285d276 100644 --- a/include/xrpl/consensus/ConsensusSpanNames.h +++ b/include/xrpl/consensus/ConsensusSpanNames.h @@ -59,7 +59,9 @@ * | Attrs: proposers, round_time_ms, quorum * | | * | +-- consensus.accept.apply [jtACCEPT thread, child of accept] - * | Created: Adaptor::doAccept() + * | Created: Adaptor::doAccept(), scoped: the txq spans doAccept + * | goes on to create nest under it; the tx apply-stage + * | spans are hash-derived roots and do not * | Attrs: ledger_seq, close_time_ripple_epoch_s, close_time_correct, * | close_resolution_ms, consensus_state, proposing, round_time_ms, * | parent_close_time_ripple_epoch_s, close_time_self_ripple_epoch_s, @@ -71,7 +73,7 @@ * | Attrs: ledger_seq, proposing * | * +-- consensus.mode_change [main thread] - * Created: Adaptor::onModeChange() + * Created: Adaptor::onModeChange(), only when the mode moves * Attrs: mode_old, mode_new * * Standalone spans (no parent, created per-message in overlay): diff --git a/include/xrpl/telemetry/SpanGuard.h b/include/xrpl/telemetry/SpanGuard.h index 10a4a80b4a..24ae206694 100644 --- a/include/xrpl/telemetry/SpanGuard.h +++ b/include/xrpl/telemetry/SpanGuard.h @@ -918,6 +918,15 @@ public: void addEvent(std::string_view name) noexcept; + /** + * Add a named event with key-value attributes to the span's timeline. + * No-op on a null guard. + * @param name Event name. + * @param attrs Attribute pairs (all string_view for simplicity). + */ + void + addEvent(std::string_view name, std::initializer_list attrs) noexcept; + /** * Record an exception as a span event and mark status as error. * No-op on a null guard. @@ -1355,6 +1364,10 @@ public: { } void + addEvent(std::string_view, std::initializer_list) noexcept + { + } + void recordException(std::exception const&) noexcept { } diff --git a/src/libxrpl/telemetry/SpanGuard.cpp b/src/libxrpl/telemetry/SpanGuard.cpp index 9c2cdc0a6e..1075124c58 100644 --- a/src/libxrpl/telemetry/SpanGuard.cpp +++ b/src/libxrpl/telemetry/SpanGuard.cpp @@ -864,6 +864,14 @@ ScopedSpanGuard::addEvent(std::string_view name) noexcept impl_->guard.addEvent(name); } +void +ScopedSpanGuard::addEvent( + std::string_view name, + std::initializer_list attrs) noexcept +{ + impl_->guard.addEvent(name, attrs); +} + void ScopedSpanGuard::recordException(std::exception const& e) noexcept { diff --git a/src/tests/libxrpl/telemetry/SpanGuardScope.cpp b/src/tests/libxrpl/telemetry/SpanGuardScope.cpp index 3da54f8bee..647cf59013 100644 --- a/src/tests/libxrpl/telemetry/SpanGuardScope.cpp +++ b/src/tests/libxrpl/telemetry/SpanGuardScope.cpp @@ -59,6 +59,7 @@ #include #include +#include #include #include #include @@ -673,6 +674,85 @@ TEST_F(SpanGuardScopeTest, spanGuard_addEvent_without_attributes_records_bare_ev EXPECT_EQ(events.front().GetAttributes().size(), 0u); } +// The scoped guard records event attributes too. consensus.accept.apply relies +// on it for one tx.included event per transaction of the accepted set. +TEST_F(SpanGuardScopeTest, scopedGuard_addEvent_records_name_and_attribute_values) +{ + namespace cs = consensus::span; + + static constexpr std::string_view kEventName{cs::event::txIncluded}; + static constexpr std::string_view kTxIdKey{cs::attr::txId}; + static constexpr std::string_view kTxId{"6B5F1A2C3D4E5F60718293A4B5C6D7E8"}; + + { + ScopedSpanGuard guard(TraceCategory::Consensus, seg::consensus, cs::op::acceptApply); + ASSERT_TRUE(static_cast(guard)); + guard.addEvent(kEventName, {{kTxIdKey, kTxId}}); + } + + auto spans = spanData()->GetSpans(); + auto* applySpan = findSpan(spans, cs::acceptApply); + ASSERT_NE(applySpan, nullptr); + + auto const& events = applySpan->GetEvents(); + ASSERT_EQ(events.size(), 1u); + EXPECT_EQ(events.front().GetName(), std::string(kEventName)); + EXPECT_EQ(events.front().GetAttributes().size(), 1u); + EXPECT_EQ(eventAttribute(events.front(), kTxIdKey), std::string(kTxId)); +} + +// A scoped child of a captured context is the ambient parent of the spans +// created after it on the same thread. A hash-derived root created inside that +// scope stays a root. consensus.accept.apply relies on both. +TEST_F(SpanGuardScopeTest, scopedChildOfCapturedContextIsAmbientForLaterSpans) +{ + namespace cs = consensus::span; + + auto const h = makeTraceIdBytes(); + { + // consensus.accept: unscoped, thread-free, context captured. + auto accept = + SpanGuard::freshRoot(TraceCategory::Consensus, seg::consensus, cs::op::accept); + ASSERT_TRUE(static_cast(accept)); + auto const acceptCtx = accept.spanContext(); + + // consensus.accept.apply: scoped child of that context. + ScopedSpanGuard const apply = ScopedSpanGuard::childSpan(cs::acceptApply, acceptCtx); + ASSERT_TRUE(static_cast(apply)); + + // ledger.build: a plain ambient scoped guard. + { + ScopedSpanGuard const build(TraceCategory::Ledger, seg::ledger, "build"); + ASSERT_TRUE(static_cast(build)); + } + + // ledger.store: hash-derived, so a deterministic root. + { + auto store = + SpanGuard::hashSpan(TraceCategory::Ledger, "ledger.store", h.data(), h.size()); + ASSERT_TRUE(static_cast(store)); + } + } + + auto spans = spanData()->GetSpans(); + auto* accept = findSpan(spans, cs::accept); + auto* apply = findSpan(spans, cs::acceptApply); + auto* build = findSpan(spans, "ledger.build"); + auto* store = findSpan(spans, "ledger.store"); + ASSERT_NE(accept, nullptr); + ASSERT_NE(apply, nullptr); + ASSERT_NE(build, nullptr); + ASSERT_NE(store, nullptr); + + EXPECT_EQ(apply->GetParentSpanId(), accept->GetSpanId()); + // build nests under apply, not beside it. + EXPECT_EQ(build->GetParentSpanId(), apply->GetSpanId()); + EXPECT_EQ(build->GetTraceId(), apply->GetTraceId()); + // The hash-derived span is a root on its own pinned trace id. + EXPECT_FALSE(store->GetParentSpanId().IsValid()); + EXPECT_TRUE(std::ranges::equal(store->GetTraceId().Id(), h)); +} + // A forced-root span started while a PendingTraceId is active adopts that // pinned 16-byte trace_id and remains a true root (no parent). TEST_F(SpanGuardScopeTest, deterministicIdGenerator_forced_root_gets_pending_trace_id) diff --git a/src/xrpld/app/consensus/RCLConsensus.cpp b/src/xrpld/app/consensus/RCLConsensus.cpp index 96bd174bd7..5a7f89db45 100644 --- a/src/xrpld/app/consensus/RCLConsensus.cpp +++ b/src/xrpld/app/consensus/RCLConsensus.cpp @@ -643,10 +643,9 @@ RCLConsensus::Adaptor::doAccept( { namespace cs = telemetry::consensus::span; - // Make the accept span ambient for the whole accept so doAccept's log lines - // (and any spans created here) correlate to it. Non-owning: acceptSpan still - // owns/ends the span. doAccept runs to completion on the JtAccept worker - // (no coroutine yield), so this scope is thread-local and safe. + // Make the accept span ambient until accept.apply opens below. Non-owning: + // acceptSpan still owns and ends the span. doAccept runs to completion on + // one thread, so the scope pops on the thread that pushed it. auto acceptActivation = telemetry::activateIfLive(acceptSpan); prevProposers_ = result.proposers; @@ -675,13 +674,10 @@ RCLConsensus::Adaptor::doAccept( closeTimeCorrect = true; } - // Parent accept.apply via the captured accept context (acceptSpanContext_): - // the accept span is a thread-free SpanGuard, so an explicit context is - // used for both the sync (onForceAccept) and async (onAccept) paths. Falls - // back to the round context if the accept span was null. - auto doAcceptSpan = acceptSpanContext_.isValid() - ? telemetry::SpanGuard::childSpan(cs::acceptApply, acceptSpanContext_) - : telemetry::SpanGuard::childSpan(cs::acceptApply, roundSpanContext_); + // Scoped: accept.apply is the ambient parent of every span doAccept creates + // from here on. Parented through acceptSpanContext_ because the accept span + // is a thread-free SpanGuard; the context is valid whenever that span is live. + auto doAcceptSpan = telemetry::ScopedSpanGuard::childSpan(cs::acceptApply, acceptSpanContext_); doAcceptSpan.setAttribute(cs::attr::ledgerSeq, static_cast(prevLedger.seq()) + 1); doAcceptSpan.setAttribute( cs::attr::closeTimeRippleEpochS, @@ -1208,9 +1204,16 @@ RCLConsensus::Adaptor::onModeChange(ConsensusMode before, ConsensusMode after) // thread-free SpanGuard, so parent explicitly via its context). A mode // change outside a round leaves roundSpanContext_ invalid, yielding a null // guard (no-op). - auto span = telemetry::SpanGuard::childSpan(cs::modeChange, roundSpanContext_); - span.setAttribute(cs::attr::modeOld, toDisplayString(before).c_str()); - span.setAttribute(cs::attr::modeNew, toDisplayString(after).c_str()); + // + // Only a real transition gets a span. MonitoredMode::set also calls this + // on every round start; the round's mode attribute below still needs that + // call, the span does not. + if (before != after) + { + auto span = telemetry::SpanGuard::childSpan(cs::modeChange, roundSpanContext_); + span.setAttribute(cs::attr::modeOld, toDisplayString(before).c_str()); + span.setAttribute(cs::attr::modeNew, toDisplayString(after).c_str()); + } JLOG(j_.info()) << "Consensus mode change before=" << to_string(before) << ", after=" << to_string(after);