diff --git a/.github/scripts/otel-naming/test_check_otel_naming.py b/.github/scripts/otel-naming/test_check_otel_naming.py index c5de49f073..2bcfd16ec4 100644 --- a/.github/scripts/otel-naming/test_check_otel_naming.py +++ b/.github/scripts/otel-naming/test_check_otel_naming.py @@ -1340,28 +1340,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. @@ -1374,7 +1400,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 2e22fe222a..7a95ca7a83 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/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/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/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/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/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 38dddb1850..9730e4519f 100644 --- a/src/xrpld/rpc/detail/ServerHandler.cpp +++ b/src/xrpld/rpc/detail/ServerHandler.cpp @@ -728,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 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 &&