Diff to add more logging and indentation for clarity in https://github.com/JeremyRubin/bitcoin/blob/checktemplateverify-rebase-4-15-21/test/functional/feature_checktemplateverify.py

feature_checktemplateverify.py.diff

diff --git a/test/functional/feature_checktemplateverify.py b/test/functional/feature_checktemplateverify.py
index db312c026..5908bb01d 100755
--- a/test/functional/feature_checktemplateverify.py
+++ b/test/functional/feature_checktemplateverify.py
@@ -249,9 +249,7 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             amount_sats=amount_sats,
         )

-        self.log.info(
-            "Creating funding txn for 10 random outputs as a p2sh script (impossible to spend)"
-        )
+        self.log.info("Creating funding txn for 10 random outputs as a p2sh script (impossible to spend)")
         p2sh_ctv_funding_tx = create_transaction_to_script(
             self.nodes[0],
             wallet,
@@ -289,9 +287,7 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             amount_sats=amount_position_2,
         )

-        self.log.info(
-            "Creating script for spend at position 1 with 2 non-null scriptsigs"
-        )
+        self.log.info("Creating script for spend at position 1 with 2 non-null scriptsigs")
         (
             outputs_specific_scriptSigs,
             script_specific_scriptSigs,
@@ -306,9 +302,7 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             sum(out.nValue for out in outputs_specific_scriptSigs) + 200 * 500
         )

-        self.log.info(
-            "Creating funding txn for spend at position 1 with 2 non-null scriptsigs"
-        )
+        self.log.info("Creating funding txn for spend at position 1 with 2 non-null scriptsigs")
         bare_ctv_specific_scriptSigs_funding_tx = create_transaction_to_script(
             self.nodes[0],
             wallet,
@@ -317,9 +311,7 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             amount_sats=amount_specific_scriptSigs,
         )

-        self.log.info(
-            "Creating script for spend at position 2 with 2 non-null scriptsigs"
-        )
+        self.log.info("Creating script for spend at position 2 with 2 non-null scriptsigs")
         (
             outputs_specific_scriptSigs_position_2,
             script_specific_scriptSigs_position_2,
@@ -335,9 +327,7 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             + 200 * 500
         )

-        self.log.info(
-            "Creating funding txn for spend at position 2 with 2 non-null scriptsigs"
-        )
+        self.log.info("Creating funding txn for spend at position 2 with 2 non-null scriptsigs")
         bare_ctv_specific_scriptSigs_position_2_funding_tx = (
             create_transaction_to_script(
                 self.nodes[0],
@@ -396,8 +386,8 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
         self.log.info("Funding all outputs")
         self.add_block(funding_txs)

-        self.log.info("Testing Taproot OP_CHECKTEMPLATEVERIFY spend")
         # Test sendrawtransaction
+        self.log.info("Testing Taproot OP_CHECKTEMPLATEVERIFY spend")
         taproot_check_template_verify_tx = CTransaction()
         taproot_check_template_verify_tx.nVersion = 2
         taproot_check_template_verify_tx.vin = [CTxIn(taproot_ctv_outpoint)]
@@ -413,25 +403,19 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             ),
             taproot_check_template_verify_tx.rehash(),
         )
-        self.log.info(
-            "Taproot OP_CHECKTEMPLATEVERIFY spend accepted by sendrawtransaction"
-        )
-
+        self.log.info("  Taproot OP_CHECKTEMPLATEVERIFY spend accepted by sendrawtransaction")
         # Now we verify that a block with this transaction is also valid
         blockhash = self.add_block([taproot_check_template_verify_tx])
-        self.log.info("Taproot OP_CHECKTEMPLATEVERIFY spend accepted in a block")
-
-        self.log.info("Rolling back the block")
-        # Reset tip
+        self.log.info("  Taproot OP_CHECKTEMPLATEVERIFY spend accepted in a block")
+        self.log.info("  Rolling back the block")
         self.nodes[0].invalidateblock(blockhash)

-        self.log.info("Testing Segwit OP_CHECKTEMPLATEVERIFY spend")
         # Test sendrawtransaction
+        self.log.info("Testing Segwit OP_CHECKTEMPLATEVERIFY spend")
         check_template_verify_tx = CTransaction()
         check_template_verify_tx.nVersion = 2
         check_template_verify_tx.vin = [CTxIn(segwit_ctv_outpoint)]
         check_template_verify_tx.vout = outputs
-
         check_template_verify_tx.wit.vtxinwit += [CTxInWitness()]
         check_template_verify_tx.wit.vtxinwit[0].scriptWitness.stack = [script]
         assert_equal(
@@ -440,118 +424,92 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             ),
             check_template_verify_tx.rehash(),
         )
-        self.log.info(
-            "Segwit OP_CHECKTEMPLATEVERIFY spend accepted by sendrawtransaction"
-        )
+        self.log.info("  Segwit OP_CHECKTEMPLATEVERIFY spend accepted by sendrawtransaction")

         # Now we verify that a block with this transaction is also valid
         blockhash = self.add_block([check_template_verify_tx])
-        self.log.info("Segwit OP_CHECKTEMPLATEVERIFY spend accepted in a block")
-
-        self.log.info("Rolling back the block")
-        # Reset tip
+        self.log.info("  Segwit OP_CHECKTEMPLATEVERIFY spend accepted in a block")
+        self.log.info("  Rolling back the block")
         self.nodes[0].invalidateblock(blockhash)

         # Show any modification will break the validity
-        self.log.info(
-            "Modifying Segwit OP_CHECKTEMPLATEVERIFY spend, block should fail"
-        )
+        self.log.info("Testing spend of modified Segwit OP_CHECKTEMPLATEVERIFY spend, block should fail")
         check_template_verify_tx_mutated_amount = check_template_verify_tx
         check_template_verify_tx_mutated_amount.vout[0].nValue += 1
         check_template_verify_tx_mutated_amount.rehash()
         self.fail_block([check_template_verify_tx_mutated_amount])
-        self.log.info("Modified Segwit OP_CHECKTEMPLATEVERIFY spend failed to confirm")
+        self.log.info("  Modified Segwit OP_CHECKTEMPLATEVERIFY spend disallowed in block")

         # Now show that only one input allowed
-        self.log.info("Testing that multiple inputs are disallowed when specified")
+        self.log.info("Testing multiple inputs are disallowed when specified, block should fail")
         check_template_verify_two_inputs = check_template_verify_tx
         check_template_verify_two_inputs.vin += [CTxIn(anyone_can_spend_outpoint)]
         check_template_verify_two_inputs.rehash()
         self.fail_block([check_template_verify_two_inputs])
-
-        self.log.info(
-            "Testing that the second input specified was actually spendable by itself"
-        )
+        self.log.info("  Multiple inputs for OP_CHECKTEMPLATEVERIFY disallowed in block")

         # Second UTXO was actually spendable
+        self.log.info("Testing that the second input specified was actually spendable by itself")
         spendtx = CTransaction()
         spendtx.nVersion = 2
         spendtx.vin = [CTxIn(anyone_can_spend_outpoint)]
         spendtx.vout += [CTxOut(int(amount_sats - 1000), random_p2sh())]
         spendtx.rehash()
         blockhash = self.add_block([spendtx])
-        # Reset tip
+        self.log.info("  Second input was accepted in a block")
+        self.log.info("  Rolling back the block")
         self.nodes[0].invalidateblock(blockhash)

-        self.log.info(
-            "Testing Segwit OP_CHECKTEMPLATEVERIFY spend with a wrong size argument"
-        )
         # Test sendrawtransaction
+        self.log.info("Testing Segwit OP_CHECKTEMPLATEVERIFY spend with a wrong size argument")
         check_template_verify_tx_wrongsize_stack = CTransaction()
         check_template_verify_tx_wrongsize_stack.nVersion = 2
         check_template_verify_tx_wrongsize_stack.vin = [
             CTxIn(segwit_ctv_wrongsize_stack_outpoint)
         ]
         check_template_verify_tx_wrongsize_stack.vout = outputs
-
         check_template_verify_tx_wrongsize_stack.wit.vtxinwit += [CTxInWitness()]
         check_template_verify_tx_wrongsize_stack.wit.vtxinwit[0].scriptWitness.stack = [
             CScript([OP_TRUE, OP_CHECKTEMPLATEVERIFY])
         ]
-
         assert_raises_rpc_error(
             -26,
             DISCOURAGED_ERROR,
             self.nodes[0].sendrawtransaction,
             check_template_verify_tx_wrongsize_stack.serialize().hex(),
         )
-        self.log.info(
-            "OP_CHECKTEMPLATEVERIFY with wrong size stack rejected by sendrawtransaction as discouraged"
-        )
-
+        self.log.info("  OP_CHECKTEMPLATEVERIFY with wrong size stack rejected by sendrawtransaction as discouraged")
         # Now we verify that a block with this transaction is valid
         blockhash = self.add_block([check_template_verify_tx_wrongsize_stack])
-        self.log.info(
-            "Segwit OP_CHECKTEMPLATEVERIFY with wrong size stack spend accepted in a block (soft fork upgradable)"
-        )
+        self.log.info("  Segwit OP_CHECKTEMPLATEVERIFY with wrong size stack spend accepted in a block (soft fork upgradable)")
+        self.log.info("  Rolling back the block")
+        self.nodes[0].invalidateblock(blockhash)

-        self.log.info(
-            "Testing Segwit OP_CHECKTEMPLATEVERIFY spend with an empty stack argument"
-        )
         # Test sendrawtransaction
+        self.log.info("Testing Segwit OP_CHECKTEMPLATEVERIFY spend with an empty stack argument, block should fail")
         check_template_verify_tx_empty_stack = CTransaction()
         check_template_verify_tx_empty_stack.nVersion = 2
         check_template_verify_tx_empty_stack.vin = [
             CTxIn(segwit_ctv_empty_stack_outpoint)
         ]
         check_template_verify_tx_empty_stack.vout = outputs
-
         check_template_verify_tx_empty_stack.wit.vtxinwit += [CTxInWitness()]
         check_template_verify_tx_empty_stack.wit.vtxinwit[0].scriptWitness.stack = [
             empty_stack_script
         ]
-
         assert_raises_rpc_error(
             -26,
             STACK_TOO_SHORT_ERROR,
             self.nodes[0].sendrawtransaction,
             check_template_verify_tx_empty_stack.serialize().hex(),
         )
-
-        self.log.info(
-            "OP_CHECKTEMPLATEVERIFY with wrong size stack rejected by sendrawtransaction as discouraged"
-        )
-
+        self.log.info("  OP_CHECKTEMPLATEVERIFY with wrong size stack rejected by sendrawtransaction as discouraged")
         # Now we verify that a block with this transaction is invalid
         self.fail_block([check_template_verify_tx_empty_stack], STACK_TOO_SHORT_ERROR)
-        self.log.info(
-            "Segwit OP_CHECKTEMPLATEVERIFY with wrong size stack spend rejected from block"
-        )
+        self.log.info("  Segwit OP_CHECKTEMPLATEVERIFY with wrong size stack spend rejected from block")

         # Show that putting some element on the stack makes it succeed for consensus but fail policy
-        self.log.info(
-            "Segwit OP_CHECKTEMPLATEVERIFY with CTV argument in the program should fail policy pass consensus if witness stack is not 32 bytes"
-        )
+        self.log.info("Testing Segwit OP_CHECKTEMPLATEVERIFY with CTV argument in the program should fail policy pass consensus if witness stack is not 32 bytes")
         check_template_verify_tx_empty_stack.wit.vtxinwit[0].scriptWitness.stack = [
             CScript([OP_TRUE]),
             empty_stack_script,
@@ -562,23 +520,16 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             self.nodes[0].sendrawtransaction,
             check_template_verify_tx_empty_stack.serialize().hex(),
         )
-        self.log.info(
-            "OP_CHECKTEMPLATEVERIFY with wrong size argument on the witness stack rejected by sendrawtransaction as discouraged"
-        )
-
+        self.log.info("  OP_CHECKTEMPLATEVERIFY with wrong size argument on the witness stack rejected by sendrawtransaction as discouraged")
         # Now we verify that a block with this transaction is valid
         blockhash = self.add_block([check_template_verify_tx_empty_stack])
-        self.log.info(
-            "Segwit OP_CHECKTEMPLATEVERIFY with empty stack spend accepted in a block with something on the witness stack"
-        )
-        self.log.info("Rolling back the block")
+        self.log.info("  Segwit OP_CHECKTEMPLATEVERIFY with empty stack spend accepted in a block with something on the witness stack")
+        self.log.info("  Rolling back the block")
         # Reset tip
         self.nodes[0].invalidateblock(blockhash)

         # Put the correct hash on
-        self.log.info(
-            "Testing OP_CHECKTEMPLATEVERIFY spend with template hash from the witness stack"
-        )
+        self.log.info("Testing OP_CHECKTEMPLATEVERIFY spend with template hash from the witness stack")
         h = check_template_verify_tx_empty_stack.get_standard_template_hash(0)
         check_template_verify_tx_empty_stack.wit.vtxinwit[0].scriptWitness.stack = [
             h,
@@ -590,29 +541,27 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             ),
             check_template_verify_tx_empty_stack.rehash(),
         )
-        self.log.info(
-            "Witness stack defined OP_CHECKTEMPLATEVERIFY spend accepted by sendrawtransaction"
-        )
+        self.log.info("  Witness stack defined OP_CHECKTEMPLATEVERIFY spend accepted by sendrawtransaction")
         # Now we verify that a block with this transaction is also valid
         blockhash = self.add_block([check_template_verify_tx_empty_stack])
-        self.log.info(
-            "Witness stack defined OP_CHECKTEMPLATEVERIFY spend accepted in a block"
-        )
-        self.log.info("Rolling back the block")
+        self.log.info("  Witness stack defined OP_CHECKTEMPLATEVERIFY spend accepted in a block")
+        self.log.info("  Rolling back the block")
         # Reset tip
         self.nodes[0].invalidateblock(blockhash)

-        self.log.info(
-            "Testing that other 32 byte arguments passed from the witness stack fail"
-        )
+        self.log.info("Testing that other 32 byte arguments passed from the witness stack rejected, block should fail")
         h = h[::-1]
         check_template_verify_tx_empty_stack.wit.vtxinwit[0].scriptWitness.stack = [
             h,
             empty_stack_script,
         ]
         self.fail_block([check_template_verify_tx_empty_stack])
+        self.log.info("  Other 32 byte arguments from witness stack failed to confirm")
+

         # Test sendrawtransaction with P2SH
+        ## ADDED THIS
+        self.log.info("Testing that P2SH OP_CHECKTEMPLATEVERIFY spend is rejected by sendrawtransaction, block should fail")
         # Mathematically, this test cannot succeed since P2SH requires that the
         # P2SH script is in the scriptsig (which contains H), and H much
         # contain a commitment to the scriptsig.
@@ -635,18 +584,14 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             self.nodes[0].sendrawtransaction,
             p2sh_check_template_verify_tx.serialize().hex(),
         )
-        self.log.info(
-            "P2SH OP_CHECKTEMPLATEVERIFY spend rejected by sendrawtransaction"
-        )
+        self.log.info("  P2SH OP_CHECKTEMPLATEVERIFY spend rejected by sendrawtransaction")

         # Now we verify that a block with this transaction is also invalid
         self.fail_block([p2sh_check_template_verify_tx])
-        self.log.info("P2SH OP_CHECKTEMPLATEVERIFY spend rejected in a block")
+        self.log.info("  P2SH OP_CHECKTEMPLATEVERIFY spend rejected in a block")

-        self.log.info(
-            "Testing a congestion control tree using bare OP_CHECKTEMPLATEVERIFY"
-        )
         # Expand Congestion Control Tree to one specific input
+        self.log.info("Testing a congestion control tree using bare OP_CHECKTEMPLATEVERIFY")
         out = bare_ctv_tree_outpoint
         txs = []
         for level in congestion_tree_txo[1:]:
@@ -657,39 +602,41 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
             out = COutPoint(int(spendtx.rehash(), 16), 0)
             txs.append(spendtx)
         self.add_block(txs)
+        self.log.info("  Congestion control tree using bare OP_CHECKTEMPLATEVERIFY accepted in block")
+        self.log.info("  Rolling back the block")
+        self.nodes[0].invalidateblock(blockhash)

         self.log.info("Testing bare OP_CHECKTEMPLATEVERIFY with CTV at position 2")
         check_template_verify_tx_pos_2 = CTransaction()
         check_template_verify_tx_pos_2.nVersion = 2
         check_template_verify_tx_pos_2.vin = [CTxIn(bare_ctv_position_2_outpoint)]
         check_template_verify_tx_pos_2.vout = outputs_position_2
-        self.log.info(
-            "Testing that the transaction fails because we have too few inputs"
-        )
+
+        self.log.info("  Testing that the transaction fails because we have too few inputs")
         self.fail_block([check_template_verify_tx_pos_2])
+        self.log.info("    Too few inputs failed to confirm")
+
+        self.log.info("  Testing that the transaction fails because the inputs are in the wrong order")
         check_template_verify_tx_pos_2.vin += [CTxIn(bare_anyone_can_spend_outpoint)]
         check_template_verify_tx_pos_2.rehash()
-        self.log.info(
-            "Testing that the transaction fails because the inputs are in the wrong order"
-        )
         self.fail_block([check_template_verify_tx_pos_2])
-        self.log.info(
-            "Testing that the transaction succeeds when the inputs are in the correct order"
-        )
+        self.log.info("    Inputs in wrong order failed to confirm")
+
+        self.log.info("  Testing that the transaction succeeds when the inputs are in the correct order")
         check_template_verify_tx_pos_2.vin.reverse()
         check_template_verify_tx_pos_2.rehash()
         blockhash = self.add_block([check_template_verify_tx_pos_2])
+        self.log.info("    Transaction added to the block")
+        self.log.info("  Rolling back the block")
         self.nodes[0].invalidateblock(blockhash)
+
+        self.log.info("Testing transaction fails because the scriptSig on the other input has been modified, block should fail")
         check_template_verify_tx_pos_2.vin[0].scriptSig = CScript([OP_TRUE])
         check_template_verify_tx_pos_2.rehash()
-        self.log.info(
-            "Testing that the transaction fails because the scriptSig on the other input has been modified"
-        )
         self.fail_block([check_template_verify_tx_pos_2])
+        self.log.info("  Modification of scriptSig failed to confirm")

-        self.log.info(
-            "Testing bare OP_CHECKTEMPLATEVERIFY with CTV at position 1 with specific scriptSigs"
-        )
+        self.log.info("Testing bare OP_CHECKTEMPLATEVERIFY with CTV at position 1 with specific scriptSigs, block should fail")
         check_template_verify_tx_specific_scriptSigs = CTransaction()
         check_template_verify_tx_specific_scriptSigs.nVersion = 2
         check_template_verify_tx_specific_scriptSigs.vin = [
@@ -698,23 +645,21 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
         ]
         check_template_verify_tx_specific_scriptSigs.vout = outputs_specific_scriptSigs
         check_template_verify_tx_specific_scriptSigs.rehash()
-        self.log.info(
-            "Testing bare OP_CHECKTEMPLATEVERIFY rejects incorrect scriptSigs"
-        )
+        self.log.info("  Testing bare OP_CHECKTEMPLATEVERIFY rejects incorrect scriptSigs")
         self.fail_block([check_template_verify_tx_specific_scriptSigs])
-
+        self.log.info("  Transaction with incorrect scriptSig failed to confirm")
         self.log.info("Testing bare OP_CHECKTEMPLATEVERIFY accepts correct scriptSigs")
         check_template_verify_tx_specific_scriptSigs.vin[1].scriptSig = CScript(
             [OP_FALSE]
         )
         check_template_verify_tx_specific_scriptSigs.rehash()
         blockhash = self.add_block([check_template_verify_tx_specific_scriptSigs])
+        self.log.info("  Transaction with correct scriptSig allowed in block")
+        self.log.info("  Rolling back the block")
         self.nodes[0].invalidateblock(blockhash)

-        self.log.info(
-            "Testing bare OP_CHECKTEMPLATEVERIFY with CTV at position 2 with specific scriptSigs"
-        )
         # This is only really to test that uncached values work correctly with scriptSig set
+        self.log.info("Testing bare OP_CHECKTEMPLATEVERIFY with CTV at position 2 with specific scriptSigs")
         check_template_verify_tx_specific_scriptSigs_position_2 = CTransaction()
         check_template_verify_tx_specific_scriptSigs_position_2.nVersion = 2
         check_template_verify_tx_specific_scriptSigs_position_2.vin = [
@@ -728,6 +673,9 @@ class CheckTemplateVerifyTest(BitcoinTestFramework):
         )
         check_template_verify_tx_specific_scriptSigs_position_2.rehash()
         self.add_block([check_template_verify_tx_specific_scriptSigs_position_2])
+        self.log.info("  Transaction allowed in block")
+        self.log.info("  Rolling back the block")
+        self.nodes[0].invalidateblock(blockhash)


 if __name__ == "__main__":