mirror of
https://github.com/XRPLF/rippled.git
synced 2026-08-19 05:10:55 +00:00
fix(telemetry): correct log-correlation defects found in PR review
Six findings from the review of #6494 survived independent verification. Each was checked against the branch tip, and where behaviour was in question, against a live collector and Loki rather than from the reviewer's claim or from documentation alone. Plan-doc section numbering. 06-implementation-phases.md used "## 6.9" twice: for the new Phase 8 section and for the pre-existing Risk Assessment. Three references already pointed at 6.8.1 and none at 6.9, and the later phases are numbered 6.8.2 through 6.8.4, so Phase 8 becomes 6.8.1 and the sequence is monotonic. Renumbering to 6.10, as suggested on the PR, would have collided with Success Metrics. filelog read position. The receiver relied on the upstream default start_at=end, which skips everything a node wrote before the first poll and reads nothing at all from a log that has stopped being written to. Read from the beginning instead, paired with a file_storage extension so a restart resumes at the last offset rather than re-ingesting the file. The collector image runs as 10001:10001 and ships no writable directory, and a fresh named volume is root-owned, so a one-shot init service prepares the volume first. It reuses an image the stack already pulls, adding no new dependency. Loki log stream label. The job resource attribute did not become a Loki index label, so the documented {job="xrpld"} queries matched nothing. Verified against grafana/loki:3.4.2 with its default config: only service_name and deployment_environment are indexed, and job arrives as structured metadata, which a stream selector cannot match. Dropped the attribute and moved the twelve queries this branch introduced to {service_name="xrpld"}. Three further occurrences in 07-observability-backends.md originate on the phase-1a branch and are left for a commit there. Trace ids on unsampled spans. Logs::format emitted trace_id and span_id whenever the span context was valid. A span dropped by the ParentBasedSampler still carries its parent's ids, so log lines advertised traces that were never exported and the log-to-trace link resolved to nothing. Require the sampled flag as well, and correct the task list and the documentation that promised the fields unconditionally. The remaining two findings were refuted. The reported risk of signing material reaching Loki does not hold: Logs::format already scrubs seven sensitive fields, and there is a single write path to the log file, so every JLOG site is covered. The suggestion to add internalLink to the Loki derived field is not applicable, because that key is not part of Grafana's schema.
This commit is contained in:
@@ -230,6 +230,7 @@ words:
|
||||
- onlatest
|
||||
- ostr
|
||||
- otelc
|
||||
- otelcol
|
||||
- oxalica
|
||||
- pargs
|
||||
- partitioner
|
||||
|
||||
@@ -568,11 +568,11 @@ See [Phase7_taskList.md](./Phase7_taskList.md) for detailed per-task breakdown.
|
||||
|
||||
---
|
||||
|
||||
## 6.9 Phase 8: Log-Trace Correlation and Centralized Log Ingestion (Week 13)
|
||||
## 6.8.1 Phase 8: Log-Trace Correlation and Centralized Log Ingestion (Week 13)
|
||||
|
||||
### Motivation
|
||||
|
||||
xrpld's `beast::Journal` logs and OpenTelemetry traces are currently two disjoint observability signals. When investigating an issue, operators must manually correlate timestamps between log files and Jaeger/Tempo traces. Phase 8 bridges this gap by injecting trace context (`trace_id`, `span_id`) into every log line emitted within an active span, and ingesting those logs into Grafana Loki via the OTel Collector's filelog receiver.
|
||||
xrpld's `beast::Journal` logs and OpenTelemetry traces are currently two disjoint observability signals. When investigating an issue, operators must manually correlate timestamps between log files and Jaeger/Tempo traces. Phase 8 bridges this gap by injecting trace context (`trace_id`, `span_id`) into every log line emitted within an active, sampled span, and ingesting those logs into Grafana Loki via the OTel Collector's filelog receiver.
|
||||
|
||||
#### Gains
|
||||
|
||||
@@ -590,7 +590,7 @@ xrpld's `beast::Journal` logs and OpenTelemetry traces are currently two disjoin
|
||||
|
||||
#### Decision
|
||||
|
||||
The correlation value far outweighs the risks. The log format change is backward-compatible (fields are appended only when a span is active), and the filelog receiver regex is straightforward to maintain.
|
||||
The correlation value far outweighs the risks. The log format change is backward-compatible (fields are appended only when a sampled span is active), and the filelog receiver regex is straightforward to maintain.
|
||||
|
||||
### Architecture
|
||||
|
||||
|
||||
@@ -919,7 +919,7 @@ state_accounting_full_duration
|
||||
> **Plan details**: [06-implementation-phases.md §6.8.1](./06-implementation-phases.md) — motivation, architecture, Mermaid diagrams
|
||||
> **Task breakdown**: [Phase8_taskList.md](./Phase8_taskList.md) — per-task implementation details
|
||||
|
||||
Phase 8 injects OTel trace context into xrpld's `Logs::format()` output, enabling log-trace correlation. When a log line is emitted within an active OTel span, the trace and span identifiers are automatically appended after the severity field:
|
||||
Phase 8 injects OTel trace context into xrpld's `Logs::format()` output, enabling log-trace correlation. When a log line is emitted within an active, sampled OTel span, the trace and span identifiers are automatically appended after the severity field:
|
||||
|
||||
### Log Format
|
||||
|
||||
@@ -935,7 +935,7 @@ Example:
|
||||
|
||||
- **`trace_id=<hex32>`** — 32-character lowercase hex trace identifier. Links to the distributed trace in Tempo/Jaeger.
|
||||
- **`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
|
||||
|
||||
@@ -973,16 +973,16 @@ Grafana Loki (v3.4.2) serves as the log storage backend. It receives log entries
|
||||
|
||||
```logql
|
||||
# Find all logs for a specific trace
|
||||
{job="xrpld"} |= "trace_id=abc123def456789012345678abcdef01"
|
||||
{service_name="xrpld"} |= "trace_id=abc123def456789012345678abcdef01"
|
||||
|
||||
# Error logs with trace context
|
||||
{job="xrpld"} |= "ERR" |= "trace_id="
|
||||
{service_name="xrpld"} |= "ERR" |= "trace_id="
|
||||
|
||||
# Logs from a specific partition with trace context
|
||||
{job="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P<trace_id>[a-f0-9]+)` | trace_id != ""
|
||||
{service_name="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P<trace_id>[a-f0-9]+)` | trace_id != ""
|
||||
|
||||
# Count traced log lines over time
|
||||
count_over_time({job="xrpld"} |= "trace_id=" [5m])
|
||||
count_over_time({service_name="xrpld"} |= "trace_id=" [5m])
|
||||
```
|
||||
|
||||
---
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -517,7 +517,7 @@ exports parsed entries to Loki. Verify Loki has received entries:
|
||||
```bash
|
||||
# Query Loki for any xrpld logs
|
||||
curl -sG "http://localhost:3100/loki/api/v1/query" \
|
||||
--data-urlencode 'query={job="xrpld"}' \
|
||||
--data-urlencode 'query={service_name="xrpld"}' \
|
||||
--data-urlencode 'limit=5' | jq '.data.result | length'
|
||||
```
|
||||
|
||||
@@ -534,7 +534,7 @@ Expected: > 0 results.
|
||||
### Step 5: Verify Grafana Loki-to-Tempo correlation
|
||||
|
||||
1. In Grafana **Explore**, select **Loki** datasource
|
||||
2. Query: `{job="xrpld"} |= "trace_id="`
|
||||
2. Query: `{service_name="xrpld"} |= "trace_id="`
|
||||
3. In the log results, click the **TraceID** derived field link
|
||||
4. Verify it navigates to the full trace in Tempo
|
||||
|
||||
|
||||
@@ -21,6 +21,25 @@
|
||||
# endpoint=http://localhost:4318/v1/traces
|
||||
|
||||
services:
|
||||
# One-shot init for the collector's offset store. Docker creates a fresh
|
||||
# named volume owned by root, but the collector image runs as 10001:10001
|
||||
# and ships no writable directory, so the file_storage extension could not
|
||||
# create its database and the collector would fail to start. Chown the
|
||||
# volume once, then exit; the collector waits for this to complete.
|
||||
#
|
||||
# Reuses the Prometheus image purely because the stack already pulls it and
|
||||
# it has a shell — this adds no new image dependency. The entrypoint is
|
||||
# overridden since that image normally starts the Prometheus server.
|
||||
otelcol-storage-init:
|
||||
image: prom/prometheus:v3.13.2
|
||||
user: "0:0"
|
||||
entrypoint: ["sh", "-c"]
|
||||
command: ["mkdir -p /data/file_storage && chown -R 10001:10001 /data"]
|
||||
volumes:
|
||||
- otelcol-storage:/data
|
||||
networks:
|
||||
- xrpld-telemetry
|
||||
|
||||
# OpenTelemetry Collector: receives spans from xrpld via OTLP protocol,
|
||||
# batches them for efficiency, and forwards to Tempo for storage.
|
||||
otel-collector:
|
||||
@@ -43,9 +62,16 @@ services:
|
||||
# XRPLD_LOG_DIR to point at another root (e.g. the integration test sets
|
||||
# it to its own workdir). Mounted read-only so the collector only tails.
|
||||
- ${XRPLD_LOG_DIR:-./data/logs}:/var/log/xrpld:ro
|
||||
# Persisted filelog read offsets, so a collector restart resumes
|
||||
# instead of re-reading every debug.log from the top.
|
||||
- otelcol-storage:/var/lib/otelcol
|
||||
depends_on:
|
||||
- tempo
|
||||
- loki
|
||||
tempo:
|
||||
condition: service_started
|
||||
loki:
|
||||
condition: service_started
|
||||
otelcol-storage-init:
|
||||
condition: service_completed_successfully
|
||||
networks:
|
||||
- xrpld-telemetry
|
||||
|
||||
@@ -118,6 +144,7 @@ volumes:
|
||||
tempo-data:
|
||||
prometheus-data:
|
||||
loki-data:
|
||||
otelcol-storage:
|
||||
|
||||
# Isolated bridge network so services communicate by container name
|
||||
# (e.g., the collector reaches Tempo at http://tempo:4317).
|
||||
|
||||
@@ -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.
|
||||
@@ -175,7 +201,7 @@ exporters:
|
||||
enabled: true
|
||||
|
||||
service:
|
||||
extensions: [health_check]
|
||||
extensions: [health_check, file_storage/filelog]
|
||||
pipelines:
|
||||
traces:
|
||||
receivers: [otlp]
|
||||
|
||||
@@ -806,7 +806,7 @@ Requires `trace_peer=1` in the `[telemetry]` config section.
|
||||
|
||||
## Log-Trace Correlation
|
||||
|
||||
When xrpld is built with `telemetry=ON`, log lines emitted within an active OpenTelemetry span automatically include `trace_id` and `span_id` fields:
|
||||
When xrpld is built with `telemetry=ON`, log lines emitted within an active, sampled OpenTelemetry span automatically include `trace_id` and `span_id` fields:
|
||||
|
||||
```
|
||||
2024-Jan-15 10:30:45.123456 UTC LedgerMaster:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Validated ledger 42
|
||||
@@ -827,19 +827,19 @@ The receiver tails `/var/log/xrpld/*/debug.log` inside the collector container.
|
||||
|
||||
```logql
|
||||
# Find all logs for a specific trace
|
||||
{job="xrpld"} |= "trace_id=abc123def456789012345678abcdef01"
|
||||
{service_name="xrpld"} |= "trace_id=abc123def456789012345678abcdef01"
|
||||
|
||||
# Error logs with trace context (log lines with ERR severity that have a trace_id)
|
||||
{job="xrpld"} |= "ERR" |= "trace_id="
|
||||
{service_name="xrpld"} |= "ERR" |= "trace_id="
|
||||
|
||||
# All logs from a specific partition that were emitted during a span
|
||||
{job="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P<trace_id>[a-f0-9]+)` | trace_id != ""
|
||||
{service_name="xrpld"} |= "LedgerMaster" | regexp `trace_id=(?P<trace_id>[a-f0-9]+)` | trace_id != ""
|
||||
|
||||
# Logs from the last hour containing trace context
|
||||
{job="xrpld"} |= "trace_id=" | regexp `(?P<partition>\S+):(?P<sev>\S+)\s+trace_id=(?P<tid>[a-f0-9]+)`
|
||||
{service_name="xrpld"} |= "trace_id=" | regexp `(?P<partition>\S+):(?P<sev>\S+)\s+trace_id=(?P<tid>[a-f0-9]+)`
|
||||
|
||||
# Count of traced vs untraced log lines
|
||||
count_over_time({job="xrpld"} |= "trace_id=" [5m])
|
||||
count_over_time({service_name="xrpld"} |= "trace_id=" [5m])
|
||||
```
|
||||
|
||||
### Verifying Log Correlation
|
||||
@@ -847,7 +847,7 @@ count_over_time({job="xrpld"} |= "trace_id=" [5m])
|
||||
1. Start the observability stack and xrpld with telemetry enabled.
|
||||
2. Send an RPC request: `curl http://localhost:5005 -d '{"method":"server_info"}'`
|
||||
3. Check the debug.log for `trace_id=` entries: `grep trace_id= /path/to/debug.log`
|
||||
4. Open Grafana at http://localhost:3000 -> Explore -> Loki and search for `{job="xrpld"} |= "trace_id="`.
|
||||
4. Open Grafana at http://localhost:3000 -> Explore -> Loki and search for `{service_name="xrpld"} |= "trace_id="`.
|
||||
5. Click the TraceID link to navigate to the corresponding trace in Tempo.
|
||||
|
||||
## Troubleshooting
|
||||
|
||||
@@ -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