Merge bitcoin/bitcoin#31112: Improve parallel script validation error debug logging

492e1f0 [validation] merge all ConnectBlock debug logging code paths (Pieter Wuille)
b49df70 [validation] include all logged information in BlockValidationState (Pieter Wuille)
7b267c0 [validation] Add detailed txin/txout information for script error messages (Pieter Wuille)
146a3d5 [validation] Make script error messages uniform for parallel/single validation (Pieter Wuille)
1ac1c33 [checkqueue] support user-defined return type through std::optional (Pieter Wuille)

Pull request description:

  ~~Builds on top of #31097~~ (now merged). Fixes #30960.

  So far, detailed information about script validation failures is only reported when running with `-par=1`, due to a lack of ability to transfer information from the script validation threads to the validation thread. Fix this by extending the `CCheckQueue` functionality to pass more results through than just success/failure, and use this to report the exact Script error, as well as the transaction input in which it occurred.

ACKs for top commit:
  achow101:
    ACK 492e1f0
  furszy:
    Code review ACK 492e1f0
  maflcko:
    re-ACK 492e1f0 🍈
  dergoegge:
    ACK 492e1f0
  instagibbs:
    ACK 492e1f0
  mzumsande:
    Code Review ACK 492e1f0

Tree-SHA512: 234f2e7dfd03bdcd2a56200875fe370962f211ea7ed334038a6a9279a758030bf94bb6246f60d06dd0473dac4b9dbf050d9a32ecaa4176f7727eff63572bf4fd

Author: achow101

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<int> 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);

src/checkqueue.h

@@ -11,19 +11,24 @@
 
 #include <algorithm>
 #include <iterator>
+#include <optional>
 #include <vector>
 
 /**
  * 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<R>.
+  *
+  * 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 <typename T>
+template <typename T, typename R = std::remove_cvref_t<decltype(std::declval<T>()().value())>>
 class CCheckQueue
 {
 private:
@@ -47,7 +52,7 @@ class CCheckQueue
     int nTotal GUARDED_BY(m_mutex){0};
 
     //! The temporary evaluation result.
-    bool fAllOk GUARDED_BY(m_mutex){true};
+    std::optional<R> m_result GUARDED_BY(m_mutex);
 
     /**
      * Number of verifications that haven't completed yet.
@@ -62,24 +67,28 @@ class CCheckQueue
     std::vector<std::thread> 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<R> Loop(bool fMaster) EXCLUSIVE_LOCKS_REQUIRED(!m_mutex)
     {
         std::condition_variable& cond = fMaster ? m_master_cv : m_worker_cv;
         std::vector<T> vChecks;
         vChecks.reserve(nBatchSize);
         unsigned int nNow = 0;
-        bool fOk = true;
+        std::optional<R> 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 @@ class CCheckQueue
                 while (queue.empty() && !m_request_stop) {
                     if (fMaster && nTodo == 0) {
                         nTotal--;
-                        bool fRet = fAllOk;
+                        std::optional<R> 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 @@ class CCheckQueue
                 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 @@ class CCheckQueue
     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<R> Complete() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex)
     {
         return Loop(true /* master thread */);
     }
@@ -188,11 +202,11 @@ class CCheckQueue
  * RAII-style controller object for a CCheckQueue that guarantees the passed
  * queue is finished before continuing.
  */
-template <typename T>
+template <typename T, typename R = std::remove_cvref_t<decltype(std::declval<T>()().value())>>
 class CCheckQueueControl
 {
 private:
-    CCheckQueue<T> * const pqueue;
+    CCheckQueue<T, R> * const pqueue;
     bool fDone;
 
 public:
@@ -207,13 +221,12 @@ class CCheckQueueControl
         }
     }
 
-    bool Wait()
+    std::optional<R> 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<T>&& vChecks)
@@ -226,7 +239,7 @@ class CCheckQueueControl
     ~CCheckQueueControl()
     {
         if (!fDone)
-            Wait();
+            Complete();
         if (pqueue != nullptr) {
             LEAVE_CRITICAL_SECTION(pqueue->m_control_mutex);
         }

src/test/checkqueue_tests.cpp

@@ -42,50 +42,48 @@ static const unsigned int QUEUE_BATCH_SIZE = 128;
 static const int SCRIPT_CHECK_THREADS = 3;
 
 struct FakeCheck {
-    bool operator()() const
+    std::optional<int> operator()() const
     {
-        return true;
+        return std::nullopt;
     }
 };
 
 struct FakeCheckCheckCompletion {
     static std::atomic<size_t> n_calls;
-    bool operator()()
+    std::optional<int> 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<int> m_result;
+    FixedCheck(std::optional<int> result) : m_result(result){};
+    std::optional<int> operator()() const { return m_result; }
 };
 
 struct UniqueCheck {
     static Mutex m;
     static std::unordered_multiset<size_t> results GUARDED_BY(m);
     size_t check_id;
     UniqueCheck(size_t check_id_in) : check_id(check_id_in){};
-    bool operator()()
+    std::optional<int> operator()()
     {
         LOCK(m);
         results.insert(check_id);
-        return true;
+        return std::nullopt;
     }
 };
 
 
 struct MemoryCheck {
     static std::atomic<size_t> fake_allocated_memory;
     bool b {false};
-    bool operator()() const
+    std::optional<int> 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<int> operator()() const
     {
-        return true;
+        return std::nullopt;
     }
     FrozenCleanupCheck() = default;
     ~FrozenCleanupCheck()
@@ -149,7 +147,7 @@ std::atomic<size_t> MemoryCheck::fake_allocated_memory{0};
 // Queue Typedefs
 typedef CCheckQueue<FakeCheckCheckCompletion> Correct_Queue;
 typedef CCheckQueue<FakeCheck> Standard_Queue;
-typedef CCheckQueue<FailingCheck> Failing_Queue;
+typedef CCheckQueue<FixedCheck> Fixed_Queue;
 typedef CCheckQueue<UniqueCheck> Unique_Queue;
 typedef CCheckQueue<MemoryCheck> Memory_Queue;
 typedef CCheckQueue<FrozenCleanupCheck> FrozenCleanup_Queue;
@@ -174,7 +172,7 @@ void CheckQueueTest::Correct_Queue_range(std::vector<size_t> 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,45 +215,45 @@ 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<Failing_Queue>(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS);
+    auto fixed_queue = std::make_unique<Fixed_Queue>(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS);
     for (size_t i = 0; i < 1001; ++i) {
-        CCheckQueueControl<FailingCheck> control(fail_queue.get());
+        CCheckQueueControl<FixedCheck> control(fixed_queue.get());
         size_t remaining = i;
         while (remaining) {
             size_t r = m_rng.randrange(10);
 
-            std::vector<FailingCheck> vChecks;
+            std::vector<FixedCheck> 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<int>(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<int>(17 * i));
+        } else {
+            BOOST_REQUIRE(!result.has_value());
         }
     }
 }
 // Test that a block validation which fails does not interfere with
 // future blocks, ie, the bad state is cleared.
 BOOST_AUTO_TEST_CASE(test_CheckQueue_Recovers_From_Failure)
 {
-    auto fail_queue = std::make_unique<Failing_Queue>(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS);
+    auto fail_queue = std::make_unique<Fixed_Queue>(QUEUE_BATCH_SIZE, SCRIPT_CHECK_THREADS);
     for (auto times = 0; times < 10; ++times) {
         for (const bool end_fails : {true, false}) {
-            CCheckQueueControl<FailingCheck> control(fail_queue.get());
+            CCheckQueueControl<FixedCheck> control(fail_queue.get());
             {
-                std::vector<FailingCheck> vChecks;
-                vChecks.resize(100, false);
-                vChecks[99] = end_fails;
+                std::vector<FixedCheck> vChecks;
+                vChecks.resize(100, FixedCheck(std::nullopt));
+                vChecks[99] = FixedCheck(end_fails ? std::make_optional<int>(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<FrozenCleanupCheck> control(queue.get());
         std::vector<FrozenCleanupCheck> 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<std::mutex> l(FrozenCleanupCheck::m);

src/test/fuzz/checkqueue.cpp

@@ -19,9 +19,10 @@ struct DumbCheck {
     {
     }
 
-    bool operator()() const
+    std::optional<int> operator()() const
     {
-        return result;
+        if (result) return std::nullopt;
+        return 1;
     }
 };
 } // namespace
@@ -45,14 +46,14 @@ 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<DumbCheck> check_queue_control{&check_queue_2};
     if (fuzzed_data_provider.ConsumeBool()) {
         check_queue_control.Add(std::move(checks_2));
     }
     if (fuzzed_data_provider.ConsumeBool()) {
-        (void)check_queue_control.Wait();
+        (void)check_queue_control.Complete();
     }
 }

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<NodeSeconds>()).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) {