From 975238d7d4ccb65e1ab00213d8a1eba4ba248139 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Fri, 11 Sep 2026 11:30:39 +0100 Subject: [PATCH] docs(telemetry): fix the node log path, log level and Grafana span link MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The config template wrote each node's log to a lowercase node{N} directory while setting service_instance_id=Node-{N}. The collector takes the node name from the log file's parent directory and stamps it as the Loki service_instance_id label, so the logs carried a name no trace or metric shared and nothing joined. Use Node-{N} and state the rule. The template also set log_level to warning. Nothing in the pipeline filters on severity; the constraint is that a log line carries trace context only when it is emitted inside an active span. At warning the only such statements in the consensus accept span are a catch path a healthy round never takes and a periodic censorship warning. At info the CNF Val / CNF buildLCL pair writes one line per accepted ledger, which is what makes this test's Step 1 findable. Grafana 13 offers the link per span, labelled "Logs for this span", in the span's Links row — not per trace. Fix the step and the expected-results row. The example log line quoted a message that does not exist. The real in-span RPC statement logs at debug, so the severity code is DBG; say which line to look for under each test, since Test 2 now logs at info. Drop the reference to workload/validate_telemetry.py: that file is not part of this branch, and its instant-endpoint call uses seconds, so the nanoseconds claim applied only to query_range. --- docker/telemetry/TESTING.md | 52 ++++++++++++++++++++++++------------- 1 file changed, 34 insertions(+), 18 deletions(-) diff --git a/docker/telemetry/TESTING.md b/docker/telemetry/TESTING.md index 456a091cd9..9705934aaa 100644 --- a/docker/telemetry/TESTING.md +++ b/docker/telemetry/TESTING.md @@ -237,14 +237,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} @@ -279,12 +279,22 @@ server=otel endpoint=http://localhost:4318/v1/metrics [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 @@ -481,9 +491,15 @@ 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:NFO trace_id=abc123def456789012345678abcdef01 span_id=0123456789abcdef Calling server_info +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. @@ -524,9 +540,9 @@ 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`. +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 @@ -534,7 +550,7 @@ Counting `.data.result | length` would count streams, not log lines. 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. Click **"Logs for this trace"** in the trace detail view +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 @@ -546,15 +562,15 @@ Counting `.data.result | length` would count streams, not log lines. ### 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 "Logs for trace" | Shows correlated log lines | -| Loki -> Tempo TraceID link | Navigates to correct trace | +| 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 | ---