log: separate script verification reasons

Replace `fScriptChecks` with `script_check_reason` and log the precise reason when checks are enabled; log a plain "Disabling" when they are skipped.
Adjust the functional test to assert the new reason strings.

Co-authored-by: w0xlt <woltx@protonmail.com>
Co-authored-by: Eunovo <eunovo9@gmail.com>
Co-authored-by: Hodlinator <172445034+hodlinator@users.noreply.github.com>
Co-authored-by: TheCharlatan <seb.kung@gmail.com>
Co-authored-by: Andrew Toth <andrewstoth@gmail.com>

src/validation.cpp

@@ -2423,9 +2423,9 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
         return true;
     }
 
-    bool fScriptChecks = true;
+    const char* script_check_reason;
     if (m_chainman.AssumedValidBlock().IsNull()) {
-        // TODO
+        script_check_reason = "assumevalid=0 (always verify)";
     } else {
         constexpr int64_t TWO_WEEKS_IN_SECONDS{60 * 60 * 24 * 7 * 2};
         // We've been configured with the hash of a block which has been externally verified to have a valid history.
@@ -2435,15 +2435,15 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
         //  effectively caching the result of part of the verification.
         BlockMap::const_iterator it{m_blockman.m_block_index.find(m_chainman.AssumedValidBlock())};
         if (it == m_blockman.m_block_index.end()) {
-            // TODO
+            script_check_reason = "assumevalid hash not in headers";
         } else if (it->second.GetAncestor(pindex->nHeight) != pindex) {
-            // TODO
+            script_check_reason = "block not in assumevalid chain";
         } else if (m_chainman.m_best_header->GetAncestor(pindex->nHeight) != pindex) {
-            // TODO
+            script_check_reason = "block not in best header chain";
         } else if (m_chainman.m_best_header->nChainWork < m_chainman.MinimumChainWork()) {
-            // TODO
+            script_check_reason = "best header chainwork below minimumchainwork";
         } else if (GetBlockProofEquivalentTime(*m_chainman.m_best_header, *pindex, *m_chainman.m_best_header, params.GetConsensus()) <= TWO_WEEKS_IN_SECONDS) {
-            // TODO
+            script_check_reason = "block too recent relative to best header";
         } else {
             // This block is a member of the assumed verified chain and an ancestor of the best header.
             // Script verification is skipped when connecting blocks under the
@@ -2459,7 +2459,7 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
             //  artificially set the default assumed verified block further back.
             // The test against the minimum chain work prevents the skipping when denied access to any chain at
             //  least as good as the expected chain.
-            fScriptChecks = false;
+            script_check_reason = nullptr;
         }
     }
 
@@ -2572,15 +2572,16 @@ bool Chainstate::ConnectBlock(const CBlock& block, BlockValidationState& state,
              Ticks<SecondsDouble>(m_chainman.time_forks),
              Ticks<MillisecondsDouble>(m_chainman.time_forks) / m_chainman.num_blocks_total);
 
-    if (fScriptChecks != m_prev_script_checks_logged && GetRole() == ChainstateRole::NORMAL) {
+    const bool fScriptChecks{!!script_check_reason};
+    if (script_check_reason != m_last_script_check_reason_logged && GetRole() == ChainstateRole::NORMAL) {
         if (fScriptChecks) {
-            LogInfo("Enabling script verification at block #%d (%s).",
+            LogInfo("Enabling script verification at block #%d (%s): %s.",
-                    pindex->nHeight, block_hash.ToString());
+                    pindex->nHeight, block_hash.ToString(), script_check_reason);
         } else {
             LogInfo("Disabling script verification at block #%d (%s).",
                     pindex->nHeight, block_hash.ToString());
         }
-        m_prev_script_checks_logged = fScriptChecks;
+        m_last_script_check_reason_logged = script_check_reason;
     }
 
     CBlockUndo blockundo;

src/validation.h

@@ -560,7 +560,7 @@ protected:
     //! Cached result of LookupBlockIndex(*m_from_snapshot_blockhash)
     mutable const CBlockIndex* m_cached_snapshot_base GUARDED_BY(::cs_main){nullptr};
 
-    std::optional<bool> m_prev_script_checks_logged GUARDED_BY(::cs_main){};
+    std::optional<const char*> m_last_script_check_reason_logged GUARDED_BY(::cs_main){};
 
 public:
     //! Reference to a BlockManager instance which itself is shared across all

test/functional/feature_assumevalid.py

@@ -153,7 +153,7 @@ class AssumeValidTest(BitcoinTestFramework):
         # nodes[0]
         # Send blocks to node0. Block 102 will be rejected.
         with self.nodes[0].assert_debug_log(expected_msgs=[
-            f"Enabling script verification at block #1 ({block_1_hash})",
+            f"Enabling script verification at block #1 ({block_1_hash}): assumevalid=0 (always verify).",
             "Block validation error: block-script-verify-flag-failed",
         ]):
             p2p0 = self.nodes[0].add_p2p_connection(BaseNode())
@@ -169,7 +169,7 @@ class AssumeValidTest(BitcoinTestFramework):
         # nodes[1]
         with self.nodes[1].assert_debug_log(expected_msgs=[
             f"Disabling script verification at block #1 ({self.blocks[0].hash_hex}).",
-            f"Enabling script verification at block #103 ({self.blocks[102].hash_hex}).",
+            f"Enabling script verification at block #103 ({self.blocks[102].hash_hex}): block not in assumevalid chain.",
         ]):
             p2p1 = self.nodes[1].add_p2p_connection(BaseNode())
 
@@ -186,7 +186,7 @@ class AssumeValidTest(BitcoinTestFramework):
         # nodes[2]
         # Send blocks to node2. Block 102 will be rejected.
         with self.nodes[2].assert_debug_log(expected_msgs=[
-            f"Enabling script verification at block #1 ({block_1_hash})",
+            f"Enabling script verification at block #1 ({block_1_hash}): block too recent relative to best header.",
             "Block validation error: block-script-verify-flag-failed",
         ]):
             p2p2 = self.nodes[2].add_p2p_connection(BaseNode())
@@ -200,7 +200,7 @@ class AssumeValidTest(BitcoinTestFramework):
 
         # nodes[3]
         with self.nodes[3].assert_debug_log(expected_msgs=[
-            f"Enabling script verification at block #1 ({block_1_hash})",
+            f"Enabling script verification at block #1 ({block_1_hash}): block not in best header chain.",
         ]):
             best_hash = self.nodes[3].getbestblockhash()
             tip_block = self.nodes[3].getblock(best_hash)
@@ -227,7 +227,7 @@ class AssumeValidTest(BitcoinTestFramework):
         alt1 = create_block(int(genesis_hash, 16), create_coinbase(1), genesis_time + 2)
         alt1.solve()
         with self.nodes[4].assert_debug_log(expected_msgs=[
-            f"Enabling script verification at block #1 ({alt1.hash_hex})",
+            f"Enabling script verification at block #1 ({alt1.hash_hex}): block not in assumevalid chain.",
         ]):
             p2p4 = self.nodes[4].add_p2p_connection(BaseNode())
             p2p4.send_header_for_blocks(self.blocks[0:103])
@@ -243,12 +243,12 @@ class AssumeValidTest(BitcoinTestFramework):
         p2p5.send_without_ping(msg_block(self.blocks[0]))
         self.wait_until(lambda: self.nodes[5].getblockcount() == 1)
         with self.nodes[5].assert_debug_log(expected_msgs=[
-            f"Enabling script verification at block #1 ({block_1_hash})",
+            f"Enabling script verification at block #1 ({block_1_hash}): assumevalid hash not in headers.",
         ]):
             self.restart_node(5, extra_args=["-reindex-chainstate", "-assumevalid=1234567890abcdef1234567890abcdef1234567890abcdef1234567890abcdef"])
             assert_equal(self.nodes[5].getblockcount(), 1)
         with self.nodes[5].assert_debug_log(expected_msgs=[
-            f"Enabling script verification at block #1 ({block_1_hash})",
+            f"Enabling script verification at block #1 ({block_1_hash}): best header chainwork below minimumchainwork.",
         ]):
             self.restart_node(5, extra_args=["-reindex-chainstate", f"-assumevalid={block102.hash_hex}", "-minimumchainwork=0xffff"])
             assert_equal(self.nodes[5].getblockcount(), 1)