fix(telemetry): create the meter before the first metric is recorded

MetricsRegistry::start() fused three steps with different prerequisites:
the exporter/provider and the synchronous instruments need only config
strings, while the observable gauges read live Application services. The
whole pipeline therefore waited on the latest prerequisite and ran near
the end of setup() -- after beginConsensus() had already recorded the
process's only operating-mode transition. state_changes_total was
emitted into a pipeline that did not exist yet, so the series never
appeared at all.

Split the two halves. start() keeps the provider and the synchronous
instruments and now runs as soon as the registry is constructed; the new
startAsyncGauges() registers the observable callbacks and runs once
overlay_ exists, still before the first consensus round. Application
gains a matching startTelemetryGauges() so each phase has its own call
site and its own precondition.

Move the jq_trans_overflow_total observable out of initSyncInstruments()
into the gauge phase. Its callback reads getOverlay(), which asserts
overlay_ is non-null, so creating it in the early phase armed the reader
thread against a half-built application -- an assert is not caught by
the callback's catch-all. The instrument is an observable counter rather
than a gauge, which is how it was mistaken for a push-only instrument.

Both start log lines are kept, one per phase, because that timeline is
what made the original ordering bug diagnosable.

Comments and preconditions are corrected to state the rule rather than
the current arrangement: start() may only create instruments whose
values are pushed, and any observable whose callback reads a service
belongs in the gauge phase. The gauge precondition now lists the
services the callbacks actually read.
This commit is contained in:
Pratik Mankawde
2026-07-30 19:48:41 +01:00
parent b31183cf78
commit 2a5fdf0857
4 changed files with 322 additions and 71 deletions

View File

@@ -14,11 +14,12 @@
* on the nodestore_state gauge. Also a public static constexpr inline,
* so it runs in both builds for the same reason.
*
* 3. The no-op / telemetry-disabled path — construction, start()/stop()
* lifecycle, and the synchronous record*() methods. Guarded, because
* when XRPL_ENABLE_TELEMETRY is defined MetricsRegistry.cpp is not
* compiled into this binary (see src/tests/libxrpl/CMakeLists.txt) and
* its out-of-line symbols are unresolvable here.
* 3. The no-op / telemetry-disabled path — construction, the two-phase
* start() / startAsyncGauges() / stop() lifecycle, and the synchronous
* record*() methods. Guarded, because when XRPL_ENABLE_TELEMETRY is
* defined MetricsRegistry.cpp is not compiled into this binary (see
* src/tests/libxrpl/CMakeLists.txt) and its out-of-line symbols are
* unresolvable here.
*/
#include <xrpld/telemetry/MetricsRegistry.h>
@@ -430,11 +431,20 @@ TEST(MetricsRegistryScaledMean, default_scale_is_one)
#include <optional>
#include <stdexcept>
#include <string>
#include <string_view>
using namespace xrpl;
namespace {
/**
* OTLP/HTTP endpoint passed to every start() call below. Nothing ever dials
* it -- these tests exercise the no-op path -- it just has to be a plausible
* URL. start() takes `std::string const&`, so call sites construct one from
* this view rather than repeating the literal.
*/
constexpr std::string_view kTestEndpoint{"http://localhost:4318/v1/metrics"};
/**
* Minimal mock ServiceRegistry for MetricsRegistry testing.
*
@@ -728,17 +738,108 @@ TEST_F(MetricsRegistryTest, disabled_start_stop)
telemetry::MetricsRegistry registry(false, mockApp_, j_);
// start() and stop() should be no-ops when disabled.
registry.start("http://localhost:4318/v1/metrics");
registry.start(std::string{kTestEndpoint});
registry.stop();
// Double stop should be safe.
registry.stop();
}
// ---------------------------------------------------------------------------
// The two-phase startup split: start() then startAsyncGauges().
//
// Why the split exists: start() reads only config strings, while the
// observable-instrument callbacks registered by startAsyncGauges() read live
// Application services (getOverlay() asserts overlay_ is non-null). The split
// lets the meter go live before the first consensus round records its
// mode-transition counter, while the callbacks still wait for the subsystems.
//
// SCOPE OF THESE TESTS -- read before adding to them. MetricsRegistry.cpp is
// compiled into this binary ONLY when telemetry is OFF
// (src/tests/libxrpl/CMakeLists.txt:117-126 -- the `else()` branch; when it is
// ON the .cpp needs concrete xrpld types such as LedgerMaster, TxQ, NetworkOPs,
// Overlay and node_store::Database, which a standalone GTest binary cannot
// link). Both start() and startAsyncGauges() therefore compile here to their
// `#else` branch, which only (void)-casts its arguments. So these tests pin the
// API SURFACE -- that both entry points exist, are callable in either order,
// and leave the object usable -- and NOT the gauge behaviour. Real coverage of
// "gauges observe values only after startAsyncGauges()" is unreachable from
// this target; it needs the enabled path plus an in-memory metric reader.
//
// Two properties the production code does NOT have, so nothing below asserts
// them: startAsyncGauges() has no idempotency guard (a second call on the
// enabled path would create a second set of same-named instruments), and
// callbacksDetached_ is one-way, so detachCallbacks() followed by
// startAsyncGauges() would register permanently-dead instruments.
// ---------------------------------------------------------------------------
TEST_F(MetricsRegistryTest, async_gauges_start_after_start_is_safe)
{
telemetry::MetricsRegistry registry(false, mockApp_, j_);
// The documented order: provider/sync instruments first, gauges second.
registry.start(std::string{kTestEndpoint});
registry.startAsyncGauges();
// State: the enable flag is untouched by either phase. Exact value, not
// merely "falsy" -- a phase that flipped it would be a real defect.
EXPECT_EQ(registry.isEnabled(), false);
// Synchronous recording must work off phase 1 alone. This is the whole
// point of the split: nothing here needs the gauges to be registered.
registry.recordRpcStarted("server_info");
registry.recordRpcFinished("server_info", 1000);
registry.stop();
EXPECT_EQ(registry.isEnabled(), false);
}
TEST_F(MetricsRegistryTest, async_gauges_before_start_does_not_break_start)
{
telemetry::MetricsRegistry registry(false, mockApp_, j_);
// Negative path: the mis-ordered call, gauges before the provider exists.
// In THIS build it reaches the (void)-cast stub, so what is actually
// proven is only that the entry point tolerates being called first and
// leaves the object usable -- not that the enabled path's `if (!meter_)`
// guard works, since that guard is inside #ifdef XRPL_ENABLE_TELEMETRY and
// is not compiled here.
registry.startAsyncGauges();
EXPECT_EQ(registry.isEnabled(), false);
// Phase 1 still works afterwards, so the bad call left no state behind.
registry.start(std::string{kTestEndpoint});
registry.recordJobQueued("ledgerData", "ProcessLData");
EXPECT_EQ(registry.isEnabled(), false);
registry.stop();
}
TEST_F(MetricsRegistryTest, async_gauges_respect_the_compile_time_guard)
{
// Constructed with enabled=true, which on the enabled path would register
// instruments for real. In this build XRPL_ENABLE_TELEMETRY is undefined,
// so both phases compile to the (void)-cast stub branch and neither
// touches the mock -- every MockServiceRegistry accessor throws, so a
// callback that actually ran would surface as a thrown exception here.
telemetry::MetricsRegistry registry(true, mockApp_, j_);
// Cause, not just state: the flag really is true, so the no-op below is
// attributable to the compile-time guard and not to an early enabled_
// return.
EXPECT_EQ(registry.isEnabled(), true);
EXPECT_NO_THROW(registry.start(std::string{kTestEndpoint}));
EXPECT_NO_THROW(registry.startAsyncGauges());
EXPECT_NO_THROW(registry.stop());
EXPECT_EQ(registry.isEnabled(), true);
}
TEST_F(MetricsRegistryTest, disabled_recording_methods)
{
telemetry::MetricsRegistry registry(false, mockApp_, j_);
registry.start("http://localhost:4318/v1/metrics");
registry.start(std::string{kTestEndpoint});
// All recording methods should be no-ops (not crash).
registry.recordRpcStarted("server_info");
@@ -756,7 +857,7 @@ TEST_F(MetricsRegistryTest, destructor_calls_stop)
{
// Let the destructor handle cleanup.
telemetry::MetricsRegistry registry(false, mockApp_, j_);
registry.start("http://localhost:4318/v1/metrics");
registry.start(std::string{kTestEndpoint});
}
// If we get here without crash, the destructor handled stop.
}

View File

@@ -1176,28 +1176,56 @@ private:
startGenesisLedger();
/**
* Start the tracing and metrics pipelines.
* Start the tracing pipeline and the metrics provider and synchronous
* instruments. First of the two telemetry startup phases.
*
* Called once from setup(), just before the [rpc_startup] loop. Starting
* here (rather than in start()) guarantees the OTel MeterProvider is live
* before any metric-emitting code runs — including startup RPCs, whose
* PerfLog instrumentation records a call-site metric. A call-site metric
* macro caches its instrument on first use via std::call_once; if that
* first use happens while the meter is still empty, the instrument latches
* null for the process lifetime and the metric silently never records.
* Called once from setup(), immediately after metricsRegistry_ is
* constructed. Starting here (rather than in start()) guarantees the OTel
* MeterProvider is live before any metric-emitting code runs — including
* the first consensus round, which records a mode-transition counter, and
* the startup RPCs, whose PerfLog instrumentation records a call-site
* metric. A call-site metric macro caches its instrument on first use via
* std::call_once; if that first use happens while the meter is still
* empty, the instrument latches null for the process lifetime and the
* metric silently never records.
*
* The call site sits after overlay_ and the other subsystems are
* constructed, because the metrics reader thread starts here and its
* observable-gauge callbacks read that state (e.g. getOverlay()); starting
* earlier would let the reader observe a half-built application.
* Rule for keeping this call site valid: only telemetry work that reads
* NO application subsystem may run here. That holds today — this phase
* uses the config strings and the node identity, and creates only
* push-model counters and histograms, which app code records into once
* it is ready. Anything that registers a callback reading a subsystem
* must go in startTelemetryGauges() instead, because a callback
* registered here can fire on the metrics reader thread while the rest of
* the application is still being built.
*
* @pre nodeIdentity_ is populated (needed for the service_instance_id
* fallback), metricsRegistry_ is constructed, and overlay_ (and the other
* subsystems read by observable-gauge callbacks) are constructed.
* fallback) and metricsRegistry_ is constructed.
*/
void
startTelemetry();
/**
* Register the pull-model observable instruments. Second telemetry phase.
*
* Called once from setup(), immediately after overlay_ is constructed.
* Registering an observable instrument arms the metrics reader thread to
* invoke its callback, and those callbacks read application services —
* getOverlay() asserts overlay_ is non-null, and an assert is not caught
* by the callbacks' own try/catch — so this cannot run as early as
* startTelemetry().
*
* @pre startTelemetry() has run, and every service the callbacks read is
* constructed. overlay_ is the binding one: the rest (networkOPs_,
* ledgerMaster_, openLedger_, txQ_, nodeStore_, nodeFamily_,
* validators_, acceptedLedgerCache_, cachedSLEs_, acquireStats_,
* timeKeeper_, relationalDatabase_, inboundLedgers_, feeTrack_) are
* already live by the time startTelemetry() is callable, and
* overlay_ is the only one built after it. See
* MetricsRegistry::startAsyncGauges() for the full list.
*/
void
startTelemetryGauges();
std::shared_ptr<Ledger>
getLastFullLedger();
@@ -1382,11 +1410,18 @@ ApplicationImp::setup(boost::program_options::variables_map const& cmdline)
telemetry_->setServiceInstanceId(toBase58(TokenType::NodePublic, nodeIdentity_->first));
// Create the OTel MetricsRegistry for gap-fill metrics (counters,
// histograms, observable gauges). It is started later, just before the
// [rpc_startup] loop (see startTelemetry()).
// histograms, observable gauges).
metricsRegistry_ = std::make_unique<telemetry::MetricsRegistry>(
telemetry_->isEnabled(), *this, logs_->journal("MetricsRegistry"));
// Start tracing and the metrics provider right away, so the meter exists
// before anything records a metric. beginConsensus() below emits a
// mode-transition counter, and it is the only mode transition the process
// ever makes — a meter created after it would lose that series entirely.
// Only the observable gauges have to wait; they are registered by
// startTelemetryGauges() once overlay_ exists.
startTelemetry();
if (!cluster_->load(config().section(Sections::kClusterNodes)))
{
JLOG(journal_.fatal()) << "Invalid entry in cluster configuration.";
@@ -1462,6 +1497,15 @@ ApplicationImp::setup(boost::program_options::variables_map const& cmdline)
collectorManager_->collector());
add(*overlay_); // add to PropertyStream
// Register the observable instruments now that overlay_ exists. This arms
// the metrics reader thread to invoke their callbacks, several of which
// read getOverlay() — registering earlier would let the reader observe a
// half-built application. The reader thread itself already started in
// startTelemetry() above; this is as early as the callbacks can safely be
// attached, and it is still before beginConsensus() so the gauges cover
// the first round.
startTelemetryGauges();
// start first consensus round
if (!networkOPs_->beginConsensus(ledgerMaster_->getClosedLedger()->header().hash, {}))
{
@@ -1528,16 +1572,6 @@ ApplicationImp::setup(boost::program_options::variables_map const& cmdline)
JLOG(journal_.warn()) << "*** standalone signing solution as soon as possible.";
}
// Start telemetry and metrics now — before the [rpc_startup] loop below —
// so the OTel meter is live before any metric-emitting code runs. Startup
// RPCs invoke PerfLog instrumentation that records a call-site metric; a
// metric macro caches its instrument on first use, so a first use before
// the meter exists would latch null for the process lifetime. Placed here,
// after overlay_ and the other subsystems the observable-gauge callbacks
// read are constructed, so the metrics reader thread never observes a
// half-built application.
startTelemetry();
//
// Execute start up rpc commands.
//
@@ -1636,6 +1670,13 @@ ApplicationImp::startTelemetry()
}
}
void
ApplicationImp::startTelemetryGauges()
{
if (metricsRegistry_)
metricsRegistry_->startAsyncGauges();
}
void
ApplicationImp::run()
{

View File

@@ -229,14 +229,45 @@ MetricsRegistry::start(std::string const& endpoint, std::string const& instanceI
JLOG(journal_.info()) << "MetricsRegistry: starting, endpoint=" << endpoint
<< ", instanceId=" << instanceId;
// Rule for anything added below: this phase may create only instruments
// whose recording is PUSHED from app code -- counters and histograms. An
// instrument registered here is live immediately, and the reader thread
// may invoke a registered callback before the rest of the Application is
// built, so any observable whose callback reads an Application service
// belongs in startAsyncGauges(), not here. That includes observable
// COUNTERS, not just gauges: jq_trans_overflow_total was created here and
// its callback read getOverlay(), which asserts overlay_ is non-null.
initExporterAndProvider(endpoint, instanceId);
initSyncInstruments();
JLOG(journal_.info()) << "MetricsRegistry: provider and instruments ready";
#else
(void)endpoint;
(void)instanceId;
(void)enabled_;
#endif // XRPL_ENABLE_TELEMETRY
}
void
MetricsRegistry::startAsyncGauges()
{
#ifdef XRPL_ENABLE_TELEMETRY
if (!enabled_)
return;
// A mis-ordered call must not crash: without a meter there is nothing to
// create instruments on, so registration is skipped entirely.
if (!meter_)
{
JLOG(journal_.warn()) << "MetricsRegistry: startAsyncGauges() called "
"before start(); no gauges registered";
return;
}
registerAsyncGauges();
JLOG(journal_.info()) << "MetricsRegistry: started successfully";
#else
(void)endpoint;
(void)instanceId;
(void)enabled_;
#endif // XRPL_ENABLE_TELEMETRY
}
@@ -340,30 +371,6 @@ MetricsRegistry::initSyncInstruments()
"validations_checked_total", "Total network validations received and checked");
stateChangesCounter_ =
meter_->CreateUInt64Counter("state_changes_total", "Total operating mode changes");
// jq_trans_overflow_total is observed from Overlay's existing cumulative
// atomic (Overlay::getJqTransOverflow()) rather than pushed. The overlay
// owns the only increment site (PeerImp), so an ObservableCounter reads the
// live total each collection cycle without threading a push path through
// develop-owned overlay code.
jqTransOverflowObservable_ = meter_->CreateInt64ObservableCounter(
"jq_trans_overflow_total", "Total job queue transaction overflows");
jqTransOverflowObservable_->AddCallback(
[](opentelemetry::metrics::ObserverResult result, void* state) {
auto* self = static_cast<MetricsRegistry*>(state);
if (self->callbacksDetached_.load(std::memory_order_acquire))
return;
try
{
opentelemetry::nostd::get<opentelemetry::nostd::shared_ptr<
opentelemetry::metrics::ObserverResultT<int64_t>>>(result)
->Observe(static_cast<int64_t>(self->app_.getOverlay().getJqTransOverflow()));
}
catch (...) // NOLINT(bugprone-empty-catch)
{
// Silently skip on error.
}
},
this);
ledgerHistoryMismatchCounter_ = meter_->CreateUInt64Counter(
"ledger_history_mismatch_total", "Total built-vs-validated ledger mismatches by reason");
txqExpiredCounter_ = meter_->CreateUInt64Counter(
@@ -560,6 +567,7 @@ MetricsRegistry::registerAsyncGauges()
// Each helper creates one observable instrument and attaches one
// callback. Keeping the registration bodies in separate methods
// preserves the 80-line-per-function limit enforced by CLAUDE.md.
registerJqTransOverflowCounter();
registerCacheHitRateGauge();
registerTxqGauge();
registerObjectCountGauge();
@@ -579,6 +587,40 @@ MetricsRegistry::registerAsyncGauges()
registerValidationTotalsCounters();
}
void
MetricsRegistry::registerJqTransOverflowCounter()
{
// jq_trans_overflow_total is observed from Overlay's existing cumulative
// atomic (Overlay::getJqTransOverflow()) rather than pushed. The overlay
// owns the only increment site (PeerImp), so an ObservableCounter reads the
// live total each collection cycle without threading a push path through
// develop-owned overlay code.
//
// Registered with the gauges, not with the synchronous instruments: the
// callback reads getOverlay(), which asserts overlay_ is non-null. Arming
// it any earlier would let a reader tick fire before the overlay exists,
// and an assert is not caught by the try block below.
jqTransOverflowObservable_ = meter_->CreateInt64ObservableCounter(
"jq_trans_overflow_total", "Total job queue transaction overflows");
jqTransOverflowObservable_->AddCallback(
[](opentelemetry::metrics::ObserverResult result, void* state) {
auto* self = static_cast<MetricsRegistry*>(state);
if (self->callbacksDetached_.load(std::memory_order_acquire))
return;
try
{
opentelemetry::nostd::get<opentelemetry::nostd::shared_ptr<
opentelemetry::metrics::ObserverResultT<int64_t>>>(result)
->Observe(static_cast<int64_t>(self->app_.getOverlay().getJqTransOverflow()));
}
catch (...) // NOLINT(bugprone-empty-catch)
{
// Silently skip on error.
}
},
this);
}
void
MetricsRegistry::registerCacheHitRateGauge()
{

View File

@@ -94,11 +94,17 @@
* Example usage:
*
* @code
* // In Application::setup(), after telemetry_ is created:
* // In Application::setup(), after telemetry_ is created. Phase 1 needs
* // only the config strings, so it runs immediately and the meter is live
* // before any metric-emitting code:
* metricsRegistry_ = std::make_unique<telemetry::MetricsRegistry>(
* telemetry_->isEnabled(), app, journal);
* metricsRegistry_->start(setup.exporterEndpoint);
*
* // Later in setup(), once overlay_ exists (the last of the services the
* // callbacks read). Phase 2 registers the observable instruments:
* metricsRegistry_->startAsyncGauges();
*
* // In PerfLogImp::rpcStart():
* if (auto* mr = app_.getMetricsRegistry())
* mr->recordRpcStarted("server_info");
@@ -207,9 +213,9 @@ namespace telemetry {
* catch-all try block so a transient failure never crashes
* the reader thread.
* - ValidationTracker protects its rolling windows internally.
* - start() and stop() are NOT thread-safe with each other and
* must be called from the single Application lifecycle
* thread.
* - start(), startAsyncGauges() and stop() are NOT thread-safe
* with each other and must all be called, in that order, from
* the single Application lifecycle thread.
*
* @note Lifetime:
* - Must be constructed AFTER telemetry_ (reads isEnabled()).
@@ -254,7 +260,24 @@ public:
operator=(MetricsRegistry const&) = delete;
/**
* Initialize the OTel metrics pipeline and register all instruments.
* Initialize the OTel metrics pipeline and create the SYNCHRONOUS
* instruments (counters and histograms).
*
* This is the first of two startup phases, and it can be called as soon
* as the registry is constructed — which is what makes the meter live
* before the first metric-emitting code runs. Startup RPCs and the first
* consensus round both record metrics; a call-site metric macro caches
* its instrument on first use, so a first use before the meter exists
* latches null for the process lifetime.
*
* @note Invariant for future changes: this phase may create only
* instruments with NO Application-reading callback. Push-model
* counters and histograms qualify; app code records into them
* when it is ready. Any observable instrument whose callback
* reads an Application service belongs in `startAsyncGauges()`,
* because registering it here arms the reader thread to invoke
* that callback against a half-built Application. This applies
* to observable COUNTERS as well as gauges.
*
* @param endpoint OTLP/HTTP endpoint URL for metric export
* (e.g. "http://localhost:4318/v1/metrics").
@@ -266,6 +289,37 @@ public:
void
start(std::string const& endpoint, std::string const& instanceId = {});
/**
* Register the pull-model observable instruments — the second startup
* phase. Mostly ObservableGauges, plus the ObservableCounters whose
* source value is already cumulative.
*
* Split from `start()` because the two halves have different
* prerequisites. `start()` needs only config strings; these callbacks
* read live Application services, so this half must run later.
* Registering an observable also arms the reader thread to invoke its
* callback on the next tick, which is why the split is about ordering
* and not just tidiness.
*
* @pre `start()` has already run (the meter exists). If it has not,
* this is a logged no-op rather than a crash.
* @pre Every service the callbacks read is constructed. The full set,
* from the `app.get*()` calls in the registration helpers, is:
* Overlay, OPs (NetworkOPs), LedgerMaster, OpenLedger, TxQ,
* NodeStore, NodeFamily, Validators, AcceptedLedgerCache,
* CachedSLEs, AcquireStats, TimeKeeper, RelationalDatabase,
* InboundLedgers and FeeTrack.
* All but Overlay already exist by the time `start()` is
* callable, so Overlay is what fixes this call's position:
* `ServiceRegistry::getOverlay()` `XRPL_ASSERT`s that
* `overlay_` is non-null, and a reader-thread tick before the
* overlay exists aborts a Debug build. The callbacks' catch-all
* try block does not catch an assert. `getTxQ()` and
* `getRelationalDatabase()` assert likewise.
*/
void
startAsyncGauges();
/**
* Detach all ObservableGauge callbacks so they no-op on the next
* reader-thread tick.
@@ -277,9 +331,15 @@ public:
* guarantees that once `detachCallbacks()` returns, no subsequent
* callback invocation will dereference an already-stopped service.
*
* Idempotent. Safe to call multiple times. Safe to call before
* `start()` (has no effect). The actual SDK-level provider
* shutdown still happens in `stop()`.
* Idempotent, and safe to call multiple times: the flag is one-way,
* only ever set to true, and nothing clears it. The actual
* SDK-level provider shutdown still happens in `stop()`.
*
* @note One-way means this is a shutdown-only call. Calling it before
* `startAsyncGauges()` does not "have no effect" — it
* permanently disarms every gauge the later call registers, so
* the instruments exist but never observe a value. Only call it
* once the process is shutting down.
*/
void
detachCallbacks() noexcept;
@@ -927,15 +987,22 @@ private:
* Register all observable gauge callbacks with the OTel SDK.
* Dispatches to one helper per metric domain so that each helper
* stays well under the 80-line-per-function limit.
*
* Called only from `startAsyncGauges()`, which owns the enabled_ and
* meter_ guards and the Application-state precondition.
*/
void
registerAsyncGauges();
// Per-domain gauge registration helpers. Each creates its instrument
// and attaches a single ObservableGauge callback that reads current
// values from Application services. The callbacks run on the OTel
// Per-domain registration helpers for the async (pull-model) phase.
// Each creates its instrument -- an ObservableGauge, or an
// ObservableCounter where the underlying value is cumulative -- and
// attaches a single callback that reads current values from Application
// services. The callbacks run on the OTel
// PeriodicExportingMetricReader background thread (~10 s tick).
void
registerJqTransOverflowCounter(); // gap-fill: overlay overflow total
void
registerCacheHitRateGauge(); // Task 9.2
void
registerTxqGauge(); // Task 9.3