From 6535e492467022d524b3af226ba61a126adb6b88 Mon Sep 17 00:00:00 2001 From: DCG-Claude Date: Thu, 24 Sep 2026 11:58:30 -0500 Subject: [PATCH 1/4] Merge bitcoin/bitcoin#28450: Add package evaluation fuzzer 262ab8ef7860d43cebc9d04721e3a075b4edf06e Add package evaluation fuzzer (Greg Sanders) Pull request description: This fuzzer target caught the issue in https://github.com/bitcoin/bitcoin/pull/28251 within 5 minutes on master branch, and an additional issue which I've applied a preliminary patch to cover. Fuzzer target does the following: 1) Picks mempool confgs, including max package size, count, mempool size, etc 2) Generates 1 to 26 transactions with arbitrary coins/fees, the first N-1 spending only confirmed outpoints 3) Nth transaction, if >1, sweeps all unconfirmed outpoints in mempool 4) If N==1, it may submit it through single-tx submission path, to allow for more interesting topologies 5) Otherwise submits through package submission interface 6) Repeat 1-5 a few hundred times per mempool instance In other words, it ends up building chains of txns in the mempool using parents-and-children packages, which is currently the topology supported on master. The test itself is a direct rip of tx_pool.cpp, with a number of assertions removed because they were failing for unknown reasons, likely due to the notification changes of single tx submission to package, which is used to track addition/removal of transactions in the test. I'll continue working on re-adding these assertions for further invariant testing. ACKs for top commit: murchandamus: ACK 262ab8ef7860d43cebc9d04721e3a075b4edf06e glozow: reACK 262ab8ef7860d43cebc9d04721e3a075b4edf06e dergoegge: tACK 262ab8ef7860d43cebc9d04721e3a075b4edf06e Tree-SHA512: 190784777d0f2361b051b3271db8f79b7927e3cab88596d2c30e556da721510bd17f6cc96f6bb03403bbf0589ad3f799fa54e63c1b2bd92a2084485b5e3e96a5 --- src/Makefile.test.include | 1 + src/test/fuzz/package_eval.cpp | 292 +++++++++++++++++++++++++++++++++ 2 files changed, 293 insertions(+) create mode 100644 src/test/fuzz/package_eval.cpp diff --git a/src/Makefile.test.include b/src/Makefile.test.include index 2b9a81623b0f..cb5bf04cb609 100644 --- a/src/Makefile.test.include +++ b/src/Makefile.test.include @@ -353,6 +353,7 @@ test_fuzz_fuzz_SOURCES = \ test/fuzz/netbase_dns_lookup.cpp \ test/fuzz/node_eviction.cpp \ test/fuzz/p2p_transport_serialization.cpp \ + test/fuzz/package_eval.cpp \ test/fuzz/parse_hd_keypath.cpp \ test/fuzz/parse_numbers.cpp \ test/fuzz/parse_script.cpp \ diff --git a/src/test/fuzz/package_eval.cpp b/src/test/fuzz/package_eval.cpp new file mode 100644 index 000000000000..bde01ccaec8b --- /dev/null +++ b/src/test/fuzz/package_eval.cpp @@ -0,0 +1,292 @@ +// Copyright (c) 2023 The Bitcoin Core developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +using node::NodeContext; + +namespace { + +const TestingSetup* g_setup; +std::vector g_outpoints_coinbase_init_mature; + +struct MockedTxPool : public CTxMemPool { + void RollingFeeUpdate() EXCLUSIVE_LOCKS_REQUIRED(!cs) + { + LOCK(cs); + lastRollingFeeUpdate = GetTime(); + blockSinceLastRollingFeeBump = true; + } +}; + +void initialize_tx_pool() +{ + static const auto testing_setup = MakeNoLogFileContext(); + g_setup = testing_setup.get(); + + for (int i = 0; i < 2 * COINBASE_MATURITY; ++i) { + COutPoint prevout{MineBlock(g_setup->m_node, P2SH_OP_TRUE)}; + if (i < COINBASE_MATURITY) { + // Remember the txids to avoid expensive disk access later on + g_outpoints_coinbase_init_mature.push_back(prevout); + } + } + SyncWithValidationInterfaceQueue(); +} + +struct OutpointsUpdater final : public CValidationInterface { + std::set& m_mempool_outpoints; + + explicit OutpointsUpdater(std::set& r) + : m_mempool_outpoints{r} {} + + void TransactionAddedToMempool(const CTransactionRef& tx, int64_t /* nAcceptTime */, uint64_t /* mempool_sequence */) override + { + // for coins spent we always want to be able to rbf so they're not removed + + // outputs from this tx can now be spent + for (uint32_t index{0}; index < tx->vout.size(); ++index) { + m_mempool_outpoints.insert(COutPoint{tx->GetHash(), index}); + } + } + + void TransactionRemovedFromMempool(const CTransactionRef& tx, MemPoolRemovalReason reason, uint64_t /* mempool_sequence */) override + { + // outpoints spent by this tx are now available + for (const auto& input : tx->vin) { + // Could already exist if this was a replacement + m_mempool_outpoints.insert(input.prevout); + } + // outpoints created by this tx no longer exist + for (uint32_t index{0}; index < tx->vout.size(); ++index) { + m_mempool_outpoints.erase(COutPoint{tx->GetHash(), index}); + } + } +}; + +struct TransactionsDelta final : public CValidationInterface { + std::set& m_added; + + explicit TransactionsDelta(std::set& a) + : m_added{a} {} + + void TransactionAddedToMempool(const CTransactionRef& tx, int64_t /* nAcceptTime */, uint64_t /* mempool_sequence */) override + { + // Transactions may be entered and booted any number of times + m_added.insert(tx); + } + + void TransactionRemovedFromMempool(const CTransactionRef& tx, MemPoolRemovalReason reason, uint64_t /* mempool_sequence */) override + { + // Transactions may be entered and booted any number of times + m_added.erase(tx); + } +}; + +void MockTime(FuzzedDataProvider& fuzzed_data_provider, const Chainstate& chainstate) +{ + const auto time = ConsumeTime(fuzzed_data_provider, + chainstate.m_chain.Tip()->GetMedianTimePast() + 1, + std::numeric_limitsnTime)>::max()); + SetMockTime(time); +} + +CTxMemPool MakeMempool(FuzzedDataProvider& fuzzed_data_provider, const NodeContext& node) +{ + // Take the default options for tests... + CTxMemPool::Options mempool_opts{MemPoolOptionsForTest(node)}; + + + // ...override specific options for this specific fuzz suite + mempool_opts.limits.ancestor_count = fuzzed_data_provider.ConsumeIntegralInRange(0, 50); + mempool_opts.limits.ancestor_size_vbytes = fuzzed_data_provider.ConsumeIntegralInRange(0, 202) * 1'000; + mempool_opts.limits.descendant_count = fuzzed_data_provider.ConsumeIntegralInRange(0, 50); + mempool_opts.limits.descendant_size_vbytes = fuzzed_data_provider.ConsumeIntegralInRange(0, 202) * 1'000; + mempool_opts.max_size_bytes = fuzzed_data_provider.ConsumeIntegralInRange(0, 200) * 1'000'000; + mempool_opts.expiry = std::chrono::hours{fuzzed_data_provider.ConsumeIntegralInRange(0, 999)}; + nBytesPerSigOp = fuzzed_data_provider.ConsumeIntegralInRange(1, 999); + + mempool_opts.estimator = nullptr; + mempool_opts.check_ratio = 1; + mempool_opts.require_standard = fuzzed_data_provider.ConsumeBool(); + + // ...and construct a CTxMemPool from it + return CTxMemPool{mempool_opts}; +} + +FUZZ_TARGET(tx_package_eval, .init = initialize_tx_pool) +{ + FuzzedDataProvider fuzzed_data_provider(buffer.data(), buffer.size()); + const auto& node = g_setup->m_node; + auto& chainstate{static_cast(node.chainman->ActiveChainstate())}; + + MockTime(fuzzed_data_provider, chainstate); + + // All RBF-spendable outpoints outside of the unsubmitted package + std::set mempool_outpoints; + std::map outpoints_value; + for (const auto& outpoint : g_outpoints_coinbase_init_mature) { + Assert(mempool_outpoints.insert(outpoint).second); + outpoints_value[outpoint] = 50 * COIN; + } + + auto outpoints_updater = std::make_shared(mempool_outpoints); + RegisterSharedValidationInterface(outpoints_updater); + + CTxMemPool tx_pool_{MakeMempool(fuzzed_data_provider, node)}; + MockedTxPool& tx_pool = *static_cast(&tx_pool_); + + chainstate.SetMempool(&tx_pool); + + LIMITED_WHILE(fuzzed_data_provider.ConsumeBool(), 300) + { + Assert(!mempool_outpoints.empty()); + + std::vector txs; + + // Make packages of 1-to-26 transactions + const auto num_txs = (size_t) fuzzed_data_provider.ConsumeIntegralInRange(1, 26); + std::set package_outpoints; + while (txs.size() < num_txs) { + + // Last transaction in a package needs to be a child of parents to get further in validation + // so the last transaction to be generated(in a >1 package) must spend all package-made outputs + // Note that this test currently only spends package outputs in last transaction. + bool last_tx = num_txs > 1 && txs.size() == num_txs - 1; + + // Create transaction to add to the mempool + const CTransactionRef tx = [&] { + CMutableTransaction tx_mut; + tx_mut.nVersion = CTransaction::CURRENT_VERSION; + tx_mut.nLockTime = fuzzed_data_provider.ConsumeBool() ? 0 : fuzzed_data_provider.ConsumeIntegral(); + // Last tx will sweep all outpoints in package + const auto num_in = last_tx ? package_outpoints.size() : fuzzed_data_provider.ConsumeIntegralInRange(1, mempool_outpoints.size()); + const auto num_out = fuzzed_data_provider.ConsumeIntegralInRange(1, mempool_outpoints.size() * 2); + + auto& outpoints = last_tx ? package_outpoints : mempool_outpoints; + + Assert(!outpoints.empty()); + + CAmount amount_in{0}; + for (size_t i = 0; i < num_in; ++i) { + // Pop random outpoint + auto pop = outpoints.begin(); + std::advance(pop, fuzzed_data_provider.ConsumeIntegralInRange(0, outpoints.size() - 1)); + const auto outpoint = *pop; + outpoints.erase(pop); + // no need to update or erase from outpoints_value + amount_in += outpoints_value.at(outpoint); + + // Create input + const auto sequence = ConsumeSequence(fuzzed_data_provider); + const auto script_sig = CScript{} << STACK_ELEM_OP_TRUE; + CTxIn in; + in.prevout = outpoint; + in.nSequence = sequence; + in.scriptSig = script_sig; + + tx_mut.vin.push_back(in); + } + const auto amount_fee = fuzzed_data_provider.ConsumeIntegralInRange(0, amount_in); + const auto amount_out = (amount_in - amount_fee) / num_out; + for (int i = 0; i < num_out; ++i) { + tx_mut.vout.emplace_back(amount_out, P2SH_OP_TRUE); + } + // TODO vary transaction sizes to catch size-related issues + auto tx = MakeTransactionRef(tx_mut); + // Restore previously removed outpoints, except in-package outpoints + if (!last_tx) { + for (const auto& in : tx->vin) { + Assert(outpoints.insert(in.prevout).second); + } + // Cache the in-package outpoints being made + for (size_t i = 0; i < tx->vout.size(); ++i) { + package_outpoints.emplace(tx->GetHash(), i); + } + } + // We need newly-created values for the duration of this run + for (size_t i = 0; i < tx->vout.size(); ++i) { + outpoints_value[COutPoint(tx->GetHash(), i)] = tx->vout[i].nValue; + } + return tx; + }(); + txs.push_back(tx); + } + + if (fuzzed_data_provider.ConsumeBool()) { + MockTime(fuzzed_data_provider, chainstate); + } + if (fuzzed_data_provider.ConsumeBool()) { + tx_pool.RollingFeeUpdate(); + } + if (fuzzed_data_provider.ConsumeBool()) { + const auto& txid = fuzzed_data_provider.ConsumeBool() ? + txs.back()->GetHash() : + PickValue(fuzzed_data_provider, mempool_outpoints).hash; + const auto delta = fuzzed_data_provider.ConsumeIntegralInRange(-50 * COIN, +50 * COIN); + tx_pool.PrioritiseTransaction(txid, delta); + } + + // Remember all added transactions + std::set added; + auto txr = std::make_shared(added); + RegisterSharedValidationInterface(txr); + const bool bypass_limits = fuzzed_data_provider.ConsumeBool(); + + // When there are multiple transactions in the package, we call ProcessNewPackage(txs, test_accept=false) + // and AcceptToMemoryPool(txs.back(), test_accept=true). When there is only 1 transaction, we might flip it + // (the package is a test accept and ATMP is a submission). + auto single_submit = txs.size() == 1 && fuzzed_data_provider.ConsumeBool(); + + const auto result_package = WITH_LOCK(::cs_main, + return ProcessNewPackage(chainstate, tx_pool, txs, /*test_accept=*/single_submit)); + // If something went wrong due to a package-specific policy, it might not return a + // validation result for the transaction. + if (result_package.m_state.GetResult() != PackageValidationResult::PCKG_POLICY) { + auto it = result_package.m_tx_results.find(txs.back()->GetHash()); + Assert(it != result_package.m_tx_results.end()); + Assert(it->second.m_result_type == MempoolAcceptResult::ResultType::VALID || + it->second.m_result_type == MempoolAcceptResult::ResultType::INVALID || + it->second.m_result_type == MempoolAcceptResult::ResultType::MEMPOOL_ENTRY); + } + + const auto res = WITH_LOCK(::cs_main, return AcceptToMemoryPool(chainstate, txs.back(), GetTime(), bypass_limits, /*test_accept=*/!single_submit)); + const bool accepted = res.m_result_type == MempoolAcceptResult::ResultType::VALID; + + SyncWithValidationInterfaceQueue(); + UnregisterSharedValidationInterface(txr); + + // There is only 1 transaction in the package. We did a test-package-accept and a ATMP + if (single_submit) { + Assert(accepted != added.empty()); + Assert(accepted == res.m_state.IsValid()); + if (accepted) { + Assert(added.size() == 1); + Assert(txs.back() == *added.begin()); + } + } else { + // This is empty if it fails early checks, or "full" if transactions are looked at deeper + Assert(result_package.m_tx_results.size() == txs.size() || result_package.m_tx_results.empty()); + } + } + + UnregisterSharedValidationInterface(outpoints_updater); + + WITH_LOCK(::cs_main, tx_pool.check(chainstate.CoinsTip(), chainstate.m_chain.Height() + 1)); +} +} // namespace From 2f8c12f1b69c53fd4882fffc3c874b723ccb73bf Mon Sep 17 00:00:00 2001 From: DCG-Claude Date: Thu, 24 Sep 2026 11:58:30 -0500 Subject: [PATCH 2/4] Merge bitcoin/bitcoin#26531: mempool: Add mempool tracepoints MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 4b7aec2951fe4595946cdc804b0dec1921d79d05 Add mempool tracepoints (virtu) Pull request description: This PR adds multiple mempool tracepoints. | tracepoint | description | | ------------- | ------------- | | `mempool:added` | Is called when a transaction enters the mempool | | `mempool:removed` | ... when a transaction is removed from the mempool | | `mempool:replaced` | ... when a transaction is replaced in the mempool | | `mempool:rejected` | ... when a transaction is rejected from entering the mempool | The tracepoints are further documented in `docs/tracing.md`. Usage is demonstrated in the example script `contrib/tracing/mempool_monitor.py`. Interface tests are provided in `test/functional/interface_usdt_mempool.py`. The rationale for passing the removal reason as a string instead of numerically is that the benefits of not having to maintain a redundant enum-string mapping seem to outweigh the small cost of string generation. The reject reason is passed as string as well, although in this instance the string does not have to be generated but is readily available. ACKs for top commit: 0xB10C: ACK 4b7aec2951fe4595946cdc804b0dec1921d79d05 achow101: ACK 4b7aec2951fe4595946cdc804b0dec1921d79d05 Tree-SHA512: 6deb3ba2d1a061292fb9b0f885f7a5c4d11b109b838102d8a8f4828cd68f5cd03fa3fc64adc6fdf54a08a1eaccce261b0aa90c2b8c33cd5fd3828c8f74978958 Dash adaptations: - src/txmempool.cpp: `#include ` added alone — upstream's adjacent ``/`` lines are context this PR does not add and Dash's include block does not have. - src/txmempool.cpp: TRACE3(mempool, added) placed as the last statement of addUnchecked(), i.e. after Dash's `addUncheckedProTx(newit, tx)` call, preserving upstream's 'end of addUnchecked' position around the Dash-only ProTx bookkeeping. - src/txmempool.cpp: TRACE5(mempool, removed) applied verbatim; Dash's RemovalReasonToString() longest string is still 'sizelimit' (9 chars), so the documented MAX_REMOVAL_REASON_LENGTH=9 holds. - doc/tracing.md: the `mempool:replaced` subsection is not added (Dash emits no such tracepoint, see omitted_hunks); heading kept as Dash's 'Adding tracepoints to Dash Core'. - contrib/tracing/mempool_monitor.py: replaced_event struct, trace_replaced BPF fn, handle_replaced, the mempool:replaced enable_probe/perf buffer, the 'replaced' metric rows and the 'replaced' branch of parse_event are dropped — enable_probe() on a probe absent from the binary raises at startup, so keeping them would make the script unusable on dashd. Also bitcoind->dashd (path arg, USAGE string, variable names) and 'Bitcoin Core'->'Dash Core' in the docstring. - contrib/tracing/README.md: ./src/bitcoind -> ./src/dashd; the mempool_monitor.py description lists only added/removed/rejected; the sample dashboard drops the 'replaced' count/rate rows and the two replaced event-log lines, and the sample 'removed ...: replaced' line now shows ': expiry' (a reason Dash's RemovalReasonToString actually returns). - test/functional/interface_usdt_mempool.py: replaced_test(), the replaced_event struct, trace_replaced and the run_test() call are dropped for the same reason; doc URL retargeted to dashpay/dash blob/develop, matching the other interface_usdt_*.py files in Dash. Not applicable to Dash (intentionally omitted): - src/validation.cpp: The TRACE7(mempool, replaced) hunk lands inside MemPoolAccept::Finalize's 'Remove conflicting transactions from the mempool' loop. Dash has no RBF: Workspace has no m_all_conflicting/m_conflicting_fees/m_conflicting_size/m_replaced_transactions and MemPoolRemovalReason has no REPLACED member, so the entire enclosing loop is absent from Dash and there is nowhere for the tracepoint to fire. The mempool:replaced tracepoint therefore does not exist in dashd, and its doc/monitor/test counterparts were dropped to match (listed under adaptations). The other three tracepoints (added/removed/rejected) are landed in full. Replayed onto a newer base. Dash adaptations: - src/txmempool.cpp: conflict was only include ordering — kept Dash's newer `#include ` and added upstream's `#include ` before it, preserving alphabetical order - src/txmempool.cpp: TRACE3(mempool, added) is placed after Dash's `addUncheckedProTx(newit, tx);` instead of after upstream's segwit-only `vTxHashes.emplace_back(tx.GetWitnessHash(), newit)` block, which Dash does not have; the tracepoint stays at the end of addUnchecked() as upstream intends - contrib/tracing/mempool_monitor.py, doc/tracing.md, contrib/tracing/README.md, test/functional/interface_usdt_mempool.py: Bitcoin→Dash / bitcoind→dashd branding and doc URL (dashpay/dash blob/develop), as published in the prior backport - src/validation.cpp: only the TRACE2(mempool, rejected) hunk lands; see omitted_hunks for the replaced tracepoint Not applicable to Dash (intentionally omitted): - src/validation.cpp: The TRACE7(mempool, replaced) hunk sits in MemPoolAccept::Finalize()'s RBF conflict-replacement loop. Dash does not implement BIP125 replace-by-fee (it relies on InstantSend locks to prevent conflicting spends), so there is no mempool replacement event to trace and no Dash counterpart where this shape of change belongs. This matches the prior published backport. - contrib/tracing/mempool_monitor.py: The replaced_event struct, trace_replaced() BPF handler, replaced perf buffer, 'replaced' row in the count/rate windows and the 'replaced' branch of parse_event() are all consumers of the mempool:replaced tracepoint, which Dash has no RBF path to emit. - test/functional/interface_usdt_mempool.py: replaced_test() and the replaced_event/trace_replaced parts of MEMPOOL_TRACEPOINTS_PROGRAM exercise mempool:replaced via an RBF bump, which Dash cannot perform. - doc/tracing.md: The 'Tracepoint mempool:replaced' section documents a tracepoint Dash does not emit. - contrib/tracing/README.md: mempool:replaced is dropped from the tracepoint list and the sample dashboard/event-log output, consistent with the omitted tracepoint. --- contrib/tracing/README.md | 46 +++ contrib/tracing/mempool_monitor.py | 328 ++++++++++++++++++++++ doc/tracing.md | 33 +++ src/txmempool.cpp | 14 + src/validation.cpp | 4 + test/functional/interface_usdt_mempool.py | 258 +++++++++++++++++ test/functional/test_runner.py | 1 + 7 files changed, 684 insertions(+) create mode 100755 contrib/tracing/mempool_monitor.py create mode 100755 test/functional/interface_usdt_mempool.py diff --git a/contrib/tracing/README.md b/contrib/tracing/README.md index 8c293e25df9a..4af5750cc09a 100644 --- a/contrib/tracing/README.md +++ b/contrib/tracing/README.md @@ -286,3 +286,49 @@ Spent a05880b8c77971ed0b9f73062c7c4cdb0ff3856ab14cbf8bc481ed571cd34b83:1 Added eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:0 5589696005 2094513 No Added eb689865f7d957938978d6207918748f74e6aa074f47874724327089445b0960:1 1565556 2094513 No ``` + +### mempool_monitor.py + +A BCC Python script producing mempool statistics and an event log. Based on the +`mempool:added`, `mempool:removed`, and `mempool:rejected` tracepoints. + +Statistics include incidence and rate for each event type since the script was +started (`total`) as well as during the last minute (`1 min`) and ten minutes +(`10 min`). The event log shows mempool events in real time, each entry +comprising a timestamp along with all event data available via the event's +tracepoint. + +```console +$ python3 contrib/tracing/mempool_monitor.py ./src/dashd +``` + +``` + Mempool Monitor + Press CTRL-C to stop. + + ┌─Event count───────────────────────┐ ┌─Event rate──────────────────────────┐ + │ Event total 1 min 10 min │ │ Event total 1 min 10 min │ + │ added 1425tx 201tx 1425tx │ │ added 4.7tx/s 3.4tx/s 4.7tx/s │ + │ removed 35tx 4tx 35tx │ │ removed 0.1tx/s 0.1tx/s 0.1tx/s │ + │ rejected 0tx 0tx 0tx │ │ rejected 0.0tx/s 0.0tx/s 0.0tx/s │ + └───────────────────────────────────┘ └─────────────────────────────────────┘ + + ┌─Event log────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐ + │ 13:10:30Z added f9064ca5bfc87cdd191faa42bf697217cd920b2b94838c1f1192e4f06c4fd217 with feerate 8.92 sat/vB (981 sat, 110 vbytes) │ + │ 13:10:30Z added 53ffa3afbe57b1bfe423e1755ca2b52c5b6cb4aa91b8b7ee9cb694953f47f234 with feerate 5.00 sat/vB (550 sat, 110 vbytes) │ + │ 13:10:30Z added 4177df5e19465eb5e53c3f8b6830a293f57474921bc6c2ae89375e0986e1f0f9 with feerate 2.98 sat/vB (429 sat, 144 vbytes) │ + │ 13:10:30Z added 931a10d83f0a268768da75dc4b9e199f2f055f12979ae5491cc304ee10f890ea with feerate 3.55 sat/vB (500 sat, 141 vbytes) │ + │ 13:10:30Z added 4cf32b295723cc4ab73f2a2e51d4bb276c0042760a4c00a3eb9595b8ebb24721 with feerate 89.21 sat/vB (12668 sat, 142 vbytes) │ + │ 13:10:31Z added c412db9089b7ed53f3e5e36d2819dd291278b59ccaabaeb17fd37c3d87fdcd57 with feerate 28.12 sat/vB (8351 sat, 297 vbytes) │ + │ 13:10:31Z added b8388a5bdc421b11460bdf477d5a85a1a39c2784e7dd7bffabe688740424ea57 with feerate 25.21 sat/vB (3554 sat, 141 vbytes) │ + │ 13:10:31Z added 4ddb88bc90a122cd9eae8a664e73bdf5bebe75f3ef901241b4a251245854a98e with feerate 24.15 sat/vB (5072 sat, 210 vbytes) │ + │ 13:10:31Z added 19101e4161bca5271ad5d03e7747f2faec7793b274dc2f3c4cf516b7cef1aac3 with feerate 7.06 sat/vB (1080 sat, 153 vbytes) │ + │ 13:10:31Z removed d1eecf9d662121322f4f31f0c2267a752d14bb3956e6016ba96e87f47890e1db with feerate 27.12 sat/vB (7213 sat, 266 vbytes): expiry │ + │ 13:10:31Z added 6c511c60d9b95b9eff81df6ecba5c86780f513fe62ce3ad6be2c5340d957025a with feerate 4.00 sat/vB (440 sat, 110 vbytes) │ + │ 13:10:31Z added 44d66f7f004bd52c46be4dff3067cab700e51c7866a84282bd8aab560a5bfb79 with feerate 3.15 sat/vB (448 sat, 142 vbytes) │ + │ 13:10:31Z added b17b7c9ec5acfbbf12f0eeef8e29826fad3105bb95eef7a47d2f1f22b4784643 with feerate 4.10 sat/vB (1348 sat, 329 vbytes) │ + │ 13:10:31Z added b7a4ad93554e57454e8a8049bfc0bd803fa962bd3f0a08926aa72e7cb23e2276 with feerate 1.01 sat/vB (205 sat, 202 vbytes) │ + │ 13:10:32Z added c78e87be86c828137a6e7e00a177c03b52202ce4c39029b99904c2a094b9da87 with feerate 11.00 sat/vB (1562 sat, 142 vbytes) │ + │ │ + └──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘ +``` diff --git a/contrib/tracing/mempool_monitor.py b/contrib/tracing/mempool_monitor.py new file mode 100755 index 000000000000..051839d4c02b --- /dev/null +++ b/contrib/tracing/mempool_monitor.py @@ -0,0 +1,328 @@ +#!/usr/bin/env python3 +# Copyright (c) 2022 The Bitcoin Core developers +# Distributed under the MIT software license, see the accompanying +# file COPYING or http://www.opensource.org/licenses/mit-license.php. + +""" Example logging Dash Core mempool events using the mempool:added, + mempool:removed, and mempool:rejected tracepoints. """ + +import curses +import sys +from datetime import datetime, timezone + +from bcc import BPF, USDT + +# BCC: The C program to be compiled to an eBPF program (by BCC) and loaded into +# a sandboxed Linux kernel VM. +PROGRAM = """ +# include + +// The longest rejection reason is 118 chars and is generated in case of SCRIPT_ERR_EVAL_FALSE by +// strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(check.GetScriptError())) +#define MAX_REJECT_REASON_LENGTH 118 +// The longest string returned by RemovalReasonToString() is 'sizelimit' +#define MAX_REMOVAL_REASON_LENGTH 9 +#define HASH_LENGTH 32 + +struct added_event +{ + u8 hash[HASH_LENGTH]; + u64 vsize; + s64 fee; +}; + +struct removed_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REMOVAL_REASON_LENGTH]; + u64 vsize; + s64 fee; + u64 entry_time; +}; + +struct rejected_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REJECT_REASON_LENGTH]; +}; + +// BPF perf buffer to push the data to user space. +BPF_PERF_OUTPUT(added_events); +BPF_PERF_OUTPUT(removed_events); +BPF_PERF_OUTPUT(rejected_events); + +int trace_added(struct pt_regs *ctx) { + struct added_event added = {}; + + bpf_usdt_readarg_p(1, ctx, &added.hash, HASH_LENGTH); + bpf_usdt_readarg(2, ctx, &added.vsize); + bpf_usdt_readarg(3, ctx, &added.fee); + + added_events.perf_submit(ctx, &added, sizeof(added)); + return 0; +} + +int trace_removed(struct pt_regs *ctx) { + struct removed_event removed = {}; + + bpf_usdt_readarg_p(1, ctx, &removed.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &removed.reason, MAX_REMOVAL_REASON_LENGTH); + bpf_usdt_readarg(3, ctx, &removed.vsize); + bpf_usdt_readarg(4, ctx, &removed.fee); + bpf_usdt_readarg(5, ctx, &removed.entry_time); + + removed_events.perf_submit(ctx, &removed, sizeof(removed)); + return 0; +} + +int trace_rejected(struct pt_regs *ctx) { + struct rejected_event rejected = {}; + + bpf_usdt_readarg_p(1, ctx, &rejected.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &rejected.reason, MAX_REJECT_REASON_LENGTH); + + rejected_events.perf_submit(ctx, &rejected, sizeof(rejected)); + return 0; +} +""" + + +def main(dashd_path): + dashd_with_usdts = USDT(path=str(dashd_path)) + + # attaching the trace functions defined in the BPF program + # to the tracepoints + dashd_with_usdts.enable_probe(probe="mempool:added", fn_name="trace_added") + dashd_with_usdts.enable_probe(probe="mempool:removed", fn_name="trace_removed") + dashd_with_usdts.enable_probe(probe="mempool:rejected", fn_name="trace_rejected") + bpf = BPF(text=PROGRAM, usdt_contexts=[dashd_with_usdts]) + + events = [] + + def get_timestamp(): + return datetime.now(timezone.utc) + + def handle_added(_, data, size): + event = bpf["added_events"].event(data) + events.append((get_timestamp(), "added", event)) + + def handle_removed(_, data, size): + event = bpf["removed_events"].event(data) + events.append((get_timestamp(), "removed", event)) + + def handle_rejected(_, data, size): + event = bpf["rejected_events"].event(data) + events.append((get_timestamp(), "rejected", event)) + + bpf["added_events"].open_perf_buffer(handle_added) + # By default, open_perf_buffer uses eight pages for a buffer, making for a total + # buffer size of 32k on most machines. In practice, this size is insufficient: + # Each `mempool:removed` event takes up 57 bytes in the buffer (32 bytes for txid, + # 9 bytes for removal reason, and 8 bytes each for vsize and fee). Full blocks + # contain around 2k transactions, requiring a buffer size of around 114kB. To cover + # this amount, 32 4k pages are required. + bpf["removed_events"].open_perf_buffer(handle_removed, page_cnt=32) + bpf["rejected_events"].open_perf_buffer(handle_rejected) + + curses.wrapper(loop, bpf, events) + + +def loop(screen, bpf, events): + dashboard = Dashboard(screen) + while True: + try: + bpf.perf_buffer_poll(timeout=50) + dashboard.render(events) + except KeyboardInterrupt: + exit() + + +class Dashboard: + """Visualization of mempool state using ncurses.""" + + INFO_WIN_HEIGHT = 2 + EVENT_WIN_HEIGHT = 7 + + def __init__(self, screen): + screen.nodelay(True) + curses.curs_set(False) + self._screen = screen + self._time_started = datetime.now(timezone.utc) + self._timestamps = {"added": [], "removed": [], "rejected": []} + self._event_history = {"added": 0, "removed": 0, "rejected": 0} + self._init_windows() + + def _init_windows(self): + """Initialize all windows.""" + self._init_info_win() + self._init_event_count_win() + self._init_event_rate_win() + self._init_event_log_win() + + @staticmethod + def create_win(x, y, height, width, title=None): + """Helper function to create generic windows and decorate them with box and title if requested.""" + win = curses.newwin(height, width, x, y) + if title: + win.box() + win.addstr(0, 2, title, curses.A_BOLD) + return win + + def _init_info_win(self): + """Create and populate the info window.""" + self._info_win = Dashboard.create_win( + x=0, y=1, height=Dashboard.INFO_WIN_HEIGHT, width=22 + ) + self._info_win.addstr(0, 0, "Mempool Monitor", curses.A_REVERSE) + self._info_win.addstr(1, 0, "Press CTRL-C to stop.", curses.A_NORMAL) + self._info_win.refresh() + + def _init_event_count_win(self): + """Create and populate the event count window.""" + self._event_count_win = Dashboard.create_win( + x=3, y=1, height=Dashboard.EVENT_WIN_HEIGHT, width=37, title="Event count" + ) + header = " {:<8} {:>8} {:>7} {:>7} " + self._event_count_win.addstr( + 1, 1, header.format("Event", "total", "1 min", "10 min"), curses.A_UNDERLINE + ) + self._event_count_win.refresh() + + def _init_event_rate_win(self): + """Create and populate the event rate window.""" + self._event_rate_win = Dashboard.create_win( + x=3, y=40, height=Dashboard.EVENT_WIN_HEIGHT, width=42, title="Event rate" + ) + header = " {:<8} {:>9} {:>9} {:>9} " + self._event_rate_win.addstr( + 1, 1, header.format("Event", "total", "1 min", "10 min"), curses.A_UNDERLINE + ) + self._event_rate_win.refresh() + + def _init_event_log_win(self): + """Create windows showing event log. This comprises a dummy boxed window and an + inset window so line breaks don't overwrite box.""" + # dummy boxed window + num_rows, num_cols = self._screen.getmaxyx() + space_above = Dashboard.INFO_WIN_HEIGHT + 1 + Dashboard.EVENT_WIN_HEIGHT + 1 + box_win_height = num_rows - space_above + box_win_width = num_cols - 2 + win_box = Dashboard.create_win( + x=space_above, + y=1, + height=box_win_height, + width=box_win_width, + title="Event log", + ) + # actual logging window + log_lines = box_win_height - 2 # top and bottom box lines + log_line_len = box_win_width - 2 - 1 # box lines and left padding + win = win_box.derwin(log_lines, log_line_len, 1, 2) + win.idlok(True) + win.scrollok(True) + win_box.refresh() + win.refresh() + self._event_log_win_box = win_box + self._event_log_win = win + + def calculate_metrics(self, events): + """Calculate count and rate metrics.""" + count, rate = {}, {} + for event_ts, event_type, event_data in events: + self._timestamps[event_type].append(event_ts) + for event_type, ts in self._timestamps.items(): + # remove timestamps older than ten minutes but keep track of their + # count for the 'total' metric + # + self._event_history[event_type] += len( + [t for t in ts if Dashboard.timestamp_age(t) >= 600] + ) + ts = [t for t in ts if Dashboard.timestamp_age(t) < 600] + self._timestamps[event_type] = ts + # count metric + count_1m = len([t for t in ts if Dashboard.timestamp_age(t) < 60]) + count_10m = len(ts) + count_total = self._event_history[event_type] + len(ts) + count[event_type] = (count_total, count_1m, count_10m) + # rate metric + runtime = Dashboard.timestamp_age(self._time_started) + rate_1m = count_1m / min(60, runtime) + rate_10m = count_10m / min(600, runtime) + rate_total = count_total / runtime + rate[event_type] = (rate_total, rate_1m, rate_10m) + return count, rate + + def _update_event_count(self, count): + """Update the event count window.""" + w = self._event_count_win + row_format = " {:<8} {:>6}tx {:>5}tx {:>5}tx " + for line, metric in enumerate(["added", "removed", "rejected"]): + w.addstr(2 + line, 1, row_format.format(metric, *count[metric])) + w.refresh() + + def _update_event_rate(self, rate): + """Update the event rate window.""" + w = self._event_rate_win + row_format = " {:<8} {:>5.1f}tx/s {:>5.1f}tx/s {:>5.1f}tx/s " + for line, metric in enumerate(["added", "removed", "rejected"]): + w.addstr(2 + line, 1, row_format.format(metric, *rate[metric])) + w.refresh() + + def _update_event_log(self, events): + """Update the event log window.""" + w = self._event_log_win + for event in events: + w.addstr(Dashboard.parse_event(event) + "\n") + w.refresh() + + def render(self, events): + """Render the dashboard.""" + count, rate = self.calculate_metrics(events) + self._update_event_count(count) + self._update_event_rate(rate) + self._update_event_log(events) + events.clear() + + @staticmethod + def parse_event(event): + """Converts events into human-readable messages""" + + ts_dt, type_, data = event + ts = ts_dt.strftime("%H:%M:%SZ") + if type_ == "added": + return ( + f"{ts} added {bytes(data.hash)[::-1].hex()}" + f" with feerate {data.fee/data.vsize:.2f} sat/vB" + f" ({data.fee} sat, {data.vsize} vbytes)" + ) + + if type_ == "removed": + return ( + f"{ts} removed {bytes(data.hash)[::-1].hex()}" + f" with feerate {data.fee/data.vsize:.2f} sat/vB" + f" ({data.fee} sat, {data.vsize} vbytes)" + f" received {ts_dt.timestamp()-data.entry_time:.1f} seconds ago" + f": {data.reason.decode('UTF-8')}" + ) + + if type_ == "rejected": + return ( + f"{ts} rejected {bytes(data.hash)[::-1].hex()}" + f": {data.reason.decode('UTF-8')}" + ) + + raise NotImplementedError("Unsupported event type: {type_}") + + @staticmethod + def timestamp_age(timestamp): + """Return age of timestamp in seconds.""" + return (datetime.now(timezone.utc) - timestamp).total_seconds() + + +if __name__ == "__main__": + if len(sys.argv) < 2: + print("USAGE: ", sys.argv[0], "path/to/dashd") + exit(1) + + path = sys.argv[1] + main(path) diff --git a/doc/tracing.md b/doc/tracing.md index 0734f1a496a1..16ee467ad9de 100644 --- a/doc/tracing.md +++ b/doc/tracing.md @@ -211,6 +211,39 @@ Arguments passed: 4. The expected transaction fee as an `int64` 5. The position of the change output as an `int32` +### Context `mempool` + +#### Tracepoint `mempool:added` + +Is called when a transaction is added to the node's mempool. Passes information +about the transaction. + +Arguments passed: +1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +2. Transaction virtual size as `uint64` +3. Transaction fee as `int64` + +#### Tracepoint `mempool:removed` + +Is called when a transaction is removed from the node's mempool. Passes information +about the transaction. + +Arguments passed: +1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +2. Removal reason as `pointer to C-style String` (max. length 9 characters) +3. Transaction virtual size as `uint64` +4. Transaction fee as `int64` +5. Transaction mempool entry time (epoch) as `uint64` + +#### Tracepoint `mempool:rejected` + +Is called when a transaction is not permitted to enter the mempool. Passes +information about the rejected transaction. + +Arguments passed: +1. Transaction ID (hash) as `pointer to unsigned chars` (i.e. 32 bytes in little-endian) +2. Reject reason as `pointer to C-style String` (max. length 118 characters) + ## Adding tracepoints to Dash Core To add a new tracepoint, `#include ` in the compilation unit where diff --git a/src/txmempool.cpp b/src/txmempool.cpp index 37c1eb10dedc..53bf4f0c8ae5 100644 --- a/src/txmempool.cpp +++ b/src/txmempool.cpp @@ -21,6 +21,7 @@ #include #include #include +#include #include #include @@ -479,6 +480,12 @@ void CTxMemPool::addUnchecked(const CTxMemPoolEntry &entry, setEntries &setAnces // fully checked by AcceptToMemoryPool() at this point, so we just assume that // everything is fine here. addUncheckedProTx(newit, tx); + + TRACE3(mempool, added, + entry.GetTx().GetHash().data(), + entry.GetTxSize(), + entry.GetFee() + ); } void CTxMemPool::addAddressIndex(const CTxMemPoolEntry& entry, const CCoinsViewCache& view) @@ -712,6 +719,13 @@ void CTxMemPool::removeUnchecked(txiter it, MemPoolRemovalReason reason) // notification. GetMainSignals().TransactionRemovedFromMempool(it->GetSharedTx(), reason, mempool_sequence); } + TRACE5(mempool, removed, + it->GetTx().GetHash().data(), + RemovalReasonToString(reason).c_str(), + it->GetTxSize(), + it->GetFee(), + std::chrono::duration_cast>(it->GetTime()).count() + ); const uint256 hash = it->GetTx().GetHash(); for (const CTxIn& txin : it->GetTx().vin) diff --git a/src/validation.cpp b/src/validation.cpp index 90c0ef99bd30..f4f1aa3bf08d 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -1700,6 +1700,10 @@ MempoolAcceptResult AcceptToMemoryPool(Chainstate& active_chainstate, const CTra if (result.m_result_type != MempoolAcceptResult::ResultType::VALID || test_accept) { if (result.m_result_type != MempoolAcceptResult::ResultType::VALID) { LogPrint(BCLog::MEMPOOL, "%s: %s %s (%s)\n", __func__, tx->GetHash().ToString(), result.m_state.GetRejectReason(), result.m_state.GetDebugMessage()); + TRACE2(mempool, rejected, + tx->GetHash().data(), + result.m_state.GetRejectReason().c_str() + ); } // Remove coins that were not present in the coins cache before calling; diff --git a/test/functional/interface_usdt_mempool.py b/test/functional/interface_usdt_mempool.py new file mode 100755 index 000000000000..2bb8f47a4925 --- /dev/null +++ b/test/functional/interface_usdt_mempool.py @@ -0,0 +1,258 @@ +#!/usr/bin/env python3 +# Copyright (c) 2022 The Bitcoin Core developers +# Distributed under the MIT software license, see the accompanying +# file COPYING or http://www.opensource.org/licenses/mit-license.php. + +""" Tests the mempool:* tracepoint API interface. + See https://github.com/dashpay/dash/blob/develop/doc/tracing.md#context-mempool +""" + +from decimal import Decimal + +# Test will be skipped if we don't have bcc installed +try: + from bcc import BPF, USDT # type: ignore[import] +except ImportError: + pass + +from test_framework.blocktools import COINBASE_MATURITY +from test_framework.messages import COIN, DEFAULT_MEMPOOL_EXPIRY_HOURS +from test_framework.p2p import P2PDataStore +from test_framework.test_framework import BitcoinTestFramework +from test_framework.util import assert_equal +from test_framework.wallet import MiniWallet + +MEMPOOL_TRACEPOINTS_PROGRAM = """ +# include + +// The longest rejection reason is 118 chars and is generated in case of SCRIPT_ERR_EVAL_FALSE by +// strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(check.GetScriptError())) +#define MAX_REJECT_REASON_LENGTH 118 +// The longest string returned by RemovalReasonToString() is 'sizelimit' +#define MAX_REMOVAL_REASON_LENGTH 9 +#define HASH_LENGTH 32 + +struct added_event +{ + u8 hash[HASH_LENGTH]; + u64 vsize; + s64 fee; +}; + +struct removed_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REMOVAL_REASON_LENGTH]; + u64 vsize; + s64 fee; + u64 entry_time; +}; + +struct rejected_event +{ + u8 hash[HASH_LENGTH]; + char reason[MAX_REJECT_REASON_LENGTH]; +}; + +// BPF perf buffer to push the data to user space. +BPF_PERF_OUTPUT(added_events); +BPF_PERF_OUTPUT(removed_events); +BPF_PERF_OUTPUT(rejected_events); + +int trace_added(struct pt_regs *ctx) { + struct added_event added = {}; + + bpf_usdt_readarg_p(1, ctx, &added.hash, HASH_LENGTH); + bpf_usdt_readarg(2, ctx, &added.vsize); + bpf_usdt_readarg(3, ctx, &added.fee); + + added_events.perf_submit(ctx, &added, sizeof(added)); + return 0; +} + +int trace_removed(struct pt_regs *ctx) { + struct removed_event removed = {}; + + bpf_usdt_readarg_p(1, ctx, &removed.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &removed.reason, MAX_REMOVAL_REASON_LENGTH); + bpf_usdt_readarg(3, ctx, &removed.vsize); + bpf_usdt_readarg(4, ctx, &removed.fee); + bpf_usdt_readarg(5, ctx, &removed.entry_time); + + removed_events.perf_submit(ctx, &removed, sizeof(removed)); + return 0; +} + +int trace_rejected(struct pt_regs *ctx) { + struct rejected_event rejected = {}; + + bpf_usdt_readarg_p(1, ctx, &rejected.hash, HASH_LENGTH); + bpf_usdt_readarg_p(2, ctx, &rejected.reason, MAX_REJECT_REASON_LENGTH); + + rejected_events.perf_submit(ctx, &rejected, sizeof(rejected)); + return 0; +} +""" + + +class MempoolTracepointTest(BitcoinTestFramework): + def set_test_params(self): + self.num_nodes = 1 + self.setup_clean_chain = True + + def skip_test_if_missing_module(self): + self.skip_if_platform_not_linux() + self.skip_if_no_bitcoind_tracepoints() + self.skip_if_no_python_bcc() + self.skip_if_no_bpf_permissions() + + def added_test(self): + """Add a transaction to the mempool and make sure the tracepoint returns + the expected txid, vsize, and fee.""" + + EXPECTED_ADDED_EVENTS = 1 + handled_added_events = 0 + + self.log.info("Hooking into mempool:added tracepoint...") + node = self.nodes[0] + ctx = USDT(pid=node.process.pid) + ctx.enable_probe(probe="mempool:added", fn_name="trace_added") + bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0) + + def handle_added_event(_, data, __): + nonlocal handled_added_events + event = bpf["added_events"].event(data) + assert_equal(txid, bytes(event.hash)[::-1].hex()) + assert_equal(vsize, event.vsize) + assert_equal(fee, event.fee) + handled_added_events += 1 + + bpf["added_events"].open_perf_buffer(handle_added_event) + + self.log.info("Sending transaction...") + fee = Decimal(31200) + tx = self.wallet.send_self_transfer(from_node=node, fee=fee / COIN) + # expected data + txid = tx["txid"] + vsize = tx["tx"].get_vsize() + + self.log.info("Polling buffer...") + bpf.perf_buffer_poll(timeout=200) + + self.log.info("Cleaning up mempool...") + self.generate(node, 1) + + bpf.cleanup() + + self.log.info("Ensuring mempool:added event was handled successfully...") + assert_equal(EXPECTED_ADDED_EVENTS, handled_added_events) + + def removed_test(self): + """Expire a transaction from the mempool and make sure the tracepoint returns + the expected txid, expiry reason, vsize, and fee.""" + + EXPECTED_REMOVED_EVENTS = 1 + handled_removed_events = 0 + + self.log.info("Hooking into mempool:removed tracepoint...") + node = self.nodes[0] + ctx = USDT(pid=node.process.pid) + ctx.enable_probe(probe="mempool:removed", fn_name="trace_removed") + bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0) + + def handle_removed_event(_, data, __): + nonlocal handled_removed_events + event = bpf["removed_events"].event(data) + assert_equal(txid, bytes(event.hash)[::-1].hex()) + assert_equal(reason, event.reason.decode("UTF-8")) + assert_equal(vsize, event.vsize) + assert_equal(fee, event.fee) + assert_equal(entry_time, event.entry_time) + handled_removed_events += 1 + + bpf["removed_events"].open_perf_buffer(handle_removed_event) + + self.log.info("Sending transaction...") + fee = Decimal(31200) + tx = self.wallet.send_self_transfer(from_node=node, fee=fee / COIN) + # expected data + txid = tx["txid"] + reason = "expiry" + vsize = tx["tx"].get_vsize() + + self.log.info("Fast-forwarding time to mempool expiry...") + entry_time = node.getmempoolentry(txid)["time"] + expiry_time = entry_time + 60 * 60 * DEFAULT_MEMPOOL_EXPIRY_HOURS + 5 + node.setmocktime(expiry_time) + + self.log.info("Triggering expiry...") + self.wallet.get_utxo(txid=txid) + self.wallet.send_self_transfer(from_node=node) + + self.log.info("Polling buffer...") + bpf.perf_buffer_poll(timeout=200) + + bpf.cleanup() + + self.log.info("Ensuring mempool:removed event was handled successfully...") + assert_equal(EXPECTED_REMOVED_EVENTS, handled_removed_events) + + def rejected_test(self): + """Create an invalid transaction and make sure the tracepoint returns + the expected txid, rejection reason, peer id, and peer address.""" + + EXPECTED_REJECTED_EVENTS = 1 + handled_rejected_events = 0 + + self.log.info("Adding P2P connection...") + node = self.nodes[0] + node.add_p2p_connection(P2PDataStore()) + + self.log.info("Hooking into mempool:rejected tracepoint...") + ctx = USDT(pid=node.process.pid) + ctx.enable_probe(probe="mempool:rejected", fn_name="trace_rejected") + bpf = BPF(text=MEMPOOL_TRACEPOINTS_PROGRAM, usdt_contexts=[ctx], debug=0) + + def handle_rejected_event(_, data, __): + nonlocal handled_rejected_events + event = bpf["rejected_events"].event(data) + assert_equal(txid, bytes(event.hash)[::-1].hex()) + assert_equal(reason, event.reason.decode("UTF-8")) + handled_rejected_events += 1 + + bpf["rejected_events"].open_perf_buffer(handle_rejected_event) + + self.log.info("Sending invalid transaction...") + tx = self.wallet.create_self_transfer(fee_rate=Decimal(0)) + node.p2ps[0].send_txs_and_test([tx["tx"]], node, success=False) + + # expected data + txid = tx["tx"].hash + reason = "min relay fee not met" + + self.log.info("Polling buffer...") + bpf.perf_buffer_poll(timeout=200) + + bpf.cleanup() + + self.log.info("Ensuring mempool:rejected event was handled successfully...") + assert_equal(EXPECTED_REJECTED_EVENTS, handled_rejected_events) + + def run_test(self): + """Tests the mempool:added, mempool:removed, and mempool:rejected + tracepoints.""" + + # Create some coinbase transactions and mature them so they can be spent + node = self.nodes[0] + self.wallet = MiniWallet(node) + self.generate(self.wallet, 4) + self.generate(node, COINBASE_MATURITY) + + # Test individual tracepoints + self.added_test() + self.removed_test() + self.rejected_test() + + +if __name__ == "__main__": + MempoolTracepointTest().main() diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py index c0a224b1cdde..7bc370115227 100755 --- a/test/functional/test_runner.py +++ b/test/functional/test_runner.py @@ -230,6 +230,7 @@ 'interface_http.py', 'interface_rpc.py', 'interface_usdt_coinselection.py', + 'interface_usdt_mempool.py', 'interface_usdt_net.py', 'interface_usdt_utxocache.py', 'interface_usdt_validation.py', From 5cd586d4746516804d94a5755348fd41cde1b74c Mon Sep 17 00:00:00 2001 From: DCG-Claude Date: Thu, 24 Sep 2026 11:58:30 -0500 Subject: [PATCH 3/4] partial Merge bitcoin/bitcoin#27944: test: various USDT functional test cleanups (27831 follow-ups) 9f55773a370a0d039e727445ccee6b84e05f562a test: refactor: usdt_mempool: store all events (stickies-v) bc432704505eb165dd86de39ea3434c6fb7a2514 test: refactor: remove unnecessary nonlocal (stickies-v) 326db63a6819813db55ba0d01ab4fe80f7a0d818 test: log sanity check assertion failures (stickies-v) f5525ad6808df6afc38e5c6e4767ab577e30629c test: store utxocache events (stickies-v) f1b99ac94fb77340c4d3a5b4bbc3df28009bc773 test: refactor: deduplicate handle_utxocache_* logic (stickies-v) ad90ba36bd930f00753643cd1fe0af72d1c828c2 test: refactor: rename inbound to is_inbound (stickies-v) afc0224cdbe73e326addf5fb98a3e95d941f2104 test: refactor: remove unnecessary blocks_checked counter (stickies-v) Pull request description: Various cleanups to the USDT functional tests, largely (but not exclusively) follow-ups to https://github.com/bitcoin/bitcoin/pull/27831#pullrequestreview-1491438045. Except for slightly different logging behaviour in "test: store utxocache events" and "test: log sanity check assertion failures", this is a refactor PR, removing unnecessary code and (imo) making it more readable and maintainable. The rationale for each change is in the corresponding commit message. Note: except for "test: store utxocache events" (which relies on its parent, and I separated into two commits because we may want the parent but not the child), all commits are stand-alone and I'm okay with dropping one/multiple commits if they turn out to be controversial or undesired. ACKs for top commit: 0xB10C: ACK 9f55773a370a0d039e727445ccee6b84e05f562a. Reviewed the code and ran the USDT interface tests. I stepped through the commits and think all changes are reasonable. Tree-SHA512: 6c37a0265b6c26d4f9552a056a690b8f86f7304bd33b4419febd8b17369cf6af799cb87c16df35d0c2a1b839ad31de24661d4384eafa88816c2051c522fd3bf5 Dash adaptations: - test/functional/interface_usdt_validation.py: the resolved hunk also deletes the in-callback assertion block that Dash's partial #27831 backport (c781f1ad39) left behind alongside the new post-poll loop; upstream's callback body is just events.append(event), so the duplicate had to go and the file now matches upstream's post-image (Dash keeps its own cflags=["-Wno-error=implicit-function-declaration"] line from #28629 and its dashpay doc URLs) Omitted (partial backport): - test/functional/interface_usdt_mempool.py: Dash's #27831 backport (c781f1ad39) is marked (Partial) and covers only net/utxocache/validation; interface_usdt_mempool.py is still at the #26531 state with assert_equal() calls inside each bcc callback, so the 'EXPECTED_*_EVENTS/handled_*_events/event = None' -> 'events = []' rewrite that #27944 performs has nothing to rewrite here (needs bitcoin/bitcoin#27831) --- test/functional/interface_usdt_net.py | 11 ++-- test/functional/interface_usdt_utxocache.py | 68 +++++++++----------- test/functional/interface_usdt_validation.py | 16 +---- 3 files changed, 36 insertions(+), 59 deletions(-) diff --git a/test/functional/interface_usdt_net.py b/test/functional/interface_usdt_net.py index d446c0e5b7a1..d7f6613802de 100755 --- a/test/functional/interface_usdt_net.py +++ b/test/functional/interface_usdt_net.py @@ -121,11 +121,11 @@ def __repr__(self): checked_outbound_version_msg = 0 events = [] - def check_p2p_message(event, inbound): + def check_p2p_message(event, is_inbound): nonlocal checked_inbound_version_msg, checked_outbound_version_msg if event.msg_type.decode("utf-8") == "version": self.log.info( - f"check_p2p_message(): {'inbound' if inbound else 'outbound'} {event}") + f"check_p2p_message(): {'inbound' if is_inbound else 'outbound'} {event}") peer = self.nodes[0].getpeerinfo()[0] msg = msg_version() msg.deserialize(BytesIO(bytes(event.msg[:event.msg_size]))) @@ -133,13 +133,12 @@ def check_p2p_message(event, inbound): assert_equal(peer["addr"], event.peer_addr.decode("utf-8")) assert_equal(peer["connection_type"], event.peer_conn_type.decode("utf-8")) - if inbound: + if is_inbound: checked_inbound_version_msg += 1 else: checked_outbound_version_msg += 1 def handle_inbound(_, data, __): - nonlocal events event = ctypes.cast(data, ctypes.POINTER(P2PMessage)).contents events.append((event, True)) @@ -157,8 +156,8 @@ def handle_outbound(_, data, __): self.log.info( "check receipt and content of in- and outbound version messages") - for event, inbound in events: - check_p2p_message(event, inbound) + for event, is_inbound in events: + check_p2p_message(event, is_inbound) assert_equal(EXPECTED_INOUTBOUND_VERSION_MSG, checked_inbound_version_msg) assert_equal(EXPECTED_INOUTBOUND_VERSION_MSG, diff --git a/test/functional/interface_usdt_utxocache.py b/test/functional/interface_usdt_utxocache.py index 338c9e589b43..3775cf53debe 100755 --- a/test/functional/interface_usdt_utxocache.py +++ b/test/functional/interface_usdt_utxocache.py @@ -253,43 +253,30 @@ def test_add_spent(self): # that the handle_* functions succeeded. EXPECTED_HANDLE_ADD_SUCCESS = 2 EXPECTED_HANDLE_SPENT_SUCCESS = 1 - handle_add_succeeds = 0 - handle_spent_succeeds = 0 - expected_utxocache_spents = [] expected_utxocache_adds = [] + expected_utxocache_spents = [] + + actual_utxocache_adds = [] + actual_utxocache_spents = [] + + def compare_utxo_with_event(utxo, event): + """Compare a utxo dict to the event produced by BPF""" + assert_equal(utxo["txid"], bytes(event.txid[::-1]).hex()) + assert_equal(utxo["index"], event.index) + assert_equal(utxo["height"], event.height) + assert_equal(utxo["value"], event.value) + assert_equal(utxo["is_coinbase"], event.is_coinbase) def handle_utxocache_add(_, data, __): - nonlocal handle_add_succeeds event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents self.log.info(f"handle_utxocache_add(): {event}") - add = expected_utxocache_adds.pop(0) - try: - assert_equal(add["txid"], bytes(event.txid[::-1]).hex()) - assert_equal(add["index"], event.index) - assert_equal(add["height"], event.height) - assert_equal(add["value"], event.value) - assert_equal(add["is_coinbase"], event.is_coinbase) - except AssertionError: - self.log.exception("Assertion failed") - else: - handle_add_succeeds += 1 + actual_utxocache_adds.append(event) def handle_utxocache_spent(_, data, __): - nonlocal handle_spent_succeeds event = ctypes.cast(data, ctypes.POINTER(UTXOCacheChange)).contents self.log.info(f"handle_utxocache_spent(): {event}") - spent = expected_utxocache_spents.pop(0) - try: - assert_equal(spent["txid"], bytes(event.txid[::-1]).hex()) - assert_equal(spent["index"], event.index) - assert_equal(spent["height"], event.height) - assert_equal(spent["value"], event.value) - assert_equal(spent["is_coinbase"], event.is_coinbase) - except AssertionError: - self.log.exception("Assertion failed") - else: - handle_spent_succeeds += 1 + actual_utxocache_spents.append(event) bpf["utxocache_add"].open_perf_buffer(handle_utxocache_add) bpf["utxocache_spent"].open_perf_buffer(handle_utxocache_spent) @@ -325,19 +312,18 @@ def handle_utxocache_spent(_, data, __): "is_coinbase": block_index == 0, }) - assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds)) - assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, - len(expected_utxocache_spents)) - bpf.perf_buffer_poll(timeout=200) - bpf.cleanup() + + assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, len(expected_utxocache_adds), len(actual_utxocache_adds)) + assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, len(expected_utxocache_spents), len(actual_utxocache_spents)) self.log.info( f"check that we successfully traced {EXPECTED_HANDLE_ADD_SUCCESS} adds and {EXPECTED_HANDLE_SPENT_SUCCESS} spent") - assert_equal(0, len(expected_utxocache_adds)) - assert_equal(0, len(expected_utxocache_spents)) - assert_equal(EXPECTED_HANDLE_ADD_SUCCESS, handle_add_succeeds) - assert_equal(EXPECTED_HANDLE_SPENT_SUCCESS, handle_spent_succeeds) + for expected_utxo, actual_event in zip(expected_utxocache_adds + expected_utxocache_spents, + actual_utxocache_adds + actual_utxocache_spents): + compare_utxo_with_event(expected_utxo, actual_event) + + bpf.cleanup() def test_flush(self): """ Tests the utxocache:flush tracepoint API. @@ -367,9 +353,13 @@ def handle_utxocache_flush(_, data, __): assert_equal(expected["mode"], FLUSHMODE_NAME[event.mode]) possible_cache_sizes.remove(event.size) # fails if size not in set # sanity checks only - assert event.memory > 0 - assert event.duration > 0 - handle_flush_succeeds += 1 + try: + assert event.memory > 0 + assert event.duration > 0 + except AssertionError: + self.log.exception("Assertion error") + else: + handle_flush_succeeds += 1 bpf["utxocache_flush"].open_perf_buffer(handle_utxocache_flush) diff --git a/test/functional/interface_usdt_validation.py b/test/functional/interface_usdt_validation.py index b309da8518e6..3a977caa7d11 100755 --- a/test/functional/interface_usdt_validation.py +++ b/test/functional/interface_usdt_validation.py @@ -86,7 +86,6 @@ def __repr__(self): self.duration) BLOCKS_EXPECTED = 2 - blocks_checked = 0 expected_blocks = dict() events = [] @@ -98,20 +97,9 @@ def __repr__(self): usdt_contexts=[ctx], debug=0, cflags=["-Wno-error=implicit-function-declaration"]) def handle_blockconnected(_, data, __): - nonlocal events, blocks_checked event = ctypes.cast(data, ctypes.POINTER(Block)).contents self.log.info(f"handle_blockconnected(): {event}") - block_hash = bytes(event.hash[::-1]).hex() - block = expected_blocks[block_hash] - assert_equal(block["hash"], block_hash) - assert_equal(block["height"], event.height) - assert_equal(len(block["tx"]), event.transactions) - assert_equal(len([tx["vin"] for tx in block["tx"]]), event.inputs) - assert_equal(0, event.sigops) # no sigops in coinbase tx - # only plausibility checks - assert event.duration > 0 - del expected_blocks[block_hash] - blocks_checked += 1 + events.append(event) bpf["block_connected"].open_perf_buffer( handle_blockconnected) @@ -136,7 +124,7 @@ def handle_blockconnected(_, data, __): # only plausibility checks assert event.duration > 0 del expected_blocks[block_hash] - assert_equal(BLOCKS_EXPECTED, blocks_checked) + assert_equal(BLOCKS_EXPECTED, len(events)) assert_equal(0, len(expected_blocks)) bpf.cleanup() From 1d1414bf814fca57ff54dc1f22917702badae6b2 Mon Sep 17 00:00:00 2001 From: DCG-Claude Date: Thu, 24 Sep 2026 11:58:30 -0500 Subject: [PATCH 4/4] Merge bitcoin/bitcoin#28088: test: Disable known broken USDT test MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit faf8be7c32be00f660eba90d3f07313fb25d5d1c test: Disable known broken USDT test (MarcoFalke) Pull request description: The failure is known and running into more failures doesn't help anyone. Not disabling the test would be a waste of CPU and developer time. https://github.com/bitcoin/bitcoin/issues/27380 Top commit has no ACKs. Tree-SHA512: d0469153b00d6b30e10a21bcd52d508fcf9f796ff2468f59aff75020a82c718bcae85caf4b58397dea6fd9e210b501353fd51567f979c6b57d3b1bb23d318216 Dash adaptations: - test/functional/interface_usdt_mempool.py: Dash still has the pre-bitcoin#27679 structure, so the disabled assertion is `assert_equal(reason, event.reason.decode("UTF-8"))` inside handle_rejected_event() rather than upstream's inlined `assert_equal(event.reason.decode("UTF-8"), "min relay fee not met")` at the end of the function; the same three-line comment referencing bitcoin/bitcoin#27380 precedes it - test/functional/interface_usdt_mempool.py: also commented out `reason = "min relay fee not met"` — in Dash's structure it is a local of rejected_test() whose only reference was the now-disabled assertion, and test/lint/lint-python.py enables flake8 F841 (assigned but never used), so leaving it live would fail lint. Upstream had no such variable to deal with - test/functional/interface_usdt_mempool.py: the incoming hunk's trailing context (`bpf.cleanup()` / `self.generate(self.wallet, 1)` after the assertions) was dropped — Dash already calls bpf.cleanup() before the event-count assertion and has no post-test generate in this function; that context belongs to upstream's refactored layout, not to the change itself --- test/functional/interface_usdt_mempool.py | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/test/functional/interface_usdt_mempool.py b/test/functional/interface_usdt_mempool.py index 2bb8f47a4925..baaa9e8518e8 100755 --- a/test/functional/interface_usdt_mempool.py +++ b/test/functional/interface_usdt_mempool.py @@ -217,7 +217,10 @@ def handle_rejected_event(_, data, __): nonlocal handled_rejected_events event = bpf["rejected_events"].event(data) assert_equal(txid, bytes(event.hash)[::-1].hex()) - assert_equal(reason, event.reason.decode("UTF-8")) + # The next test is already known to fail, so disable it to avoid + # wasting CPU time and developer time. See + # https://github.com/bitcoin/bitcoin/issues/27380 + #assert_equal(reason, event.reason.decode("UTF-8")) handled_rejected_events += 1 bpf["rejected_events"].open_perf_buffer(handle_rejected_event) @@ -228,7 +231,7 @@ def handle_rejected_event(_, data, __): # expected data txid = tx["tx"].hash - reason = "min relay fee not met" + #reason = "min relay fee not met" self.log.info("Polling buffer...") bpf.perf_buffer_poll(timeout=200)