Merge bitcoin#9768: [qa] Add logging to test_framework.py

64c0800 Use logging in individual tests (John Newbery)
38ad281 Use logging in test_framework/comptool.py (John Newbery)
ff19073 Use logging in test_framework/blockstore.py (John Newbery)
2a9c7c7 Use logging in test_framework/util.py (John Newbery)
b0dec4a Remove manual debug settings in qa tests. (John Newbery)
af1363c Always enable debug log and microsecond logging for test nodes. (John Newbery)
6d0e325 Use logging in mininode.py (John Newbery)
553a976 Add logging to p2p-segwit.py (John Newbery)
0e6d23d Add logging to test_framework.py (John Newbery)

Tree-SHA512: 42ee2acbf444ec32d796f930f9f6e272da03c75e93d974a126d4ea9b2dbaa77cc57ab5e63ce3fd33d609049d884eb8d9f65272c08922d10f8db69d4a60ad05a3

qa/rpc-tests/abandonconflict.py

@@ -23,8 +23,8 @@ def __init__(self):
 
     def setup_network(self):
         self.nodes = []
-        self.nodes.append(start_node(0, self.options.tmpdir, ["-debug","-logtimemicros","-minrelaytxfee=0.00001"]))
-        self.nodes.append(start_node(1, self.options.tmpdir, ["-debug","-logtimemicros"]))
+        self.nodes.append(start_node(0, self.options.tmpdir, ["-minrelaytxfee=0.00001"]))
+        self.nodes.append(start_node(1, self.options.tmpdir))
         connect_nodes(self.nodes[0], 1)
 
     def run_test(self):
@@ -82,7 +82,7 @@ def run_test(self):
         # TODO: redo with eviction
         # Note had to make sure tx did not have AllowFree priority
         stop_node(self.nodes[0],0)
-        self.nodes[0]=start_node(0, self.options.tmpdir, ["-debug","-logtimemicros","-minrelaytxfee=0.0001"])
+        self.nodes[0]=start_node(0, self.options.tmpdir, ["-minrelaytxfee=0.0001"])
 
         # Verify txs no longer in mempool
         assert_equal(len(self.nodes[0].getrawmempool()), 0)
@@ -108,7 +108,7 @@ def run_test(self):
 
         # Verify that even with a low min relay fee, the tx is not reaccepted from wallet on startup once abandoned
         stop_node(self.nodes[0],0)
-        self.nodes[0]=start_node(0, self.options.tmpdir, ["-debug","-logtimemicros","-minrelaytxfee=0.00001"])
+        self.nodes[0]=start_node(0, self.options.tmpdir, ["-minrelaytxfee=0.00001"])
         assert_equal(len(self.nodes[0].getrawmempool()), 0)
         assert_equal(self.nodes[0].getbalance(), balance)
 
@@ -128,7 +128,7 @@ def run_test(self):
 
         # Remove using high relay fee again
         stop_node(self.nodes[0],0)
-        self.nodes[0]=start_node(0, self.options.tmpdir, ["-debug","-logtimemicros","-minrelaytxfee=0.0001"])
+        self.nodes[0]=start_node(0, self.options.tmpdir, ["-minrelaytxfee=0.0001"])
         assert_equal(len(self.nodes[0].getrawmempool()), 0)
         newbalance = self.nodes[0].getbalance()
         assert_equal(newbalance, balance - Decimal("24.9996"))
@@ -159,9 +159,9 @@ def run_test(self):
         self.nodes[0].invalidateblock(self.nodes[0].getbestblockhash())
         newbalance = self.nodes[0].getbalance()
         #assert_equal(newbalance, balance - Decimal("10"))
-        print("If balance has not declined after invalidateblock then out of mempool wallet tx which is no longer")
-        print("conflicted has not resumed causing its inputs to be seen as spent.  See Issue #7315")
-        print(str(balance) + " -> " + str(newbalance) + " ?")
+        self.log.info("If balance has not declined after invalidateblock then out of mempool wallet tx which is no longer")
+        self.log.info("conflicted has not resumed causing its inputs to be seen as spent.  See Issue #7315")
+        self.log.info(str(balance) + " -> " + str(newbalance) + " ?")
 
 if __name__ == '__main__':
     AbandonConflictTest().main()

qa/rpc-tests/assumevalid.py

@@ -73,7 +73,7 @@ def setup_network(self):
         # we need to pre-mine a block with an invalid transaction
         # signature so we can pass in the block hash as assumevalid.
         self.nodes = []
-        self.nodes.append(start_node(0, self.options.tmpdir, ["-debug"]))
+        self.nodes.append(start_node(0, self.options.tmpdir))
 
     def run_test(self):
 
@@ -146,14 +146,14 @@ def run_test(self):
 
         # Start node1 and node2 with assumevalid so they accept a block with a bad signature.
         self.nodes.append(start_node(1, self.options.tmpdir,
-                                     ["-debug", "-assumevalid=" + hex(block102.sha256)]))
+                                     ["-assumevalid=" + hex(block102.sha256)]))
         node1 = BaseNode()  # connects to node1
         connections.append(NodeConn('127.0.0.1', p2p_port(1), self.nodes[1], node1))
         node1.add_connection(connections[1])
         node1.wait_for_verack()
 
         self.nodes.append(start_node(2, self.options.tmpdir,
-                                     ["-debug", "-assumevalid=" + hex(block102.sha256)]))
+                                     ["-assumevalid=" + hex(block102.sha256)]))
         node2 = BaseNode()  # connects to node2
         connections.append(NodeConn('127.0.0.1', p2p_port(2), self.nodes[2], node2))
         node2.add_connection(connections[2])

qa/rpc-tests/bip65-cltv-p2p.py

@@ -42,7 +42,7 @@ def __init__(self):
     def setup_network(self):
         # Must set the blockversion for this test
         self.nodes = start_nodes(self.num_nodes, self.options.tmpdir,
-                                 extra_args=[['-debug', '-whitelist=127.0.0.1', '-blockversion=3']],
+                                 extra_args=[['-whitelist=127.0.0.1', '-blockversion=3']],
                                  binary=[self.options.testbinary])
 
     def run_test(self):

qa/rpc-tests/bip68-112-113-p2p.py

@@ -100,7 +100,7 @@ def setup_network(self):
         # Must set the blockversion for this test
         # Must also set '-maxtipage=600100' to allow syncing from very old blocks
         self.nodes = start_nodes(self.num_nodes, self.options.tmpdir,
-                                 extra_args=[['-debug', '-whitelist=127.0.0.1', '-blockversion=4', '-maxtipage=600100']],
+                                 extra_args=[['-whitelist=127.0.0.1', '-blockversion=4', '-maxtipage=600100']],
                                  binary=[self.options.testbinary])
 
     def run_test(self):

qa/rpc-tests/bip68-sequence.py

@@ -24,8 +24,8 @@ def __init__(self):
 
     def setup_network(self):
         self.nodes = []
-        self.nodes.append(start_node(0, self.options.tmpdir, ["-debug", "-blockprioritysize=0"]))
-        self.nodes.append(start_node(1, self.options.tmpdir, ["-debug", "-blockprioritysize=0", "-acceptnonstdtxn=0"]))
+        self.nodes.append(start_node(0, self.options.tmpdir, ["-blockprioritysize=0"]))
+        self.nodes.append(start_node(1, self.options.tmpdir, ["-blockprioritysize=0", "-acceptnonstdtxn=0"]))
         self.is_network_split = False
         self.relayfee = self.nodes[0].getnetworkinfo()["relayfee"]
         connect_nodes(self.nodes[0], 1)
@@ -34,26 +34,26 @@ def run_test(self):
         # Generate some coins
         self.nodes[0].generate(110)
 
-        print("Running test disable flag")
+        self.log.info("Running test disable flag")
         self.test_disable_flag()
 
-        print("Running test sequence-lock-confirmed-inputs")
+        self.log.info("Running test sequence-lock-confirmed-inputs")
         self.test_sequence_lock_confirmed_inputs()
 
-        print("Running test sequence-lock-unconfirmed-inputs")
+        self.log.info("Running test sequence-lock-unconfirmed-inputs")
         self.test_sequence_lock_unconfirmed_inputs()
 
-        print("Running test BIP68 not consensus before versionbits activation")
+        self.log.info("Running test BIP68 not consensus before versionbits activation")
         self.test_bip68_not_consensus()
 
-        print("Activating BIP68 (and 112/113)")
+        self.log.info("Activating BIP68 (and 112/113)")
         self.activateCSV()
 
-        print("Verifying nVersion=2 transactions are standard.")
-        print("Note that with current versions of Dash Core software, nVersion=2 transactions are always standard (independent of BIP68 activation status).")
+        self.log.info("Verifying nVersion=2 transactions are standard.")
+        self.log.info("Note that nVersion=2 transactions are always standard (independent of BIP68 activation status).")
         self.test_version2_relay()
 
-        print("Passed\n")
+        self.log.info("Passed")
 
     # Test that BIP68 is not in effect if tx version is 1, or if
     # the first sequence bit is set.

qa/rpc-tests/bip9-softforks.py

@@ -35,7 +35,7 @@ def __init__(self):
 
     def setup_network(self):
         self.nodes = start_nodes(self.num_nodes, self.options.tmpdir,
-                                 extra_args=[['-debug', '-whitelist=127.0.0.1']],
+                                 extra_args=[['-whitelist=127.0.0.1']],
                                  binary=[self.options.testbinary])
 
     def run_test(self):

qa/rpc-tests/bipdersig-p2p.py

@@ -49,7 +49,7 @@ def __init__(self):
     def setup_network(self):
         # Must set the blockversion for this test
         self.nodes = start_nodes(self.num_nodes, self.options.tmpdir,
-                                 extra_args=[['-debug', '-whitelist=127.0.0.1', '-blockversion=2']],
+                                 extra_args=[['-whitelist=127.0.0.1', '-blockversion=2']],
                                  binary=[self.options.testbinary])
 
     def run_test(self):

qa/rpc-tests/fundrawtransaction.py

@@ -34,8 +34,6 @@ def setup_network(self, split=False):
         self.sync_all()
 
     def run_test(self):
-        print("Mining blocks...")
-
         min_relay_tx_fee = self.nodes[0].getnetworkinfo()['relayfee']
         # This test is not meant to test fee estimation and we'd like
         # to be sure all txs are sent at a consistent desired feerate

qa/rpc-tests/getblocktemplate_longpoll.py

@@ -29,7 +29,7 @@ def __init__(self):
         self.setup_clean_chain = False
 
     def run_test(self):
-        print("Warning: this test will take about 70 seconds in the best case. Be patient.")
+        self.log.info("Warning: this test will take about 70 seconds in the best case. Be patient.")
         wait_to_sync(self.nodes[0])
         self.nodes[0].generate(10)
         templat = self.nodes[0].getblocktemplate()

qa/rpc-tests/import-rescan.py

@@ -7,11 +7,11 @@
 Test rescan behavior of importaddress, importpubkey, importprivkey, and
 importmulti RPCs with different types of keys and rescan options.
 
-In the first part of the test, node 1 creates an address for each type of
-import RPC call and node 0 sends BTC to it. Then other nodes import the
-addresses, and the test makes listtransactions and getbalance calls to confirm
-that the importing node either did or did not execute rescans picking up the
-send transactions.
+In the first part of the test, node 0 creates an address for each type of
+import RPC call and sends BTC to it. Then other nodes import the addresses,
+and the test makes listtransactions and getbalance calls to confirm that the
+importing node either did or did not execute rescans picking up the send
+transactions.
 
 In the second part of the test, node 0 sends more BTC to each address, and the
 test makes more listtransactions and getbalance calls to confirm that the
@@ -117,7 +117,7 @@ def __init__(self):
         self.num_nodes = 2 + len(IMPORT_NODES)
 
     def setup_network(self):
-        extra_args = [["-debug=1"] for _ in range(self.num_nodes)]
+        extra_args = [[] for _ in range(self.num_nodes)]
         for i, import_node in enumerate(IMPORT_NODES, 2):
             if import_node.prune:
                 # txindex is enabled by default in Dash and needs to be disabled for import-rescan.py

qa/rpc-tests/importmulti.py

@@ -17,7 +17,7 @@ def setup_network(self, split=False):
         self.is_network_split=False
 
     def run_test (self):
-        print ("Mining blocks...")
+        self.log.info("Mining blocks...")
         self.nodes[0].generate(1)
         self.nodes[1].generate(1)
         timestamp = self.nodes[1].getblock(self.nodes[1].getbestblockhash())['mediantime']
@@ -48,7 +48,7 @@ def run_test (self):
         # RPC importmulti -----------------------------------------------
 
         # Bitcoin Address
-        print("Should import an address")
+        self.log.info("Should import an address")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
@@ -64,7 +64,7 @@ def run_test (self):
         watchonly_address = address['address']
         watchonly_timestamp = timestamp
 
-        print("Should not import an invalid address")
+        self.log.info("Should not import an invalid address")
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
                 "address": "not valid address",
@@ -76,7 +76,7 @@ def run_test (self):
         assert_equal(result[0]['error']['message'], 'Invalid address')
 
         # ScriptPubKey + internal
-        print("Should import a scriptPubKey with internal flag")
+        self.log.info("Should import a scriptPubKey with internal flag")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": address['scriptPubKey'],
@@ -90,7 +90,7 @@ def run_test (self):
         assert_equal(address_assert['timestamp'], timestamp)
 
         # ScriptPubKey + !internal
-        print("Should not import a scriptPubKey without internal flag")
+        self.log.info("Should not import a scriptPubKey without internal flag")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": address['scriptPubKey'],
@@ -106,7 +106,7 @@ def run_test (self):
 
 
         # Address + Public key + !Internal
-        print("Should import an address with public key")
+        self.log.info("Should import an address with public key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
@@ -123,7 +123,7 @@ def run_test (self):
 
 
         # ScriptPubKey + Public key + internal
-        print("Should import a scriptPubKey with internal and with public key")
+        self.log.info("Should import a scriptPubKey with internal and with public key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         request = [{
             "scriptPubKey": address['scriptPubKey'],
@@ -139,7 +139,7 @@ def run_test (self):
         assert_equal(address_assert['timestamp'], timestamp)
 
         # ScriptPubKey + Public key + !internal
-        print("Should not import a scriptPubKey without internal and with public key")
+        self.log.info("Should not import a scriptPubKey without internal and with public key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         request = [{
             "scriptPubKey": address['scriptPubKey'],
@@ -156,7 +156,7 @@ def run_test (self):
         assert_equal('timestamp' in address_assert, False)
 
         # Address + Private key + !watchonly
-        print("Should import an address with private key")
+        self.log.info("Should import an address with private key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
@@ -172,7 +172,7 @@ def run_test (self):
         assert_equal(address_assert['timestamp'], timestamp)
 
         # Address + Private key + watchonly
-        print("Should not import an address with private key and with watchonly")
+        self.log.info("Should not import an address with private key and with watchonly")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
@@ -191,7 +191,7 @@ def run_test (self):
         assert_equal('timestamp' in address_assert, False)
 
         # ScriptPubKey + Private key + internal
-        print("Should import a scriptPubKey with internal and with private key")
+        self.log.info("Should import a scriptPubKey with internal and with private key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": address['scriptPubKey'],
@@ -206,7 +206,7 @@ def run_test (self):
         assert_equal(address_assert['timestamp'], timestamp)
 
         # ScriptPubKey + Private key + !internal
-        print("Should not import a scriptPubKey without internal and with private key")
+        self.log.info("Should not import a scriptPubKey without internal and with private key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
             "scriptPubKey": address['scriptPubKey'],
@@ -233,7 +233,7 @@ def run_test (self):
         timestamp = self.nodes[1].getblock(self.nodes[1].getbestblockhash())['mediantime']
         transaction = self.nodes[1].gettransaction(transactionid)
 
-        print("Should import a p2sh")
+        self.log.info("Should import a p2sh")
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
                 "address": multi_sig_script['address']
@@ -261,7 +261,7 @@ def run_test (self):
         timestamp = self.nodes[1].getblock(self.nodes[1].getbestblockhash())['mediantime']
         transaction = self.nodes[1].gettransaction(transactionid)
 
-        print("Should import a p2sh with respective redeem script")
+        self.log.info("Should import a p2sh with respective redeem script")
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
                 "address": multi_sig_script['address']
@@ -289,7 +289,7 @@ def run_test (self):
         timestamp = self.nodes[1].getblock(self.nodes[1].getbestblockhash())['mediantime']
         transaction = self.nodes[1].gettransaction(transactionid)
 
-        print("Should import a p2sh with respective redeem script and private keys")
+        self.log.info("Should import a p2sh with respective redeem script and private keys")
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
                 "address": multi_sig_script['address']
@@ -316,7 +316,7 @@ def run_test (self):
         self.nodes[1].generate(1)
         transaction = self.nodes[1].gettransaction(transactionid)
 
-        print("Should import a p2sh with respective redeem script and private keys")
+        self.log.info("Should import a p2sh with respective redeem script and private keys")
         result = self.nodes[1].importmulti([{
             "scriptPubKey": {
                 "address": multi_sig_script['address']
@@ -332,7 +332,7 @@ def run_test (self):
 
 
         # Address + Public key + !Internal + Wrong pubkey
-        print("Should not import an address with a wrong public key")
+        self.log.info("Should not import an address with a wrong public key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         address2 = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
@@ -352,7 +352,7 @@ def run_test (self):
 
 
         # ScriptPubKey + Public key + internal + Wrong pubkey
-        print("Should not import a scriptPubKey with internal and with a wrong public key")
+        self.log.info("Should not import a scriptPubKey with internal and with a wrong public key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         address2 = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         request = [{
@@ -372,7 +372,7 @@ def run_test (self):
 
 
         # Address + Private key + !watchonly + Wrong private key
-        print("Should not import an address with a wrong private key")
+        self.log.info("Should not import an address with a wrong private key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         address2 = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
@@ -392,7 +392,7 @@ def run_test (self):
 
 
         # ScriptPubKey + Private key + internal + Wrong private key
-        print("Should not import a scriptPubKey with internal and with a wrong private key")
+        self.log.info("Should not import a scriptPubKey with internal and with a wrong private key")
         address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         address2 = self.nodes[0].validateaddress(self.nodes[0].getnewaddress())
         result = self.nodes[1].importmulti([{
@@ -418,7 +418,7 @@ def run_test (self):
         assert_equal(address_assert['timestamp'], watchonly_timestamp);
 
         # Bad or missing timestamps
-        print("Should throw on invalid or missing timestamp values")
+        self.log.info("Should throw on invalid or missing timestamp values")
         assert_raises_message(JSONRPCException, 'Missing required timestamp field for key',
             self.nodes[1].importmulti, [{
                 "scriptPubKey": address['scriptPubKey'],