merge: bring the lock-free ValidationTracker forward from phase10-workload-validation

Only the workload README conflicted; the tracker, config and test files merged
clean, which closes the chain from phase-7.
This commit is contained in:
Pratik Mankawde
2026-09-09 17:10:15 +01:00
44 changed files with 2661 additions and 1266 deletions

View File

@@ -49,6 +49,15 @@ the end of this test for which do and which do not.
docker compose -f docker/telemetry/docker-compose.yml up -d
```
The `xrpld-logdir-init` service creates `docker/telemetry/data/logs` and gives it
to uid/gid 1000. If `id -u` on this host is not 1000, xrpld cannot write its log
there and the log pipeline stays empty, so set the ids first:
```bash
XRPLD_UID=$(id -u) XRPLD_GID=$(id -g) \
docker compose -f docker/telemetry/docker-compose.yml up -d
```
Wait for services to be ready:
```bash
@@ -175,7 +184,7 @@ Run the integration test script:
bash docker/telemetry/integration-test.sh
```
It checks prerequisites, clears the previous run, brings up the observability stack, generates six validator key pairs and their node configs, starts the nodes, waits for consensus and then for a validated ledger, exercises RPC and submits a transaction, verifies traces in Tempo and both the spanmetrics and the StatsD-derived metrics in Prometheus, then prints a summary and leaves the stack running.
It checks prerequisites, clears the previous run, brings up the observability stack, generates six validator key pairs and their node configs, starts the nodes, waits for consensus and then for a validated ledger, exercises RPC and submits a transaction, verifies traces in Tempo and both the spanmetrics and the native `beast::insight` metrics that arrive over OTLP in Prometheus, checks that no StatsD listener is needed, then prints a summary and leaves the stack running.
The script announces each step as it runs, so read its `Step N:` headers for the authoritative sequence — they are not restated here, because a numbered copy of them drifts as soon as a step is added.
@@ -256,19 +265,18 @@ online_delete=256
/tmp/xrpld-integration/validators.txt
[ips_fixed]
127.0.0.1 51235
127.0.0.1 51236
127.0.0.1 51237
127.0.0.1 51238
127.0.0.1 51239
127.0.0.1 51240
{one "127.0.0.1 <port>" line for each port in 51235-51240 except this node's
own 51234 + node_number — a node must not list itself as a fixed peer, so
each config carries five lines, not six}
[peer_private]
1
[telemetry]
enabled=1
service_instance_id=Node-{N}
traces_endpoint=http://localhost:4318/v1/traces
metrics_endpoint=http://localhost:4318/v1/metrics
batch_size=512
batch_delay_ms=2000
max_queue_size=2048
@@ -278,6 +286,10 @@ trace_consensus=1
trace_peer=1
trace_ledger=1
[insight]
server=otel
endpoint=http://localhost:4318/v1/metrics
[rpc_startup]
{ "command": "log_level", "severity": "warning" }
@@ -599,7 +611,7 @@ Expected: log lines with `trace_id=<32hex> span_id=<16hex>` between the
severity code and the message. Example:
```
2024-Jan-15 10:30:45.123456 UTC RPCHandler:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Calling server_info
2024-Jan-15 10:30:45.123456789 UTC RPCHandler:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Calling server_info
```
Lines emitted outside of an active span (background tasks, startup) will
@@ -610,41 +622,59 @@ NOT have trace context — this is expected.
Extract a `trace_id` from the log and verify it exists in Tempo:
```bash
TRACE_ID=$(grep -o 'trace_id=[a-f0-9]\{32\}' /path/to/debug.log | head -1 | cut -d= -f2)
TRACE_ID=$(grep -m1 -o 'trace_id=[a-f0-9]\{32\}' /path/to/debug.log | cut -d= -f2)
echo "Checking trace: $TRACE_ID"
curl -s "http://localhost:3200/api/traces/$TRACE_ID" | jq '.batches | length'
```
Expected result: `> 0` (the trace exists in Tempo).
Tempo returns the trace in OTLP shape, so the array is `batches`, not `data`,
and one trace can arrive as several batches.
### Step 3: Verify Loki log ingestion
The OTel Collector's filelog receiver tails xrpld's debug.log and
The OTel Collector's file_log receiver tails xrpld's debug.log and
exports parsed entries to Loki. Verify Loki has received entries:
```bash
# Query Loki for any xrpld logs
curl -sG "http://localhost:3100/loki/api/v1/query" \
# Query Loki for any xrpld logs in the last 10 minutes
NOW_NS=$(($(date +%s) * 1000000000))
curl -sG "http://localhost:3100/loki/api/v1/query_range" \
--data-urlencode 'query={service_name="xrpld"}' \
--data-urlencode 'limit=5' | jq '.data.result | length'
--data-urlencode "start=$((NOW_NS - 600000000000))" \
--data-urlencode "end=${NOW_NS}" \
--data-urlencode 'limit=5' \
--data-urlencode 'direction=backward' |
jq '[.data.result[].values | length] | add // 0'
```
Expected: > 0 results.
Expected: > 0 log lines.
> **Use `service_name`, not `job`.** The collector's `resource/logs` processor
> applies an `upsert` to **both** `service.name=xrpld` and `job=xrpld`
> (`otel-collector-config.yaml:57-70`), and its comment says the `job` attribute
> is there so operators can paste `{job="xrpld"}`. That does not work: on OTLP
> ingest Loki promotes only an allow-listed set of resource attributes to indexed
> stream labels (`service.name` → `service_name`, plus `service.namespace`,
Use `query_range`, not `query`. Loki rejects a bare log selector on the
instant `/query` endpoint with HTTP 400 and a `text/plain` body
("log queries are not supported as an instant query type"), so `jq` fails to
parse it and the step never prints a number — even when ingestion is working.
Only metric queries such as `sum(count_over_time(...))` are allowed there,
which is why the validation scripts can use the instant endpoint.
Timestamps are unix nanoseconds, matching `workload/validate_telemetry.py`.
Counting `.data.result | length` would count streams, not log lines.
> **Use `service_name`, not `job`.** The local stack's `resource/logs` processor
> sets one key, `service.name=xrpld` (`otel-collector-config.yaml:84-86`); its
> comment there explains that a custom `job` attribute is not promoted to a
> stream label and tells you to select on `service_name`. Only the Grafana Cloud
> variant also sets `job=xrpld` (`otel-collector-config.grafanacloud.yaml:73-75`).
> Either way `{job="xrpld"}` does not work as a selector: on OTLP ingest Loki
> promotes only an allow-listed set of resource attributes to indexed stream
> labels (`service.name` → `service_name`, plus `service.namespace`,
> `service.instance.id`, `deployment.environment`, `k8s.*`, `cloud.*`), and `job`
> is not on the list. This repo mounts no Loki config override — the `loki`
> service runs the image's built-in `/etc/loki/local-config.yaml`
> (`docker-compose.yml:75`) — so `job` lands in **structured metadata**, which
> (`docker-compose.yml:116`) — so `job` lands in **structured metadata**, which
> cannot be a stream selector. `{job="xrpld"}` therefore returns **zero results
> with no error**, which reads exactly like "logs are not being ingested". If
> this query is empty, check `{service_name="xrpld"}` before debugging the
> pipeline. All 38 Loki queries in the shipped dashboards select on
> pipeline. All 35 Loki queries in the shipped dashboards select on
> `service_name`; none uses `job`.
### Step 4: Verify Grafana Tempo-to-Loki correlation
@@ -700,9 +730,9 @@ Expected: > 0 results.
ss -tlnp | grep ":$p " && echo "port $p in use"
done
```
2. Verify `[ips_fixed]` lists all 6 peer ports
2. Verify `[ips_fixed]` lists the 5 other peer ports, and not the node's own
3. Verify `validators.txt` has all 6 public keys
4. Check node debug logs: `tail -50 /tmp/xrpld-integration/node1/debug.log`
4. Check node debug logs: `tail -50 /tmp/xrpld-integration/Node-1/debug.log`
5. Ensure `[peer_private]` is set to `1` (prevents reaching out to public network)
### Transaction not processing
@@ -735,15 +765,15 @@ Expected: > 0 results.
The mount source defaults to the repo-relative `docker/telemetry/data/logs`
(where the telemetry configs write). Override `XRPLD_LOG_DIR` to tail logs
from another root.
2. Check OTel Collector logs for filelog receiver errors:
2. Check OTel Collector logs for file_log receiver errors:
```bash
docker compose -f docker/telemetry/docker-compose.yml logs otel-collector | grep -i "filelog\|loki\|error"
docker compose -f docker/telemetry/docker-compose.yml logs otel-collector | grep -i "file_log\|loki\|error"
```
3. Verify Loki is running:
```bash
curl -s http://localhost:3100/ready
```
4. Verify the filelog receiver glob pattern matches your log files:
4. Verify the file_log receiver glob pattern matches your log files:
The default pattern is `/var/log/xrpld/*/debug.log`
### Grafana trace-log links not working

View File

@@ -17,6 +17,15 @@
// See docker/telemetry/otel-collector-config.grafanacloud.yaml for the
// authoritative collector equivalent; keep the dimension list in sync with it.
//
// Logs are tailed here too, so all three signals leave a node through one
// exporter with one resource identity. The reference collector reads the log
// file with otelcol's own filelog receiver; Alloy's equivalent
// (otelcol.receiver.filelog) is still public-preview and refuses to load
// without --stability.level=public-preview on the alloy service, so the Loki
// source components are used instead and bridged into OTLP by
// otelcol.receiver.loki. Every component below is generally-available, so the
// service needs no extra flag.
//
// PIPELINE
//
// HOST / SYSTEMD METRICS:
@@ -30,6 +39,15 @@
// ▼
// exporter.otlphttp (GC OTLP gateway)
//
// xrpld LOGS (debug.log):
// file_match ─▶ loki.source.file ─▶ loki.process ─▶ receiver.loki
// (parse+label) │ OTLP logs
// ▼
// processor.transform.tier ─▶ processor.batch
// │
// ▼
// exporter.otlphttp (GC OTLP gateway)
//
// The Grafana Cloud OTLP gateway converts OTLP resource attributes to
// Prometheus labels server-side, so no otelcol.exporter.prometheus is needed.
//
@@ -44,11 +62,20 @@
// GRAFANACLOUD_OTLP_URL OTLP/HTTP gateway URL, including the /otlp path
// GRAFANACLOUD_OTLP_USER OTLP basic-auth username (numeric stack id)
// GRAFANACLOUD_OTLP_KEY OTLP basic-auth password (access token)
// XRPLD_HOST_LABEL host label for this node's scraped metrics
// XRPLD_HOST_LABEL host label for this node's scraped metrics, and
// the service.instance.id stamped on its logs. It
// must equal the node's [telemetry]
// service_instance_id, or logs carry a node name
// that no trace or metric shares and nothing joins.
// Optional:
// XRPLD_LOG_GLOB debug.log path to tail. Defaults to
// /space/xrpld/log/debug.log, the devnet layout.
//
// PER-DEPLOYMENT EDITS: the deployment.environment and xrpl.network.type tier
// values in otelcol.processor.transform are literals (OTTL cannot read env
// vars) -- edit them to match this node's tier and network.
// vars) -- edit them to match this node's tier and network. The log path is the
// exception: it is built in River, where sys.env does expand, and concatenated
// into the OTTL statement.
logging {
level = "info"
@@ -134,6 +161,68 @@ otelcol.receiver.otlp "xrpld" {
// * xrpl.network.type -> set only when absent (don't overwrite the node's
// own value). OTTL `where ... == nil` gives insert (not upsert) semantics.
// * telemetry.sdk.* -> deleted (SDK noise).
// ===========================================================================
// xrpld LOGS (debug.log --> OTLP gateway)
// ===========================================================================
// Tail the node's debug.log. devnet writes a single flat file
// (/space/xrpld/log/debug.log) rather than the per-node subdirectory the docker
// stack uses, so identity cannot be read off the path here -- it comes from
// XRPLD_HOST_LABEL below. Override XRPLD_LOG_GLOB for a different layout.
local.file_match "xrpld_logs" {
path_targets = [{
__path__ = coalesce(sys.env("XRPLD_LOG_GLOB"), "/space/xrpld/log/debug.log"),
}]
}
loki.source.file "xrpld_logs" {
targets = local.file_match.xrpld_logs.targets
forward_to = [loki.process.xrpld_logs.receiver]
}
// Parse the line Logs::format() emits:
// YYYY-Mmm-DD HH:MM:SS.fffffffff UTC <partition>:<severity> [trace_id=... span_id=...] <message>
// The `partition:` prefix is omitted when the partition is empty, so that group
// is optional, and trace_id/span_id are present only for a sampled span.
loki.process "xrpld_logs" {
forward_to = [otelcol.receiver.loki.xrpld.receiver]
stage.regex {
expression = "^(?P<log_time>\\S+\\s+\\S+)\\s+\\S+\\s+(?:(?P<partition>\\S+):)?(?P<severity>\\S+)\\s+(?:trace_id=(?P<trace_id>[a-f0-9]+)\\s+span_id=(?P<span_id>[a-f0-9]+)\\s+)?"
}
// Use the node's own timestamp, not ingest time, or a log line cannot be
// lined up with the span it belongs to. The node emits nanosecond precision;
// the fractional part of this layout accepts any number of digits.
stage.timestamp {
source = "log_time"
format = "2006-Jan-02 15:04:05.999999999"
location = "UTC"
}
// A regex capture stays in the pipeline's extracted map and never reaches the
// entry unless a stage attaches it. Structured metadata keeps these queryable
// without making any of them an indexed label.
stage.structured_metadata {
values = {
partition = "",
severity = "",
trace_id = "",
span_id = "",
}
}
}
// Bridge the Loki entries into OTLP so logs use the same exporter, and get the
// same resource identity, as traces and metrics. Note this receiver produces an
// EMPTY resource and puts everything on the log record, so the resource
// attributes are set in processor.transform below.
otelcol.receiver.loki "xrpld" {
output {
logs = [otelcol.processor.transform.tier.input]
}
}
otelcol.processor.transform "tier" {
error_mode = "ignore"
@@ -166,6 +255,40 @@ otelcol.processor.transform "tier" {
]
}
// Logs use `log` context, not `resource`, for two reasons: receiver.loki
// hands over an empty resource, and the fields to promote (severity, trace
// ids) live on the record. Each Alloy instance serves one node, so writing a
// resource attribute from a record is unambiguous here.
//
// service.instance.id is concatenated in from XRPLD_HOST_LABEL because OTTL
// has no env() converter. Loki promotes only an allow-listed set of RESOURCE
// attributes to indexed stream labels, and service.instance.id is on that
// list, so it arrives as the label service_instance_id that the dashboards
// filter on. Setting it as a record attribute instead would make it
// structured metadata, which cannot be used in a {...} stream selector.
log_statements {
context = "log"
statements = [
"set(resource.attributes[\"service.instance.id\"], \"" + coalesce(sys.env("XRPLD_HOST_LABEL"), "unknown") + "\")",
`set(resource.attributes["service.name"], "xrpld")`,
`set(resource.attributes["deployment.environment"], "prod")`,
`set(resource.attributes["xrpl.network.type"], "mainnet") where resource.attributes["xrpl.network.type"] == nil`,
// Promote the parsed fields onto the first-class OTLP record fields, so
// Grafana links a log line to its trace natively instead of re-parsing
// the body. The guards matter: most lines are emitted outside a sampled
// span and must keep an empty trace id rather than an invalid one.
`set(severity_text, attributes["severity"]) where attributes["severity"] != nil`,
`set(trace_id.string, attributes["trace_id"]) where attributes["trace_id"] != nil`,
`set(span_id.string, attributes["span_id"]) where attributes["span_id"] != nil`,
// Drop the bridge's own bookkeeping so it does not become structured
// metadata on every line.
`delete_key(attributes, "filename")`,
`delete_key(attributes, "loki.attribute.labels")`,
`delete_key(attributes, "log.file.path")`,
`delete_key(attributes, "log.file.name")`,
]
}
output {
// Traces fan out: to the batch/gateway path AND into the spanmetrics
// connector so the RED metrics are derived from the same tagged spans.
@@ -175,6 +298,7 @@ otelcol.processor.transform "tier" {
]
// Native metrics go straight to the batch/gateway path.
metrics = [otelcol.processor.batch.xrpld.input]
logs = [otelcol.processor.batch.xrpld.input]
}
}
@@ -264,6 +388,7 @@ otelcol.processor.batch "xrpld" {
output {
traces = [otelcol.exporter.otlphttp.grafanacloud.input]
metrics = [otelcol.exporter.otlphttp.grafanacloud.input]
logs = [otelcol.exporter.otlphttp.grafanacloud.input]
}
}

View File

@@ -11,7 +11,7 @@
# run-full-validation.sh starts NUM_NODES (default 5) xrpld instances on
# 127.0.0.1, each with a cfg it generates inline, peered to each other via
# [ips_fixed]. They reach the collector through the published ports below and
# write their logs into the bind-mounted workdir for the filelog receiver.
# write their logs into the bind-mounted workdir for the file_log receiver.
#
# Usage:
# # Start the telemetry backend on its own:
@@ -47,7 +47,7 @@ services:
- "13133:13133" # Health check
volumes:
- ./otel-collector-config.yaml:/etc/otel-collector-config.yaml:ro
# Mount the validation workdir so the filelog receiver can tail node
# Mount the validation workdir so the file_log receiver can tail node
# logs. run-full-validation.sh sets XRPLD_LOG_DIR to its workdir; the
# default matches that workdir so a bare `docker compose up` also works.
- ${XRPLD_LOG_DIR:-/tmp/xrpld-validation}:/var/log/xrpld:ro

View File

@@ -3,7 +3,7 @@
# Provides services for local development:
# - otel-collector: receives OTLP traces from xrpld, batches and
# forwards them to Tempo. Also tails xrpld log files
# via filelog receiver and exports to Loki. Listens on ports
# via file_log receiver and exports to Loki. Listens on ports
# 4317 (gRPC) and 4318 (HTTP).
# - tempo: Grafana Tempo tracing backend, queryable via Grafana Explore
# on port 3000. Recommended for production (S3/GCS storage, TraceQL).
@@ -46,11 +46,34 @@ services:
networks:
- xrpld-telemetry
# One-shot init for the xrpld log root. Docker creates a missing bind-mount
# source as root, and xrpld then cannot create the <network> subdirectory
# inside it. Config::getDebugLogFile() only warns on that failure and carries
# on, so the node looks healthy while writing no debug.log at all and the
# whole log pipeline stays empty with no error at any layer. Create the
# directory here and hand it to the host user instead.
#
# XRPLD_UID/XRPLD_GID default to 1000, the first non-root user on a typical
# Linux host. Set them if `id -u` differs, or xrpld still cannot write.
# Reuses the Prometheus image for the same reason otelcol-storage-init does.
xrpld-logdir-init:
image: prom/prometheus:v3.13.2
user: "0:0"
entrypoint: ["sh", "-c"]
command:
[
"mkdir -p /data/logs && chown ${XRPLD_UID:-1000}:${XRPLD_GID:-1000} /data /data/logs",
]
volumes:
- ./data:/data
networks:
- xrpld-telemetry
# OpenTelemetry Collector: receives spans from xrpld via OTLP protocol,
# batches them for efficiency, and forwards to Tempo for storage.
otel-collector:
image: otel/opentelemetry-collector-contrib:0.158.0
# Second --config layers filelog offset persistence on top of the shared
# Second --config layers file_log offset persistence on top of the shared
# base config; the collector deep-merges them. Only this stack keeps its
# logs across restarts, so only this stack needs it.
command:
@@ -68,16 +91,18 @@ services:
volumes:
# Mount collector pipeline config (receivers → processors → exporters)
- ./otel-collector-config.yaml:/etc/otel-collector-config.yaml:ro
# Dev-only overlay: persist filelog read offsets across restarts
# Dev-only overlay: persist file_log read offsets across restarts
- ./otel-collector-filestorage.yaml:/etc/otel-collector-filestorage.yaml:ro
# Mount the xrpld log root for the filelog receiver. The telemetry
# Mount the xrpld log root for the file_log receiver. The telemetry
# configs write to docker/telemetry/data/logs/<network>/debug.log, so
# the default source is the repo-relative ./data/logs — user-owned and
# needing no root, so `docker compose up` works with no setup. Override
# XRPLD_LOG_DIR to point at another root (e.g. the integration test sets
# it to its own workdir). Mounted read-only so the collector only tails.
# the default source is the repo-relative ./data/logs, which
# xrpld-logdir-init has already created and handed to the host user.
# Override XRPLD_LOG_DIR to point at another root (e.g. the integration
# test sets it to its own workdir; that root is created by the test, so
# the init service is a no-op there). Mounted read-only so the collector
# only tails.
- ${XRPLD_LOG_DIR:-./data/logs}:/var/log/xrpld:ro
# Persisted filelog read offsets, so a collector restart resumes
# Persisted file_log read offsets, so a collector restart resumes
# instead of re-reading every debug.log from the top.
- otelcol-storage:/var/lib/otelcol
depends_on:
@@ -87,6 +112,8 @@ services:
condition: service_started
otelcol-storage-init:
condition: service_completed_successfully
xrpld-logdir-init:
condition: service_completed_successfully
networks:
- xrpld-telemetry
@@ -107,7 +134,7 @@ services:
# Grafana Loki for centralized log ingestion and log-trace
# correlation. Loki 3.x supports native OTLP ingestion, so the OTel
# Collector exports via otlphttp to Loki's /otlp endpoint.
# Collector exports via otlp_http to Loki's /otlp endpoint.
# Query logs via Grafana Explore -> Loki at http://localhost:3000.
loki:
image: grafana/loki:3.7.6

View File

@@ -1035,7 +1035,7 @@
{
"type": "timeseries",
"title": "Log Line Rate By Severity",
"description": "###### What this is:\n*Rate of log lines emitted by xrpld, split by severity.*\n\n###### How it's computed:\n*Per-second count of matching log lines grouped by the severity field parsed out of each line.*\n\n###### Reading it:\n*Use this to confirm the log pipeline is alive, and to see at a glance whether DBG lines are being collected at all.*\n\n###### Healthy range:\n*Workload-dependent. If the DBG series is absent, every panel in a [DBG] row on this dashboard will be empty.*\n\n###### Watch for:\n*A sudden collapse to only WRN and ERR, which means debug logging was turned off and the [DBG] rows have gone blind rather than quiet.*\n\n###### Keywords:\n- **Severity** *(per line)* — xrpld log level: DBG, NFO, WRN, ERR, FTL.\n- **Structured metadata** *(per line)* — Loki fields parsed from the line, filtered with `|` rather than in the stream selector.\n\n###### Computation boundary:\n*Result: Per node per severity — a count of log lines, not of events in the node.*\n*Derived in the Grafana query; the collector's filelog receiver parses severity, xrpld itself exports no such metric.*\n\n###### Source:\n[Log.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/basics/Log.cpp)\n\n###### Function:\n`Logs::Sink::write`\n\n###### References:\n[Loki structured metadata](https://grafana.com/docs/loki/latest/get-started/labels/structured-metadata/)",
"description": "###### What this is:\n*Rate of log lines emitted by xrpld, split by severity.*\n\n###### How it's computed:\n*Per-second count of matching log lines grouped by the severity field parsed out of each line.*\n\n###### Reading it:\n*Use this to confirm the log pipeline is alive, and to see at a glance whether DBG lines are being collected at all.*\n\n###### Healthy range:\n*Workload-dependent. If the DBG series is absent, every panel in a [DBG] row on this dashboard will be empty.*\n\n###### Watch for:\n*A sudden collapse to only WRN and ERR, which means debug logging was turned off and the [DBG] rows have gone blind rather than quiet.*\n\n###### Keywords:\n- **Severity** *(per line)* — xrpld log level: DBG, NFO, WRN, ERR, FTL.\n- **Structured metadata** *(per line)* — Loki fields parsed from the line, filtered with `|` rather than in the stream selector.\n\n###### Computation boundary:\n*Result: Per node per severity — a count of log lines, not of events in the node.*\n*Derived in the Grafana query; the collector's file_log receiver parses severity, xrpld itself exports no such metric.*\n\n###### Source:\n[Log.cpp](https://github.com/XRPLF/rippled/blob/develop/src/libxrpl/basics/Log.cpp)\n\n###### Function:\n`Logs::Sink::write`\n\n###### References:\n[Loki structured metadata](https://grafana.com/docs/loki/latest/get-started/labels/structured-metadata/)",
"gridPos": {
"h": 10,
"w": 12,

View File

@@ -1,6 +1,6 @@
# Grafana Loki data source provisioning for rippled log-trace correlation.
#
# Loki ingests rippled logs via OTel Collector's filelog receiver.
# Loki ingests rippled logs via OTel Collector's file_log receiver.
# The derivedFields config links trace_id values in log lines back to
# Tempo traces, enabling one-click log-to-trace navigation in Grafana.

View File

@@ -37,11 +37,26 @@ GENESIS_SEED="snoPBrXtMeMyMHUVTgbuqAfg1SUTb"
DEST_ACCOUNT="" # Generated dynamically via wallet_propose
TEMPO="http://localhost:3200"
PROM="http://localhost:9090"
LOKI="http://localhost:3100"
# How long to wait for a log line to travel file -> file_log receiver -> batch
# processor -> Loki. The batch timeout is 1s, so this is mostly ingestion slack.
LOKI_INGEST_TIMEOUT=30
# Hard ceiling on every curl probe below. curl has no overall timeout of its
# own, so a server that accepts the connection and then never answers parks a
# poll loop forever and its attempt count stops bounding anything. 5 s is well
# above a healthy reply, so only a wedged server hits the ceiling.
CURL_MAX_TIME=5
# Counters for pass/fail
PASS=0
FAIL=0
# Unix seconds just before this run's nodes start. Every Tempo search is
# bounded to this run, so a previous run's traces cannot satisfy an assertion.
# Set in Step 5; check_span refuses to run while it is empty.
RUN_START=""
# ---------------------------------------------------------------------------
# Helpers
# ---------------------------------------------------------------------------
@@ -65,8 +80,16 @@ check_span() {
# -G is required: it moves the urlencoded params into the query string.
# Without it curl POSTs them as a request body, and Tempo answers 200
# while ignoring the query — so every span name would look present.
count=$(curl -sfG "$TEMPO/api/search" \
#
# start/end bound the search to this run. Tempo keeps blocks for
# block_retention (tempo.yaml, 1h) on a named volume, so without a bound
# an older run's spans answer for this one. The end margin covers spans
# exported while this query is in flight.
[ -n "$RUN_START" ] || die "check_span called before RUN_START was set"
count=$(curl -sfG --max-time "$CURL_MAX_TIME" "$TEMPO/api/search" \
--data-urlencode "q={resource.service.name=\"xrpld\" && name=\"$op\"}" \
--data-urlencode "start=$RUN_START" \
--data-urlencode "end=$(($(date +%s) + 60))" \
--data-urlencode "limit=5" |
jq '.traces | length' 2>/dev/null || echo 0)
if [ "$count" -gt 0 ]; then
@@ -88,7 +111,7 @@ check_log_correlation() {
local sample_trace_id=""
for i in $(seq 1 "$NUM_NODES"); do
local logfile="$WORKDIR/node$i/debug.log"
local logfile="$WORKDIR/Node-$i/debug.log"
if [ ! -f "$logfile" ]; then
continue
fi
@@ -98,12 +121,17 @@ check_log_correlation() {
total_matches=$((total_matches + matches))
# Capture the first trace_id we find for cross-referencing with Tempo
if [ -z "$sample_trace_id" ] && [ "$matches" -gt 0 ]; then
sample_trace_id=$(grep -o 'trace_id=[a-f0-9]\{32\}' "$logfile" | head -1 | cut -d= -f2)
# -m1 makes grep stop after the first match and exit normally.
# Piping into `head -1` instead closes the pipe under grep, and
# under `set -o pipefail` the resulting SIGPIPE (141) aborts the
# whole run. It only bites once the log is bigger than the pipe
# buffer, so it reads as a flaky test.
sample_trace_id=$(grep -m1 -o 'trace_id=[a-f0-9]\{32\}' "$logfile" | cut -d= -f2)
fi
done
if [ "$files_scanned" -eq 0 ]; then
fail "Log correlation: no debug.log files found in $WORKDIR/node*/"
fail "Log correlation: no debug.log files found in $WORKDIR/Node-*/"
return
fi
@@ -124,14 +152,54 @@ check_log_correlation() {
else
fail "Log-Tempo cross-check: trace_id=$sample_trace_id NOT found in Tempo"
fi
check_loki_ingestion "$sample_trace_id"
fi
}
# Verify the log line actually reached Loki, not just the local file.
#
# Without this the log-correlation check passes on a stack whose log mount is
# wrong or whose Loki exporter is broken, because reading the file and reading
# Tempo both still work. This is the only assertion that exercises the
# file_log -> Loki hop, so it is what makes the log pipeline tested rather than
# merely configured.
#
# Uses /query_range, not /query: Loki rejects a bare log selector on the instant
# endpoint with HTTP 400 and a text/plain body, so jq could never parse it.
# Bounds are unix nanoseconds, matching workload/validate_telemetry.py.
check_loki_ingestion() {
local trace_id="$1"
local lines=0
local start_ns end_ns
for attempt in $(seq 1 "$LOKI_INGEST_TIMEOUT"); do
end_ns=$(($(date +%s) * 1000000000))
# Look back over the whole run, not a fixed window: the entry carries
# the timestamp parsed out of the log line, not its ingestion time.
start_ns=$((end_ns - 86400000000000))
lines=$(curl -sfG "$LOKI/loki/api/v1/query_range" \
--data-urlencode "query={service_name=\"xrpld\"} |= \"$trace_id\"" \
--data-urlencode "start=$start_ns" \
--data-urlencode "end=$end_ns" \
--data-urlencode "limit=5" \
--data-urlencode "direction=backward" |
jq '[.data.result[].values | length] | add // 0' 2>/dev/null) || lines=0
if [ "${lines:-0}" -gt 0 ]; then
ok "Loki ingestion: trace_id=$trace_id found in Loki ($lines lines, attempt $attempt)"
return
fi
sleep 1
done
fail "Loki ingestion: trace_id=$trace_id never reached Loki after ${LOKI_INGEST_TIMEOUT}s"
}
cleanup() {
log "Cleaning up..."
# Kill xrpld nodes
for i in $(seq 1 "$NUM_NODES"); do
local pidfile="$WORKDIR/node$i/xrpld.pid"
local pidfile="$WORKDIR/Node-$i/xrpld.pid"
if [ -f "$pidfile" ]; then
kill "$(cat "$pidfile")" 2>/dev/null || true
rm -f "$pidfile"
@@ -172,7 +240,7 @@ log "All prerequisites met."
# ---------------------------------------------------------------------------
log "Cleaning previous run data..."
for i in $(seq 1 "$NUM_NODES"); do
pidfile="$WORKDIR/node$i/xrpld.pid"
pidfile="$WORKDIR/Node-$i/xrpld.pid"
if [ -f "$pidfile" ]; then
kill "$(cat "$pidfile")" 2>/dev/null || true
fi
@@ -215,7 +283,7 @@ for attempt in $(seq 1 30); do
# The OTLP HTTP endpoint returns 405 for GET (expects POST), which
# means it is listening. curl -sf would fail on 405, so we check
# the HTTP status code explicitly.
status=$(curl -so /dev/null -w '%{http_code}' http://localhost:4318/ 2>/dev/null || echo 000)
status=$(curl -so /dev/null -w '%{http_code}' --max-time "$CURL_MAX_TIME" http://localhost:4318/ 2>/dev/null || echo 000)
if [ "$status" != "000" ]; then
log "otel-collector ready (attempt $attempt, HTTP $status)."
break
@@ -228,7 +296,7 @@ done
log "Waiting for Tempo to be ready..."
for attempt in $(seq 1 30); do
if curl -sf "$TEMPO/ready" >/dev/null 2>&1; then
if curl -sf --max-time "$CURL_MAX_TIME" "$TEMPO/ready" >/dev/null 2>&1; then
log "Tempo ready (attempt $attempt)."
break
fi
@@ -238,6 +306,18 @@ for attempt in $(seq 1 30); do
sleep 1
done
log "Waiting for Loki to be ready..."
for attempt in $(seq 1 60); do
if curl -sf "$LOKI/ready" >/dev/null 2>&1; then
log "Loki ready (attempt $attempt)."
break
fi
if [ "$attempt" -eq 60 ]; then
die "Loki not ready after 60s"
fi
sleep 1
done
# ---------------------------------------------------------------------------
# Step 3: Generate validator keys
# ---------------------------------------------------------------------------
@@ -279,7 +359,7 @@ TEMP_PID=$!
log "Temporary xrpld started (PID $TEMP_PID), waiting for RPC..."
for attempt in $(seq 1 30); do
if curl -sf http://localhost:5099 -d '{"method":"server_info"}' >/dev/null 2>&1; then
if curl -sf --max-time "$CURL_MAX_TIME" http://localhost:5099 -d '{"method":"server_info"}' >/dev/null 2>&1; then
log "Temporary xrpld RPC ready (attempt $attempt)."
break
fi
@@ -294,7 +374,7 @@ declare -a SEEDS
declare -a PUBKEYS
for i in $(seq 1 "$NUM_NODES"); do
result=$(curl -sf http://localhost:5099 -d '{"method":"validation_create"}')
result=$(curl -sf --max-time "$CURL_MAX_TIME" http://localhost:5099 -d '{"method":"validation_create"}')
seed=$(echo "$result" | jq -r '.result.validation_seed')
pubkey=$(echo "$result" | jq -r '.result.validation_public_key')
if [ -z "$seed" ] || [ "$seed" = "null" ]; then
@@ -327,7 +407,7 @@ VALIDATORS_FILE="$WORKDIR/validators.txt"
# Create per-node configs
for i in $(seq 1 "$NUM_NODES"); do
NODE_DIR="$WORKDIR/node$i"
NODE_DIR="$WORKDIR/Node-$i"
mkdir -p "$NODE_DIR/nudb" "$NODE_DIR/db"
RPC_PORT=$((RPC_PORT_BASE + i - 1))
@@ -430,8 +510,12 @@ done
# ---------------------------------------------------------------------------
log "Starting $NUM_NODES xrpld nodes..."
# Lower bound for every Tempo search below. Only these nodes have a
# [telemetry] section, so nothing before this instant belongs to this run.
RUN_START=$(date +%s)
for i in $(seq 1 "$NUM_NODES"); do
NODE_DIR="$WORKDIR/node$i"
NODE_DIR="$WORKDIR/Node-$i"
"$XRPLD" --conf "$NODE_DIR/xrpld.cfg" --start >"$NODE_DIR/stdout.log" 2>&1 &
echo $! >"$NODE_DIR/xrpld.pid"
log " Node $i started (PID $(cat "$NODE_DIR/xrpld.pid"))"
@@ -461,7 +545,7 @@ while [ "$nodes_ready" -lt "$NUM_NODES" ]; do
nodes_ready=0
for i in $(seq 1 "$NUM_NODES"); do
RPC_PORT=$((RPC_PORT_BASE + i - 1))
state=$(curl -sf "http://localhost:$RPC_PORT" \
state=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT" \
-d '{"method":"server_info"}' 2>/dev/null |
jq -r '.result.info.server_state' 2>/dev/null || echo "unreachable")
if [ "$state" = "proposing" ]; then
@@ -489,7 +573,7 @@ fi
# ---------------------------------------------------------------------------
log "Waiting for first validated ledger..."
for attempt in $(seq 1 60); do
val_seq=$(curl -sf "http://localhost:$RPC_PORT_BASE" \
val_seq=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d '{"method":"server_info"}' 2>/dev/null |
jq -r '.result.info.validated_ledger.seq // 0' 2>/dev/null || echo 0)
if [ "$val_seq" -gt 2 ] 2>/dev/null; then
@@ -507,11 +591,11 @@ done
# ---------------------------------------------------------------------------
log "Exercising RPC spans..."
curl -sf "http://localhost:$RPC_PORT_BASE" \
curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d '{"method":"server_info"}' >/dev/null
curl -sf "http://localhost:$RPC_PORT_BASE" \
curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d '{"method":"server_state"}' >/dev/null
curl -sf "http://localhost:$RPC_PORT_BASE" \
curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d '{"method":"ledger","params":[{"ledger_index":"current"}]}' >/dev/null
log "RPC commands sent. Waiting 5s for batch export..."
@@ -526,7 +610,7 @@ log "Submitting Payment transaction..."
log " Generating destination wallet..."
# Guarded: under set -e an unguarded curl failure would abort the whole
# script, so the fallback below could never run.
wallet_result=$(curl -sf "http://localhost:$RPC_PORT_BASE" \
wallet_result=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d '{"method":"wallet_propose"}') || wallet_result=""
DEST_ACCOUNT=$(echo "$wallet_result" | jq -r '.result.account_id' 2>/dev/null || echo "")
if [ -z "$DEST_ACCOUNT" ] || [ "$DEST_ACCOUNT" = "null" ]; then
@@ -536,13 +620,13 @@ fi
log " Destination: $DEST_ACCOUNT"
# Get genesis account info
acct_result=$(curl -sf "http://localhost:$RPC_PORT_BASE" \
acct_result=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d "{\"method\":\"account_info\",\"params\":[{\"account\":\"$GENESIS_ACCOUNT\"}]}") || acct_result=""
seq_num=$(echo "$acct_result" | jq -r '.result.account_data.Sequence' 2>/dev/null || echo "unknown")
log " Genesis account sequence: $seq_num"
# Submit payment
submit_result=$(curl -sf "http://localhost:$RPC_PORT_BASE" \
submit_result=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d "{\"method\":\"submit\",\"params\":[{\"secret\":\"$GENESIS_SEED\",\"tx_json\":{\"TransactionType\":\"Payment\",\"Account\":\"$GENESIS_ACCOUNT\",\"Destination\":\"$DEST_ACCOUNT\",\"Amount\":\"10000000\"}}]}") || submit_result=""
engine_result=$(echo "$submit_result" | jq -r '.result.engine_result' 2>/dev/null || echo "unknown")
@@ -564,7 +648,7 @@ sleep 15
log "Verifying spans in Tempo..."
# Check service registration
services=$(curl -sf "$TEMPO/api/v2/search/tag/resource.service.name/values" |
services=$(curl -sf --max-time "$CURL_MAX_TIME" "$TEMPO/api/v2/search/tag/resource.service.name/values" |
jq -r '.tagValues[].value' 2>/dev/null || echo "")
if echo "$services" | grep -q "xrpld"; then
ok "Service 'xrpld' registered in Tempo"
@@ -622,7 +706,7 @@ sleep 20
# Names come from the spanmetrics connector's `namespace: "span"` in
# otel-collector-config.yaml. Without that namespace the connector emits
# traces_span_metrics_*, so these queries must move whenever it changes.
calls_count=$(curl -sf "$PROM/api/v1/query?query=span_calls_total" |
calls_count=$(curl -sf --max-time "$CURL_MAX_TIME" "$PROM/api/v1/query?query=span_calls_total" |
jq '.data.result | length' 2>/dev/null || echo 0)
if [ "$calls_count" -gt 0 ]; then
ok "Prometheus: span_calls_total ($calls_count series)"
@@ -630,7 +714,7 @@ else
fail "Prometheus: span_calls_total (0 series)"
fi
duration_count=$(curl -sf "$PROM/api/v1/query?query=span_duration_milliseconds_count" |
duration_count=$(curl -sf --max-time "$CURL_MAX_TIME" "$PROM/api/v1/query?query=span_duration_milliseconds_count" |
jq '.data.result | length' 2>/dev/null || echo 0)
if [ "$duration_count" -gt 0 ]; then
ok "Prometheus: duration histogram ($duration_count series)"
@@ -639,7 +723,7 @@ else
fi
# Check Grafana
if curl -sf http://localhost:3000/api/health >/dev/null 2>&1; then
if curl -sf --max-time "$CURL_MAX_TIME" http://localhost:3000/api/health >/dev/null 2>&1; then
ok "Grafana: healthy at localhost:3000"
else
fail "Grafana: not reachable at localhost:3000"
@@ -656,7 +740,7 @@ sleep 20
check_otel_metric() {
local metric_name="$1"
local result
result=$(curl -sf "$PROM/api/v1/query?query=$metric_name" |
result=$(curl -sf --max-time "$CURL_MAX_TIME" "$PROM/api/v1/query?query=$metric_name" |
jq '.data.result | length' 2>/dev/null || echo 0)
if [ "$result" -gt 0 ]; then
ok "OTel: $metric_name ($result series)"
@@ -793,7 +877,7 @@ echo " xrpld nodes (6) are running:"
for i in $(seq 1 "$NUM_NODES"); do
RPC_PORT=$((RPC_PORT_BASE + i - 1))
PEER_PORT=$((PEER_PORT_BASE + i - 1))
echo " Node $i: RPC=localhost:$RPC_PORT Peer=:$PEER_PORT PID=$(cat "$WORKDIR/node$i/xrpld.pid" 2>/dev/null || echo 'unknown')"
echo " Node $i: RPC=localhost:$RPC_PORT Peer=:$PEER_PORT PID=$(cat "$WORKDIR/Node-$i/xrpld.pid" 2>/dev/null || echo 'unknown')"
done
echo ""
echo " To tear down:"

View File

@@ -38,9 +38,14 @@ receivers:
endpoint: 0.0.0.0:4317
http:
endpoint: 0.0.0.0:4318
filelog:
file_log:
include:
- /var/log/xrpld/*/debug.log
# Needed to recover which node a line came from. The subdirectory name is
# the only per-node signal in the log stream: Logs::format() writes
# trace_id and span_id but no node identity. Emitters name the directory
# after their own service_instance_id so the two agree.
include_file_path: true
operators:
- type: regex_parser
regex: '^(?P<timestamp>\S+\s+\S+)\s+\S+\s+(?:(?P<partition>\S+):)?(?P<severity>\S+)\s+(?:trace_id=(?P<trace_id>[a-f0-9]+)\s+span_id=(?P<span_id>[a-f0-9]+)\s+)?(?P<message>.*)$'
@@ -48,6 +53,26 @@ receivers:
parse_from: attributes.timestamp
layout: "%Y-%b-%d %H:%M:%S.%f"
location: UTC
# Lift the per-node directory out of the file path and onto the
# RESOURCE. include_file_path alone is not enough: it produces a log
# RECORD attribute, and on OTLP ingest Loki promotes only an allow-list
# of RESOURCE attributes to indexed stream labels. A record attribute
# becomes structured metadata, which cannot be used in a {...} selector.
# service.instance.id is on that allow-list and arrives as the LogQL
# label service_instance_id, which is the label the dashboards filter on.
# Dotted keys need bracket syntax; dot notation would be read as a
# nested traversal and match nothing.
- type: regex_parser
parse_from: attributes["log.file.path"]
parse_to: attributes
regex: "^/var/log/xrpld/(?P<node_dir>[^/]+)/"
- type: move
from: attributes.node_dir
to: resource["service.instance.id"]
# Drop the raw path once the node name is on the resource. Keeping it
# would add a structured-metadata field to every line for no benefit.
- type: remove
field: attributes["log.file.path"]
processors:
batch:
@@ -246,7 +271,7 @@ exporters:
endpoint: tempo:4317
tls:
insecure: true
otlphttp/loki:
otlp_http/loki:
endpoint: http://loki:3100/otlp
prometheus:
endpoint: 0.0.0.0:8889
@@ -259,7 +284,7 @@ exporters:
# Single OTLP/HTTP exporter to Grafana Cloud. The gateway fans the three
# signals out to hosted Tempo (traces), Mimir/Prometheus (metrics), and
# Loki (logs). Retry + queue guard against transient gateway errors.
otlphttp/grafanacloud:
otlp_http/grafanacloud:
endpoint: ${env:GRAFANA_CLOUD_OTLP_ENDPOINT}
auth:
authenticator: basicauth/grafanacloud
@@ -272,7 +297,7 @@ service:
extensions: [health_check, basicauth/grafanacloud]
pipelines:
# Each pipeline keeps its local exporter(s) AND adds Grafana Cloud.
# For cloud-only, drop debug/otlp/tempo, prometheus, and otlphttp/loki
# For cloud-only, drop debug/otlp/tempo, prometheus, and otlp_http/loki
# from the respective exporter lists.
# 100% of spans feed the spanmetrics connector so span-derived RED
# metrics stay exact. No tail sampling on this branch.
@@ -285,7 +310,7 @@ service:
traces/store:
receivers: [otlp]
processors: [tail_sampling, resource/tier, resource/stripsdk, batch]
exporters: [otlp/tempo, otlphttp/grafanacloud]
exporters: [otlp/tempo, otlp_http/grafanacloud]
# The local Prometheus scrape promotes tier/instance resource attrs to
# labels via resource_to_telemetry_conversion; Grafana Cloud (OTLP) does
# not, so it runs a separate pipeline that copies them onto datapoint
@@ -299,8 +324,8 @@ service:
receivers: [otlp, spanmetrics]
processors:
[resource/tier, resource/stripsdk, transform/cloudlabels, batch]
exporters: [otlphttp/grafanacloud]
exporters: [otlp_http/grafanacloud]
logs:
receivers: [filelog]
receivers: [file_log]
processors: [resource/logs, resource/tier, resource/stripsdk, batch]
exporters: [otlphttp/loki, otlphttp/grafanacloud]
exporters: [otlp_http/loki, otlp_http/grafanacloud]

View File

@@ -3,7 +3,7 @@
# Pipelines:
# traces: OTLP receiver -> batch processor -> debug + Tempo + spanmetrics
# metrics: OTLP receiver + spanmetrics connector -> Prometheus exporter
# logs: filelog receiver -> batch processor -> otlphttp/Loki
# logs: file_log receiver -> batch processor -> otlp_http/Loki
#
# xrpld sends traces via OTLP/HTTP to port 4318. The collector batches
# them, forwards to Tempo, and derives RED metrics via the spanmetrics
@@ -14,16 +14,12 @@
# metrics pipelines. Metrics are exported to Prometheus alongside
# span-derived metrics.
#
# The filelog receiver tails xrpld's debug.log files under
# The file_log receiver tails xrpld's debug.log files under
# /var/log/xrpld/ (mounted from the host). A regex_parser operator
# extracts timestamp, partition, severity, and optional trace_id/span_id
# fields injected by Logs::format(). Parsed logs are exported to Grafana
# Loki for log-trace correlation.
extensions:
health_check:
endpoint: 0.0.0.0:13133
receivers:
otlp:
protocols:
@@ -35,8 +31,13 @@ receivers:
# correlation. Extracts structured fields (timestamp, partition, severity,
# trace_id, span_id, message) via regex. The trace_id and span_id are
# optional — only present when the log was emitted within an active span.
filelog:
file_log:
include: [/var/log/xrpld/*/debug.log]
# Needed to recover which node a line came from. The subdirectory name is
# the only per-node signal in the log stream: Logs::format() writes
# trace_id and span_id but no node identity. Emitters name the directory
# after their own service_instance_id so the two agree.
include_file_path: true
# Read each file from the start. The upstream default is `end`, which
# skips everything written before the receiver's first poll — so any log
# line a node emitted before the collector got to it would be lost, and
@@ -49,16 +50,36 @@ receivers:
start_at: beginning
operators:
# Log format emitted by Logs::format() is:
# YYYY-Mmm-DD HH:MM:SS.ffffff UTC <partition>:<severity> [trace_id=... span_id=...] <message>
# YYYY-Mmm-DD HH:MM:SS.fffffffff UTC <partition>:<severity> [trace_id=... span_id=...] <message>
# The `partition:` prefix is omitted when partition is empty, so the
# capture group is non-capturing optional. Fractional seconds up to 6
# digits are parsed via the `%f` strptime directive.
# capture group is non-capturing optional. The node emits nanosecond
# precision (9 digits); `%f` accepts any number of fractional digits.
- type: regex_parser
regex: '^(?P<timestamp>\S+\s+\S+)\s+\S+\s+(?:(?P<partition>\S+):)?(?P<severity>\S+)\s+(?:trace_id=(?P<trace_id>[a-f0-9]+)\s+span_id=(?P<span_id>[a-f0-9]+)\s+)?(?P<message>.*)$'
timestamp:
parse_from: attributes.timestamp
layout: "%Y-%b-%d %H:%M:%S.%f"
location: UTC
# Lift the per-node directory out of the file path and onto the
# RESOURCE. include_file_path alone is not enough: it produces a log
# RECORD attribute, and on OTLP ingest Loki promotes only an allow-list
# of RESOURCE attributes to indexed stream labels. A record attribute
# becomes structured metadata, which cannot be used in a {...} selector.
# service.instance.id is on that allow-list and arrives as the LogQL
# label service_instance_id, which is the label the dashboards filter on.
# Dotted keys need bracket syntax; dot notation would be read as a
# nested traversal and match nothing.
- type: regex_parser
parse_from: attributes["log.file.path"]
parse_to: attributes
regex: "^/var/log/xrpld/(?P<node_dir>[^/]+)/"
- type: move
from: attributes.node_dir
to: resource["service.instance.id"]
# Drop the raw path once the node name is on the resource. Keeping it
# would add a structured-metadata field to every line for no benefit.
- type: remove
field: attributes["log.file.path"]
processors:
batch:
@@ -302,7 +323,7 @@ exporters:
# Export logs to Grafana Loki via OTLP/HTTP. Loki 3.x supports
# native OTLP ingestion on its /otlp endpoint, replacing the removed
# loki exporter (dropped in otel-collector-contrib v0.147.0).
otlphttp/loki:
otlp_http/loki:
endpoint: http://loki:3100/otlp
prometheus:
endpoint: 0.0.0.0:8889
@@ -313,6 +334,10 @@ exporters:
resource_to_telemetry_conversion:
enabled: true
extensions:
health_check:
endpoint: 0.0.0.0:13133
service:
extensions: [health_check]
pipelines:
@@ -322,11 +347,14 @@ service:
exporters: [debug, otlp/tempo, spanmetrics]
metrics:
receivers: [otlp, spanmetrics]
# batch keeps the OTLP metric path from exporting one request per
# instrument. It delays a sample by at most the batch timeout, which
# is well under the Prometheus scrape interval.
processors: [resource/tier, resource/stripsdk, batch]
exporters: [prometheus]
# Log pipeline ingests xrpld debug.log via filelog receiver,
# Log pipeline ingests xrpld debug.log via file_log receiver,
# batches entries, and exports to Loki for log-trace correlation.
logs:
receivers: [filelog]
receivers: [file_log]
processors: [resource/logs, resource/tier, resource/stripsdk, batch]
exporters: [otlphttp/loki]
exporters: [otlp_http/loki]

View File

@@ -1,4 +1,4 @@
# Collector overlay that persists filelog read offsets. Applied ONLY by the
# Collector overlay that persists file_log read offsets. Applied ONLY by the
# developer stack (docker/telemetry/docker-compose.yml), as a second --config
# after otel-collector-config.yaml; the collector deep-merges the two.
#
@@ -15,14 +15,14 @@
# instead of re-reading debug.log from the top.
extensions:
file_storage/filelog:
file_storage/file_log:
directory: /var/lib/otelcol/file_storage
create_directory: true
receivers:
filelog:
storage: file_storage/filelog
file_log:
storage: file_storage/file_log
# Lists are replaced rather than merged, so this must repeat the base entry.
service:
extensions: [health_check, file_storage/filelog]
extensions: [health_check, file_storage/file_log]

View File

@@ -213,9 +213,9 @@ python3 tx_submitter.py --endpoint ws://localhost:6006 \
Automated validation that all expected telemetry data exists. Every metric in `expected_metrics.json` is required — if it doesn't fire, the validation fails. Spans are required unless the entry carries `"optional": true`.
- **Span validation**: All span types from `expected_spans.json` with required attributes and parent-child hierarchies. Entries marked `"optional": true` only fire under traffic the harness may not produce (HTTP/JSON-RPC client, gRPC client, path-finding RPC — see [Pathfinding is not exercised](#pathfinding-is-not-exercised) — missing-ledger fetch, mode transitions); their absence is recorded as a passing skip, not a failure.
- **Span validation**: All span types from `expected_spans.json` with required attributes and parent-child hierarchies. The 16 entries marked `"optional": true` are the ones the harness cannot guarantee: no gRPC client, no path-finding RPC (see [Pathfinding is not exercised](#pathfinding-is-not-exercised)), no missing-ledger fetch, no mode transition, no WebSocket handshake, and the six `txq.*` spans only when fee escalation puts something in the queue. `rpc.http_request` and `rpc.process` are marked optional because the generator drives WebSocket rather than HTTP. Their absence is recorded as a passing skip, not a failure.
- **Metric validation**: All metrics from `expected_metrics.json` — SpanMetrics, `beast::insight` gauges/counters/histograms, `MetricsRegistry` OTLP metrics. Every listed metric must have > 0 series. Uses the Prometheus `/api/v1/series` endpoint (not instant queries), polled until the metric appears or the poll window elapses, so a late-populating or quiet series is not a false negative.
- **Log-trace correlation**: trace_id/span_id in Loki logs (requires Loki). The two checks are `log.trace_id_present` and `log.trace_id_cross_reference`, and they exist only when `--skip-loki` is **not** passed — `run_validation()` builds them inside an `if not skip_loki` branch, so with the flag they are absent from the report rather than reported as skipped. **CI always passes `--skip-loki`, so these two are never exercised there** — see [CI Integration](#ci-integration).
- **Log-trace correlation**: trace_id/span_id in Loki logs (requires Loki). The two checks are `log.trace_id_present` and `log.trace_id_cross_reference`, and they exist only when `--skip-loki` is **not** passed — `run_validation()` builds them inside an `if not skip_loki` branch, so with the flag they are absent from the report rather than reported as skipped. The workflow passes no `--skip-loki`, so both checks are built and gated on every CI run — see [CI Integration](#ci-integration).
- **Dashboard validation**: Every dashboard uid listed under `grafana_dashboards.uids` in `expected_metrics.json` loads with panels. That list currently covers **all 16** dashboards provisioned in `docker/telemetry/grafana/dashboards/`. Note the scope of this check: it asks the Grafana API whether the dashboard exists and returns a panel count — it does **not** run the panels' queries, so a dashboard can pass here while individual panels render empty.
```bash
@@ -359,7 +359,7 @@ from the running nodes, and writes them as JSON. `benchmark.sh` calls it once
per leg; it is rarely run by hand.
```bash
./collect_system_metrics.sh 5020,5021,5022 300 /tmp/metrics.json
./collect_system_metrics.sh 5020,5021,5022 300 /tmp/metrics.json [pids_csv]
```
Processes are selected by matching `argv[0]`'s basename against the daemon
@@ -370,8 +370,12 @@ string, are not sampled — including them diluted the CPU average and
attributed a foreign process's RSS to the node. `ps -C xrpld` is not usable
for this: xrpld renames itself, so its `comm` is `xrpld-main`.
Selection covers the whole host, so a second xrpld from another checkout is
sampled as well. Benchmark on a machine running one cluster only.
A fourth argument narrows selection to an explicit pid list, and `benchmark.sh`
always passes its own nodes' pids. It has to: `run-full-validation.sh` leaves its
five validation nodes running while the benchmark's three start, so host-wide
selection would average eight processes in both arms and report the largest of
them as the RSS peak. Without the argument the scope is still the whole host, so
a second xrpld from another checkout is sampled as well.
The output carries a `metrics_complete` flag. It is `false` when any
measurement source came back empty — no matching process, no successful RPC
@@ -433,7 +437,7 @@ Categories:
The validation runs as a GitHub Actions workflow (`.github/workflows/telemetry-validation.yml`):
- Triggered manually (`workflow_dispatch`) or on pushes to telemetry branches. There is no cron schedule.
- Triggered manually (`workflow_dispatch`), or by any push touching the workflow's `paths` globs. There is no branch filter and no cron schedule.
- Builds xrpld, starts the full stack, runs load, validates
- Uploads reports as artifacts (and node logs when validation did not succeed)
- Writes the validation summary and the regression-gate summary to the workflow **Step Summary** (`$GITHUB_STEP_SUMMARY`). It does **not** comment on the PR — the workflow declares no `permissions:` block and calls no GitHub API, so read the summary on the run page.
@@ -446,10 +450,10 @@ them again — load shape comes entirely from `--profile` and
### Log-trace correlation in CI
The workflow no longer passes `--skip-loki`, so `log.trace_id_present` and
The workflow passes no `--skip-loki`, so `log.trace_id_present` and
`log.trace_id_cross_reference` are constructed and gated on every CI run. A green
`Telemetry Validation` is now evidence that log lines carry trace context and
that a logged trace id resolves to an exported trace. `integration-test.sh` has
`Telemetry Validation` is evidence that log lines carry trace context and that a
logged trace id resolves to an exported trace. `integration-test.sh` has
its own `check_log_correlation()`, but no workflow runs that script.
Correlation depends on four independent legs, and a failed check on its own names
@@ -515,8 +519,8 @@ Re-run it after any change to log formatting, span activation, the collector's
**Why.** Pathfinding is disabled on every node this harness starts, so those calls could only ever fail:
- `src/xrpld/core/detail/Config.cpp:725-726` sets `pathSearchMax = 0` whenever a `[validation_seed]` or `[validator_token]` section is present — "by default, validators don't have pathfinding enabled".
- `run-full-validation.sh:308` writes `[validation_seed]` into every generated node cfg, and that script carries no `[path_search]`, `[path_search_fast]` or `[path_search_max]` section to put the default back.
- `src/xrpld/rpc/handlers/orderbook/RipplePathFind.cpp:48-49` therefore returns `rpcNOT_SUPPORTED`; `PathFind.cpp:39` does the same for `path_find`.
- `run-full-validation.sh` writes `[validation_seed]` into every generated node cfg, and that script carries no `[path_search]`, `[path_search_fast]` or `[path_search_max]` section to put the default back.
- `src/xrpld/rpc/handlers/orderbook/RipplePathFind.cpp:59-60` therefore returns `RpcNotSupported`; `PathFind.cpp:50-51` does the same for `path_find`.
**Why the refusals would not be harmless.** They are not silent. `pathfind.request` is opened at `RipplePathFind.cpp:35`, **above** that guard, so a refused call still exports a span, and the enclosing `rpc.command.ripple_path_find` span carries `rpc_status=error`. At a 3% weight that is a steady ~3% error floor in `span_calls_total{status_code="STATUS_CODE_ERROR"}` — a figure that reads as an xrpld error rate and is not one. **An error-rate threshold derived from a harness run that does issue path-finding load is measuring the harness, not xrpld.**

View File

@@ -142,7 +142,7 @@ needs a finer low-end ladder **as well as** a spread-aware baseline.
`0.005` / `0.0095` / `0.0099` ms, which is `0.5` / `0.95` / `0.99 × 0.01` ms — the ladder's first
edge times the quantile, the signature of every sample landing in the first bucket. Those numbers
are interpolation arithmetic on the bucket floor, not latencies. It is physically plausible:
[`LedgerMaster.cpp:463`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L463) wraps an
[`LedgerMaster.cpp:470`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L470) wraps an
in-memory `ledgerHistory_.insert`, which completes in single-digit microseconds.
While all the mass stays under 10 us the reported quantile cannot move materially, so **no
@@ -180,7 +180,7 @@ while the other quantile stayed well inside its bound in the same run — the si
not of a regression.
The mechanism is arrival timing, not slow code. The span opens only once a quorum-completing
validation arrives ([`LedgerMaster.cpp:987`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L987),
validation arrives ([`LedgerMaster.cpp:1003`](../../../../src/xrpld/app/ledger/detail/LedgerMaster.cpp#L1003),
inside `checkAccept`, past the `tvc < minVal` early return) and wraps the promotion work that
follows — `setValidated`, `setFull`, `setValidLedger`, `pendSaveValidated`. Its duration therefore
tracks when peer validations arrive in a 5-node cluster and what promotion then schedules, so a
@@ -323,7 +323,7 @@ each node's `[rpc_startup]` stanza. Logging is **synchronous**, and several of t
spans contain log statements, so the configured level is part of the measurement:
- `ledger.build` contains [`BuildLedger.cpp:81`](../../../../src/xrpld/app/ledger/detail/BuildLedger.cpp#L81) (debug).
- `consensus.accept` contains [RCLConsensus.cpp:655/663/686](../../../../src/xrpld/app/consensus/RCLConsensus.cpp#L663) (debug) — `:663` logs **once per transaction** in the canonical set.
- `consensus.accept` contains [RCLConsensus.cpp:683/687/698/715](../../../../src/xrpld/app/consensus/RCLConsensus.cpp#L715) (debug) — `:715` logs **once per transaction** in the canonical set.
- `tx.apply` and the other `spans.names` entries in [`../regression-metrics.json`](../regression-metrics.json) are affected the same way.
Raising the level admits more of those statements and inflates the p50/p95/p99 of the very
@@ -415,7 +415,7 @@ the first produces metrics that look gated in the report but are not.
`rpc.process` is deliberately absent from the `spans.names` list in
`regression-metrics.json`, so no `span.rpc.process.*` key appears in this
baseline. The span is created only in `ServerHandler::processRequest()`
(`src/xrpld/rpc/detail/ServerHandler.cpp:705`), which is reached only from the
(`src/xrpld/rpc/detail/ServerHandler.cpp:718`), which is reached only from the
HTTP/JSON-RPC session path. The harness load generator is WebSocket-only and
that path never calls `processRequest`, so the span is never emitted under any
workload profile here — `expected_spans.json` marks it `"optional": true` for

View File

@@ -1,11 +1,18 @@
#!/usr/bin/env bash
# benchmark.sh — Performance benchmark for rippled telemetry overhead.
#
# Runs two identical workloads against a rippled cluster:
# Runs the same client workload twice against a rippled cluster:
# 1. Baseline: telemetry disabled ([telemetry] enabled=0)
# 2. Telemetry: full telemetry enabled (traces + StatsD + all categories)
# 2. Telemetry: full telemetry enabled (traces + native OTel metrics)
#
# Compares CPU, memory, RPC latency, TPS, and consensus round time.
# Both arms drive rpc_load_generator.py and tx_submitter.py at one fixed rate for
# the whole sample window, so the delta is attributable to telemetry rather than
# to a difference in offered load. The workload is not optional: with only the
# sampler's own ~1 request/sec of server_info, the tx.*, txq.*, transactor-stage
# and non-server_info rpc.command.* spans are never entered, and those are where
# a per-operation span cost shows up. A pass on an idle cluster says nothing.
#
# Compares CPU, memory, RPC latency, TPS, and mean consensus round time.
# Outputs a Markdown table with pass/fail against configured thresholds.
#
# Usage:
@@ -76,6 +83,30 @@ WORKDIR="/tmp/xrpld-benchmark"
RESULTS_DIR="$SCRIPT_DIR/benchmark-results"
RPC_PORT_BASE=5020
PEER_PORT_BASE=51250
# Above run-full-validation.sh's 6006.. so both harnesses can share a box.
WS_PORT_BASE=6020
# Head start the generators get before the sampler opens its window.
# tx_submitter.py creates and funds eight accounts from genesis and then waits
# for those payments to validate, so without a lead the first seconds of every
# window carry no transaction load. Identical in both arms, so it cancels out.
WORKLOAD_LEAD_SEC=20
# One flat offered rate, not a workload-profiles.json profile: both arms must
# issue the same work for the delta to mean anything, and a profile's phase
# shaping only adds variance. Payment-only for the same reason -- a rejected
# transaction costs a different amount of work than an applied one.
WORKLOAD_RPC_RATE="${BENCH_RPC_RATE:-30}"
WORKLOAD_TX_TPS="${BENCH_TX_TPS:-3}"
# This arm's generator pids, reaped by wait_workload and killed by the trap.
WORKLOAD_PIDS=()
# Hard ceiling on every RPC probe below. curl applies no overall timeout of its
# own, so a node that accepts the connection and then stops answering parks the
# poll loop for the rest of the run. The loops here count attempts, not seconds,
# so without this their stated timeouts are not bounds at all.
CURL_MAX_TIME="${CURL_MAX_TIME:-5}"
# ---------------------------------------------------------------------------
# Argument parsing
@@ -121,8 +152,12 @@ done
command -v jq >/dev/null 2>&1 || cannot_measure "jq not found"
command -v bc >/dev/null 2>&1 || cannot_measure "bc not found"
command -v curl >/dev/null 2>&1 || cannot_measure "curl not found"
command -v python3 >/dev/null 2>&1 ||
cannot_measure "python3 not found (the load generators need it)"
python3 -c 'import websockets' 2>/dev/null ||
cannot_measure "python3 'websockets' package not found -- pip install -r $SCRIPT_DIR/requirements.txt"
mkdir -p "$RESULTS_DIR"
mkdir -p "$RESULTS_DIR" || cannot_measure "Could not create the results directory $RESULTS_DIR"
TIMESTAMP=$(date +%Y%m%d_%H%M%S)
# ---------------------------------------------------------------------------
@@ -139,11 +174,14 @@ start_cluster() {
log "Starting $NUM_NODES-node cluster ($label, telemetry=$telemetry_enabled)..."
rm -rf "$WORKDIR"
mkdir -p "$WORKDIR"
rm -rf "$WORKDIR" || cannot_measure "Could not clear the workdir $WORKDIR"
mkdir -p "$WORKDIR" || cannot_measure "Could not create the workdir $WORKDIR"
# Generate keys using first node.
bash "$SCRIPT_DIR/generate-validator-keys.sh" "$XRPLD" "$NUM_NODES" "$WORKDIR"
# Generate keys using a temporary standalone node. The helper fails through
# its own die(), which exits 1 -- the code this script reserves for a
# measured breach. Remap it, or a keygen failure reads as "too expensive".
bash "$SCRIPT_DIR/generate-validator-keys.sh" "$XRPLD" "$NUM_NODES" "$WORKDIR" ||
cannot_measure "generate-validator-keys.sh failed; no keys for the $NUM_NODES-node cluster"
# Set before the spawn loop so a failure part-way through it still gets
# cleaned up by the EXIT trap.
@@ -151,15 +189,28 @@ start_cluster() {
# Build per-node configs.
for i in $(seq 1 "$NUM_NODES"); do
local node_dir="$WORKDIR/node$i"
mkdir -p "$node_dir/nudb" "$node_dir/db"
local node_dir="$WORKDIR/bench-node-$i"
mkdir -p "$node_dir/nudb" "$node_dir/db" ||
cannot_measure "Could not create node$i directories under $node_dir"
local rpc_port
rpc_port=$((RPC_PORT_BASE + i - 1))
local peer_port
peer_port=$((PEER_PORT_BASE + i - 1))
local ws_port
ws_port=$((WS_PORT_BASE + i - 1))
# Split from the declaration on purpose: `local seed=$(...)` reports
# local's status, not jq's, so the guard below would never fire.
local seed
seed=$(jq -r ".[$((i - 1))].seed" "$WORKDIR/validator-keys.json")
seed=$(jq -r ".[$((i - 1))].seed" "$WORKDIR/validator-keys.json") ||
cannot_measure "Could not read node$i's seed from $WORKDIR/validator-keys.json"
# jq prints "null" and exits 0 when the array is short, so the exit
# status alone does not catch a truncated key file.
case "$seed" in
"" | null)
cannot_measure "node$i has no seed in $WORKDIR/validator-keys.json"
;;
esac
# Build ips_fixed list.
local ips_fixed=""
@@ -200,9 +251,13 @@ endpoint=http://localhost:4318/v1/metrics"
enabled=0"
fi
# No `|| cannot_measure` here: a guard after `<<EOCFG` is read as the
# heredoc's first line, so it lands in the config and never runs. The
# mkdir above already covers the only realistic failure.
cat >"$node_dir/xrpld.cfg" <<EOCFG
[server]
port_rpc
port_ws
port_peer
[port_rpc]
@@ -211,6 +266,15 @@ ip = 127.0.0.1
admin = 127.0.0.1
protocol = http
# The generators speak WebSocket only. admin is required rather than cosmetic:
# tx_submitter.py calls wallet_propose and submits with "secret". Declared in
# BOTH arms, so the listener itself is not part of the measured delta.
[port_ws]
port = $ws_port
ip = 127.0.0.1
admin = 127.0.0.1
protocol = ws
[port_peer]
port = $peer_port
ip = 0.0.0.0
@@ -268,7 +332,7 @@ EOCFG
local port
port=$((RPC_PORT_BASE + i - 1))
local state
state=$(curl -sf "http://localhost:$port" \
state=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$port" \
-d '{"method":"server_info"}' 2>/dev/null |
jq -r '.result.info.server_state' 2>/dev/null || echo "")
if [ "$state" = "proposing" ]; then
@@ -297,7 +361,7 @@ stop_cluster() {
log "Stopping cluster..."
for i in $(seq 1 "$NUM_NODES"); do
local pidfile="$WORKDIR/node$i/xrpld.pid"
local pidfile="$WORKDIR/bench-node-$i/xrpld.pid"
if [ -f "$pidfile" ]; then
kill "$(cat "$pidfile")" 2>/dev/null || true
fi
@@ -324,7 +388,7 @@ stop_cluster() {
# after argument parsing so the handler name always resolves. Without it, any
# failure between start_cluster and stop_cluster leaks the xrpld children
# along with their RPC ports (5020+) and peer ports (51250+).
trap stop_cluster EXIT
trap 'stop_workload; stop_cluster' EXIT
# Build RPC ports CSV string.
rpc_ports_csv() {
@@ -342,13 +406,101 @@ rpc_ports_csv() {
# source came back empty (3). An all-zero or partial sample set clears every
# threshold, so an incomplete leg aborts with "cannot measure" instead of being
# compared and passed.
# Echoes one ws:// endpoint per node, space separated.
ws_endpoints() {
local i out=""
for i in $(seq 1 "$NUM_NODES"); do
out="$out ws://localhost:$((WS_PORT_BASE + i - 1))"
done
printf '%s' "${out# }"
}
# This cluster's xrpld pids, comma separated, for the sampler's process filter.
# Without it the sampler matches every xrpld on the host: run-full-validation.sh
# leaves five validation nodes running while these three start, so both arms
# average eight processes and the delta is diluted away.
node_pids_csv() {
local i out="" pid
for i in $(seq 1 "$NUM_NODES"); do
pid=$(cat "$WORKDIR/bench-node-$i/xrpld.pid" 2>/dev/null) || continue
[ -n "$pid" ] && out="$out,$pid"
done
printf '%s' "${out#,}"
}
# Starts this arm's generators, then waits out the funding lead so the sampler's
# whole window is under load. Logs and JSON summaries go to RESULTS_DIR, not
# WORKDIR: the next arm's start_cluster rm -rf's WORKDIR.
start_workload() {
local label="$1"
local gen_duration=$((DURATION + WORKLOAD_LEAD_SEC))
local logdir="$RESULTS_DIR/workload-${TIMESTAMP}"
mkdir -p "$logdir" || cannot_measure "Could not create the workload log dir $logdir"
log "Starting workload ($label): ${WORKLOAD_RPC_RATE} rpc/s + ${WORKLOAD_TX_TPS} tps for ${gen_duration}s..."
# shellcheck disable=SC2046 # --endpoints takes a list; splitting is intended
python3 "$SCRIPT_DIR/rpc_load_generator.py" \
--endpoints $(ws_endpoints) \
--rate "$WORKLOAD_RPC_RATE" \
--duration "$gen_duration" \
--output "$logdir/$label-rpc.json" \
>"$logdir/$label-rpc.log" 2>&1 &
WORKLOAD_PIDS+=("$!")
python3 "$SCRIPT_DIR/tx_submitter.py" \
--endpoint "ws://localhost:$WS_PORT_BASE" \
--tps "$WORKLOAD_TX_TPS" \
--duration "$gen_duration" \
--weights '{"Payment": 100}' \
--output "$logdir/$label-tx.json" \
>"$logdir/$label-tx.log" 2>&1 &
WORKLOAD_PIDS+=("$!")
sleep "$WORKLOAD_LEAD_SEC"
}
# Reaps this arm's generators. A non-zero generator means the arms did not do
# the same work, so nothing is attributable: "cannot measure", never "too slow".
wait_workload() {
local label="$1"
local pid status=0
for pid in ${WORKLOAD_PIDS[@]+"${WORKLOAD_PIDS[@]}"}; do
wait "$pid" || status=$?
done
WORKLOAD_PIDS=()
[ "$status" -eq 0 ] ||
cannot_measure "$label workload generator exited $status; the arms did not do identical work -- see $RESULTS_DIR/workload-${TIMESTAMP}/"
}
# Kills any generator still running, so an aborted arm leaves no python3 holding
# WebSocket connections. Guarded like stop_cluster's commands: this runs from the
# EXIT trap, where an unguarded failure would discard the real exit status.
stop_workload() {
local pid
for pid in ${WORKLOAD_PIDS[@]+"${WORKLOAD_PIDS[@]}"}; do
kill "$pid" 2>/dev/null || true
done
WORKLOAD_PIDS=()
return 0
}
collect_metrics() {
local label="$1"
local out_file="$2"
local status=0
# An empty or short list would silently fall back to host-wide sampling,
# which is the outcome the pid argument exists to prevent.
local pids
pids=$(node_pids_csv)
local n_pids
n_pids=$(printf '%s' "$pids" | awk -F, '{print NF}')
[ "${n_pids:-0}" -eq "$NUM_NODES" ] ||
cannot_measure "$label: found $n_pids of $NUM_NODES node pids, so the sampler cannot be scoped to this cluster"
bash "$SCRIPT_DIR/collect_system_metrics.sh" \
"$(rpc_ports_csv)" "$DURATION" "$out_file" || status=$?
"$(rpc_ports_csv)" "$DURATION" "$out_file" "$pids" || status=$?
[ "$status" -eq 0 ] ||
cannot_measure "$label metric collection failed (exit $status) — refusing to compare an incomplete run"
@@ -371,13 +523,17 @@ log "="
# --- Baseline run ---
BASELINE_FILE="$RESULTS_DIR/baseline-${TIMESTAMP}.json"
start_cluster "0" "baseline"
start_workload "baseline"
collect_metrics "baseline" "$BASELINE_FILE"
wait_workload "baseline"
stop_cluster
# --- Telemetry run ---
TELEMETRY_FILE="$RESULTS_DIR/telemetry-${TIMESTAMP}.json"
start_cluster "1" "telemetry"
start_workload "telemetry"
collect_metrics "telemetry" "$TELEMETRY_FILE"
wait_workload "telemetry"
stop_cluster
# ---------------------------------------------------------------------------
@@ -522,7 +678,7 @@ cat >"$REPORT_FILE" <<EOMD
impact could not be computed. Such rows count as failures.
\`Consensus Round Mean\` is the mean inter-ledger interval derived from the
collector's 5 s ledger-sequence samples, not a percentile.
collector's 2 s ledger-sequence samples, not a percentile.
## Summary

View File

@@ -6,10 +6,17 @@
# Used by benchmark.sh for baseline vs telemetry comparison.
#
# Usage:
# ./collect_system_metrics.sh <rpc_ports_csv> <duration_seconds> <output_file>
# ./collect_system_metrics.sh <rpc_ports_csv> <duration_seconds> <output_file> [pids_csv]
#
# pids_csv narrows process sampling to exactly those pids. Without it the scope
# is every xrpld on the host, which averages in any other cluster's nodes and
# reports the largest of them as the RSS peak. benchmark.sh passes its own pids
# because run-full-validation.sh leaves five validation nodes running while the
# benchmark's three start, and diluting the arms alike hides the delta.
#
# Example:
# ./collect_system_metrics.sh "5005,5006,5007" 300 /tmp/metrics-baseline.json
# ./collect_system_metrics.sh "5020,5021,5022" 120 /tmp/m.json "8801,8802,8803"
#
# Output JSON format:
# {
@@ -54,6 +61,7 @@ usage() {
echo " rpc_ports_csv Comma-separated RPC ports (e.g., 5005,5006,5007)"
echo " duration_seconds How long to collect metrics"
echo " output_file Path to write JSON results"
echo " pids_csv Optional: sample only these pids, not every host xrpld"
exit 1
}
@@ -64,16 +72,33 @@ fi
RPC_PORTS_CSV="$1"
DURATION="$2"
OUTPUT_FILE="$3"
PIDS_CSV="${4:-}"
# Reject a malformed pid list rather than silently sampling the whole host,
# which is the outcome this argument exists to prevent.
case "$PIDS_CSV" in
'') ;;
*[!0-9,]*) die "pids_csv must be a comma-separated list of pids, got '$PIDS_CSV'" ;;
esac
IFS=',' read -ra RPC_PORTS <<<"$RPC_PORTS_CSV"
SAMPLE_INTERVAL=5
# consensus_round_mean_ms below counts DISTINCT ledger sequences seen by this
# loop, so it cannot resolve a close interval shorter than SAMPLE_INTERVAL. At
# 5 s it read back 5000 ms for every close time from 2 s to 5 s, so a 10%
# regression measured 0% and the benchmark's 1% consensus gate could never fire.
# 2 s is the close-time floor itself (ledgerMinClose, ConsensusParms.h:93), which
# is enough: measured against this file's own arithmetic, a 10% regression shows
# up as at least 9.3% anywhere in the 2 s to 5 s band. 1 s only doubles the
# probe load for slightly worse numbers.
SAMPLE_INTERVAL=2
# Hard ceiling on every RPC probe below. curl applies no overall timeout of its
# own, so a node that accepts the connection and then stops answering — what a
# stalled job queue looks like from outside — parks the sampling loop for the
# rest of the run. 5 s is one sample interval and some thousands of times a
# healthy server_info, so it bounds a wedged node's cost to one lost sample
# while never truncating a real reply. A probe that hits the ceiling exits
# rest of the run. 5 s is some thousands of times a healthy server_info, so it
# bounds a wedged node's cost to a couple of lost samples while never
# truncating a real reply. A probe that hits the ceiling exits
# non-zero and is therefore skipped rather than recorded, which is the same
# rule the latency loop already applies to a refused connection; if every
# probe hits it, the empty file trips the placeholder warning below.
@@ -175,21 +200,31 @@ for sample in $(seq 1 "$SAMPLES"); do
# and -C matches nothing. "rippled" is accepted alongside "xrpld" so a
# rename of the binary cannot silently zero the collector.
#
# Scope is the whole host, as it always was: a second xrpld from another
# checkout is sampled too. Only run a benchmark on a box with one cluster.
# Scope is the pid list when one was given, and the whole host otherwise.
# Host scope averages in any other cluster's xrpld and reports the largest
# of them as the RSS peak, which reads as noise against a 5 MB threshold.
#
# A %cpu of exactly 0.0 is a real reading and is counted — dropping idle
# samples would inflate the average — while non-numeric output is
# rejected by the pattern. An RSS of 0 is not a live process, so it
# contributes no memory sample; counting it would leave the file non-empty
# and mark a dead cluster's 0 MB peak as a complete measurement.
ps -eo %cpu=,rss=,args= |
awk -v cpu_file="$CPU_FILE" -v mem_file="$MEM_FILE" '
$3 !~ /(^|\/)(xrpld|rippled)$/ { next }
$1 ~ /^[0-9]+(\.[0-9]+)?$/ { cpu_sum += $1; cpu_n++ }
$2 ~ /^[0-9]+$/ && $2 + 0 > 0 { printf("%.2f\n", $2 / 1024) >> mem_file }
END { if (cpu_n > 0) printf("%.2f\n", cpu_sum / cpu_n) >> cpu_file }
' || die "process sampling failed on sample $sample/$SAMPLES"
ps -eo pid=,%cpu=,rss=,args= |
awk -v cpu_file="$CPU_FILE" -v mem_file="$MEM_FILE" -v pids="$PIDS_CSV" '
BEGIN { if (pids != "") { n = split(pids, a, ","); for (i = 1; i <= n; i++) want[a[i]] = 1 } }
pids != "" && !($1 in want) { next }
pids == "" && $4 !~ /(^|\/)(xrpld|rippled)$/ { next }
$2 ~ /^[0-9]+(\.[0-9]+)?$/ { cpu_sum += $2; cpu_n++ }
$3 ~ /^[0-9]+$/ && $3 + 0 > 0 { printf("%.2f\n", $3 / 1024) >> mem_file }
END {
# With an explicit pid list the expected count is known, so a
# dead node is detectable. Without it, exit 1 would fire on any
# host with no xrpld at all, which the empty-file check below
# already reports.
if (pids != "" && cpu_n != n) exit 1
if (cpu_n > 0) printf("%.2f\n", cpu_sum / cpu_n) >> cpu_file
}
' || die "process sampling failed on sample $sample/$SAMPLES: expected $(echo "$PIDS_CSV" | tr -cd , | wc -c)+1 live pids"
# Collect RPC latency from each node. Only a successful call is a latency
# measurement: a refused connection returns in well under a millisecond,
@@ -310,12 +345,15 @@ else
METRICS_COMPLETE=false
fi
# Mean inter-ledger interval in ms: DURATION / (distinct ledgers - 1) * 1000.
# Mean inter-ledger interval in ms: ELAPSED / (distinct ledgers - 1) * 1000.
#
# This is a MEAN, not a percentile — the JSON key says so. It is also aliased
# by the sample loop: LEDGER_FILE gets one sequence per sample, so at a
# SAMPLE_INTERVAL of 5 s the series cannot resolve a close interval faster
# than that (a ~4 s close is invisible). Read it as a coarse trend only.
# ELAPSED, not DURATION: DURATION is what the caller asked for, while the loop
# also spends time on its own probes, so it always runs longer. TPS above uses
# ELAPSED for the same reason.
#
# This is a MEAN, not a percentile — the JSON key says so. It still cannot
# resolve a close interval at or below SAMPLE_INTERVAL, because LEDGER_FILE
# gets at most one sequence per sample. Read it as a coarse trend.
if [ -s "$LEDGER_FILE" ]; then
UNIQUE_LEDGERS=$(sort -u "$LEDGER_FILE" | wc -l)
# The > 1 test also keeps the divisor below at 1 or more.
@@ -328,7 +366,7 @@ if [ -s "$LEDGER_FILE" ]; then
# sampling loop and the CPU average, so computing this with awk removes
# the failure path rather than reporting it. The divisor is >= 1 by the
# test above.
CONSENSUS_MEAN=$(awk -v d="$DURATION" -v u="$UNIQUE_LEDGERS" \
CONSENSUS_MEAN=$(awk -v d="$ELAPSED" -v u="$UNIQUE_LEDGERS" \
'BEGIN { printf "%.0f", d * 1000 / (u - 1) }')
else
warn "Ledger seq never advanced ($UNIQUE_LEDGERS distinct); consensus_round_mean_ms is a 0 placeholder"

View File

@@ -282,6 +282,29 @@ def compute_delta(
current = current_entry.get("value") if current_entry else None
unit = (baseline_entry or current_entry or {}).get("unit", "")
# A unit change makes the two numbers incomparable, so subtracting them is
# meaningless: us -> ms reads as a 99.9% improvement and the gate passes.
# Fail instead, and name both units so the baseline can be refreshed.
baseline_unit = (baseline_entry or {}).get("unit", "")
current_unit = (current_entry or {}).get("unit", "")
if baseline_unit and current_unit and baseline_unit != current_unit:
pct_threshold, abs_threshold = resolve_thresholds(key, thresholds)
return MetricDelta(
key=key,
baseline=baseline,
current=current,
delta=None,
pct_change=None,
unit=f"{baseline_unit}->{current_unit}",
threshold_pct=pct_threshold,
threshold_abs=abs_threshold,
regressed=True,
note=(
f"unit changed: baseline is {baseline_unit}, current run is "
f"{current_unit} -- refresh the baseline instead of comparing"
),
)
if baseline is None and current is None:
return _skip_delta(
key, None, None, unit, thresholds, "no data (neither baseline nor current)"
@@ -358,6 +381,12 @@ def print_summary(deltas: list[MetricDelta]) -> None:
"absolute bound alone where the baseline is not positive):"
)
_print_table(regressions)
# A regression can also be recorded with no delta at all -- a unit
# change makes the two numbers incomparable. That row prints as dashes,
# so name the reason here or the table looks like a bug.
for d in regressions:
if d.delta is None:
print(f" {d.key}: {d.note}")
if improvements:
top = improvements[:5]
@@ -401,7 +430,12 @@ def write_report(
"window": timings.get("window"),
"profile": timings.get("profile"),
"summary": {
# total is every key in the report, which is the UNION of the
# baseline and the current run -- not the baseline count. "compared"
# is the only number that says how much was actually gated: a delta
# exists only when both sides had a value.
"total": len(deltas),
"compared": sum(1 for d in deltas if d.delta is not None),
"regressions": len(regressions),
"improvements": sum(
1

View File

@@ -277,7 +277,7 @@
"not_asserted": {
"description": "Emitted-and-dashboarded metrics deliberately left unasserted because they are workload-gated or defect-gated: the harness workload cannot guarantee they appear, and a check that fails on a healthy run is worse than no check. This group has no \"metrics\" key, so validate_telemetry.py skips it (validate_metrics iterates category_data.get(\"metrics\", [])). Promote an entry into an asserted group only after the workload is changed to guarantee it. This map is the ONLY machine-readable record of an emitted-but-unasserted name, so every such name belongs here rather than in a prose note inside an asserted group -- prose cannot be linted. Concretely, phase-10 adds an _unaccounted_metric_names pass that harvests this map's keys as accounted names, so a name recorded only in a prose note is reported as unaccounted once that lands. It is warning-only and cannot fail CI, and it accepts a third source as well (an accounted_patterns regex list), so this map is the right home but not the only possible one. Caveat when adding: check_otel_naming.py Rule K harvests names only from `metrics` LISTS and from metric/name keys, so these dict KEYS are never validated against the MetricNames.h constants -- a typo here is silent, and must be checked by eye against the emit site cited in its own reason string.",
"metrics_excluded": {
"rpc_method_errored_total": "MetricsRegistry.cpp:332-333, push counter. 'Errored' here means a thrown C++ exception, not an error status in the JSON reply: the only caller is PerfLogImp.cpp:409 under 'if (!finish)', reached only through PerfLogImp::rpcError (PerfLogImp.h:150-153), whose only call site is the catch (std::exception&) handler in RPCHandler.cpp:213. An RPC that returns an error status normally still takes the rpcFinish path at RPCHandler.cpp:190 and increments rpc_method_finished_total. That distinction mattered here while the generator still issued ripple_path_find: those calls were in fact refused — pathfinding is off on every harness node, so doRipplePathFind returns rpcNOT_SUPPORTED (see pathfind_fast_milliseconds below) — and it would have been easy to conclude from that alone that this counter must fire. It does not, because a refusal is a normal return, not a throw. The harness issues no path-finding command at all, so the question is moot here, but the distinction is kept on record because it is the one that decides this entry. Nothing in rpc_load_generator.py's remaining server_info / fee / account / ledger / tx / DEX mix is expected to throw either, so no series may ever be created.",
"rpc_method_errored_total": "MetricsRegistry.cpp:332-333, push counter. 'Errored' here means a thrown C++ exception, not an error status in the JSON reply: the only caller is PerfLogImp.cpp:409 under 'if (!finish)', reached only through PerfLogImp::rpcError (PerfLogImp.h:150-153), whose only call site is the catch (std::exception&) handler in RPCHandler.cpp:213. An RPC that returns an error status normally still takes the rpcFinish path at RPCHandler.cpp:190 and increments rpc_method_finished_total. That distinction mattered here while the generator still issued ripple_path_find: those calls were in fact refused — pathfinding is off on every harness node, so doRipplePathFind returns RpcNotSupported (see pathfind_fast_milliseconds below) — and it would have been easy to conclude from that alone that this counter must fire. It does not, because a refusal is a normal return, not a throw. The harness issues no path-finding command at all, so the question is moot here, but the distinction is kept on record because it is the one that decides this entry. Nothing in rpc_load_generator.py's remaining server_info / fee / account / ledger / tx / DEX mix is expected to throw either, so no series may ever be created.",
"ledger_history_mismatch_total": "MetricsRegistry.cpp:377, incremented only from LedgerHistory.cpp:332 on a built-vs-validated ledger mismatch. On a healthy run it never fires — asserting it would mean asserting a defect.",
"txq_expired_total": "MetricsRegistry.cpp:379, incremented only at TxQ.cpp:1428 when a queued tx expires past its LastLedgerSequence. CI does run a txq-burst phase (workload-profiles.json:41, 30 s of single-type Payment at 60 TPS), but that does not guarantee sustained fee escalation followed by expiry: a run in which every other check passed still exposed only txq_metrics and no txq_expired_total.",
"txq_dropped_total": "MetricsRegistry.cpp:381, incremented only at TxQ.cpp:1302 / :1347 on queue-full admission refusal. Same reason as txq_expired_total.",
@@ -301,8 +301,8 @@
"rotation_copy_node_restore_total": "SHAMapStoreImp.cpp:283. Fires only for a clean tree node reachable from the validated state map whose sole on-disk copy an EARLIER rotation removed, so it needs at least two rotations (512 validated ledgers, ~15-20 min at the cluster's close rate) plus real prior data loss. The run window is 270 s. Note that the rotation_state gauge sub-series ARE asserted -- see sync_diagnostics._b5_rotation_note for why a series exists while a rotation never runs.",
"rpc_size_bytes": "ServerHandler.cpp:191, group('rpc')->makeEvent('size', Unit::Bytes). The OTLP Prometheus exporter derives the metric-name suffix from the declared unit, so a byte unit yields rpc_size_bytes. The Unit::Bytes declaration itself landed earlier, in 76c9051203; what 24094e427b changed was the exporter finally consuming it, replacing a hardcoded CreateDoubleHistogram(name, 'Duration in ms', 'ms') with otelUnitDescription(unit)/otelUnitCode(unit), and that is what renamed the series off rpc_size_milliseconds and the millisecond bucket ladder. Neither name was ever recorded here, so the harness could confirm neither the rename nor a regression back onto that ladder. Notified from ServerHandler::processRequest:1133, the HTTP JSON-RPC path — it computes an HTTP status and appends a trailing newline — and the load generators are WebSocket-only, the same gate regression-metrics.json:4 records for rpc.process, so only the harness's handful of HTTP health polls reach it. Real coverage needs an HTTP JSON-RPC phase in rpc_load_generator.py; that is a workload change rather than a harness correction, and is deliberately out of scope here.",
"rpc_time_milliseconds": "ServerHandler.cpp:192, group('rpc')->makeEvent('time') with the default millisecond unit. Notified from ServerHandler::processRequest:1129, the same HTTP JSON-RPC call site as rpc_size_bytes and behind the same WebSocket-only gate.",
"pathfind_fast_milliseconds": "PathRequestManager.h:35, makeEvent('pathfind_fast') with the default millisecond unit, so the exported form is the pathfind_fast_milliseconds_bucket/_count/_sum triple and there is no bare series — the same convention io_latency and rpc_method_us follow, and rpc-pathfinding queries the _bucket. THE OPERATIVE BLOCKER IS THE CONFIG, NOT THE CALL GRAPH: pathfinding is disabled outright on every harness node, so no PathRequest is ever constructed and no pathfind_* histogram can exist. Config.cpp:725-726 sets pathSearchMax to 0 whenever a [validation_seed] or [validator_token] section is present ('By default, validators don't have pathfinding enabled'); run-full-validation.sh writes [validation_seed] into every generated node cfg (:308) and contains no [path_search], [path_search_fast] or [path_search_max] section to put it back (grep count 0 for path_search in that file — the only [path_search*] sections in docker/telemetry/ are in xrpld-telemetry.cfg and xrpld-telemetry-mainnet.cfg, neither of which the harness uses); and doRipplePathFind returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49, before context.loadType is set and before any branch on the ledger parameter. That config gate alone would keep the metric absent even if the generator did issue the command, because every such call is refused at the front door; and the generator issues no path-finding RPC in the first place. Two independent reasons. Read that first: the structural argument below is correct and matters if pathfinding is ever enabled, but it is not why the metric is missing today. STRUCTURAL ARGUMENT (verified, applies once pathSearchMax is non-zero): reportFast's only caller is PathRequest.cpp:852, inside the 'if (fast && quickReply_ == {})' branch of PathRequest::doUpdate. The only doUpdate call that passes fast=true is in PathRequest::doCreate (PathRequest.cpp:259), guarded by '!hasCompletion()'. Both ripple_path_find entry points construct the PathRequest with a completion function, so hasCompletion() (:161-164) is true and the fast pass is skipped: with no ledger specified doRipplePathFind goes to makeLegacyPathRequest, which passes the coroutine-post lambda (RipplePathFind.cpp:140-160); with a ledger specified it goes to doLegacyPathRequest, which passes an empty-body but non-null lambda (PathRequestManager.cpp:317). Only the path_find streaming subscription reaches reportFast, because makePathRequest builds the request from a subscriber with no completion (PathRequestManager.cpp:261). The load generator has never used path_find: it fires one request per send and awaits one reply, which a streaming subscription does not fit. Covering this metric therefore needs both a [path_search_max] override (or a non-validator node) in run-full-validation.sh and a path_find subscription phase in the generator. Both are harness/workload changes and out of scope here. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC.",
"pathfind_full_milliseconds": "PathRequestManager.h:36, makeEvent('pathfind_full'); same histogram naming as pathfind_fast_milliseconds above. Notified from reportFull (:87-90) via PathRequest.cpp:857, the 'else if (!fast && fullReply_ == {})' branch. Blocked by exactly the same config gate as pathfind_fast_milliseconds, and the probability of emission under the harness workload is zero, not low: pathSearchMax is 0 on every harness node (Config.cpp:725-726 plus the [validation_seed] section at run-full-validation.sh:308, with no [path_search*] override anywhere in that file), so doRipplePathFind returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49 and no PathRequest object is ever constructed for reportFull to fire from. An earlier revision of this entry described the path as reachable-but-probabilistic — emitting one ledger close behind the request via PathRequestManager::updateAll's one-shot branch (PathRequestManager.cpp:160-166) — and prescribed sending an explicit ledger_index from the generator so doLegacyPathRequest would call doUpdate(cache, false) synchronously (PathRequestManager.cpp:321). Both halves were wrong. The probability is zero rather than merely unreliable, and the prescribed remedy cannot work at all, because the pathSearchMax guard fires before the ledger parameter is read: adding ledger_index changes nothing while pathfinding is off. The generator also issues no path-finding RPC, so covering this metric needs a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND path-finding load added — a harness-topology plus workload change, out of scope here. The workload README section 'Pathfinding is not exercised' holds the recipe. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC rather than with a broken exporter.",
"pathfind_fast_milliseconds": "PathRequestManager.h:35, makeEvent('pathfind_fast') with the default millisecond unit, so the exported form is the pathfind_fast_milliseconds_bucket/_count/_sum triple and there is no bare series — the same convention io_latency and rpc_method_us follow, and rpc-pathfinding queries the _bucket. THE OPERATIVE BLOCKER IS THE CONFIG, NOT THE CALL GRAPH: pathfinding is disabled outright on every harness node, so no PathRequest is ever constructed and no pathfind_* histogram can exist. Config.cpp:725-726 sets pathSearchMax to 0 whenever a [validation_seed] or [validator_token] section is present ('By default, validators don't have pathfinding enabled'); run-full-validation.sh writes [validation_seed] into every generated node cfg and contains no [path_search], [path_search_fast] or [path_search_max] section to put it back (grep count 0 for path_search in that file — the only [path_search*] sections in docker/telemetry/ are in xrpld-telemetry.cfg and xrpld-telemetry-mainnet.cfg, neither of which the harness uses); and doRipplePathFind returns RpcNotSupported at RipplePathFind.cpp:59-60, before context.loadType is set and before any branch on the ledger parameter. That config gate alone would keep the metric absent even if the generator did issue the command, because every such call is refused at the front door; and the generator issues no path-finding RPC in the first place. Two independent reasons. Read that first: the structural argument below is correct and matters if pathfinding is ever enabled, but it is not why the metric is missing today. STRUCTURAL ARGUMENT (verified, applies once pathSearchMax is non-zero): reportFast's only caller is PathRequest.cpp:852, inside the 'if (fast && quickReply_ == {})' branch of PathRequest::doUpdate. The only doUpdate call that passes fast=true is in PathRequest::doCreate (PathRequest.cpp:259), guarded by '!hasCompletion()'. Both ripple_path_find entry points construct the PathRequest with a completion function, so hasCompletion() (:161-164) is true and the fast pass is skipped: with no ledger specified doRipplePathFind goes to makeLegacyPathRequest, which passes the coroutine-post lambda (RipplePathFind.cpp:140-160); with a ledger specified it goes to doLegacyPathRequest, which passes an empty-body but non-null lambda (PathRequestManager.cpp:317). Only the path_find streaming subscription reaches reportFast, because makePathRequest builds the request from a subscriber with no completion (PathRequestManager.cpp:261). The load generator has never used path_find: it fires one request per send and awaits one reply, which a streaming subscription does not fit. Covering this metric therefore needs both a [path_search_max] override (or a non-validator node) in run-full-validation.sh and a path_find subscription phase in the generator. Both are harness/workload changes and out of scope here. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC.",
"pathfind_full_milliseconds": "PathRequestManager.h:36, makeEvent('pathfind_full'); same histogram naming as pathfind_fast_milliseconds above. Notified from reportFull (:87-90) via PathRequest.cpp:857, the 'else if (!fast && fullReply_ == {})' branch. Blocked by exactly the same config gate as pathfind_fast_milliseconds, and the probability of emission under the harness workload is zero, not low: pathSearchMax is 0 on every harness node (Config.cpp:725-726 plus the [validation_seed] section run-full-validation.sh writes, with no [path_search*] override anywhere in that file), so doRipplePathFind returns RpcNotSupported at RipplePathFind.cpp:59-60 and no PathRequest object is ever constructed for reportFull to fire from. An earlier revision of this entry described the path as reachable-but-probabilistic — emitting one ledger close behind the request via PathRequestManager::updateAll's one-shot branch (PathRequestManager.cpp:160-166) — and prescribed sending an explicit ledger_index from the generator so doLegacyPathRequest would call doUpdate(cache, false) synchronously (PathRequestManager.cpp:321). Both halves were wrong. The probability is zero rather than merely unreliable, and the prescribed remedy cannot work at all, because the pathSearchMax guard fires before the ledger parameter is read: adding ledger_index changes nothing while pathfinding is off. The generator also issues no path-finding RPC, so covering this metric needs a [path_search_max] override (or a non-validator node) in run-full-validation.sh AND path-finding load added — a harness-topology plus workload change, out of scope here. The workload README section 'Pathfinding is not exercised' holds the recipe. Grafana Cloud shows zero series in 180 days on the devnet nodes, consistent with those nodes receiving no pathfinding RPC rather than with a broken exporter.",
"warn_total": "include/xrpl/resource/detail/Logic.h:41, makeMeter('warn'). makeMeter maps to CreateUInt64Counter (OTelCollector.cpp:878-881 -> :773-777), so the Prometheus exporter appends _total; the meter is created on the bare collector with no group, hence the unprefixed name. Incremented only at Logic.h:481, inside the 'if (notify)' branch reached when a consumer's balance crosses kWarningThreshold. A cooperating 5-node cluster plus a rate-limited load generator never charges a consumer that far, and Grafana Cloud confirms zero series in 180 days. Recorded explicitly because this was briefly mis-diagnosed as a phantom metric: the rpc-pathfinding panel that queries it is correct, and renders empty only because the condition has not occurred.",
"drop_total": "include/xrpl/resource/detail/Logic.h:42, makeMeter('drop'); same CreateUInt64Counter mapping and same _total suffix as warn_total. Incremented only at Logic.h:505, when a consumer's balance is at or above kDropThreshold and the connection is dropped. Grafana Cloud shows 2 live series, so unlike warn_total this one does fire in the wild — but only on a genuinely abusive consumer, which the harness deliberately does not create, so it is condition-gated all the same. Its rpc-pathfinding panel is likewise correct rather than phantom.",
"jobq_*_milliseconds, jobq_*_q_milliseconds": "This key is a pattern rather than a literal metric name — unlike every other entry in this map it stands for a whole family, one pair per job type. Created per job type in JobTypeData.h:97-98 from info.name() and info.name() + kSuffixQueued ('_q'), so the exported names are jobq_<jobtype>_milliseconds and jobq_<jobtype>_q_milliseconds with the job type lowercased by formatName. Which job types appear depends on which jobs a run happens to schedule, so no individual name is guaranteed. They are also rounded up to a whole millisecond at source (Event.h:47-51 applies ceil to a millisecond value type), which is why 6e2b2da772 moved the ledger-data-sync q-wait panels off jobq_<jobtype>_q_milliseconds_bucket onto job_queued_us_bucket — they are poor assertion targets regardless."

View File

@@ -25,7 +25,7 @@
"required_attributes": [],
"config_flag": "trace_rpc",
"optional": true,
"note": "HTTP-only. Created solely in ServerHandler::processRequest() (ServerHandler.cpp:705), 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."
"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.*",
@@ -242,7 +242,7 @@
"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:666, 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)."
},
{
"name": "consensus.validation.send",
@@ -449,7 +449,7 @@
"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 (:308) and has no [path_search*] override, and doRipplePathFind then returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49 — 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'."
"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'."
},
{
"name": "pathfind.discover",
@@ -467,7 +467,7 @@
"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 rpcNOT_SUPPORTED first because pathfinding is disabled on every node (PathFind.cpp:39, RipplePathFind.cpp:48; 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)."
},
{
"name": "grpc.*",
@@ -485,7 +485,7 @@
"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:705), 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."
"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",
@@ -517,7 +517,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 (:308) with no [path_search*] override, and doRipplePathFind returns rpcNOT_SUPPORTED at RipplePathFind.cpp:48-49 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."
"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",
@@ -547,7 +547,7 @@
"child": "pathfind.discover",
"description": "The path computation contains the discovery pass.",
"skip": true,
"skip_reason": "Real relationship with BOTH ends absent, for the reason given in full on the pathfind.compute entry above: pathfinding is disabled on every harness node because Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] section is present, run-full-validation.sh writes one for all five nodes (:308) with no [path_search_max] override, so doRipplePathFind returns rpcNOT_SUPPORTED before any PathRequest is constructed -- and the harness sends no path-finding RPC at all either. Asserting this needs both blockers lifted, which is a workload and node-config change rather than a harness one. Listed here so that the pathfinding family is fully accounted for rather than partly silent.",
"skip_reason": "Real relationship with BOTH ends absent, for the reason given in full on the pathfind.compute entry above: pathfinding is disabled on every harness node because Config.cpp:725-726 zeroes pathSearchMax whenever a [validation_seed] section is present, run-full-validation.sh writes one for all five nodes with no [path_search_max] override, so doRipplePathFind returns RpcNotSupported before any PathRequest is constructed -- and the harness sends no path-finding RPC at all either. Asserting this needs both blockers lifted, which is a workload and node-config change rather than a harness one. Listed here so that the pathfinding family is fully accounted for rather than partly silent.",
"added": "Closes the declared-but-unlisted gap"
},
{

View File

@@ -4,6 +4,20 @@
# Uses a temporary standalone xrpld instance to call `validation_create` RPC
# for each node. Outputs a JSON file mapping node index to seed + public key.
#
# Production does this differently, and deliberately not the way this script
# does. There, `validator-keys-tool` runs `create_keys` once to make a master
# key that never leaves the operator's custody, then `create_token` to mint a
# revocable `[validator_token]` for the node; rotating a node means minting a
# new token, not moving the master key. This harness uses `validation_create`
# instead, which puts the seed itself in `[validation_seed]` on the node.
#
# That is safe here only because the cluster is disposable: the keys are made on
# the same machine that runs the nodes, into a temp workdir that the next run
# deletes, so there is no custody boundary for the two-step split to protect.
# The tool is also not present on this path -- it is built only with
# `-Dvalidator_keys=ON`, which the telemetry CI job does not pass. Do not copy
# this script's approach to a node holding a key you care about.
#
# Usage:
# ./generate-validator-keys.sh <xrpld_binary> <num_nodes> <output_dir>
#
@@ -58,6 +72,12 @@ TEMP_DIR="$(mktemp -d)"
TEMP_PORT=5099
TEMP_CFG="$TEMP_DIR/xrpld.cfg"
# Hard ceiling on every RPC probe below. curl applies no overall timeout of its
# own, so a node that accepts the connection and then stops answering parks the
# poll loop for the rest of the run. The loops here count attempts, not seconds,
# so without this their stated timeouts are not bounds at all.
CURL_MAX_TIME="${CURL_MAX_TIME:-5}"
log "Starting temporary xrpld for key generation (port $TEMP_PORT)..."
cat >"$TEMP_CFG" <<EOCFG
@@ -98,7 +118,7 @@ trap cleanup_temp EXIT
# Wait for RPC to become available
for attempt in $(seq 1 30); do
if curl -sf "http://localhost:$TEMP_PORT" \
if curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$TEMP_PORT" \
-d '{"method":"server_info"}' >/dev/null 2>&1; then
log "Temporary xrpld RPC ready (attempt $attempt)."
break
@@ -118,7 +138,7 @@ KEYS_JSON="["
VALIDATORS_TXT="[validators]"
for i in $(seq 1 "$NUM_NODES"); do
result=$(curl -sf "http://localhost:$TEMP_PORT" \
result=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$TEMP_PORT" \
-d '{"method":"validation_create"}')
seed=$(echo "$result" | jq -r '.result.validation_seed')
pubkey=$(echo "$result" | jq -r '.result.validation_public_key')

View File

@@ -2,7 +2,7 @@
"_description": "Metric surface for the OTel-driven regression gate. Each entry names a metric, the quantiles to capture, and how to query Prometheus. The comparator compares current run against baseline-timings.json under these exact keys.",
"_key_format": "{category}.{name}.p{quantile} (e.g. span.tx.process.p99, job.transaction.queued.p95). Only the categories defined below are captured; there is no rpc_methods group, so no rpc.* key is produced or gated (FU-4).",
"_excluded_spans": "rpc.process is deliberately absent from spans.names. It is created only in ServerHandler::processRequest() on the HTTP/JSON-RPC path, which the workload load generators, being WebSocket-only, never reach, so its quantiles were captured as null every run and could never gate. (The harness shell scripts do issue a few HTTP JSON-RPC health polls, far too few to produce a meaningful quantile.) See baselines/README.md.",
"_excluded_ledger_store": "ledger.store is deliberately absent from spans.names too, for a different reason: it is below the ladder's resolution. The 2026-08-24 capture returned p50/p95/p99 of exactly 0.005/0.0095/0.0099 ms, which is 0.5/0.95/0.99 x the ladder's first edge of 0.01 ms — the signature of every sample landing in the first bucket, so the numbers are interpolation arithmetic on the bucket floor rather than latencies. That is physically plausible: LedgerMaster.cpp:463 wraps an in-memory ledgerHistory_.insert, which completes in single-digit microseconds. While all mass stays under 10 us the reported quantile cannot move materially, so NO absolute bound can gate it — every ledger.store slowing from 2 us to 9 us, 4.5x, leaves the reported value unchanged. Three keys that read as covered but cannot fire are worse than no keys (the same argument that excluded rpc.process), so they were removed rather than left in with a bound that looks derived. Restoring the key needs sub-10us edges on the collector's spanmetrics ladder (for example 0.001ms and 0.005ms) plus the matching entries in HistogramBuckets.h — that is the ladder's branch, not this file. ledger.store presence is still asserted by expected_spans.json and docker/telemetry/integration-test.sh, and its rate is still on the ledger-operations dashboard; only the latency gate drops it.",
"_excluded_ledger_store": "ledger.store is deliberately absent from spans.names too, for a different reason: it is below the ladder's resolution. The 2026-08-24 capture returned p50/p95/p99 of exactly 0.005/0.0095/0.0099 ms, which is 0.5/0.95/0.99 x the ladder's first edge of 0.01 ms — the signature of every sample landing in the first bucket, so the numbers are interpolation arithmetic on the bucket floor rather than latencies. That is physically plausible: LedgerMaster.cpp:470 wraps an in-memory ledgerHistory_.insert, which completes in single-digit microseconds. While all mass stays under 10 us the reported quantile cannot move materially, so NO absolute bound can gate it — every ledger.store slowing from 2 us to 9 us, 4.5x, leaves the reported value unchanged. Three keys that read as covered but cannot fire are worse than no keys (the same argument that excluded rpc.process), so they were removed rather than left in with a bound that looks derived. Restoring the key needs sub-10us edges on the collector's spanmetrics ladder (for example 0.001ms and 0.005ms) plus the matching entries in HistogramBuckets.h — that is the ladder's branch, not this file. ledger.store presence is still asserted by expected_spans.json and docker/telemetry/integration-test.sh, and its rate is still on the ledger-operations dashboard; only the latency gate drops it.",
"_excluded_quantiles": "A THIRD KIND OF EXCLUSION, and the only one that deleting a name cannot express. spans.names lists span NAMES while _quantiles is shared across all of them, so the declared surface is the names x quantiles product and dropping ONE quantile of ONE span needs a subtraction. excluded_keys below is that subtraction: a flat {category}.{name}.p{quantile} key, exactly as _key_format defines it, mapped to the reason it is not gated. It can only ever remove a key, never add one, so a typo cannot silently start gating something new -- and check_regression_bounds.py rule F rejects an entry that would not otherwise be declared, an entry with an empty reason, and an entry that still carries a threshold override or a baseline value, so the exclusion cannot rot into dead config. Both prom_queries.py (which builds the capture plan) and check_regression_bounds.py (rule A) subtract it, so an excluded key is not queried, never reaches timings.json, and is not expected in the baseline. NOTHING ELSE CHANGES: the quantile is still computable from Prometheus with the _query_template above, the span is still asserted by expected_spans.json, and its rate is still on the ledger-operations dashboard. Only the latency gate drops it.",
"_excluded_shape": "ALL FIVE ENTRIES BELOW SHARE ONE SHAPE, and it is worth naming because it will recur: the observed maximum across CI runs exceeds (baseline + bound), so an ordinary run clears the trip point with nothing having regressed. Two mechanisms produce that, and both are visible here. (1) A baseline that lands in the ladder's LOW buckets gets a tiny derived bound, because the bound IS the distance to the next edge up -- span.tx.apply.p50 at 0.0060 ms sits in the first bucket (0, 0.01] and gets 0.0440 ms of headroom, against a metric that has been measured at 2.3378 ms. (2) A spread so large that no bucket of headroom could absorb it -- span.ledger.validate.p99's 66.8x range reaches 25.8750 ms against a 10 ms trip point even though its bound is a comparatively generous 8.94 ms. The first mechanism is the one that excludes three keys here, and it is a property of WHERE THE CAPTURED RUN LANDED rather than of the metric: the same span.tx.apply.p50 has read 0.7917 ms, mid-distribution, where the identical rule produces a 4.21 ms bound that absorbs the whole range. Whether the gate functioned was therefore decided by luck of the draw. THE FOLLOW-UP THAT WOULD RESTORE COVERAGE, stated so it is not left implied: a baseline captured from a SINGLE run cannot support these keys, because one sample carries no information about spread and the bound is derived from that one sample alone. What would let them be gated again is a multi-run baseline -- or a spread measurement captured alongside the baseline, so a bound can be sized against observed variance instead of against the ladder only. That is not implemented; it is the design change these five exclusions are waiting on. Until then, do NOT re-gate any of them by re-baselining until a run happens to land favourably, which is the failure this note exists to prevent.",
"excluded_keys": {
@@ -10,7 +10,7 @@
"span.ledger.build.p50": "The same mechanism as span.consensus.ledger_close.p50, one bucket up. Baseline 0.1151 ms sits in (0.1, 0.25], so hi_next is 0.5 ms and the bound is 0.3849 ms -- a 4.34x trip point. Across three CI runs the value spans 0.1151 to 2.3826 ms, a 20.7x spread (25.3x over four runs), and the observed maximum is 4.77x the trip point. Note what the previous baseline hid: at 1.0612 ms the same rule gave a 8.94 ms bound and a 10 ms trip point, which absorbed the entire range, so this key read as gated purely because that capture landed mid-distribution. Ledger construction is the hot path this gate most wants to guard, which makes the loss real and worth fixing properly -- with a baseline that carries spread information, not with a wider bound.",
"span.tx.apply.p50": "The most extreme case of the low-bucket mechanism, and the clearest evidence that a single-run baseline cannot size a bound for these keys. Baseline 0.00597 ms lands in the ladder's FIRST bucket (0, 0.01], so hi_next is 0.05 ms and the bound is 0.0440 ms. Across three CI runs the value spans 0.00597 to 2.3378 ms, a 391.8x spread (364x over four runs), putting the observed maximum at 46.76x its trip point -- by far the worst of the five. The previous baseline read 0.7917 ms for the same key on the same workload, a 132x difference between two runs, and at that value the identical rule produced a 4.21 ms bound whose 5 ms trip point absorbed the full range. Nothing about the metric changed between those two captures; only where the sampled run fell in its own distribution did. Separately, a baseline inside the first bucket means the reported figure is interpolation across that bucket and tracks the FRACTION of applies finishing under 10 us rather than a latency, which is the ledger.store problem in embryo -- so restoring this key needs a finer low-end ladder as well as a spread-aware baseline. Rule E does not flag it because the value is not quantile x first_edge exactly.",
"span.ledger.validate.p95": "Run-to-run variance is larger than the bound this ladder can derive. Measured across four CI runs the value spans 0.1281 to 0.7500 ms, a 5.9x spread, against a baseline of 0.2404 ms whose trip point is the next ladder edge at 0.5 ms -- so an ordinary run clears the trip point with nothing having regressed. Run 32867433073 read 0.7500 ms, +212%, and turned CI red. The derived bound models QUANTIZATION noise only (hi_next - baseline is one bucket of headroom); the dominant noise term for this span is peer-validation arrival timing in a 5-node cluster, and that term was never measured before the key was gated. Widening is not available: a bound that tolerated 0.7500 ms would reach past the 1 ms edge and leave the key gating nothing. This is a variance limit, not a defect and not a missing bound -- do NOT re-gate it by widening.",
"span.ledger.validate.p99": "The same mechanism as p95, two orders of magnitude worse. Across the same four runs the value spans 0.3875 to 25.8750 ms, a 66.8x spread, against a baseline of 1.0600 ms and a 10 ms trip point; run 32862589645 read 25.8750 ms, +2341%. The span opens only once a quorum-completing validation arrives (LedgerMaster.cpp:987, inside checkAccept, past the tvc < minVal early return) and wraps the promotion work that follows -- setValidated, setFull, setValidLedger, pendSaveValidated -- so its duration tracks peer-validation arrival timing and what promotion then triggers. One slow consensus round therefore dominates the tail of a 3m rate window, and which round that is differs every run. A bound tolerating 25.8750 ms would be ~24.8 ms against a 1.0600 ms baseline, which gates nothing at all. Note that the two CI failures landed on DIFFERENT quantiles in different runs while the other quantile stayed well inside its bound in the same run: that asymmetry is the signature of variance, not of a regression."
"span.ledger.validate.p99": "The same mechanism as p95, two orders of magnitude worse. Across the same four runs the value spans 0.3875 to 25.8750 ms, a 66.8x spread, against a baseline of 1.0600 ms and a 10 ms trip point; run 32862589645 read 25.8750 ms, +2341%. The span opens only once a quorum-completing validation arrives (LedgerMaster.cpp:1003, inside checkAccept, past the tvc < minVal early return) and wraps the promotion work that follows -- setValidated, setFull, setValidLedger, pendSaveValidated -- so its duration tracks peer-validation arrival timing and what promotion then triggers. One slow consensus round therefore dominates the tail of a 3m rate window, and which round that is differs every run. A bound tolerating 25.8750 ms would be ~24.8 ms against a 1.0600 ms baseline, which gates nothing at all. Note that the two CI failures landed on DIFFERENT quantiles in different runs while the other quantile stayed well inside its bound in the same run: that asymmetry is the signature of variance, not of a regression."
},
"spans": {
"_query_template": "histogram_quantile({quantile}, sum by (le) (rate(span_duration_milliseconds_bucket{span_name=\"{name}\"}[{window}])))",

View File

@@ -770,6 +770,12 @@ def main() -> None:
try:
custom = json.loads(args.weights)
weights = {k: int(v) for k, v in custom.items()}
if not weights or sum(weights.values()) <= 0:
logger.error(
"Invalid --weights: the values must sum to more than 0, got %s",
weights,
)
sys.exit(1)
logger.info("Using custom weights: %s", weights)
except (json.JSONDecodeError, ValueError) as exc:
logger.error("Invalid --weights JSON: %s", exc)

View File

@@ -80,6 +80,12 @@ NUM_NODES=5
RPC_PORT_BASE=5005
WS_PORT_BASE=6006
PEER_PORT_BASE=51235
# Hard ceiling on every RPC probe below. curl applies no overall timeout of its
# own, so a node that accepts the connection and then stops answering parks the
# poll loop for the rest of the run. The loops here count attempts, not seconds,
# so without this their stated timeouts are not bounds at all.
CURL_MAX_TIME="${CURL_MAX_TIME:-5}"
# Inert: parsed from --rpc-rate/--rpc-duration/--tx-tps/--tx-duration and never
# read again. Load shape comes from the workload profile instead. Kept because
# the CI workflow still passes the four flags.
@@ -260,14 +266,14 @@ mkdir -p "$WORKDIR" "$REPORT_DIR" || die "Could not create $WORKDIR and $REPORT_
# Step 1: Start observability stack
# ---------------------------------------------------------------------------
log "Step 1: Starting observability stack..."
# Point the collector's log mount at this run's workdir so the filelog
# Point the collector's log mount at this run's workdir so the file_log
# receiver tails the per-node debug.log files generated below.
XRPLD_LOG_DIR="$WORKDIR" docker compose -f "$COMPOSE_FILE" up -d ||
die "docker compose up failed for $COMPOSE_FILE — the observability stack did not start"
log "Waiting for OTel Collector..."
for attempt in $(seq 1 30); do
status=$(curl -so /dev/null -w '%{http_code}' http://localhost:4318/ 2>/dev/null || echo 000)
status=$(curl -so /dev/null -w '%{http_code}' --max-time "$CURL_MAX_TIME" http://localhost:4318/ 2>/dev/null || echo 000)
if [ "$status" != "000" ]; then
ok "OTel Collector ready (attempt $attempt)"
break
@@ -278,7 +284,7 @@ done
log "Waiting for Tempo..."
for attempt in $(seq 1 30); do
if curl -sf "http://localhost:3200/ready" >/dev/null 2>&1; then
if curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:3200/ready" >/dev/null 2>&1; then
ok "Tempo ready (attempt $attempt)"
break
fi
@@ -288,7 +294,7 @@ done
log "Waiting for Prometheus..."
for attempt in $(seq 1 30); do
if curl -sf "http://localhost:9090/-/healthy" >/dev/null 2>&1; then
if curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:9090/-/healthy" >/dev/null 2>&1; then
ok "Prometheus ready (attempt $attempt)"
break
fi
@@ -305,7 +311,7 @@ bash "$SCRIPT_DIR/generate-validator-keys.sh" "$XRPLD" "$NUM_NODES" "$WORKDIR" |
die "generate-validator-keys.sh failed — no validator keys for the $NUM_NODES-node cluster"
for i in $(seq 1 "$NUM_NODES"); do
NODE_DIR="$WORKDIR/node$i"
NODE_DIR="$WORKDIR/validator-$i"
mkdir -p "$NODE_DIR/nudb" "$NODE_DIR/db" || die "Could not create node$i directories under $NODE_DIR"
RPC_PORT=$((RPC_PORT_BASE + i - 1))
@@ -472,15 +478,15 @@ node_running() {
report_stopped_nodes() {
local i pid status
for i in $(seq 1 "$NUM_NODES"); do
pid=$(cat "$WORKDIR/node$i/xrpld.pid" 2>/dev/null || echo "")
pid=$(cat "$WORKDIR/validator-$i/xrpld.pid" 2>/dev/null || echo "")
[ -n "$pid" ] || continue
node_running "$pid" && continue
status=0
wait "$pid" 2>/dev/null || status=$?
warn "node$i (pid $pid) is not running — wait status $status"
if [ -s "$WORKDIR/node$i/stdout.log" ]; then
if [ -s "$WORKDIR/validator-$i/stdout.log" ]; then
warn "node$i last output:"
tail -n 15 "$WORKDIR/node$i/stdout.log" | sed 's/^/ /' >&2
tail -n 15 "$WORKDIR/validator-$i/stdout.log" | sed 's/^/ /' >&2
else
warn "node$i wrote no stdout at all"
fi
@@ -494,7 +500,7 @@ for attempt in $(seq 1 120); do
laggards=""
for i in $(seq 1 "$NUM_NODES"); do
port=$((RPC_PORT_BASE + i - 1))
state=$(curl -sf "http://localhost:$port" \
state=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$port" \
-d '{"method":"server_info"}' 2>/dev/null |
jq -r '.result.info.server_state' 2>/dev/null || echo "")
if [ "$state" = "proposing" ]; then
@@ -552,7 +558,7 @@ echo ""
# Wait for first validated ledger.
log "Waiting for validated ledger..."
for attempt in $(seq 1 60); do
val_seq=$(curl -sf "http://localhost:$RPC_PORT_BASE" \
val_seq=$(curl -sf --max-time "$CURL_MAX_TIME" "http://localhost:$RPC_PORT_BASE" \
-d '{"method":"server_info"}' 2>/dev/null |
jq -r '.result.info.validated_ledger.seq // 0' 2>/dev/null || echo 0)
if [ "$val_seq" -gt 2 ] 2>/dev/null; then
@@ -600,7 +606,7 @@ fi
# ---------------------------------------------------------------------------
# Log-trace correlation has four legs and a failed check names none of them:
# the node must write a debug.log line carrying trace ids, the collector
# container must see that file, its filelog receiver must parse and export the
# container must see that file, its file_log receiver must parse and export the
# line, and Loki must return it for the validator's own LogQL. Each leg below
# reports what it observed, so a reader with only the CI log can tell which one
# broke instead of guessing.
@@ -698,7 +704,7 @@ diag_node_logs() {
local i log bytes total correlated sample
echo " [leg 1/4 node] debug.log lines matching '$DIAG_TRACE_RE'"
for i in $(seq 1 "$NUM_NODES"); do
log="$WORKDIR/node$i/debug.log"
log="$WORKDIR/validator-$i/debug.log"
if [ ! -f "$log" ]; then
echo " node$i: no debug.log at $log — the node never opened its log sink"
continue
@@ -780,10 +786,10 @@ diag_collector_mount() {
sed 's/^/ /' || echo " (container-side listing failed)"
}
# Leg 3 — collector: did the filelog receiver parse and export those lines?
# Leg 3 — collector: did the file_log receiver parse and export those lines?
#
# Two independent readings. The collector's own stderr names every file the
# receiver opened and carries any filelog parse or Loki export error. Its
# receiver opened and carries any file_log parse or Loki export error. Its
# internal telemetry counts log records in and out: accepted>0 with sent=0 is
# an export failure, accepted=0 while files are being watched is a parse
# failure.
@@ -795,7 +801,7 @@ diag_collector_mount() {
# exists; when it reports nothing matching, the leg says so.
diag_collector_pipeline() {
local cid img watched problems metrics
echo " [leg 3/4 collector] filelog receiver state"
echo " [leg 3/4 collector] file_log receiver state"
if ! command -v docker >/dev/null 2>&1; then
echo " docker is not on PATH — leg skipped"
return 0
@@ -816,12 +822,12 @@ diag_collector_pipeline() {
# Second filter keys on the collector's own logs-pipeline markers so this
# does not report warnings from the trace or metric pipelines. Nothing is
# excluded beyond that: the collector's benign config-alias deprecation
# notices ("filelog" -> "file_log") do surface here, and suppressing lines
# notices ("file_log" -> "file_log") do surface here, and suppressing lines
# because they are usually harmless is how a diagnostic hides the one that
# was not.
problems=$(diag_run docker logs "$cid" 2>&1 |
grep -iE '(warn|error)' |
grep -iE 'filelog|fileconsumer|loki|signal": *"logs' |
grep -iE 'file_log|fileconsumer|loki|signal": *"logs' |
tail -n 20 || true)
if [ -n "$problems" ]; then
echo " logs-pipeline warnings and errors (last 20):"
@@ -863,7 +869,7 @@ diag_loki_stream() {
[ -n "$selector" ] || selector="$DIAG_LOG_SELECTOR"
[ -n "$correlation" ] || correlation="$DIAG_LOG_SELECTOR $DIAG_LOG_FILTER"
# sum() is required, for the reason recorded at _log_loki_diagnostics in
# validate_telemetry.py: the filelog regex_parser leaves message/timestamp
# validate_telemetry.py: the file_log regex_parser leaves message/timestamp
# as log-record attributes, Loki's OTLP path turns those into structured
# metadata that joins a metric query's label set, so an unaggregated
# count_over_time yields one series per log line and Loki rejects the query
@@ -1070,7 +1076,7 @@ echo " xrpld nodes ($NUM_NODES) are running:"
for i in $(seq 1 "$NUM_NODES"); do
rpc=$((RPC_PORT_BASE + i - 1))
ws=$((WS_PORT_BASE + i - 1))
pid=$(cat "$WORKDIR/node$i/xrpld.pid" 2>/dev/null || echo 'unknown')
pid=$(cat "$WORKDIR/validator-$i/xrpld.pid" 2>/dev/null || echo 'unknown')
echo " Node $i: RPC=$rpc WS=$ws PID=$pid"
done
echo ""

View File

@@ -192,6 +192,8 @@ class TxStats:
total_errors: Transactions that returned an error engine_result.
by_type: Per-transaction-type count of submissions.
errors_by_type: Per-transaction-type count of errors.
setup_failed: True if account setup never produced enough funded
accounts, so the timed loop never ran.
"""
total_submitted: int = 0
@@ -199,6 +201,7 @@ class TxStats:
total_errors: int = 0
by_type: dict[str, int] = field(default_factory=dict)
errors_by_type: dict[str, int] = field(default_factory=dict)
setup_failed: bool = False
def record(self, tx_type: str, success: bool) -> None:
"""Record the result of a transaction submission."""
@@ -223,6 +226,7 @@ class TxStats:
),
"by_type": self.by_type,
"errors_by_type": self.errors_by_type,
"setup_failed": self.setup_failed,
}
@@ -978,6 +982,10 @@ async def run_submitter(
len(accounts),
len(created),
)
# The caller turns this into a non-zero exit. Without it a funding
# failure looks like a clean run of zero transactions, and the run
# only fails later as "spans missing", which points nowhere.
stats.setup_failed = True
return stats
logger.info(
@@ -1078,6 +1086,12 @@ def main() -> None:
try:
custom = json.loads(args.weights)
weights = {k: int(v) for k, v in custom.items()}
if not weights or sum(weights.values()) <= 0:
logger.error(
"Invalid --weights: the values must sum to more than 0, got %s",
weights,
)
sys.exit(1)
logger.info("Using custom weights: %s", weights)
except (json.JSONDecodeError, ValueError) as exc:
logger.error("Invalid --weights JSON: %s", exc)
@@ -1101,6 +1115,11 @@ def main() -> None:
json.dump(summary, f, indent=2)
logger.info("Summary written to %s", args.output)
# After the report is written, so the failure is still diagnosable.
if stats.setup_failed:
logger.error("Account setup failed; no transactions were submitted.")
sys.exit(1)
if __name__ == "__main__":
main()

View File

@@ -1938,7 +1938,7 @@ async def _log_loki_diagnostics(session: aiohttp.ClientSession, loki_url: str) -
"Loki diagnostic: service_name values: %s", ", ".join(found) or "(none)"
)
# sum() is load-bearing, not cosmetic. The filelog receiver's regex_parser
# sum() is load-bearing, not cosmetic. The file_log receiver's regex_parser
# leaves message, timestamp, trace_id and span_id as log-record attributes,
# and Loki's OTLP path stores those as structured metadata, which joins the
# label set of a metric query. Because `message` and `timestamp` are unique
@@ -2558,6 +2558,48 @@ def _bounds_description(lo: float, hi: float | None, exclusive_lo: bool) -> str:
return desc
async def _poll_instant_query(
session: aiohttp.ClientSession,
prometheus_url: str,
query: str,
deadline: float,
) -> list[dict[str, Any]]:
"""Run an instant query, retrying until it returns series or time runs out.
A bounds check needs the sample value, so it cannot use the /api/v1/series
endpoint the metric checks poll. An instant query answers from the last
scrape, and a gauge that stops changing can fall out of it, so one attempt
is not enough to call the series absent.
Args:
session: aiohttp client session.
prometheus_url: Prometheus API base URL.
query: PromQL instant query.
deadline: Monotonic deadline. Never slept past.
Returns:
The result list, empty if nothing appeared before the deadline.
"""
while True:
async with session.get(
f"{prometheus_url}/api/v1/query", params={"query": query}
) as resp:
data = await resp.json()
# An error is not "not yet": a bad query never becomes good, so
# retrying it only burns the whole deadline. Raise instead, and let
# the caller report it against the check's own name.
if data.get("status") != "success":
raise RuntimeError(
"Prometheus rejected the query: "
f"{data.get('error') or data.get('status')}"
)
results = data.get("data", {}).get("result", [])
remaining = deadline - time.monotonic()
if results or remaining <= 0:
return results
await asyncio.sleep(min(METRIC_POLL_INTERVAL_SEC, remaining))
async def _check_parity_value(
session: aiohttp.ClientSession,
prometheus_url: str,
@@ -2581,18 +2623,20 @@ async def _check_parity_value(
check_name = f"parity.value_sanity.{name}"
try:
async with session.get(
f"{prometheus_url}/api/v1/query", params={"query": entry["query"]}
) as resp:
data = await resp.json()
results = data.get("data", {}).get("result", [])
deadline = time.monotonic() + METRIC_POLL_TIMEOUT_SEC
results = await _poll_instant_query(
session, prometheus_url, entry["query"], deadline
)
if not results:
return CheckResult(
name=check_name,
category="parity",
passed=False,
message=f"{name}: no data returned from Prometheus",
message=(
f"{name}: no data returned from Prometheus after "
f"{METRIC_POLL_TIMEOUT_SEC:g}s"
),
)
values: list[float] = []

View File

@@ -436,9 +436,16 @@ async def run_phase(
tasks = _launch_phase_tasks(phase, endpoints, report_dir, prefix)
if not tasks:
logger.warning(
"Phase %d: %s — no workload configured, skipping", phase_idx + 1, name
# An error, not a warning. The exit gate is built from phase errors and
# from error RATES, and both rates short-circuit to 0.0 when nothing was
# sent -- so a profile with a mistyped key ("rpcs", "RPC") would produce
# no traffic at all and still exit 0.
message = (
f"phase {phase_idx + 1} '{name}' configures no workload: "
"it declares neither 'rpc' nor 'tx'"
)
logger.error("%s", message)
result.errors.append(message)
return result
for label, report_path, task in tasks:

View File

@@ -14,7 +14,12 @@
# {{RPC_PORT}} — HTTP RPC port
# {{WS_PORT}} — WebSocket port
# {{PEER_PORT}} — Peer protocol port
# {{DATA_DIR}} — Node data directory
# {{DATA_DIR}} — Node data directory. Its last path segment must
# equal service_instance_id below: the collector's
# file_log receiver reads that segment off the log
# file path and stamps it as the Loki label
# service_instance_id, so a mismatch gives log lines
# a node name no trace or metric shares.
# {{VALIDATION_SEED}} — Validator seed from key generation
# {{VALIDATORS_FILE}} — Path to shared validators.txt
# {{IPS_FIXED}} — Peer addresses (one per line)

View File

@@ -93,10 +93,15 @@ docker/telemetry/data
# --- Logging ----------------------------------------------------------------
# Path is resolved relative to this config file's directory (docker/telemetry),
# so this writes to docker/telemetry/data/logs/devnet/debug.log — the same
# so this writes to docker/telemetry/data/logs/xrpld-devnet/debug.log — the same
# dir the compose stack bind-mounts into the collector as /var/log/xrpld.
#
# The subdirectory name must equal [telemetry] service_instance_id below. The
# collector reads it off the file path and stamps it as the Loki label
# service_instance_id, so a mismatch here means log lines carry a node name
# that no trace or metric shares, and nothing joins.
[debug_logfile]
data/logs/devnet/debug.log
data/logs/xrpld-devnet/debug.log
[rpc_startup]
{ "command": "log_level", "severity": "debug" }