From 1ac1c33f3f120bbe0bde4fa948299bc07cac47ee Mon Sep 17 00:00:00 2001 From: Pieter Wuille Date: Wed, 16 Oct 2024 05:53:19 -0400 Subject: [PATCH 1/5] [checkqueue] support user-defined return type through std::optional The check type function now needs to return a std::optional for some type R, and the check queue overall will return std::nullopt if all individual checks return that, or one of the non-nullopt values if there is at least one. For most tests, we use R=int, but for the actual validation code, we make it return the ScriptError. --- src/bench/checkqueue.cpp | 6 +-- src/checkqueue.h | 65 ++++++++++++++++++------------- src/test/checkqueue_tests.cpp | 70 +++++++++++++++++----------------- src/test/fuzz/checkqueue.cpp | 9 +++-- src/test/script_p2sh_tests.cpp | 2 +- src/test/transaction_tests.cpp | 2 +- src/validation.cpp | 40 ++++++++++--------- src/validation.h | 5 +-- 8 files changed, 107 insertions(+), 92 deletions(-) diff --git a/src/bench/checkqueue.cpp b/src/bench/checkqueue.cpp index d1454f3634..8134154eb1 100644 --- a/src/bench/checkqueue.cpp +++ b/src/bench/checkqueue.cpp @@ -34,9 +34,9 @@ static void CCheckQueueSpeedPrevectorJob(benchmark::Bench& bench) explicit PrevectorJob(FastRandomContext& insecure_rand){ p.resize(insecure_rand.randrange(PREVECTOR_SIZE*2)); } - bool operator()() + std::optional operator()() { - return true; + return std::nullopt; } }; @@ -62,7 +62,7 @@ static void CCheckQueueSpeedPrevectorJob(benchmark::Bench& bench) } // control waits for completion by RAII, but // it is done explicitly here for clarity - control.Wait(); + control.Complete(); }); } BENCHMARK(CCheckQueueSpeedPrevectorJob, benchmark::PriorityLevel::HIGH); diff --git a/src/checkqueue.h b/src/checkqueue.h index a1de000714..be41bf8bac 100644 --- a/src/checkqueue.h +++ b/src/checkqueue.h @@ -11,19 +11,24 @@ #include #include +#include #include /** * Queue for verifications that have to be performed. * The verifications are represented by a type T, which must provide an - * operator(), returning a bool. + * operator(), returning an std::optional. + * + * The overall result of the computation is std::nullopt if all invocations + * return std::nullopt, or one of the other results otherwise. * * One thread (the master) is assumed to push batches of verifications * onto the queue, where they are processed by N-1 worker threads. When * the master is done adding work, it temporarily joins the worker pool * as an N'th worker, until all jobs are done. + * */ -template +template ()().value())>> class CCheckQueue { private: @@ -47,7 +52,7 @@ private: int nTotal GUARDED_BY(m_mutex){0}; //! The temporary evaluation result. - bool fAllOk GUARDED_BY(m_mutex){true}; + std::optional m_result GUARDED_BY(m_mutex); /** * Number of verifications that haven't completed yet. @@ -62,24 +67,28 @@ private: std::vector m_worker_threads; bool m_request_stop GUARDED_BY(m_mutex){false}; - /** Internal function that does bulk of the verification work. */ - bool Loop(bool fMaster) EXCLUSIVE_LOCKS_REQUIRED(!m_mutex) + /** Internal function that does bulk of the verification work. If fMaster, return the final result. */ + std::optional Loop(bool fMaster) EXCLUSIVE_LOCKS_REQUIRED(!m_mutex) { std::condition_variable& cond = fMaster ? m_master_cv : m_worker_cv; std::vector vChecks; vChecks.reserve(nBatchSize); unsigned int nNow = 0; - bool fOk = true; + std::optional local_result; + bool do_work; do { { WAIT_LOCK(m_mutex, lock); // first do the clean-up of the previous loop run (allowing us to do it in the same critsect) if (nNow) { - fAllOk &= fOk; + if (local_result.has_value() && !m_result.has_value()) { + std::swap(local_result, m_result); + } nTodo -= nNow; - if (nTodo == 0 && !fMaster) + if (nTodo == 0 && !fMaster) { // We processed the last element; inform the master it can exit and return the result m_master_cv.notify_one(); + } } else { // first iteration nTotal++; @@ -88,18 +97,19 @@ private: while (queue.empty() && !m_request_stop) { if (fMaster && nTodo == 0) { nTotal--; - bool fRet = fAllOk; + std::optional to_return = std::move(m_result); // reset the status for new work later - fAllOk = true; + m_result = std::nullopt; // return the current status - return fRet; + return to_return; } nIdle++; cond.wait(lock); // wait nIdle--; } if (m_request_stop) { - return false; + // return value does not matter, because m_request_stop is only set in the destructor. + return std::nullopt; } // Decide how many work units to process now. @@ -112,12 +122,15 @@ private: vChecks.assign(std::make_move_iterator(start_it), std::make_move_iterator(queue.end())); queue.erase(start_it, queue.end()); // Check whether we need to do work at all - fOk = fAllOk; + do_work = !m_result.has_value(); } // execute work - for (T& check : vChecks) - if (fOk) - fOk = check(); + if (do_work) { + for (T& check : vChecks) { + local_result = check(); + if (local_result.has_value()) break; + } + } vChecks.clear(); } while (true); } @@ -146,8 +159,9 @@ public: CCheckQueue(CCheckQueue&&) = delete; CCheckQueue& operator=(CCheckQueue&&) = delete; - //! Wait until execution finishes, and return whether all evaluations were successful. - bool Wait() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex) + //! Join the execution until completion. If at least one evaluation wasn't successful, return + //! its error. + std::optional Complete() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex) { return Loop(true /* master thread */); } @@ -188,11 +202,11 @@ public: * RAII-style controller object for a CCheckQueue that guarantees the passed * queue is finished before continuing. */ -template +template ()().value())>> class CCheckQueueControl { private: - CCheckQueue * const pqueue; + CCheckQueue * const pqueue; bool fDone; public: @@ -207,13 +221,12 @@ public: } } - bool Wait() + std::optional Complete() { - if (pqueue == nullptr) - return true; - bool fRet = pqueue->Wait(); + if (pqueue == nullptr) return std::nullopt; + auto ret = pqueue->Complete(); fDone = true; - return fRet; + return ret; } void Add(std::vector&& vChecks) @@ -226,7 +239,7 @@ public: ~CCheckQueueControl() { if (!fDone) - Wait(); + Complete(); if (pqueue != nullptr) { LEAVE_CRITICAL_SECTION(pqueue->m_control_mutex); } diff --git a/src/test/checkqueue_tests.cpp b/src/test/checkqueue_tests.cpp index b7014db4a5..2463ce6da5 100644 --- a/src/test/checkqueue_tests.cpp +++ b/src/test/checkqueue_tests.cpp @@ -42,28 +42,26 @@ static const unsigned int QUEUE_BATCH_SIZE = 128; static const int SCRIPT_CHECK_THREADS = 3; struct FakeCheck { - bool operator()() const + std::optional operator()() const { - return true; + return std::nullopt; } }; struct FakeCheckCheckCompletion { static std::atomic n_calls; - bool operator()() + std::optional operator()() { n_calls.fetch_add(1, std::memory_order_relaxed); - return true; + return std::nullopt; } }; -struct FailingCheck { - bool fails; - FailingCheck(bool _fails) : fails(_fails){}; - bool operator()() const - { - return !fails; - } +struct FixedCheck +{ + std::optional m_result; + FixedCheck(std::optional result) : m_result(result){}; + std::optional operator()() const { return m_result; } }; struct UniqueCheck { @@ -71,11 +69,11 @@ struct UniqueCheck { static std::unordered_multiset results GUARDED_BY(m); size_t check_id; UniqueCheck(size_t check_id_in) : check_id(check_id_in){}; - bool operator()() + std::optional operator()() { LOCK(m); results.insert(check_id); - return true; + return std::nullopt; } }; @@ -83,9 +81,9 @@ struct UniqueCheck { struct MemoryCheck { static std::atomic fake_allocated_memory; bool b {false}; - bool operator()() const + std::optional operator()() const { - return true; + return std::nullopt; } MemoryCheck(const MemoryCheck& x) { @@ -110,9 +108,9 @@ struct FrozenCleanupCheck { static std::condition_variable cv; static std::mutex m; bool should_freeze{true}; - bool operator()() const + std::optional operator()() const { - return true; + return std::nullopt; } FrozenCleanupCheck() = default; ~FrozenCleanupCheck() @@ -149,7 +147,7 @@ std::atomic MemoryCheck::fake_allocated_memory{0}; // Queue Typedefs typedef CCheckQueue Correct_Queue; typedef CCheckQueue Standard_Queue; -typedef CCheckQueue Failing_Queue; +typedef CCheckQueue Fixed_Queue; typedef CCheckQueue Unique_Queue; typedef CCheckQueue Memory_Queue; typedef CCheckQueue FrozenCleanup_Queue; @@ -174,7 +172,7 @@ void CheckQueueTest::Correct_Queue_range(std::vector range) total -= vChecks.size(); control.Add(std::move(vChecks)); } - BOOST_REQUIRE(control.Wait()); + BOOST_REQUIRE(!control.Complete().has_value()); BOOST_REQUIRE_EQUAL(FakeCheckCheckCompletion::n_calls, i); } } @@ -217,27 +215,27 @@ BOOST_AUTO_TEST_CASE(test_CheckQueue_Correct_Random) } -/** Test that failing checks are caught */ +/** Test that distinct failing checks are caught */ BOOST_AUTO_TEST_CASE(test_CheckQueue_Catches_Failure) { - auto fail_queue = std::make_unique(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS); + auto fixed_queue = std::make_unique(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS); for (size_t i = 0; i < 1001; ++i) { - CCheckQueueControl control(fail_queue.get()); + CCheckQueueControl control(fixed_queue.get()); size_t remaining = i; while (remaining) { size_t r = m_rng.randrange(10); - std::vector vChecks; + std::vector vChecks; vChecks.reserve(r); for (size_t k = 0; k < r && remaining; k++, remaining--) - vChecks.emplace_back(remaining == 1); + vChecks.emplace_back(remaining == 1 ? std::make_optional(17 * i) : std::nullopt); control.Add(std::move(vChecks)); } - bool success = control.Wait(); + auto result = control.Complete(); if (i > 0) { - BOOST_REQUIRE(!success); - } else if (i == 0) { - BOOST_REQUIRE(success); + BOOST_REQUIRE(result.has_value() && *result == static_cast(17 * i)); + } else { + BOOST_REQUIRE(!result.has_value()); } } } @@ -245,17 +243,17 @@ BOOST_AUTO_TEST_CASE(test_CheckQueue_Catches_Failure) // future blocks, ie, the bad state is cleared. BOOST_AUTO_TEST_CASE(test_CheckQueue_Recovers_From_Failure) { - auto fail_queue = std::make_unique(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS); + auto fail_queue = std::make_unique(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS); for (auto times = 0; times < 10; ++times) { for (const bool end_fails : {true, false}) { - CCheckQueueControl control(fail_queue.get()); + CCheckQueueControl control(fail_queue.get()); { - std::vector vChecks; - vChecks.resize(100, false); - vChecks[99] = end_fails; + std::vector vChecks; + vChecks.resize(100, FixedCheck(std::nullopt)); + vChecks[99] = FixedCheck(end_fails ? std::make_optional(2) : std::nullopt); control.Add(std::move(vChecks)); } - bool r =control.Wait(); + bool r = !control.Complete().has_value(); BOOST_REQUIRE(r != end_fails); } } @@ -329,8 +327,8 @@ BOOST_AUTO_TEST_CASE(test_CheckQueue_FrozenCleanup) CCheckQueueControl control(queue.get()); std::vector vChecks(1); control.Add(std::move(vChecks)); - bool waitResult = control.Wait(); // Hangs here - assert(waitResult); + auto result = control.Complete(); // Hangs here + assert(!result); }); { std::unique_lock l(FrozenCleanupCheck::m); diff --git a/src/test/fuzz/checkqueue.cpp b/src/test/fuzz/checkqueue.cpp index 6320b500b6..6b93886c71 100644 --- a/src/test/fuzz/checkqueue.cpp +++ b/src/test/fuzz/checkqueue.cpp @@ -19,9 +19,10 @@ struct DumbCheck { { } - bool operator()() const + std::optional operator()() const { - return result; + if (result) return std::nullopt; + return 1; } }; } // namespace @@ -45,7 +46,7 @@ FUZZ_TARGET(checkqueue) check_queue_1.Add(std::move(checks_1)); } if (fuzzed_data_provider.ConsumeBool()) { - (void)check_queue_1.Wait(); + (void)check_queue_1.Complete(); } CCheckQueueControl check_queue_control{&check_queue_2}; @@ -53,6 +54,6 @@ FUZZ_TARGET(checkqueue) check_queue_control.Add(std::move(checks_2)); } if (fuzzed_data_provider.ConsumeBool()) { - (void)check_queue_control.Wait(); + (void)check_queue_control.Complete(); } } diff --git a/src/test/script_p2sh_tests.cpp b/src/test/script_p2sh_tests.cpp index 096de0724f..bb408b7b0f 100644 --- a/src/test/script_p2sh_tests.cpp +++ b/src/test/script_p2sh_tests.cpp @@ -121,7 +121,7 @@ BOOST_AUTO_TEST_CASE(sign) { CScript sigSave = txTo[i].vin[0].scriptSig; txTo[i].vin[0].scriptSig = txTo[j].vin[0].scriptSig; - bool sigOK = CScriptCheck(txFrom.vout[txTo[i].vin[0].prevout.n], CTransaction(txTo[i]), signature_cache, 0, SCRIPT_VERIFY_P2SH | SCRIPT_VERIFY_STRICTENC, false, &txdata)(); + bool sigOK = !CScriptCheck(txFrom.vout[txTo[i].vin[0].prevout.n], CTransaction(txTo[i]), signature_cache, 0, SCRIPT_VERIFY_P2SH | SCRIPT_VERIFY_STRICTENC, false, &txdata)().has_value(); if (i == j) BOOST_CHECK_MESSAGE(sigOK, strprintf("VerifySignature %d %d", i, j)); else diff --git a/src/test/transaction_tests.cpp b/src/test/transaction_tests.cpp index f38c015f6d..8beeec4991 100644 --- a/src/test/transaction_tests.cpp +++ b/src/test/transaction_tests.cpp @@ -588,7 +588,7 @@ BOOST_AUTO_TEST_CASE(test_big_witness_transaction) control.Add(std::move(vChecks)); } - bool controlCheck = control.Wait(); + bool controlCheck = !control.Complete().has_value(); assert(controlCheck); } diff --git a/src/validation.cpp b/src/validation.cpp index 95f3bc58d7..1ba9bb22cd 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2103,10 +2103,15 @@ void UpdateCoins(const CTransaction& tx, CCoinsViewCache& inputs, CTxUndo &txund AddCoins(inputs, tx, nHeight); } -bool CScriptCheck::operator()() { +std::optional CScriptCheck::operator()() { const CScript &scriptSig = ptxTo->vin[nIn].scriptSig; const CScriptWitness *witness = &ptxTo->vin[nIn].scriptWitness; - return VerifyScript(scriptSig, m_tx_out.scriptPubKey, witness, nFlags, CachingTransactionSignatureChecker(ptxTo, nIn, m_tx_out.nValue, cacheStore, *m_signature_cache, *txdata), &error); + ScriptError error{SCRIPT_ERR_UNKNOWN_ERROR}; + if (VerifyScript(scriptSig, m_tx_out.scriptPubKey, witness, nFlags, CachingTransactionSignatureChecker(ptxTo, nIn, m_tx_out.nValue, cacheStore, *m_signature_cache, *txdata), &error)) { + return std::nullopt; + } else { + return error; + } } ValidationCache::ValidationCache(const size_t script_execution_cache_bytes, const size_t signature_cache_bytes) @@ -2195,9 +2200,7 @@ bool CheckInputScripts(const CTransaction& tx, TxValidationState& state, CScriptCheck check(txdata.m_spent_outputs[i], tx, validation_cache.m_signature_cache, i, flags, cacheSigStore, &txdata); if (pvChecks) { pvChecks->emplace_back(std::move(check)); - } else if (!check()) { - ScriptError error{check.GetScriptError()}; - + } else if (auto result = check(); result.has_value()) { if (flags & STANDARD_NOT_MANDATORY_VERIFY_FLAGS) { // Check whether the failure was caused by a // non-mandatory script verification check, such as @@ -2209,21 +2212,23 @@ bool CheckInputScripts(const CTransaction& tx, TxValidationState& state, // data providers. CScriptCheck check2(txdata.m_spent_outputs[i], tx, validation_cache.m_signature_cache, i, flags & ~STANDARD_NOT_MANDATORY_VERIFY_FLAGS, cacheSigStore, &txdata); - if (check2()) - return state.Invalid(TxValidationResult::TX_NOT_STANDARD, strprintf("non-mandatory-script-verify-flag (%s)", ScriptErrorString(check.GetScriptError()))); - - // If the second check failed, it failed due to a mandatory script verification - // flag, but the first check might have failed on a non-mandatory script - // verification flag. - // - // Avoid reporting a mandatory script check failure with a non-mandatory error - // string by reporting the error from the second check. - error = check2.GetScriptError(); + auto mandatory_result = check2(); + if (!mandatory_result.has_value()) { + return state.Invalid(TxValidationResult::TX_NOT_STANDARD, strprintf("non-mandatory-script-verify-flag (%s)", ScriptErrorString(*result))); + } else { + // If the second check failed, it failed due to a mandatory script verification + // flag, but the first check might have failed on a non-mandatory script + // verification flag. + // + // Avoid reporting a mandatory script check failure with a non-mandatory error + // string by reporting the error from the second check. + result = mandatory_result; + } } // MANDATORY flag failures correspond to // TxValidationResult::TX_CONSENSUS. - return state.Invalid(TxValidationResult::TX_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(error))); + return state.Invalid(TxValidationResult::TX_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(*result))); } } @@ -2710,7 +2715,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-cb-amount"); } - if (!control.Wait()) { + auto parallel_result = control.Complete(); + if (parallel_result.has_value()) { LogPrintf("ERROR: %s: CheckQueue failed\n", __func__); return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "block-validation-failed"); } diff --git a/src/validation.h b/src/validation.h index 723babca31..14fe145730 100644 --- a/src/validation.h +++ b/src/validation.h @@ -335,7 +335,6 @@ private: unsigned int nIn; unsigned int nFlags; bool cacheStore; - ScriptError error{SCRIPT_ERR_UNKNOWN_ERROR}; PrecomputedTransactionData *txdata; SignatureCache* m_signature_cache; @@ -348,9 +347,7 @@ public: CScriptCheck(CScriptCheck&&) = default; CScriptCheck& operator=(CScriptCheck&&) = default; - bool operator()(); - - ScriptError GetScriptError() const { return error; } + std::optional operator()(); }; // CScriptCheck is used a lot in std::vector, make sure that's efficient From 146a3d542683ddb89a31104f5211dfc757d1dafb Mon Sep 17 00:00:00 2001 From: Pieter Wuille Date: Fri, 18 Oct 2024 06:01:23 -0400 Subject: [PATCH 2/5] [validation] Make script error messages uniform for parallel/single validation This makes the debug output mostly the same for -par=1 and parallel validation runs. Of course, parallel validation is non-deterministic in what error it may encounter first if there are multiple issues. Also, the way certain script-related and non-script-related checks are performed differs between the two modes still, which may result in discrepancies. --- src/test/miner_tests.cpp | 3 +-- src/validation.cpp | 8 ++++---- test/functional/feature_block.py | 1 - test/functional/feature_cltv.py | 3 +-- test/functional/feature_csv_activation.py | 1 - test/functional/feature_dersig.py | 3 +-- test/functional/feature_nulldummy.py | 1 - test/functional/feature_taproot.py | 1 - test/functional/p2p_segwit.py | 9 ++++----- 9 files changed, 11 insertions(+), 19 deletions(-) diff --git a/src/test/miner_tests.cpp b/src/test/miner_tests.cpp index f6ae6549bc..c5ecf7022e 100644 --- a/src/test/miner_tests.cpp +++ b/src/test/miner_tests.cpp @@ -403,8 +403,7 @@ void MinerTestingSetup::TestBasicMining(const CScript& scriptPubKey, const std:: tx.vout[0].nValue -= LOWFEE; hash = tx.GetHash(); AddToMempool(tx_mempool, entry.Fee(LOWFEE).Time(Now()).SpendsCoinbase(false).FromTx(tx)); - // Should throw block-validation-failed - BOOST_CHECK_EXCEPTION(AssemblerForTest(tx_mempool).CreateNewBlock(scriptPubKey), std::runtime_error, HasReason("block-validation-failed")); + BOOST_CHECK_EXCEPTION(AssemblerForTest(tx_mempool).CreateNewBlock(scriptPubKey), std::runtime_error, HasReason("mandatory-script-verify-flag-failed")); // Delete the dummy blocks again. while (m_node.chainman->ActiveChain().Tip()->nHeight > nHeight) { diff --git a/src/validation.cpp b/src/validation.cpp index 1ba9bb22cd..54901b2c58 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2688,8 +2688,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, // Any transaction validation failure in ConnectBlock is a block consensus failure state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, tx_state.GetRejectReason(), tx_state.GetDebugMessage()); - LogError("ConnectBlock(): CheckInputScripts on %s failed with %s\n", - tx.GetHash().ToString(), state.ToString()); + LogInfo("Script validation error in block: %s\n", tx_state.GetRejectReason()); return false; } control.Add(std::move(vChecks)); @@ -2717,8 +2716,9 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, auto parallel_result = control.Complete(); if (parallel_result.has_value()) { - LogPrintf("ERROR: %s: CheckQueue failed\n", __func__); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "block-validation-failed"); + state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(*parallel_result))); + LogInfo("Script validation error in block: %s", state.GetRejectReason()); + return false; } const auto time_4{SteadyClock::now()}; m_chainman.time_verify += time_4 - time_2; diff --git a/test/functional/feature_block.py b/test/functional/feature_block.py index 43bf61c174..384ca311c7 100755 --- a/test/functional/feature_block.py +++ b/test/functional/feature_block.py @@ -88,7 +88,6 @@ class FullBlockTest(BitcoinTestFramework): self.extra_args = [[ '-acceptnonstdtxn=1', # This is a consensus block test, we don't care about tx policy '-testactivationheight=bip34@2', - '-par=1', # Until https://github.com/bitcoin/bitcoin/issues/30960 is fixed ]] def run_test(self): diff --git a/test/functional/feature_cltv.py b/test/functional/feature_cltv.py index dc01f8fa8f..52d0fd1704 100755 --- a/test/functional/feature_cltv.py +++ b/test/functional/feature_cltv.py @@ -87,7 +87,6 @@ class BIP65Test(BitcoinTestFramework): self.noban_tx_relay = True self.extra_args = [[ f'-testactivationheight=cltv@{CLTV_HEIGHT}', - '-par=1', # Use only one script thread to get the exact reject reason for testing '-acceptnonstdtxn=1', # cltv_invalidate is nonstandard ]] self.setup_clean_chain = True @@ -175,7 +174,7 @@ class BIP65Test(BitcoinTestFramework): block.hashMerkleRoot = block.calc_merkle_root() block.solve() - with self.nodes[0].assert_debug_log(expected_msgs=[f'CheckInputScripts on {block.vtx[-1].hash} failed with {expected_cltv_reject_reason}']): + with self.nodes[0].assert_debug_log(expected_msgs=[f'Script validation error in block: {expected_cltv_reject_reason}']): peer.send_and_ping(msg_block(block)) assert_equal(int(self.nodes[0].getbestblockhash(), 16), tip) peer.sync_with_ping() diff --git a/test/functional/feature_csv_activation.py b/test/functional/feature_csv_activation.py index df02bcc6ad..d5b6d0dba9 100755 --- a/test/functional/feature_csv_activation.py +++ b/test/functional/feature_csv_activation.py @@ -99,7 +99,6 @@ class BIP68_112_113Test(BitcoinTestFramework): self.noban_tx_relay = True self.extra_args = [[ f'-testactivationheight=csv@{CSV_ACTIVATION_HEIGHT}', - '-par=1', # Use only one script thread to get the exact reject reason for testing ]] self.supports_cli = False diff --git a/test/functional/feature_dersig.py b/test/functional/feature_dersig.py index 48b0b745c6..2180e7ce3d 100755 --- a/test/functional/feature_dersig.py +++ b/test/functional/feature_dersig.py @@ -51,7 +51,6 @@ class BIP66Test(BitcoinTestFramework): self.noban_tx_relay = True self.extra_args = [[ f'-testactivationheight=dersig@{DERSIG_HEIGHT}', - '-par=1', # Use only one script thread to get the exact log msg for testing ]] self.setup_clean_chain = True self.rpc_timeout = 240 @@ -131,7 +130,7 @@ class BIP66Test(BitcoinTestFramework): block.hashMerkleRoot = block.calc_merkle_root() block.solve() - with self.nodes[0].assert_debug_log(expected_msgs=[f'CheckInputScripts on {block.vtx[-1].hash} failed with mandatory-script-verify-flag-failed (Non-canonical DER signature)']): + with self.nodes[0].assert_debug_log(expected_msgs=[f'Script validation error in block: mandatory-script-verify-flag-failed (Non-canonical DER signature)']): peer.send_and_ping(msg_block(block)) assert_equal(int(self.nodes[0].getbestblockhash(), 16), tip) peer.sync_with_ping() diff --git a/test/functional/feature_nulldummy.py b/test/functional/feature_nulldummy.py index a53f78c13d..885bc4855b 100755 --- a/test/functional/feature_nulldummy.py +++ b/test/functional/feature_nulldummy.py @@ -57,7 +57,6 @@ class NULLDUMMYTest(BitcoinTestFramework): self.extra_args = [[ f'-testactivationheight=segwit@{COINBASE_MATURITY + 5}', '-addresstype=legacy', - '-par=1', # Use only one script thread to get the exact reject reason for testing ]] def create_transaction(self, *, txid, input_details=None, addr, amount, privkey): diff --git a/test/functional/feature_taproot.py b/test/functional/feature_taproot.py index 443c1c33da..daf11a9ae6 100755 --- a/test/functional/feature_taproot.py +++ b/test/functional/feature_taproot.py @@ -1285,7 +1285,6 @@ class TaprootTest(BitcoinTestFramework): def set_test_params(self): self.num_nodes = 1 self.setup_clean_chain = True - self.extra_args = [["-par=1"]] def block_submit(self, node, txs, msg, err_msg, cb_pubkey=None, fees=0, sigops_weight=0, witness=False, accept=False): diff --git a/test/functional/p2p_segwit.py b/test/functional/p2p_segwit.py index ac35762427..677a1120d6 100755 --- a/test/functional/p2p_segwit.py +++ b/test/functional/p2p_segwit.py @@ -214,6 +214,9 @@ class SegWitTest(BitcoinTestFramework): self.noban_tx_relay = True # This test tests SegWit both pre and post-activation, so use the normal BIP9 activation. self.extra_args = [ + # -par=1 should not affect validation outcome or logging/reported failures. It is kept + # here to exercise the code path still (as it is distinct for multithread script + # validation). ["-acceptnonstdtxn=1", f"-testactivationheight=segwit@{SEGWIT_HEIGHT}", "-par=1"], ["-acceptnonstdtxn=0", f"-testactivationheight=segwit@{SEGWIT_HEIGHT}"], ] @@ -507,10 +510,6 @@ class SegWitTest(BitcoinTestFramework): # When the block is serialized without witness, validation fails because the transaction is # invalid (transactions are always validated with SCRIPT_VERIFY_WITNESS so a segwit v0 transaction # without a witness is invalid). - # Note: The reject reason for this failure could be - # 'block-validation-failed' (if script check threads > 1) or - # 'mandatory-script-verify-flag-failed (Witness program was passed an - # empty witness)' (otherwise). test_witness_block(self.nodes[0], self.test_node, block, accepted=False, with_witness=False, reason='mandatory-script-verify-flag-failed (Witness program was passed an empty witness)') @@ -1015,7 +1014,7 @@ class SegWitTest(BitcoinTestFramework): tx2.vout.append(CTxOut(tx.vout[0].nValue, CScript([OP_TRUE]))) tx2.wit.vtxinwit.extend([CTxInWitness(), CTxInWitness()]) tx2.wit.vtxinwit[0].scriptWitness.stack = [CScript([CScriptNum(1)]), CScript([CScriptNum(1)]), witness_script] - tx2.wit.vtxinwit[1].scriptWitness.stack = [CScript([OP_TRUE])] + tx2.wit.vtxinwit[1].scriptWitness.stack = [] block = self.build_next_block() self.update_witness_block_with_transactions(block, [tx2]) From 7b267c034fdc2c8cb964a763f182ff98a75ba2ac Mon Sep 17 00:00:00 2001 From: Pieter Wuille Date: Fri, 18 Oct 2024 06:53:44 -0400 Subject: [PATCH 3/5] [validation] Add detailed txin/txout information for script error messages Don't just report which script error occurred, but which in which input of which transaction, and which UTXO was being spent. --- src/validation.cpp | 15 ++++++++------- src/validation.h | 2 +- 2 files changed, 9 insertions(+), 8 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index 54901b2c58..b8f89f4b88 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2103,14 +2103,15 @@ void UpdateCoins(const CTransaction& tx, CCoinsViewCache& inputs, CTxUndo &txund AddCoins(inputs, tx, nHeight); } -std::optional CScriptCheck::operator()() { +std::optional> CScriptCheck::operator()() { const CScript &scriptSig = ptxTo->vin[nIn].scriptSig; const CScriptWitness *witness = &ptxTo->vin[nIn].scriptWitness; ScriptError error{SCRIPT_ERR_UNKNOWN_ERROR}; if (VerifyScript(scriptSig, m_tx_out.scriptPubKey, witness, nFlags, CachingTransactionSignatureChecker(ptxTo, nIn, m_tx_out.nValue, cacheStore, *m_signature_cache, *txdata), &error)) { return std::nullopt; } else { - return error; + auto debug_str = strprintf("input %i of %s (wtxid %s), spending %s:%i", nIn, ptxTo->GetHash().ToString(), ptxTo->GetWitnessHash().ToString(), ptxTo->vin[nIn].prevout.hash.ToString(), ptxTo->vin[nIn].prevout.n); + return std::make_pair(error, std::move(debug_str)); } } @@ -2214,7 +2215,7 @@ bool CheckInputScripts(const CTransaction& tx, TxValidationState& state, flags & ~STANDARD_NOT_MANDATORY_VERIFY_FLAGS, cacheSigStore, &txdata); auto mandatory_result = check2(); if (!mandatory_result.has_value()) { - return state.Invalid(TxValidationResult::TX_NOT_STANDARD, strprintf("non-mandatory-script-verify-flag (%s)", ScriptErrorString(*result))); + return state.Invalid(TxValidationResult::TX_NOT_STANDARD, strprintf("non-mandatory-script-verify-flag (%s)", ScriptErrorString(result->first)), result->second); } else { // If the second check failed, it failed due to a mandatory script verification // flag, but the first check might have failed on a non-mandatory script @@ -2228,7 +2229,7 @@ bool CheckInputScripts(const CTransaction& tx, TxValidationState& state, // MANDATORY flag failures correspond to // TxValidationResult::TX_CONSENSUS. - return state.Invalid(TxValidationResult::TX_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(*result))); + return state.Invalid(TxValidationResult::TX_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(result->first)), result->second); } } @@ -2688,7 +2689,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, // Any transaction validation failure in ConnectBlock is a block consensus failure state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, tx_state.GetRejectReason(), tx_state.GetDebugMessage()); - LogInfo("Script validation error in block: %s\n", tx_state.GetRejectReason()); + LogInfo("Script validation error in block: %s\n", state.ToString()); return false; } control.Add(std::move(vChecks)); @@ -2716,8 +2717,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, auto parallel_result = control.Complete(); if (parallel_result.has_value()) { - state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(*parallel_result))); - LogInfo("Script validation error in block: %s", state.GetRejectReason()); + state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(parallel_result->first)), parallel_result->second); + LogInfo("Script validation error in block: %s", state.ToString()); return false; } const auto time_4{SteadyClock::now()}; diff --git a/src/validation.h b/src/validation.h index 14fe145730..6b67dc485b 100644 --- a/src/validation.h +++ b/src/validation.h @@ -347,7 +347,7 @@ public: CScriptCheck(CScriptCheck&&) = default; CScriptCheck& operator=(CScriptCheck&&) = default; - std::optional operator()(); + std::optional> operator()(); }; // CScriptCheck is used a lot in std::vector, make sure that's efficient From b49df703f031894b41ec1a624137e5d3206940b5 Mon Sep 17 00:00:00 2001 From: Pieter Wuille Date: Tue, 5 Nov 2024 08:35:57 -0500 Subject: [PATCH 4/5] [validation] include all logged information in BlockValidationState --- src/validation.cpp | 17 +++++++++++------ 1 file changed, 11 insertions(+), 6 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index b8f89f4b88..37a99547b9 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2596,7 +2596,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, for (size_t o = 0; o < tx->vout.size(); o++) { if (view.HaveCoin(COutPoint(tx->GetHash(), o))) { LogPrintf("ERROR: ConnectBlock(): tried to overwrite transaction\n"); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-BIP30"); + return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-BIP30", + "tried to overwrite transaction"); } } } @@ -2646,14 +2647,16 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, if (!Consensus::CheckTxInputs(tx, tx_state, view, pindex->nHeight, txfee)) { // Any transaction validation failure in ConnectBlock is a block consensus failure state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, - tx_state.GetRejectReason(), tx_state.GetDebugMessage()); + tx_state.GetRejectReason(), + tx_state.GetDebugMessage() + " in transaction " + tx.GetHash().ToString()); LogError("%s: Consensus::CheckTxInputs: %s, %s\n", __func__, tx.GetHash().ToString(), state.ToString()); return false; } nFees += txfee; if (!MoneyRange(nFees)) { LogPrintf("ERROR: %s: accumulated fee in the block out of range.\n", __func__); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-accumulated-fee-outofrange"); + return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-accumulated-fee-outofrange", + "accumulated fee in the block out of range"); } // Check that transaction is BIP68 final @@ -2666,7 +2669,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, if (!SequenceLocks(tx, nLockTimeFlags, prevheights, *pindex)) { LogPrintf("ERROR: %s: contains a non-BIP68-final transaction\n", __func__); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-nonfinal"); + return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-nonfinal", + "contains a non-BIP68-final transaction " + tx.GetHash().ToString()); } } @@ -2677,7 +2681,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, nSigOpsCost += GetTransactionSigOpCost(tx, view, flags); if (nSigOpsCost > MAX_BLOCK_SIGOPS_COST) { LogPrintf("ERROR: ConnectBlock(): too many sigops\n"); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-blk-sigops"); + return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-blk-sigops", "too many sigops"); } if (!tx.IsCoinBase()) @@ -2712,7 +2716,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, params.GetConsensus()); if (block.vtx[0]->GetValueOut() > blockReward) { LogPrintf("ERROR: ConnectBlock(): coinbase pays too much (actual=%d vs limit=%d)\n", block.vtx[0]->GetValueOut(), blockReward); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-cb-amount"); + return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-cb-amount", + strprintf("coinbase pays too much (actual=%d vs limit=%d)", block.vtx[0]->GetValueOut(), blockReward)); } auto parallel_result = control.Complete(); From 492e1f09943fcb6145c21d470299305a19e17d8b Mon Sep 17 00:00:00 2001 From: Pieter Wuille Date: Tue, 5 Nov 2024 09:31:30 -0500 Subject: [PATCH 5/5] [validation] merge all ConnectBlock debug logging code paths --- src/validation.cpp | 44 +++++++++++++++---------------- test/functional/feature_cltv.py | 2 +- test/functional/feature_dersig.py | 2 +- 3 files changed, 24 insertions(+), 24 deletions(-) diff --git a/src/validation.cpp b/src/validation.cpp index 37a99547b9..1cc4259919 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -2595,9 +2595,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, for (const auto& tx : block.vtx) { for (size_t o = 0; o < tx->vout.size(); o++) { if (view.HaveCoin(COutPoint(tx->GetHash(), o))) { - LogPrintf("ERROR: ConnectBlock(): tried to overwrite transaction\n"); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-BIP30", - "tried to overwrite transaction"); + state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-BIP30", + "tried to overwrite transaction"); } } } @@ -2636,6 +2635,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, blockundo.vtxundo.reserve(block.vtx.size() - 1); for (unsigned int i = 0; i < block.vtx.size(); i++) { + if (!state.IsValid()) break; const CTransaction &tx = *(block.vtx[i]); nInputs += tx.vin.size(); @@ -2649,14 +2649,13 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, tx_state.GetRejectReason(), tx_state.GetDebugMessage() + " in transaction " + tx.GetHash().ToString()); - LogError("%s: Consensus::CheckTxInputs: %s, %s\n", __func__, tx.GetHash().ToString(), state.ToString()); - return false; + break; } nFees += txfee; if (!MoneyRange(nFees)) { - LogPrintf("ERROR: %s: accumulated fee in the block out of range.\n", __func__); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-accumulated-fee-outofrange", - "accumulated fee in the block out of range"); + state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-accumulated-fee-outofrange", + "accumulated fee in the block out of range"); + break; } // Check that transaction is BIP68 final @@ -2668,9 +2667,9 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, } if (!SequenceLocks(tx, nLockTimeFlags, prevheights, *pindex)) { - LogPrintf("ERROR: %s: contains a non-BIP68-final transaction\n", __func__); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-nonfinal", - "contains a non-BIP68-final transaction " + tx.GetHash().ToString()); + state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-txns-nonfinal", + "contains a non-BIP68-final transaction " + tx.GetHash().ToString()); + break; } } @@ -2680,8 +2679,8 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, // * witness (when witness enabled in flags and excludes coinbase) nSigOpsCost += GetTransactionSigOpCost(tx, view, flags); if (nSigOpsCost > MAX_BLOCK_SIGOPS_COST) { - LogPrintf("ERROR: ConnectBlock(): too many sigops\n"); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-blk-sigops", "too many sigops"); + state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-blk-sigops", "too many sigops"); + break; } if (!tx.IsCoinBase()) @@ -2693,8 +2692,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, // Any transaction validation failure in ConnectBlock is a block consensus failure state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, tx_state.GetRejectReason(), tx_state.GetDebugMessage()); - LogInfo("Script validation error in block: %s\n", state.ToString()); - return false; + break; } control.Add(std::move(vChecks)); } @@ -2714,16 +2712,17 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, Ticks(m_chainman.time_connect) / m_chainman.num_blocks_total); CAmount blockReward = nFees + GetBlockSubsidy(pindex->nHeight, params.GetConsensus()); - if (block.vtx[0]->GetValueOut() > blockReward) { - LogPrintf("ERROR: ConnectBlock(): coinbase pays too much (actual=%d vs limit=%d)\n", block.vtx[0]->GetValueOut(), blockReward); - return state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-cb-amount", - strprintf("coinbase pays too much (actual=%d vs limit=%d)", block.vtx[0]->GetValueOut(), blockReward)); + if (block.vtx[0]->GetValueOut() > blockReward && state.IsValid()) { + state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, "bad-cb-amount", + strprintf("coinbase pays too much (actual=%d vs limit=%d)", block.vtx[0]->GetValueOut(), blockReward)); } auto parallel_result = control.Complete(); - if (parallel_result.has_value()) { + if (parallel_result.has_value() && state.IsValid()) { state.Invalid(BlockValidationResult::BLOCK_CONSENSUS, strprintf("mandatory-script-verify-flag-failed (%s)", ScriptErrorString(parallel_result->first)), parallel_result->second); - LogInfo("Script validation error in block: %s", state.ToString()); + } + if (!state.IsValid()) { + LogInfo("Block validation error: %s", state.ToString()); return false; } const auto time_4{SteadyClock::now()}; @@ -2734,8 +2733,9 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state, Ticks(m_chainman.time_verify), Ticks(m_chainman.time_verify) / m_chainman.num_blocks_total); - if (fJustCheck) + if (fJustCheck) { return true; + } if (!m_blockman.WriteUndoDataForBlock(blockundo, state, *pindex)) { return false; diff --git a/test/functional/feature_cltv.py b/test/functional/feature_cltv.py index 52d0fd1704..557fcc7cea 100755 --- a/test/functional/feature_cltv.py +++ b/test/functional/feature_cltv.py @@ -174,7 +174,7 @@ class BIP65Test(BitcoinTestFramework): block.hashMerkleRoot = block.calc_merkle_root() block.solve() - with self.nodes[0].assert_debug_log(expected_msgs=[f'Script validation error in block: {expected_cltv_reject_reason}']): + with self.nodes[0].assert_debug_log(expected_msgs=[f'Block validation error: {expected_cltv_reject_reason}']): peer.send_and_ping(msg_block(block)) assert_equal(int(self.nodes[0].getbestblockhash(), 16), tip) peer.sync_with_ping() diff --git a/test/functional/feature_dersig.py b/test/functional/feature_dersig.py index 2180e7ce3d..1d18803f45 100755 --- a/test/functional/feature_dersig.py +++ b/test/functional/feature_dersig.py @@ -130,7 +130,7 @@ class BIP66Test(BitcoinTestFramework): block.hashMerkleRoot = block.calc_merkle_root() block.solve() - with self.nodes[0].assert_debug_log(expected_msgs=[f'Script validation error in block: mandatory-script-verify-flag-failed (Non-canonical DER signature)']): + with self.nodes[0].assert_debug_log(expected_msgs=[f'Block validation error: mandatory-script-verify-flag-failed (Non-canonical DER signature)']): peer.send_and_ping(msg_block(block)) assert_equal(int(self.nodes[0].getbestblockhash(), 16), tip) peer.sync_with_ping()