diff --git a/.github/scripts/levelization/results/ordering.txt b/.github/scripts/levelization/results/ordering.txt index d9c4f24ecf..be1115a063 100644 --- a/.github/scripts/levelization/results/ordering.txt +++ b/.github/scripts/levelization/results/ordering.txt @@ -193,6 +193,7 @@ tests.libxrpl > xrpl.config tests.libxrpl > xrpl.consensus tests.libxrpl > xrpl.core tests.libxrpl > xrpld.app +tests.libxrpl > xrpld.rpc tests.libxrpl > xrpld.telemetry tests.libxrpl > xrpl.json tests.libxrpl > xrpl.ledger @@ -313,6 +314,7 @@ xrpld.rpc > xrpl.basics xrpld.rpc > xrpl.config xrpld.rpc > xrpl.core xrpld.rpc > xrpld.core +xrpld.rpc > xrpld.telemetry xrpld.rpc > xrpl.json xrpld.rpc > xrpl.ledger xrpld.rpc > xrpl.net diff --git a/.github/scripts/otel-naming/test_check_otel_naming.py b/.github/scripts/otel-naming/test_check_otel_naming.py index 42f9d76227..bc5f161e67 100644 --- a/.github/scripts/otel-naming/test_check_otel_naming.py +++ b/.github/scripts/otel-naming/test_check_otel_naming.py @@ -1530,28 +1530,54 @@ class RuleDDashboards(unittest.TestCase): ["bogus_label"], ) + # Rule D returns early on an empty L1 set, so a test that passes one asserts + # nothing. Each test below passes a nonempty L1 set and puts `bogus_label` in + # the same expression as the labels under test: the assertion then pins both + # halves at once — the accepted labels are absent from the result, and Rule D + # demonstrably ran because it flagged the bad one. + def test_builtin_labels_not_flagged(self): self.assertEqual( - self._run('"expr": "sum by (le, span_name, exported_instance) (x)"', set()), - [], + self._run( + '"expr": "sum by (le, span_name, exported_instance, bogus_label) (x)"', + {"command"}, + ), + ["bogus_label"], ) def test_external_infra_labels_not_flagged(self): # EXTERNAL_INFRA_LABELS (perf-iac identity labels with no in-tree - # source) must be recognized as valid, distinct from `builtins`. - expr = "sum by (" + ", ".join(sorted(chk.EXTERNAL_INFRA_LABELS)) + ") (x)" - self.assertEqual(self._run(f'"expr": "{expr}"', set()), []) + # source) must be recognized as valid, distinct from `builtins`. The + # names are spelled out rather than joined from chk.EXTERNAL_INFRA_LABELS + # because building the query from the set that validates it passes for + # whatever that set happens to hold — including an empty one. + self.assertEqual( + self._run( + '"expr": "sum by (xrpl_branch, xrpl_node_role, bogus_label) (x)"', + {"command"}, + ), + ["bogus_label"], + ) def test_prometheus_name_label_not_flagged(self): # `__name__` is the Prometheus reserved metric-name label; the renamed # system-*.json dashboards use `sum by (le, __name__)`. self.assertEqual( - self._run('"expr": "sum by (le, __name__) (rate(x[5m]))"', set()), - [], + self._run( + '"expr": "sum by (le, __name__, bogus_label) (rate(x[5m]))"', + {"command"}, + ), + ["bogus_label"], ) def test_l1_label_passes(self): - self.assertEqual(self._run('"q": "{command=\\"x\\"}"', {"command"}), []) + # `by (...)` form, not a `{command="x"}` selector: a dashboard stores the + # query inside a JSON string, so its quotes are escaped on disk and the + # selector branch extracts nothing from them here. + self.assertEqual( + self._run('"expr": "sum by (command, bogus_label) (x)"', {"command"}), + ["bogus_label"], + ) def test_traceql_span_prefix_stripped(self): # `span.establish_count` must validate against the bare L1 key. @@ -1564,7 +1590,15 @@ class RuleDDashboards(unittest.TestCase): ) def test_traceql_resource_prefix_stripped(self): - self.assertEqual(self._run('"q": "{resource.service_name=\\"x\\"}"', set()), []) + # `resource.service_name` must validate against the bare builtin, same as + # the `span.` case above. + self.assertEqual( + self._run( + '"expr": "count_over_time(x) by (resource.service_name, bogus_label)"', + {"command"}, + ), + ["bogus_label"], + ) def test_native_metric_label_passes(self): # `job_type` / `reason` are emitted by MetricsRegistry, not span attrs. diff --git a/OpenTelemetryPlan/00-tracing-fundamentals.md b/OpenTelemetryPlan/00-tracing-fundamentals.md index 9c6f96d7af..1c7675243a 100644 --- a/OpenTelemetryPlan/00-tracing-fundamentals.md +++ b/OpenTelemetryPlan/00-tracing-fundamentals.md @@ -297,9 +297,9 @@ XRPL has a unique advantage: its core workflows produce **globally unique 256-bi Transaction: STTx::getTransactionID() → uint256 tid_ TMTransaction::rawTransaction → recompute hash from bytes -Consensus: ConsensusProposal::prevLedger_ → uint256 (previous ledger hash) - ConsensusProposal::position_ → uint256 (TxSet hash) - LedgerHeader::seq → uint32_t (ledger sequence) +Consensus: ConsensusProposal::previousLedger_ → uint256 (previous ledger hash) + ConsensusProposal::position_ → uint256 (TxSet hash) + LedgerHeader::seq → uint32_t (ledger sequence) Validation: STValidation::getLedgerHash() → uint256 STValidation::getNodeID() → NodeID (160-bit) diff --git a/OpenTelemetryPlan/02-design-decisions.md b/OpenTelemetryPlan/02-design-decisions.md index 7468d204bb..da20680e87 100644 --- a/OpenTelemetryPlan/02-design-decisions.md +++ b/OpenTelemetryPlan/02-design-decisions.md @@ -285,17 +285,19 @@ via `resource/stripsdk`. See [05 §5.5.1](./05-configuration-reference.md). #### Transaction Attributes -| Key | Type | Description | -| -------------- | ------ | ------------------------------------- | -| `tx_hash` | string | Transaction hash (hex) | -| `tx_type` | string | `"Payment"`, `"OfferCreate"`, etc. | -| `tx_account` | string | Source account (redacted in prod) | -| `tx_sequence` | int64 | Account sequence number | -| `tx_fee` | int64 | Fee in drops | -| `tx_result` | string | `"tesSUCCESS"`, `"tecPATH_DRY"`, etc. | -| `ledger_index` | int64 | Ledger containing transaction | -| `relay_count` | int64 | Peers the transaction was relayed to | -| `suppressed` | bool | `true` when HashRouter dropped a dup | +| Key | Type | Description | +| -------------------- | ------ | ------------------------------------- | +| `tx_hash` | string | Transaction hash (hex) | +| `tx_type` | string | `"Payment"`, `"OfferCreate"`, etc. | +| `tx_account` | string | Source account (redacted in prod) | +| `tx_sequence` | int64 | Account sequence number | +| `tx_fee` | int64 | Fee in drops | +| `tx_result` | string | `"tesSUCCESS"`, `"tecPATH_DRY"`, etc. | +| `current_ledger_seq` | int64 | Open ledger the transaction targeted | +| `relay_count` | int64 | Peers the transaction was relayed to | +| `suppressed` | bool | `true` when HashRouter dropped a dup | + +> **Note:** `current_ledger_seq` and `ledger_seq` are the same concept — a ledger's sequence number — but they name different ledgers, so the design keeps two keys rather than one. `current_ledger_seq` is the open or in-flight ledger a transaction's work was applied into; it is named after the RPC field `ledger_current_index`. `ledger_seq` (see [Ledger & Job Attributes](#ledger--job-attributes)) is a closed or validated ledger, set by the ledger and consensus spans. Neither is spelled `ledger_index`: per rule 2 of [Telemetry span attribute naming](../CONTRIBUTING.md#telemetry-span-attribute-naming), one concept gets one key reused verbatim, and a different referent is disambiguated with a prefix rather than a synonym. #### Consensus Attributes @@ -355,7 +357,7 @@ Establish-phase gap fill and cross-node correlation attributes (Phase 4a): | Key | Type | Description | | --------------------------- | ------- | --------------------------------- | | `ledger_hash` | string | Ledger hash | -| `ledger_index` | int64 | Ledger sequence/index | +| `ledger_seq` | int64 | Closed/validated ledger sequence | | `close_time_ripple_epoch_s` | int64 | Close time (Ripple epoch seconds) | | `ledger_tx_count` | int64 | Transaction count | | `job_type` | string | Job type name | @@ -746,9 +748,12 @@ A PerfLog entry is a JSON object with fields such as `time`, `method`, - No request-level detail - No causal relationships - Single-node perspective + - Aggregation happens on the StatsD server, not in the process In xrpld, Beast Insight is used through `increment` (counters), `gauge` -(point-in-time values), and `timing` (durations) calls. +(point-in-time values), and `timing` (durations) calls. A `timing` call sends +each measured value as its own raw `|ms` sample, so the histogram a dashboard +reads is built by the StatsD server from that stream of values. #### OpenTelemetry (NEW) @@ -757,6 +762,7 @@ In xrpld, Beast Insight is used through `increment` (counters), `gauge` - **Cross-node correlation** via `trace_id` - Parent-child span relationships - Rich attributes per span + - A `Histogram` instrument that aggregates **at the point of measure** - Industry standard (CNCF) - **Limitations**: - Requires collector infrastructure @@ -766,6 +772,13 @@ A span is created via `startSpan` (e.g. `"tx.relay"`), annotated with attributes such as `tx_hash` and `peer_id`, and is automatically linked to its parent through the active context. +OpenTelemetry is not only spans. The same SDK offers a `Histogram` instrument, +and a `Record()` call folds the value straight into bucket counts inside the +process — no per-event record is shipped and no server-side aggregation step is +needed. That is what makes it affordable in a hot loop where one span per event +would not be, and it is the one thing Beast Insight cannot do, because its +`timing` path ships raw values and aggregates them on the StatsD server. + ### 2.6.3 When to Use Each | Scenario | PerfLog | StatsD | OpenTelemetry | @@ -776,6 +789,15 @@ parent through the active context. | "Which node delayed consensus?" | ❌ | ❌ | ✅ | | "What happened on node X at time T?" | ✅ | ❌ | ✅ | | "Show me the TX journey across 5 nodes" | ❌ | ❌ | ✅ | +| "p99 NodeStore fetch latency?" | ❌ | ❌ | ✅ | + +The last row is the case a span cannot answer. One `TMGetObjectByHash` message +requests up to `tuning::kHardMaxReplyNodes` objects, so a span per NodeStore +fetch is not affordable in that loop. Instead the fetch loop's wall time is +recorded once per message into an OpenTelemetry `Histogram` +(`getobject_lookup_us`), and the quantile is read off its buckets. StatsD is +marked ❌ because that instrument is recorded on the native OpenTelemetry metrics +path, not through Beast Insight. ### 2.6.4 Coexistence Strategy diff --git a/OpenTelemetryPlan/05-configuration-reference.md b/OpenTelemetryPlan/05-configuration-reference.md index 564d748494..bc88b82295 100644 --- a/OpenTelemetryPlan/05-configuration-reference.md +++ b/OpenTelemetryPlan/05-configuration-reference.md @@ -164,7 +164,7 @@ Setting `traces_endpoint` therefore moves traces only; both metric pipelines fol > available on both. Components that hold a `ServiceRegistry&` (e.g. > `NetworkOPsImp`) call `registry_.get().getTelemetry()`. Components that > still hold an `Application&` (e.g. `ServerHandler`, `PeerImp`, -> `RCLConsensusAdaptor`) call `app_.getTelemetry()` directly. +> `RCLConsensus::Adaptor`) call `app_.getTelemetry()` directly. --- @@ -528,10 +528,10 @@ before adding more. {resource.service.name="xrpld" && span.tx_hash="ABC123..."} # Find slow RPC commands (>100ms) -{resource.service.name="xrpld" && name=~"rpc.command.*"} | duration > 100ms +{resource.service.name="xrpld" && name=~"rpc.command.*"} | { duration > 100ms } # Find consensus rounds taking >5 seconds -{resource.service.name="xrpld" && name="consensus.round"} | duration > 5s +{resource.service.name="xrpld" && name="consensus.round"} | { duration > 5s } # Find failed transaction processing {resource.service.name="xrpld" && name="tx.process" && span.ter_result!="tesSUCCESS"} @@ -545,7 +545,7 @@ before adding more. {resource.service.name="xrpld" && name="tx.process" && span.local=false} # Compare latency across nodes -{resource.service.name="xrpld" && name="rpc.command.account_info"} | avg(duration) by (resource.service.instance.id) +{resource.service.name="xrpld" && name="rpc.command.account_info"} | avg_over_time(duration) by (resource.service.instance.id) ``` > Queries in earlier drafts used `tx.validate`, `tx.relay` and diff --git a/OpenTelemetryPlan/06-implementation-phases.md b/OpenTelemetryPlan/06-implementation-phases.md index 02027028ca..89ae7e34b7 100644 --- a/OpenTelemetryPlan/06-implementation-phases.md +++ b/OpenTelemetryPlan/06-implementation-phases.md @@ -120,7 +120,7 @@ gantt | ---- | -------------------------------------------------------------------------- | | 2.1 | Implement W3C Trace Context HTTP header extraction | | 2.2 | Instrument `ServerHandler::onRequest()` | -| 2.3 | Instrument `RPCHandler::doCommand()` | +| 2.3 | Instrument `xrpl::rpc::doCommand()` | | 2.4 | Add RPC-specific attributes | | 2.5 | Instrument WebSocket handler | | 2.6 | PathFinding instrumentation (`pathfind.request`, `pathfind.compute` spans) | @@ -200,16 +200,16 @@ and [Phase3_taskList.md Task 3.9](./Phase3_taskList.md) for the full implementat ### Tasks -| Task | Description | Status | -| ---- | ---------------------------------------------- | ------------------ | -| 4.1 | Instrument `RCLConsensusAdaptor::startRound()` | ✅ Done (via 4a.2) | -| 4.2 | Instrument phase transitions | ✅ Done | -| 4.3 | Instrument proposal handling | ✅ Done | -| 4.4 | Instrument validation handling | ✅ Done | -| 4.5 | Add consensus-specific attributes | ✅ Done | -| 4.6 | Correlate with transaction traces | ✅ Done | -| 4.7 | Build verification and testing | ✅ Done | -| 4.8 | Validation span enrichment (ext. dashboard) | ✅ Done (partial) | +| Task | Description | Status | +| ---- | ------------------------------------------- | ------------------ | +| 4.1 | Instrument `RCLConsensus::startRound()` | ✅ Done (via 4a.2) | +| 4.2 | Instrument phase transitions | ✅ Done | +| 4.3 | Instrument proposal handling | ✅ Done | +| 4.4 | Instrument validation handling | ✅ Done | +| 4.5 | Add consensus-specific attributes | ✅ Done | +| 4.6 | Correlate with transaction traces | ✅ Done | +| 4.7 | Build verification and testing | ✅ Done | +| 4.8 | Validation span enrichment (ext. dashboard) | ✅ Done (partial) | **Note**: The original plan doc listed tasks 4.7-4.11 as "Validator list tracing", "Amendment voting tracing", "SHAMap sync tracing", "Multi-validator integration tests", diff --git a/OpenTelemetryPlan/09-data-collection-reference.md b/OpenTelemetryPlan/09-data-collection-reference.md index 99aa2a9c5e..e4eeb029e8 100644 --- a/OpenTelemetryPlan/09-data-collection-reference.md +++ b/OpenTelemetryPlan/09-data-collection-reference.md @@ -1146,6 +1146,10 @@ repeated here: [Per-Job-Type Metrics](#per-job-type-metrics-synchronous-countershistogram). - Five `getobject_*` instruments covering the `TMGetObjectByHash` request path — see [GetObject Request Path](#getobject-request-path-synchronous-countershistograms). +- Two request-count histograms, `rpc_batch_size` and `pathfind_discovered_paths`, + which give the aggregate distribution of two values that until now existed only + as span attributes on a sampled trace — see + [RPC Request-Count Histograms](#rpc-request-count-histograms). - Three per-job-type queue gauge families (`jobq__waiting` / `_running` / `_deferred`). These travel the `beast::insight` pipeline, not the OTel SDK one, so they are documented in @@ -1555,6 +1559,55 @@ macro (see `src/xrpld/telemetry/MetricMacros.h` and `PerfLogImp.cpp`), not throu `MetricsRegistry` member. As an UpDownCounter it carries no `_total` suffix (that is reserved for monotonic counters). +#### RPC Request-Count Histograms + +Two histograms describing how much work one request asks for. Names and +descriptions are the `constexpr` constants in +`include/xrpl/telemetry/RpcMetricNames.h`; both are recorded at their call sites +via `XRPL_METRIC_*`, and both have an explicit-bucket view registered in +`src/xrpld/telemetry/MetricsRegistry.cpp`. + +| Prometheus Metric | Type | Labels | Description | +| --------------------------- | --------- | ------ | ------------------------------------------------------- | +| `rpc_batch_size` | Histogram | (none) | Sub-requests per batch JSON-RPC call | +| `pathfind_discovered_paths` | Histogram | (none) | Payment paths produced per pathfinding pass, all assets | + +| Metric | Recorded at | Beside the span attribute | +| --------------------------- | ----------------------------------------------- | ------------------------- | +| `rpc_batch_size` | `ServerHandler::processRequest`, `method=batch` | `batch_size` | +| `pathfind_discovered_paths` | `PathRequest::findPaths`, after the asset loop | `pathfind_num_paths` | + +**Why both a span attribute and a histogram for the same value.** The attribute +answers "how big was this one request" on a trace someone is already looking at. +It cannot give a distribution, because an unsampled trace is never read. The +histogram answers "how big are these requests" across every call. Neither +replaces the other, so both stay. + +`rpc_batch_size` is recorded only when `method == "batch"`, matching the +attribute. Recording a plain single request would add the value 1 on every RPC +and bury the batch distribution. + +`pathfind_discovered_paths` records inside the existing +`#ifdef XRPL_ENABLE_TELEMETRY` block, because the running total it reports is +only maintained in a telemetry build. Zero is a normal and interesting value: a +pass that found no path at all records it. + +**Both use `buckets::kObjectCountBuckets`, and the reason is the floor.** The SDK +default boundaries begin `0, 5, 10, 25`, so every batch of one to five +sub-requests — the ordinary case — lands in a single bucket and +`histogram_quantile` returns that edge scaled by the quantile rather than a +count. The object-count ladder's `1, 2, 4, 8, 16` edges sit where both +distributions have their mass. + +- **Path counts cannot saturate.** `PathRequest::kMaxPaths` (4) per source asset + times `tuning::kMaxAutoSrcCur` (88) bounds a pass at 352 paths, well under the + ladder's 12288 top edge. +- **Batch sizes can.** Nothing caps the sub-request count; the only bound is + `tuning::kMaxRequestSize` (1 MB) over the smallest sub-request an array can + hold, about 333,000. The ladder is not extended into a range no measured + workload occupies, so an over-ceiling batch lands in `+Inf` and is read as + `rpc_batch_size_count - rpc_batch_size_bucket{le="12288"}` instead. + #### Per-Job-Type Metrics (Synchronous Counters/Histogram) | Prometheus Metric | Type | Labels | Description | @@ -1632,8 +1685,8 @@ information the batch totals do not already carry. **All three histograms need an explicit bucket view.** The SDK's default histogram boundaries top out at 10000. Every one of these three exceeds that, so -without a view their top quantiles would all read as a flat 10000. Six views are -registered in `src/xrpld/telemetry/MetricsRegistry.cpp`, and three of the six are +without a view their top quantiles would all read as a flat 10000. Eight views are +registered in `src/xrpld/telemetry/MetricsRegistry.cpp`, and three of the eight are for this family: | Instrument | View helper | Boundaries | @@ -1642,9 +1695,11 @@ for this family: | `getobject_request_objects` | `addHistogramView()`, own set | `1, 2, 4, 8, 16, 64, 256, 1024, 4096, 12288` | | `getobject_charge` | `addHistogramView()`, own set | `0, 100, 500, 1000, 5000, 10000, 25000, 50000, 100000` | -The other three views are `addMicrosecondHistogramView()` on `job_queued_us`, -`job_running_us`, and `rpc_method_us` — four µs-ladder views plus these two -custom sets. +The other five views are `addMicrosecondHistogramView()` on `job_queued_us`, +`job_running_us` and `rpc_method_us`, plus `rpc_batch_size` and +`pathfind_discovered_paths` on the object-count ladder — four µs-ladder views and +four custom-boundary ones. See +[RPC Request-Count Histograms](#rpc-request-count-histograms) for the latter two. **Why the latter two do not use the µs ladder.** They are not durations. The µs ladder's buckets are chosen for time (sub-millisecond jobs through multi-second diff --git a/OpenTelemetryPlan/Phase3_taskList.md b/OpenTelemetryPlan/Phase3_taskList.md index 55e0a9ed64..3b73809b98 100644 --- a/OpenTelemetryPlan/Phase3_taskList.md +++ b/OpenTelemetryPlan/Phase3_taskList.md @@ -509,12 +509,14 @@ This gives the best of both worlds: guaranteed cross-node correlation via determ | `tx.process` | `applied` | bool | `e.applied` (set after batch application) | | `tx.receive` | `tx_type` | string | `TxFormats::getInstance().findByType(stx->getTxnType())->getName()` | | `txq.enqueue` | `tx_type` | string | same pattern as above | -| `txq.enqueue` | `txq_status` | string | `queued` / `applied_direct` / `applied` / `rejected` | +| `txq.enqueue` | `txq_status` | string | `queued` / `applied_direct` / `applied` / `failed` / `rejected` | +| `txq.enqueue` | `ter_code` | string | `transToken(directApplied->ter)` (set on the direct-apply path) | | `txq.enqueue` | `fee_level_paid` | int64 | `getFeeLevelPaid(view, *tx).value()` | | `txq.enqueue` | `required_fee_level` | int64 | `getRequiredFeeLevel(...).value()` | | `txq.batch_clear` | `num_cleared` | int64 | queued txs cleared ahead of the applying tx | | `txq.cleanup` | `expired_count` | int64 | entries dropped for passed `LastLedgerSequence` | | `txq.accept_tx` | `txq_status` | string | `applied` / `failed` / `retried` | +| `txq.accept_tx` | `ter_code` | string | `transToken(txnResult)` (set before branching on the outcome) | | `txq.accept` | `ledger_changed` | bool | set at end of accept loop | **New attr keys**: `TxSpanNames.h` (`txType`, `fee`, `sequence`, `terResult`, `applied`), `TxQSpanNames.h` (`txType`). diff --git a/cfg/xrpld-example.cfg b/cfg/xrpld-example.cfg index 281bb95fbd..d7e1d8e9fa 100644 --- a/cfg/xrpld-example.cfg +++ b/cfg/xrpld-example.cfg @@ -1827,17 +1827,18 @@ validators.txt # # batch_size=512 # -# Maximum number of spans exported in a single batch. Default: 512. +# Maximum number of spans exported in a single batch. Must be at least 1 +# and must not exceed max_queue_size. Default: 512. # # batch_delay_ms=5000 # # Maximum delay (milliseconds) before a partial batch is flushed. -# Default: 5000 (5 seconds). +# Must be at least 1. Default: 5000 (5 seconds). # # max_queue_size=2048 # -# Maximum number of spans queued in memory before drops occur. -# Default: 2048. +# Maximum number of spans queued in memory before drops occur. Must be +# at least 1 and at least as large as batch_size. Default: 2048. # # --- Metric export --- # diff --git a/docs/telemetry-runbook.md b/docs/telemetry-runbook.md index 71ba999f8c..0f8fe923b8 100644 --- a/docs/telemetry-runbook.md +++ b/docs/telemetry-runbook.md @@ -1932,6 +1932,45 @@ Aggregation choices worth knowing when reading these: > peer sends an oversized request. Verify its panel with a synthetic oversized > request; do not assume it works because the query parses. +#### RPC Request-Count Metrics + +Two histograms describing how much work one RPC asks for. Names and descriptions +are the `constexpr` constants in `include/xrpl/telemetry/RpcMetricNames.h`; both +are recorded at their call sites and both get an explicit-bucket view in +`MetricsRegistry.cpp`. + +| Prometheus Metric | Kind | Labels | Recorded at | Description | +| --------------------------- | --------- | ------ | ----------------------------------------------- | --------------------------------------------------------- | +| `rpc_batch_size` | Histogram | none | `ServerHandler::processRequest`, `method=batch` | Sub-requests per batch JSON-RPC call | +| `pathfind_discovered_paths` | Histogram | none | `PathRequest::findPaths`, after the asset loop | Payment paths produced per pass, across all source assets | + +Reading them: + +- Each one sits beside a span attribute carrying the same value — + `batch_size` and `pathfind_num_paths`. Use the attribute to ask what one slow + request did; use the histogram to ask what requests do in general. An attribute + cannot answer the second question, because an unsampled trace is never read. +- `rpc_batch_size` records **only for `method == "batch"`**. A non-batch request + is not a batch of one, and recording it would put the value 1 on every RPC and + bury the distribution. +- `pathfind_discovered_paths` counts zero when a pass found no path, and that is + the most interesting reading on this instrument. It shares the lowest bucket + with "found exactly one path"; everything above is separated. +- Both use the object-count bucket ladder, not the µs one. They are counts, and + the SDK's default boundaries start `0, 5, 10, 25` — which puts every ordinary + batch in one bucket and makes each quantile an interpolation on the edge. +- **`rpc_batch_size` can saturate.** Nothing caps the sub-request count except + the 1 MB request-size limit, so a batch above the ladder's 12288 top edge lands + in `+Inf`. Read the overflow directly rather than trusting p99 there: + +```promql +rpc_batch_size_count - rpc_batch_size_bucket{le="12288"} +``` + +> On a healthy local network `rpc_batch_size` has **no series at all** — nothing +> issues batch RPCs. An empty panel is the expected reading, not a wiring fault. +> Verify it by sending one batch request, not by looking for a series. + #### Adding a New Metric diff --git a/include/xrpl/consensus/ConsensusSpanNames.h b/include/xrpl/consensus/ConsensusSpanNames.h index e337fa56c6..3c09dded41 100644 --- a/include/xrpl/consensus/ConsensusSpanNames.h +++ b/include/xrpl/consensus/ConsensusSpanNames.h @@ -15,8 +15,9 @@ * * consensus.round [main thread, root] * | Created: Adaptor::startRoundTracing() - * | Attrs: consensus_ledger_id, ledger_seq, consensus_mode, - * | trace_strategy, consensus_round_id + * | Attrs: consensus_ledger_id, ledger_seq, trace_strategy, + * | consensus_round_id; consensus_mode from + * | Adaptor::onModeChange() * | * +-- consensus.phase.open [main thread, child] * | Created: Consensus::startRoundInternal() @@ -151,6 +152,11 @@ using ::xrpl::telemetry::attr::ledgerSeq; * Use `_` underscore form for TraceQL ergonomics. */ inline constexpr auto ledgerId = makeStr("consensus_ledger_id"); +/** + * Consensus mode. On consensus.round it is written by onModeChange, the point + * at which the engine applies the mode; on consensus.ledger_close the engine + * passes the mode in. + */ inline constexpr auto mode = makeStr("consensus_mode"); inline constexpr auto round = makeStr("consensus_round"); inline constexpr auto roundId = makeStr("consensus_round_id"); diff --git a/include/xrpl/telemetry/DeterministicIdGenerator.h b/include/xrpl/telemetry/DeterministicIdGenerator.h index 60d4aa5c4a..390b5b6f84 100644 --- a/include/xrpl/telemetry/DeterministicIdGenerator.h +++ b/include/xrpl/telemetry/DeterministicIdGenerator.h @@ -75,7 +75,7 @@ namespace xrpl::telemetry { * @code * // With an active parent span, startSpan() inherits the parent's trace_id * // and the SDK does NOT call GenerateTraceId(), so no PendingTraceId is used. - * // auto child = parentGuard.childSpan(rpc_span::op::process); // random/parent trace_id + * // auto child = parentGuard.childSpan(rpc_span::prefix::command); // random/parent trace_id * @endcode */ class DeterministicIdGenerator final : public opentelemetry::sdk::trace::IdGenerator diff --git a/include/xrpl/telemetry/RpcMetricNames.h b/include/xrpl/telemetry/RpcMetricNames.h new file mode 100644 index 0000000000..1869fd44d0 --- /dev/null +++ b/include/xrpl/telemetry/RpcMetricNames.h @@ -0,0 +1,101 @@ +#pragma once + +// cspell:ignore ISTOGRAM +// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's +// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. + +/** + * Metric names and descriptions for the RPC request-count histograms. + * + * These two instruments measure how much work one request asks for. A span + * attribute cannot answer that in aggregate: it is readable only on a trace + * that was sampled, so it describes one call and never the distribution over + * all of them. The span attributes stay in place for single-request + * debugging; these histograms carry the shape. + * + * Each name is used at two sites, which is why they are shared constants + * rather than literals: + * + * RpcMetricNames.h + * | + * +--> ServerHandler.cpp (records kRpcBatchSize) + * | + * +--> PathRequest.cpp (records kPathfindDiscoveredPaths) + * | + * +--> MetricsRegistry.cpp (addHistogramView: registers the + * explicit bucket edges for both) + * + * A drifted name silently drops the bucket override. The SDK default edges + * start at 0, 5, 10, 25, so every batch of one to five sub-requests would + * then land in one bucket and every quantile would be an interpolation + * inside it. + * + * Placed under `include/xrpl/telemetry/` for the same reason + * GetObjectMetricNames.h is: the record sites are `xrpld.rpc` and the view + * registration is `xrpld.telemetry`, and `include/xrpl/` is the one level + * both modules are allowed to reach. + * + * Example usage -- recording the batch size: + * @code + * if (batch) + * { + * span.setAttribute(rpc_span::attr::batchSize, static_cast(size)); + * XRPL_METRIC_HISTOGRAM_RECORD(app_, kRpcBatchSize, kRpcBatchSizeDesc, size); + * } + * @endcode + * + * Example usage -- edge case: a pathfinding pass that produced no paths still + * records, because "found nothing" is the observation that matters most on + * this instrument: + * @code + * std::int64_t totalPaths = 0; // no source asset yielded a path + * XRPL_METRIC_HISTOGRAM_RECORD( + * app_, kPathfindDiscoveredPaths, kPathfindDiscoveredPathsDesc, totalPaths); + * @endcode + * + * @note These are `constexpr char[]`, not `std::string_view`. The OTel C++ + * API takes `nostd::string_view`, which has no converting constructor from + * `std::string_view` on this build, so a `string_view` constant would not + * compile at the call sites. Same convention as GetObjectMetricNames.h. + * + * @note Both share `buckets::kObjectCountBuckets`, whose top edge is 12288. + * A pathfinding pass cannot reach it. A batch can: nothing caps the + * sub-request count except the one-megabyte request-size limit. An + * over-ceiling batch lands in `+Inf` and stays countable as + * `rpc_batch_size_count - rpc_batch_size_bucket{le="12288"}`, so the overflow + * is visible rather than lost. No measured workload occupies that range, so + * the ladder is not extended into it. + * + * @note Header-only constants with no runtime state, so there is nothing to + * synchronize -- safe to include from any thread context. + */ + +namespace xrpl::telemetry { + +// ===== Metric names ========================================================== + +/** + * Distribution of the sub-request count in a batch JSON-RPC call. + * + * Recorded only for `method == "batch"`. A plain single request would + * otherwise flood the histogram with the value 1 and bury the batch + * distribution this instrument exists to show. + */ +inline constexpr char kRpcBatchSize[] = "rpc_batch_size"; + +/** + * Distribution of the payment paths one pathfinding pass produced, summed + * across every candidate source asset. + */ +inline constexpr char kPathfindDiscoveredPaths[] = "pathfind_discovered_paths"; + +// ===== Instrument descriptions =============================================== + +/** @{ */ +inline constexpr char kRpcBatchSizeDesc[] = "Sub-requests per batch JSON-RPC call"; + +inline constexpr char kPathfindDiscoveredPathsDesc[] = + "Payment paths produced per pathfinding pass, across all source assets"; +/** @} */ + +} // namespace xrpl::telemetry diff --git a/include/xrpl/telemetry/SpanGuard.h b/include/xrpl/telemetry/SpanGuard.h index 9ccfcca607..10a4a80b4a 100644 --- a/include/xrpl/telemetry/SpanGuard.h +++ b/include/xrpl/telemetry/SpanGuard.h @@ -99,7 +99,7 @@ * auto ctx = span.spanContext(); * * // Thread B: create child with captured context - * auto child = SpanGuard::childSpan(rpc_span::op::process, ctx); + * auto child = SpanGuard::childSpan(rpc_span::prefix::command, ctx); * @endcode * * 4. Conditional check (rarely needed — methods are no-ops on null): @@ -155,6 +155,22 @@ * }); * @endcode * + * 8. Internal work inside a category whose default role is Server: + * @code + * #include + * using namespace xrpl::telemetry; + * + * // Only the inbound handler is the server side of a remote call. + * // Work below it is internal, so pass the role explicitly: the + * // category default (Server) would read as a second inbound + * // request and leave an unpaired edge in a service graph. + * auto span = SpanGuard::span( + * TraceCategory::Rpc, + * rpc_span::prefix::rpc, + * rpc_span::op::process, + * SpanRole::Internal); + * @endcode + * * @note Thread safety: SpanGuard is thread-free. It holds only the * span (no Scope), so it never binds to a thread-local context stack * and may be moved to and destroyed on any thread. To make a span the @@ -204,6 +220,25 @@ namespace xrpl::telemetry { */ enum class TraceCategory { Rpc, Transactions, Consensus, Peer, Ledger }; +/** + * Role a span plays in a call relationship. Each value maps to the OTel + * span kind of the same name; see Telemetry::startSpan() for what those + * mean. + * + * Orthogonal to TraceCategory. The category names the subsystem and gates + * the span on config (`trace_rpc=1`); the role says whether the span + * handles a remote call or is internal work. An Rpc-category span can be + * either: the inbound request handler is Server, everything it calls into + * is Internal. + * + * FromCategory takes the category's own role, so a call site that does not + * care passes nothing. Pick a role explicitly where the category default + * is wrong: trace backends pair Server with Client and Consumer with + * Producer, so internal work left as Server becomes an unpaired edge in a + * service graph. + */ +enum class SpanRole { FromCategory, Internal, Server, Client, Producer, Consumer }; + /** * Raw trace context bytes for cross-node propagation. * @@ -322,9 +357,16 @@ public: * @param cat Trace subsystem category. * @param prefix Span name prefix (e.g. "rpc.command"). * @param name Span name suffix (e.g. "submit"). + * @param role Call-relationship role; defaults to the category's own + * role. Pass Internal for work the category maps to Server or Consumer + * but that handles no remote call. */ [[nodiscard]] static SpanGuard - span(TraceCategory cat, std::string_view prefix, std::string_view name) noexcept; + span( + TraceCategory cat, + std::string_view prefix, + std::string_view name, + SpanRole role = SpanRole::FromCategory) noexcept; /** * Create a span that always starts a fresh trace root. @@ -339,10 +381,16 @@ public: * @param cat Trace subsystem category. * @param prefix Span name prefix (e.g. "peer"). * @param name Span name suffix (e.g. "validation.receive"). + * @param role Call-relationship role; defaults to the category's own + * role. See span(). * @return An active root-span guard, or a null guard if disabled. */ [[nodiscard]] static SpanGuard - freshRoot(TraceCategory cat, std::string_view prefix, std::string_view name) noexcept; + freshRoot( + TraceCategory cat, + std::string_view prefix, + std::string_view name, + SpanRole role = SpanRole::FromCategory) noexcept; // --- Child / linked span creation ---------------------------------- @@ -664,10 +712,12 @@ public: * using namespace xrpl::telemetry; * * ScopedSpanGuard span( - * TraceCategory::Rpc, rpc_span::prefix::command, commandName); - * span.setAttribute(rpc_span::attr::command, commandName); - * // childSpan parents to `span` because it is active on this thread - * auto child = span.childSpan(rpc_span::op::process); + * TraceCategory::Rpc, rpc_span::prefix::rpc, rpc_span::op::process); + * // childSpan takes the name verbatim, so pass a full dotted constant, + * // never a bare op:: suffix. The child parents to `span` because + * // `span` is active on this thread. + * auto child = span.childSpan(rpc_span::prefix::command); + * child.setAttribute(rpc_span::attr::command, commandName); * @endcode * * 2. Capture on this thread, hand off to another (edge case): @@ -714,8 +764,14 @@ public: * @param cat Trace subsystem category. * @param prefix Span name prefix (e.g. "rpc.command"). * @param name Span name suffix (e.g. "submit"). + * @param role Call-relationship role; defaults to the category's own + * role. See SpanGuard::span(). */ - ScopedSpanGuard(TraceCategory cat, std::string_view prefix, std::string_view name) noexcept; + ScopedSpanGuard( + TraceCategory cat, + std::string_view prefix, + std::string_view name, + SpanRole role = SpanRole::FromCategory) noexcept; ~ScopedSpanGuard(); @@ -734,10 +790,16 @@ public: * @param cat Trace subsystem category. * @param prefix Span name prefix. * @param name Span name suffix. + * @param role Call-relationship role; defaults to the category's own + * role. See SpanGuard::span(). * @return An active scoped root-span guard, or a null one if disabled. */ [[nodiscard]] static ScopedSpanGuard - freshRoot(TraceCategory cat, std::string_view prefix, std::string_view name) noexcept; + freshRoot( + TraceCategory cat, + std::string_view prefix, + std::string_view name, + SpanRole role = SpanRole::FromCategory) noexcept; // --- Child / linked span creation ---------------------------------- @@ -1029,13 +1091,21 @@ public: operator=(SpanGuard const&) = delete; [[nodiscard]] static SpanGuard - span(TraceCategory, std::string_view, std::string_view) noexcept + span( + TraceCategory, + std::string_view, + std::string_view, + SpanRole = SpanRole::FromCategory) noexcept { return {}; } [[nodiscard]] static SpanGuard - freshRoot(TraceCategory, std::string_view, std::string_view) noexcept + freshRoot( + TraceCategory, + std::string_view, + std::string_view, + SpanRole = SpanRole::FromCategory) noexcept { return {}; } @@ -1183,7 +1253,11 @@ class ScopedSpanGuard ScopedSpanGuard() = default; public: - ScopedSpanGuard(TraceCategory, std::string_view, std::string_view) noexcept + ScopedSpanGuard( + TraceCategory, + std::string_view, + std::string_view, + SpanRole = SpanRole::FromCategory) noexcept { } /** @@ -1204,7 +1278,11 @@ public: operator=(ScopedSpanGuard const&) = delete; [[nodiscard]] static ScopedSpanGuard - freshRoot(TraceCategory, std::string_view, std::string_view) noexcept + freshRoot( + TraceCategory, + std::string_view, + std::string_view, + SpanRole = SpanRole::FromCategory) noexcept { return {}; } diff --git a/include/xrpl/telemetry/Telemetry.h b/include/xrpl/telemetry/Telemetry.h index 3ead41a089..48eec93407 100644 --- a/include/xrpl/telemetry/Telemetry.h +++ b/include/xrpl/telemetry/Telemetry.h @@ -53,14 +53,18 @@ * * 2. Child span for a sub-operation (scoped child): * @code - * auto parent = SpanGuard::span( + * auto parent = ScopedSpanGuard( * TraceCategory::Rpc, rpc_span::prefix::rpc, rpc_span::op::process); * { - * auto child = parent.childSpan(rpc_span::op::process); - * child.setAttribute(rpc_span::attr::version, apiVersion); + * auto child = parent.childSpan(rpc_span::prefix::command); + * child.setAttribute(rpc_span::attr::version, static_cast(apiVersion)); * // child ends here * } * @endcode + * childSpan() parents to the ambient scope, so the parent must be a + * ScopedSpanGuard. A plain SpanGuard is not ambient: pass its spanContext() + * to childSpan(name, ctx) instead. childSpan() takes the name verbatim, so + * pass a full dotted constant, never a bare op:: suffix. * * 3. Unrelated span (cross-scope, same thread): * @code @@ -78,7 +82,7 @@ * auto ctx = parentGuard.spanContext(); * * // Thread B: create child span with explicit parent - * auto child = SpanGuard::childSpan(rpc_span::op::process, ctx); + * auto child = SpanGuard::childSpan(rpc_span::prefix::command, ctx); * @endcode * * @note Thread safety: The Telemetry interface is safe for concurrent reads diff --git a/src/libxrpl/telemetry/SpanGuard.cpp b/src/libxrpl/telemetry/SpanGuard.cpp index de46821674..9c2cdc0a6e 100644 --- a/src/libxrpl/telemetry/SpanGuard.cpp +++ b/src/libxrpl/telemetry/SpanGuard.cpp @@ -90,7 +90,10 @@ SpanContext::SpanContext(std::shared_ptr impl) : impl_(std::move(impl)) bool SpanContext::isValid() const noexcept { - return impl_ != nullptr; + // Holding a Context is not proof of holding a span. GetCurrent() hands back + // an empty Context on a thread with no active span, and threadLocalContext() + // wraps that too. Ask the Context for its span instead of trusting impl_. + return impl_ != nullptr && otel_trace::GetSpan(impl_->ctx)->GetContext().IsValid(); } // ===== SpanGuard::Impl ==================================================== @@ -178,11 +181,13 @@ namespace { constexpr char const* kLinkTypeKey = "link_type"; constexpr char const* kLinkTypeFollowsFrom = "follows_from"; -// Map a TraceCategory to an OTel SpanKind so Tempo's service-graph / -// RED metrics see the correct direction. RPC spans are emitted at the -// server entry point (handler dispatch), Peer spans at inbound-message -// receipt. Transactions / Consensus / Ledger are internal processing -// and keep the default kInternal. +// Per-category default OTel SpanKind, used when a call site passes no +// SpanRole. A category cannot tell an inbound entry point from the +// internal work under it, so RPC and Peer default to the entry-point +// kind and any call site below the entry point passes SpanRole::Internal +// instead. Transactions / Consensus / Ledger are internal throughout. +// The kind drives direction in Tempo's service-graph / RED metrics, +// which pair kServer with kClient and kConsumer with kProducer. otel_trace::SpanKind categoryToSpanKind(TraceCategory cat) { @@ -200,6 +205,38 @@ categoryToSpanKind(TraceCategory cat) return otel_trace::SpanKind::kInternal; // unreachable } +/** + * Resolve the span kind to start a span with. + * + * An explicit SpanRole wins; SpanRole::FromCategory falls back to the + * category default above. Role and category are separate axes, so a single + * category can emit both an inbound handler and the internal work under it. + * + * @param cat Trace subsystem category. Read only for SpanRole::FromCategory. + * @param role Role the caller asked for. + * @return The OTel span kind for this span. + */ +[[nodiscard]] otel_trace::SpanKind +resolveSpanKind(TraceCategory cat, SpanRole role) +{ + switch (role) + { + case SpanRole::FromCategory: + return categoryToSpanKind(cat); + case SpanRole::Internal: + return otel_trace::SpanKind::kInternal; + case SpanRole::Server: + return otel_trace::SpanKind::kServer; + case SpanRole::Client: + return otel_trace::SpanKind::kClient; + case SpanRole::Producer: + return otel_trace::SpanKind::kProducer; + case SpanRole::Consumer: + return otel_trace::SpanKind::kConsumer; + } + return categoryToSpanKind(cat); // unreachable +} + /** * Join a span-name prefix and suffix into the dotted full name. * @@ -231,7 +268,11 @@ joinSpanName(std::string_view prefix, std::string_view name) noexcept } // namespace SpanGuard -SpanGuard::span(TraceCategory cat, std::string_view prefix, std::string_view name) noexcept +SpanGuard::span( + TraceCategory cat, + std::string_view prefix, + std::string_view name, + SpanRole role) noexcept { auto* tel = Telemetry::getInstance(); if ((tel == nullptr) || !tel->isEnabled() || !isCategoryEnabled(*tel, cat)) @@ -239,11 +280,15 @@ SpanGuard::span(TraceCategory cat, std::string_view prefix, std::string_view nam auto const fullName = joinSpanName(prefix, name); if (!fullName) return {}; - return SpanGuard(std::make_unique(tel->startSpan(*fullName, categoryToSpanKind(cat)))); + return SpanGuard(std::make_unique(tel->startSpan(*fullName, resolveSpanKind(cat, role)))); } SpanGuard -SpanGuard::freshRoot(TraceCategory cat, std::string_view prefix, std::string_view name) noexcept +SpanGuard::freshRoot( + TraceCategory cat, + std::string_view prefix, + std::string_view name, + SpanRole role) noexcept { auto* tel = Telemetry::getInstance(); if ((tel == nullptr) || !tel->isEnabled() || !isCategoryEnabled(*tel, cat)) @@ -254,7 +299,7 @@ SpanGuard::freshRoot(TraceCategory cat, std::string_view prefix, std::string_vie // Force a fresh trace root: do NOT inherit this thread's active span. auto rootCtx = opentelemetry::context::Context{otel_trace::kIsRootSpanKey, true}; return SpanGuard( - std::make_unique(tel->startSpan(*fullName, rootCtx, categoryToSpanKind(cat)))); + std::make_unique(tel->startSpan(*fullName, rootCtx, resolveSpanKind(cat, role)))); } // ===== Child / linked span creation ======================================== @@ -705,8 +750,9 @@ ScopedSpanGuard::~ScopedSpanGuard() ScopedSpanGuard::ScopedSpanGuard( TraceCategory cat, std::string_view prefix, - std::string_view name) noexcept - : ScopedSpanGuard(SpanGuard::span(cat, prefix, name)) + std::string_view name, + SpanRole role) noexcept + : ScopedSpanGuard(SpanGuard::span(cat, prefix, name, role)) { } @@ -714,9 +760,10 @@ ScopedSpanGuard ScopedSpanGuard::freshRoot( TraceCategory cat, std::string_view prefix, - std::string_view name) noexcept + std::string_view name, + SpanRole role) noexcept { - return ScopedSpanGuard(SpanGuard::freshRoot(cat, prefix, name)); + return ScopedSpanGuard(SpanGuard::freshRoot(cat, prefix, name, role)); } ScopedSpanGuard diff --git a/src/libxrpl/telemetry/TelemetryConfig.cpp b/src/libxrpl/telemetry/TelemetryConfig.cpp index 01a2f4297e..c6d4933363 100644 --- a/src/libxrpl/telemetry/TelemetryConfig.cpp +++ b/src/libxrpl/telemetry/TelemetryConfig.cpp @@ -15,6 +15,8 @@ #include #include +#include +#include #include #include #include @@ -78,6 +80,71 @@ constexpr auto metricExportInterval = kDefaultMetricExportInterval; constexpr auto metricExportTimeout = kDefaultMetricExportTimeout; } // namespace dflt +/** + * Smallest accepted value for the three batch settings. + * + * All three size a queue or a timer, so zero is meaningless for every one of + * them. The OTel BatchSpanProcessor takes them as given and does not validate, + * so the config parser is the only place a nonsense value can be rejected. + */ +constexpr std::uint32_t kMinBatchSetting = 1u; + +/** + * Section name used in error messages, so the operator knows where to look. + */ +constexpr char const* kSectionLabel = "[telemetry]"; + +/** + * Read a config value and reject anything outside minValue..UINT32_MAX. + * + * Section::get() lets boost::bad_lexical_cast escape. That derives from + * std::bad_cast, not std::runtime_error, so a mistyped value gives the operator + * a bare "bad cast" naming no key. Wrap it and rethrow with the key name. + * + * @param section The [telemetry] section to read from. + * @param name Key to read, as documented in cfg/xrpld-example.cfg. + * @param absentValue Value returned when the key is absent. + * @param minValue Smallest accepted value. + * @return The configured value, or absentValue if the key is absent. + * @note Throws std::runtime_error for a value that is not a whole number, and + * for one out of range, with a different message for each. + */ +[[nodiscard]] std::uint32_t +readBounded( + Section const& section, + char const* name, + std::uint32_t absentValue, + std::uint32_t minValue) +{ + // Read as signed. boost::lexical_cast to an unsigned type wraps a leading + // minus instead of failing ("-1" yields 4294967295), so reading signed is + // the only way to see a negative value and reject it below. + std::optional parsed; + try + { + parsed = section.get(name); + } + catch (...) + { + Throw( + std::string("Invalid value '") + name + "' in " + kSectionLabel + + ": must be a whole number."); + } + + if (!parsed) + return absentValue; + + constexpr auto maxValue = static_cast(std::numeric_limits::max()); + if (*parsed < static_cast(minValue) || *parsed > maxValue) + { + Throw( + std::string("Invalid value '") + name + "' in " + kSectionLabel + ": must be between " + + std::to_string(minValue) + " and " + std::to_string(maxValue) + "."); + } + + return static_cast(*parsed); +} + /** * Throw unless the given path names a file this process can read. * @@ -260,10 +327,22 @@ makeTelemetrySetup( // traces; volume reduction is delegated to the collector's tail sampling. // setup.samplingRatio is a const member fixed at 1.0; nothing to parse. - setup.batchSize = section.valueOr(key::batchSize, dflt::batchSize); + setup.batchSize = readBounded(section, key::batchSize, dflt::batchSize, kMinBatchSetting); setup.batchDelay = std::chrono::milliseconds{ - section.valueOr(key::batchDelayMs, dflt::batchDelayMs)}; - setup.maxQueueSize = section.valueOr(key::maxQueueSize, dflt::maxQueueSize); + readBounded(section, key::batchDelayMs, dflt::batchDelayMs, kMinBatchSetting)}; + setup.maxQueueSize = + readBounded(section, key::maxQueueSize, dflt::maxQueueSize, kMinBatchSetting); + + // The OTel SDK documents max_export_batch_size <= max_queue_size as a + // precondition of BatchSpanProcessorOptions and does not enforce it, so + // reject the pair here rather than hand the SDK a state it forbids. + if (setup.batchSize > setup.maxQueueSize) + { + Throw( + std::string("Invalid value '") + key::batchSize + "' in " + kSectionLabel + + ": must not exceed '" + key::maxQueueSize + "' (" + std::to_string(setup.maxQueueSize) + + ")."); + } setup.metricExportInterval = durationOr(section, key::metricExportIntervalMs, dflt::metricExportInterval); diff --git a/src/tests/libxrpl/telemetry/RpcMetricNames.cpp b/src/tests/libxrpl/telemetry/RpcMetricNames.cpp new file mode 100644 index 0000000000..ea27f80f28 --- /dev/null +++ b/src/tests/libxrpl/telemetry/RpcMetricNames.cpp @@ -0,0 +1,232 @@ +/** + * GTest unit tests for the RPC request-count metric names and their bucket fit. + * + * Two facts here have no other guard in CI. First, a metric NAME is the + * Prometheus series every panel and alert selects on, and + * `check_otel_naming.py` checks span attribute keys, not metric names -- so a + * rename or a stray unit suffix would pass every gate and blank the panels. + * Second, the reason these two histograms need an explicit-bucket view is the + * ladder FLOOR, which is invisible in a dashboard: a quantile that falls inside + * bucket 0 is interpolated from the bucket edge and reads back as a plausible + * number. The bucket-index tests below pin that with the SDK's own placement + * rule rather than leaving it to review. + */ + +#include + +#include + +#include + +#include + +#include +#include +#include +#include +#include + +namespace xrpl::telemetry { + +namespace { + +/** + * Placement rule the OTel SDK uses: the bucket index of a sample is the count + * of edges strictly below it, found with `std::lower_bound` over the ascending + * edge list. Recomputed here rather than asserted from memory, so a ladder edit + * moves the expected indices with it. + * + * @param ladder Bucket upper bounds, ascending. + * @param sample Value to place. + * @return Zero-based bucket index; `ladder.size()` means the `+Inf` bucket. + */ +[[nodiscard]] std::size_t +bucketIndex(std::span ladder, double sample) +{ + return static_cast(std::ranges::lower_bound(ladder, sample) - ladder.begin()); +} + +/** + * Last underscore-separated segment of a metric name. + * + * @param name Metric name. + * @return The text after the final underscore, or the whole name when there is + * no underscore. + */ +[[nodiscard]] std::string_view +lastSegment(std::string_view name) +{ + auto const pos = name.rfind('_'); + return pos == std::string_view::npos ? name : name.substr(pos + 1); +} + +/** + * The opentelemetry-cpp default explicit-bucket boundaries, quoted from the + * SDK because they are the ladder these two instruments would fall back to if + * their view were dropped. Not a repo constant, so there is no symbol to read + * them from. + */ +inline constexpr std::array kSdkDefaultBuckets{ + 0.0, + 5.0, + 10.0, + 25.0, + 50.0, + 75.0, + 100.0, + 250.0, + 500.0, + 750.0, + 1'000.0, + 2'500.0, + 5'000.0, + 7'500.0, + 10'000.0}; + +/** + * Smallest number of bytes one batch sub-request can occupy inside the + * `params` array: the two braces of an empty object plus its separating comma. + * An empty object still passes `isObject()`, so the handler iterates over it. + */ +inline constexpr int kMinBatchItemBytes = 3; + +} // namespace + +TEST(RpcMetricNames, namesAreTheExactExportedSeriesNames) +{ + // These strings ARE the Prometheus series. Changing one is a + // dashboard-breaking change, so it has to be a deliberate edit here too. + EXPECT_EQ(std::string_view{kRpcBatchSize}, "rpc_batch_size"); + EXPECT_EQ(std::string_view{kPathfindDiscoveredPaths}, "pathfind_discovered_paths"); +} + +TEST(RpcMetricNames, descriptionsAreTheExactExportedHelpText) +{ + // The description becomes the Prometheus `# HELP` line, so it is part of + // the exported surface, not a code comment. + EXPECT_EQ(std::string_view{kRpcBatchSizeDesc}, "Sub-requests per batch JSON-RPC call"); + EXPECT_EQ( + std::string_view{kPathfindDiscoveredPathsDesc}, + "Payment paths produced per pathfinding pass, across all source assets"); +} + +TEST(RpcMetricNames, namesAreLowerSnakeCase) +{ + for (std::string_view const name : + {std::string_view{kRpcBatchSize}, std::string_view{kPathfindDiscoveredPaths}}) + { + ASSERT_FALSE(name.empty()); + EXPECT_TRUE(name.front() >= 'a' && name.front() <= 'z') + << name << " must start with a lowercase letter"; + EXPECT_NE(name.back(), '_') << name << " must not end with an underscore"; + for (char const c : name) + { + EXPECT_TRUE((c >= 'a' && c <= 'z') || (c >= '0' && c <= '9') || c == '_') + << name << " contains '" << c << "', which is not lower_snake_case"; + } + EXPECT_EQ(name.find("__"), std::string_view::npos) + << name << " must not contain a double underscore"; + } +} + +TEST(RpcMetricNames, namesEndInTheCountedNounAndNotAUnitOrCounterSuffix) +{ + // Both instruments count things. `_total` is the Prometheus counter suffix + // and `_count`/`_sum`/`_bucket` are the ones the exporter appends to a + // histogram, so a base name ending in any of them collides with a series + // the exporter generates. `_us`/`_ms`/`_bytes` would claim a unit these + // values do not have. + EXPECT_EQ(lastSegment(kRpcBatchSize), "size"); + EXPECT_EQ(lastSegment(kPathfindDiscoveredPaths), "paths"); + + for (std::string_view const name : + {std::string_view{kRpcBatchSize}, std::string_view{kPathfindDiscoveredPaths}}) + { + for (std::string_view const reserved : + {"total", "count", "sum", "bucket", "us", "ms", "s", "seconds", "bytes"}) + { + EXPECT_NE(lastSegment(name), reserved) + << name << " ends in the reserved suffix _" << reserved; + } + } +} + +TEST(RpcMetricBucketFit, objectCountLadderSeparatesTheSmallestCounts) +{ + using buckets::kObjectCountBuckets; + + // The five edges that carry both distributions. Stated exactly: raising the + // floor is the defect this test exists to catch. + ASSERT_GE(kObjectCountBuckets.size(), 5u); + EXPECT_EQ(kObjectCountBuckets[0], 1.0); + EXPECT_EQ(kObjectCountBuckets[1], 2.0); + EXPECT_EQ(kObjectCountBuckets[2], 4.0); + EXPECT_EQ(kObjectCountBuckets[3], 8.0); + EXPECT_EQ(kObjectCountBuckets[4], 16.0); + + std::span const ladder{kObjectCountBuckets}; + + // A pathfinding pass that found nothing shares bucket 0 with a pass that + // found exactly one path; every larger count is separated. + EXPECT_EQ(bucketIndex(ladder, 0.0), 0u); + EXPECT_EQ(bucketIndex(ladder, 1.0), 0u); + EXPECT_EQ(bucketIndex(ladder, 2.0), 1u); + EXPECT_EQ(bucketIndex(ladder, 3.0), 2u); + EXPECT_EQ(bucketIndex(ladder, 4.0), 2u); + EXPECT_EQ(bucketIndex(ladder, 8.0), 3u); + EXPECT_EQ(bucketIndex(ladder, 16.0), 4u); +} + +TEST(RpcMetricBucketFit, theSdkDefaultLadderWouldCollapseEverySmallBatch) +{ + // This is why both instruments get an explicit-bucket view. On the SDK + // default ladder every batch from 1 to 5 sub-requests lands in one bucket, + // so histogram_quantile interpolates inside it and returns the edge scaled + // by the quantile -- a number that looks like a batch size and is not one. + std::span const sdk{kSdkDefaultBuckets}; + EXPECT_EQ(bucketIndex(sdk, 1.0), 1u); + EXPECT_EQ(bucketIndex(sdk, 2.0), 1u); + EXPECT_EQ(bucketIndex(sdk, 4.0), 1u); + EXPECT_EQ(bucketIndex(sdk, 5.0), 1u); + + // The chosen ladder spreads those same four values over three buckets. + std::span const chosen{buckets::kObjectCountBuckets}; + EXPECT_EQ(bucketIndex(chosen, 1.0), 0u); + EXPECT_EQ(bucketIndex(chosen, 2.0), 1u); + EXPECT_EQ(bucketIndex(chosen, 4.0), 2u); + EXPECT_EQ(bucketIndex(chosen, 5.0), 3u); +} + +TEST(RpcMetricBucketFit, aMaximumSizedBatchStillOverflowsTheLadderCeiling) +{ + // The documented limitation of rpc_batch_size, as an executable fact. + // Nothing caps the sub-request count except the request-size limit, so the + // largest possible batch is far above the ladder's top edge and lands in + // `+Inf`. RpcMetricNames.h documents the query that counts the overflow. + // If the ladder is ever raised past this bound, this test goes red and that + // note has to change with it. + constexpr int kLargestPossibleBatch = rpc::tuning::kMaxRequestSize / kMinBatchItemBytes; + EXPECT_EQ(kLargestPossibleBatch, 333'333); + EXPECT_EQ(buckets::kObjectCountBuckets.back(), 12'288.0); + EXPECT_GT(static_cast(kLargestPossibleBatch), buckets::kObjectCountBuckets.back()); + + // A pass-through check on the placement helper: the overflow really does + // land in the +Inf bucket, whose index is one past the last edge. + std::span const ladder{buckets::kObjectCountBuckets}; + EXPECT_EQ(bucketIndex(ladder, static_cast(kLargestPossibleBatch)), ladder.size()); +} + +// The placement helper must also disagree with the ladder when it should. A +// helper that always returned 0 would let every index assertion above pass. +TEST(RpcMetricBucketFit, bucketIndexPlacesAboveAndBelowEveryEdge) +{ + constexpr std::array probe{10.0, 20.0}; + std::span const ladder{probe}; + EXPECT_EQ(bucketIndex(ladder, 9.9), 0u); + EXPECT_EQ(bucketIndex(ladder, 10.0), 0u); + EXPECT_EQ(bucketIndex(ladder, 10.1), 1u); + EXPECT_EQ(bucketIndex(ladder, 20.0), 1u); + EXPECT_EQ(bucketIndex(ladder, 20.1), 2u); +} + +} // namespace xrpl::telemetry diff --git a/src/tests/libxrpl/telemetry/SpanGuardScope.cpp b/src/tests/libxrpl/telemetry/SpanGuardScope.cpp index 8795b4f614..8b3d33026c 100644 --- a/src/tests/libxrpl/telemetry/SpanGuardScope.cpp +++ b/src/tests/libxrpl/telemetry/SpanGuardScope.cpp @@ -15,6 +15,10 @@ // - DeterministicIdGenerator (installed by the test TracerProvider) mints a // caller-pinned trace_id for a forced-root span. PendingTraceId pins the id // for one root span; an ambient child under a live parent never adopts it. +// - addEvent records the event name and every attribute onto the exported +// span. The attribute overload copies each pair into an OTel +// key-value-iterable, so the values are read back off the exported SpanData +// rather than trusted. // // The whole file is telemetry-only: when XRPL_ENABLE_TELEMETRY is not defined // SpanGuard is a no-op stub and the OpenTelemetry SDK headers are unavailable, @@ -23,9 +27,11 @@ #ifdef XRPL_ENABLE_TELEMETRY #include +#include #include #include #include +#include #include #include @@ -37,6 +43,7 @@ #include #include #include +#include #include #include #include @@ -60,6 +67,7 @@ #include #include #include +#include #include #include @@ -265,6 +273,28 @@ countSpans( return count; } +/** + * Read one string attribute off an exported span event. + * + * Returns a sentinel instead of asserting so the caller's EXPECT_EQ prints the + * key that was wrong. + * + * @param event Exported event to read. + * @param key Attribute key to look up. + * @return The attribute's string value; "" when the key is absent, + * "" when it holds another variant alternative. + */ +std::string +eventAttribute(otel_sdk_trace::SpanDataEvent const& event, std::string_view key) +{ + auto const& attrs = event.GetAttributes(); + auto const it = attrs.find(std::string(key)); + if (it == attrs.end()) + return ""; + auto const* const value = opentelemetry::nostd::get_if(&it->second); + return value != nullptr ? *value : ""; +} + /** * Build the 16-byte deterministic trace_id used by the generator tests * (bytes 1..16). Kept out of line so every generator test pins the same id. @@ -582,6 +612,67 @@ TEST_F(SpanGuardScopeTest, activate_sets_ambient_without_owning) EXPECT_EQ(txSpan->GetSpanId(), activeId); } +// addEvent(name, attrs) on a LIVE span must reach the exporter with the event +// name and every attribute value intact. The overload rebuilds each pair into an +// OTel key-value-iterable, so a dropped or mistyped pair would be invisible +// without reading the exported event back. Values are asserted individually as +// well as by count: two attributes with one value blanked still counts as two. +TEST_F(SpanGuardScopeTest, spanGuard_addEvent_records_name_and_attribute_values) +{ + namespace cs = consensus::span; + + static constexpr std::string_view kEventName{cs::event::txIncluded}; + static constexpr std::string_view kTxIdKey{cs::attr::txId}; + static constexpr std::string_view kTxId{"6B5F1A2C3D4E5F60718293A4B5C6D7E8"}; + static constexpr std::string_view kStateKey{cs::attr::consensusState}; + static constexpr std::string_view kState{cs::val::finished}; + + { + auto guard = SpanGuard::span(TraceCategory::Consensus, seg::consensus, cs::op::acceptApply); + ASSERT_TRUE(static_cast(guard)); + guard.addEvent(kEventName, {{kTxIdKey, kTxId}, {kStateKey, kState}}); + } // guard ends the span, exporting it. + + auto spans = spanData()->GetSpans(); + auto* applySpan = findSpan(spans, cs::acceptApply); + ASSERT_NE(applySpan, nullptr); + + auto const& events = applySpan->GetEvents(); + ASSERT_EQ(events.size(), 1u); + auto const& event = events.front(); + + EXPECT_EQ(event.GetName(), std::string(kEventName)); + EXPECT_EQ(event.GetAttributes().size(), 2u); + EXPECT_EQ(event.GetDroppedAttributesCount(), 0u); + EXPECT_EQ(eventAttribute(event, kTxIdKey), std::string(kTxId)); + EXPECT_EQ(eventAttribute(event, kStateKey), std::string(kState)); +} + +// The name-only overload records the event with NO attributes, so a regression +// that leaked attributes between the two overloads shows up here rather than as +// an extra key on a production event. +TEST_F(SpanGuardScopeTest, spanGuard_addEvent_without_attributes_records_bare_event) +{ + namespace cs = consensus::span; + + static constexpr std::string_view kEventName{cs::event::phaseAccepted}; + + { + auto guard = SpanGuard::span(TraceCategory::Consensus, seg::consensus, cs::op::round); + ASSERT_TRUE(static_cast(guard)); + guard.addEvent(kEventName); + } + + auto spans = spanData()->GetSpans(); + auto* roundSpan = findSpan(spans, cs::round); + ASSERT_NE(roundSpan, nullptr); + + auto const& events = roundSpan->GetEvents(); + ASSERT_EQ(events.size(), 1u); + EXPECT_EQ(events.front().GetName(), std::string(kEventName)); + EXPECT_EQ(events.front().GetAttributes().size(), 0u); +} + // A forced-root span started while a PendingTraceId is active adopts that // pinned 16-byte trace_id and remains a true root (no parent). TEST_F(SpanGuardScopeTest, deterministicIdGenerator_forced_root_gets_pending_trace_id) diff --git a/src/tests/libxrpl/telemetry/TelemetryConfig.cpp b/src/tests/libxrpl/telemetry/TelemetryConfig.cpp index 4832326bd6..2f77770358 100644 --- a/src/tests/libxrpl/telemetry/TelemetryConfig.cpp +++ b/src/tests/libxrpl/telemetry/TelemetryConfig.cpp @@ -7,9 +7,13 @@ #include #include +#include #include +#include +#include #include #include +#include using namespace xrpl; @@ -107,6 +111,71 @@ writeCertFile(std::string const& path) } } // namespace mtls +/** + * Batch-setting keys of the [telemetry] section. + * + * Spelled once so every case below matches what the parser reads. A + * misspelling cannot hide: the accepting cases would see the default instead + * of the value they wrote, and the rejecting cases would stop rejecting. + */ +namespace key { +constexpr char const* batchSize = "batch_size"; +constexpr char const* batchDelayMs = "batch_delay_ms"; +constexpr char const* maxQueueSize = "max_queue_size"; +} // namespace key + +/** + * The upper bound quoted in the expected messages below. + * + * makeTelemetrySetup() derives it from std::uint32_t, so pin the literal to + * that type here rather than repeating an unanchored number in 5 messages. + */ +static_assert(std::numeric_limits::max() == 4294967295u); + +using KeyValue = std::pair; + +/** + * Parse a [telemetry] section holding only the given keys. + * + * A key that is not listed stays absent, so its default applies. + * + * @param values Key/value pairs to write into the section. + * @return The populated Setup struct. + */ +telemetry::Telemetry::Setup +parseBatch(std::initializer_list values) +{ + Section section; + for (auto const& [name, value] : values) + section.set(name, value); + return telemetry::makeTelemetrySetup(section, "nHUtest123", "2.0.0", 0); +} + +/** + * Parse and return the rejection message. + * + * Only std::runtime_error is caught. A boost::bad_lexical_cast escaping the + * parser derives from std::bad_cast, so it propagates and fails the test + * instead of being mistaken for a clean rejection. That is the point of the + * not-a-number cases. + * + * @param values Key/value pairs to write into the section. + * @return The exception message, or "" if the parse succeeded. + */ +std::string +batchRejection(std::initializer_list values) +{ + try + { + static_cast(parseBatch(values)); + return {}; + } + catch (std::runtime_error const& e) + { + return e.what(); + } +} + /** * Shared inputs for the metric export cadence tests of makeTelemetrySetup(). * @@ -203,6 +272,11 @@ TEST(TelemetryConfig, parse_empty_section) EXPECT_EQ(setup.serviceVersion, "2.0.0"); EXPECT_EQ(setup.serviceInstanceId, "nHUtest123"); EXPECT_DOUBLE_EQ(setup.samplingRatio, 1.0); + // An absent key takes the documented default. setup_defaults covers the + // struct's own initializers; these three cover the parser applying them. + EXPECT_EQ(setup.batchSize, 512u); + EXPECT_EQ(setup.batchDelay, std::chrono::milliseconds{5000}); + EXPECT_EQ(setup.maxQueueSize, 2048u); EXPECT_TRUE(setup.traceRpc); EXPECT_TRUE(setup.traceTransactions); EXPECT_TRUE(setup.traceConsensus); @@ -494,6 +568,127 @@ TEST(TelemetryConfig, tls_ca_cert_not_checked_when_use_tls_off) EXPECT_EQ(setup.tlsCertPath, absentCa); } +TEST(TelemetryConfig, batch_settings_accept_the_lower_bound_exactly) +{ + auto const setup = + parseBatch({{key::batchSize, "1"}, {key::batchDelayMs, "1"}, {key::maxQueueSize, "1"}}); + EXPECT_EQ(setup.batchSize, 1u); + EXPECT_EQ(setup.batchDelay, std::chrono::milliseconds{1}); + EXPECT_EQ(setup.maxQueueSize, 1u); +} + +TEST(TelemetryConfig, batch_settings_accept_the_upper_bound_exactly) +{ + auto const setup = parseBatch( + {{key::batchSize, "4294967295"}, + {key::batchDelayMs, "4294967295"}, + {key::maxQueueSize, "4294967295"}}); + EXPECT_EQ(setup.batchSize, 4294967295u); + EXPECT_EQ(setup.batchDelay, std::chrono::milliseconds{4294967295}); + EXPECT_EQ(setup.maxQueueSize, 4294967295u); +} + +TEST(TelemetryConfig, batch_size_zero_is_rejected) +{ + EXPECT_EQ( + batchRejection({{key::batchSize, "0"}}), + "Invalid value 'batch_size' in [telemetry]: must be between 1 and 4294967295."); +} + +TEST(TelemetryConfig, batch_delay_ms_zero_is_rejected) +{ + EXPECT_EQ( + batchRejection({{key::batchDelayMs, "0"}}), + "Invalid value 'batch_delay_ms' in [telemetry]: must be between 1 and 4294967295."); +} + +TEST(TelemetryConfig, max_queue_size_zero_is_rejected) +{ + EXPECT_EQ( + batchRejection({{key::maxQueueSize, "0"}}), + "Invalid value 'max_queue_size' in [telemetry]: must be between 1 and 4294967295."); +} + +TEST(TelemetryConfig, batch_size_not_a_number_is_rejected_as_runtime_error) +{ + // Section::get() reaches boost::lexical_cast, which throws a std::bad_cast. + // Catching only std::runtime_error is the point: this fails unless the + // parser turned that into a message naming the key. + EXPECT_EQ( + batchRejection({{key::batchSize, "abc"}}), + "Invalid value 'batch_size' in [telemetry]: must be a whole number."); +} + +TEST(TelemetryConfig, batch_delay_ms_not_a_number_is_rejected_as_runtime_error) +{ + EXPECT_EQ( + batchRejection({{key::batchDelayMs, "abc"}}), + "Invalid value 'batch_delay_ms' in [telemetry]: must be a whole number."); +} + +TEST(TelemetryConfig, max_queue_size_not_a_number_is_rejected_as_runtime_error) +{ + EXPECT_EQ( + batchRejection({{key::maxQueueSize, "abc"}}), + "Invalid value 'max_queue_size' in [telemetry]: must be a whole number."); +} + +TEST(TelemetryConfig, batch_size_fractional_is_rejected) +{ + // A batch counts spans, so "512.5" must not silently truncate to 512. + EXPECT_EQ( + batchRejection({{key::batchSize, "512.5"}}), + "Invalid value 'batch_size' in [telemetry]: must be a whole number."); +} + +TEST(TelemetryConfig, batch_settings_reject_negative_rather_than_wrapping) +{ + // boost::lexical_cast to an unsigned type turns "-1" into 4294967295 + // instead of failing, so a negative must land on the range check. + EXPECT_EQ( + batchRejection({{key::batchSize, "-1"}}), + "Invalid value 'batch_size' in [telemetry]: must be between 1 and 4294967295."); + EXPECT_EQ( + batchRejection({{key::batchDelayMs, "-1"}}), + "Invalid value 'batch_delay_ms' in [telemetry]: must be between 1 and 4294967295."); + EXPECT_EQ( + batchRejection({{key::maxQueueSize, "-1"}}), + "Invalid value 'max_queue_size' in [telemetry]: must be between 1 and 4294967295."); +} + +TEST(TelemetryConfig, max_queue_size_above_the_upper_bound_is_rejected) +{ + EXPECT_EQ( + batchRejection({{key::maxQueueSize, "4294967296"}}), + "Invalid value 'max_queue_size' in [telemetry]: must be between 1 and 4294967295."); +} + +TEST(TelemetryConfig, batch_size_above_max_queue_size_is_rejected) +{ + // The OTel SDK documents max_export_batch_size <= max_queue_size as a + // precondition and does not enforce it, so the parser must. + EXPECT_EQ( + batchRejection({{key::batchSize, "600"}, {key::maxQueueSize, "512"}}), + "Invalid value 'batch_size' in [telemetry]: must not exceed 'max_queue_size' (512)."); +} + +TEST(TelemetryConfig, batch_size_above_a_lowered_max_queue_size_is_rejected) +{ + // The likely operator mistake: lowering only max_queue_size and leaving + // batch_size at its 512 default. + EXPECT_EQ( + batchRejection({{key::maxQueueSize, "256"}}), + "Invalid value 'batch_size' in [telemetry]: must not exceed 'max_queue_size' (256)."); +} + +TEST(TelemetryConfig, batch_size_equal_to_max_queue_size_is_accepted) +{ + // The cross-check rejects only batchSize > maxQueueSize, so equal passes. + auto const setup = parseBatch({{key::batchSize, "512"}, {key::maxQueueSize, "512"}}); + EXPECT_EQ(setup.batchSize, 512u); + EXPECT_EQ(setup.maxQueueSize, 512u); +} + TEST(TelemetryConfig, metric_cadence_defaults_when_absent) { // Neither key set, so both must land on the constants Telemetry.h declares. diff --git a/src/tests/libxrpl/telemetry/ValidationTracker.cpp b/src/tests/libxrpl/telemetry/ValidationTracker.cpp index d8bce6cccc..69a7ed5312 100644 --- a/src/tests/libxrpl/telemetry/ValidationTracker.cpp +++ b/src/tests/libxrpl/telemetry/ValidationTracker.cpp @@ -290,6 +290,77 @@ TEST_F(ValidationTrackerTest, OnlyWeValidated) EXPECT_DOUBLE_EQ(tracker_.agreementPct1h(), 0.0); } +// --------------------------------------------------------------- +// 10. A counted ledger is never counted twice +// reconcile() drops the oldest reconciled events once the +// pending map passes kMaxPendingEvents. A validation arriving +// for one of those ledgers afterwards must not reach the +// agreement or missed totals a second time. +// +// Two hashes are made the oldest so the trim drops both: +// - evictedMiss (network only) reconciles as a miss. Our late +// validation cannot repair an entry the trim dropped, so +// totalMissed staying at 1 proves the trim really dropped +// it. A fixture where the trim did not run would repair it +// and report 0 misses. +// - evictedAgreed (both sides) reconciles as an agreement. +// Re-recording both sides is what double-counts an +// agreement. +// --------------------------------------------------------------- +TEST_F(ValidationTrackerTest, CountedLedgerNotCountedTwice) +{ + // The trim drops the oldest reconciled entries first. Each pause makes + // the next record time strictly larger, so these two are the oldest. + auto const evictedMiss = makeHash(1); + tracker_.recordNetworkValidation(evictedMiss, 1); + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + + auto const evictedAgreed = makeHash(2); + tracker_.recordOurValidation(evictedAgreed, 2); + tracker_.recordNetworkValidation(evictedAgreed, 2); + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + + // Fill to three over the bound so the trim drops three entries: the two + // above plus one filler. + constexpr std::size_t kFill = ValidationTracker::kMaxPendingEvents + 1; + for (std::size_t i = 0; i < kFill; ++i) + { + auto const hash = makeHash(i + 3); + auto const seq = static_cast(i + 3); + tracker_.recordOurValidation(hash, seq); + tracker_.recordNetworkValidation(hash, seq); + } + + std::this_thread::sleep_for(std::chrono::seconds(9)); + tracker_.reconcile(); + + // Every filler plus evictedAgreed agrees; evictedMiss is the one miss. + EXPECT_EQ(tracker_.totalAgreements(), kFill + 1); + EXPECT_EQ(tracker_.totalMissed(), 1u); + EXPECT_EQ(tracker_.agreements1h(), kFill + 1); + EXPECT_EQ(tracker_.missed1h(), 1u); + + // Validations arrive again for the two dropped ledgers. + tracker_.recordOurValidation(evictedMiss, 1); + tracker_.recordOurValidation(evictedAgreed, 2); + tracker_.recordNetworkValidation(evictedAgreed, 2); + + // Long enough for a re-created pending entry to pass the grace period. + std::this_thread::sleep_for(std::chrono::seconds(9)); + tracker_.reconcile(); + + // Both ledgers were already counted, so every total is unchanged. + EXPECT_EQ(tracker_.totalAgreements(), kFill + 1); + EXPECT_EQ(tracker_.totalMissed(), 1u); + EXPECT_EQ(tracker_.agreements1h(), kFill + 1); + EXPECT_EQ(tracker_.missed1h(), 1u); + + // The send and check counters count messages, not ledgers, so the + // repeated validations do count towards them. + EXPECT_EQ(tracker_.totalValidationsSent(), kFill + 3); + EXPECT_EQ(tracker_.totalValidationsChecked(), kFill + 3); +} + // --------------------------------------------------------------- // 10. Gross miss tally is monotonic across a late repair // The gross lifetime tallies (totalAgreementsEver/totalMissedEver) diff --git a/src/xrpld/app/consensus/RCLConsensus.cpp b/src/xrpld/app/consensus/RCLConsensus.cpp index 2841d72ed4..16d53e6e1f 100644 --- a/src/xrpld/app/consensus/RCLConsensus.cpp +++ b/src/xrpld/app/consensus/RCLConsensus.cpp @@ -1168,6 +1168,14 @@ RCLConsensus::Adaptor::onModeChange(ConsensusMode before, ConsensusMode after) censorshipDetector_.reset(); mode_ = after; + + // consensus.round is created before the engine applies the mode, so this is + // the first point where the round's mode is known. Every mode transition, + // including the one at round start, reaches here. + if (roundSpan_ && *roundSpan_) + { + roundSpan_->setAttribute(cs::attr::mode, toDisplayString(after).c_str()); + } } json::Value @@ -1397,7 +1405,6 @@ RCLConsensus::Adaptor::startRoundTracing(RCLCxLedger const& prevLgr) roundSpan_->setAttribute(cs::attr::ledgerId, to_string(prevLgr.id()).c_str()); roundSpan_->setAttribute(cs::attr::ledgerSeq, static_cast(prevLgr.seq()) + 1); - roundSpan_->setAttribute(cs::attr::mode, toDisplayString(mode_.load()).c_str()); roundSpan_->setAttribute(cs::attr::traceStrategy, strategy.c_str()); roundSpan_->setAttribute(cs::attr::roundId, static_cast(prevLgr.seq()) + 1); roundSpan_->setAttribute(cs::attr::previousLedgerSeq, static_cast(prevLgr.seq())); @@ -1406,6 +1413,10 @@ RCLConsensus::Adaptor::startRoundTracing(RCLCxLedger const& prevLgr) cs::attr::previousRoundTimeMs, static_cast(prevRoundTime_.load().count())); roundSpan_->setAttribute(cs::attr::consensusPhase, cs::val::phaseOpen); + // consensus_mode is stamped by onModeChange, which the engine calls just + // after this with the mode it is applying. Setting it here would record the + // previous round's mode. + roundSpan_->addEvent(cs::event::phaseOpen); // roundSpanContext_ is the durable handle that child spans on other diff --git a/src/xrpld/app/misc/detail/TxQ.cpp b/src/xrpld/app/misc/detail/TxQ.cpp index cd415112a8..97bfe3be7c 100644 --- a/src/xrpld/app/misc/detail/TxQ.cpp +++ b/src/xrpld/app/misc/detail/TxQ.cpp @@ -802,7 +802,16 @@ TxQ::apply( // into the ledger. if (auto directApplied = tryDirectApply(app, view, tx, flags, j)) { - span.setAttribute(txq_span::attr::txqStatus, txq_span::val::appliedDirect); + // A result comes back even when the apply failed, so branch on the outcome. + // transToken() builds a string, so the whole block is guarded. + if (span) + { + span.setAttribute(txq_span::attr::terCode, transToken(directApplied->ter).c_str()); + if (directApplied->applied) + span.setAttribute(txq_span::attr::txqStatus, txq_span::val::appliedDirect); + else + span.setAttribute(txq_span::attr::txqStatus, txq_span::val::failed); + } return *directApplied; } diff --git a/src/xrpld/rpc/detail/PathRequest.cpp b/src/xrpld/rpc/detail/PathRequest.cpp index 1154109fc9..b61bf1edee 100644 --- a/src/xrpld/rpc/detail/PathRequest.cpp +++ b/src/xrpld/rpc/detail/PathRequest.cpp @@ -1,3 +1,7 @@ +// cspell:ignore ISTOGRAM +// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's +// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. + #include #include @@ -8,6 +12,7 @@ #include #include #include +#include #include #include @@ -50,6 +55,14 @@ #include #include +// The path-count metric name and description. Both are only ever used inside an +// XRPL_METRIC_* argument list, and those macros expand to nothing when +// telemetry is off, so the include is guarded like its uses -- clang-tidy's +// misc-include-cleaner rejects an include nothing references. +#ifdef XRPL_ENABLE_TELEMETRY +#include +#endif // XRPL_ENABLE_TELEMETRY + namespace xrpl { PathRequest::PathRequest( @@ -745,6 +758,12 @@ PathRequest::findPaths( #ifdef XRPL_ENABLE_TELEMETRY span.setAttribute(pathfind_span::attr::numPaths, totalPaths); + // The attribute answers "how many paths did THIS pass find" on one sampled + // trace. The histogram answers "how many paths do passes find" across all + // of them, which no attribute can, since an unsampled trace is never read. + // Inside the guard because totalPaths only exists when telemetry is built. + XRPL_METRIC_HISTOGRAM_RECORD( + app_, kPathfindDiscoveredPaths, kPathfindDiscoveredPathsDesc, totalPaths); #endif /* The resource fee is based on the number of source currencies used. diff --git a/src/xrpld/rpc/detail/RPCHandler.cpp b/src/xrpld/rpc/detail/RPCHandler.cpp index e3400b746f..317adee22a 100644 --- a/src/xrpld/rpc/detail/RPCHandler.cpp +++ b/src/xrpld/rpc/detail/RPCHandler.cpp @@ -164,8 +164,10 @@ callMethod(JsonContext& context, Method method, std::string const& name, Object& { // Scoped so this command nests under rpc.process and becomes the ambient // parent of any command-internal spans (e.g. pathfind.request). Coro-aware - // storage keeps the scope correct across doRipplePathFind's yield. - auto span = ScopedSpanGuard(TraceCategory::Rpc, rpc_span::prefix::command, name); + // storage keeps the scope correct across doRipplePathFind's yield. Internal + // rather than Server: the inbound boundary is above rpc.process. + auto span = + ScopedSpanGuard(TraceCategory::Rpc, rpc_span::prefix::command, name, SpanRole::Internal); span.setAttribute(rpc_span::attr::command, name.c_str()); span.setAttribute(rpc_span::attr::version, static_cast(context.apiVersion)); span.setAttribute( @@ -283,7 +285,9 @@ doCommand(rpc::JsonContext& context, json::Value& result) // registered handler names (plus "unknown") — see the helper for why // raw request input must not reach the telemetry pipeline. auto const cmdName = resolveCommandSpanName(context); - auto span = ScopedSpanGuard(TraceCategory::Rpc, rpc_span::prefix::command, cmdName); + // Internal for the same reason as the success path above. + auto span = ScopedSpanGuard( + TraceCategory::Rpc, rpc_span::prefix::command, cmdName, SpanRole::Internal); span.setAttribute(rpc_span::attr::command, cmdName); // Mirror the attribute set callMethod() puts on a successful command // span, so error spans stay filterable by API version and role. diff --git a/src/xrpld/rpc/detail/ServerHandler.cpp b/src/xrpld/rpc/detail/ServerHandler.cpp index 3c797d3fcb..9730e4519f 100644 --- a/src/xrpld/rpc/detail/ServerHandler.cpp +++ b/src/xrpld/rpc/detail/ServerHandler.cpp @@ -1,3 +1,7 @@ +// cspell:ignore ISTOGRAM +// The all-caps macro name XRPL_METRIC_HISTOGRAM_RECORD trips cspell's +// compound-word splitter, which emits the subword "ISTOGRAM"; ignore it here. + #include #include @@ -10,6 +14,7 @@ #include #include #include // IWYU pragma: keep +#include #include #include @@ -77,6 +82,14 @@ #include #include +// The batch-size metric name and description. Both are only ever used inside an +// XRPL_METRIC_* argument list, and those macros expand to nothing when +// telemetry is off, so the include is guarded like its uses -- clang-tidy's +// misc-include-cleaner rejects an include nothing references. +#ifdef XRPL_ENABLE_TELEMETRY +#include +#endif // XRPL_ENABLE_TELEMETRY + namespace xrpl { using namespace telemetry; @@ -715,7 +728,9 @@ ServerHandler::processRequest( // yield in doRipplePathFind: the coro-aware context storage moves this // scope with the coroutine on resume (it is never stranded on a worker's // thread-local stack), so nesting and log-trace correlation both hold. - auto span = ScopedSpanGuard(TraceCategory::Rpc, rpc_span::prefix::rpc, rpc_span::op::process); + // Internal, not Server: the inbound boundary is rpc.http_request above. + auto span = ScopedSpanGuard( + TraceCategory::Rpc, rpc_span::prefix::rpc, rpc_span::op::process, SpanRole::Internal); auto rpcJ = app_.getJournal("RPC"); // Tracks whether any failure occurred. Set on every error path (early @@ -760,7 +775,14 @@ ServerHandler::processRequest( } span.setAttribute(rpc_span::attr::isBatch, batch); if (batch) + { span.setAttribute(rpc_span::attr::batchSize, static_cast(size)); + // The attribute answers "how big was THIS batch" on one sampled trace. + // The histogram answers "how big are batches" across all of them, which + // no attribute can, since an unsampled trace is never read. + XRPL_METRIC_HISTOGRAM_RECORD( + app_, telemetry::kRpcBatchSize, telemetry::kRpcBatchSizeDesc, size); + } json::Value reply(batch ? json::ValueType::Array : json::ValueType::Object); diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index a3e706a73c..f335e26925 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -68,6 +68,7 @@ #include #include #include +#include #include // For networkTypeFromId(), the one xrpl.network.type mapping both export // paths use. Adds no levelization edge: xrpld.telemetry > xrpl.telemetry @@ -335,6 +336,22 @@ MetricsRegistry::initExporterAndProvider(StartOptions const& options) // so a dashboard can show how close charges run to each. addHistogramView(*views, kGetObjectCharge, buckets::toVector(buckets::kChargeBuckets)); + // The two RPC request-count histograms are recorded at their ServerHandler + // and PathRequest call sites, so the names come from the shared constants + // all three sites use. Both are small counts, and the reason they need a + // view is the FLOOR rather than the ceiling: the SDK default edges start + // 0, 5, 10, 25, so a batch of one to five sub-requests -- the normal case -- + // would land in a single bucket and every quantile over it would be an + // interpolation inside that bucket rather than a measurement. + // + // The object-count ladder is the fit: its 1, 2, 4, 8, 16 edges sit exactly + // where both distributions have their mass. Path counts are hard-bounded at + // kMaxPaths * kMaxAutoSrcCur = 352, well under its 12288 top. Batch sizes + // have no such cap; see the ceiling note in RpcMetricNames.h. + addHistogramView(*views, kRpcBatchSize, buckets::toVector(buckets::kObjectCountBuckets)); + addHistogramView( + *views, kPathfindDiscoveredPaths, buckets::toVector(buckets::kObjectCountBuckets)); + // Create MeterProvider with resource, then attach the metric reader. provider_ = metric_sdk::MeterProviderFactory::Create(std::move(views), resourceAttrs); provider_->AddMetricReader(std::move(reader)); diff --git a/src/xrpld/telemetry/ValidationTracker.h b/src/xrpld/telemetry/ValidationTracker.h index a5b048780e..8cdde51da3 100644 --- a/src/xrpld/telemetry/ValidationTracker.h +++ b/src/xrpld/telemetry/ValidationTracker.h @@ -47,6 +47,7 @@ namespace xrpl::telemetry { * | ValidationTracker | * |---------------------------| * | pending_ (hash_map) |----> LedgerEvent per hash + * | tallied_ (hash_set) |----> hashes already counted * | window1h_ (deque) |----> WindowEvent sliding window * | window24h_ (deque) |----> WindowEvent sliding window * | atomic totals | @@ -104,6 +105,13 @@ public: */ using TimePoint = Clock::time_point; + /** + * Maximum number of pending (unreconciled + recently reconciled) events. + * Once the pending map passes this size, reconcile() drops the oldest + * reconciled events. Public so a test can size a fixture against it. + */ + static constexpr std::size_t kMaxPendingEvents = 1000; + /** * Record that this node sent a validation for the given ledger. * @param ledgerHash Hash of the ledger we validated. @@ -302,9 +310,12 @@ private: static constexpr auto kLateRepairWindow = std::chrono::minutes(5); /** - * Maximum number of pending (unreconciled + recently reconciled) events. + * Maximum number of ledger hashes remembered as already counted. + * At one ledger every four seconds this spans about eleven hours. + * A validation arriving for a ledger counted before that is counted + * again. */ - static constexpr std::size_t kMaxPendingEvents = 1000; + static constexpr std::size_t kMaxTalliedEvents = 10000; /** * Duration of the short rolling window. @@ -322,7 +333,8 @@ private: static constexpr auto kWindow7d = std::chrono::hours(168); /** - * Protects pending_, window1h_, window24h_, and window7d_. + * Protects pending_, tallied_, talliedOrder_, window1h_, window24h_, + * and window7d_. */ mutable std::mutex mutex_; @@ -331,6 +343,19 @@ private: */ hash_map pending_; + /** + * Ledger hashes already counted into the agreement and missed totals. + * Membership survives eviction from pending_, so a ledger reaches the + * totals once. Holds at most kMaxTalliedEvents hashes. + */ + hash_set tallied_; + + /** + * The hashes in tallied_ in the order they were counted. The front is + * the oldest and is dropped first once the bound is reached. + */ + std::deque talliedOrder_; + /** * Sliding window of reconciled events (last 1 hour). */ @@ -393,6 +418,27 @@ private: */ std::atomic totalValidationsChecked_{0}; + /** + * Locate the pending event for a ledger, creating it on first sight. + * @param ledgerHash Hash of the ledger being recorded. + * @param seq Ledger sequence number, stored only on creation. + * @return Pointer to the event, or nullptr for a ledger that already + * reached the totals and left pending_. The caller records nothing in + * that case. + * @note Called with mutex_ held. + */ + [[nodiscard]] LedgerEvent* + pendingEvent(uint256 const& ledgerHash, LedgerIndex seq); + + /** + * Remember a ledger hash as counted, dropping the oldest remembered + * hash once kMaxTalliedEvents is reached. + * @param ledgerHash Hash of the ledger just counted into the totals. + * @note Called with mutex_ held. + */ + void + noteTallied(uint256 const& ledgerHash); + /** * Remove entries older than their respective window durations. * @param now Current time point. diff --git a/src/xrpld/telemetry/detail/ValidationTracker.cpp b/src/xrpld/telemetry/detail/ValidationTracker.cpp index d718f0027e..36c0a778df 100644 --- a/src/xrpld/telemetry/detail/ValidationTracker.cpp +++ b/src/xrpld/telemetry/detail/ValidationTracker.cpp @@ -18,20 +18,49 @@ namespace xrpl::telemetry { +ValidationTracker::LedgerEvent* +ValidationTracker::pendingEvent(uint256 const& ledgerHash, LedgerIndex seq) +{ + if (auto const it = pending_.find(ledgerHash); it != pending_.end()) + return &it->second; + + // A hash in tallied_ already reached the totals and left pending_. + // Building a fresh record for it would count the same ledger twice. + if (tallied_.contains(ledgerHash)) + return nullptr; + + auto& evt = pending_[ledgerHash]; + evt.ledgerHash = ledgerHash; + evt.seq = seq; + evt.recordTime = Clock::now(); + return &evt; +} + +void +ValidationTracker::noteTallied(uint256 const& ledgerHash) +{ + if (!tallied_.insert(ledgerHash).second) + return; + + talliedOrder_.push_back(ledgerHash); + while (talliedOrder_.size() > kMaxTalliedEvents) + { + tallied_.erase(talliedOrder_.front()); + talliedOrder_.pop_front(); + } +} + void ValidationTracker::recordOurValidation(uint256 const& ledgerHash, LedgerIndex seq) { std::scoped_lock const lock(mutex_); - auto& evt = pending_[ledgerHash]; - if (evt.recordTime == TimePoint{}) - { - // First time seeing this ledger hash -- initialize. - evt.ledgerHash = ledgerHash; - evt.seq = seq; - evt.recordTime = Clock::now(); - } - evt.weValidated = true; totalValidationsSent_.fetch_add(1, std::memory_order_relaxed); + + // The counter above counts messages, so it also counts a ledger that is + // already tallied. Only the per-ledger record is skipped. + if (auto* const evt = pendingEvent(ledgerHash, seq)) + evt->weValidated = true; + boundPending(ledgerHash); } @@ -39,15 +68,11 @@ void ValidationTracker::recordNetworkValidation(uint256 const& ledgerHash, LedgerIndex seq) { std::scoped_lock const lock(mutex_); - auto& evt = pending_[ledgerHash]; - if (evt.recordTime == TimePoint{}) - { - evt.ledgerHash = ledgerHash; - evt.seq = seq; - evt.recordTime = Clock::now(); - } - evt.networkValidated = true; totalValidationsChecked_.fetch_add(1, std::memory_order_relaxed); + + if (auto* const evt = pendingEvent(ledgerHash, seq)) + evt->networkValidated = true; + boundPending(ledgerHash); } @@ -106,6 +131,12 @@ ValidationTracker::boundPending(uint256 const& justRecorded) if (!oldest->second.reconciled) classifyPending(oldest->second, Clock::now()); + // The entry has now reached the totals and is about to leave pending_, so + // remember it as counted. Without this a later validation for the same + // ledger would build a fresh record that reconcile() would count a second + // time. + noteTallied(oldest->first); + pending_.erase(oldest); } @@ -130,6 +161,7 @@ ValidationTracker::reconcile() // moved once, here, at first classification -- see the // counting-decision note in the repair branch below. classifyPending(evt, now); + noteTallied(hash); } else if ( evt.reconciled && !evt.agreed && evt.weValidated && evt.networkValidated &&