diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index 080421a5c6..2a0d330a71 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -574,14 +574,14 @@ See [Phase7_taskList.md](./Phase7_taskList.md) for detailed per-task breakdown. ### 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 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 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 (`GetSpan`, `GetContext`) already linked in Phase 1. +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 @@ -592,33 +592,54 @@ 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 sampled 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 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 `filelog` 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. +- **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())"] - Format["Logs::format()"] - OTelCtx["OTel Context
(thread-local)"] + 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 -.->|"GetSpan()→GetContext()"| Format + OTelCtx -.->|"`GetContext() + if IsValid and IsSampled`"| Format end - subgraph output["Log Output"] - LogLine["2024-01-15T10:30:45.123Z
LedgerMaster:NFO
trace_id=abc123...
span_id=def456...
Validated ledger 42"] + 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 @@ -632,16 +653,35 @@ flowchart LR ```mermaid flowchart LR subgraph collector["OTel Collector"] - FR["filelog receiver
tails debug.log"] - RP["regex_parser
extracts trace_id,
span_id, severity"] - BP["batch processor"] - LE["otlp/loki exporter"] + 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"] + 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 @@ -659,7 +699,7 @@ flowchart LR | ---- | ---------------------------------------------- | | 8.1 | Inject trace_id into Logs::format() | | 8.2 | Add Loki to Docker Compose stack | -| 8.3 | Add filelog receiver to OTel Collector | +| 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) | @@ -670,7 +710,7 @@ flowchart LR - [ ] 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 filelog receiver +- [ ] 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 diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 0d67842bee..d2263d9e4e 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -956,7 +956,7 @@ Phase 8 injects OTel trace context into xrpld's `Logs::format()` output, enablin Example: ``` -2024-Jan-15 10:30:45.123456 UTC LedgerMaster:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Validated ledger 42 +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. @@ -970,10 +970,10 @@ The trace context injection is implemented in `Logs::format()` (`src/libxrpl/bas ### Log Ingestion Pipeline ``` -xrpld debug.log -> OTel Collector filelog receiver -> regex_parser -> Loki exporter -> Grafana Loki +xrpld debug.log -> OTel Collector file_log receiver -> regex_parser -> Loki exporter -> Grafana Loki ``` -The OTel Collector's `filelog` receiver tails `debug.log` files and uses a `regex_parser` operator to extract structured fields: +The OTel Collector's `file_log` receiver tails `debug.log` files and uses a `regex_parser` operator to extract structured fields: | Field | Type | Description | | ----------- | -------- | -------------------------------------------------------- | @@ -993,7 +993,7 @@ Bidirectional linking between logs and traces is configured via Grafana datasour ### Loki Backend -Grafana Loki (v3.4.2) serves as the log storage backend. It receives log entries from the OTel Collector's `otlphttp/loki` exporter via the native OTLP endpoint at `http://loki:3100/otlp`. +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 diff --git a/docker/telemetry/TESTING.md b/docker/telemetry/TESTING.md index 01a3fc90cb..d3576562b4 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 @@ -469,7 +478,7 @@ Expected: log lines with `trace_id=<32hex> span_id=<16hex>` between the severity code and the message. Example: ``` -2024-Jan-15 10:30:45.123456 UTC RPCHandler:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Calling server_info +2024-Jan-15 10:30:45.123456789 UTC RPCHandler:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Calling server_info ``` Lines emitted outside of an active span (background tasks, startup) will @@ -480,26 +489,42 @@ NOT have trace context — this is expected. Extract a `trace_id` from the log and verify it exists in Tempo: ```bash -TRACE_ID=$(grep -o 'trace_id=[a-f0-9]\{32\}' /path/to/debug.log | head -1 | cut -d= -f2) +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 '.data | length' +curl -s "http://localhost:3200/api/traces/$TRACE_ID" | jq '.batches | length' ``` -Expected result: `1` (the trace exists in Tempo). +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 filelog receiver tails xrpld's debug.log and +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 -curl -sG "http://localhost:3100/loki/api/v1/query" \ +# 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 'limit=5' | jq '.data.result | length' + --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 results. +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, +which is why the validation scripts can use the instant endpoint. +Timestamps are unix nanoseconds, matching `workload/validate_telemetry.py`. +Counting `.data.result | length` would count streams, not log lines. ### Step 4: Verify Grafana Tempo-to-Loki correlation @@ -555,7 +580,7 @@ Expected: > 0 results. ``` 2. Verify `[ips_fixed]` lists all 6 peer ports 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` (prevents reaching out to public network) ### Transaction not processing @@ -588,15 +613,15 @@ Expected: > 0 results. 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 filelog receiver errors: +2. Check OTel Collector logs for file_log receiver errors: ```bash - docker compose -f docker/telemetry/docker-compose.yml logs otel-collector | grep -i "filelog\|loki\|error" + 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 filelog receiver glob pattern matches your log files: +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 diff --git a/docker/telemetry/docker-compose.yml b/docker/telemetry/docker-compose.yml index 98f6965c3f..5665f9d56d 100644 --- a/docker/telemetry/docker-compose.yml +++ b/docker/telemetry/docker-compose.yml @@ -3,7 +3,7 @@ # Provides services for local development: # - otel-collector: receives OTLP traces from xrpld, batches and # forwards them to Tempo. Also tails xrpld log files -# via filelog receiver and exports to Loki. Listens on ports +# 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). @@ -40,11 +40,34 @@ services: 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 - # Second --config layers filelog offset persistence on top of the shared + # 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: @@ -62,16 +85,18 @@ services: volumes: # Mount collector pipeline config (receivers → processors → exporters) - ./otel-collector-config.yaml:/etc/otel-collector-config.yaml:ro - # Dev-only overlay: persist filelog read offsets across restarts + # 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 filelog receiver. The telemetry + # 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 — user-owned and - # needing no root, so `docker compose up` works with no setup. Override - # 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. + # 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 filelog read offsets, so a collector restart resumes + # 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: @@ -81,6 +106,8 @@ services: condition: service_started otelcol-storage-init: condition: service_completed_successfully + xrpld-logdir-init: + condition: service_completed_successfully networks: - xrpld-telemetry @@ -101,7 +128,7 @@ services: # Grafana Loki for centralized log ingestion and log-trace # correlation. Loki 3.x supports native OTLP ingestion, so the OTel - # Collector exports via otlphttp to Loki's /otlp endpoint. + # 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 diff --git a/docker/telemetry/grafana/provisioning/datasources/loki.yaml b/docker/telemetry/grafana/provisioning/datasources/loki.yaml index 0a6b73a575..a70ac9deb3 100644 --- a/docker/telemetry/grafana/provisioning/datasources/loki.yaml +++ b/docker/telemetry/grafana/provisioning/datasources/loki.yaml @@ -1,6 +1,6 @@ # Grafana Loki data source provisioning for rippled log-trace correlation. # -# Loki ingests rippled logs via OTel Collector's filelog receiver. +# 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. diff --git a/docker/telemetry/integration-test.sh b/docker/telemetry/integration-test.sh index e3981d4e4a..6c930dcee9 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 # Counters for pass/fail PASS=0 @@ -88,7 +92,7 @@ check_log_correlation() { local sample_trace_id="" for i in $(seq 1 "$NUM_NODES"); do - local logfile="$WORKDIR/node$i/debug.log" + local logfile="$WORKDIR/Node-$i/debug.log" if [ ! -f "$logfile" ]; then continue fi @@ -97,12 +101,17 @@ check_log_correlation() { 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 - sample_trace_id=$(grep -o 'trace_id=[a-f0-9]\{32\}' "$logfile" | head -1 | cut -d= -f2) + # -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*/" + fail "Log correlation: no debug.log files found in $WORKDIR/Node-*/" return fi @@ -123,14 +132,54 @@ check_log_correlation() { 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" @@ -171,7 +220,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 @@ -237,6 +286,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 # --------------------------------------------------------------------------- @@ -326,7 +387,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)) @@ -419,7 +480,7 @@ done log "Starting $NUM_NODES xrpld nodes..." 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"))" @@ -719,7 +780,7 @@ 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 618eb94d5a..8ad4545dea 100644 --- a/docker/telemetry/otel-collector-config.yaml +++ b/docker/telemetry/otel-collector-config.yaml @@ -3,7 +3,7 @@ # Pipelines: # traces: OTLP receiver -> batch processor -> debug + Tempo + spanmetrics # metrics: OTLP receiver + spanmetrics connector -> Prometheus exporter -# logs: filelog receiver -> batch processor -> otlphttp/Loki +# 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 spanmetrics @@ -14,16 +14,12 @@ # metrics pipelines. Metrics are exported to Prometheus alongside # span-derived metrics. # -# The filelog receiver tails xrpld's debug.log files under +# 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. -extensions: - health_check: - endpoint: 0.0.0.0:13133 - receivers: otlp: protocols: @@ -35,8 +31,13 @@ receivers: # 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. - filelog: + 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 @@ -49,16 +50,36 @@ receivers: start_at: beginning operators: # Log format emitted by Logs::format() is: - # YYYY-Mmm-DD HH:MM:SS.ffffff UTC : [trace_id=... span_id=...] + # 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. Fractional seconds up to 6 - # digits are parsed via the `%f` strptime directive. + # 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: @@ -179,7 +200,7 @@ exporters: # 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). - otlphttp/loki: + otlp_http/loki: endpoint: http://loki:3100/otlp prometheus: endpoint: 0.0.0.0:8889 @@ -190,6 +211,10 @@ exporters: resource_to_telemetry_conversion: enabled: true +extensions: + health_check: + endpoint: 0.0.0.0:13133 + service: extensions: [health_check] pipelines: @@ -199,11 +224,14 @@ service: exporters: [debug, otlp/tempo, spanmetrics] metrics: receivers: [otlp, spanmetrics] + # batch keeps the OTLP metric path from exporting one request per + # instrument. It delays a sample by at most the batch timeout, which + # is well under the Prometheus scrape interval. processors: [resource/tier, resource/stripsdk, batch] exporters: [prometheus] - # Log pipeline ingests xrpld debug.log via filelog receiver, + # Log pipeline ingests xrpld debug.log via file_log receiver, # batches entries, and exports to Loki for log-trace correlation. logs: - receivers: [filelog] + receivers: [file_log] processors: [resource/logs, resource/tier, resource/stripsdk, batch] - exporters: [otlphttp/loki] + exporters: [otlp_http/loki] diff --git a/docker/telemetry/otel-collector-filestorage.yaml b/docker/telemetry/otel-collector-filestorage.yaml index 5362431725..fec6c7ddab 100644 --- a/docker/telemetry/otel-collector-filestorage.yaml +++ b/docker/telemetry/otel-collector-filestorage.yaml @@ -1,4 +1,4 @@ -# Collector overlay that persists filelog read offsets. Applied ONLY by the +# 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. # @@ -15,14 +15,14 @@ # instead of re-reading debug.log from the top. extensions: - file_storage/filelog: + file_storage/file_log: directory: /var/lib/otelcol/file_storage create_directory: true receivers: - filelog: - storage: file_storage/filelog + 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/filelog] + extensions: [health_check, file_storage/file_log] diff --git a/docker/telemetry/xrpld-telemetry.cfg b/docker/telemetry/xrpld-telemetry.cfg index 64c59f4577..3294630bc9 100644 --- a/docker/telemetry/xrpld-telemetry.cfg +++ b/docker/telemetry/xrpld-telemetry.cfg @@ -35,10 +35,15 @@ advisory_delete=0 docker/telemetry/data # Path is resolved relative to this config file's directory (docker/telemetry), -# so this writes to docker/telemetry/data/logs/devnet/debug.log — the same -# dir the compose stack bind-mounts into the collector as /var/log/xrpld. +# 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] -data/logs/devnet/debug.log +data/logs/xrpld-standalone/debug.log [rpc_startup] { "command": "log_level", "severity": "debug" } diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index e90b30171c..adbeda9ffb 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -857,7 +857,7 @@ Requires `trace_peer=1` in the `[telemetry]` config section. 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 +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: @@ -867,9 +867,11 @@ This enables bidirectional navigation between logs and traces in Grafana: ### Log Ingestion Pipeline -Log files are ingested by the OTel Collector's `filelog` 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. +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`) and which needs no root. 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-network or per-node subdirectory. +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. @@ -973,9 +975,9 @@ count_over_time({service_name="xrpld"} |= "trace_id=" [5m]) ### 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 filelog receiver errors: `docker compose logs otel-collector` +- 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 filelog receiver glob `/var/log/xrpld/*/debug.log` matches your log layout — the log file must sit one subdirectory below the mount root +- 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