From cbb85819975a5ebee439403d26b44a5835827433 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Wed, 9 Sep 2026 15:11:49 +0100 Subject: [PATCH] fix(telemetry): make the log pipeline actually deliver, and fix its docs Addresses the open review findings on this branch. The log root was never delivered at all. Docker creates a missing bind-mount source as root, Config::getDebugLogFile() only warns when it cannot create the network subdirectory inside it, and Application carries on. The node therefore looked healthy while writing no debug.log, and Loki stayed empty with no error at any layer. docker/telemetry/data/logs has in fact been root-owned in a working checkout since it was first created. A one-shot xrpld-logdir-init service now creates the directory and hands it to XRPLD_UID/XRPLD_GID, following the pattern the storage-init service already uses. Ingested logs carried no node identity, so a multi-node stack collapsed into one indistinguishable stream while every dashboard filters on service_instance_id. The receiver now sets include_file_path and lifts the per-node directory onto the resource attribute service.instance.id, which is on the allow-list Loki promotes to an indexed stream label. A record attribute would only become structured metadata and could not be used in a selector. For that to join anything the directory name has to equal the emitter's service_instance_id, so the node directories are renamed to match: node$i becomes Node-$i, and the standalone config writes to logs/xrpld-standalone. The integration test aborted before reporting. Under set -o pipefail the grep | head -1 pipeline is killed by SIGPIPE once the log exceeds the pipe buffer, so the run exited 141 somewhere past a few hundred matching lines and read as a flaky test. grep -m1 stops on its own. The test also verified the local file and Tempo but never that a line reached Loki, which is the one hop this branch adds, so a bounded Loki assertion is added alongside a readiness wait. Documentation fixes: the Tempo cross-check counted .data, but Tempo returns OTLP shape so the array is batches and one trace can span several; the Loki step used the instant /query endpoint, which rejects a bare log selector with HTTP 400 and a text/plain body, so jq could never parse it and the step never printed a number even when ingestion worked. The filelog comment claimed six fractional digits where the node always emits nine. The two flowcharts used
, carried no legend, and advertised GetSpan(), which Log.cpp deliberately avoids in favour of reading the thread-local context directly. Finally, rename the deprecated collector component names: the pinned collector warns on every start that otlphttp and filelog are aliases for otlp_http and file_log. Alloy's otelcol.exporter.otlphttp and otelcol.receiver.filelog are that product's own component names and are not deprecated, so they are left alone. --- OpenTelemetryPlan/06-implementation-phases.md | 78 ++++++++++++++----- .../09-data-collection-reference.md | 8 +- docker/telemetry/TESTING.md | 51 ++++++++---- docker/telemetry/docker-compose.yml | 47 ++++++++--- .../provisioning/datasources/loki.yaml | 2 +- docker/telemetry/integration-test.sh | 77 ++++++++++++++++-- docker/telemetry/otel-collector-config.yaml | 56 +++++++++---- .../telemetry/otel-collector-filestorage.yaml | 10 +-- docker/telemetry/xrpld-telemetry.cfg | 11 ++- docs/telemetry-runbook.md | 12 +-- 10 files changed, 270 insertions(+), 82 deletions(-) diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index 080421a5c6..2a0d330a71 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -574,14 +574,14 @@ See [Phase7_taskList.md](./Phase7_taskList.md) for detailed per-task breakdown. ### Motivation -xrpld's `beast::Journal` logs and OpenTelemetry traces are currently two disjoint observability signals. When investigating an issue, operators must manually correlate timestamps between log files and Jaeger/Tempo traces. Phase 8 bridges this gap by injecting trace context (`trace_id`, `span_id`) into every log line emitted within an active, sampled span, and ingesting those logs into Grafana Loki via the OTel Collector's filelog receiver. +xrpld's `beast::Journal` logs and OpenTelemetry traces are currently two disjoint observability signals. When investigating an issue, operators must manually correlate timestamps between log files and Jaeger/Tempo traces. Phase 8 bridges this gap by injecting trace context (`trace_id`, `span_id`) into every log line emitted within an active, sampled span, and ingesting those logs into Grafana Loki via the OTel Collector's file_log receiver. #### Gains 1. **One-click trace-to-log navigation** — Click a trace in Tempo/Jaeger and immediately see the corresponding log lines in Loki, filtered by `trace_id`. 2. **Reverse lookup (log-to-trace)** — Loki derived fields make `trace_id` values clickable links back to Tempo. 3. **Unified observability** — All three pillars (traces, metrics, logs) flow through the same OTel Collector pipeline and are visible in a single Grafana instance. -4. **Zero new dependencies in xrpld** — Uses existing OTel SDK headers (`GetSpan`, `GetContext`) already linked in Phase 1. +4. **Zero new dependencies in xrpld** — Uses existing OTel SDK headers (`RuntimeContext`, `SpanContext`) already linked in Phase 1. 5. **Negligible overhead** — The implementation checks the thread-local context value directly, avoiding heap allocation on the no-span path (~15-20ns). On the active-span path, total cost is ~50ns per log call. At typical logging rates, overhead is negligible. #### Losses / Risks @@ -592,33 +592,54 @@ xrpld's `beast::Journal` logs and OpenTelemetry traces are currently two disjoin #### Decision -The correlation value far outweighs the risks. The log format change is backward-compatible (fields are appended only when a sampled span is active), and the filelog receiver regex is straightforward to maintain. +The correlation value far outweighs the risks. The log format change is backward-compatible (fields are appended only when a sampled span is active), and the file_log receiver regex is straightforward to maintain. ### Architecture Phase 8 has two independent sub-phases that can be developed in parallel: - **Phase 8a (code change)**: Modify `Logs::format()` in `src/libxrpl/basics/Log.cpp` to append `trace_id= span_id=` when the current thread has an active OTel span. Guarded by `#ifdef XRPL_ENABLE_TELEMETRY`. -- **Phase 8b (infra only)**: Add Loki to the Docker Compose stack, configure the OTel Collector's `filelog` receiver to tail xrpld's log file, parse out structured fields (timestamp, partition, severity, trace_id, span_id, message), and export to Loki via OTLP. Configure Grafana Tempo↔Loki bidirectional linking. +- **Phase 8b (infra only)**: Add Loki to the Docker Compose stack, configure the OTel Collector's `file_log` receiver to tail xrpld's log file, parse out structured fields (timestamp, partition, severity, trace_id, span_id, message), and export to Loki via OTLP. Configure Grafana Tempo↔Loki bidirectional linking. #### Trace ID Injection Flow ```mermaid flowchart LR subgraph xrpld["xrpld process"] - JLOG["JLOG(j.info())"] - Format["Logs::format()"] - OTelCtx["OTel Context
(thread-local)"] + JLOG["`**JLOG(j.info())** + a log call on some thread`"] + Format["`**Logs::format()** + builds the log line`"] + OTelCtx["`**OTel thread-local context** + RuntimeContext::GetCurrent() + GetValue(kSpanKey)`"] JLOG --> Format - OTelCtx -.->|"GetSpan()→GetContext()"| Format + OTelCtx -.->|"`GetContext() + if IsValid and IsSampled`"| Format end - subgraph output["Log Output"] - LogLine["2024-01-15T10:30:45.123Z
LedgerMaster:NFO
trace_id=abc123...
span_id=def456...
Validated ledger 42"] + subgraph output["Log output"] + LogLine["`2026-Jan-15 10:30:45.123456789 UTC + LedgerMaster:NFO + trace_id=abc123... span_id=def456... + Validated ledger 42`"] end Format --> LogLine + subgraph legend["Reading the diagram"] + direction LR + L1["`**Solid arrow** + happens on every log call`"] + L2["`**Dotted arrow** + only adds ids when a sampled span is active on this thread`"] + L3["`**kSpanKey lookup** + reads the context value directly, so the no-span path allocates nothing`"] + end + + L1 ~~~ L2 ~~~ L3 + output ~~~ legend + style xrpld fill:#1a237e,stroke:#0d1642,color:#fff style output fill:#1b5e20,stroke:#0d3d14,color:#fff style JLOG fill:#283593,stroke:#1a237e,color:#fff @@ -632,16 +653,35 @@ flowchart LR ```mermaid flowchart LR subgraph collector["OTel Collector"] - FR["filelog receiver
tails debug.log"] - RP["regex_parser
extracts trace_id,
span_id, severity"] - BP["batch processor"] - LE["otlp/loki exporter"] + FR["`**file_log receiver** + tails debug.log`"] + RP["`**regex_parser** + extracts timestamp, partition, + severity, trace_id, span_id`"] + BP["`**batch processor**`"] + LE["`**otlp_http/loki exporter**`"] FR --> RP --> BP --> LE end - LogFile["xrpld
debug.log"] --> FR - LE --> Loki["Grafana Loki
:3100"] - Loki <-->|"derivedFields ↔
tracesToLogs"| Tempo["Grafana Tempo"] + LogFile["`**xrpld** + debug.log`"] --> FR + LE --> Loki["`**Grafana Loki** + :3100`"] + Loki <-->|"`derivedFields + tracesToLogs`"| Tempo["`**Grafana Tempo**`"] + + subgraph legend["Reading the diagram"] + direction LR + L1["`**Solid arrow** + the path every log line takes`"] + L2["`**Double arrow** + Grafana links the two backends both ways: a trace jumps to its logs, a trace_id in a log jumps back to the trace`"] + L3["`**otlp_http, not otlp** + Loki is reached over OTLP/HTTP; the old dedicated loki exporter was removed upstream`"] + end + + L1 ~~~ L2 ~~~ L3 + collector ~~~ legend style collector fill:#e65100,stroke:#bf360c,color:#fff style FR fill:#f57c00,stroke:#e65100,color:#fff @@ -659,7 +699,7 @@ flowchart LR | ---- | ---------------------------------------------- | | 8.1 | Inject trace_id into Logs::format() | | 8.2 | Add Loki to Docker Compose stack | -| 8.3 | Add filelog receiver to OTel Collector | +| 8.3 | Add file_log receiver to OTel Collector | | 8.4 | Configure Grafana trace-to-log correlation | | 8.5 | Update integration tests | | 8.6 | Update documentation (runbook, reference docs) | @@ -670,7 +710,7 @@ flowchart LR - [ ] Log lines within active spans contain `trace_id= span_id=` - [ ] Log lines outside spans have no trace context (no empty fields) -- [ ] Loki ingests xrpld logs via OTel Collector filelog receiver +- [ ] Loki ingests xrpld logs via OTel Collector file_log receiver - [ ] Grafana Tempo → Loki one-click correlation works - [ ] Grafana Loki → Tempo reverse lookup works via derived field - [ ] Integration test verifies trace_id presence in logs diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 0d67842bee..d2263d9e4e 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -956,7 +956,7 @@ Phase 8 injects OTel trace context into xrpld's `Logs::format()` output, enablin Example: ``` -2024-Jan-15 10:30:45.123456 UTC LedgerMaster:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Validated ledger 42 +2024-Jan-15 10:30:45.123456789 UTC LedgerMaster:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Validated ledger 42 ``` - **`trace_id=`** — 32-character lowercase hex trace identifier. Links to the distributed trace in Tempo/Jaeger. @@ -970,10 +970,10 @@ The trace context injection is implemented in `Logs::format()` (`src/libxrpl/bas ### Log Ingestion Pipeline ``` -xrpld debug.log -> OTel Collector filelog receiver -> regex_parser -> Loki exporter -> Grafana Loki +xrpld debug.log -> OTel Collector file_log receiver -> regex_parser -> Loki exporter -> Grafana Loki ``` -The OTel Collector's `filelog` receiver tails `debug.log` files and uses a `regex_parser` operator to extract structured fields: +The OTel Collector's `file_log` receiver tails `debug.log` files and uses a `regex_parser` operator to extract structured fields: | Field | Type | Description | | ----------- | -------- | -------------------------------------------------------- | @@ -993,7 +993,7 @@ Bidirectional linking between logs and traces is configured via Grafana datasour ### Loki Backend -Grafana Loki (v3.4.2) serves as the log storage backend. It receives log entries from the OTel Collector's `otlphttp/loki` exporter via the native OTLP endpoint at `http://loki:3100/otlp`. +Grafana Loki (v3.4.2) serves as the log storage backend. It receives log entries from the OTel Collector's `otlp_http/loki` exporter via the native OTLP endpoint at `http://loki:3100/otlp`. ### LogQL Query Examples diff --git a/docker/telemetry/TESTING.md b/docker/telemetry/TESTING.md index 01a3fc90cb..d3576562b4 100644 --- a/docker/telemetry/TESTING.md +++ b/docker/telemetry/TESTING.md @@ -45,6 +45,15 @@ the end of this test for which do and which do not. docker compose -f docker/telemetry/docker-compose.yml up -d ``` +The `xrpld-logdir-init` service creates `docker/telemetry/data/logs` and gives it +to uid/gid 1000. If `id -u` on this host is not 1000, xrpld cannot write its log +there and the log pipeline stays empty, so set the ids first: + +```bash +XRPLD_UID=$(id -u) XRPLD_GID=$(id -g) \ + docker compose -f docker/telemetry/docker-compose.yml up -d +``` + Wait for services to be ready: ```bash @@ -469,7 +478,7 @@ Expected: log lines with `trace_id=<32hex> span_id=<16hex>` between the severity code and the message. Example: ``` -2024-Jan-15 10:30:45.123456 UTC RPCHandler:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Calling server_info +2024-Jan-15 10:30:45.123456789 UTC RPCHandler:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Calling server_info ``` Lines emitted outside of an active span (background tasks, startup) will @@ -480,26 +489,42 @@ NOT have trace context — this is expected. Extract a `trace_id` from the log and verify it exists in Tempo: ```bash -TRACE_ID=$(grep -o 'trace_id=[a-f0-9]\{32\}' /path/to/debug.log | head -1 | cut -d= -f2) +TRACE_ID=$(grep -m1 -o 'trace_id=[a-f0-9]\{32\}' /path/to/debug.log | cut -d= -f2) echo "Checking trace: $TRACE_ID" -curl -s "http://localhost:3200/api/traces/$TRACE_ID" | jq '.data | length' +curl -s "http://localhost:3200/api/traces/$TRACE_ID" | jq '.batches | length' ``` -Expected result: `1` (the trace exists in Tempo). +Expected result: `> 0` (the trace exists in Tempo). +Tempo returns the trace in OTLP shape, so the array is `batches`, not `data`, +and one trace can arrive as several batches. ### Step 3: Verify Loki log ingestion -The OTel Collector's filelog receiver tails xrpld's debug.log and +The OTel Collector's file_log receiver tails xrpld's debug.log and exports parsed entries to Loki. Verify Loki has received entries: ```bash -# Query Loki for any xrpld logs -curl -sG "http://localhost:3100/loki/api/v1/query" \ +# Query Loki for any xrpld logs in the last 10 minutes +NOW_NS=$(($(date +%s) * 1000000000)) +curl -sG "http://localhost:3100/loki/api/v1/query_range" \ --data-urlencode 'query={service_name="xrpld"}' \ - --data-urlencode 'limit=5' | jq '.data.result | length' + --data-urlencode "start=$((NOW_NS - 600000000000))" \ + --data-urlencode "end=${NOW_NS}" \ + --data-urlencode 'limit=5' \ + --data-urlencode 'direction=backward' | + jq '[.data.result[].values | length] | add // 0' ``` -Expected: > 0 results. +Expected: > 0 log lines. + +Use `query_range`, not `query`. Loki rejects a bare log selector on the +instant `/query` endpoint with HTTP 400 and a `text/plain` body +("log queries are not supported as an instant query type"), so `jq` fails to +parse it and the step never prints a number — even when ingestion is working. +Only metric queries such as `sum(count_over_time(...))` are allowed there, +which is why the validation scripts can use the instant endpoint. +Timestamps are unix nanoseconds, matching `workload/validate_telemetry.py`. +Counting `.data.result | length` would count streams, not log lines. ### Step 4: Verify Grafana Tempo-to-Loki correlation @@ -555,7 +580,7 @@ Expected: > 0 results. ``` 2. Verify `[ips_fixed]` lists all 6 peer ports 3. Verify `validators.txt` has all 6 public keys -4. Check node debug logs: `tail -50 /tmp/xrpld-integration/node1/debug.log` +4. Check node debug logs: `tail -50 /tmp/xrpld-integration/Node-1/debug.log` 5. Ensure `[peer_private]` is set to `1` (prevents reaching out to public network) ### Transaction not processing @@ -588,15 +613,15 @@ Expected: > 0 results. The mount source defaults to the repo-relative `docker/telemetry/data/logs` (where the telemetry configs write). Override `XRPLD_LOG_DIR` to tail logs from another root. -2. Check OTel Collector logs for filelog receiver errors: +2. Check OTel Collector logs for file_log receiver errors: ```bash - docker compose -f docker/telemetry/docker-compose.yml logs otel-collector | grep -i "filelog\|loki\|error" + docker compose -f docker/telemetry/docker-compose.yml logs otel-collector | grep -i "file_log\|loki\|error" ``` 3. Verify Loki is running: ```bash curl -s http://localhost:3100/ready ``` -4. Verify the filelog receiver glob pattern matches your log files: +4. Verify the file_log receiver glob pattern matches your log files: The default pattern is `/var/log/xrpld/*/debug.log` ### Grafana trace-log links not working diff --git a/docker/telemetry/docker-compose.yml b/docker/telemetry/docker-compose.yml index 98f6965c3f..5665f9d56d 100644 --- a/docker/telemetry/docker-compose.yml +++ b/docker/telemetry/docker-compose.yml @@ -3,7 +3,7 @@ # Provides services for local development: # - otel-collector: receives OTLP traces from xrpld, batches and # forwards them to Tempo. Also tails xrpld log files -# via filelog receiver and exports to Loki. Listens on ports +# via file_log receiver and exports to Loki. Listens on ports # 4317 (gRPC) and 4318 (HTTP). # - tempo: Grafana Tempo tracing backend, queryable via Grafana Explore # on port 3000. Recommended for production (S3/GCS storage, TraceQL). @@ -40,11 +40,34 @@ services: networks: - xrpld-telemetry + # One-shot init for the xrpld log root. Docker creates a missing bind-mount + # source as root, and xrpld then cannot create the subdirectory + # inside it. Config::getDebugLogFile() only warns on that failure and carries + # on, so the node looks healthy while writing no debug.log at all and the + # whole log pipeline stays empty with no error at any layer. Create the + # directory here and hand it to the host user instead. + # + # XRPLD_UID/XRPLD_GID default to 1000, the first non-root user on a typical + # Linux host. Set them if `id -u` differs, or xrpld still cannot write. + # Reuses the Prometheus image for the same reason otelcol-storage-init does. + xrpld-logdir-init: + image: prom/prometheus:v3.13.2 + user: "0:0" + entrypoint: ["sh", "-c"] + command: + [ + "mkdir -p /data/logs && chown ${XRPLD_UID:-1000}:${XRPLD_GID:-1000} /data /data/logs", + ] + volumes: + - ./data:/data + networks: + - xrpld-telemetry + # OpenTelemetry Collector: receives spans from xrpld via OTLP protocol, # batches them for efficiency, and forwards to Tempo for storage. otel-collector: image: otel/opentelemetry-collector-contrib:0.158.0 - # Second --config layers filelog offset persistence on top of the shared + # Second --config layers file_log offset persistence on top of the shared # base config; the collector deep-merges them. Only this stack keeps its # logs across restarts, so only this stack needs it. command: @@ -62,16 +85,18 @@ services: volumes: # Mount collector pipeline config (receivers → processors → exporters) - ./otel-collector-config.yaml:/etc/otel-collector-config.yaml:ro - # Dev-only overlay: persist filelog read offsets across restarts + # Dev-only overlay: persist file_log read offsets across restarts - ./otel-collector-filestorage.yaml:/etc/otel-collector-filestorage.yaml:ro - # Mount the xrpld log root for the filelog receiver. The telemetry + # Mount the xrpld log root for the file_log receiver. The telemetry # configs write to docker/telemetry/data/logs//debug.log, so - # the default source is the repo-relative ./data/logs — user-owned and - # needing no root, so `docker compose up` works with no setup. Override - # XRPLD_LOG_DIR to point at another root (e.g. the integration test sets - # it to its own workdir). Mounted read-only so the collector only tails. + # the default source is the repo-relative ./data/logs, which + # xrpld-logdir-init has already created and handed to the host user. + # Override XRPLD_LOG_DIR to point at another root (e.g. the integration + # test sets it to its own workdir; that root is created by the test, so + # the init service is a no-op there). Mounted read-only so the collector + # only tails. - ${XRPLD_LOG_DIR:-./data/logs}:/var/log/xrpld:ro - # Persisted filelog read offsets, so a collector restart resumes + # Persisted file_log read offsets, so a collector restart resumes # instead of re-reading every debug.log from the top. - otelcol-storage:/var/lib/otelcol depends_on: @@ -81,6 +106,8 @@ services: condition: service_started otelcol-storage-init: condition: service_completed_successfully + xrpld-logdir-init: + condition: service_completed_successfully networks: - xrpld-telemetry @@ -101,7 +128,7 @@ services: # Grafana Loki for centralized log ingestion and log-trace # correlation. Loki 3.x supports native OTLP ingestion, so the OTel - # Collector exports via otlphttp to Loki's /otlp endpoint. + # Collector exports via otlp_http to Loki's /otlp endpoint. # Query logs via Grafana Explore -> Loki at http://localhost:3000. loki: image: grafana/loki:3.4.2 diff --git a/docker/telemetry/grafana/provisioning/datasources/loki.yaml b/docker/telemetry/grafana/provisioning/datasources/loki.yaml index 0a6b73a575..a70ac9deb3 100644 --- a/docker/telemetry/grafana/provisioning/datasources/loki.yaml +++ b/docker/telemetry/grafana/provisioning/datasources/loki.yaml @@ -1,6 +1,6 @@ # Grafana Loki data source provisioning for rippled log-trace correlation. # -# Loki ingests rippled logs via OTel Collector's filelog receiver. +# Loki ingests rippled logs via OTel Collector's file_log receiver. # The derivedFields config links trace_id values in log lines back to # Tempo traces, enabling one-click log-to-trace navigation in Grafana. diff --git a/docker/telemetry/integration-test.sh b/docker/telemetry/integration-test.sh index e3981d4e4a..6c930dcee9 100755 --- a/docker/telemetry/integration-test.sh +++ b/docker/telemetry/integration-test.sh @@ -37,6 +37,10 @@ GENESIS_SEED="snoPBrXtMeMyMHUVTgbuqAfg1SUTb" DEST_ACCOUNT="" # Generated dynamically via wallet_propose TEMPO="http://localhost:3200" PROM="http://localhost:9090" +LOKI="http://localhost:3100" +# How long to wait for a log line to travel file -> file_log receiver -> batch +# processor -> Loki. The batch timeout is 1s, so this is mostly ingestion slack. +LOKI_INGEST_TIMEOUT=30 # Counters for pass/fail PASS=0 @@ -88,7 +92,7 @@ check_log_correlation() { local sample_trace_id="" for i in $(seq 1 "$NUM_NODES"); do - local logfile="$WORKDIR/node$i/debug.log" + local logfile="$WORKDIR/Node-$i/debug.log" if [ ! -f "$logfile" ]; then continue fi @@ -97,12 +101,17 @@ check_log_correlation() { matches=$(grep -c 'trace_id=[a-f0-9]\{32\} span_id=[a-f0-9]\{16\}' "$logfile") || matches=0 total_matches=$((total_matches + matches)) if [ -z "$sample_trace_id" ] && [ "$matches" -gt 0 ]; then - sample_trace_id=$(grep -o 'trace_id=[a-f0-9]\{32\}' "$logfile" | head -1 | cut -d= -f2) + # -m1 makes grep stop after the first match and exit normally. + # Piping into `head -1` instead closes the pipe under grep, and + # under `set -o pipefail` the resulting SIGPIPE (141) aborts the + # whole run. It only bites once the log is bigger than the pipe + # buffer, so it reads as a flaky test. + sample_trace_id=$(grep -m1 -o 'trace_id=[a-f0-9]\{32\}' "$logfile" | cut -d= -f2) fi done if [ "$files_scanned" -eq 0 ]; then - fail "Log correlation: no debug.log files found in $WORKDIR/node*/" + fail "Log correlation: no debug.log files found in $WORKDIR/Node-*/" return fi @@ -123,14 +132,54 @@ check_log_correlation() { else fail "Log-Tempo cross-check: trace_id=$sample_trace_id NOT found in Tempo" fi + + check_loki_ingestion "$sample_trace_id" fi } +# Verify the log line actually reached Loki, not just the local file. +# +# Without this the log-correlation check passes on a stack whose log mount is +# wrong or whose Loki exporter is broken, because reading the file and reading +# Tempo both still work. This is the only assertion that exercises the +# file_log -> Loki hop, so it is what makes the log pipeline tested rather than +# merely configured. +# +# Uses /query_range, not /query: Loki rejects a bare log selector on the instant +# endpoint with HTTP 400 and a text/plain body, so jq could never parse it. +# Bounds are unix nanoseconds, matching workload/validate_telemetry.py. +check_loki_ingestion() { + local trace_id="$1" + local lines=0 + local start_ns end_ns + + for attempt in $(seq 1 "$LOKI_INGEST_TIMEOUT"); do + end_ns=$(($(date +%s) * 1000000000)) + # Look back over the whole run, not a fixed window: the entry carries + # the timestamp parsed out of the log line, not its ingestion time. + start_ns=$((end_ns - 86400000000000)) + lines=$(curl -sfG "$LOKI/loki/api/v1/query_range" \ + --data-urlencode "query={service_name=\"xrpld\"} |= \"$trace_id\"" \ + --data-urlencode "start=$start_ns" \ + --data-urlencode "end=$end_ns" \ + --data-urlencode "limit=5" \ + --data-urlencode "direction=backward" | + jq '[.data.result[].values | length] | add // 0' 2>/dev/null) || lines=0 + if [ "${lines:-0}" -gt 0 ]; then + ok "Loki ingestion: trace_id=$trace_id found in Loki ($lines lines, attempt $attempt)" + return + fi + sleep 1 + done + + fail "Loki ingestion: trace_id=$trace_id never reached Loki after ${LOKI_INGEST_TIMEOUT}s" +} + cleanup() { log "Cleaning up..." # Kill xrpld nodes for i in $(seq 1 "$NUM_NODES"); do - local pidfile="$WORKDIR/node$i/xrpld.pid" + local pidfile="$WORKDIR/Node-$i/xrpld.pid" if [ -f "$pidfile" ]; then kill "$(cat "$pidfile")" 2>/dev/null || true rm -f "$pidfile" @@ -171,7 +220,7 @@ log "All prerequisites met." # --------------------------------------------------------------------------- log "Cleaning previous run data..." for i in $(seq 1 "$NUM_NODES"); do - pidfile="$WORKDIR/node$i/xrpld.pid" + pidfile="$WORKDIR/Node-$i/xrpld.pid" if [ -f "$pidfile" ]; then kill "$(cat "$pidfile")" 2>/dev/null || true fi @@ -237,6 +286,18 @@ for attempt in $(seq 1 30); do sleep 1 done +log "Waiting for Loki to be ready..." +for attempt in $(seq 1 60); do + if curl -sf "$LOKI/ready" >/dev/null 2>&1; then + log "Loki ready (attempt $attempt)." + break + fi + if [ "$attempt" -eq 60 ]; then + die "Loki not ready after 60s" + fi + sleep 1 +done + # --------------------------------------------------------------------------- # Step 3: Generate validator keys # --------------------------------------------------------------------------- @@ -326,7 +387,7 @@ VALIDATORS_FILE="$WORKDIR/validators.txt" # Create per-node configs for i in $(seq 1 "$NUM_NODES"); do - NODE_DIR="$WORKDIR/node$i" + NODE_DIR="$WORKDIR/Node-$i" mkdir -p "$NODE_DIR/nudb" "$NODE_DIR/db" RPC_PORT=$((RPC_PORT_BASE + i - 1)) @@ -419,7 +480,7 @@ done log "Starting $NUM_NODES xrpld nodes..." for i in $(seq 1 "$NUM_NODES"); do - NODE_DIR="$WORKDIR/node$i" + NODE_DIR="$WORKDIR/Node-$i" "$XRPLD" --conf "$NODE_DIR/xrpld.cfg" --start >"$NODE_DIR/stdout.log" 2>&1 & echo $! >"$NODE_DIR/xrpld.pid" log " Node $i started (PID $(cat "$NODE_DIR/xrpld.pid"))" @@ -719,7 +780,7 @@ echo " xrpld nodes (6) are running:" for i in $(seq 1 "$NUM_NODES"); do RPC_PORT=$((RPC_PORT_BASE + i - 1)) PEER_PORT=$((PEER_PORT_BASE + i - 1)) - echo " Node $i: RPC=localhost:$RPC_PORT Peer=:$PEER_PORT PID=$(cat "$WORKDIR/node$i/xrpld.pid" 2>/dev/null || echo 'unknown')" + echo " Node $i: RPC=localhost:$RPC_PORT Peer=:$PEER_PORT PID=$(cat "$WORKDIR/Node-$i/xrpld.pid" 2>/dev/null || echo 'unknown')" done echo "" echo " To tear down:" diff --git a/docker/telemetry/otel-collector-config.yaml b/docker/telemetry/otel-collector-config.yaml index 618eb94d5a..8ad4545dea 100644 --- a/docker/telemetry/otel-collector-config.yaml +++ b/docker/telemetry/otel-collector-config.yaml @@ -3,7 +3,7 @@ # Pipelines: # traces: OTLP receiver -> batch processor -> debug + Tempo + spanmetrics # metrics: OTLP receiver + spanmetrics connector -> Prometheus exporter -# logs: filelog receiver -> batch processor -> otlphttp/Loki +# logs: file_log receiver -> batch processor -> otlp_http/Loki # # xrpld sends traces via OTLP/HTTP to port 4318. The collector batches # them, forwards to Tempo, and derives RED metrics via the spanmetrics @@ -14,16 +14,12 @@ # metrics pipelines. Metrics are exported to Prometheus alongside # span-derived metrics. # -# The filelog receiver tails xrpld's debug.log files under +# The file_log receiver tails xrpld's debug.log files under # /var/log/xrpld/ (mounted from the host). A regex_parser operator # extracts timestamp, partition, severity, and optional trace_id/span_id # fields injected by Logs::format(). Parsed logs are exported to Grafana # Loki for log-trace correlation. -extensions: - health_check: - endpoint: 0.0.0.0:13133 - receivers: otlp: protocols: @@ -35,8 +31,13 @@ receivers: # correlation. Extracts structured fields (timestamp, partition, severity, # trace_id, span_id, message) via regex. The trace_id and span_id are # optional — only present when the log was emitted within an active span. - filelog: + file_log: include: [/var/log/xrpld/*/debug.log] + # Needed to recover which node a line came from. The subdirectory name is + # the only per-node signal in the log stream: Logs::format() writes + # trace_id and span_id but no node identity. Emitters name the directory + # after their own service_instance_id so the two agree. + include_file_path: true # Read each file from the start. The upstream default is `end`, which # skips everything written before the receiver's first poll — so any log # line a node emitted before the collector got to it would be lost, and @@ -49,16 +50,36 @@ receivers: start_at: beginning operators: # Log format emitted by Logs::format() is: - # YYYY-Mmm-DD HH:MM:SS.ffffff UTC : [trace_id=... span_id=...] + # YYYY-Mmm-DD HH:MM:SS.fffffffff UTC : [trace_id=... span_id=...] # The `partition:` prefix is omitted when partition is empty, so the - # capture group is non-capturing optional. Fractional seconds up to 6 - # digits are parsed via the `%f` strptime directive. + # capture group is non-capturing optional. The node emits nanosecond + # precision (9 digits); `%f` accepts any number of fractional digits. - type: regex_parser regex: '^(?P\S+\s+\S+)\s+\S+\s+(?:(?P\S+):)?(?P\S+)\s+(?:trace_id=(?P[a-f0-9]+)\s+span_id=(?P[a-f0-9]+)\s+)?(?P.*)$' timestamp: parse_from: attributes.timestamp layout: "%Y-%b-%d %H:%M:%S.%f" location: UTC + # Lift the per-node directory out of the file path and onto the + # RESOURCE. include_file_path alone is not enough: it produces a log + # RECORD attribute, and on OTLP ingest Loki promotes only an allow-list + # of RESOURCE attributes to indexed stream labels. A record attribute + # becomes structured metadata, which cannot be used in a {...} selector. + # service.instance.id is on that allow-list and arrives as the LogQL + # label service_instance_id, which is the label the dashboards filter on. + # Dotted keys need bracket syntax; dot notation would be read as a + # nested traversal and match nothing. + - type: regex_parser + parse_from: attributes["log.file.path"] + parse_to: attributes + regex: "^/var/log/xrpld/(?P[^/]+)/" + - type: move + from: attributes.node_dir + to: resource["service.instance.id"] + # Drop the raw path once the node name is on the resource. Keeping it + # would add a structured-metadata field to every line for no benefit. + - type: remove + field: attributes["log.file.path"] processors: batch: @@ -179,7 +200,7 @@ exporters: # Export logs to Grafana Loki via OTLP/HTTP. Loki 3.x supports # native OTLP ingestion on its /otlp endpoint, replacing the removed # loki exporter (dropped in otel-collector-contrib v0.147.0). - otlphttp/loki: + otlp_http/loki: endpoint: http://loki:3100/otlp prometheus: endpoint: 0.0.0.0:8889 @@ -190,6 +211,10 @@ exporters: resource_to_telemetry_conversion: enabled: true +extensions: + health_check: + endpoint: 0.0.0.0:13133 + service: extensions: [health_check] pipelines: @@ -199,11 +224,14 @@ service: exporters: [debug, otlp/tempo, spanmetrics] metrics: receivers: [otlp, spanmetrics] + # batch keeps the OTLP metric path from exporting one request per + # instrument. It delays a sample by at most the batch timeout, which + # is well under the Prometheus scrape interval. processors: [resource/tier, resource/stripsdk, batch] exporters: [prometheus] - # Log pipeline ingests xrpld debug.log via filelog receiver, + # Log pipeline ingests xrpld debug.log via file_log receiver, # batches entries, and exports to Loki for log-trace correlation. logs: - receivers: [filelog] + receivers: [file_log] processors: [resource/logs, resource/tier, resource/stripsdk, batch] - exporters: [otlphttp/loki] + exporters: [otlp_http/loki] diff --git a/docker/telemetry/otel-collector-filestorage.yaml b/docker/telemetry/otel-collector-filestorage.yaml index 5362431725..fec6c7ddab 100644 --- a/docker/telemetry/otel-collector-filestorage.yaml +++ b/docker/telemetry/otel-collector-filestorage.yaml @@ -1,4 +1,4 @@ -# Collector overlay that persists filelog read offsets. Applied ONLY by the +# Collector overlay that persists file_log read offsets. Applied ONLY by the # developer stack (docker/telemetry/docker-compose.yml), as a second --config # after otel-collector-config.yaml; the collector deep-merges the two. # @@ -15,14 +15,14 @@ # instead of re-reading debug.log from the top. extensions: - file_storage/filelog: + file_storage/file_log: directory: /var/lib/otelcol/file_storage create_directory: true receivers: - filelog: - storage: file_storage/filelog + file_log: + storage: file_storage/file_log # Lists are replaced rather than merged, so this must repeat the base entry. service: - extensions: [health_check, file_storage/filelog] + extensions: [health_check, file_storage/file_log] diff --git a/docker/telemetry/xrpld-telemetry.cfg b/docker/telemetry/xrpld-telemetry.cfg index 64c59f4577..3294630bc9 100644 --- a/docker/telemetry/xrpld-telemetry.cfg +++ b/docker/telemetry/xrpld-telemetry.cfg @@ -35,10 +35,15 @@ advisory_delete=0 docker/telemetry/data # Path is resolved relative to this config file's directory (docker/telemetry), -# so this writes to docker/telemetry/data/logs/devnet/debug.log — the same -# dir the compose stack bind-mounts into the collector as /var/log/xrpld. +# so this writes to docker/telemetry/data/logs/xrpld-standalone/debug.log — the +# same dir the compose stack bind-mounts into the collector as /var/log/xrpld. +# +# The subdirectory name must equal [telemetry] service_instance_id below. The +# collector reads it off the file path and stamps it as the Loki label +# service_instance_id, so a mismatch here means log lines carry a node name +# that no trace or metric shares, and nothing joins. [debug_logfile] -data/logs/devnet/debug.log +data/logs/xrpld-standalone/debug.log [rpc_startup] { "command": "log_level", "severity": "debug" } diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index e90b30171c..adbeda9ffb 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -857,7 +857,7 @@ Requires `trace_peer=1` in the `[telemetry]` config section. When xrpld is built with `telemetry=ON`, log lines emitted within an active, sampled OpenTelemetry span automatically include `trace_id` and `span_id` fields: ``` -2024-Jan-15 10:30:45.123456 UTC LedgerMaster:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Validated ledger 42 +2024-Jan-15 10:30:45.123456789 UTC LedgerMaster:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Validated ledger 42 ``` This enables bidirectional navigation between logs and traces in Grafana: @@ -867,9 +867,11 @@ This enables bidirectional navigation between logs and traces in Grafana: ### 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. +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`). 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-node subdirectory. + +That subdirectory is load-bearing, not cosmetic. Docker creates a missing bind-mount source as root, and `Config::getDebugLogFile()` only warns when it cannot create the log directory, so a root-owned log root produces a healthy-looking node that writes no `debug.log` and an empty Loki with no error at any layer. The `xrpld-logdir-init` service creates the directory and hands it to `XRPLD_UID`/`XRPLD_GID` (default 1000) to prevent that. The receiver also lifts the subdirectory name onto the resource attribute `service.instance.id`, which Loki indexes as the label `service_instance_id`, so each emitter must name its log directory after its own `[telemetry] service_instance_id` or log lines carry a node name that no trace or metric shares. Each file is read from the beginning, because the receiver's own default (`end`) would skip anything a node wrote before the collector's first poll and would never read a log that has stopped being written to. Read offsets are held in memory by default, so a restarted collector re-reads the files it already ingested. The developer stack avoids that by layering `otel-collector-filestorage.yaml` as a second `--config`, which adds a `file_storage` extension that keeps the offsets on a named volume; a one-shot init service prepares that volume, because the collector runs as a non-root user and a fresh Docker volume is owned by root. Ephemeral stacks such as the workload validation harness create a fresh log directory per run, so they have nothing to resume from and deliberately omit the overlay. @@ -973,9 +975,9 @@ count_over_time({service_name="xrpld"} |= "trace_id=" [5m]) ### 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