From d4282cc36e387083661e1de558e78a9ad228ecb0 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Sat, 15 Aug 2026 17:32:57 +0100 Subject: [PATCH 1/2] fix(telemetry): correct log-correlation defects found in PR review Six findings from the review of #6494 survived independent verification. Each was checked against the branch tip, and where behaviour was in question, against a live collector and Loki rather than from the reviewer's claim or from documentation alone. Plan-doc section numbering. 06-implementation-phases.md used "## 6.9" twice: for the new Phase 8 section and for the pre-existing Risk Assessment. Three references already pointed at 6.8.1 and none at 6.9, and the later phases are numbered 6.8.2 through 6.8.4, so Phase 8 becomes 6.8.1 and the sequence is monotonic. Renumbering to 6.10, as suggested on the PR, would have collided with Success Metrics. filelog read position. The receiver relied on the upstream default start_at=end, which skips everything a node wrote before the first poll and reads nothing at all from a log that has stopped being written to. Read from the beginning instead, paired with a file_storage extension so a restart resumes at the last offset rather than re-ingesting the file. The collector image runs as 10001:10001 and ships no writable directory, and a fresh named volume is root-owned, so a one-shot init service prepares the volume first. It reuses an image the stack already pulls, adding no new dependency. Loki log stream label. The job resource attribute did not become a Loki index label, so the documented {job="xrpld"} queries matched nothing. Verified against grafana/loki:3.4.2 with its default config: only service_name and deployment_environment are indexed, and job arrives as structured metadata, which a stream selector cannot match. Dropped the attribute and moved the twelve queries this branch introduced to {service_name="xrpld"}. Three further occurrences in 07-observability-backends.md originate on the phase-1a branch and are left for a commit there. Trace ids on unsampled spans. Logs::format emitted trace_id and span_id whenever the span context was valid. A span dropped by the ParentBasedSampler still carries its parent's ids, so log lines advertised traces that were never exported and the log-to-trace link resolved to nothing. Require the sampled flag as well, and correct the task list and the documentation that promised the fields unconditionally. The remaining two findings were refuted. The reported risk of signing material reaching Loki does not hold: Logs::format already scrubs seven sensitive fields, and there is a single write path to the log file, so every JLOG site is covered. The suggestion to add internalLink to the Loki derived field is not applicable, because that key is not part of Grafana's schema. --- .cspell.config.yaml | 1 + OpenTelemetryPlan/06-implementation-phases.md | 6 +-- .../09-data-collection-reference.md | 12 ++--- OpenTelemetryPlan/Phase8_taskList.md | 8 ++-- docker/telemetry/TESTING.md | 4 +- docker/telemetry/docker-compose.yml | 31 ++++++++++++- docker/telemetry/otel-collector-config.yaml | 46 +++++++++++++++---- docs/telemetry-runbook.md | 14 +++--- src/libxrpl/basics/Log.cpp | 19 ++++++-- 9 files changed, 103 insertions(+), 38 deletions(-) diff --git a/.cspell.config.yaml b/.cspell.config.yaml index 24cacf5afa..e8cc7945a5 100644 --- a/.cspell.config.yaml +++ b/.cspell.config.yaml @@ -230,6 +230,7 @@ words: - onlatest - ostr - otelc + - otelcol - oxalica - pargs - partitioner diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index aa1600de66..c17b88a28e 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -568,11 +568,11 @@ See [Phase7_taskList.md](./Phase7_taskList.md) for detailed per-task breakdown. --- -## 6.9 Phase 8: Log-Trace Correlation and Centralized Log Ingestion (Week 13) +## 6.8.1 Phase 8: Log-Trace Correlation and Centralized Log Ingestion (Week 13) ### 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 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 filelog receiver. #### Gains @@ -590,7 +590,7 @@ 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 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 filelog receiver regex is straightforward to maintain. ### Architecture diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 03c32fb428..dd197f2986 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -919,7 +919,7 @@ state_accounting_full_duration > **Plan details**: [06-implementation-phases.md §6.8.1](./06-implementation-phases.md) — motivation, architecture, Mermaid diagrams > **Task breakdown**: [Phase8_taskList.md](./Phase8_taskList.md) — per-task implementation details -Phase 8 injects OTel trace context into xrpld's `Logs::format()` output, enabling log-trace correlation. When a log line is emitted within an active OTel span, the trace and span identifiers are automatically appended after the severity field: +Phase 8 injects OTel trace context into xrpld's `Logs::format()` output, enabling log-trace correlation. When a log line is emitted within an active, sampled OTel span, the trace and span identifiers are automatically appended after the severity field: ### Log Format @@ -935,7 +935,7 @@ Example: - **`trace_id=`** — 32-character lowercase hex trace identifier. Links to the distributed trace in Tempo/Jaeger. - **`span_id=`** — 16-character lowercase hex span identifier. Identifies the specific span within the trace. -- **Only present** when the log is emitted within an active OTel span. Log lines outside of traced code paths have no trace context fields. +- **Only present** when the log is emitted within an active OTel span whose context is sampled. Log lines outside of traced code paths, and lines inside a span the sampler dropped, have no trace context fields. A dropped span still carries its parent's identifiers, so emitting them would point at a trace that was never exported. ### Implementation @@ -973,16 +973,16 @@ Grafana Loki (v3.4.2) serves as the log storage backend. It receives log entries ```logql # Find all logs for a specific trace -{job="xrpld"} |= "trace_id=abc123def456789012345678abcdef01" +{service_name="xrpld"} |= "trace_id=abc123def456789012345678abcdef01" # Error logs with trace context -{job="xrpld"} |= "ERR" |= "trace_id=" +{service_name="xrpld"} |= "ERR" |= "trace_id=" # Logs from a specific partition with trace context -{job="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P[a-f0-9]+)` | trace_id != "" +{service_name="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P[a-f0-9]+)` | trace_id != "" # Count traced log lines over time -count_over_time({job="xrpld"} |= "trace_id=" [5m]) +count_over_time({service_name="xrpld"} |= "trace_id=" [5m]) ``` --- diff --git a/OpenTelemetryPlan/Phase8_taskList.md b/OpenTelemetryPlan/Phase8_taskList.md index 7849990858..f9bbb0e2ab 100644 --- a/OpenTelemetryPlan/Phase8_taskList.md +++ b/OpenTelemetryPlan/Phase8_taskList.md @@ -19,7 +19,7 @@ ## Task 8.1: Inject trace_id into Logs::format() -**Objective**: Add OTel trace context to every log line that is emitted within an active span. +**Objective**: Add OTel trace context to every log line that is emitted within an active, sampled span. The sampled flag matters because a span dropped by the `ParentBasedSampler` still carries its parent's ids, so emitting them would advertise a trace that was never exported. **What to do**: @@ -36,7 +36,7 @@ auto span = opentelemetry::nostd::get< opentelemetry::nostd::shared_ptr>(spanValue); auto spanCtx = span->GetContext(); - if (spanCtx.IsValid()) + if (spanCtx.IsValid() && spanCtx.IsSampled()) { char traceId[32], spanId[16]; spanCtx.trace_id().ToLowerBase16( @@ -62,7 +62,7 @@ - `src/libxrpl/basics/Log.cpp` -**Performance note**: The implementation checks the thread-local context value directly (avoiding the heap allocation that `GetSpan()` performs on the no-span path). On threads without an active span (~99% of log lines), the cost is a thread-local read + variant type check (~15-20ns). On the active-span path, an additional shared_ptr copy + `GetContext()` + `IsValid()` adds ~50ns total. Overhead is negligible at typical logging rates. +**Performance note**: The implementation checks the thread-local context value directly (avoiding the heap allocation that `GetSpan()` performs on the no-span path). On threads without an active span (~99% of log lines), the cost is a thread-local read + variant type check (~15-20ns). On the active-span path, an additional shared_ptr copy + `GetContext()` + `IsValid()`/`IsSampled()` adds ~50ns total. Overhead is negligible at typical logging rates. --- @@ -230,7 +230,7 @@ **Exit Criteria** (from [06-implementation-phases.md §6.8.1](./06-implementation-phases.md)): -- [ ] Log lines within active spans contain `trace_id= span_id=` +- [ ] Log lines within active, sampled 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 - [ ] Grafana Tempo -> Loki one-click correlation works diff --git a/docker/telemetry/TESTING.md b/docker/telemetry/TESTING.md index dd7e8a66ca..d6404c0ee1 100644 --- a/docker/telemetry/TESTING.md +++ b/docker/telemetry/TESTING.md @@ -517,7 +517,7 @@ 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" \ - --data-urlencode 'query={job="xrpld"}' \ + --data-urlencode 'query={service_name="xrpld"}' \ --data-urlencode 'limit=5' | jq '.data.result | length' ``` @@ -534,7 +534,7 @@ Expected: > 0 results. ### Step 5: Verify Grafana Loki-to-Tempo correlation 1. In Grafana **Explore**, select **Loki** datasource -2. Query: `{job="xrpld"} |= "trace_id="` +2. Query: `{service_name="xrpld"} |= "trace_id="` 3. In the log results, click the **TraceID** derived field link 4. Verify it navigates to the full trace in Tempo diff --git a/docker/telemetry/docker-compose.yml b/docker/telemetry/docker-compose.yml index 44709c4ca8..faeacedae3 100644 --- a/docker/telemetry/docker-compose.yml +++ b/docker/telemetry/docker-compose.yml @@ -21,6 +21,25 @@ # endpoint=http://localhost:4318/v1/traces services: + # One-shot init for the collector's offset store. Docker creates a fresh + # named volume owned by root, but the collector image runs as 10001:10001 + # and ships no writable directory, so the file_storage extension could not + # create its database and the collector would fail to start. Chown the + # volume once, then exit; the collector waits for this to complete. + # + # Reuses the Prometheus image purely because the stack already pulls it and + # it has a shell — this adds no new image dependency. The entrypoint is + # overridden since that image normally starts the Prometheus server. + otelcol-storage-init: + image: prom/prometheus:v3.13.2 + user: "0:0" + entrypoint: ["sh", "-c"] + command: ["mkdir -p /data/file_storage && chown -R 10001:10001 /data"] + volumes: + - otelcol-storage:/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: @@ -43,9 +62,16 @@ services: # 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. - ${XRPLD_LOG_DIR:-./data/logs}:/var/log/xrpld:ro + # Persisted filelog read offsets, so a collector restart resumes + # instead of re-reading every debug.log from the top. + - otelcol-storage:/var/lib/otelcol depends_on: - - tempo - - loki + tempo: + condition: service_started + loki: + condition: service_started + otelcol-storage-init: + condition: service_completed_successfully networks: - xrpld-telemetry @@ -118,6 +144,7 @@ volumes: tempo-data: prometheus-data: loki-data: + otelcol-storage: # Isolated bridge network so services communicate by container name # (e.g., the collector reaches Tempo at http://tempo:4317). diff --git a/docker/telemetry/otel-collector-config.yaml b/docker/telemetry/otel-collector-config.yaml index 8025232113..2b65abf475 100644 --- a/docker/telemetry/otel-collector-config.yaml +++ b/docker/telemetry/otel-collector-config.yaml @@ -23,6 +23,18 @@ extensions: health_check: endpoint: 0.0.0.0:13133 + # Persists filelog read offsets so a collector restart resumes where it + # stopped instead of re-reading each debug.log from the top. Without this + # the receiver keeps offsets in memory only. + # + # The directory must be writable by the user the collector runs as. The + # image ships no writable directory (no /var/lib, no /tmp), so this path + # comes from a mounted volume; see the otel-collector service in + # docker-compose.yml. Point `directory` somewhere else if a deployment + # mounts its state elsewhere. + file_storage/filelog: + directory: /var/lib/otelcol/file_storage + create_directory: true receivers: otlp: @@ -37,6 +49,14 @@ receivers: # optional — only present when the log was emitted within an active span. filelog: include: [/var/log/xrpld/*/debug.log] + # 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 + # nothing is read at all from a file that has stopped being written to. + # Paired with the file_storage extension above so restarting the + # collector resumes at the last offset rather than re-ingesting the file. + start_at: beginning + storage: file_storage/filelog operators: # Log format emitted by Logs::format() is: # YYYY-Mmm-DD HH:MM:SS.ffffff UTC : [trace_id=... span_id=...] @@ -56,18 +76,24 @@ processors: send_batch_size: 100 resource/logs: attributes: + # Loki 3.x OTLP ingestion promotes only its own allow-list of resource + # attributes to stream (index) labels; `service.name` is on that list + # and arrives as the label `service_name`, which is what the LogQL + # examples in the runbook and TESTING.md select on. + # + # A custom `job` attribute is NOT on that list. Verified against + # grafana/loki:3.4.2 with the default config: after ingesting through + # this pipeline, /loki/api/v1/labels returned only `service_name` and + # `deployment_environment`, `{job="xrpld"}` matched 0 streams, and + # `job` appeared as structured metadata instead — which a `{...}` + # stream selector cannot match. Promoting it would mean mounting a Loki + # config and adding it to limits_config.otlp_config.resource_attributes + # (additive to Loki's defaults unless ignore_defaults is set), which is + # not worth a constant value — especially as Loki caps index labels at + # 15 and already promotes ~17 by default. Select on `service_name`. - key: service.name value: xrpld action: upsert - # Loki 3.x OTLP ingestion converts `service.name` to the label - # `service_name`. The runbook and integration-test queries use the - # canonical Loki label `job` so operators can paste `{job="xrpld"}` - # without guessing the otel-to-loki naming convention. Upsert the - # `job` resource attribute here so it round-trips through OTLP - # into Loki as the `job` label. - - key: job - value: xrpld - action: upsert # Deployment-tier tagging. Each collector serves ONE environment and ONE # network, so it stamps both onto every signal it forwards. This lets a # single Grafana stack hold data from many collectors and filter by tier. @@ -175,7 +201,7 @@ exporters: enabled: true service: - extensions: [health_check] + extensions: [health_check, file_storage/filelog] pipelines: traces: receivers: [otlp] diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 7d7ee5bdc4..bc35e8f516 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -806,7 +806,7 @@ Requires `trace_peer=1` in the `[telemetry]` config section. ## Log-Trace Correlation -When xrpld is built with `telemetry=ON`, log lines emitted within an active OpenTelemetry span automatically include `trace_id` and `span_id` fields: +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 @@ -827,19 +827,19 @@ The receiver tails `/var/log/xrpld/*/debug.log` inside the collector container. ```logql # Find all logs for a specific trace -{job="xrpld"} |= "trace_id=abc123def456789012345678abcdef01" +{service_name="xrpld"} |= "trace_id=abc123def456789012345678abcdef01" # Error logs with trace context (log lines with ERR severity that have a trace_id) -{job="xrpld"} |= "ERR" |= "trace_id=" +{service_name="xrpld"} |= "ERR" |= "trace_id=" # All logs from a specific partition that were emitted during a span -{job="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P[a-f0-9]+)` | trace_id != "" +{service_name="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P[a-f0-9]+)` | trace_id != "" # Logs from the last hour containing trace context -{job="xrpld"} |= "trace_id=" | regexp `(?P\S+):(?P\S+)\s+trace_id=(?P[a-f0-9]+)` +{service_name="xrpld"} |= "trace_id=" | regexp `(?P\S+):(?P\S+)\s+trace_id=(?P[a-f0-9]+)` # Count of traced vs untraced log lines -count_over_time({job="xrpld"} |= "trace_id=" [5m]) +count_over_time({service_name="xrpld"} |= "trace_id=" [5m]) ``` ### Verifying Log Correlation @@ -847,7 +847,7 @@ count_over_time({job="xrpld"} |= "trace_id=" [5m]) 1. Start the observability stack and xrpld with telemetry enabled. 2. Send an RPC request: `curl http://localhost:5005 -d '{"method":"server_info"}'` 3. Check the debug.log for `trace_id=` entries: `grep trace_id= /path/to/debug.log` -4. Open Grafana at http://localhost:3000 -> Explore -> Loki and search for `{job="xrpld"} |= "trace_id="`. +4. Open Grafana at http://localhost:3000 -> Explore -> Loki and search for `{service_name="xrpld"} |= "trace_id="`. 5. Click the TraceID link to navigate to the corresponding trace in Tempo. ## Troubleshooting diff --git a/src/libxrpl/basics/Log.cpp b/src/libxrpl/basics/Log.cpp index 46a3829e78..bf46844143 100644 --- a/src/libxrpl/basics/Log.cpp +++ b/src/libxrpl/basics/Log.cpp @@ -302,9 +302,9 @@ Logs::format( } #ifdef XRPL_ENABLE_TELEMETRY - // Inject OTel trace context when an active span exists on this thread. - // Checks the thread-local context value directly to avoid the heap - // allocation that GetSpan() performs on the no-span path. + // Inject OTel trace context when an active, sampled span exists on this + // thread. Checks the thread-local context value directly to avoid the + // heap allocation that GetSpan() performs on the no-span path. { auto context = opentelemetry::context::RuntimeContext::GetCurrent(); auto spanValue = context.GetValue(opentelemetry::trace::kSpanKey); @@ -314,7 +314,18 @@ Logs::format( auto span = opentelemetry::nostd::get< opentelemetry::nostd::shared_ptr>(spanValue); auto spanCtx = span->GetContext(); - if (spanCtx.IsValid()) + // Require the sampled flag as well as a valid context. A dropped + // span still carries its parent's ids, so a valid context does + // not imply the span reaches the backend. An unsampled remote + // parent arrives either because an upstream node propagated + // sampled=0, or because a peer omitted trace_flags entirely and + // it defaults to 0 (TraceContextPropagator, TxTracing, + // ConsensusReceiveTracing). Either way the ParentBasedSampler + // drops the local span, while the tracer still returns a no-op + // span with a valid context. + // Logging those ids would advertise a trace that was never + // exported, leaving the log-to-trace link resolving to nothing. + if (spanCtx.IsValid() && spanCtx.IsSampled()) { // Hex widths of a W3C trace context: 16-byte trace_id and // 8-byte span_id render to 32 and 16 lowercase hex chars. From a61c34971200df73ecbde8afb8cdd906e6a8acd1 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Sat, 15 Aug 2026 17:48:44 +0100 Subject: [PATCH 2/2] fix(telemetry): switch sample config to server=otel This branch removes the collector's StatsD receiver and un-publishes 8125/udp, but xrpld-telemetry.cfg still selected server=statsd, so the sample config sent beast::insight metrics over UDP to a port nothing listens on. Phase7_taskList.md:132 lists this switch as required work. Select server=otel and replace address= with the OTLP metrics endpoint. Document that endpoint and prefix are informational only, since OTelCollector records on the global MeterProvider that [telemetry] configures and formatName() applies no prefix, and note that beast instruments are not exported yet because the collector is constructed before the MeterProvider is registered. --- docker/telemetry/xrpld-telemetry.cfg | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/docker/telemetry/xrpld-telemetry.cfg b/docker/telemetry/xrpld-telemetry.cfg index 0a50c3bbaa..f03af1cbde 100644 --- a/docker/telemetry/xrpld-telemetry.cfg +++ b/docker/telemetry/xrpld-telemetry.cfg @@ -58,10 +58,17 @@ trace_consensus=1 trace_peer=1 trace_ledger=1 -# --- StatsD metrics (beast::insight) --- -# Sends UDP metrics to the collector's StatsD receiver so the StatsD -# dashboards have data. The collector binds this port on the host loopback. +# --- Insight (native OTel metrics via beast::insight) --- +# server selects the beast::insight backend. Only server=otel is usable with +# this stack: the collector defines no StatsD receiver and 8125/udp is not +# published, so server=statsd sends UDP to a port nothing listens on. +# endpoint and prefix are informational only. OTelCollector records on the +# global MeterProvider that [telemetry] configures, and formatName() does not +# apply the prefix, so metric names are bare and lowercase. +# Known limitation: the collector is built before the MeterProvider is +# registered, so beast::insight instruments bind to a no-op meter and are not +# exported yet. Tracing and the [telemetry] metrics pipeline are unaffected. [insight] -server=statsd -address=127.0.0.1:8125 +server=otel +endpoint=http://localhost:4318/v1/metrics prefix=xrpld