ARCHIVE/rippled
1
0
Fork 0
mirror of https://github.com/XRPLF/rippled.git synced 2026-08-21 22:30:57 +00:00
Code Issues Packages Projects Releases Wiki Activity

feat(telemetry): add tx-set, acquire-phase, dial and serve spans (WP-B2)

Browse Source 
Four blind spots in the sync exchange, each now a span:

- txset.acquire: transaction-set acquisition had no span at all, though it
  is the sibling of ledger.acquire and runs every consensus round. A round
  that falls behind because its tx set never arrived was indistinguishable
  from one that deliberated slowly.
- ledger.acquire.{header,astree,txtree}: the acquire span was flat, so the
  account-state tree, which dominates a fresh sync, could not be separated
  from the transaction tree. These are children, closed before the parent.
- peer.dial: the outbound dial already had outcome counters; the span adds
  the per-attempt timeline, so a slow stage is visible rather than only its
  terminal reason.
- ledger.serve: serving a peer's ledger request was uninstrumented, so this
  node's contribution to someone else's sync was invisible.

Every span finalizes exactly once. Outcomes come from shared compile-time
rules rather than a literal per branch, so no exit can mislabel itself and
an exit added later cannot omit one. Destructor paths are noexcept.

One rule needed care: the timeout path also sets the failure flag, because
that is how the timeout loop stops, so precedence puts timeout ahead of
failure or a timed-out acquire would read as a data fault.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
Pratik Mankawde
2026-07-25 20:19:10 +01:00
parent 92729bacce
commit ce7e119260
12 changed files with 1478 additions and 47 deletions
Download Patch File Download Diff File Expand all files Collapse all files

451
src/tests/libxrpl/telemetry/LedgerSpanNames.cpp
View File

@@ -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 <xrpld/app/ledger/detail/...>. 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 <xrpld/app/ledger/detail/...> and
* <xrpld/overlay/detail/...>. 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 <xrpld/app/ledger/detail/LedgerSpanNames.h>
#include <xrpld/overlay/detail/PeerSpanNames.h>
#include <xrpl/telemetry/SpanGuard.h>
#include <xrpl/telemetry/SpanNames.h>
#include <gtest/gtest.h>
#include <array>
#include <cstddef>
#include <cstdint>
#include <optional>
#include <string_view>
@@ -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<std::string_view, 5> 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<bool>(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<std::int64_t>(21));
guard.setAttribute(ledger_span::attr::durationMs, static_cast<std::int64_t>(5250));
guard.setAttribute(ledger_span::attr::peerCount, static_cast<std::int64_t>(0));
// InboundLedger::beginPhaseSpan() / endPhaseSpan()
guard.setAttribute(ledger_span::attr::ledgerHash, "FEDCBA9876543210");
guard.setAttribute(ledger_span::attr::ledgerSeq, static_cast<std::int64_t>(9000));
guard.setAttribute(ledger_span::attr::timedOut, true);
guard.setAttribute(ledger_span::attr::missingNodes, static_cast<std::int64_t>(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<std::int64_t>(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<std::int64_t>(15000));
// Still inactive: no span was created, so none can be exported.
EXPECT_FALSE(static_cast<bool>(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<bool>(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<bool>(childOfCtx));
EXPECT_FALSE(guard.spanContext().isValid());
}
} // namespace
#endif // XRPL_ENABLE_TELEMETRY

91
src/xrpld/app/ledger/InboundLedger.h
View File

@@ -29,6 +29,7 @@
#include <optional>
#include <set>
#include <string>
#include <string_view>
#include <utility>
#include <vector>
@@ -278,6 +279,70 @@ private:
void
finalizeAcquireSpan(std::optional<std::size_t> 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<telemetry::SpanGuard>& 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<telemetry::SpanGuard>& span,
bool complete,
std::optional<int> missingNodes) noexcept;
clock_type& clock_;
clock_type::time_point lastAction_;
@@ -336,6 +401,32 @@ private:
* thread's context stack.
*/
std::optional<telemetry::SpanGuard> 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<telemetry::SpanGuard> headerSpan_;
std::optional<telemetry::SpanGuard> asTreeSpan_;
std::optional<telemetry::SpanGuard> 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

170
src/xrpld/app/ledger/detail/InboundLedger.cpp
View File

@@ -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<telemetry::SpanGuard>& 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<std::int64_t>(seq_));
}
span.emplace(std::move(child));
}
void
InboundLedger::endPhaseSpan(
std::optional<telemetry::SpanGuard>& span,
bool complete,
std::optional<int> 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<std::int64_t>(*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<std::size_t> 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<Peer> 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<Peer> 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;

252
src/xrpld/app/ledger/detail/LedgerSpanNames.h
View File

@@ -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 <xrpl/telemetry/SpanNames.h>
@@ -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

158
src/xrpld/app/ledger/detail/TransactionAcquire.cpp
View File

@@ -2,6 +2,7 @@
#include <xrpld/app/ledger/ConsensusTransSetSF.h>
#include <xrpld/app/ledger/InboundTransactions.h>
#include <xrpld/app/ledger/detail/LedgerSpanNames.h>
#include <xrpld/app/ledger/detail/TimeoutCounter.h>
#include <xrpld/app/main/Application.h>
#include <xrpld/overlay/PeerSet.h>
@@ -14,11 +15,14 @@
#include <xrpl/shamap/SHAMap.h>
#include <xrpl/shamap/SHAMapAddNode.h>
#include <xrpl/shamap/SHAMapMissingNode.h>
#include <xrpl/telemetry/SpanGuard.h>
#include <xrpl.pb.h>
#include <algorithm>
#include <chrono>
#include <cstddef>
#include <cstdint>
#include <exception>
#include <memory>
#include <utility>
@@ -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<std::int64_t>(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::int64_t>(std::chrono::duration_cast<std::chrono::milliseconds>(
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<std::int64_t>(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<SHAMap> 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<SHAMap> 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);

104
src/xrpld/app/ledger/detail/TransactionAcquire.h
View File

@@ -10,16 +10,59 @@
#include <xrpl/basics/base_uint.h>
#include <xrpl/shamap/SHAMap.h>
#include <xrpl/shamap/SHAMapAddNode.h>
#include <xrpl/telemetry/SpanGuard.h>
#include <chrono>
#include <cstddef>
#include <memory>
#include <optional>
#include <utility>
#include <vector>
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<TransactionAcquire>,
public CountedObject<TransactionAcquire>
@@ -28,7 +71,7 @@ public:
using pointer = std::shared_ptr<TransactionAcquire>;
TransactionAcquire(Application& app, uint256 const& hash, std::unique_ptr<PeerSet> peerSet);
~TransactionAcquire() override = default;
~TransactionAcquire() override;
SHAMapAddNode
takeNodes(
@@ -46,6 +89,33 @@ private:
bool haveRoot_{false};
std::unique_ptr<PeerSet> 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<telemetry::SpanGuard> acquireSpan_;
void
onTimer(bool progress, ScopedLockType& peerSetLock) override;
@@ -59,6 +129,36 @@ private:
trigger(std::shared_ptr<Peer> const&);
std::weak_ptr<TimeoutCounter>
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

92
src/xrpld/overlay/detail/ConnectAttempt.cpp
View File

@@ -10,6 +10,7 @@
#include <xrpld/overlay/detail/Handshake.h>
#include <xrpld/overlay/detail/OverlayImpl.h>
#include <xrpld/overlay/detail/PeerImp.h>
#include <xrpld/overlay/detail/PeerSpanNames.h>
#include <xrpld/overlay/detail/ProtocolVersion.h>
#include <xrpld/peerfinder/PeerfinderManager.h>
#include <xrpld/peerfinder/Slot.h>
@@ -17,6 +18,7 @@
#include <xrpl/basics/Log.h>
#include <xrpl/beast/net/IPAddressConversion.h>
#include <xrpl/beast/net/IPEndpoint.h>
#include <xrpl/beast/utility/Journal.h>
#include <xrpl/beast/utility/instrumentation.h>
#include <xrpl/json/json_reader.h>
@@ -24,6 +26,8 @@
#include <xrpl/protocol/PublicKey.h>
#include <xrpl/protocol/tokens.h>
#include <xrpl/resource/Consumer.h>
#include <xrpl/telemetry/SpanGuard.h>
#include <xrpl/telemetry/SpanNames.h>
#include <boost/asio/bind_executor.hpp>
#include <boost/asio/buffer.hpp>
@@ -41,10 +45,12 @@
#include <chrono>
#include <cstddef>
#include <cstdint>
#include <exception>
#include <memory>
#include <optional>
#include <string>
#include <string_view>
#include <utility>
#include <vector>
@@ -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::int64_t>(std::chrono::duration_cast<std::chrono::milliseconds>(
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<bool>(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;
}

42
src/xrpld/overlay/detail/ConnectAttempt.h
View File

@@ -10,12 +10,15 @@
#include <xrpl/beast/utility/Journal.h>
#include <xrpl/beast/utility/WrappedSink.h>
#include <xrpl/resource/Consumer.h>
#include <xrpl/telemetry/SpanGuard.h>
#include <chrono>
#include <cstdint>
#include <memory>
#include <optional>
#include <sstream>
#include <string>
#include <string_view>
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<telemetry::SpanGuard> 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 <class = void>
static boost::asio::ip::tcp::endpoint

61
src/xrpld/overlay/detail/PeerImp.cpp
View File

@@ -6,6 +6,7 @@
#include <xrpld/app/ledger/InboundTransactions.h>
#include <xrpld/app/ledger/LedgerMaster.h>
#include <xrpld/app/ledger/TransactionMaster.h>
#include <xrpld/app/ledger/detail/LedgerSpanNames.h>
#include <xrpld/app/misc/Transaction.h>
#include <xrpld/app/misc/ValidatorList.h>
#include <xrpld/consensus/ConsensusSpanNames.h>
@@ -39,6 +40,7 @@
#include <xrpl/basics/chrono.h>
#include <xrpl/basics/random.h>
#include <xrpl/basics/safe_cast.h>
#include <xrpl/basics/scope.h>
#include <xrpl/basics/strHex.h>
#include <xrpl/beast/utility/Journal.h>
#include <xrpl/beast/utility/Zero.h>
@@ -3458,6 +3460,57 @@ PeerImp::getTxSet(std::shared_ptr<protocol::TMGetLedger> 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<std::int64_t>(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<std::int64_t>(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<std::int64_t>(ledgerData.ledgerseq()));
}
}
void
PeerImp::processLedgerRequest(std::shared_ptr<protocol::TMGetLedger> const& m)
{
@@ -3472,6 +3525,14 @@ PeerImp::processLedgerRequest(std::shared_ptr<protocol::TMGetLedger> 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)

44
src/xrpld/overlay/detail/PeerImp.h
View File

@@ -32,6 +32,7 @@
#include <xrpl/resource/Consumer.h>
#include <xrpl/resource/Fees.h>
#include <xrpl/server/Handoff.h>
#include <xrpl/telemetry/SpanGuard.h>
#include <boost/circular_buffer.hpp>
#include <boost/endian/conversion.hpp>
@@ -746,6 +747,49 @@ private:
void
processLedgerRequest(std::shared_ptr<protocol::TMGetLedger> 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

59
src/xrpld/overlay/detail/PeerSpanNames.h
View File

@@ -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 <xrpl/telemetry/SpanNames.h>
@@ -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