diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index 8283fa92d1..28538fe724 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -627,11 +627,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 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 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 @@ -649,7 +649,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 3b0f2b16a2..42d3461511 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -943,7 +943,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 @@ -959,7 +959,7 @@ Example: - **`trace_id=`** — 32-character lowercase hex trace identifier. Links to the distributed trace in Tempo. - **`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 diff --git a/OpenTelemetryPlan/Phase8_taskList.md b/OpenTelemetryPlan/Phase8_taskList.md index 8c4d80e80b..566041bd75 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/docker-compose.yml b/docker/telemetry/docker-compose.yml index c4ec3a7bb8..42c06ebca5 100644 --- a/docker/telemetry/docker-compose.yml +++ b/docker/telemetry/docker-compose.yml @@ -27,6 +27,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: @@ -49,9 +68,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 @@ -162,6 +188,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 5615213a20..3d4e5c5134 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. @@ -221,7 +247,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 d09ce1c3e8..86ab9351bc 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -2631,7 +2631,7 @@ curl -sG http://localhost:9090/api/v1/query \ ## 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 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.