From ac07e1345f765446a353ac74376bbcdc8e62301e Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Wed, 9 Sep 2026 15:12:36 +0100 Subject: [PATCH] fix(telemetry): name the harness log directories after their instance ids The collector reads the per-node directory off the log file path and stamps it as the Loki label service_instance_id, so the directory name has to equal the node's own [telemetry] service_instance_id or log lines carry a node name that no trace or metric shares and nothing joins. Both harness scripts disagreed with themselves: run-full-validation.sh wrote to node$i while setting validator-${i}, and benchmark.sh wrote to node$i while setting bench-node-${i}. Rename the directories to match the ids rather than the reverse, so no existing trace or metric label value moves and no harness expectation has to be re-checked. Only path references are renamed; the human-readable "node$i" in log and error messages is left as prose. The config template is not rendered by any script, so its DATA_DIR documentation gains a note about the same constraint instead. Also rename the deprecated otlphttp/filelog collector component names in the harness scripts and docs. --- docker/telemetry/docker-compose.workload.yaml | 4 +-- docker/telemetry/workload/README.md | 8 +++--- docker/telemetry/workload/benchmark.sh | 6 ++-- .../telemetry/workload/run-full-validation.sh | 28 +++++++++---------- .../telemetry/workload/validate_telemetry.py | 2 +- .../workload/xrpld-validator.cfg.template | 7 ++++- docs/telemetry-runbook.md | 22 +++++++-------- 7 files changed, 41 insertions(+), 36 deletions(-) diff --git a/docker/telemetry/docker-compose.workload.yaml b/docker/telemetry/docker-compose.workload.yaml index 6ab809d705..5e81570f95 100644 --- a/docker/telemetry/docker-compose.workload.yaml +++ b/docker/telemetry/docker-compose.workload.yaml @@ -11,7 +11,7 @@ # run-full-validation.sh starts NUM_NODES (default 5) xrpld instances on # 127.0.0.1, each with a cfg it generates inline, peered to each other via # [ips_fixed]. They reach the collector through the published ports below and -# write their logs into the bind-mounted workdir for the filelog receiver. +# write their logs into the bind-mounted workdir for the file_log receiver. # # Usage: # # Start the telemetry backend on its own: @@ -47,7 +47,7 @@ services: - "13133:13133" # Health check volumes: - ./otel-collector-config.yaml:/etc/otel-collector-config.yaml:ro - # Mount the validation workdir so the filelog receiver can tail node + # Mount the validation workdir so the file_log receiver can tail node # logs. run-full-validation.sh sets XRPLD_LOG_DIR to its workdir; the # default matches that workdir so a bare `docker compose up` also works. - ${XRPLD_LOG_DIR:-/tmp/xrpld-validation}:/var/log/xrpld:ro diff --git a/docker/telemetry/workload/README.md b/docker/telemetry/workload/README.md index 07c3bacb0a..185baed713 100644 --- a/docker/telemetry/workload/README.md +++ b/docker/telemetry/workload/README.md @@ -32,7 +32,7 @@ run-full-validation.sh (shell orchestrator) | |-- docker-compose.workload.yaml | |-- otel-collector (otlp receiver: traces + beast::insight metrics; - | | filelog receiver: node debug.log -> Loki) + | | file_log receiver: node debug.log -> Loki) | |-- tempo (trace backend + TraceQL search API) | |-- prometheus (metrics scraping) | |-- loki (log aggregation for log-trace correlation) @@ -458,7 +458,7 @@ its own `check_log_correlation()`, but no workflow runs that script. Correlation depends on four independent legs, and a failed check on its own names 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 +collector container must see that file, its `file_log` 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 @@ -467,7 +467,7 @@ 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. -Those two entry counts **must** be wrapped in `sum()`. The `filelog` receiver's +Those two entry counts **must** be wrapped in `sum()`. The `file_log` receiver's `regex_parser` leaves `message` and `timestamp` as log-record attributes, and Loki's OTLP path stores them as structured metadata that joins the label set of a metric query — so an unaggregated `count_over_time` returns one series per log @@ -510,7 +510,7 @@ docker/telemetry/workload/run-full-validation.sh --xrpld .build/xrpld ``` Re-run it after any change to log formatting, span activation, the collector's -`filelog` receiver, or the Loki exporter. +`file_log` receiver, or the Loki exporter. ### Pathfinding is not exercised diff --git a/docker/telemetry/workload/benchmark.sh b/docker/telemetry/workload/benchmark.sh index da22b350b1..7035a2bc43 100755 --- a/docker/telemetry/workload/benchmark.sh +++ b/docker/telemetry/workload/benchmark.sh @@ -189,7 +189,7 @@ start_cluster() { # Build per-node configs. for i in $(seq 1 "$NUM_NODES"); do - local node_dir="$WORKDIR/node$i" + local node_dir="$WORKDIR/bench-node-$i" mkdir -p "$node_dir/nudb" "$node_dir/db" || cannot_measure "Could not create node$i directories under $node_dir" @@ -361,7 +361,7 @@ stop_cluster() { log "Stopping cluster..." for i in $(seq 1 "$NUM_NODES"); do - local pidfile="$WORKDIR/node$i/xrpld.pid" + local pidfile="$WORKDIR/bench-node-$i/xrpld.pid" if [ -f "$pidfile" ]; then kill "$(cat "$pidfile")" 2>/dev/null || true fi @@ -422,7 +422,7 @@ ws_endpoints() { node_pids_csv() { local i out="" pid for i in $(seq 1 "$NUM_NODES"); do - pid=$(cat "$WORKDIR/node$i/xrpld.pid" 2>/dev/null) || continue + pid=$(cat "$WORKDIR/bench-node-$i/xrpld.pid" 2>/dev/null) || continue [ -n "$pid" ] && out="$out,$pid" done printf '%s' "${out#,}" diff --git a/docker/telemetry/workload/run-full-validation.sh b/docker/telemetry/workload/run-full-validation.sh index 44222deee2..59c7b1b372 100755 --- a/docker/telemetry/workload/run-full-validation.sh +++ b/docker/telemetry/workload/run-full-validation.sh @@ -266,7 +266,7 @@ mkdir -p "$WORKDIR" "$REPORT_DIR" || die "Could not create $WORKDIR and $REPORT_ # Step 1: Start observability stack # --------------------------------------------------------------------------- log "Step 1: Starting observability stack..." -# Point the collector's log mount at this run's workdir so the filelog +# Point the collector's log mount at this run's workdir so the file_log # receiver tails the per-node debug.log files generated below. XRPLD_LOG_DIR="$WORKDIR" docker compose -f "$COMPOSE_FILE" up -d || die "docker compose up failed for $COMPOSE_FILE — the observability stack did not start" @@ -311,7 +311,7 @@ bash "$SCRIPT_DIR/generate-validator-keys.sh" "$XRPLD" "$NUM_NODES" "$WORKDIR" | die "generate-validator-keys.sh failed — no validator keys for the $NUM_NODES-node cluster" for i in $(seq 1 "$NUM_NODES"); do - NODE_DIR="$WORKDIR/node$i" + NODE_DIR="$WORKDIR/validator-$i" mkdir -p "$NODE_DIR/nudb" "$NODE_DIR/db" || die "Could not create node$i directories under $NODE_DIR" RPC_PORT=$((RPC_PORT_BASE + i - 1)) @@ -478,15 +478,15 @@ node_running() { report_stopped_nodes() { local i pid status for i in $(seq 1 "$NUM_NODES"); do - pid=$(cat "$WORKDIR/node$i/xrpld.pid" 2>/dev/null || echo "") + pid=$(cat "$WORKDIR/validator-$i/xrpld.pid" 2>/dev/null || echo "") [ -n "$pid" ] || continue node_running "$pid" && continue status=0 wait "$pid" 2>/dev/null || status=$? warn "node$i (pid $pid) is not running — wait status $status" - if [ -s "$WORKDIR/node$i/stdout.log" ]; then + if [ -s "$WORKDIR/validator-$i/stdout.log" ]; then warn "node$i last output:" - tail -n 15 "$WORKDIR/node$i/stdout.log" | sed 's/^/ /' >&2 + tail -n 15 "$WORKDIR/validator-$i/stdout.log" | sed 's/^/ /' >&2 else warn "node$i wrote no stdout at all" fi @@ -606,7 +606,7 @@ fi # --------------------------------------------------------------------------- # Log-trace correlation has four legs and a failed check names none of them: # the node must write a debug.log line carrying trace ids, the collector -# container must see that file, its filelog receiver must parse and export the +# container must see that file, its file_log receiver must parse and export the # line, and Loki must return it for the validator's own LogQL. Each leg below # reports what it observed, so a reader with only the CI log can tell which one # broke instead of guessing. @@ -704,7 +704,7 @@ diag_node_logs() { local i log bytes total correlated sample echo " [leg 1/4 node] debug.log lines matching '$DIAG_TRACE_RE'" for i in $(seq 1 "$NUM_NODES"); do - log="$WORKDIR/node$i/debug.log" + log="$WORKDIR/validator-$i/debug.log" if [ ! -f "$log" ]; then echo " node$i: no debug.log at $log — the node never opened its log sink" continue @@ -786,10 +786,10 @@ diag_collector_mount() { sed 's/^/ /' || echo " (container-side listing failed)" } -# Leg 3 — collector: did the filelog receiver parse and export those lines? +# Leg 3 — collector: did the file_log receiver parse and export those lines? # # Two independent readings. The collector's own stderr names every file the -# receiver opened and carries any filelog parse or Loki export error. Its +# receiver opened and carries any file_log parse or Loki export error. Its # internal telemetry counts log records in and out: accepted>0 with sent=0 is # an export failure, accepted=0 while files are being watched is a parse # failure. @@ -801,7 +801,7 @@ diag_collector_mount() { # exists; when it reports nothing matching, the leg says so. diag_collector_pipeline() { local cid img watched problems metrics - echo " [leg 3/4 collector] filelog receiver state" + echo " [leg 3/4 collector] file_log receiver state" if ! command -v docker >/dev/null 2>&1; then echo " docker is not on PATH — leg skipped" return 0 @@ -822,12 +822,12 @@ diag_collector_pipeline() { # Second filter keys on the collector's own logs-pipeline markers so this # does not report warnings from the trace or metric pipelines. Nothing is # excluded beyond that: the collector's benign config-alias deprecation - # notices ("filelog" -> "file_log") do surface here, and suppressing lines + # notices ("file_log" -> "file_log") do surface here, and suppressing lines # because they are usually harmless is how a diagnostic hides the one that # was not. problems=$(diag_run docker logs "$cid" 2>&1 | grep -iE '(warn|error)' | - grep -iE 'filelog|fileconsumer|loki|signal": *"logs' | + grep -iE 'file_log|fileconsumer|loki|signal": *"logs' | tail -n 20 || true) if [ -n "$problems" ]; then echo " logs-pipeline warnings and errors (last 20):" @@ -869,7 +869,7 @@ diag_loki_stream() { [ -n "$selector" ] || selector="$DIAG_LOG_SELECTOR" [ -n "$correlation" ] || correlation="$DIAG_LOG_SELECTOR $DIAG_LOG_FILTER" # sum() is required, for the reason recorded at _log_loki_diagnostics in - # validate_telemetry.py: the filelog regex_parser leaves message/timestamp + # validate_telemetry.py: the file_log regex_parser leaves message/timestamp # as log-record attributes, Loki's OTLP path turns those into structured # metadata that joins a metric query's label set, so an unaggregated # count_over_time yields one series per log line and Loki rejects the query @@ -1076,7 +1076,7 @@ echo " xrpld nodes ($NUM_NODES) are running:" for i in $(seq 1 "$NUM_NODES"); do rpc=$((RPC_PORT_BASE + i - 1)) ws=$((WS_PORT_BASE + i - 1)) - pid=$(cat "$WORKDIR/node$i/xrpld.pid" 2>/dev/null || echo 'unknown') + pid=$(cat "$WORKDIR/validator-$i/xrpld.pid" 2>/dev/null || echo 'unknown') echo " Node $i: RPC=$rpc WS=$ws PID=$pid" done echo "" diff --git a/docker/telemetry/workload/validate_telemetry.py b/docker/telemetry/workload/validate_telemetry.py index 2b7b79eb23..988fe75f8f 100644 --- a/docker/telemetry/workload/validate_telemetry.py +++ b/docker/telemetry/workload/validate_telemetry.py @@ -1680,7 +1680,7 @@ async def _log_loki_diagnostics(session: aiohttp.ClientSession, loki_url: str) - "Loki diagnostic: service_name values: %s", ", ".join(found) or "(none)" ) - # sum() is load-bearing, not cosmetic. The filelog receiver's regex_parser + # sum() is load-bearing, not cosmetic. The file_log receiver's regex_parser # leaves message, timestamp, trace_id and span_id as log-record attributes, # and Loki's OTLP path stores those as structured metadata, which joins the # label set of a metric query. Because `message` and `timestamp` are unique diff --git a/docker/telemetry/workload/xrpld-validator.cfg.template b/docker/telemetry/workload/xrpld-validator.cfg.template index 623b781707..adeccea97a 100644 --- a/docker/telemetry/workload/xrpld-validator.cfg.template +++ b/docker/telemetry/workload/xrpld-validator.cfg.template @@ -14,7 +14,12 @@ # {{RPC_PORT}} — HTTP RPC port # {{WS_PORT}} — WebSocket port # {{PEER_PORT}} — Peer protocol port -# {{DATA_DIR}} — Node data directory +# {{DATA_DIR}} — Node data directory. Its last path segment must +# equal service_instance_id below: the collector's +# file_log receiver reads that segment off the log +# file path and stamps it as the Loki label +# service_instance_id, so a mismatch gives log lines +# a node name no trace or metric shares. # {{VALIDATION_SEED}} — Validator seed from key generation # {{VALIDATORS_FILE}} — Path to shared validators.txt # {{IPS_FIXED}} — Peer addresses (one per line) diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 2d85f4e99f..1ddad3ec6c 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -111,7 +111,7 @@ Both set `[insight] server=otel` (native metrics → collector → Prometheus, w drives the dashboards) and `service_instance_id`, exposed by Prometheus as the `service_instance_id` label that the `$node` dashboard variable filters on. The mainnet config logs to `/var/log/xrpld/mainnet/debug.log` — the path -the collector's filelog receiver tails for log-trace correlation. +the collector's file_log receiver tails for log-trace correlation. Metrics begin flowing as soon as the node connects to peers (`server_state` ≥ `connected`); full ledger and consensus panels populate after sync @@ -210,12 +210,12 @@ To return to local-only export, bring the stack up with just the base The prepared config **dual-exports**: data goes to both the local stack and Grafana Cloud, so the on-box backends remain a fallback. For cloud-only, remove the local exporters (`debug`, `otlp/tempo`, `prometheus`, -`otlphttp/loki`) from the respective pipelines in +`otlp_http/loki`) from the respective pipelines in `otel-collector-config.grafanacloud.yaml`, leaving only -`otlphttp/grafanacloud`. +`otlp_http/grafanacloud`. > **Note**: shipping logs to Grafana Cloud requires keeping xrpld file -> logging on (at least `warning` level) so the collector's filelog receiver +> logging on (at least `warning` level) so the collector's file_log receiver > has a `debug.log` to tail. Traces and metrics are unaffected by log level. ### Importing dashboards to Grafana Cloud @@ -2843,7 +2843,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 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: +> **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 `file_log` receiver or the Loki exporter: > > ```bash > docker/telemetry/workload/run-full-validation.sh --xrpld .build/xrpld @@ -2864,7 +2864,7 @@ log_level RPCHandler debug ### Log Ingestion Pipeline -Log files are ingested by the OTel Collector's `filelog` receiver, which tails `debug.log` files and parses them with a regex that extracts `timestamp`, `partition`, `severity`, `trace_id`, `span_id`, and `message` fields. Parsed entries are exported to Grafana Loki. +Log files are ingested by the OTel Collector's `file_log` receiver, which tails `debug.log` files and parses them with a regex that extracts `timestamp`, `partition`, `severity`, `trace_id`, `span_id`, and `message` fields. Parsed entries are exported to Grafana Loki. The receiver tails `/var/log/xrpld/*/debug.log` inside the collector container. docker-compose bind-mounts the host log root there; the source defaults to the repo-relative `docker/telemetry/data/logs`, which the telemetry configs write to (`data/logs//debug.log`) and which needs no root. To tail logs from elsewhere, set `XRPLD_LOG_DIR` before `docker compose up` (the integration test does this to point at its own workdir). The single trailing `*` matches one per-network or per-node subdirectory. @@ -2899,7 +2899,7 @@ after the selector and cannot be discovered by `label_values()`. # Logs from the last hour containing trace context. `partition`, `severity`, and # `trace_id` are already parsed into structured metadata by the collector's -# filelog receiver, so re-extracting them with regexp is unnecessary work. +# file_log receiver, so re-extracting them with regexp is unnecessary work. {service_name="xrpld"} | trace_id != "" # Count of traced vs untraced log lines @@ -3614,9 +3614,9 @@ not a sign the cache is working. ### No logs in Loki - Verify the log file mount in docker-compose.yml points to the correct xrpld log directory (default source `docker/telemetry/data/logs`, or the `XRPLD_LOG_DIR` override) and that xrpld actually writes `debug.log` there -- Check OTel Collector logs for filelog receiver errors: `docker compose logs otel-collector` +- Check OTel Collector logs for file_log receiver errors: `docker compose logs otel-collector` - Verify Loki is running: `curl http://localhost:3100/ready` -- Check the filelog receiver glob `/var/log/xrpld/*/debug.log` matches your log layout — the log file must sit one subdirectory below the mount root +- Check the file_log receiver glob `/var/log/xrpld/*/debug.log` matches your log layout — the log file must sit one subdirectory below the mount root ## Performance Tuning @@ -3920,12 +3920,12 @@ container as the main CI, so Conan and ccache hit the shared caches), and 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 + `file_log` 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. Those two Loki entry counts are `sum(count_over_time(...))`, and the `sum()` is - load-bearing: the `filelog` receiver leaves `message` and `timestamp` as + load-bearing: the `file_log` receiver leaves `message` and `timestamp` as log-record attributes, Loki's OTLP path stores them as structured metadata, and structured metadata joins a metric query's label set — so an unaggregated `count_over_time` produces one series per log line and Loki answers `HTTP 400