diff --git a/include/xrpl/consensus/ConsensusSpanNames.h b/include/xrpl/consensus/ConsensusSpanNames.h index e9d073b5e9..db649443a4 100644 --- a/include/xrpl/consensus/ConsensusSpanNames.h +++ b/include/xrpl/consensus/ConsensusSpanNames.h @@ -59,7 +59,9 @@ * | Attrs: proposers, round_time_ms, quorum * | | * | +-- consensus.accept.apply [jtACCEPT thread, child of accept] - * | Created: Adaptor::doAccept() + * | Created: Adaptor::doAccept(), scoped: the txq spans doAccept + * | goes on to create nest under it; the tx apply-stage + * | spans are hash-derived roots and do not * | Attrs: ledger_seq, close_time_ripple_epoch_s, close_time_correct, * | close_resolution_ms, consensus_state, proposing, round_time_ms, * | parent_close_time_ripple_epoch_s, close_time_self_ripple_epoch_s, @@ -71,7 +73,7 @@ * | Attrs: ledger_seq, proposing * | * +-- consensus.mode_change [main thread] - * Created: Adaptor::onModeChange() + * Created: Adaptor::onModeChange(), only when the mode moves * Attrs: mode_old, mode_new * * Standalone spans (no parent, created per-message in overlay): diff --git a/include/xrpl/telemetry/SpanGuard.h b/include/xrpl/telemetry/SpanGuard.h index 10a4a80b4a..24ae206694 100644 --- a/include/xrpl/telemetry/SpanGuard.h +++ b/include/xrpl/telemetry/SpanGuard.h @@ -918,6 +918,15 @@ public: void addEvent(std::string_view name) noexcept; + /** + * Add a named event with key-value attributes to the span's timeline. + * No-op on a null guard. + * @param name Event name. + * @param attrs Attribute pairs (all string_view for simplicity). + */ + void + addEvent(std::string_view name, std::initializer_list attrs) noexcept; + /** * Record an exception as a span event and mark status as error. * No-op on a null guard. @@ -1355,6 +1364,10 @@ public: { } void + addEvent(std::string_view, std::initializer_list) noexcept + { + } + void recordException(std::exception const&) noexcept { } diff --git a/src/libxrpl/telemetry/SpanGuard.cpp b/src/libxrpl/telemetry/SpanGuard.cpp index 4939fb012a..5ec341a5fd 100644 --- a/src/libxrpl/telemetry/SpanGuard.cpp +++ b/src/libxrpl/telemetry/SpanGuard.cpp @@ -863,6 +863,14 @@ ScopedSpanGuard::addEvent(std::string_view name) noexcept impl_->guard.addEvent(name); } +void +ScopedSpanGuard::addEvent( + std::string_view name, + std::initializer_list attrs) noexcept +{ + impl_->guard.addEvent(name, attrs); +} + void ScopedSpanGuard::recordException(std::exception const& e) noexcept { diff --git a/src/tests/libxrpl/telemetry/SpanGuardScope.cpp b/src/tests/libxrpl/telemetry/SpanGuardScope.cpp index 9f266c4c2a..c84fef9b63 100644 --- a/src/tests/libxrpl/telemetry/SpanGuardScope.cpp +++ b/src/tests/libxrpl/telemetry/SpanGuardScope.cpp @@ -59,6 +59,7 @@ #include #include +#include #include #include #include @@ -673,6 +674,85 @@ TEST_F(SpanGuardScopeTest, spanGuard_addEvent_without_attributes_records_bare_ev EXPECT_EQ(events.front().GetAttributes().size(), 0u); } +// The scoped guard records event attributes too. consensus.accept.apply relies +// on it for one tx.included event per transaction of the accepted set. +TEST_F(SpanGuardScopeTest, scopedGuard_addEvent_records_name_and_attribute_values) +{ + namespace cs = consensus::span; + + static constexpr std::string_view kEventName{cs::event::txIncluded}; + static constexpr std::string_view kTxIdKey{cs::attr::txId}; + static constexpr std::string_view kTxId{"6B5F1A2C3D4E5F60718293A4B5C6D7E8"}; + + { + ScopedSpanGuard guard(TraceCategory::Consensus, seg::consensus, cs::op::acceptApply); + ASSERT_TRUE(static_cast(guard)); + guard.addEvent(kEventName, {{kTxIdKey, kTxId}}); + } + + auto spans = spanData()->GetSpans(); + auto* applySpan = findSpan(spans, cs::acceptApply); + ASSERT_NE(applySpan, nullptr); + + auto const& events = applySpan->GetEvents(); + ASSERT_EQ(events.size(), 1u); + EXPECT_EQ(events.front().GetName(), std::string(kEventName)); + EXPECT_EQ(events.front().GetAttributes().size(), 1u); + EXPECT_EQ(eventAttribute(events.front(), kTxIdKey), std::string(kTxId)); +} + +// A scoped child of a captured context is the ambient parent of the spans +// created after it on the same thread. A hash-derived root created inside that +// scope stays a root. consensus.accept.apply relies on both. +TEST_F(SpanGuardScopeTest, scopedChildOfCapturedContextIsAmbientForLaterSpans) +{ + namespace cs = consensus::span; + + auto const h = makeTraceIdBytes(); + { + // consensus.accept: unscoped, thread-free, context captured. + auto accept = + SpanGuard::freshRoot(TraceCategory::Consensus, seg::consensus, cs::op::accept); + ASSERT_TRUE(static_cast(accept)); + auto const acceptCtx = accept.spanContext(); + + // consensus.accept.apply: scoped child of that context. + ScopedSpanGuard const apply = ScopedSpanGuard::childSpan(cs::acceptApply, acceptCtx); + ASSERT_TRUE(static_cast(apply)); + + // ledger.build: a plain ambient scoped guard. + { + ScopedSpanGuard const build(TraceCategory::Ledger, seg::ledger, "build"); + ASSERT_TRUE(static_cast(build)); + } + + // ledger.store: hash-derived, so a deterministic root. + { + auto store = + SpanGuard::hashSpan(TraceCategory::Ledger, "ledger.store", h.data(), h.size()); + ASSERT_TRUE(static_cast(store)); + } + } + + auto spans = spanData()->GetSpans(); + auto* accept = findSpan(spans, cs::accept); + auto* apply = findSpan(spans, cs::acceptApply); + auto* build = findSpan(spans, "ledger.build"); + auto* store = findSpan(spans, "ledger.store"); + ASSERT_NE(accept, nullptr); + ASSERT_NE(apply, nullptr); + ASSERT_NE(build, nullptr); + ASSERT_NE(store, nullptr); + + EXPECT_EQ(apply->GetParentSpanId(), accept->GetSpanId()); + // build nests under apply, not beside it. + EXPECT_EQ(build->GetParentSpanId(), apply->GetSpanId()); + EXPECT_EQ(build->GetTraceId(), apply->GetTraceId()); + // The hash-derived span is a root on its own pinned trace id. + EXPECT_FALSE(store->GetParentSpanId().IsValid()); + EXPECT_TRUE(std::ranges::equal(store->GetTraceId().Id(), h)); +} + // A forced-root span started while a PendingTraceId is active adopts that // pinned 16-byte trace_id and remains a true root (no parent). TEST_F(SpanGuardScopeTest, deterministicIdGenerator_forced_root_gets_pending_trace_id) diff --git a/src/xrpld/app/consensus/RCLConsensus.cpp b/src/xrpld/app/consensus/RCLConsensus.cpp index 3763fc9316..c1d2834653 100644 --- a/src/xrpld/app/consensus/RCLConsensus.cpp +++ b/src/xrpld/app/consensus/RCLConsensus.cpp @@ -595,10 +595,9 @@ RCLConsensus::Adaptor::doAccept( { namespace cs = telemetry::consensus::span; - // Make the accept span ambient for the whole accept so doAccept's log lines - // (and any spans created here) correlate to it. Non-owning: acceptSpan still - // owns/ends the span. doAccept runs to completion on the JtAccept worker - // (no coroutine yield), so this scope is thread-local and safe. + // Make the accept span ambient until accept.apply opens below. Non-owning: + // acceptSpan still owns and ends the span. doAccept runs to completion on + // one thread, so the scope pops on the thread that pushed it. auto acceptActivation = telemetry::activateIfLive(acceptSpan); prevProposers_ = result.proposers; @@ -627,13 +626,10 @@ RCLConsensus::Adaptor::doAccept( closeTimeCorrect = true; } - // Parent accept.apply via the captured accept context (acceptSpanContext_): - // the accept span is a thread-free SpanGuard, so an explicit context is - // used for both the sync (onForceAccept) and async (onAccept) paths. Falls - // back to the round context if the accept span was null. - auto doAcceptSpan = acceptSpanContext_.isValid() - ? telemetry::SpanGuard::childSpan(cs::acceptApply, acceptSpanContext_) - : telemetry::SpanGuard::childSpan(cs::acceptApply, roundSpanContext_); + // Scoped: accept.apply is the ambient parent of every span doAccept creates + // from here on. Parented through acceptSpanContext_ because the accept span + // is a thread-free SpanGuard; the context is valid whenever that span is live. + auto doAcceptSpan = telemetry::ScopedSpanGuard::childSpan(cs::acceptApply, acceptSpanContext_); doAcceptSpan.setAttribute(cs::attr::ledgerSeq, static_cast(prevLedger.seq()) + 1); doAcceptSpan.setAttribute( cs::attr::closeTimeRippleEpochS, @@ -1139,9 +1135,16 @@ RCLConsensus::Adaptor::onModeChange(ConsensusMode before, ConsensusMode after) // thread-free SpanGuard, so parent explicitly via its context). A mode // change outside a round leaves roundSpanContext_ invalid, yielding a null // guard (no-op). - auto span = telemetry::SpanGuard::childSpan(cs::modeChange, roundSpanContext_); - span.setAttribute(cs::attr::modeOld, toDisplayString(before).c_str()); - span.setAttribute(cs::attr::modeNew, toDisplayString(after).c_str()); + // + // Only a real transition gets a span. MonitoredMode::set also calls this + // on every round start; the round's mode attribute below still needs that + // call, the span does not. + if (before != after) + { + auto span = telemetry::SpanGuard::childSpan(cs::modeChange, roundSpanContext_); + span.setAttribute(cs::attr::modeOld, toDisplayString(before).c_str()); + span.setAttribute(cs::attr::modeNew, toDisplayString(after).c_str()); + } JLOG(j_.info()) << "Consensus mode change before=" << to_string(before) << ", after=" << to_string(after);