diff --git a/.cspell.config.yaml b/.cspell.config.yaml index d8679b0a89..f8781dc990 100644 --- a/.cspell.config.yaml +++ b/.cspell.config.yaml @@ -341,6 +341,7 @@ words: - txns - txqueue - txs + - txset - ubsan - UBSAN - ufdio diff --git a/src/tests/libxrpl/telemetry/LedgerSpanNames.cpp b/src/tests/libxrpl/telemetry/LedgerSpanNames.cpp index f1b20c3e43..635476682b 100644 --- a/src/tests/libxrpl/telemetry/LedgerSpanNames.cpp +++ b/src/tests/libxrpl/telemetry/LedgerSpanNames.cpp @@ -1,6 +1,9 @@ /** * @file LedgerSpanNames.cpp - * Unit tests for the ledger.acquire span contract in LedgerSpanNames.h. + * Unit tests for the sync-diagnostic span contracts in LedgerSpanNames.h and + * PeerSpanNames.h: `ledger.acquire` and, in the WP-B2 block at the end of this + * file, `txset.acquire`, the three `ledger.acquire.{header,astree,txtree}` + * phase children, `ledger.serve` and `peer.dial`. * * Two things are pinned here: * @@ -22,22 +25,34 @@ * InboundLedger, so it is asserted directly here: no Application, no peer * set, and no test-only hook added to production code to reach it. * + * The WP-B2 spans follow the same two rules, with three more pure functions + * standing in for their emitters' exits: `phaseOutcome()` for the acquire + * phases and tx-set fetch, and `serveObjectType()` / `serveOutcome()` for the + * eight exits of PeerImp::processLedgerRequest. Every one is asserted over its + * whole input domain, which is what proves no exit can leave a span without an + * outcome -- the property the emitters rely on and that no compiler enforces. + * * Compiled only when XRPL_ENABLE_TELEMETRY is defined, because that is the * configuration in which this test target has `src/` on its include path and - * can therefore reach . The header itself is not - * telemetry-conditional (constants and one constexpr function, no OTel types); - * only this file's ability to include it is. + * can therefore reach and + * . Neither header is telemetry-conditional + * (constants and constexpr functions, no OTel types); only this file's ability + * to include them is. */ #ifdef XRPL_ENABLE_TELEMETRY #include +#include + #include #include #include +#include +#include #include #include #include @@ -224,6 +239,434 @@ TEST(LedgerSpanNames, inactive_guard_finalize_sequence_is_a_no_op) EXPECT_FALSE(empty.has_value()); } +// =========================================================================== +// WP-B2 — the new sync-diagnostic spans +// +// Same contract as the ledger.acquire block above and asserted the same way: +// the wire names and attribute keys are pinned literally because they are a +// cross-component contract (the collector aggregates on them, Tempo indexes +// them, expected_spans.json asserts them by name, and a dashboard PromQL +// selector matches them -- a rename would break all four with no compile +// error), and the outcome rules are pinned over their whole input domain +// because they are what guarantees every exit path of every new span records +// an outcome. +// =========================================================================== + +TEST(LedgerSpanNames, txset_acquire_span_name_is_dot_qualified) +{ + // TransactionAcquire::init builds the name as prefix::txset + "." + + // op::acquire. A tx set is not a ledger, so it gets its own root segment + // rather than hiding under `ledger.` -- assert both halves so the composed + // "txset.acquire" cannot drift from what the dashboard queries. + EXPECT_EQ(std::string_view(ledger_span::prefix::txset), "txset"); + EXPECT_EQ(std::string_view(ledger_span::op::acquire), "acquire"); +} + +TEST(LedgerSpanNames, phase_child_span_names_are_fully_composed) +{ + // These are used with childSpan(name, ctx), which takes ONE complete name, + // so unlike the parent they are pre-joined here. Assert the exact composed + // strings: they are what the phase-duration panel selects on and what + // expected_spans.json lists. + EXPECT_EQ(std::string_view(ledger_span::acquireHeader), "ledger.acquire.header"); + EXPECT_EQ(std::string_view(ledger_span::acquireAsTree), "ledger.acquire.astree"); + EXPECT_EQ(std::string_view(ledger_span::acquireTxTree), "ledger.acquire.txtree"); +} + +TEST(LedgerSpanNames, phase_child_span_names_are_children_of_the_acquire_name) +{ + // The naming property, not just the spelling: each phase name must extend + // the parent's "ledger.acquire" exactly, because that shared prefix is what + // the panel's span_name=~"ledger.acquire..*" selector relies on to pick up + // all three phases and no other span. + auto const parent = std::string_view("ledger.acquire"); + for (std::string_view const phase : + {std::string_view(ledger_span::acquireHeader), + std::string_view(ledger_span::acquireAsTree), + std::string_view(ledger_span::acquireTxTree)}) + { + EXPECT_TRUE(phase.starts_with(parent)) << "phase not under the parent name: " << phase; + // A '.' immediately after the parent, and a non-empty leaf after that. + ASSERT_GT(phase.size(), parent.size() + 1); + EXPECT_EQ(phase[parent.size()], '.'); + EXPECT_FALSE(phase.substr(parent.size() + 1).empty()); + // The leaf must be one segment: a further dot would make the panel's + // selector pick up a grandchild that does not exist. + EXPECT_EQ(phase.substr(parent.size() + 1).find('.'), std::string_view::npos); + } +} + +TEST(LedgerSpanNames, phase_child_span_names_are_mutually_distinct) +{ + // Cause, not just state: the duration panel plots one series per phase, so + // two phases sharing a name would silently merge the account-state tree + // (nearly all of a fresh sync) into another phase's line. + EXPECT_NE( + std::string_view(ledger_span::acquireHeader), std::string_view(ledger_span::acquireAsTree)); + EXPECT_NE( + std::string_view(ledger_span::acquireHeader), std::string_view(ledger_span::acquireTxTree)); + EXPECT_NE( + std::string_view(ledger_span::acquireAsTree), std::string_view(ledger_span::acquireTxTree)); +} + +TEST(LedgerSpanNames, serve_span_name_is_dot_qualified) +{ + EXPECT_EQ(std::string_view(seg::ledger), "ledger"); + EXPECT_EQ(std::string_view(ledger_span::op::serve), "serve"); +} + +TEST(LedgerSpanNames, b2_attribute_keys_match_collector_and_tempo) +{ + // `timed_out` and `object_type` are the two NEW spanmetrics dimensions + // listed in BOTH collector configs; the rest are span-only. + EXPECT_EQ(std::string_view(ledger_span::attr::timedOut), "timed_out"); + EXPECT_EQ(std::string_view(ledger_span::attr::objectType), "object_type"); + // Span-only, asserted by expected_spans.json. txset_hash is additionally a + // dedicated Parquet span column in tempo.yaml, for the same per-object + // reason ledger_hash is: it identifies WHICH set stalled, and as a metric + // dimension it would mint one series per consensus round. + EXPECT_EQ(std::string_view(ledger_span::attr::txSetHash), "txset_hash"); + EXPECT_EQ(std::string_view(ledger_span::attr::missingNodes), "missing_nodes"); + EXPECT_EQ(std::string_view(ledger_span::attr::servedNodes), "served_nodes"); + EXPECT_EQ(std::string_view(ledger_span::attr::durationMs), "duration_ms"); +} + +TEST(LedgerSpanNames, b2_attribute_keys_are_bare_underscore_never_dotted) +{ + // The naming spec reserves dotted keys for resource attributes; a dotted + // span-attribute key fails the CI naming check. Assert the property so a + // key added to this group later is covered too. + for (std::string_view const key : + {std::string_view(ledger_span::attr::timedOut), + std::string_view(ledger_span::attr::objectType), + std::string_view(ledger_span::attr::txSetHash), + std::string_view(ledger_span::attr::missingNodes), + std::string_view(ledger_span::attr::servedNodes), + std::string_view(ledger_span::attr::durationMs)}) + { + EXPECT_EQ(key.find('.'), std::string_view::npos) << "dotted span-attr key: " << key; + EXPECT_FALSE(key.empty()); + } +} + +TEST(LedgerSpanNames, timeout_outcome_value_is_distinct_from_the_other_three) +{ + // `timeout` is the value WP-B2 adds to the outcome set the collector + // aggregates. It must be distinct from all three existing values, because + // the whole point is separating "peers never supplied the data" from + // "the data was bad" (failed) and "we stopped waiting" (abandoned). + EXPECT_EQ(std::string_view(ledger_span::val::timeout), "timeout"); + EXPECT_NE( + std::string_view(ledger_span::val::timeout), std::string_view(ledger_span::val::failed)); + EXPECT_NE( + std::string_view(ledger_span::val::timeout), std::string_view(ledger_span::val::complete)); + EXPECT_NE( + std::string_view(ledger_span::val::timeout), std::string_view(ledger_span::val::abandoned)); +} + +TEST(LedgerSpanNames, serve_object_type_values_are_the_four_request_kinds) +{ + // These become the `object_type` dimension's value set (cardinality 4), + // which is what makes it safe as a metric dimension. + EXPECT_EQ(std::string_view(ledger_span::val::header), "header"); + EXPECT_EQ(std::string_view(ledger_span::val::txTree), "tx"); + EXPECT_EQ(std::string_view(ledger_span::val::asTree), "as"); + EXPECT_EQ(std::string_view(ledger_span::val::txSet), "txset"); +} + +TEST(LedgerSpanNames, serve_outcome_values_are_the_three_terminal_states) +{ + // `complete` is shared with the acquire outcomes (same concept, told apart + // by span name); `partial` and `refused` are serve-specific. + EXPECT_EQ(std::string_view(ledger_span::val::partial), "partial"); + EXPECT_EQ(std::string_view(ledger_span::val::refused), "refused"); + EXPECT_NE( + std::string_view(ledger_span::val::partial), std::string_view(ledger_span::val::refused)); + EXPECT_NE( + std::string_view(ledger_span::val::partial), std::string_view(ledger_span::val::complete)); + EXPECT_NE( + std::string_view(ledger_span::val::refused), std::string_view(ledger_span::val::complete)); +} + +TEST(LedgerSpanNames, phaseOutcome_normal_completion_is_complete) +{ + // A phase whose tree assembled, or a tx set that arrived: complete_ set, + // nothing else. Reached from receiveNode()/trigger() for a phase and from + // done() for a tx set. + EXPECT_EQ( + ledger_span::phaseOutcome(/*failed=*/false, /*complete=*/true, /*timedOut=*/false), + "complete"); +} + +TEST(LedgerSpanNames, phaseOutcome_bad_data_is_failed) +{ + // A terminal data fault with no timeout: a peer served a tree or set that + // would not build. This is the case `timeout` must NOT absorb. + EXPECT_EQ( + ledger_span::phaseOutcome(/*failed=*/true, /*complete=*/false, /*timedOut=*/false), + "failed"); +} + +TEST(LedgerSpanNames, phaseOutcome_exhausted_budget_reports_timeout_not_failed) +{ + // THE assertion this rule exists for, and the one that would regress + // silently. Both emitters' exhausted-budget path sets timedOut_ AND + // failed_ -- failed_ is how the TimeoutCounter base stops its timer loop -- + // so if `failed` were checked first, every timeout would be relabelled as a + // data fault and the "peers are not serving this" signal would vanish + // exactly when a node is stuck. + EXPECT_EQ( + ledger_span::phaseOutcome(/*failed=*/true, /*complete=*/false, /*timedOut=*/true), + "timeout"); +} + +TEST(LedgerSpanNames, phaseOutcome_timeout_outranks_a_late_completion) +{ + // Edge case: the budget expired and the data then arrived. It still reports + // `timeout`, because the retry budget was really spent -- counting it as a + // success would hide the cost. + EXPECT_EQ( + ledger_span::phaseOutcome(/*failed=*/false, /*complete=*/true, /*timedOut=*/true), + "timeout"); +} + +TEST(LedgerSpanNames, phaseOutcome_dropped_mid_fetch_is_abandoned) +{ + // No flag at all: the object was destroyed while still fetching (the + // InboundLedger sweep, or InboundTransactions::newRound dropping a set). + // Reporting a value here is what keeps a stuck-then-swept unit in the + // outcome rate instead of vanishing from it. + EXPECT_EQ( + ledger_span::phaseOutcome(/*failed=*/false, /*complete=*/false, /*timedOut=*/false), + "abandoned"); +} + +TEST(LedgerSpanNames, phaseOutcome_covers_its_whole_input_domain) +{ + // No input combination yields an empty or undeclared value, which is the + // property that guarantees no exit can end up with a blank outcome and that + // the spanmetrics dimension can never gain an unexpected fifth value. + for (bool const failed : {false, true}) + { + for (bool const complete : {false, true}) + { + for (bool const timedOut : {false, true}) + { + auto const outcome = ledger_span::phaseOutcome(failed, complete, timedOut); + EXPECT_FALSE(outcome.empty()) + << "failed=" << failed << " complete=" << complete << " timedOut=" << timedOut; + EXPECT_TRUE( + outcome == std::string_view(ledger_span::val::complete) || + outcome == std::string_view(ledger_span::val::failed) || + outcome == std::string_view(ledger_span::val::timeout) || + outcome == std::string_view(ledger_span::val::abandoned)) + << "undeclared outcome '" << outcome << "' for failed=" << failed + << " complete=" << complete << " timedOut=" << timedOut; + // Whenever the budget expired, the answer is `timeout` + // regardless of the other two -- the precedence property, not + // just the four sampled points above. + if (timedOut) + EXPECT_EQ(outcome, std::string_view(ledger_span::val::timeout)); + } + } + } +} + +TEST(LedgerSpanNames, phaseOutcome_is_a_compile_time_rule) +{ + // constexpr, so the rule costs nothing at its call sites and the mapping is + // fixed by the compiler itself. + static_assert(ledger_span::phaseOutcome(false, true, false) == std::string_view("complete")); + static_assert(ledger_span::phaseOutcome(true, false, false) == std::string_view("failed")); + static_assert(ledger_span::phaseOutcome(true, false, true) == std::string_view("timeout")); + static_assert(ledger_span::phaseOutcome(false, false, false) == std::string_view("abandoned")); + SUCCEED(); +} + +TEST(LedgerSpanNames, serveObjectType_maps_every_protobuf_itype) +{ + // The exact protobuf TMLedgerInfoType values, which are fixed by the wire + // protocol: liBASE=0, liTX_NODE=1, liAS_NODE=2, liTS_CANDIDATE=3. Passed as + // an int so this rule stays free of protobuf headers and assertable here. + EXPECT_EQ(ledger_span::serveObjectType(0), "header"); + EXPECT_EQ(ledger_span::serveObjectType(1), "tx"); + EXPECT_EQ(ledger_span::serveObjectType(2), "as"); + EXPECT_EQ(ledger_span::serveObjectType(3), "txset"); +} + +TEST(LedgerSpanNames, serveObjectType_never_yields_an_undeclared_value) +{ + // Edge case: an out-of-range itype cannot occur -- PeerImp::onMessage + // rejects the request before the worker runs -- but the rule must still + // produce a declared value rather than an empty attribute, so the + // object_type dimension's value set stays closed at four. + for (int const itype : {-1, 4, 99}) + { + auto const value = ledger_span::serveObjectType(itype); + EXPECT_EQ(value, std::string_view(ledger_span::val::header)) + << "unexpected fallback for itype=" << itype; + } +} + +TEST(LedgerSpanNames, serveOutcome_empty_reply_is_refused) +{ + // Seven of the eight exits of processLedgerRequest send nothing, and all of + // them reach this through a zero node count. Deriving the value from the + // reply is what makes those seven impossible to mislabel. + EXPECT_EQ(ledger_span::serveOutcome(/*servedNodes=*/0, /*softCap=*/128), "refused"); +} + +TEST(LedgerSpanNames, serveOutcome_partial_reply_below_cap_is_complete) +{ + EXPECT_EQ(ledger_span::serveOutcome(/*servedNodes=*/12, /*softCap=*/128), "complete"); + EXPECT_EQ(ledger_span::serveOutcome(/*servedNodes=*/127, /*softCap=*/128), "complete"); +} + +TEST(LedgerSpanNames, serveOutcome_reply_at_the_cap_is_partial) +{ + // Edge case at the exact boundary: the assembly loop stops here, so the + // requester must come back for the rest. Counting it as a success would + // hide the extra round trips a large tree really costs. + EXPECT_EQ(ledger_span::serveOutcome(/*servedNodes=*/128, /*softCap=*/128), "partial"); + EXPECT_EQ(ledger_span::serveOutcome(/*servedNodes=*/256, /*softCap=*/128), "partial"); +} + +TEST(LedgerSpanNames, serveOutcome_never_yields_an_undeclared_value) +{ + // Negative counts cannot occur (nodes_size() is non-negative) but must + // still map to a declared value rather than an empty attribute. + for (int const served : {-5, 0, 1, 64, 128, 4096}) + { + auto const outcome = ledger_span::serveOutcome(served, 128); + EXPECT_TRUE( + outcome == std::string_view(ledger_span::val::complete) || + outcome == std::string_view(ledger_span::val::partial) || + outcome == std::string_view(ledger_span::val::refused)) + << "undeclared serve outcome '" << outcome << "' for servedNodes=" << served; + } +} + +TEST(LedgerSpanNames, serveOutcome_is_a_compile_time_rule) +{ + static_assert(ledger_span::serveOutcome(0, 128) == std::string_view("refused")); + static_assert(ledger_span::serveOutcome(1, 128) == std::string_view("complete")); + static_assert(ledger_span::serveOutcome(128, 128) == std::string_view("partial")); + SUCCEED(); +} + +TEST(LedgerSpanNames, peer_dial_span_name_is_dot_qualified) +{ + // ConnectAttempt::run builds the name as seg::peer + "." + op::dial. + EXPECT_EQ(std::string_view(seg::peer), "peer"); + EXPECT_EQ(std::string_view(peer_span::op::dial), "dial"); +} + +TEST(LedgerSpanNames, peer_dial_attribute_keys_are_bare_underscore) +{ + // remote_endpoint is the dedicated Parquet span column in tempo.yaml and + // is deliberately NOT a spanmetrics dimension: one series per peer address + // would be unbounded cardinality. + EXPECT_EQ(std::string_view(peer_span::attr::remoteEndpoint), "remote_endpoint"); + EXPECT_EQ(std::string_view(peer_span::attr::durationMs), "duration_ms"); + EXPECT_EQ(std::string_view(peer_span::attr::outcome), "outcome"); + for (std::string_view const key : + {std::string_view(peer_span::attr::remoteEndpoint), + std::string_view(peer_span::attr::durationMs), + std::string_view(peer_span::attr::outcome)}) + { + EXPECT_EQ(key.find('.'), std::string_view::npos) << "dotted span-attr key: " << key; + } +} + +TEST(LedgerSpanNames, peer_dial_outcome_values_match_the_counter_label_set) +{ + // These five ARE the values ConnectAttempt::reportOutcome passes to the + // overlay_connect_total counter -- the span and the counter read the same + // constants from the same funnel, which is what stops them drifting apart. + // Pinned literally because the Bootstrap-row dial panel and the runbook + // both name them. + EXPECT_EQ(std::string_view(peer_span::val::connected), "connected"); + EXPECT_EQ(std::string_view(peer_span::val::tcpFail), "tcp_fail"); + EXPECT_EQ(std::string_view(peer_span::val::tlsFail), "tls_fail"); + EXPECT_EQ(std::string_view(peer_span::val::upgradeFail), "upgrade_fail"); + EXPECT_EQ(std::string_view(peer_span::val::timeout), "timeout"); +} + +TEST(LedgerSpanNames, peer_dial_outcome_values_are_mutually_distinct) +{ + // The dial panel splits by this attribute, so two outcomes sharing a value + // would merge two different failure stages into one line -- and the stage + // is the whole diagnostic content of the dial signal. + std::array const values{ + peer_span::val::connected, + peer_span::val::tcpFail, + peer_span::val::tlsFail, + peer_span::val::upgradeFail, + peer_span::val::timeout}; + for (std::size_t i = 0; i < values.size(); ++i) + { + EXPECT_FALSE(values[i].empty()); + for (std::size_t j = i + 1; j < values.size(); ++j) + EXPECT_NE(values[i], values[j]) << "duplicate dial outcome at " << i << "," << j; + } +} + +TEST(LedgerSpanNames, b2_inactive_guard_finalize_sequences_are_no_ops) +{ + // Negative / disabled path for all four new spans. A default-constructed + // SpanGuard is the exact state TransactionAcquire::acquireSpan_, + // InboundLedger's three phase handles and ConnectAttempt::dialSpan_ hold + // when telemetry is off or the category is disabled: operator bool() is + // false and every setter is inert. Drive the full finalize sequence of each + // emitter -- the same calls, in the same order -- and assert the guard + // stays inactive and nothing crashes. This is what proves the new spans + // emit nothing on a node with telemetry disabled, including from a + // destructor. + SpanGuard guard; + ASSERT_FALSE(static_cast(guard)); + + // TransactionAcquire::finalizeAcquireSpan() + guard.setAttribute(ledger_span::attr::txSetHash, "0123456789ABCDEF"); + guard.setAttribute( + ledger_span::attr::outcome, + ledger_span::phaseOutcome(/*failed=*/false, /*complete=*/false, /*timedOut=*/false)); + guard.setAttribute(ledger_span::attr::timeouts, static_cast(21)); + guard.setAttribute(ledger_span::attr::durationMs, static_cast(5250)); + guard.setAttribute(ledger_span::attr::peerCount, static_cast(0)); + + // InboundLedger::beginPhaseSpan() / endPhaseSpan() + guard.setAttribute(ledger_span::attr::ledgerHash, "FEDCBA9876543210"); + guard.setAttribute(ledger_span::attr::ledgerSeq, static_cast(9000)); + guard.setAttribute(ledger_span::attr::timedOut, true); + guard.setAttribute(ledger_span::attr::missingNodes, static_cast(256)); + + // PeerImp::processLedgerRequest()'s scope-exit finalizer + guard.setAttribute(ledger_span::attr::objectType, ledger_span::serveObjectType(/*itype=*/2)); + guard.setAttribute(ledger_span::attr::servedNodes, static_cast(0)); + guard.setAttribute( + ledger_span::attr::outcome, ledger_span::serveOutcome(/*servedNodes=*/0, /*softCap=*/128)); + + // ConnectAttempt::reportOutcome() + guard.setAttribute(peer_span::attr::remoteEndpoint, "10.0.0.5:51235"); + guard.setAttribute(peer_span::attr::outcome, peer_span::val::timeout); + guard.setAttribute(peer_span::attr::durationMs, static_cast(15000)); + + // Still inactive: no span was created, so none can be exported. + EXPECT_FALSE(static_cast(guard)); + + // childSpan on an inactive guard yields another inactive guard, which is + // what makes InboundLedger::beginPhaseSpan() a no-op when telemetry is off: + // it never creates a phase span at all, so the whole per-phase feature + // costs one branch on the disabled path. + auto const child = guard.childSpan(ledger_span::acquireAsTree); + EXPECT_FALSE(static_cast(child)); + // Same via the explicit-parent overload, the one beginPhaseSpan() actually + // calls: an invalid parent context yields an inactive child. + auto const childOfCtx = SpanGuard::childSpan(ledger_span::acquireTxTree, guard.spanContext()); + EXPECT_FALSE(static_cast(childOfCtx)); + EXPECT_FALSE(guard.spanContext().isValid()); +} + } // namespace #endif // XRPL_ENABLE_TELEMETRY diff --git a/src/xrpld/app/ledger/InboundLedger.h b/src/xrpld/app/ledger/InboundLedger.h index abaaf521aa..5bacbd6856 100644 --- a/src/xrpld/app/ledger/InboundLedger.h +++ b/src/xrpld/app/ledger/InboundLedger.h @@ -29,6 +29,7 @@ #include #include #include +#include #include #include @@ -278,6 +279,70 @@ private: void finalizeAcquireSpan(std::optional peerCount) noexcept; + /** + * Open the span for the fetch phase now in progress and close any phase + * whose data has arrived. + * + * One acquire is really three sequential fetches -- the header, then the + * account-state tree, then the transaction tree -- and on a fresh sync the + * state tree dominates. The parent span is flat, so it cannot say which of + * the three a stuck acquire is stuck in. These child spans can. + * + * Written as an idempotent state sync over the `have*_` flags rather than + * as open/close calls scattered through the fetch code: the flags are the + * real phase boundary, so deriving the span state from them cannot drift + * out of step with the fetch, and the function is safe to call from any + * progress point however often. + * + * The tree phases never open before the header arrives, because the header + * is what names their root hashes -- until then there is nothing to fetch. + * + * @note noexcept and allocation-free on the disabled path: with telemetry + * off the parent span is inactive, so no child is ever created. + * @note Call with mtx_ held, as every call site does. Called at phase + * boundaries and per received packet, never per SHAMap node. + */ + void + syncPhaseSpans() noexcept; + + /** + * Start one phase child span, parented to the acquire span. + * + * Parented through the acquire span's captured context rather than the + * thread's ambient context, so a phase opened on a JtLedgerData worker + * still lands under the right acquire. + * + * @param span The phase span handle to fill; untouched if already open. + * @param name Full span name from LedgerSpanNames.h. + * + * @note A no-op when the acquire span is absent or inactive, which is what + * makes the whole phase-span feature cost nothing when telemetry is + * disabled. + */ + void + beginPhaseSpan(std::optional& span, std::string_view name) noexcept; + + /** + * End one phase child span exactly once, stamping its outcome. + * + * Idempotent by the same rule as finalizeAcquireSpan(): the handle is + * cleared, so a later call finds nothing and cannot overwrite the outcome + * the real phase end recorded. + * + * @param span The phase span handle to end. + * @param complete Whether this phase's data was fully assembled. + * @param missingNodes Nodes still outstanding in this phase's tree, or + * nullopt for the header phase, which has no tree. + * + * @note noexcept, and the attribute writes are wrapped, because this is + * reached from ~InboundLedger via finalizeAcquireSpan(). + */ + void + endPhaseSpan( + std::optional& span, + bool complete, + std::optional missingNodes) noexcept; + clock_type& clock_; clock_type::time_point lastAction_; @@ -336,6 +401,32 @@ private: * thread's context stack. */ std::optional acquireSpan_; + + /** + * Child spans for the three fetch phases of this acquire, each a child of + * acquireSpan_ and each open only while its phase is in progress. + * + * Present so a stuck acquire names the phase it is stuck in: on a fresh + * sync the account-state tree is nearly all of the work, and the flat + * parent span cannot separate it from the small transaction tree or from + * the header wait that gates both. + * + * Same ownership contract as acquireSpan_: written under mtx_ or from the + * destructor, and thread-free, so a phase may be ended on whichever worker + * receives its last node. + */ + std::optional headerSpan_; + std::optional asTreeSpan_; + std::optional txTreeSpan_; + + /** + * True once the acquire has exhausted its timeout budget, so each phase + * still open at that point reports `timeout` rather than `abandoned`. + * Distinct from `failed_`, which the same path also sets: `failed_` is how + * the timer loop stops, while this is what says the cause was peers not + * supplying data rather than data that would not apply. + */ + bool timedOut_{false}; }; } // namespace xrpl diff --git a/src/xrpld/app/ledger/detail/InboundLedger.cpp b/src/xrpld/app/ledger/detail/InboundLedger.cpp index fc2ba4d128..ed2aef14f4 100644 --- a/src/xrpld/app/ledger/detail/InboundLedger.cpp +++ b/src/xrpld/app/ledger/detail/InboundLedger.cpp @@ -160,6 +160,10 @@ InboundLedger::init(ScopedLockType& collectionLock) if (!complete_) { + // Open the span for whichever phase the local lookup left outstanding, + // so the phase timeline starts at the same instant the network fetch + // does rather than at the first reply. + syncPhaseSpans(); addPeers(); queueJob(sl); return; @@ -465,6 +469,10 @@ InboundLedger::onTimer(bool wasProgress, ScopedLockType&) { JLOG(journal_.warn()) << timeouts_ << " timeouts for ledger " << hash_; } + // Record WHY before done() finalizes the spans. failed_ alone reads as + // "the data was bad"; this path is "no peer supplied it in time", and + // any phase still open is stamped `timeout` because of this flag. + timedOut_ = true; failed_ = true; done(); return; @@ -524,9 +532,145 @@ InboundLedger::pmDowncast() return shared_from_this(); } +void +InboundLedger::beginPhaseSpan( + std::optional& span, + std::string_view name) noexcept +{ + // Already open, or there is no parent to hang it on. The second case is + // also the disabled path: with telemetry off acquireSpan_ is inactive, so + // no phase span is ever created and this whole feature costs one branch. + if (span || !acquireSpan_ || !*acquireSpan_) + return; + + // Parented through the acquire span's OWN captured context, not the + // thread's ambient context: a phase can open on a JtLedgerData worker where + // the ambient context is unrelated, and childSpan(name) would then attach + // it to whatever happened to be active there. + auto child = telemetry::SpanGuard::childSpan(name, acquireSpan_->spanContext()); + if (!child) + return; + // The identity every phase shares with its parent, so a phase span found + // on its own in a search still says which ledger it belongs to. + child.setAttribute(telemetry::ledger_span::attr::ledgerHash, to_string(hash_).c_str()); + if (seq_ != 0) + { + child.setAttribute( + telemetry::ledger_span::attr::ledgerSeq, static_cast(seq_)); + } + span.emplace(std::move(child)); +} + +void +InboundLedger::endPhaseSpan( + std::optional& span, + bool complete, + std::optional missingNodes) noexcept +{ + // Idempotent: the handle is cleared below, so a second call finds nothing + // and cannot overwrite the outcome the real phase end recorded. + if (!span) + return; + + // Wrapped because ~InboundLedger reaches this through + // finalizeAcquireSpan(): an exception escaping a destructor during + // unwinding would terminate the process. + try + { + if (*span) + { + using namespace telemetry; + // Same shared rule for every phase, so no phase can mislabel its + // own end and a phase still open when the acquire dies reports + // `timeout` (budget gone) or `abandoned` (swept) rather than + // nothing at all. + span->setAttribute( + ledger_span::attr::outcome, + ledger_span::phaseOutcome(failed_, complete, timedOut_)); + span->setAttribute(ledger_span::attr::timedOut, timedOut_); + // The count the phase's last getMissingNodes() sweep already + // produced -- read, never recomputed, so no second tree walk. A + // non-zero value on a timed-out phase is the "peers are not serving + // this tree" signature. + if (missingNodes) + { + span->setAttribute( + ledger_span::attr::missingNodes, static_cast(*missingNodes)); + } + } + } + catch (...) // NOLINT(bugprone-empty-catch) + { + // Telemetry must never break an acquire. A span missing one attribute + // is still worth exporting, so fall through and end it below. + } + + // End the span outside the try so it happens on every path, and + // unconditionally so it never leaks even when it was inactive. + span.reset(); +} + +void +InboundLedger::syncPhaseSpans() noexcept +{ + // Nothing to parent to: telemetry off, ledger category disabled, or the + // acquire already finalized. One branch on the disabled path. + if (!acquireSpan_ || !*acquireSpan_) + return; + + using namespace telemetry; + + // The header gates both trees, so it is the only phase that can be open + // before there is anything else to fetch. + if (!haveHeader_) + { + beginPhaseSpan(headerSpan_, ledger_span::acquireHeader); + return; + } + // The header arrived. Close its span with no missing-node count -- a header + // is a single object, not a tree. + endPhaseSpan(headerSpan_, /*complete=*/true, /*missingNodes=*/std::nullopt); + + // Both trees are fetched concurrently once their root hashes are known, so + // both spans can be open at once. Each closes when its own tree completes, + // which is what lets a trace show the state tree still running long after + // the transaction tree finished -- the normal shape of a fresh sync. + if (haveState_) + { + endPhaseSpan(asTreeSpan_, /*complete=*/true, getMissingNodeCount(SHAMapType::STATE)); + } + else + { + beginPhaseSpan(asTreeSpan_, ledger_span::acquireAsTree); + } + + if (haveTransactions_) + { + endPhaseSpan(txTreeSpan_, /*complete=*/true, getMissingNodeCount(SHAMapType::TRANSACTION)); + } + else + { + beginPhaseSpan(txTreeSpan_, ledger_span::acquireTxTree); + } +} + void InboundLedger::finalizeAcquireSpan(std::optional peerCount) noexcept { + // Close any phase still open BEFORE the parent ends, so no child span + // outlives its parent. A phase open at this point is one that never + // finished: it takes `timeout` when the retry budget ran out and + // `abandoned` when the acquire was swept, which is exactly the case these + // spans exist to show. Each carries the last missing-node count its own + // sweep produced, so a stuck phase reports how much it was still waiting + // for. + // Ahead of the acquire-span check below because each is independently + // idempotent: on a second call they are already empty, and when telemetry + // is off they were never created. + endPhaseSpan(headerSpan_, haveHeader_, std::nullopt); + endPhaseSpan(asTreeSpan_, haveState_, getMissingNodeCount(SHAMapType::STATE)); + endPhaseSpan(txTreeSpan_, haveTransactions_, getMissingNodeCount(SHAMapType::TRANSACTION)); + // Idempotent: the handle is cleared below, so a later exit finds nothing to // finalize and cannot overwrite the outcome the real exit recorded. if (!acquireSpan_) @@ -669,6 +813,13 @@ InboundLedger::trigger(std::shared_ptr const& peer, TriggerReason reason) stream << ss.str(); } + // Open the span for whatever phase is now outstanding. Placed here, at the + // top of the one function every progress point funnels through (a reply, a + // timeout, a newly added peer), so a phase span exists for the whole time + // that phase is being requested. Idempotent, so repeated triggers within + // one phase do nothing. + syncPhaseSpans(); + if (!haveHeader_) { tryDB(app_.getNodeFamily().db()); @@ -914,6 +1065,12 @@ InboundLedger::trigger(std::shared_ptr const& peer, TriggerReason reason) } } + // A tree may have completed in the blocks above without the whole acquire + // completing (the usual shape: the small transaction tree finishes long + // before the state tree). Close that phase now so its span duration is the + // real fetch time rather than stretching to the next trigger. + syncPhaseSpans(); + if (complete_ || failed_) { JLOG(journal_.debug()) << "Done:" << (complete_ ? " complete" : "") @@ -1007,6 +1164,13 @@ InboundLedger::takeHeader(std::string const& data) // publish its count. refreshMissingNodeCounts(); + // The header phase ends exactly here, and the tree phases become openable + // for the first time -- until now their root hashes were unknown. Doing it + // here rather than at the next trigger() is what keeps the header span's + // duration equal to the real header wait, which on a fresh node is the + // first thing that can stall. + syncPhaseSpans(); + ledger_->txMap().setSynching(); ledger_->stateMap().setSynching(); @@ -1107,6 +1271,12 @@ InboundLedger::receiveNode(protocol::TMLedgerData const& packet, SHAMapAddNode& // reading as a permanently stuck one. Outside the per-node loop above. refreshMissingNodeCounts(); + // This is the batch that completed a tree, so close that phase's span + // here. Without it the phase would stay open until the next trigger() + // and its duration would absorb the wait for the other tree. Outside + // the per-node loop above, so it runs once per completing batch. + syncPhaseSpans(); + if (haveTransactions_ && haveState_) { complete_ = true; diff --git a/src/xrpld/app/ledger/detail/LedgerSpanNames.h b/src/xrpld/app/ledger/detail/LedgerSpanNames.h index 7b70deaa08..c8abdfd0be 100644 --- a/src/xrpld/app/ledger/detail/LedgerSpanNames.h +++ b/src/xrpld/app/ledger/detail/LedgerSpanNames.h @@ -12,7 +12,18 @@ * ledger.store (LedgerMaster — ledger storage) * ledger.validate (LedgerMaster — ledger validation acceptance) * ledger.acquire (InboundLedger — fetch a missing ledger from peers) + * +-- ledger.acquire.header (the ledger header / liBASE phase) + * +-- ledger.acquire.astree (the account-state SHAMap phase) + * +-- ledger.acquire.txtree (the transaction SHAMap phase) + * ledger.serve (PeerImp — serve a peer's ledger-data request) * tx.apply (BuildLedger — transaction application) + * txset.acquire (TransactionAcquire — fetch a proposed tx set) + * + * Why the acquire phases are separate child spans: a fresh sync is + * dominated by the account-state tree, but the flat parent span cannot + * separate it from the (usually tiny) transaction tree or from the header + * wait that gates both. Each phase carries its own missing-node count and + * timeout flag, so the phase that is stuck names itself. */ #include @@ -29,8 +40,35 @@ inline constexpr auto store = makeStr("store"); inline constexpr auto validate = makeStr("validate"); inline constexpr auto apply = makeStr("apply"); inline constexpr auto acquire = makeStr("acquire"); +inline constexpr auto serve = makeStr("serve"); } // namespace op +// ===== Span prefixes ========================================================= + +namespace prefix { +/** + * "txset" — root prefix for transaction-set acquisition spans. A tx set is + * not a ledger, so it gets its own root rather than hiding under `ledger.`. + */ +inline constexpr auto txset = makeStr("txset"); +} // namespace prefix + +// ===== Full span names ======================================================= +// +// Joined names for the factories that take one complete span name rather than +// a prefix/suffix pair (childSpan(name) / childSpan(name, ctx)). + +/** + * The three phases of one ledger acquisition, each a child of ledger.acquire. + * + * `astree` and `txtree` are single words on purpose: they are the wire span + * names a dashboard and TraceQL query match on, so they must stay stable and + * unambiguous rather than reading as a further-nested `as.tree`. + */ +inline constexpr auto acquireHeader = join(join(seg::ledger, op::acquire), makeStr("header")); +inline constexpr auto acquireAsTree = join(join(seg::ledger, op::acquire), makeStr("astree")); +inline constexpr auto acquireTxTree = join(join(seg::ledger, op::acquire), makeStr("txtree")); + // ===== Attribute keys ======================================================== namespace attr { @@ -63,6 +101,40 @@ inline constexpr auto acquireReason = makeStr("acquire_reason"); inline constexpr auto timeouts = makeStr("timeouts"); inline constexpr auto peerCount = makeStr("peer_count"); inline constexpr auto outcome = makeStr("outcome"); + +/** + * Per-phase ledger.acquire attrs (header / AS-tree / TX-tree child spans). + * + * `missingNodes` is the count the phase's last getMissingNodes() sweep already + * produced, so recording it costs nothing extra; `timedOut` says whether the + * phase ended on the retry budget rather than on completion. Both are bounded + * only by the tree size, so `missing_nodes` stays span-only (Tempo-searchable) + * while `timed_out` — two values — is safe as a spanmetrics dimension. + */ +inline constexpr auto missingNodes = makeStr("missing_nodes"); +inline constexpr auto timedOut = makeStr("timed_out"); + +/** + * txset.acquire attrs (TransactionAcquire fetch lifecycle). + * + * The set's own root hash identifies which proposed set stalled, so like + * `ledgerHash` it is per-object and stays span-only. `durationMs` is recorded + * explicitly rather than left to the span's own duration because the span is + * ended from the acquiring thread and its wall time is the number an operator + * reads directly off a trace. + */ +inline constexpr auto txSetHash = makeStr("txset_hash"); +inline constexpr auto durationMs = makeStr("duration_ms"); + +/** + * ledger.serve attrs (the JtLedgerReq worker answering a peer). + * + * `objectType` names which of the four request kinds was served, and + * `servedNodes` how many SHAMap nodes the reply carried — accumulated by the + * reply-assembly loop and written once after it, never per node. + */ +inline constexpr auto objectType = makeStr("object_type"); +inline constexpr auto servedNodes = makeStr("served_nodes"); } // namespace attr // ===== Attribute values ====================================================== @@ -88,12 +160,49 @@ namespace val { inline constexpr auto complete = makeStr("complete"); inline constexpr auto failed = makeStr("failed"); inline constexpr auto abandoned = makeStr("abandoned"); +/** + * Extra terminal value for the per-phase acquire and txset.acquire spans. + * + * `ledger.acquire` itself never uses this: an acquire that exhausts its retry + * budget sets failed_, so its outcome is `failed`. A phase and a tx set can + * instead end while the parent fetch is still alive, and `timeout` is what + * names that -- the phase ran out of time, but nothing failed permanently. + */ +inline constexpr auto timeout = makeStr("timeout"); + /** * ledger.acquire reason values (mirror InboundLedger::Reason). */ inline constexpr auto history = makeStr("history"); inline constexpr auto consensus = makeStr("consensus"); inline constexpr auto generic = makeStr("generic"); + +/** + * ledger.serve object_type values (mirror the protobuf `itype` request kinds). + * + * Four bounded values, one per TMGetLedger info type: the ledger header + * (`liBASE`), the transaction tree (`liTX_NODE`), the account-state tree + * (`liAS_NODE`), and a proposed transaction set (`liTS_CANDIDATE`). Serving + * the state tree is what a syncing peer needs most, so telling it apart from + * the cheap header replies is the point of the split. + */ +inline constexpr auto header = makeStr("header"); +inline constexpr auto txTree = makeStr("tx"); +inline constexpr auto asTree = makeStr("as"); +inline constexpr auto txSet = makeStr("txset"); + +/** + * ledger.serve outcome values. + * + * - complete: a reply with at least one node was sent. + * - partial: nodes were sent but the reply hit a size cap, so the requester + * must ask again for the rest. + * - refused: nothing was sent. The paired `serve_refused_total` counter + * carries the specific cause; the span records only that this + * request went unanswered, so a trace shows the gap. + */ +inline constexpr auto partial = makeStr("partial"); +inline constexpr auto refused = makeStr("refused"); } // namespace val // ===== Outcome rule ========================================================== @@ -149,4 +258,147 @@ acquireOutcome(bool failed, bool complete) noexcept return val::abandoned; } +/** + * Pick the terminal `outcome` for ONE acquire phase (header / AS-tree / + * TX-tree) or for a tx-set fetch. + * + * The sibling of acquireOutcome() for the units whose lifetime is shorter than + * the whole fetch. It takes one more input, `timedOut`, because these units + * have a fourth end state the parent does not: a unit can stop because the + * retry budget expired. Reporting that as `failed` would say "bad data" and as + * `abandoned` would say "we stopped caring", so `timeout` names it directly -- + * and it is the value a stuck fresh sync shows, which is why these spans + * exist. + * + * Precedence is `timeout` > `failed` > `complete` > `abandoned`, and the + * timeout-first order is the load-bearing part. The exhausted-budget path in + * both emitters sets the terminal `failed_` flag as well, because that flag is + * how the TimeoutCounter base stops its timer loop -- so `timedOut` implies + * `failed`, and checking `failed` first would relabel every timeout as a data + * fault and erase the distinction. A genuine data fault never sets `timedOut`, + * so nothing is lost the other way round. + * + * A pure constexpr function with no dependency on InboundLedger or + * TransactionAcquire, so the whole rule is assertable from the lib-only test + * binary, which cannot link xrpld. + * + * @param failed The unit's `failed_` flag (terminal error). + * @param complete The unit's `complete_` flag (all data assembled). + * @param timedOut Whether the unit's retry budget expired before it ended. + * @return `timeout`, `failed`, `complete` or `abandoned`, in that precedence. + * + * Example -- the healthy and the stuck case: + * @code + * phaseOutcome(false, true, false); // "complete" -- assembled in time + * phaseOutcome(true, false, true); // "timeout" -- budget gone; the failed_ + * // flag the same path sets is subsumed + * @endcode + * + * Example -- edge case: a unit torn down mid-fetch with no flag set at all + * still reports a value, so it stays in the outcome rate: + * @code + * phaseOutcome(false, false, false); // "abandoned" + * @endcode + * + * @note Pure and side-effect free; safe to call from any thread, including a + * destructor (it allocates nothing and cannot throw). + */ +[[nodiscard]] constexpr std::string_view +phaseOutcome(bool failed, bool complete, bool timedOut) noexcept +{ + if (timedOut) + return val::timeout; + if (failed) + return val::failed; + if (complete) + return val::complete; + return val::abandoned; +} + +/** + * Pick the `object_type` value for a served ledger-data request from the + * protobuf `itype` the peer asked with. + * + * Kept as a rule rather than a per-branch literal because + * `processLedgerRequest` reaches its exits from four different places, and a + * per-branch value would let two of them disagree about the same request. It + * takes a plain int so this header stays free of the protobuf headers and the + * rule remains assertable from the lib-only test binary; the caller passes + * `m->itype()`, whose enum values are fixed by the wire protocol. + * + * @param itype The protobuf TMLedgerInfoType: 0 `liBASE`, 1 `liTX_NODE`, + * 2 `liAS_NODE`, 3 `liTS_CANDIDATE`. + * @return `header`, `tx`, `as` or `txset`; `header` for an unrecognised value, + * which cannot occur because onMessage() rejects the request first. + * + * Example -- the two request kinds a syncing peer sends most: + * @code + * serveObjectType(2); // "as" -- account-state tree, the bulk of a sync + * serveObjectType(0); // "header" -- the cheap liBASE reply + * @endcode + * + * @note Pure and side-effect free. + */ +[[nodiscard]] constexpr std::string_view +serveObjectType(int itype) noexcept +{ + switch (itype) + { + case 1: + return val::txTree; + case 2: + return val::asTree; + case 3: + return val::txSet; + default: + return val::header; + } +} + +/** + * Pick the `outcome` value for a served ledger-data request from the size of + * the reply it produced. + * + * `processLedgerRequest` has eight exits and only one of them sends anything, + * so a per-branch value would be seven chances to mislabel. Deriving it from + * the reply itself removes that: the reply's node count is the one piece of + * state that already exists at every exit, and is zero on all seven refusals. + * + * A reply that reached the soft cap is `partial`, not `complete`: the assembly + * loop stopped early and the requester must ask again for the rest, so counting + * it as a success would hide the round trips a large tree really costs. + * + * @param servedNodes Nodes in the reply, i.e. `ledgerData.nodes_size()`. + * @param softCap The reply-size cap the assembly loop stops at + * (`Tuning::kSoftMaxReplyNodes`). Passed in so this header needs no + * overlay dependency and the rule stays assertable from the lib-only + * test binary. + * @return `refused` for an empty reply, `partial` at or above the cap, + * otherwise `complete`. + * + * Example -- the served and the refused case: + * @code + * serveOutcome(12, 128); // "complete" -- whole request answered + * serveOutcome(0, 128); // "refused" -- nothing sent; the paired + * // serve_refused_total counter says why + * @endcode + * + * Example -- edge case: a reply that filled the cap is not a success, because + * the peer must come back for the remainder: + * @code + * serveOutcome(128, 128); // "partial" + * @endcode + * + * @note Pure and side-effect free; safe to call while unwinding. + */ +[[nodiscard]] constexpr std::string_view +serveOutcome(int servedNodes, int softCap) noexcept +{ + if (servedNodes <= 0) + return val::refused; + if (servedNodes >= softCap) + return val::partial; + return val::complete; +} + } // namespace xrpl::telemetry::ledger_span diff --git a/src/xrpld/app/ledger/detail/TransactionAcquire.cpp b/src/xrpld/app/ledger/detail/TransactionAcquire.cpp index 62312b04d2..8c9e260ae5 100644 --- a/src/xrpld/app/ledger/detail/TransactionAcquire.cpp +++ b/src/xrpld/app/ledger/detail/TransactionAcquire.cpp @@ -2,6 +2,7 @@ #include #include +#include #include #include #include @@ -14,11 +15,14 @@ #include #include #include +#include #include #include +#include #include +#include #include #include #include @@ -50,32 +54,114 @@ TransactionAcquire::TransactionAcquire( map_->setUnbacked(); } +TransactionAcquire::~TransactionAcquire() +{ + // Last exit. A set dropped here (swept by newRound because it never + // arrived, or torn down at shutdown) reached no result, so this is what + // stamps outcome=abandoned instead of exporting a span with no outcome at + // all. Already-finalized acquisitions are untouched: the helper is + // idempotent. + finalizeAcquireSpan(); +} + +void +TransactionAcquire::finalizeAcquireSpan() noexcept +{ + // Idempotent: the handle is cleared below, so a later exit finds nothing to + // finalize and cannot overwrite the outcome the real exit recorded. + if (!acquireSpan_) + return; + + // The attribute writes are wrapped because the destructor is one of the + // callers: an exception escaping there during unwinding would terminate the + // process. Each setAttribute is itself noexcept today; the try is the + // structural guarantee that stays correct if that ever changes. + try + { + if (*acquireSpan_) + { + using namespace telemetry; + // Derived from this object's own flags by the shared rule, so no + // call site can mislabel an exit and every exit gets an outcome. + // No flag set means the set was dropped while still in flight. + acquireSpan_->setAttribute( + ledger_span::attr::outcome, + ledger_span::phaseOutcome(failed_, complete_, timedOut_)); + acquireSpan_->setAttribute( + ledger_span::attr::timeouts, static_cast(timeouts_)); + // Recorded explicitly as well as implied by the span's own + // duration: this is the number an operator reads straight off a + // trace when asking how long a proposed set took to arrive. + acquireSpan_->setAttribute( + ledger_span::attr::durationMs, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - acquireStart_) + .count())); + // Peers still tracked for this fetch. Safe here, unlike the ledger + // equivalent: PeerSet::getPeerIds() returns its own member set and + // takes no Overlay lock. + acquireSpan_->setAttribute( + ledger_span::attr::peerCount, + static_cast(peerSet_->getPeerIds().size())); + } + } + catch (...) // NOLINT(bugprone-empty-catch) + { + // Telemetry must never break an acquisition, and this also runs from + // the destructor. A span missing one attribute is still worth + // exporting, so fall through and end it below. + } + + // End the span, outside the try so it happens on every path. Unconditional + // so the span never leaks even when it was inactive, and so this helper is + // exactly-once: a later exit sees an empty handle and returns above. + // ~SpanGuard is implicitly noexcept, so this cannot throw out of here. + acquireSpan_.reset(); +} + void TransactionAcquire::done() { // We hold a PeerSet lock and so cannot do real work here - if (failed_) + // Keep the span active as the ambient context across the outcome log below + // so that line carries the span's trace_id. The activation is non-owning; + // acquireSpan_ still owns the span. It pops at the end of this block, while + // the span is still alive, and only then is the span finalized and ended. { - JLOG(journal_.debug()) << "Failed to acquire TX set " << hash_; - } - else - { - JLOG(journal_.debug()) << "Acquired TX set " << hash_; - map_->setImmutable(); + auto acquireActivation = telemetry::activateIfLive(acquireSpan_); - uint256 const& hash(hash_); - std::shared_ptr const& map(map_); - auto const pap = &app_; - // Note that, when we're in the process of shutting down, addJob() - // may reject the request. If that happens then giveSet() will - // not be called. That's fine. According to David the giveSet() call - // just updates the consensus and related structures when we acquire - // a transaction set. No need to update them if we're shutting down. - app_.getJobQueue().addJob(JtTxnData, "ComplAcquire", [pap, hash, map]() { - pap->getInboundTransactions().giveSet(hash, map, true); - }); + if (failed_) + { + JLOG(journal_.debug()) << "Failed to acquire TX set " << hash_; + } + else + { + JLOG(journal_.debug()) << "Acquired TX set " << hash_; + map_->setImmutable(); + + uint256 const& hash(hash_); + std::shared_ptr const& map(map_); + auto const pap = &app_; + // Note that, when we're in the process of shutting down, addJob() + // may reject the request. If that happens then giveSet() will + // not be called. That's fine. According to David the giveSet() + // call just updates the consensus and related structures when we + // acquire a transaction set. No need to update them if we're + // shutting down. + app_.getJobQueue().addJob(JtTxnData, "ComplAcquire", [pap, hash, map]() { + pap->getInboundTransactions().giveSet(hash, map, true); + }); + } + // acquireActivation pops here, before the span is ended below. } + + // The normal exit. done() is reached from trigger() (complete or invalid + // data) and from onTimer() (timeout budget exhausted), and both are + // terminal, so the span ends here rather than waiting for the object to be + // released. TimeoutCounter::isDone() is already true by now, so the timer + // loop will not call back in. + finalizeAcquireSpan(); } void @@ -83,6 +169,11 @@ TransactionAcquire::onTimer(bool progress, ScopedLockType& psl) { if (timeouts_ > kMaxTimeouts) { + // Record WHY before done() finalizes the span. failed_ alone would + // report `failed`, which reads as bad data; this path is instead "no + // peer ever supplied the set", and that is the distinction a stuck + // fresh sync turns on. + timedOut_ = true; failed_ = true; done(); return; @@ -245,6 +336,37 @@ TransactionAcquire::init(int numPeers) { ScopedLockType sl(mtx_); + // Start the clock and the span before the first peer is asked. addPeers() + // below calls trigger() per peer, and trigger() can reach done() in the + // same call stack, so anything set up after it could be missed entirely by + // a set that resolves immediately. + acquireStart_ = std::chrono::steady_clock::now(); + + // Span the acquisition so a proposed tx set that never arrives is + // traceable. TransactionAcquire had no telemetry at all before this, so a + // consensus round stalled waiting on a set looked identical to an idle one. + // Finalized by finalizeAcquireSpan() on whichever exit this object takes, + // including the destructor. + { + using namespace telemetry; + // acquireSpan_ is emplaced here but may be reset on a JtTxnData worker + // thread. A SpanGuard is thread-free (owns no thread-local Scope), so it + // can be created here and destroyed on the worker with no scope to + // strip. Category Ledger: a tx set is ledger-fetch traffic, and this + // shares the `trace_ledger` flag with ledger.acquire so the two halves + // of a stuck sync cannot be enabled apart. + acquireSpan_.emplace( + SpanGuard::span( + TraceCategory::Ledger, ledger_span::prefix::txset, ledger_span::op::acquire)); + if (*acquireSpan_) + { + // The set's root hash is the only identity it has -- there is no + // sequence number -- so it is what makes a stalled fetch findable + // in a trace search. + acquireSpan_->setAttribute(ledger_span::attr::txSetHash, to_string(hash_).c_str()); + } + } + addPeers(numPeers); setTimer(sl); diff --git a/src/xrpld/app/ledger/detail/TransactionAcquire.h b/src/xrpld/app/ledger/detail/TransactionAcquire.h index 5b33066390..4b88f526ad 100644 --- a/src/xrpld/app/ledger/detail/TransactionAcquire.h +++ b/src/xrpld/app/ledger/detail/TransactionAcquire.h @@ -10,16 +10,59 @@ #include #include #include +#include +#include #include #include +#include #include #include namespace xrpl { // VFALCO TODO rename to PeerTxRequest -// A transaction set we are trying to acquire +/** + * A transaction set we are trying to acquire. + * + * The tx-set sibling of InboundLedger: same TimeoutCounter base, same + * trigger / onTimer / takeNodes shape, fetching the transaction SHAMap a + * consensus proposal referenced rather than a whole ledger. + * + * +-----------------+ + * | TimeoutCounter | timer loop, timeouts_/complete_/failed_ flags + * +--------+--------+ + * | + * +--------v-----------------------------+ + * | TransactionAcquire | + * | map_ : the tx SHAMap being | + * | assembled | + * | peerSet_ : peers asked for nodes | + * | acquireSpan_ : "txset.acquire" span | + * +--------------------------------------+ + * + * Acquisition lifecycle and where the span ends: + * + * init() -- span starts, timer set + * | + * +--> trigger() ---- root or missing nodes requested from a peer + * | ^ | + * | | v + * +--> takeNodes() -- nodes applied, trigger() again + * | + * +--> onTimer() ---- retry, or give up past the timeout budget + * | + * v + * done() -- span finalized (complete | failed | timeout) + * or + * ~TransactionAcquire() -- span finalized (abandoned) when the set is + * dropped by the round sweep or at shutdown + * + * @note Thread safety: unchanged by the span. `acquireSpan_` is written only + * under `mtx_` or from the destructor, both of which exclude every other + * writer. A SpanGuard owns no thread-local scope, so it can be ended on + * whichever JtTxnData worker reaches the terminal path. + */ class TransactionAcquire final : public TimeoutCounter, public std::enable_shared_from_this, public CountedObject @@ -28,7 +71,7 @@ public: using pointer = std::shared_ptr; TransactionAcquire(Application& app, uint256 const& hash, std::unique_ptr peerSet); - ~TransactionAcquire() override = default; + ~TransactionAcquire() override; SHAMapAddNode takeNodes( @@ -46,6 +89,33 @@ private: bool haveRoot_{false}; std::unique_ptr peerSet_; + /** + * When this acquisition started, set in init() before the first peer is + * asked. Base for the span's `duration_ms` attribute. + */ + std::chrono::steady_clock::time_point acquireStart_; + + /** + * True once the timeout budget has been exhausted, so the span's outcome + * reads `timeout` rather than the bare `failed` the flag alone would give. + * Distinct from `failed_`, which onTimer() also sets on that path: the two + * together are what separate "peers never supplied the set" from "a peer + * supplied an invalid one". + */ + bool timedOut_{false}; + + /** + * Spans the whole acquisition: started in init(), ended by + * finalizeAcquireSpan() on whichever exit this object takes, including the + * destructor. Held for the object's lifetime so a set that is dropped + * mid-fetch still reports an outcome instead of exporting a span with + * none. + * Thread-free: a SpanGuard holds no thread-local scope, so it may be + * created on the acquiring thread and ended on a JtTxnData worker or in + * the destructor. + */ + std::optional acquireSpan_; + void onTimer(bool progress, ScopedLockType& peerSetLock) override; @@ -59,6 +129,36 @@ private: trigger(std::shared_ptr const&); std::weak_ptr pmDowncast() override; + + /** + * End the acquire span exactly once, stamping the outcome it reached. + * + * A tx-set acquisition can leave through two exits: done(), reached from + * trigger() on success or invalid data and from onTimer() when the timeout + * budget runs out, and the destructor, when the round sweep in + * InboundTransactions::newRound drops a set that never arrived. Both call + * this, so the span always carries an `outcome` and its duration always + * ends at the real exit rather than stretching to whenever the object + * happened to be released. + * + * The outcome is derived from this object's own flags by the shared + * phaseOutcome() rule rather than passed in, so no call site can mislabel + * an exit and no exit added later can forget one: + * failed_ -> "failed", timedOut_ -> "timeout", complete_ -> "complete", + * otherwise "abandoned" (dropped with no result). + * + * Idempotent: the span handle is cleared here, so the second and later + * calls do nothing and cannot overwrite the outcome the real exit + * recorded. + * + * @note noexcept, and the attribute writes are wrapped, because the + * destructor calls this: an exception escaping a destructor during + * unwinding would terminate the process. + * @note Called once per acquisition, never on the per-node path in + * takeNodes(). + */ + void + finalizeAcquireSpan() noexcept; }; } // namespace xrpl diff --git a/src/xrpld/overlay/detail/ConnectAttempt.cpp b/src/xrpld/overlay/detail/ConnectAttempt.cpp index 9225388d4a..08084c7148 100644 --- a/src/xrpld/overlay/detail/ConnectAttempt.cpp +++ b/src/xrpld/overlay/detail/ConnectAttempt.cpp @@ -10,6 +10,7 @@ #include #include #include +#include #include #include #include @@ -17,6 +18,7 @@ #include #include +#include #include #include #include @@ -24,6 +26,8 @@ #include #include #include +#include +#include #include #include @@ -41,10 +45,12 @@ #include #include +#include #include #include #include #include +#include #include #include @@ -84,6 +90,15 @@ ConnectAttempt::~ConnectAttempt() if (slot_ != nullptr) overlay_.peerFinder().onClosed(slot_); JLOG(journal_.trace()) << "~ConnectAttempt"; + + // Last resort for an attempt torn down without reaching a terminal path + // (overlay shutdown, or an operation_aborted early return). The span ends + // here with no `outcome`, which is the honest record: the dial really did + // take this long and really did not conclude. Attempts that did conclude + // already ended their span in reportOutcome(), so this is a no-op for them + // -- ~optional on an empty handle. Nothing here can throw: ~SpanGuard is + // noexcept and no attribute is written. + dialSpan_.reset(); } void @@ -110,6 +125,26 @@ ConnectAttempt::run() // queues a strand-bound wait that can read dialStart_ via reportOutcome(). dialStart_ = std::chrono::steady_clock::now(); + // Span the dial beside the clock it shares, and for the same reason: the + // constructor is too early and setTimer() already queues a wait that can + // reach reportOutcome(). A fresh trace root -- a dial is the first thing a + // starting node does, so there is nothing to parent it to, and freshRoot() + // stops it inheriting whatever unrelated span happens to be active on the + // thread that decided to dial. + { + using namespace telemetry; + dialSpan_.emplace( + SpanGuard::freshRoot(TraceCategory::Peer, seg::peer, peer_span::op::dial)); + if (*dialSpan_) + { + // Which peer. Deliberately span-only, never a metric label: one + // series per peer address would be unbounded cardinality. + dialSpan_->setAttribute( + peer_span::attr::remoteEndpoint, + to_string(beast::IPAddressConversion::fromAsio(remoteEndpoint_)).c_str()); + } + } + setTimer(); stream_.next_layer().async_connect( @@ -119,7 +154,7 @@ ConnectAttempt::run() } void -ConnectAttempt::reportOutcome(char const* outcome) +ConnectAttempt::reportOutcome(std::string_view outcome) { if (outcomeReported_) return; @@ -143,6 +178,29 @@ ConnectAttempt::reportOutcome(char const* outcome) "overlay_connect_total", "Outbound peer connection attempts, by terminal outcome", {{"outcome", std::string(outcome)}}); + + // End the span with the SAME outcome value the counter just recorded, from + // the same funnel, so the two can never disagree. The first-call-wins guard + // above makes this exactly-once at no extra cost. + if (dialSpan_) + { + if (*dialSpan_) + { + using namespace telemetry; + dialSpan_->setAttribute(peer_span::attr::outcome, outcome); + // Same elapsed time the histogram above records, stamped on the + // individual attempt so one slow dial is findable in a trace + // instead of only visible in an aggregate p95. + dialSpan_->setAttribute( + peer_span::attr::durationMs, + static_cast(std::chrono::duration_cast( + std::chrono::steady_clock::now() - dialStart_) + .count())); + } + // Unconditional, so the span never leaks even when it was inactive, and + // so the destructor's reset() finds an empty handle. + dialSpan_.reset(); + } } //------------------------------------------------------------------------------ @@ -230,7 +288,7 @@ ConnectAttempt::onTimer(error_code ec) close(); return; } - reportOutcome("timeout"); + reportOutcome(telemetry::peer_span::val::timeout); fail("Timeout"); } @@ -244,7 +302,7 @@ ConnectAttempt::onConnect(error_code ec) if (ec == boost::asio::error::operation_aborted) return; - reportOutcome("tcp_fail"); + reportOutcome(telemetry::peer_span::val::tcpFail); fail("onConnect", ec); return; } @@ -256,7 +314,7 @@ ConnectAttempt::onConnect(error_code ec) socket_.local_endpoint(ec); if (ec) { - reportOutcome("tcp_fail"); + reportOutcome(telemetry::peer_span::val::tcpFail); fail("onConnect", ec); return; } @@ -282,7 +340,7 @@ ConnectAttempt::onHandshake(error_code ec) if (ec == boost::asio::error::operation_aborted) return; - reportOutcome("tls_fail"); + reportOutcome(telemetry::peer_span::val::tlsFail); fail("onHandshake", ec); return; } @@ -290,7 +348,7 @@ ConnectAttempt::onHandshake(error_code ec) auto const localEndpoint = socket_.local_endpoint(ec); if (ec) { - reportOutcome("tls_fail"); + reportOutcome(telemetry::peer_span::val::tlsFail); fail("onHandshake", ec); return; } @@ -298,7 +356,7 @@ ConnectAttempt::onHandshake(error_code ec) if (!overlay_.peerFinder().onConnected( slot_, beast::IPAddressConversion::fromAsio(localEndpoint))) { - reportOutcome("tls_fail"); + reportOutcome(telemetry::peer_span::val::tlsFail); fail("Duplicate connection"); return; } @@ -306,7 +364,7 @@ ConnectAttempt::onHandshake(error_code ec) auto const sharedValue = makeSharedValue(*streamPtr_, journal_); if (!sharedValue) { - reportOutcome("tls_fail"); + reportOutcome(telemetry::peer_span::val::tlsFail); close(); // makeSharedValue logs return; } @@ -348,7 +406,7 @@ ConnectAttempt::onWrite(error_code ec) if (ec == boost::asio::error::operation_aborted) return; - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); fail("onWrite", ec); return; } @@ -386,7 +444,7 @@ ConnectAttempt::onRead(error_code ec) return; } - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); fail("onRead", ec); return; } @@ -406,7 +464,7 @@ ConnectAttempt::onShutdown(error_code ec) if (ec != boost::asio::error::eof) { - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); fail("onShutdown", ec); return; } @@ -460,7 +518,7 @@ ConnectAttempt::processResponse() { JLOG(journal_.info()) << "Unable to upgrade to peer protocol: " << response_.result() << " (" << response_.reason() << ")"; - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); close(); return; } @@ -477,7 +535,7 @@ ConnectAttempt::processResponse() if (!negotiatedProtocol) { - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); fail("processResponse: Unable to negotiate protocol version"); return; } @@ -486,7 +544,7 @@ ConnectAttempt::processResponse() auto const sharedValue = makeSharedValue(*streamPtr_, journal_); if (!sharedValue) { - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); close(); // makeSharedValue logs return; } @@ -517,7 +575,7 @@ ConnectAttempt::processResponse() overlay_.peerFinder().activate(slot_, publicKey, static_cast(member)); if (result != PeerFinder::Result::Success) { - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); fail("Outbound " + std::string(to_string(result))); return; } @@ -538,11 +596,11 @@ ConnectAttempt::processResponse() // Only after addActive succeeds is the dial genuinely complete. If // anything above threw, the catch below reports the failure instead. - reportOutcome("connected"); + reportOutcome(telemetry::peer_span::val::connected); } catch (std::exception const& e) { - reportOutcome("upgrade_fail"); + reportOutcome(telemetry::peer_span::val::upgradeFail); fail(std::string("Handshake failure (") + e.what() + ")"); return; } diff --git a/src/xrpld/overlay/detail/ConnectAttempt.h b/src/xrpld/overlay/detail/ConnectAttempt.h index 56c29771d0..bdf8f0fd18 100644 --- a/src/xrpld/overlay/detail/ConnectAttempt.h +++ b/src/xrpld/overlay/detail/ConnectAttempt.h @@ -10,12 +10,15 @@ #include #include #include +#include #include #include #include +#include #include #include +#include namespace xrpl { @@ -66,6 +69,23 @@ private: */ bool outcomeReported_{false}; + /** + * Spans this dial: started in run() beside `dialStart_`, ended by + * reportOutcome() on whichever terminal path the state machine takes, and + * by the destructor for an attempt torn down without one. + * + * The counters WP-A1 added answer "how many dials failed, and at which + * stage". This span answers what they cannot: which peer, and how the time + * was spent inside one slow attempt. Both are needed because a dial that + * hangs is invisible in a rate. + * + * Thread-free (a SpanGuard holds no thread-local scope). All the completion + * handlers that end it are bound through `bind_executor(strand_, ...)`, so + * every access after run() is on one strand; run() itself writes it before + * any async operation is started, so those handlers see it safely. + */ + std::optional dialSpan_; + public: ConnectAttempt( Application& app, @@ -125,6 +145,12 @@ private: * Emits: * - `overlay_dial_latency_ms` histogram, no labels * - `overlay_connect_total` counter, label `outcome` + * - ends the `peer.dial` span with the same `outcome` value plus + * `remote_endpoint` and `duration_ms` + * + * The span shares this funnel rather than being ended per branch, so the + * span's outcome and the counter's label can never disagree, and the + * first-call-wins guard makes the span exactly-once for free. * * Dial state machine and where each outcome is reported: * @@ -138,9 +164,12 @@ private: * +-- bad status / protocol / activate ... "upgrade_fail" * +-- PeerImp created + addActive ........ "connected" * - * @param outcome One of "connected", "tcp_fail", "tls_fail", - * "upgrade_fail", "timeout". A string literal, so no allocation - * happens on the caller side. + * @param outcome One of the `peer_span::val` dial-outcome constants: + * `connected`, `tcpFail`, `tlsFail`, `upgradeFail`, `timeout`. Taken + * as a string_view over a compile-time constant, so no allocation + * happens on the caller side. The constants are the single source + * for both the counter label and the span attribute, so the two + * cannot drift apart. * * @note Per-connection path: one dial per outbound peer, so this is not * a hot loop. @@ -154,14 +183,17 @@ private: * @note Known limitation: an attempt torn down by overlay shutdown * mid-dial (stop() -> close(), or the operation_aborted early * returns) is deliberately not counted -- it has no network - * outcome to attribute. + * outcome to attribute. The span is still ended, by the destructor, + * with no `outcome` attribute: a span whose duration is real but + * whose outcome is absent is exactly what "torn down mid-dial" + * means, and dropping it would instead hide the attempt. * @note MetricsRegistry is already started when this runs: * ApplicationImp::setup() calls startTelemetry() before * ApplicationImp::start() calls overlay_->start(). No-op when * telemetry is compiled out or disabled at runtime. */ void - reportOutcome(char const* outcome); + reportOutcome(std::string_view outcome); template static boost::asio::ip::tcp::endpoint diff --git a/src/xrpld/overlay/detail/PeerImp.cpp b/src/xrpld/overlay/detail/PeerImp.cpp index 17d394fc2e..3f7320370e 100644 --- a/src/xrpld/overlay/detail/PeerImp.cpp +++ b/src/xrpld/overlay/detail/PeerImp.cpp @@ -6,6 +6,7 @@ #include #include #include +#include #include #include #include @@ -39,6 +40,7 @@ #include #include #include +#include #include #include #include @@ -3458,6 +3460,57 @@ PeerImp::getTxSet(std::shared_ptr const& m) const return shaMap; } +telemetry::SpanGuard +PeerImp::startServeSpan(int itype) const +{ + // A fresh trace root: the request arrives from the wire and is handled on a + // shared JtLedgerReq worker, so freshRoot() stops it inheriting whatever + // unrelated span happens to be active on that worker. + auto span = telemetry::SpanGuard::freshRoot( + telemetry::TraceCategory::Ledger, + telemetry::seg::ledger, + telemetry::ledger_span::op::serve); + if (span) + { + // Which of the four request kinds, from the shared rule so no exit can + // disagree with another about the same request. + span.setAttribute( + telemetry::ledger_span::attr::objectType, + telemetry::ledger_span::serveObjectType(itype)); + // Which peer we are serving. Span-only: one metric series per peer id + // would be unbounded, which is why the paired serve_refused_total + // counter deliberately carries no peer label either. + span.setAttribute(telemetry::peer_span::attr::peerId, static_cast(id())); + } + return span; +} + +void +PeerImp::finishServeSpan( + telemetry::SpanGuard& span, + protocol::TMLedgerData const& ledgerData) noexcept +{ + if (!span) + return; + using namespace telemetry; + // `ledgerData` IS the reply, so its node count is the served-node count and + // is 0 on every refusal path. Reading it here rather than accumulating in + // the assembly loop is what keeps the per-node path untouched, and is also + // what lets one rule cover all eight exits. + auto const served = ledgerData.nodes_size(); + span.setAttribute(ledger_span::attr::servedNodes, static_cast(served)); + span.setAttribute( + ledger_span::attr::outcome, ledger_span::serveOutcome(served, Tuning::kSoftMaxReplyNodes)); + // Which ledger was served. Known only once getLedger() succeeded, so it is + // read here rather than at span start. Span-only: a per-ledger value as a + // metric dimension would mint one series per ledger. + if (ledgerData.has_ledgerseq() && ledgerData.ledgerseq() != 0) + { + span.setAttribute( + ledger_span::attr::ledgerSeq, static_cast(ledgerData.ledgerseq())); + } +} + void PeerImp::processLedgerRequest(std::shared_ptr const& m) { @@ -3472,6 +3525,14 @@ PeerImp::processLedgerRequest(std::shared_ptr const& m) bool fatLeaves{true}; auto const itype{m->itype()}; + // Span this serve, and stamp its result on whichever of the eight exits + // below is taken. The scope-exit guard is what makes that exactly-once + // without repeating an emit per branch, and without any exit -- including + // one added later -- being able to forget. + auto serveSpan = startServeSpan(itype); + ScopeExit const finalizeServeSpan{ + [&serveSpan, &ledgerData]() noexcept { PeerImp::finishServeSpan(serveSpan, ledgerData); }}; + if (itype == protocol::liTS_CANDIDATE) { if (sharedMap = getTxSet(m); !sharedMap) diff --git a/src/xrpld/overlay/detail/PeerImp.h b/src/xrpld/overlay/detail/PeerImp.h index 7481939a71..c486e38954 100644 --- a/src/xrpld/overlay/detail/PeerImp.h +++ b/src/xrpld/overlay/detail/PeerImp.h @@ -32,6 +32,7 @@ #include #include #include +#include #include #include @@ -746,6 +747,49 @@ private: void processLedgerRequest(std::shared_ptr const& m); + /** + * Start the `ledger.serve` span for one incoming ledger-data request. + * + * This is the supply side of somebody else's sync: this worker is what a + * syncing peer waits on, and nothing measured how long it takes or whether + * it produced anything at all. A fresh trace root, because the request + * arrives from the wire on a shared `JtLedgerReq` worker whose ambient span + * is unrelated. + * + * @param itype The protobuf `TMLedgerInfoType` the peer requested, used to + * stamp `object_type`. Taken as an int so the shared naming rule + * needs no protobuf dependency. + * @return An active span guard, or a null guard when telemetry is disabled + * or the ledger trace category is off. + * + * @note One call per request, never inside the per-tree-node reply loop. + */ + [[nodiscard]] telemetry::SpanGuard + startServeSpan(int itype) const; + + /** + * End the `ledger.serve` span, stamping what the request produced. + * + * Called from a scope-exit guard in processLedgerRequest, which is what + * makes it exactly-once across that function's eight exits without + * repeating an emit per branch — and what stops an exit added later from + * silently forgetting to record one. + * + * Both recorded values are READ from state that already exists at every + * exit rather than accumulated: `ledgerData` is the reply itself, so its + * node count is the served-node count and is zero on all seven refusal + * paths. The per-node assembly loop is therefore untouched. + * + * @param span The span to finish; a null guard is a no-op. + * @param ledgerData The reply as assembled so far, empty on a refusal. + * + * @note noexcept: it runs from a scope-exit guard, so it must not throw + * even when the function body leaves by exception. Every call it + * makes is itself noexcept. + */ + static void + finishServeSpan(telemetry::SpanGuard& span, protocol::TMLedgerData const& ledgerData) noexcept; + protected: // Kept `protected` so test subclasses (see // TMGetObjectByHash_test) can drive the diff --git a/src/xrpld/overlay/detail/PeerSpanNames.h b/src/xrpld/overlay/detail/PeerSpanNames.h index 6212d8fca2..a578036ad5 100644 --- a/src/xrpld/overlay/detail/PeerSpanNames.h +++ b/src/xrpld/overlay/detail/PeerSpanNames.h @@ -4,12 +4,27 @@ * Compile-time span name constants for peer overlay tracing. * * Used by PeerImp for peer message handling spans (proposals, - * validations). Built on StaticStr/join() from SpanNames.h. + * validations) and by ConnectAttempt for the outbound dial span. + * Built on StaticStr/join() from SpanNames.h. * * Span hierarchy: * * peer.proposal.receive (PeerImp — incoming proposal) * peer.validation.receive (PeerImp — incoming validation) + * peer.dial (ConnectAttempt — outbound connect attempt) + * + * peer.dial is a trace root: it is the first thing a fresh node does, so + * nothing exists yet to parent it to. + * + * +---------------+ starts +----------------------------+ + * | ConnectAttempt|---------->| span "peer.dial" | + * | ::run() | | outcome / remote_endpoint | + * +---------------+ | duration_ms | + * | +----------------------------+ + * | one terminal path ends it (reportOutcome) + * v + * onTimer / onConnect / onHandshake / onWrite / onRead / + * onShutdown / processResponse */ #include @@ -21,6 +36,7 @@ namespace xrpl::telemetry::peer_span { namespace op { inline constexpr auto proposalReceive = makeStr("proposal.receive"); inline constexpr auto validationReceive = makeStr("validation.receive"); +inline constexpr auto dial = makeStr("dial"); } // namespace op // ===== Attribute keys ======================================================== @@ -40,6 +56,47 @@ using ::xrpl::telemetry::attr::peerId; */ inline constexpr auto proposalTrusted = makeStr("proposal_trusted"); inline constexpr auto validationTrusted = makeStr("validation_trusted"); + +/** + * peer.dial attrs (outbound connect attempt). + * + * `outcome` is the same terminal-reason set the `overlay_connect_total` + * counter already labels with, so the span and the counter can be read + * against each other. `remoteEndpoint` says WHICH peer, which the counter + * deliberately cannot carry: one series per peer address would be unbounded + * cardinality, so it stays span-only and Tempo-searchable instead. + * `durationMs` mirrors the `overlay_dial_latency_ms` histogram value onto the + * individual attempt, so one slow dial is findable rather than only visible + * in an aggregate p95. + */ +inline constexpr auto remoteEndpoint = makeStr("remote_endpoint"); +inline constexpr auto durationMs = makeStr("duration_ms"); +inline constexpr auto outcome = makeStr("outcome"); } // namespace attr +// ===== Attribute values ====================================================== + +namespace val { +/** + * peer.dial outcome values. + * + * The identical five slugs `ConnectAttempt::reportOutcome` already passes to + * the `overlay_connect_total` counter, defined here so the span and the + * counter cannot drift apart: the dial state machine names its outcome once + * and both signals receive that same value. + * + * - connected: the peer was activated and added to the overlay. + * - tcp_fail: the TCP connect or local-endpoint read failed. + * - tls_fail: the TLS handshake, slot check or shared value failed. + * - upgrade_fail: TLS succeeded but the HTTP upgrade, protocol negotiation + * or activation was rejected. + * - timeout: the attempt never reached any terminal state in time. + */ +inline constexpr auto connected = makeStr("connected"); +inline constexpr auto tcpFail = makeStr("tcp_fail"); +inline constexpr auto tlsFail = makeStr("tls_fail"); +inline constexpr auto upgradeFail = makeStr("upgrade_fail"); +inline constexpr auto timeout = makeStr("timeout"); +} // namespace val + } // namespace xrpl::telemetry::peer_span