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 `