diff --git a/src/tests/libxrpl/telemetry/MetricsRegistry.cpp b/src/tests/libxrpl/telemetry/MetricsRegistry.cpp index f21ddfe831..c6a707cb0c 100644 --- a/src/tests/libxrpl/telemetry/MetricsRegistry.cpp +++ b/src/tests/libxrpl/telemetry/MetricsRegistry.cpp @@ -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 @@ -430,11 +431,20 @@ TEST(MetricsRegistryScaledMean, default_scale_is_one) #include #include #include +#include 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. } diff --git a/src/xrpld/app/main/Application.cpp b/src/xrpld/app/main/Application.cpp index c543e7e628..bb999fc9c1 100644 --- a/src/xrpld/app/main/Application.cpp +++ b/src/xrpld/app/main/Application.cpp @@ -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 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_->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() { diff --git a/src/xrpld/telemetry/MetricsRegistry.cpp b/src/xrpld/telemetry/MetricsRegistry.cpp index 5424e7a8b7..a0eb50ced3 100644 --- a/src/xrpld/telemetry/MetricsRegistry.cpp +++ b/src/xrpld/telemetry/MetricsRegistry.cpp @@ -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(state); - if (self->callbacksDetached_.load(std::memory_order_acquire)) - return; - try - { - opentelemetry::nostd::get>>(result) - ->Observe(static_cast(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(state); + if (self->callbacksDetached_.load(std::memory_order_acquire)) + return; + try + { + opentelemetry::nostd::get>>(result) + ->Observe(static_cast(self->app_.getOverlay().getJqTransOverflow())); + } + catch (...) // NOLINT(bugprone-empty-catch) + { + // Silently skip on error. + } + }, + this); +} + void MetricsRegistry::registerCacheHitRateGauge() { diff --git a/src/xrpld/telemetry/MetricsRegistry.h b/src/xrpld/telemetry/MetricsRegistry.h index 22d7fe2eba..20494999fa 100644 --- a/src/xrpld/telemetry/MetricsRegistry.h +++ b/src/xrpld/telemetry/MetricsRegistry.h @@ -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_->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