mirror of
https://github.com/XRPLF/rippled.git
synced 2026-08-19 05:10:55 +00:00
Merge branch 'pratik/otel-phase8-log-correlation' into pratik/otel-phase9-metric-gap-fill
Conflict resolutions: - docker/telemetry/xrpld-telemetry.cfg: relocation conflict. phase-9 had already moved [insight] to the end of the file with server=otel, so the incoming block was dropped rather than inserted. Keeping both would have produced two [insight] sections, which merge last-wins into a single effective section, silently reviving the bug this branch just fixed. phase-9's per-branch service_instance_id=xrpld-devnet is preserved. - OpenTelemetryPlan/06-implementation-phases.md: kept both corrections. phase-9's "Tempo" is right (no Jaeger anywhere in the stack) and phase-8's "active, sampled span" is right: Log.cpp:328 injects only when spanCtx.IsValid() && spanCtx.IsSampled(). - OpenTelemetryPlan/09-data-collection-reference.md and docs/telemetry-runbook.md: kept phase-9's structured-metadata LogQL. The collector's filelog regex_parser already extracts partition, severity, trace_id and span_id, so phase-8's inline regexp forms are redundant, and a line filter matches the literal text in a message body.
This commit is contained in:
@@ -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
|
||||
|
||||
|
||||
@@ -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=<hex32>`** — 32-character lowercase hex trace identifier. Links to the distributed trace in Tempo.
|
||||
- **`span_id=<hex16>`** — 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
|
||||
|
||||
|
||||
@@ -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<opentelemetry::trace::Span>>(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=<hex> span_id=<hex>`
|
||||
- [ ] Log lines within active, sampled spans contain `trace_id=<hex> span_id=<hex>`
|
||||
- [ ] 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
|
||||
|
||||
@@ -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).
|
||||
|
||||
@@ -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 <partition>:<severity> [trace_id=... span_id=...] <message>
|
||||
@@ -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]
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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<opentelemetry::trace::Span>>(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.
|
||||
|
||||
Reference in New Issue
Block a user