From c65cb0e2a89e5ba886bce1df61b79c652bdf10ae Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Tue, 25 Aug 2026 18:20:38 +0100 Subject: [PATCH] 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. --- .github/workflows/telemetry-validation.yml | 2 +- OpenTelemetryPlan/06-implementation-phases.md | 8 +- docker/telemetry/workload/README.md | 34 +- .../telemetry/workload/run-full-validation.sh | 327 ++++++++++++++++++ .../telemetry/workload/validate_telemetry.py | 133 ++++++- docs/telemetry-runbook.md | 39 ++- 6 files changed, 502 insertions(+), 41 deletions(-) diff --git a/.github/workflows/telemetry-validation.yml b/.github/workflows/telemetry-validation.yml index 55c81d4465..8cb1305c32 100644 --- a/.github/workflows/telemetry-validation.yml +++ b/.github/workflows/telemetry-validation.yml @@ -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" diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index 4e925d16fb..9be3127c15 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -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 diff --git a/docker/telemetry/workload/README.md b/docker/telemetry/workload/README.md index 80af47300e..5c10527978 100644 --- a/docker/telemetry/workload/README.md +++ b/docker/telemetry/workload/README.md @@ -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 diff --git a/docker/telemetry/workload/run-full-validation.sh b/docker/telemetry/workload/run-full-validation.sh index d5295c9b3e..3524ef5648 100755 --- a/docker/telemetry/workload/run-full-validation.sh +++ b/docker/telemetry/workload/run-full-validation.sh @@ -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 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:-}' 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:-}" + echo " service_name values: ${values:-}" + 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" # --------------------------------------------------------------------------- diff --git a/docker/telemetry/workload/validate_telemetry.py b/docker/telemetry/workload/validate_telemetry.py index 7f67118d8a..ef990dd8c3 100644 --- a/docker/telemetry/workload/validate_telemetry.py +++ b/docker/telemetry/workload/validate_telemetry.py @@ -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(), diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 071677c6ac..de70a911d3 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -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 `