diff --git a/.cspell.config.yaml b/.cspell.config.yaml index 405c5fe68af..1a96e67a198 100644 --- a/.cspell.config.yaml +++ b/.cspell.config.yaml @@ -180,6 +180,7 @@ words: - libxrpl - llection - LOCALGOOD + - logql - logwstream - Lombrozo - lresolv @@ -238,6 +239,7 @@ words: - onlatest - ostr - otelc + - otelcol - otool - oxalica - pargs diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index 54a2f8a2b80..0dad6834a0f 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -52,6 +52,15 @@ gantt section Phase 5 Documentation & Deploy :p5, after p4, 1w + + section Phase 6 + StatsD Metrics Bridge :p6, after p5, 1w + + section Phase 7 + Native OTel Metrics :p7, after p6, 2w + + section Phase 8 + Log-Trace Correlation :p8, after p7, 1w ``` --- @@ -561,6 +570,154 @@ See [Phase7_taskList.md](./Phase7_taskList.md) for detailed per-task breakdown. --- +## 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, 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 (`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 + +1. **Log format change** — Existing log parsers that rely on a fixed format will need updating to handle the optional `trace_id=... span_id=...` fields. +2. **Loki resource usage** — Log ingestion adds storage and memory overhead to the observability stack (mitigated by retention policies). +3. **Filelog receiver complexity** — The regex parser must be kept in sync with the log format; a format change in `Logs::format()` could break parsing. + +#### 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 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 `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())** + 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 -.->|"`GetContext() + if IsValid and IsSampled`"| Format + end + + 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 + style Format fill:#283593,stroke:#1a237e,color:#fff + style OTelCtx fill:#283593,stroke:#1a237e,color:#fff + style LogLine fill:#2e7d32,stroke:#1b5e20,color:#fff +``` + +#### Loki Ingestion Pipeline + +```mermaid +flowchart LR + subgraph collector["OTel Collector"] + 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**`"] + + 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 + style RP fill:#f57c00,stroke:#e65100,color:#fff + style BP fill:#f57c00,stroke:#e65100,color:#fff + style LE fill:#f57c00,stroke:#e65100,color:#fff + style LogFile fill:#1a237e,stroke:#0d1642,color:#fff + style Loki fill:#4a148c,stroke:#2e0d57,color:#fff + style Tempo fill:#4a148c,stroke:#2e0d57,color:#fff +``` + +### Tasks + +| Task | Description | +| ---- | ---------------------------------------------- | +| 8.1 | Inject trace_id into Logs::format() | +| 8.2 | Add Loki to Docker Compose stack | +| 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) | + +**Parallel work**: Task 8.2 (Loki infra) can run in parallel with Task 8.1 (code change). Tasks 8.3–8.6 are sequential. + +### Exit Criteria + +- [ ] 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 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 +- [ ] No performance regression from trace_id injection (< 0.1% overhead) + +--- + ## 6.9 Risk Assessment ```mermaid @@ -839,6 +996,7 @@ Clear, measurable criteria for each phase. | Phase 5 | Production deployment | Operators trained | End of Week 9 | | Phase 6 | StatsD metrics in Prometheus | 3 dashboards operational | End of Week 10 | | Phase 7 | All metrics via OTLP | No StatsD dependency | End of Week 12 | +| Phase 8 | trace_id in logs + Loki | Tempo↔Loki correlation | End of Week 13 | --- diff --git a/OpenTelemetryPlan/08-appendix.md b/OpenTelemetryPlan/08-appendix.md index 00ab25c0dc9..a98b91d803e 100644 --- a/OpenTelemetryPlan/08-appendix.md +++ b/OpenTelemetryPlan/08-appendix.md @@ -193,6 +193,7 @@ flowchart TB | [Phase5_taskList.md](./Phase5_taskList.md) | Ledger processing & advanced tracing | | [Phase5_IntegrationTest_taskList.md](./Phase5_IntegrationTest_taskList.md) | Observability stack integration tests | | [Phase7_taskList.md](./Phase7_taskList.md) | Native OTel metrics migration | +| [Phase8_taskList.md](./Phase8_taskList.md) | Log-trace correlation | --- diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 70acd07a8cb..5daeda135d7 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -941,6 +941,79 @@ state_accounting_full_duration --- +## 5a. Log-Trace Correlation (Phase 8) + +> **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, sampled OTel span, the trace and span identifiers are automatically appended after the severity field: + +### Log Format + +``` + : trace_id=<32hex> span_id=<16hex> +``` + +Example: + +``` +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. +- **`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 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 + +The trace context injection is implemented in `Logs::format()` (`src/libxrpl/basics/Log.cpp`), guarded by `#ifdef XRPL_ENABLE_TELEMETRY`. It checks the thread-local runtime context value directly (via `RuntimeContext::GetCurrent().GetValue(kSpanKey)`) to avoid the heap allocation that `GetSpan()` performs on the no-span path. On threads without an active span, the cost is a thread-local read + variant type check (~15-20ns). On the active-span path, total cost is ~50ns per log call. + +### Log Ingestion Pipeline + +``` +xrpld debug.log -> OTel Collector file_log receiver -> regex_parser -> Loki exporter -> Grafana Loki +``` + +The OTel Collector's `file_log` receiver tails `debug.log` files and uses a `regex_parser` operator to extract structured fields: + +| Field | Type | Description | +| ----------- | -------- | -------------------------------------------------------- | +| `timestamp` | datetime | Log timestamp | +| `partition` | string | Log partition (e.g., `LedgerMaster`, `PeerImp`) | +| `severity` | string | Severity code (`TRC`, `DBG`, `NFO`, `WRN`, `ERR`, `FTL`) | +| `trace_id` | string | 32-hex trace identifier (optional) | +| `span_id` | string | 16-hex span identifier (optional) | +| `message` | string | Log message body | + +### Grafana Correlation + +Bidirectional linking between logs and traces is configured via Grafana datasource provisioning: + +- **Tempo -> Loki** (`tracesToLogs`): Clicking "Logs for this trace" on a Tempo trace view filters Loki logs by `trace_id`, showing all log lines from that trace. +- **Loki -> Tempo** (`derivedFields`): A regex-based derived field on the Loki datasource extracts `trace_id` from log lines and renders it as a clickable link to the corresponding trace in Tempo. + +### Loki Backend + +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 + +```logql +# Find all logs for a specific trace +{service_name="xrpld"} |= "trace_id=abc123def456789012345678abcdef01" + +# Error logs with trace context +{service_name="xrpld"} |= "ERR" |= "trace_id=" + +# Logs from a specific partition with trace context +{service_name="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P[a-f0-9]+)` | trace_id != "" + +# Count traced log lines over time +count_over_time({service_name="xrpld"} |= "trace_id=" [5m]) +``` + +--- + ## 6. Known Issues | Issue | Impact | Status | diff --git a/OpenTelemetryPlan/OpenTelemetryPlan.md b/OpenTelemetryPlan/OpenTelemetryPlan.md index 760d50822e1..280367e0d62 100644 --- a/OpenTelemetryPlan/OpenTelemetryPlan.md +++ b/OpenTelemetryPlan/OpenTelemetryPlan.md @@ -164,7 +164,7 @@ OpenTelemetry Collector configurations are provided for development and producti ## 6. Implementation Phases -The implementation spans 12 weeks across 7 phases: +The implementation spans 13 weeks across 8 phases: | Phase | Duration | Focus | Key Deliverables | | ----- | ----------- | --------------------- | ----------------------------------------------------------- | @@ -175,8 +175,9 @@ The implementation spans 12 weeks across 7 phases: | 5 | Week 9 | Documentation | Runbook, Dashboards, Training | | 6 | Week 10 | StatsD Metrics Bridge | OTel Collector StatsD receiver, 3 Grafana dashboards | | 7 | Weeks 11-12 | Native OTel Metrics | OTelCollector impl, OTLP metrics export, StatsD deprecation | +| 8 | Week 13 | Log-Trace Correlation | trace_id in logs, Loki ingestion, Tempo↔Loki linking | -**Total Effort**: 60.6 developer-days with 2 developers +**Total Effort**: 65.1 developer-days with 2 developers ➡️ **[View full Implementation Phases](./06-implementation-phases.md)** diff --git a/OpenTelemetryPlan/Phase8_taskList.md b/OpenTelemetryPlan/Phase8_taskList.md new file mode 100644 index 00000000000..f9bbb0e2abe --- /dev/null +++ b/OpenTelemetryPlan/Phase8_taskList.md @@ -0,0 +1,239 @@ +# Phase 8: Log-Trace Correlation and Centralized Log Ingestion — Task List + +> **Goal**: Inject trace context (trace_id, span_id) into xrpld's Journal log output for log-trace correlation, and add OTel Collector filelog receiver to ingest logs into Grafana Loki for unified observability. +> +> **Scope**: Two independent sub-phases — 8a (code change: trace_id in logs) and 8b (infra only: filelog receiver to Loki). No changes to the `beast::Journal` public API. +> +> **Branch**: `pratik/otel-phase8-log-correlation` (from `pratik/otel-phase7-native-metrics`) + +### Related Plan Documents + +| Document | Relevance | +| ---------------------------------------------------------------- | -------------------------------------------------------------- | +| [06-implementation-phases.md](./06-implementation-phases.md) | Phase 8 plan: motivation, architecture, exit criteria (§6.8.1) | +| [07-observability-backends.md](./07-observability-backends.md) | Loki backend recommendation, Grafana data source provisioning | +| [Phase7_taskList.md](./Phase7_taskList.md) | Prerequisite — native OTel metrics pipeline must be working | +| [05-configuration-reference.md](./05-configuration-reference.md) | `[telemetry]` config (trace_id injection toggle) | + +--- + +## Task 8.1: Inject trace_id into Logs::format() + +**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**: + +- Edit `src/libxrpl/basics/Log.cpp`: + - In `Logs::format()` (around line 346), after severity is appended, check for active OTel span. The implementation checks the context value directly to avoid the heap allocation that `GetSpan()` performs on the no-span path: + ```cpp + #ifdef XRPL_ENABLE_TELEMETRY + { + auto context = opentelemetry::context::RuntimeContext::GetCurrent(); + auto spanValue = context.GetValue(opentelemetry::trace::kSpanKey); + if (opentelemetry::nostd::holds_alternative< + opentelemetry::nostd::shared_ptr>(spanValue)) + { + auto span = opentelemetry::nostd::get< + opentelemetry::nostd::shared_ptr>(spanValue); + auto spanCtx = span->GetContext(); + if (spanCtx.IsValid() && spanCtx.IsSampled()) + { + char traceId[32], spanId[16]; + spanCtx.trace_id().ToLowerBase16( + opentelemetry::nostd::span{traceId}); + spanCtx.span_id().ToLowerBase16( + opentelemetry::nostd::span{spanId}); + output += "trace_id="; + output.append(traceId, 32); + output += " span_id="; + output.append(spanId, 16); + output += ' '; + } + } + } + #endif + ``` + - Add `#include` for OTel context headers, guarded by `#ifdef XRPL_ENABLE_TELEMETRY` + +- Edit `include/xrpl/basics/Log.h`: + - No changes needed — format() signature unchanged + +**Key modified files**: + +- `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()`/`IsSampled()` adds ~50ns total. Overhead is negligible at typical logging rates. + +--- + +## Task 8.2: Add Loki to Docker Compose Stack + +**Objective**: Add Grafana Loki as a log storage backend in the development observability stack. + +**What to do**: + +- Edit `docker/telemetry/docker-compose.yml`: + - Add Loki service: + ```yaml + loki: + image: grafana/loki:3.4.2 + ports: + - "3100:3100" + command: -config.file=/etc/loki/local-config.yaml + ``` + - Add Loki as a Grafana data source in provisioning + +- Create `docker/telemetry/grafana/provisioning/datasources/loki.yaml`: + - Configure Loki data source with derived fields linking `trace_id` to Tempo + +**Key new files**: + +- `docker/telemetry/grafana/provisioning/datasources/loki.yaml` + +**Key modified files**: + +- `docker/telemetry/docker-compose.yml` + +--- + +## Task 8.3: Add Filelog Receiver to OTel Collector + +**Objective**: Configure the OTel Collector to tail xrpld's log file and export to Loki. + +**What to do**: + +- Edit `docker/telemetry/otel-collector-config.yaml`: + - Add `filelog` receiver: + ```yaml + receivers: + filelog: + include: [/var/log/xrpld/*/debug.log] + operators: + - type: regex_parser + regex: '^(?P\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-%m-%dT%H:%M:%S.%fZ" + ``` + - Add logs pipeline: + ```yaml + service: + pipelines: + logs: + receivers: [filelog] + processors: [batch] + exporters: [otlp/loki] + ``` + - Add Loki exporter: + ```yaml + exporters: + otlphttp/loki: + endpoint: http://loki:3100/otlp + ``` + +- Mount xrpld's log directory into the collector container via docker-compose volume + +**Key modified files**: + +- `docker/telemetry/otel-collector-config.yaml` +- `docker/telemetry/docker-compose.yml` + +--- + +## Task 8.4: Configure Grafana Trace-to-Log Correlation + +**Objective**: Enable one-click navigation from Tempo traces to Loki logs in Grafana. + +**What to do**: + +- Edit Grafana Tempo data source provisioning to add `tracesToLogs` configuration: + + ```yaml + tracesToLogs: + datasourceUid: loki + filterByTraceID: true + filterBySpanID: false + tags: ["partition", "severity"] + ``` + +- Edit Grafana Loki data source provisioning to add `derivedFields` linking trace_id back to Tempo: + ```yaml + derivedFields: + - datasourceUid: tempo + matcherRegex: "trace_id=(\\w+)" + name: TraceID + url: "$${__value.raw}" + ``` + +**Key modified files**: + +- `docker/telemetry/grafana/provisioning/datasources/loki.yaml` +- `docker/telemetry/grafana/provisioning/datasources/` (Tempo data source file) + +--- + +## Task 8.5: Update Integration Tests + +**Objective**: Verify trace_id appears in logs and Loki correlation works. + +**What to do**: + +- Edit `docker/telemetry/integration-test.sh`: + - After sending RPC requests (which create spans), grep xrpld's log output for `trace_id=` + - Verify trace_id matches a trace visible in Tempo + - Optionally: query Loki via API to confirm log ingestion + +**Key modified files**: + +- `docker/telemetry/integration-test.sh` + +--- + +## Task 8.6: Update Documentation + +**Objective**: Document the log correlation feature in runbook and reference docs. + +**What to do**: + +- Edit `docs/telemetry-runbook.md`: + - Add "Log-Trace Correlation" section explaining how to use Grafana Tempo -> Loki linking + - Add LogQL query examples for filtering by trace_id + +- Edit `OpenTelemetryPlan/09-data-collection-reference.md`: + - Add new section "3. Log Correlation" between SpanMetrics and StatsD sections + - Document the log format with trace_id injection + - Document Loki as a new backend + +- Edit `docker/telemetry/TESTING.md`: + - Add log correlation verification steps + +**Key modified files**: + +- `docs/telemetry-runbook.md` +- `OpenTelemetryPlan/09-data-collection-reference.md` +- `docker/telemetry/TESTING.md` + +--- + +## Summary Table + +| Task | Description | Sub-Phase | New Files | Modified Files | Depends On | +| ---- | ------------------------------------------ | --------- | --------- | -------------- | ---------- | +| 8.1 | Inject trace_id into Logs::format() | 8a | 0 | 1 | Phase 7 | +| 8.2 | Add Loki to Docker Compose stack | 8b | 1 | 1 | -- | +| 8.3 | Add filelog receiver to OTel Collector | 8b | 0 | 2 | 8.1, 8.2 | +| 8.4 | Configure Grafana trace-to-log correlation | 8b | 0 | 2 | 8.3 | +| 8.5 | Update integration tests | 8a + 8b | 0 | 1 | 8.4 | +| 8.6 | Update documentation | 8a + 8b | 0 | 3 | 8.5 | + +**Parallel work**: Task 8.2 (Loki infra) can run in parallel with Task 8.1 (code change). Tasks 8.3-8.6 are sequential. + +**Exit Criteria** (from [06-implementation-phases.md §6.8.1](./06-implementation-phases.md)): + +- [ ] 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 +- [ ] Grafana Loki -> Tempo reverse lookup works via derived field +- [ ] Integration test verifies trace_id presence in logs +- [ ] No performance regression from trace_id injection (< 0.1% overhead) diff --git a/docker/telemetry/TESTING.md b/docker/telemetry/TESTING.md index afa75ff7b90..fbb07247a8e 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 @@ -288,14 +297,14 @@ protocol = peer [node_db] type=NuDB -path=/tmp/xrpld-integration/node{N}/nudb +path=/tmp/xrpld-integration/Node-{N}/nudb online_delete=256 [database_path] -/tmp/xrpld-integration/node{N}/db +/tmp/xrpld-integration/Node-{N}/db [debug_logfile] -/tmp/xrpld-integration/node{N}/debug.log +/tmp/xrpld-integration/Node-{N}/debug.log [validation_seed] {seed from step 2} @@ -332,12 +341,22 @@ trace_ledger=1 server=otel [rpc_startup] -{ "command": "log_level", "severity": "warning" } +{ "command": "log_level", "severity": "info" } [ssl_verify] 0 ``` +The per-node directory name must equal `[telemetry] service_instance_id`: the +collector reads the node name off the log file's path and stamps it as the Loki +label `service_instance_id`, so a mismatch leaves the logs labelled with a node +name that no trace or metric shares. + +`log_level` is `info`, not `warning`. A log line carries trace context only when +it is emitted inside an active span, and the pair that reliably carries it — the +`CNF Val` / `CNF buildLCL` branches inside the consensus accept span, one of +which fires for every accepted ledger — logs at `info`. + #### Step 4: Create validators.txt ```ini @@ -562,6 +581,109 @@ Pre-configured datasources: - **Tempo**: Trace data at `http://tempo:3200` - **Prometheus**: Metrics at `http://prometheus:9090` +- **Loki**: Log data at `http://loki:3100` (via Grafana Explore) + +--- + +## Test 3: Log-Trace Correlation + +xrpld injects `trace_id` and `span_id` into its log output when +a log line is emitted within an active OTel span. This test verifies the +end-to-end log-trace correlation pipeline. + +### Step 1: Verify trace_id in log output + +After running Test 1 or Test 2 (which generate RPC spans), check the +xrpld debug.log for trace context: + +```bash +grep 'trace_id=[a-f0-9]\{32\} span_id=[a-f0-9]\{16\}' /path/to/debug.log +``` + +Expected: log lines with `trace_id=<32hex> span_id=<16hex>` between the +severity code and the message. Example: + +``` +2024-Jan-15 10:30:45.123456789 UTC RPCHandler:DBG trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef RPC call server_info completed in 0.000123seconds +``` + +That example is a Test 1 line. `xrpld-telemetry.cfg` logs at `debug`, so the +in-span RPC statement above appears. Test 2's nodes log at `info`, which +suppresses it — there, look for the `CNF Val` / `CNF buildLCL` lines from the +consensus accept span instead. Either carries trace context; only the message +differs. + +Lines emitted outside of an active span (background tasks, startup) will +NOT have trace context — this is expected. + +### Step 2: Cross-check trace_id in Tempo + +Extract a `trace_id` from the log and verify it exists in Tempo: + +```bash +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 '.batches | length' +``` + +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 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 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 "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 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, so a +check that needs a count rather than the lines themselves can use the instant +endpoint. `query_range` timestamps are unix nanoseconds. +Counting `.data.result | length` would count streams, not log lines. + +### Step 4: Verify Grafana Tempo-to-Loki correlation + +1. Open Grafana at http://localhost:3000 +2. Navigate to **Explore** -> select **Tempo** datasource +3. Search for a trace (e.g., operation `rpc.command.server_info`) +4. Expand a span and click **"Logs for this span"** in its **Links** row +5. Verify that Loki log lines appear, filtered by the trace's `trace_id` + +### Step 5: Verify Grafana Loki-to-Tempo correlation + +1. In Grafana **Explore**, select **Loki** datasource +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 + +### Expected results + +| Check | Expected | +| --------------------------- | ---------------------------------------- | +| `trace_id=` in debug.log | Present in log lines within active spans | +| `span_id=` in debug.log | Present alongside trace_id | +| Logs without active span | No trace_id/span_id fields | +| trace_id in Tempo | Matches a valid trace | +| Loki log ingestion | Logs visible via LogQL | +| Tempo -> Loki span log link | Shows correlated log lines | +| Loki -> Tempo TraceID link | Navigates to correct trace | --- @@ -590,7 +712,7 @@ Pre-configured datasources: ``` 2. Verify `[ips_fixed]` lists the 5 other peer ports, and not the node's own 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`. In `src/libxrpl/peerfinder/Config.cpp` it sets both `autoConnect = !standalone && !peerPrivate` and `wantIncoming = (!config.peerPrivate) && (port != 0)`, so it stops the node @@ -608,6 +730,47 @@ Pre-configured datasources: 2. Check submit response for error codes 3. In standalone mode, remember to call `ledger_accept` after submitting +### No trace_id in log output + +1. Verify xrpld was built with `telemetry=ON` (`-Dtelemetry=ON` in CMake) +2. Verify `enabled=1` in the `[telemetry]` config section +3. Log lines only contain trace context when emitted inside an active span. + Background logs (startup, periodic tasks outside spans) will not have + `trace_id`/`span_id`. +4. Ensure the trace category is enabled (e.g., `trace_rpc=1` for RPC logs) + +### No logs in Loki + +1. Verify the log file mount in docker-compose.yml: + ```yaml + volumes: + - ${XRPLD_LOG_DIR:-./data/logs}:/var/log/xrpld:ro + ``` + 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 file_log receiver errors: + ```bash + 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 file_log receiver glob pattern matches your log files: + The default pattern is `/var/log/xrpld/*/debug.log` + +### Grafana trace-log links not working + +1. Verify `tracesToLogs` is configured in the Tempo datasource provisioning + (`docker/telemetry/grafana/provisioning/datasources/tempo.yaml`) +2. Verify `derivedFields` is configured in the Loki datasource provisioning + (`docker/telemetry/grafana/provisioning/datasources/loki.yaml`) +3. Restart Grafana after changing provisioning files: + ```bash + docker compose -f docker/telemetry/docker-compose.yml restart grafana + ``` + ### Spanmetrics not appearing in Prometheus 1. Verify otel-collector config has `span_metrics` connector diff --git a/docker/telemetry/docker-compose.yml b/docker/telemetry/docker-compose.yml index 344e0cbd172..e8960f60f67 100644 --- a/docker/telemetry/docker-compose.yml +++ b/docker/telemetry/docker-compose.yml @@ -2,12 +2,15 @@ # # Provides services for local development: # - otel-collector: receives OTLP traces from xrpld, batches and -# forwards them to Tempo. Listens on ports 4317 (gRPC) -# and 4318 (HTTP). +# forwards them to Tempo. Also tails xrpld log files +# 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). -# - grafana: dashboards on port 3000, pre-configured with Tempo -# and Prometheus datasources. +# - loki: Grafana Loki log aggregation backend for centralized log +# ingestion and log-trace correlation. +# - grafana: dashboards on port 3000, pre-configured with Tempo, +# Prometheus, and Loki datasources. # # Usage: # docker compose -f docker/telemetry/docker-compose.yml up -d @@ -18,11 +21,60 @@ # traces_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 + + # 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 - command: ["--config=/etc/otel-collector-config.yaml"] + # 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: + [ + "--config=/etc/otel-collector-config.yaml", + "--config=/etc/otel-collector-filestorage.yaml", + ] # Published on the host loopback only. The receivers have no auth and no # TLS, so only processes on this host may reach them. Note this 127.0.0.1 # is the HOST interface docker listens on; the container-side bind lives in @@ -40,8 +92,29 @@ services: volumes: # Mount collector pipeline config (receivers → processors → exporters) - ./otel-collector-config.yaml:/etc/otel-collector-config.yaml:ro + # 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 file_log receiver. The telemetry + # configs write to docker/telemetry/data/logs//debug.log, so + # 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 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: - - tempo + tempo: + condition: service_started + loki: + condition: service_started + otelcol-storage-init: + condition: service_completed_successfully + xrpld-logdir-init: + condition: service_completed_successfully networks: - xrpld-telemetry @@ -60,6 +133,20 @@ services: networks: - xrpld-telemetry + # Grafana Loki for centralized log ingestion and log-trace + # correlation. Loki 3.x supports native OTLP ingestion, so the OTel + # 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 + ports: + - "127.0.0.1:3100:3100" + command: -config.file=/etc/loki/local-config.yaml + volumes: + - loki-data:/loki + networks: + - xrpld-telemetry + prometheus: # Pinned to an exact patch release for reproducible, config-stable runs. image: prom/prometheus:v3.13.2 @@ -67,6 +154,7 @@ services: - "127.0.0.1:9090:9090" volumes: - ./prometheus.yml:/etc/prometheus/prometheus.yml:ro + - prometheus-data:/prometheus depends_on: - otel-collector networks: @@ -88,6 +176,7 @@ services: depends_on: - tempo - prometheus + - loki networks: - xrpld-telemetry @@ -96,6 +185,9 @@ services: # docker compose -f docker/telemetry/docker-compose.yml down -v 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/grafana/provisioning/datasources/loki.yaml b/docker/telemetry/grafana/provisioning/datasources/loki.yaml new file mode 100644 index 00000000000..a70ac9deb31 --- /dev/null +++ b/docker/telemetry/grafana/provisioning/datasources/loki.yaml @@ -0,0 +1,20 @@ +# Grafana Loki data source provisioning for rippled log-trace correlation. +# +# 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. + +apiVersion: 1 + +datasources: + - name: Loki + type: loki + access: proxy + url: http://loki:3100 + uid: loki + jsonData: + derivedFields: + - datasourceUid: tempo + matcherRegex: "trace_id=(\\w+)" + name: TraceID + url: "$${__value.raw}" diff --git a/docker/telemetry/grafana/provisioning/datasources/tempo.yaml b/docker/telemetry/grafana/provisioning/datasources/tempo.yaml index 23d8ff03dbb..589d7cdf8dd 100644 --- a/docker/telemetry/grafana/provisioning/datasources/tempo.yaml +++ b/docker/telemetry/grafana/provisioning/datasources/tempo.yaml @@ -27,6 +27,14 @@ datasources: # Prometheus service is added to docker-compose.yml. serviceMap: datasourceUid: prometheus + # Trace-to-log correlation — enables one-click navigation + # from a Tempo trace to the corresponding Loki log lines. Filters + # by trace_id so only logs from the same trace are shown. + tracesToLogs: + datasourceUid: loki + filterByTraceID: true + filterBySpanID: false + tags: [] tracesToMetrics: datasourceUid: prometheus spanStartTimeShift: "-1h" @@ -183,6 +191,12 @@ datasources: operator: "=" scope: span type: dynamic + # tx_type: transaction type (e.g., "Payment", "OfferCreate"). + - id: tx-type + tag: tx_type + operator: "=" + scope: span + type: dynamic # Consensus tracing filters - id: consensus-mode tag: consensus_mode @@ -199,6 +213,12 @@ datasources: operator: "=" scope: span type: static + # ledger_hash: ledger hash — scope all spans to a specific closed ledger. + - id: ledger-hash + tag: ledger_hash + operator: "=" + scope: span + type: static - id: consensus-close-time-correct tag: close_time_correct operator: "=" diff --git a/docker/telemetry/integration-test.sh b/docker/telemetry/integration-test.sh index 58bd50f9ec3..ac5083e69b7 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 # Hard ceiling on every curl probe below. curl has no overall timeout of its # own, so a server that accepts the connection and then never answers parks a @@ -95,11 +99,106 @@ check_span() { fi } +# Verify trace_id injection in xrpld log output. +# Greps all node debug.log files for the "trace_id= span_id=" +# pattern that Logs::format() injects when an active OTel span exists. +# Also cross-checks that a trace_id found in logs matches a trace in Tempo. +check_log_correlation() { + log "Checking log-trace correlation..." + + local total_matches=0 + local files_scanned=0 + local sample_trace_id="" + + for i in $(seq 1 "$NUM_NODES"); do + local logfile="$WORKDIR/Node-$i/debug.log" + if [ ! -f "$logfile" ]; then + continue + fi + files_scanned=$((files_scanned + 1)) + local matches + 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 + # -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-*/" + return + fi + + if [ "$total_matches" -gt 0 ]; then + ok "Log correlation: found $total_matches log lines with trace_id ($files_scanned nodes scanned)" + else + fail "Log correlation: no trace_id found in any node debug.log ($files_scanned nodes scanned)" + fi + + # Cross-check: verify the sample trace_id exists in Tempo + if [ -n "$sample_trace_id" ]; then + local trace_found + # Tempo /api/traces/{id} returns OTLP shape: {"batches":[...]} + trace_found=$(curl -sf "$TEMPO/api/traces/$sample_trace_id" | + jq '.batches | length' 2>/dev/null) || trace_found=0 + if [ "$trace_found" -gt 0 ]; then + ok "Log-Tempo cross-check: trace_id=$sample_trace_id found in Tempo" + 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" @@ -141,7 +240,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 @@ -178,7 +277,10 @@ trap 'exit 130' INT trap 'exit 143' TERM log "Starting observability stack..." -docker compose -f "$COMPOSE_FILE" up -d +# Point the collector's log mount at this test's workdir so it tails the +# per-node debug.log files this script generates. The compose default +# (./data/logs) is for user-run xrpld; the test owns its own log root. +XRPLD_LOG_DIR="$WORKDIR" docker compose -f "$COMPOSE_FILE" up -d log "Waiting for otel-collector to be ready..." for attempt in $(seq 1 30); do @@ -208,6 +310,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 # --------------------------------------------------------------------------- @@ -297,7 +411,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)) @@ -394,7 +508,7 @@ log "Starting $NUM_NODES xrpld nodes..." RUN_START=$(date +%s) 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"))" @@ -567,6 +681,13 @@ log "--- Peer Spans (trace_peer=1) ---" check_span "peer.proposal.receive" check_span "peer.validation.receive" +# --------------------------------------------------------------------------- +# Step 9b: Verify log-trace correlation +# --------------------------------------------------------------------------- +log "" +log "--- Log-Trace Correlation ---" +check_log_correlation + # --------------------------------------------------------------------------- # Step 10: Verify Prometheus span_metrics # --------------------------------------------------------------------------- @@ -681,12 +802,13 @@ echo "" echo " Tempo: http://localhost:3200" echo " Grafana: http://localhost:3000" echo " Prometheus: http://localhost:9090" +echo " Loki: http://localhost:3100" echo "" 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 bd38e567e32..1cabe74f068 100644 --- a/docker/telemetry/otel-collector-config.yaml +++ b/docker/telemetry/otel-collector-config.yaml @@ -3,10 +3,22 @@ # Pipelines: # traces: OTLP receiver -> batch processor -> debug + Tempo + span_metrics # metrics: OTLP receiver + span_metrics connector -> Prometheus exporter +# 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 span_metrics # connector, which Prometheus scrapes on port 8889. +# +# xrpld sends beast::insight metrics natively via OTLP/HTTP to port 4318 +# (same endpoint as traces). The OTLP receiver feeds both the traces and +# metrics pipelines. Metrics are exported to Prometheus alongside +# span-derived metrics. +# +# 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. receivers: otlp: @@ -15,11 +27,84 @@ receivers: endpoint: 0.0.0.0:4317 http: endpoint: 0.0.0.0:4318 + # Filelog receiver tails xrpld debug.log files for log-trace + # 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. + 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 + # nothing is read at all from a file that has stopped being written to. + # + # Offsets are kept in memory here, so a restarted collector re-reads the + # file. Stacks that keep their logs across restarts layer + # otel-collector-filestorage.yaml on top to persist them; ephemeral + # stacks get a fresh log directory each run and need nothing. + start_at: beginning + operators: + # Log format emitted by Logs::format() is: + # 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. 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: timeout: 1s 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 # 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. @@ -106,6 +191,11 @@ exporters: endpoint: tempo:4317 tls: insecure: true + # 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). + otlp_http/loki: + endpoint: http://loki:3100/otlp prometheus: endpoint: 0.0.0.0:8889 # Promote resource attributes (deployment.environment, xrpl.network.type, @@ -133,3 +223,9 @@ service: # is well under the Prometheus scrape interval. processors: [resource/tier, resource/stripsdk, batch] exporters: [prometheus] + # Log pipeline ingests xrpld debug.log via file_log receiver, + # batches entries, and exports to Loki for log-trace correlation. + logs: + receivers: [file_log] + processors: [resource/logs, resource/tier, resource/stripsdk, batch] + exporters: [otlp_http/loki] diff --git a/docker/telemetry/otel-collector-filestorage.yaml b/docker/telemetry/otel-collector-filestorage.yaml new file mode 100644 index 00000000000..fec6c7ddaba --- /dev/null +++ b/docker/telemetry/otel-collector-filestorage.yaml @@ -0,0 +1,28 @@ +# 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. +# +# Why this is an overlay rather than part of the base config: the base config +# is shared by every stack that runs the collector, including the ephemeral +# workload-validation stack, which creates a fresh log directory per run and so +# has nothing to resume from. The extension needs a writable directory, and the +# collector image runs as 10001:10001 with no writable path of its own, so +# requiring it in the base config would force every stack to mount a volume +# just to start. Keeping it here means the base config stays self-sufficient. +# +# The developer stack benefits because its log directory and this volume both +# survive `docker compose down`, so a restart resumes at the last offset +# instead of re-reading debug.log from the top. + +extensions: + file_storage/file_log: + directory: /var/lib/otelcol/file_storage + create_directory: true + +receivers: + 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/file_log] diff --git a/docker/telemetry/xrpld-telemetry.cfg b/docker/telemetry/xrpld-telemetry.cfg index 4c816603e2d..3294630bc92 100644 --- a/docker/telemetry/xrpld-telemetry.cfg +++ b/docker/telemetry/xrpld-telemetry.cfg @@ -34,8 +34,16 @@ advisory_delete=0 [database_path] docker/telemetry/data +# Path is resolved relative to this config file's directory (docker/telemetry), +# 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] -docker/telemetry/data/debug.log +data/logs/xrpld-standalone/debug.log [rpc_startup] { "command": "log_level", "severity": "debug" } diff --git a/docs/build/telemetry.md b/docs/build/telemetry.md index df4e1adfc39..c2a34690f46 100644 --- a/docs/build/telemetry.md +++ b/docs/build/telemetry.md @@ -218,11 +218,11 @@ flowchart TD ### Coroutine-aware context storage -The active-context stack is not a plain `thread_local`. At telemetry start -xrpld installs `CoroAwareContextStorage`, which keeps the stack in an -`xrpl::LocalValue`. Because `JobQueue::Coro::resume()` swaps the coroutine's -`LocalValue` store in and out with the coroutine, the ambient context _follows -the coroutine_ across every yield and resume — even when it resumes on a +The active-context stack is not a plain `thread_local`. During startup, before +any thread is created, xrpld installs `CoroAwareContextStorage`, which keeps the +stack in an `xrpl::LocalValue`. Because `JobQueue::Coro::resume()` swaps the +coroutine's `LocalValue` store in and out with the coroutine, the ambient context +_follows the coroutine_ across every yield and resume — even when it resumes on a different worker thread. A `ScopedSpanGuard` held across a coroutine yield is therefore safe: its scope rides the coroutine and pops on the same store it was pushed onto, so it never pops the wrong stack. Off a coroutine the `LocalValue` diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index e4397d968bf..6d4dcb8a2ae 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -18,8 +18,10 @@ docker compose -f docker/telemetry/docker-compose.yml up -d This starts: -- **OTel Collector** on ports 4317 (gRPC), 4318 (HTTP), and 13133 (health) -- **Tempo** trace storage on http://localhost:3200 +- **OTel Collector** on ports 4317 (gRPC) and 4318 (HTTP), and 13133 (health) +- **Tempo** on http://localhost:3200 (trace backend) +- **Prometheus** on http://localhost:9090 +- **Loki** on http://localhost:3100 (log aggregation) - **Grafana** on http://localhost:3000 (Tempo pre-configured as datasource) ### 2. Enable telemetry in xrpld @@ -854,6 +856,56 @@ Requires `trace_peer=1` in the `[telemetry]` config section. | `peer.proposal.receive` | `{span_name="peer.proposal.receive"}` | Peer Network (Rate, Trusted/Untrusted) | | `peer.validation.receive` | `{span_name="peer.validation.receive"}` | Peer Network (Rate, Trusted/Untrusted) | +## Log-Trace Correlation + +When xrpld is built with telemetry (Conan `-o telemetry=True`), log lines emitted within an active, sampled OpenTelemetry span automatically include `trace_id` and `span_id` fields: + +``` +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: + +- **Tempo -> Loki**: Click "Logs for this trace" on any trace in Grafana Tempo to see all log lines from that trace. +- **Loki -> Tempo**: Click the `TraceID` derived field link on any log line containing `trace_id=` to jump to the full trace in Tempo. + +### Log Ingestion Pipeline + +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`). 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. + +### LogQL Query Examples + +```logql +# Find all logs for a specific trace +{service_name="xrpld"} |= "trace_id=abc123def456789012345678abcdef01" + +# Error logs with trace context (log lines with ERR severity that have a trace_id) +{service_name="xrpld"} |= "ERR" |= "trace_id=" + +# All logs from a specific partition that were emitted during a span +{service_name="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P[a-f0-9]+)` | trace_id != "" + +# Logs from the last hour containing trace context +{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({service_name="xrpld"} |= "trace_id=" [5m]) +``` + +### Verifying Log Correlation + +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 `{service_name="xrpld"} |= "trace_id="`. +5. Click the TraceID link to navigate to the corresponding trace in Tempo. + ## Troubleshooting ### No traces appearing in Tempo @@ -917,6 +969,20 @@ Requires `trace_peer=1` in the `[telemetry]` config section. - If you did not mean to enable telemetry at all, set `enabled=0` — that clears all three checks whichever one fired +### No trace_id in log output + +- Verify xrpld was built with Conan `-o telemetry=True`, which defines the `XRPL_ENABLE_TELEMETRY` preprocessor flag +- Verify `enabled=1` in the `[telemetry]` config section +- Log lines only contain `trace_id`/`span_id` when emitted inside an active span — background logs outside of RPC/consensus/transaction processing will not have trace context +- Check that the specific trace category is enabled (e.g., `trace_rpc=1`) + +### 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 file_log receiver errors: `docker compose logs otel-collector` +- Verify Loki is running: `curl http://localhost:3100/ready` +- 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 | Scenario | Recommendation | diff --git a/include/xrpl/telemetry/CoroAwareContextStorage.h b/include/xrpl/telemetry/CoroAwareContextStorage.h index d7c047e7527..cea330baf76 100644 --- a/include/xrpl/telemetry/CoroAwareContextStorage.h +++ b/include/xrpl/telemetry/CoroAwareContextStorage.h @@ -31,9 +31,10 @@ * | (swapped by Coro) | * +------------------------+ * - * Install once at telemetry start via - * opentelemetry::context::RuntimeContext::SetRuntimeContextStorage(), BEFORE - * any span is created (SDK requirement). + * Install once from main() via + * opentelemetry::context::RuntimeContext::SetRuntimeContextStorage(), before + * any thread is started. That call writes a non-atomic process-global + * shared_ptr which every log line reads back, so a later install would race. * * @note Thread-safety: each thread/coroutine sees its own LocalValue store, so * the stack is never shared across threads — no locking needed. The storage @@ -44,7 +45,7 @@ * the coroutine's store — not a pattern here (spans are created inside their * own coro/job body). * - * Example 1 — install at telemetry start (primary use): + * Example 1 — install from main(), before any thread (primary use): * @code * using opentelemetry::context::RuntimeContext; * RuntimeContext::SetRuntimeContextStorage( diff --git a/src/libxrpl/basics/Log.cpp b/src/libxrpl/basics/Log.cpp index 68525f5a65d..ce17514b237 100644 --- a/src/libxrpl/basics/Log.cpp +++ b/src/libxrpl/basics/Log.cpp @@ -6,6 +6,15 @@ #include +#ifdef XRPL_ENABLE_TELEMETRY +#include +#include +#include +#include +#include +#include +#endif // XRPL_ENABLE_TELEMETRY + #include #include #include @@ -19,6 +28,11 @@ #include #include +#ifdef XRPL_ENABLE_TELEMETRY +// std::size_t names the hex widths used when formatting a trace context. +#include +#endif // XRPL_ENABLE_TELEMETRY + namespace xrpl { Logs::Sink::Sink(std::string partition, beast::Severity thresh, Logs& logs) @@ -291,6 +305,51 @@ Logs::format( break; } +#ifdef XRPL_ENABLE_TELEMETRY + // 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); + if (opentelemetry::nostd::holds_alternative< + opentelemetry::nostd::shared_ptr>(spanValue)) + { + auto span = opentelemetry::nostd::get< + opentelemetry::nostd::shared_ptr>(spanValue); + auto spanCtx = span->GetContext(); + // 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. A span is dropped when + // its local parent was dropped, or when the head sampler's ratio + // rejects its trace id; a peer's sampled flag does not decide it + // (see makeHeadSampler). Either way 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. + constexpr std::size_t kTraceIdHexLen = 32; + constexpr std::size_t kSpanIdHexLen = 16; + constexpr auto kTraceIdPrefix = "trace_id="; + constexpr auto kSpanIdPrefix = " span_id="; + char traceId[kTraceIdHexLen], spanId[kSpanIdHexLen]; + spanCtx.trace_id().ToLowerBase16( + opentelemetry::nostd::span{traceId}); + spanCtx.span_id().ToLowerBase16( + opentelemetry::nostd::span{spanId}); + output += kTraceIdPrefix; + output.append(traceId, kTraceIdHexLen); + output += kSpanIdPrefix; + output.append(spanId, kSpanIdHexLen); + output += ' '; + } + } + } +#endif // XRPL_ENABLE_TELEMETRY + output += message; // Limit the maximum length of the output diff --git a/src/libxrpl/telemetry/SpanGuard.cpp b/src/libxrpl/telemetry/SpanGuard.cpp index e8c0fe42cf8..a3e804ab3d0 100644 --- a/src/libxrpl/telemetry/SpanGuard.cpp +++ b/src/libxrpl/telemetry/SpanGuard.cpp @@ -618,6 +618,7 @@ SpanGuard::addEvent(std::string_view name, std::initializer_list // std::vector> doesn't satisfy is_key_value_iterable. // Wrap in nostd::span over the vector's storage so the SDK accepts it. std::vector> + otelAttrs; otelAttrs.reserve(attrs.size()); for (auto const& [k, v] : attrs) diff --git a/src/libxrpl/telemetry/Telemetry.cpp b/src/libxrpl/telemetry/Telemetry.cpp index 978376058f1..591b5504fa6 100644 --- a/src/libxrpl/telemetry/Telemetry.cpp +++ b/src/libxrpl/telemetry/Telemetry.cpp @@ -21,7 +21,6 @@ #include #include #include -#include #include #include #include @@ -29,7 +28,6 @@ #include #include -#include #include #include #include @@ -265,13 +263,6 @@ class TelemetryImpl : public Telemetry */ std::shared_ptr meterProvider_; - /** - * Coroutine-aware runtime-context storage, installed globally so the OTel - * ambient context follows JobQueue coroutines. Held for the process - * lifetime because it must outlive every span (SDK requirement). - */ - opentelemetry::nostd::shared_ptr contextStorage_; - /** * Set by stop(), so a second call does nothing. */ @@ -496,17 +487,10 @@ class TelemetryImpl : public Telemetry std::move(sampler), std::make_unique()); - // Install coroutine-aware context storage BEFORE any span is created - // so the OTel ambient context follows JobQueue coroutines across - // yield/resume (fixes wrong-thread scope pop; keeps log-trace - // correlation). Must precede SetTracerProvider and the first span. - // Not reset in stop(): resetting the storage while spans may still - // exist is undefined behaviour (SDK), and by stop() all spans are - // gone, so the storage is simply left installed for process lifetime. - contextStorage_ = - opentelemetry::nostd::shared_ptr( - new CoroAwareContextStorage()); - opentelemetry::context::RuntimeContext::SetRuntimeContextStorage(contextStorage_); + // main() installs the coroutine-aware runtime-context storage while the + // process is single-threaded. It cannot be installed here: start() runs + // from setup(), by which point the io threads read that global pointer + // on every log line. // Set as global provider trace_api::Provider::SetTracerProvider( diff --git a/src/xrpld/app/main/Main.cpp b/src/xrpld/app/main/Main.cpp index 3e5640dcbff..7a1f7483932 100644 --- a/src/xrpld/app/main/Main.cpp +++ b/src/xrpld/app/main/Main.cpp @@ -19,8 +19,11 @@ #include #include #include +#include #include +#include #include +#include #include #include @@ -32,6 +35,13 @@ #include #include +#ifdef XRPL_ENABLE_TELEMETRY +#include + +#include +#include +#endif // XRPL_ENABLE_TELEMETRY + #include #include #include @@ -353,6 +363,39 @@ runUnitTests( #endif // ENABLE_TESTS //------------------------------------------------------------------------------ +namespace { + +/** + * Parse the [telemetry] section, or log why it cannot be parsed. + * + * run() calls this before any thread starts, while it still owns the logs. A + * bad value then stops startup like any other config error. + * + * @param config The loaded server config. + * @param nodeKey The node public key, the default service instance id. + * @param j Journal the reason is written to. + * @return The parsed section, or std::nullopt after logging the reason. + */ +std::optional +readTelemetrySetup(Config const& config, PublicKey const& nodeKey, beast::Journal j) +{ + try + { + return telemetry::makeTelemetrySetup( + config.section(Sections::kTelemetry), + toBase58(TokenType::NodePublic, nodeKey), + build_info::getVersionString(), + config.networkId); + } + catch (std::exception const& e) + { + JLOG(j.fatal()) << e.what(); + return std::nullopt; + } +} + +} // namespace + int run(int argc, char** argv) { @@ -822,20 +865,36 @@ run(int argc, char** argv) return -1; } + auto const telemetrySetup = + readTelemetrySetup(*config, nodeIdentity->first, logs->journal("Application")); + if (!telemetrySetup) + return -1; + +#ifdef XRPL_ENABLE_TELEMETRY + // Install the coroutine-aware OTel context storage while the process is + // still single-threaded. SetRuntimeContextStorage() writes a + // process-global shared_ptr that every log line reads through + // RuntimeContext::GetCurrent(), and neither side is atomic; the io + // threads start inside makeApplication() below. + if (telemetrySetup->enabled) + { + opentelemetry::context::RuntimeContext::SetRuntimeContextStorage( + opentelemetry::nostd::shared_ptr( + new telemetry::CoroAwareContextStorage())); + } +#endif // XRPL_ENABLE_TELEMETRY + // Application construction runs member initializers that validate - // config (for example the [telemetry] section) and can throw. A throw - // from a member-initializer list cannot be recovered inside the - // constructor, so catch it here. Left uncaught it reaches - // std::terminate, whose default handler prints a C++ terminate dump - // and raises SIGABRT, leaving a core file where the system allows one; - // the catch replaces that with two operator-readable lines on stderr - // and a non-zero exit status. + // config and can throw. A throw from a member-initializer list cannot + // be recovered inside the constructor, so catch it here. Left uncaught + // it reaches std::terminate, whose default handler prints a C++ + // terminate dump and raises SIGABRT, leaving a core file where the + // system allows one; the catch replaces that with two operator-readable + // lines on stderr and a non-zero exit status. // - // Only the construction is covered. The [telemetry] section is parsed - // near the top of the member list, before the job queue and node store - // are built, so unwinding that throw destroys little. setup() is - // left outside deliberately: it starts subsystems whose shutdown order - // is delicate, and only the normal stop sequence gets that order right. + // Only the construction is covered. setup() is left outside + // deliberately: it starts subsystems whose shutdown order is delicate, + // and only the normal stop sequence gets that order right. std::unique_ptr app; try {