mirror of
https://github.com/XRPLF/rippled.git
synced 2026-09-27 15:28:03 +00:00
feat(telemetry): gate log-trace correlation in CI with per-leg diagnostics
The two log-correlation checks have never executed in CI: the workflow
hardcoded --skip-loki, so validate_telemetry.py never constructed
log.trace_id_present or log.trace_id_cross_reference. A green Telemetry
Validation therefore carried no evidence that a log line reaches Loki with
trace context. Drop the flag so both checks run and can fail the job.
Correlation spans four independent legs and a failed check names none of
them, so run-full-validation.sh now prints a per-leg diagnostic after the
suite whenever the checks are enabled:
node per-node debug.log line count, the count matching the injected
trace_id/span_id shape, one sample line, and the severity mix,
so "no log at all", "log level too high" and "no active sampled
span" are distinguishable
mount the container-side listing of /var/log/xrpld, taken with the
collector's own mounts and uid. That image is built from
scratch and carries no shell, so the listing runs in a
throwaway container with --volumes-from, not via docker exec
collector the receiver's watched files, logs-pipeline warnings, and the
internal log-record counters, read from inside the container's
network namespace because that endpoint binds to the
container's own localhost and its port is not published
loki the exact query used, the label inventory, and entry counts for
the stream selector with and without the line filter, so "Loki
has nothing" and "Loki has lines but none carry a trace id" are
distinguishable
The diagnostics are non-fatal by construction: every leg runs in its own
subshell with errexit off, each docker and curl call is guarded, and the
coordinator always returns success. Verified with no containers and no Loki
reachable, with an emptied PATH, and with a leg forced to exit non-zero.
validate_telemetry.py gains a matching diagnostic beside the checks,
following _log_prometheus_metric_names: warnings only, never a check
result. Its stream selector and line filter move into module constants
that the shell diagnostic reads back, so the two cannot drift into
describing different queries.
No check was widened or auto-passed, and LOG_QUERY_WINDOW_SECONDS stays at
four hours; a wider window would let a check pass on a previous run's logs.
This commit is contained in:
Pratik Mankawde
2
.github/workflows/telemetry-validation.yml
vendored
2
.github/workflows/telemetry-validation.yml
vendored
@@ -234,7 +234,7 @@ jobs:
|
||||
# and never reads them. Load shape comes from the default
|
||||
# --profile full-validation. They are still passed so the flags stay
|
||||
# exercised if they are ever wired up.
|
||||
ARGS="--xrpld ${{ env.BUILD_DIR }}/xrpld --skip-loki"
|
||||
ARGS="--xrpld ${{ env.BUILD_DIR }}/xrpld"
|
||||
ARGS="$ARGS --rpc-rate $RPC_RATE"
|
||||
ARGS="$ARGS --rpc-duration $RPC_DURATION"
|
||||
ARGS="$ARGS --tx-tps $TX_TPS"
|
||||
|
||||
@@ -1044,7 +1044,8 @@ later metric families. The categories are:
|
||||
only asks Grafana for the dashboard and its panel count; it does not run the
|
||||
panel queries.
|
||||
- **Log-trace correlation** — `trace_id` present in Loki plus a Tempo reverse
|
||||
lookup (skipped in CI via `--skip-loki`, not absent from the suite)
|
||||
lookup (gated in CI; `run-full-validation.sh` prints a node/mount/collector/Loki
|
||||
diagnostic alongside them so a failure names the leg that broke)
|
||||
|
||||
See [Phase10_taskList.md](./Phase10_taskList.md) for the per-task breakdown.
|
||||
|
||||
@@ -1053,8 +1054,9 @@ See [Phase10_taskList.md](./Phase10_taskList.md) for the per-task breakdown.
|
||||
1. `rpc.process` -> `rpc.command.*` hierarchy — not assertable under the
|
||||
harness's WebSocket-only load, because `rpc.process` is created only on the
|
||||
HTTP path. This is a load-shape limitation, not a context-propagation bug.
|
||||
2. Log-trace correlation — implemented and passing locally; CI passes
|
||||
`--skip-loki`.
|
||||
2. Log-trace correlation — the two `validate_telemetry.py` checks are now gated
|
||||
in CI, but `integration-test.sh`'s own `check_log_correlation()` is still run
|
||||
by no workflow.
|
||||
3. Legacy `beast::insight` coverage — `expected_metrics.json` asserts a
|
||||
representative subset, not all ~270 families.
|
||||
4. Sustained load / backpressure — the `stress` profile exists in
|
||||
|
||||
@@ -400,27 +400,33 @@ Of the five `workflow_dispatch` inputs, only `run_benchmark` changes behaviour.
|
||||
them again — load shape comes entirely from `--profile` and
|
||||
`workload-profiles.json`. Their `description:` fields say so.
|
||||
|
||||
### What CI does not cover
|
||||
### Log-trace correlation in CI
|
||||
|
||||
The workflow invokes the harness with a hardcoded `--skip-loki`
|
||||
(`telemetry-validation.yml:237`), and `validate_telemetry.py` creates the
|
||||
`log.trace_id_present` and `log.trace_id_cross_reference` checks only inside an
|
||||
`if not skip_loki` branch (`validate_telemetry.py:1657`). Those two checks are
|
||||
therefore **never constructed on a CI run** — a green `Telemetry Validation`
|
||||
carries no evidence that log lines carry trace context or that a Tempo trace id
|
||||
resolves in Loki. `integration-test.sh` has its own `check_log_correlation()`, but
|
||||
no workflow runs that script either.
|
||||
The workflow no longer passes `--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
|
||||
its own `check_log_correlation()`, but no workflow runs that script.
|
||||
|
||||
Cover the gap locally by omitting the flag:
|
||||
Correlation depends on four independent legs, and a failed check on its own 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 line, and Loki must return it for the validator's LogQL.
|
||||
`run-full-validation.sh` prints a per-leg diagnostic after the suite whenever the
|
||||
Loki checks are enabled — per-node correlated-line counts and severity mix, the
|
||||
container-side view of `/var/log/xrpld`, the receiver's watched files and
|
||||
internal log-record counters, and Loki's own entry counts for the selector with
|
||||
and without the line filter. Read that block first; it identifies the broken leg
|
||||
without reproducing anything.
|
||||
|
||||
The same block prints locally:
|
||||
|
||||
```bash
|
||||
docker/telemetry/workload/run-full-validation.sh --xrpld .build/xrpld
|
||||
```
|
||||
|
||||
Do that after any change to log formatting, span activation, the collector's
|
||||
`filelog` receiver, or the Loki exporter. Removing `--skip-loki` from the workflow
|
||||
would make CI exercise Loki ingestion and filelog mounting for the first time, so
|
||||
it is held back as its own change rather than folded into an unrelated push.
|
||||
Re-run it after any change to log formatting, span activation, the collector's
|
||||
`filelog` receiver, or the Loki exporter.
|
||||
|
||||
### Pathfinding is not exercised
|
||||
|
||||
|
||||
@@ -87,6 +87,20 @@ BASELINE_FILE="${BASELINE_FILE:-$SCRIPT_DIR/baselines/baseline-timings.json}"
|
||||
THRESHOLDS_FILE="${THRESHOLDS_FILE:-$SCRIPT_DIR/regression-thresholds.json}"
|
||||
METRICS_FILE="${METRICS_FILE:-$SCRIPT_DIR/regression-metrics.json}"
|
||||
|
||||
# Loki API base URL. Matches validate_telemetry.py's DEFAULT_LOKI, so the
|
||||
# diagnostics below query the same instance the log-correlation checks do.
|
||||
LOKI_URL="${LOKI_URL:-http://localhost:3100}"
|
||||
# Query window for the Loki diagnostics, in seconds. MUST stay equal to
|
||||
# LOG_QUERY_WINDOW_SECONDS in validate_telemetry.py (4h): a diagnostic that
|
||||
# looked further back than the check would report entries the check cannot see,
|
||||
# which is the one way these numbers could mislead rather than explain.
|
||||
DIAG_LOG_WINDOW_SECONDS=14400
|
||||
# The shape Logs::format() actually injects: a 32-hex trace_id followed by a
|
||||
# 16-hex span_id, both lowercase (src/libxrpl/basics/Log.cpp). Matching the
|
||||
# exact widths rather than a loose "trace_id=" substring keeps a truncated or
|
||||
# all-zero id from being counted as a correlated line.
|
||||
DIAG_TRACE_RE='trace_id=[0-9a-f]{32} span_id=[0-9a-f]{16}'
|
||||
|
||||
GENESIS_ACCOUNT="rHb9CJAWyB4rj91VRWn96DkukG4bwdtyTh"
|
||||
GENESIS_SEED="snoPBrXtMeMyMHUVTgbuqAfg1SUTb"
|
||||
|
||||
@@ -528,6 +542,310 @@ else
|
||||
fold_exit 2
|
||||
fi
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Log-trace correlation diagnostics
|
||||
# ---------------------------------------------------------------------------
|
||||
# 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
|
||||
# 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.
|
||||
#
|
||||
# Everything here is diagnostic. Every leg runs in its own subshell with
|
||||
# errexit off, and every external call is guarded, so a missing container, a
|
||||
# wedged docker daemon or an unreachable endpoint degrades to a printed note.
|
||||
# A diagnostic must never be the reason a run fails.
|
||||
|
||||
# Fallback copies of the stream selector and line filter the log checks use.
|
||||
# Only reached when the constants cannot be read out of validate_telemetry.py
|
||||
# (see diag_validator_const); the module is the source of truth.
|
||||
DIAG_LOG_SELECTOR='{service_name="xrpld"}'
|
||||
DIAG_LOG_FILTER='|= "trace_id="'
|
||||
|
||||
# Bound every external call: a hung docker daemon or endpoint must not stall
|
||||
# the run. Absent coreutils' timeout the calls still run, just unbounded.
|
||||
DIAG_HAVE_TIMEOUT=false
|
||||
if command -v timeout >/dev/null 2>&1; then
|
||||
DIAG_HAVE_TIMEOUT=true
|
||||
fi
|
||||
|
||||
diag_run() {
|
||||
if [ "$DIAG_HAVE_TIMEOUT" = true ]; then
|
||||
timeout 20 "$@"
|
||||
else
|
||||
"$@"
|
||||
fi
|
||||
}
|
||||
|
||||
# Container id of the running collector; empty when it is not up.
|
||||
diag_collector_cid() {
|
||||
docker compose -f "$COMPOSE_FILE" ps -q otel-collector 2>/dev/null | head -1
|
||||
}
|
||||
|
||||
# An image from this same stack that carries a shell, used to look inside the
|
||||
# collector's mounts and network namespace.
|
||||
#
|
||||
# The collector's own image cannot serve: it is built from scratch and ships
|
||||
# only the binary, so `docker exec <collector> ls` fails with "executable file
|
||||
# not found in $PATH". Read from the compose config rather than from a running
|
||||
# container so it resolves even when that service is down, and taken from the
|
||||
# stack so this never pulls an image the run did not already need.
|
||||
diag_shell_image() {
|
||||
docker compose -f "$COMPOSE_FILE" config --format json 2>/dev/null |
|
||||
jq -r '.services.prometheus.image // empty' 2>/dev/null
|
||||
}
|
||||
|
||||
# Read a string constant out of validate_telemetry.py.
|
||||
#
|
||||
# Two copies of the same query would drift, and the copy with no check attached
|
||||
# is the one that ends up wrong — so the query is derived from the module that
|
||||
# runs the checks rather than restated here. $2 is the fallback, used only when
|
||||
# the import is impossible (e.g. aiohttp missing); it is the value the module
|
||||
# defines today, so the worst case is a stale literal rather than no output.
|
||||
diag_validator_const() {
|
||||
python3 -c \
|
||||
"import sys; sys.path.insert(0, '$SCRIPT_DIR'); import validate_telemetry as v; print(v.$1)" \
|
||||
2>/dev/null || printf '%s\n' "$2"
|
||||
}
|
||||
|
||||
# Sum an instant LogQL count over every stream it returns. Returns non-zero
|
||||
# when Loki could not be queried, which the caller reports as unavailable
|
||||
# rather than as zero — "Loki said none" and "Loki did not answer" are
|
||||
# different findings.
|
||||
diag_loki_count() {
|
||||
local body
|
||||
body=$(diag_run curl -sfG --max-time 10 "$LOKI_URL/loki/api/v1/query" \
|
||||
--data-urlencode "query=$1" --data-urlencode "time=$2" 2>/dev/null) || return 1
|
||||
printf '%s' "$body" |
|
||||
jq -er '[.data.result[].value[1] | tonumber] | add // 0' 2>/dev/null || return 1
|
||||
}
|
||||
|
||||
# Leg 1 — node: does xrpld emit correlated lines at all?
|
||||
#
|
||||
# Separates the three node-side failures that all surface as "no correlated
|
||||
# logs": no debug.log at all (the node died before opening its log sink), a log
|
||||
# level too high to reach the correlated call sites (severity mix shows no
|
||||
# NFO), and lines flowing but none emitted inside an active sampled span
|
||||
# (correlated=0 alongside a healthy severity mix).
|
||||
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"
|
||||
if [ ! -f "$log" ]; then
|
||||
echo " node$i: no debug.log at $log — the node never opened its log sink"
|
||||
continue
|
||||
fi
|
||||
bytes=$(wc -c <"$log" 2>/dev/null || echo 0)
|
||||
total=$(wc -l <"$log" 2>/dev/null || echo 0)
|
||||
# grep -c exits 1 on zero matches but still prints the count, so the
|
||||
# guard keeps the 0 rather than replacing it with an empty string.
|
||||
correlated=$(grep -cE "$DIAG_TRACE_RE" "$log" 2>/dev/null || true)
|
||||
echo " node$i: bytes=$bytes lines=$total correlated=${correlated:-0}"
|
||||
# Severity mix from the '[partition:]SEV' token, which Logs::format()
|
||||
# writes as the 4th whitespace-separated field. Fixed key order so two
|
||||
# runs' output can be diffed directly. Lines whose 4th field is not a
|
||||
# severity code are message continuations, counted as unparsed.
|
||||
awk '{
|
||||
n = split($4, f, ":")
|
||||
s = f[n]
|
||||
if (s ~ /^(TRC|DBG|NFO|WRN|ERR|FTL)$/)
|
||||
c[s]++
|
||||
else
|
||||
other++
|
||||
}
|
||||
END {
|
||||
split("TRC DBG NFO WRN ERR FTL", order, " ")
|
||||
line = ""
|
||||
for (k = 1; k <= 6; k++)
|
||||
line = line sprintf("%s=%d ", order[k], c[order[k]] + 0)
|
||||
printf " severity: %sunparsed=%d\n", line, other + 0
|
||||
}' "$log" 2>/dev/null || echo " severity: (could not be computed)"
|
||||
sample=$(grep -m1 -E "$DIAG_TRACE_RE" "$log" 2>/dev/null || true)
|
||||
if [ -n "$sample" ]; then
|
||||
printf ' sample: %.200s\n' "$sample"
|
||||
fi
|
||||
done
|
||||
}
|
||||
|
||||
# Leg 2 — mount: does the collector container see those files?
|
||||
#
|
||||
# A correct host-side log with an empty container-side view is the signature of
|
||||
# a mount or permission problem. The listing runs in a throwaway container
|
||||
# started with --volumes-from and the collector's own uid, so it reproduces the
|
||||
# collector's exact mount set and access rights instead of the host's.
|
||||
diag_collector_mount() {
|
||||
local cid img usr binds
|
||||
local -a user_flag=()
|
||||
echo " [leg 2/4 mount] container-side view of /var/log/xrpld"
|
||||
if ! command -v docker >/dev/null 2>&1; then
|
||||
echo " docker is not on PATH — leg skipped"
|
||||
return 0
|
||||
fi
|
||||
cid=$(diag_collector_cid)
|
||||
if [ -z "$cid" ]; then
|
||||
echo " otel-collector container is not running — leg skipped"
|
||||
return 0
|
||||
fi
|
||||
echo " binds declared on the container:"
|
||||
binds=$(diag_run docker inspect \
|
||||
-f '{{range .Mounts}}{{.Type}} {{.Source}} -> {{.Destination}} rw={{.RW}}{{"\n"}}{{end}}' \
|
||||
"$cid" 2>/dev/null || true)
|
||||
if [ -n "$binds" ]; then
|
||||
printf '%s\n' "$binds" | sed '/^[[:space:]]*$/d; s/^/ /'
|
||||
else
|
||||
echo " (docker inspect reported no mounts)"
|
||||
fi
|
||||
img=$(diag_shell_image)
|
||||
if [ -z "$img" ]; then
|
||||
echo " no stack image with a shell resolved — container-side listing skipped"
|
||||
return 0
|
||||
fi
|
||||
usr=$(diag_run docker inspect -f '{{.Config.User}}' "$cid" 2>/dev/null || true)
|
||||
if [ -n "$usr" ]; then
|
||||
user_flag=(--user "$usr")
|
||||
fi
|
||||
echo " listing as uid '${usr:-<image default>}' using $img:"
|
||||
diag_run docker run --rm --volumes-from "$cid" \
|
||||
${user_flag[@]+"${user_flag[@]}"} --entrypoint /bin/sh "$img" -c \
|
||||
'ls -la /var/log/xrpld 2>&1
|
||||
find /var/log/xrpld -maxdepth 2 -name debug.log -exec ls -l {} \; 2>&1' |
|
||||
sed 's/^/ /' || echo " (container-side listing failed)"
|
||||
}
|
||||
|
||||
# Leg 3 — collector: did the filelog 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
|
||||
# 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.
|
||||
#
|
||||
# That telemetry endpoint binds to the container's own localhost and its port
|
||||
# is not published, so it is unreachable from the host and is read from inside
|
||||
# the container's network namespace instead. The names below are a filter over
|
||||
# whatever the collector reports, not an assertion that any given series
|
||||
# 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"
|
||||
if ! command -v docker >/dev/null 2>&1; then
|
||||
echo " docker is not on PATH — leg skipped"
|
||||
return 0
|
||||
fi
|
||||
cid=$(diag_collector_cid)
|
||||
if [ -z "$cid" ]; then
|
||||
echo " otel-collector container is not running — leg skipped"
|
||||
return 0
|
||||
fi
|
||||
watched=$(diag_run docker logs "$cid" 2>&1 |
|
||||
grep -F 'Started watching file' | grep -oE '"path": "[^"]*"' | sort -u || true)
|
||||
if [ -n "$watched" ]; then
|
||||
echo " files the receiver opened:"
|
||||
printf '%s\n' "$watched" | sed 's/^/ /'
|
||||
else
|
||||
echo " the receiver reported opening no files"
|
||||
fi
|
||||
# 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
|
||||
# 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' |
|
||||
tail -n 20 || true)
|
||||
if [ -n "$problems" ]; then
|
||||
echo " logs-pipeline warnings and errors (last 20):"
|
||||
printf '%s\n' "$problems" | cut -c1-300 | sed 's/^/ /'
|
||||
else
|
||||
echo " no logs-pipeline warnings or errors in the collector's output"
|
||||
fi
|
||||
img=$(diag_shell_image)
|
||||
if [ -z "$img" ]; then
|
||||
echo " no stack image with a shell resolved — internal telemetry skipped"
|
||||
return 0
|
||||
fi
|
||||
metrics=$(diag_run docker run --rm --network "container:$cid" \
|
||||
--entrypoint /bin/sh "$img" -c \
|
||||
'wget -qO- --timeout=5 http://localhost:8888/metrics 2>/dev/null' 2>/dev/null |
|
||||
grep -E '^otelcol_([a-z]+_)*log_records|^otelcol_fileconsumer' || true)
|
||||
if [ -n "$metrics" ]; then
|
||||
echo " collector internal log-record counters:"
|
||||
printf '%s\n' "$metrics" | sed 's/^/ /'
|
||||
else
|
||||
echo " collector internal telemetry reported no log-record counters"
|
||||
fi
|
||||
}
|
||||
|
||||
# Leg 4 — Loki: is the entry queryable by the validator's own LogQL?
|
||||
#
|
||||
# Counts the selector on its own and the selector plus line filter separately,
|
||||
# so "Loki has nothing" is distinguishable from "Loki has lines but none carry
|
||||
# a trace id". The label inventory catches the third case: entries ingested
|
||||
# under a label set the validator's selector cannot match.
|
||||
diag_loki_stream() {
|
||||
local now selector correlation query_all query_filtered
|
||||
local total matching labels values sample
|
||||
echo " [leg 4/4 loki] entries in the last ${DIAG_LOG_WINDOW_SECONDS}s (the window the checks use)"
|
||||
now=$(date +%s)
|
||||
selector=$(diag_validator_const LOG_STREAM_SELECTOR "$DIAG_LOG_SELECTOR")
|
||||
correlation=$(diag_validator_const LOG_CORRELATION_QUERY \
|
||||
"$DIAG_LOG_SELECTOR $DIAG_LOG_FILTER")
|
||||
[ -n "$selector" ] || selector="$DIAG_LOG_SELECTOR"
|
||||
[ -n "$correlation" ] || correlation="$DIAG_LOG_SELECTOR $DIAG_LOG_FILTER"
|
||||
query_all="count_over_time($selector[${DIAG_LOG_WINDOW_SECONDS}s])"
|
||||
query_filtered="count_over_time($correlation [${DIAG_LOG_WINDOW_SECONDS}s])"
|
||||
echo " validator LogQL: $correlation"
|
||||
echo " diagnostic LogQL: $query_all"
|
||||
echo " $query_filtered"
|
||||
labels=$(diag_run curl -sf --max-time 10 "$LOKI_URL/loki/api/v1/labels" 2>/dev/null |
|
||||
jq -r '.data // [] | join(", ")' 2>/dev/null || true)
|
||||
values=$(diag_run curl -sf --max-time 10 \
|
||||
"$LOKI_URL/loki/api/v1/label/service_name/values" 2>/dev/null |
|
||||
jq -r '.data // [] | join(", ")' 2>/dev/null || true)
|
||||
echo " stream labels Loki knows: ${labels:-<none or unreachable>}"
|
||||
echo " service_name values: ${values:-<none or unreachable>}"
|
||||
if total=$(diag_loki_count "$query_all" "$now"); then
|
||||
echo " entries matching the selector: $total"
|
||||
else
|
||||
echo " entries matching the selector: unavailable (Loki did not answer)"
|
||||
fi
|
||||
if matching=$(diag_loki_count "$query_filtered" "$now"); then
|
||||
echo " entries also matching the line filter: $matching"
|
||||
else
|
||||
echo " entries also matching the line filter: unavailable (Loki did not answer)"
|
||||
fi
|
||||
sample=$(diag_run curl -sfG --max-time 10 "$LOKI_URL/loki/api/v1/query_range" \
|
||||
--data-urlencode "query=$correlation" \
|
||||
--data-urlencode "start=$((now - DIAG_LOG_WINDOW_SECONDS))000000000" \
|
||||
--data-urlencode "end=${now}000000000" \
|
||||
--data-urlencode "limit=1" --data-urlencode "direction=backward" 2>/dev/null |
|
||||
jq -r '.data.result[0].values[0][1] // empty' 2>/dev/null || true)
|
||||
if [ -n "$sample" ]; then
|
||||
printf ' sample entry: %.200s\n' "$sample"
|
||||
fi
|
||||
}
|
||||
|
||||
# Run every leg, isolated. Each subshell disables errexit and nounset so a leg
|
||||
# that trips still prints what it had, and its failure is reported rather than
|
||||
# propagated. Always returns success.
|
||||
run_log_correlation_diagnostics() {
|
||||
local leg
|
||||
echo ""
|
||||
echo "--- Log-trace correlation diagnostics (non-fatal, for attribution only) ---"
|
||||
for leg in diag_node_logs diag_collector_mount diag_collector_pipeline diag_loki_stream; do
|
||||
(
|
||||
set +e +u +o pipefail
|
||||
"$leg"
|
||||
) || warn "$leg: the diagnostic itself failed — ignored"
|
||||
done
|
||||
echo ""
|
||||
return 0
|
||||
}
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
# Step 5: Run telemetry validation suite
|
||||
# ---------------------------------------------------------------------------
|
||||
@@ -546,6 +864,15 @@ if [ "$VALIDATION_EXIT" -eq 0 ]; then
|
||||
else
|
||||
fail "Some telemetry validation checks failed (exit $VALIDATION_EXIT)"
|
||||
fi
|
||||
|
||||
# Only when the log-correlation checks actually ran: with --skip-loki there is
|
||||
# no result to attribute. Runs whether they passed or failed — the same numbers
|
||||
# that explain a failure are what proves a pass was not a coincidence. Placed
|
||||
# after the suite so its Loki counts are never earlier than the checks' own.
|
||||
if [ "$SKIP_LOKI" != true ]; then
|
||||
run_log_correlation_diagnostics
|
||||
fi
|
||||
|
||||
fold_exit "$VALIDATION_EXIT"
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
@@ -48,6 +48,16 @@ import aiohttp
|
||||
# someone re-runs it later to investigate a result.
|
||||
LOG_QUERY_WINDOW_SECONDS = 4 * 60 * 60
|
||||
|
||||
# Loki's OTLP ingestion promotes service.name to the stream label
|
||||
# `service_name`; a `job` attribute arrives as structured metadata, which a
|
||||
# stream selector cannot match (see otel-collector-config.yaml). Declared once
|
||||
# so both log checks and the diagnostic below report on the same query -- a
|
||||
# diagnostic that queried something else would describe a different failure
|
||||
# than the one being investigated.
|
||||
LOG_STREAM_SELECTOR = '{service_name="xrpld"}'
|
||||
LOG_TRACE_LINE_FILTER = '|= "trace_id="'
|
||||
LOG_CORRELATION_QUERY = f"{LOG_STREAM_SELECTOR} {LOG_TRACE_LINE_FILTER}"
|
||||
|
||||
logger = logging.getLogger("validate_telemetry")
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
@@ -1290,6 +1300,118 @@ async def _check_metric_label(
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
|
||||
async def _loki_json(
|
||||
session: aiohttp.ClientSession,
|
||||
loki_url: str,
|
||||
path: str,
|
||||
params: dict[str, str] | None = None,
|
||||
) -> dict[str, Any] | None:
|
||||
"""GET one Loki API path and decode it, or None if that failed.
|
||||
|
||||
Diagnostic-only helper: every failure is a warning, so one unreachable
|
||||
endpoint does not suppress the rest of the diagnostic.
|
||||
|
||||
Args:
|
||||
session: aiohttp client session.
|
||||
loki_url: Loki API base URL.
|
||||
path: API path, including its leading slash.
|
||||
params: Optional query parameters.
|
||||
|
||||
Returns:
|
||||
The decoded response body, or None when the request or decode failed.
|
||||
"""
|
||||
try:
|
||||
async with session.get(f"{loki_url}{path}", params=params or {}) as resp:
|
||||
return await resp.json()
|
||||
except Exception as exc: # noqa: BLE001 - diagnostic must never raise
|
||||
logger.warning("Loki diagnostic: GET %s failed: %s", path, exc)
|
||||
return None
|
||||
|
||||
|
||||
async def _loki_count(
|
||||
session: aiohttp.ClientSession, loki_url: str, query: str
|
||||
) -> int | None:
|
||||
"""Sum an instant LogQL count over every stream it returns.
|
||||
|
||||
Returns None rather than 0 when Loki could not be queried. "Loki holds
|
||||
none" and "Loki did not answer" are different findings, and printing the
|
||||
same number for both is how a diagnostic misleads.
|
||||
|
||||
Args:
|
||||
session: aiohttp client session.
|
||||
loki_url: Loki API base URL.
|
||||
query: An instant LogQL metric query.
|
||||
|
||||
Returns:
|
||||
Total entry count, or None when the query could not be evaluated.
|
||||
"""
|
||||
params = {"query": query, "time": str(int(time.time()))}
|
||||
data = await _loki_json(session, loki_url, "/loki/api/v1/query", params)
|
||||
if data is None:
|
||||
return None
|
||||
try:
|
||||
results = data.get("data", {}).get("result", [])
|
||||
return sum(int(float(entry["value"][1])) for entry in results)
|
||||
except Exception as exc: # noqa: BLE001 - diagnostic must never raise
|
||||
logger.warning("Loki diagnostic: could not read count for %s: %s", query, exc)
|
||||
return None
|
||||
|
||||
|
||||
async def _log_loki_diagnostics(session: aiohttp.ClientSession, loki_url: str) -> None:
|
||||
"""Log what Loki holds for the stream the correlation checks select.
|
||||
|
||||
Same role as _log_prometheus_metric_names on the metric side, and the same
|
||||
contract: diagnostic only, every failure a warning, never a check result.
|
||||
A failed correlation check says a log line was not found; these numbers say
|
||||
which of the three Loki-side reasons applies — nothing was ingested at all,
|
||||
entries exist but none carry a trace id, or entries arrived under a label
|
||||
set this selector cannot match (which the label inventory exposes).
|
||||
|
||||
Counted over exactly LOG_QUERY_WINDOW_SECONDS, the window the checks use.
|
||||
A wider window here would report entries the checks cannot see, including a
|
||||
previous run's, and describe a failure that is not the one at hand.
|
||||
|
||||
Args:
|
||||
session: aiohttp client session.
|
||||
loki_url: Loki API base URL.
|
||||
"""
|
||||
window = f"[{LOG_QUERY_WINDOW_SECONDS}s]"
|
||||
logger.info("Loki diagnostic: the checks below query %s", LOG_CORRELATION_QUERY)
|
||||
|
||||
labels = await _loki_json(session, loki_url, "/loki/api/v1/labels")
|
||||
if labels is not None:
|
||||
names = labels.get("data") or []
|
||||
logger.info(
|
||||
"Loki diagnostic: stream labels Loki knows: %s",
|
||||
", ".join(names) or "(none)",
|
||||
)
|
||||
|
||||
values = await _loki_json(
|
||||
session, loki_url, "/loki/api/v1/label/service_name/values"
|
||||
)
|
||||
if values is not None:
|
||||
found = values.get("data") or []
|
||||
logger.info(
|
||||
"Loki diagnostic: service_name values: %s", ", ".join(found) or "(none)"
|
||||
)
|
||||
|
||||
for label, query in (
|
||||
("selector only", f"count_over_time({LOG_STREAM_SELECTOR}{window})"),
|
||||
(
|
||||
"selector + line filter",
|
||||
f"count_over_time({LOG_CORRELATION_QUERY} {window})",
|
||||
),
|
||||
):
|
||||
total = await _loki_count(session, loki_url, query)
|
||||
logger.info(
|
||||
"Loki diagnostic: %s = %s entries in the last %ds [%s]",
|
||||
label,
|
||||
"unavailable" if total is None else total,
|
||||
LOG_QUERY_WINDOW_SECONDS,
|
||||
query,
|
||||
)
|
||||
|
||||
|
||||
async def validate_log_trace_correlation(
|
||||
session: aiohttp.ClientSession,
|
||||
loki_url: str,
|
||||
@@ -1310,13 +1432,14 @@ async def validate_log_trace_correlation(
|
||||
"""
|
||||
logger.info("--- Log-Trace Correlation Validation (Loki) ---")
|
||||
|
||||
# Numbers first, so a failure below is read next to the state that caused
|
||||
# it. Never raises and never adds a check (see _log_loki_diagnostics).
|
||||
await _log_loki_diagnostics(session, loki_url)
|
||||
|
||||
# Check 1: Any logs with trace_id exist.
|
||||
try:
|
||||
params = {
|
||||
# Loki's OTLP ingestion promotes service.name to the label
|
||||
# `service_name`. A `job` attribute is structured metadata, which a
|
||||
# stream selector cannot match — see otel-collector-config.yaml.
|
||||
"query": '{service_name="xrpld"} |= "trace_id="',
|
||||
"query": LOG_CORRELATION_QUERY,
|
||||
"limit": 5,
|
||||
"direction": "backward",
|
||||
**_log_query_window(),
|
||||
@@ -1360,7 +1483,7 @@ async def validate_log_trace_correlation(
|
||||
# written to a log must resolve to a trace that was actually exported.
|
||||
try:
|
||||
loki_params = {
|
||||
"query": '{service_name="xrpld"} |= "trace_id="',
|
||||
"query": LOG_CORRELATION_QUERY,
|
||||
"limit": 5,
|
||||
"direction": "backward",
|
||||
**_log_query_window(),
|
||||
|
||||
@@ -2774,7 +2774,7 @@ The sampled check is normally satisfied on a self-rooted consensus round — hea
|
||||
|
||||
With all four satisfied, `info` is the minimum level at which the `log.trace_id_present` and `log.trace_id_cross_reference` checks pass by construction, and it is what the correlation-checking harnesses generate: the cfgs written by [run-full-validation.sh](../docker/telemetry/workload/run-full-validation.sh) and [integration-test.sh](../docker/telemetry/integration-test.sh) each set `enabled=1`, `trace_consensus=1` and `log_level info` together. `benchmark.sh` deliberately does not — it stays at `warning` to keep log I/O out of the overhead measurement, and it runs no correlation check. At `warning` and above that pair is suppressed and correlation becomes incidental — dependent on a `warn`-or-worse line happening to fire inside some active span.
|
||||
|
||||
> **CI does not exercise either check.** `log.trace_id_present` and `log.trace_id_cross_reference` never run in CI — see [Coverage gap](#ci-workflow) for why. Cover them locally, without `--skip-loki`, after any change to log formatting, span activation, the `filelog` receiver or the Loki exporter:
|
||||
> **CI exercises both checks.** `log.trace_id_present` and `log.trace_id_cross_reference` are gated on every CI run — see [CI workflow](#ci-workflow) for the invocation and the per-leg diagnostics printed alongside them. Run the same thing locally after any change to log formatting, span activation, the `filelog` receiver or the Loki exporter:
|
||||
>
|
||||
> ```bash
|
||||
> docker/telemetry/workload/run-full-validation.sh --xrpld .build/xrpld
|
||||
@@ -3602,7 +3602,7 @@ Harness options (`run-full-validation.sh`):
|
||||
| `--xrpld PATH` | `.build/xrpld` | Binary to run. Also settable via the `XRPLD` env var. |
|
||||
| `--nodes NUM` | `5` | Size of the local validator cluster. |
|
||||
| `--profile NAME` | `full-validation` | Load profile from `workload-profiles.json` (`full-validation`, `quick-smoke`, `stress`). This is the **only** thing that sets load shape. |
|
||||
| `--skip-loki` | off | Skip the log-trace correlation checks. CI always passes this. |
|
||||
| `--skip-loki` | off | Skip the log-trace correlation checks and their per-leg diagnostics. Local exploration only; CI does not pass this. |
|
||||
| `--skip-regression` | off | Skip timing capture and the baseline comparison. Local exploration only. |
|
||||
| `--with-benchmark` | off | Also run `benchmark.sh` (telemetry-off vs telemetry-on overhead) after validation. |
|
||||
| `--cleanup` | — | Tear everything down and exit. |
|
||||
@@ -3625,9 +3625,9 @@ stands today.
|
||||
| ---------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
|
||||
| Spans | Every **required** entry in `expected_spans.json` — 41 span types at the time of writing: 25 required, 16 marked `"optional": true` | Span name found in Tempo carrying its `required_attributes`, plus the declared parent-child relationships. An `"optional": true` entry that does not fire is recorded as a skip, not a failure — it needs traffic the harness may not generate (HTTP/JSON-RPC client, gRPC client, missing-ledger fetch, mode transitions) or that it deliberately no longer generates (path-finding RPC — see "Pathfinding is not exercised" in [the workload README](../docker/telemetry/workload/README.md)). |
|
||||
| Metrics | Every entry in every asserted category of `expected_metrics.json` — 84 checks across 25 asserting categories at the time of writing: 79 metric names plus 5 `required_labels` checks | SpanMetrics, `beast::insight` gauges/counters exported over OTLP, and the `MetricsRegistry` OTLP metrics. Each must have > 0 Prometheus series; none are optional. A category may also declare `required_labels`, and each label there becomes one additional check that at least one of that category's series carries it with a non-empty value (matched as `<label>!=""`, because Prometheus cannot distinguish an absent label from an empty one). Those labels were declared but never actually read until the check was generalised, so they were documented as required while going unverified; `spanmetrics` contributes 4 and `job_queue` 1. The separate `not_asserted` group lists metrics deliberately left out of the gate because they are workload-gated or defect-gated; it has neither a `metrics` nor a `required_labels` key, so the validator skips it entirely. |
|
||||
| Logs | 2 checks | `trace_id`/`span_id` present in Loki, and a Tempo trace id resolves in Loki. Skipped in CI, which runs `--skip-loki`. |
|
||||
| Logs | 2 checks | `trace_id`/`span_id` present in Loki, and a logged trace id resolves in Tempo. Gated in CI. `run-full-validation.sh` prints a four-leg diagnostic (node, mount, collector, Loki) after the suite whenever these run, so a failure names the leg that broke. |
|
||||
| Parity | 10 checks | 6 span attributes the external-parity dashboard panels read, plus 4 metric value-sanity bounds. |
|
||||
| Dashboards | Every uid in `expected_metrics.json` under `grafana_dashboards.uids` — currently all 15 provisioned dashboards | Each listed dashboard loads and reports a panel count. This is a provisioning check only: it does **not** execute the panels' queries, so a dashboard can pass while individual panels render empty. `log-derived-insights` is Loki-backed, so under `--skip-loki` only its provisioning is meaningfully covered. |
|
||||
| Dashboards | Every uid in `expected_metrics.json` under `grafana_dashboards.uids` — currently all 15 provisioned dashboards | Each listed dashboard loads and reports a panel count. This is a provisioning check only: it does **not** execute the panels' queries, so a dashboard can pass while individual panels render empty. `log-derived-insights` is Loki-backed, so only its provisioning is covered here; its data path is covered by the two log checks instead. |
|
||||
| Reverse coverage | 2 checks — `metric.reverse_coverage` and `span.reverse_coverage` | The only checks that run in the opposite direction: they read the full emitted inventory (the Prometheus `__name__` label values, the Tempo `span.name` tag values) and name everything the contract never mentions, sorted and one per line in the log. **Warn only — `passed` is hardcoded `True` in `_reverse_coverage_result`, so these can never fail CI.** Downstream branches legitimately add telemetry an upstream contract has not seen, and a hard failure would redden all of them. A metric family is accounted for by a `metrics` entry, by a `not_asserted.metrics_excluded` key, or by an anchored regex under the top-level `accounted_patterns` list — which exists for families whose membership is derived mechanically from a table in the code (the per-job-type job-queue instruments, the overlay per-category traffic cross product) plus the Prometheus scrape plumbing that is not xrpld telemetry. Histogram `_bucket`/`_count`/`_sum` names fold onto their base family before matching. Spans need no pattern list: the check reuses the forward matcher, so `rpc.command.*` covers every command it expands to. |
|
||||
|
||||
### Running Individual Tools
|
||||
@@ -3808,20 +3808,23 @@ container as the main CI, so Conan and ccache hit the shared caches), and
|
||||
the workflow file, `docker/telemetry/**`, and the telemetry sources under
|
||||
`include/xrpl/telemetry/**`, `src/libxrpl/telemetry/**` and
|
||||
`src/xrpld/telemetry/**`. There is no cron schedule.
|
||||
- **Invocation**: `run-full-validation.sh --xrpld <binary> --skip-loki`, so the
|
||||
default `full-validation` profile is used and the Loki checks are skipped.
|
||||
- **Coverage gap — log-trace correlation is never checked in CI**: the
|
||||
`--skip-loki` above is hardcoded at
|
||||
[telemetry-validation.yml:237](../.github/workflows/telemetry-validation.yml#L237),
|
||||
and `validate_telemetry.py` creates `log.trace_id_present` and
|
||||
`log.trace_id_cross_reference` only inside an `if not skip_loki` branch
|
||||
([:1657](../docker/telemetry/workload/validate_telemetry.py#L1657)), so those
|
||||
two checks are not merely skipped — they are never constructed and never appear
|
||||
in the report. `docker/telemetry/integration-test.sh` (which has its own
|
||||
`check_log_correlation()`) is run by no workflow at all. A green
|
||||
`Telemetry Validation` therefore carries no evidence about correlation; run it
|
||||
locally without the flag to cover it:
|
||||
`docker/telemetry/workload/run-full-validation.sh --xrpld .build/xrpld`.
|
||||
- **Invocation**: `run-full-validation.sh --xrpld <binary>`, so the default
|
||||
`full-validation` profile is used and no category is skipped.
|
||||
- **Log-trace correlation is gated**: `--skip-loki` is not passed
|
||||
([telemetry-validation.yml:237](../.github/workflows/telemetry-validation.yml#L237)),
|
||||
so `log.trace_id_present` and `log.trace_id_cross_reference` are constructed and
|
||||
can fail the job. Correlation spans four independent legs — node, mount,
|
||||
collector, Loki — and a failed check names none of them, so
|
||||
`run-full-validation.sh` prints a per-leg diagnostic after the suite whenever
|
||||
these checks are enabled: per-node counts of `debug.log` lines carrying the
|
||||
injected `trace_id`/`span_id` shape plus the severity mix, the container-side
|
||||
listing of `/var/log/xrpld` taken with the collector's own mounts and uid, the
|
||||
`filelog` receiver's watched files, logs-pipeline warnings and internal
|
||||
log-record counters, and Loki's entry counts for the stream selector with and
|
||||
without the line filter. The diagnostics are non-fatal by construction: each
|
||||
leg is isolated and a missing container or unreachable endpoint prints a note.
|
||||
`docker/telemetry/integration-test.sh` (which has its own
|
||||
`check_log_correlation()`) is still run by no workflow.
|
||||
- **Inputs**: only `run_benchmark` changes behaviour. `rpc_rate`, `rpc_duration`,
|
||||
`tx_tps` and `tx_duration` are inert, as noted in their descriptions.
|
||||
- **Results**: reports are uploaded as the `telemetry-validation-reports`
|
||||
|
||||
Reference in New Issue
Block a user