diff --git a/docker/telemetry/TESTING.md b/docker/telemetry/TESTING.md index 128687622c..fbb07247a8 100644 --- a/docker/telemetry/TESTING.md +++ b/docker/telemetry/TESTING.md @@ -91,7 +91,12 @@ curl -s http://localhost:5005 \ ### Step 4: Submit a transaction -Close the ledger first (required in standalone mode): +Close the ledger to drive a simulated consensus round — that round is what +produces the `consensus.*` spans. It is not required for `submit` itself: +standalone puts the node in `OperatingMode::FULL` at startup +(`NetworkOPsImp::setStandAlone()`), and the one validated-ledger-age gate on +the submit path is skipped when `config.standalone()` is set +(`checkTxJsonFields()` in `src/xrpld/rpc/detail/TransactionSign.cpp`). ```bash curl -s http://localhost:5005 -d '{"method":"ledger_accept"}' @@ -107,7 +112,7 @@ curl -s http://localhost:5005 -d '{ "tx_json": { "TransactionType": "Payment", "Account": "rHb9CJAWyB4rj91VRWn96DkukG4bwdtyTh", - "Destination": "rPMh7Pi9ct699iZUTWzJaUMR1o42VEfGqF", + "Destination": "rN7n7otQDd6FczFgLdSqtcsAUxDkw6fzRH", "Amount": "10000000" } }] @@ -116,6 +121,12 @@ curl -s http://localhost:5005 -d '{ Expected result: `"tesSUCCESS"`. +The destination does not have to exist yet. 10 XRP is exactly the default base +reserve (`FeeSetup::accountReserve` in `src/xrpld/core/Config.h`), so the +payment creates and funds the account. `integration-test.sh` does not hardcode +a destination at all — it calls `wallet_propose` and uses the `account_id` that +comes back. + Close the ledger again to finalize: ```bash @@ -132,7 +143,7 @@ Or open Grafana Explore with Tempo datasource: http://localhost:3000 ```bash # Kill xrpld (Ctrl+C or) -kill $(pgrep -f 'xrpld.*xrpld-telemetry') +pkill -f 'xrpld --conf docker/telemetry/xrpld-telemetry\.cfg' # Stop observability stack docker compose -f docker/telemetry/docker-compose.yml down @@ -141,21 +152,70 @@ docker compose -f docker/telemetry/docker-compose.yml down rm -rf docker/telemetry/data/ ``` +The pattern is anchored on the whole `--conf ` argument with the `.` +escaped, so it matches this node and not another xrpld run or an editor whose +command line happens to name the same file. `pkill` is also a no-op when +nothing matches, where `kill $(pgrep ...)` errors out with no arguments. + ### Expected spans (standalone mode) -| Span Name | Expected | Notes | -| ---------------------------------------------------------------------------------------------------------- | -------- | ------------------------------------------------- | -| `rpc.http_request` | Yes | Every HTTP RPC call | -| `rpc.process` | Yes | Every RPC processing | -| `rpc.command.server_info` | Yes | server_info RPC | -| `rpc.command.server_state` | Yes | server_state RPC | -| `rpc.command.ledger` | Yes | ledger RPC | -| `rpc.command.submit` | Yes | submit RPC | -| `rpc.command.ledger_accept` | Yes | ledger_accept RPC | -| `tx.process` | Yes | Transaction submission | -| `tx.receive` | No | No peers in standalone | -| `consensus.round`, `.phase.open`, `.ledger_close`, `.accept`, `.accept.apply` | Yes | `ledger_accept` drives a simulated round | -| `consensus.establish`, `.update_positions`, `.check`, `.proposal.*`, `.validation.receive`, `.mode_change` | No | `simulate` jumps straight to `Accepted`; no peers | +| Span Name | Expected | Notes | +| ----------------------------------------------------------------------------- | -------- | ------------------------------------------ | +| `rpc.http_request` | Yes | Every HTTP RPC call | +| `rpc.process` | Yes | Every RPC processing | +| `rpc.command.server_info` | Yes | server_info RPC | +| `rpc.command.server_state` | Yes | server_state RPC | +| `rpc.command.ledger` | Yes | ledger RPC | +| `rpc.command.submit` | Yes | submit RPC | +| `rpc.command.ledger_accept` | Yes | ledger_accept RPC | +| `rpc.ws_upgrade`, `rpc.ws_message` | No | Need a WebSocket client | +| `tx.process` | Yes | Transaction submission | +| `tx.preflight`, `tx.preclaim`, `tx.transactor` | Yes | Apply stages of the Payment | +| `tx.apply` | Yes | Ledger build applies the tx set | +| `tx.receive` | No | No peers in standalone | +| `txq.enqueue`, `txq.apply_direct` | Yes | `TxQ::apply` on the submit path | +| `txq.accept`, `txq.cleanup` | Yes | Run on every ledger close | +| `txq.accept_tx`, `txq.batch_clear` | No | Nothing is ever queued here | +| `ledger.build`, `ledger.store` | Yes | `buildLCL` builds, then stores | +| `ledger.validate` | No | `checkAccept` is unreachable in standalone | +| `consensus.round`, `.phase.open`, `.ledger_close`, `.accept`, `.accept.apply` | Yes | `ledger_accept` drives a simulated round | +| `consensus.mode_change` | Yes | Fires once per round start | +| `consensus.establish`, `.update_positions`, `.check` | No | `phaseEstablish()` never runs | +| `consensus.proposal.send`, `.validation.send` | No | The config carries no validator key | +| `consensus.proposal.receive`, `.validation.receive` | No | No peers | +| `peer.proposal.receive`, `peer.validation.receive` | No | No peers | +| `pathfind.*` | No | No path request, no path subscription | +| `grpc.*` | No | No `[port_grpc]` in the config | + +Four of the "No" rows have a reason worth spelling out. + +- `ledger.validate` belongs to `LedgerMaster::checkAccept`, and standalone never + reaches it: `consensusBuilt` returns early when standalone, and `switchLCL` + takes its standalone branch instead of calling `checkAccept`. That + `getNeededValidations()` returns 0 in standalone is therefore not enough on its + own. +- `consensus.establish`, `.update_positions` and `.check` are started from + `phaseEstablish()`. `simulate` does call `closeLedger({})` — which is exactly + why `.phase.open` and `.ledger_close` do fire — and then sets the phase to + `Accepted` itself, so `phaseEstablish()` is never entered. +- `.proposal.send` and `.validation.send` are absent for a different reason + again: `xrpld-telemetry.cfg` carries no `validation_seed` or + `validator_token`, so `preStartRound` leaves `validating_` false. The node + observes rather than proposes, and `validate()` — the owner of + `.validation.send` — is never called. +- `pathfind.update_all` is emitted only while at least one path subscription is + active, and this test makes no `path_find` or `ripple_path_find` call. + +`.mode_change` is in the "Yes" rows because it does not depend on the mode +actually changing. `startRoundInternal` calls `mode_.set()`, `MonitoredMode::set` +calls `onModeChange` with no equality test, and `onModeChange` creates the span +before the `before != after` check — that check guards only the censorship-detector +reset. + +One `consensus.round` span reaches Tempo, not two. `roundSpan_` is reset only at +the top of the next `startRoundTracing()`, so after the two `ledger_accept` calls +the first round's span has ended and been exported while the second is still open. +Only ended spans are exported. --- @@ -174,7 +234,7 @@ bash docker/telemetry/integration-test.sh It checks prerequisites, clears the previous run, brings up the observability stack, generates six validator key pairs and their node configs, starts the nodes, waits for consensus and then for a validated ledger, exercises RPC and submits a transaction, verifies traces in Tempo and both the span_metrics and the native `beast::insight` metrics that arrive over OTLP in Prometheus, checks that no StatsD listener is needed, then prints a summary and leaves the stack running. -The script announces each step as it runs, so read its `Step N:` headers for the authoritative sequence — they are not restated here, because a numbered copy of them drifts as soon as a step is added. +The authoritative sequence is the 14 `# Step N:` banner comments in the script source, so read the file rather than the console — none of the script's 48 runtime `log` lines print a step number. The sequence is not restated here, because a numbered copy of it drifts as soon as a step is added. Its Tempo checks cover the RPC, transaction, consensus, ledger and peer span categories from a fixed list, which is narrower than the loop in the "Verification Queries" section below. @@ -351,7 +411,7 @@ curl -s http://localhost:5005 -d '{ "tx_json": { "TransactionType": "Payment", "Account": "rHb9CJAWyB4rj91VRWn96DkukG4bwdtyTh", - "Destination": "rPMh7Pi9ct699iZUTWzJaUMR1o42VEfGqF", + "Destination": "rN7n7otQDd6FczFgLdSqtcsAUxDkw6fzRH", "Amount": "10000000" } }] @@ -360,9 +420,13 @@ curl -s http://localhost:5005 -d '{ Expected result: `"tesSUCCESS"`, the same as Test 1 Step 4. -Wait 15 seconds for consensus and batch export. +Wait 15 seconds for the consensus round and the trace batch export. Prometheus +needs longer: `integration-test.sh` waits a further 20 s before its span_metrics +queries and another 20 s before its StatsD queries, so 35 s and 55 s after the +submit. Querying the metrics block at 15 s returns no series, which looks like a +broken pipeline and is not one. -#### Step 8: Verify in Tempo +#### Step 8: Verify in Tempo and Prometheus See the "Verification Queries" section below. @@ -403,29 +467,76 @@ Attributes are deliberately not repeated here. Keeping a second copy is how this Base URL: `http://localhost:3200` +Run `RUN_START=$(date +%s)` **before** starting xrpld (Test 1 Step 2, Test 2 +Step 5), in the same shell you will run the block below in. Tempo keeps blocks +for `block_retention` (`tempo.yaml`, 1h) on a named volume, so a search with no +time bound is answered by the previous run's traces. + ```bash TEMPO="http://localhost:3200" +# Refuse to run unbounded rather than report a previous run's traces. +: "${RUN_START:?record RUN_START=\$(date +%s) before starting xrpld}" + # List all services curl -s "$TEMPO/api/v2/search/tag/resource.service.name/values" | jq '.tagValues[].value' -# Query traces by operation -for op in "rpc.http_request" "rpc.ws_upgrade" "rpc.ws_message" "rpc.process" \ +# Count traces per span name. Test 1 produces a subset of this list — read it +# against the "Expected spans (standalone mode)" table above, not as pass/fail. +# +# -G is required: it moves the urlencoded parameters into the query string. +# Without it curl POSTs them as a request body, Tempo answers 200 and ignores +# the query, and every span name comes back non-zero. start/end bound the +# search to this run; the end margin covers spans exported while the query is +# in flight. +for op in "rpc.http_request" "rpc.process" \ "rpc.command.server_info" "rpc.command.server_state" "rpc.command.ledger" \ + "rpc.command.submit" "rpc.command.ledger_accept" \ "tx.process" "tx.receive" "tx.apply" \ - "consensus.proposal.send" "consensus.ledger_close" \ + "tx.preflight" "tx.preclaim" "tx.transactor" \ + "txq.enqueue" "txq.apply_direct" "txq.accept" "txq.cleanup" \ + "consensus.round" "consensus.phase.open" "consensus.ledger_close" \ + "consensus.establish" "consensus.update_positions" "consensus.check" \ "consensus.accept" "consensus.accept.apply" \ - "consensus.validation.send" \ + "consensus.proposal.send" "consensus.validation.send" \ + "consensus.mode_change" \ + "consensus.proposal.receive" "consensus.validation.receive" \ "ledger.build" "ledger.validate" "ledger.store" \ "peer.proposal.receive" "peer.validation.receive"; do - count=$(curl -s "$TEMPO/api/search" \ + count=$(curl -sfG "$TEMPO/api/search" \ --data-urlencode "q={resource.service.name=\"xrpld\" && name=\"$op\"}" \ + --data-urlencode "start=$RUN_START" \ + --data-urlencode "end=$(($(date +%s) + 60))" \ --data-urlencode "limit=5" | jq '.traces | length') printf "%-35s %s traces\n" "$op" "$count" done ``` +Eight more span families exist but need a trigger neither test performs, so they +are counted separately — a zero here is the expected answer, not a failure. +`rpc.ws_*` need a WebSocket client, the `pathfind.*` family needs a `path_find` +or `ripple_path_find` call, and the two `txq` names need a transaction sitting in +the queue. + +```bash +for op in "rpc.ws_upgrade" "rpc.ws_message" \ + "pathfind.request" "pathfind.compute" "pathfind.discover" "pathfind.update_all" \ + "txq.accept_tx" "txq.batch_clear"; do + count=$(curl -sfG "$TEMPO/api/search" \ + --data-urlencode "q={resource.service.name=\"xrpld\" && name=\"$op\"}" \ + --data-urlencode "start=$RUN_START" \ + --data-urlencode "end=$(($(date +%s) + 60))" \ + --data-urlencode "limit=5" | + jq '.traces | length') + printf "%-35s %s traces\n" "$op" "$count" +done +``` + +The remaining family is `grpc.`, whose span name is the gRPC method, so +it has no fixed string to query and needs a `[port_grpc]` stanza neither test +configures. + ### Prometheus API Base URL: `http://localhost:9090` @@ -602,7 +713,11 @@ Counting `.data.result | length` would count streams, not log lines. 2. Verify `[ips_fixed]` lists the 5 other peer ports, and not the node's own 3. Verify `validators.txt` has all 6 public keys 4. Check node debug logs: `tail -50 /tmp/xrpld-integration/Node-1/debug.log` -5. Ensure `[peer_private]` is set to `1` (prevents reaching out to public network) +5. Ensure `[peer_private]` is set to `1`. In `src/libxrpl/peerfinder/Config.cpp` + it sets both `autoConnect = !standalone && !peerPrivate` and + `wantIncoming = (!config.peerPrivate) && (port != 0)`, so it stops the node + reaching out to the public network **and** stops it accepting inbound peers. + The nodes here find each other through `[ips_fixed]`, which is unaffected. ### Transaction not processing diff --git a/src/libxrpl/beast/insight/OTelCollector.cpp b/src/libxrpl/beast/insight/OTelCollector.cpp index aba5e59835..9454af2f1f 100644 --- a/src/libxrpl/beast/insight/OTelCollector.cpp +++ b/src/libxrpl/beast/insight/OTelCollector.cpp @@ -548,17 +548,25 @@ public: /** * @brief Register a gauge for observable callback reading. - * @param gauge Pointer to the gauge to register. + * + * Takes the owning shared_ptr so the list can store a weak reference. + * Called from makeGauge() rather than the gauge's constructor, because a + * weak_ptr cannot be formed until the shared_ptr owns the object. + * + * @param gauge Owning pointer to the gauge to register. */ void - addGauge(OTelGaugeImpl* gauge); + addGauge(std::shared_ptr const& gauge); /** - * @brief Unregister a gauge. - * @param gauge Pointer to the gauge to unregister. + * @brief Drop entries for gauges that have been destroyed. + * + * Called from ~OTelGaugeImpl. The dying gauge's weak_ptr has already + * expired by then, so the entry is identified by expiry rather than by + * address. */ void - removeGauge(OTelGaugeImpl* gauge); + removeExpiredGauges(); /** @} */ /** @@ -618,8 +626,17 @@ private: /** * Registered gauges read during observable callbacks. + * + * Weak for the same reason as hooks_. onCollectionReady() and + * onCollectionStopping() snapshot this list and then call arm()/disarm() + * with mutex_ released, because both enter the SDK's observable registry + * lock. A raw pointer copied out of the list could be dangling by then, + * since ~OTelGaugeImpl only re-acquires mutex_ to prune its own entry. + * Locking a weak_ptr keeps the gauge alive for exactly the duration of + * that arm or disarm call, and one destroyed since the snapshot is + * skipped rather than followed. */ - std::vector gauges_; + std::vector> gauges_; /** * @brief Shortest gap between two hook invocations. @@ -714,7 +731,8 @@ OTelEventImpl::notify(value_type const& value) OTelGaugeImpl::OTelGaugeImpl(std::string name, std::shared_ptr const& collector) : name_(std::move(name)), collector_(collector) { - collector_->addGauge(this); + // Registration happens in makeGauge(), not here: no weak_ptr to this + // object exists until the owning shared_ptr does. } void @@ -764,7 +782,7 @@ OTelGaugeImpl::~OTelGaugeImpl() // callback for this instrument is in flight — removal is synchronous. // A no-op when never armed, or already disarmed at shutdown. disarm(); - collector_->removeGauge(this); + collector_->removeExpiredGauges(); } void @@ -893,7 +911,9 @@ OTelCollectorImp::makeEvent(std::string const& name, Unit unit) Gauge OTelCollectorImp::makeGauge(std::string const& name) { - return Gauge(std::make_shared(formatName(name), shared_from_this())); + auto gauge = std::make_shared(formatName(name), shared_from_this()); + addGauge(gauge); + return Gauge(gauge); } Meter @@ -949,17 +969,18 @@ OTelCollectorImp::callHooks() } void -OTelCollectorImp::addGauge(OTelGaugeImpl* gauge) +OTelCollectorImp::addGauge(std::shared_ptr const& gauge) { std::scoped_lock const lock(mutex_); - gauges_.push_back(gauge); + gauges_.emplace_back(gauge); } void -OTelCollectorImp::removeGauge(OTelGaugeImpl* gauge) +OTelCollectorImp::removeExpiredGauges() { std::scoped_lock const lock(mutex_); - std::erase(gauges_, gauge); + std::erase_if( + gauges_, [](std::weak_ptr const& gauge) { return gauge.expired(); }); } void @@ -969,15 +990,24 @@ OTelCollectorImp::onCollectionReady() // observable registry lock, and the reader thread takes that lock before // calling callHooks(), which wants mutex_. callHooks() copies its hook list // for the same reason. - std::vector gauges; + std::vector> gauges; { std::scoped_lock const lock(mutex_); gauges = gauges_; } std::size_t armed = 0; - for (auto* gauge : gauges) + std::size_t live = 0; + for (auto const& weakGauge : gauges) { + // Locking keeps this gauge alive across its own arm() call. One + // destroyed since the snapshot locks to null and is skipped, and is + // not counted in the total below: it has no metric to register. + auto const gauge = weakGauge.lock(); + if (!gauge) + continue; + ++live; + // Telemetry must never stop the node, so one bad instrument costs only // its own metric. try @@ -998,8 +1028,7 @@ OTelCollectorImp::onCollectionReady() if (auto stream = journal_.info()) { - stream << "OTelCollector: registered " << armed << " of " << gauges.size() - << " observable gauges"; + stream << "OTelCollector: registered " << armed << " of " << live << " observable gauges"; } } @@ -1008,17 +1037,26 @@ OTelCollectorImp::onCollectionStopping() { // Same lock discipline as onCollectionReady(): snapshot, then act outside // the lock, because disarm() enters the SDK's observable registry lock. - std::vector gauges; + std::vector> gauges; { std::scoped_lock const lock(mutex_); gauges = gauges_; } - for (auto* gauge : gauges) - gauge->disarm(); + // Locking keeps each gauge alive across its own disarm() call. One already + // destroyed disarmed itself in ~OTelGaugeImpl, so skipping it is correct. + std::size_t disarmed = 0; + for (auto const& weakGauge : gauges) + { + if (auto const gauge = weakGauge.lock()) + { + gauge->disarm(); + ++disarmed; + } + } if (auto stream = journal_.info()) - stream << "OTelCollector: stopped observing " << gauges.size() << " gauges"; + stream << "OTelCollector: stopped observing " << disarmed << " gauges"; } opentelemetry::nostd::shared_ptr const& diff --git a/src/tests/libxrpl/beast/insight/StatsDCollector.cpp b/src/tests/libxrpl/beast/insight/StatsDCollector.cpp index aaab3e571e..8d8c6692b0 100644 --- a/src/tests/libxrpl/beast/insight/StatsDCollector.cpp +++ b/src/tests/libxrpl/beast/insight/StatsDCollector.cpp @@ -1,5 +1,7 @@ #include +#include +#include #include #include