diff --git a/qa/rpc-tests/abandonconflict.py b/qa/rpc-tests/abandonconflict.py --- a/qa/rpc-tests/abandonconflict.py +++ b/qa/rpc-tests/abandonconflict.py @@ -19,12 +19,10 @@ def setup_network(self): self.nodes = [] self.nodes.append( - start_node(0, self.options.tmpdir, ["-debug", - "-logtimemicros", - "-minrelaytxfee=0.00001"])) + start_node(0, self.options.tmpdir, + ["-logtimemicros", "-minrelaytxfee=0.00001"])) self.nodes.append( - start_node(1, self.options.tmpdir, ["-debug", - "-logtimemicros"])) + start_node(1, self.options.tmpdir, ["-logtimemicros"])) connect_nodes(self.nodes[0], 1) def run_test(self): @@ -93,7 +91,7 @@ # 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", + "-logtimemicros", "-minrelaytxfee=0.0001"]) # Verify txs no longer in mempool @@ -124,7 +122,7 @@ # from wallet on startup once abandoned stop_node(self.nodes[0], 0) self.nodes[0] = start_node(0, self.options.tmpdir, [ - "-debug", "-logtimemicros", + "-logtimemicros", "-minrelaytxfee=0.00001"]) assert_equal(len(self.nodes[0].getrawmempool()), 0) assert_equal(self.nodes[0].getbalance(), balance) @@ -147,7 +145,7 @@ # Remove using high relay fee again stop_node(self.nodes[0], 0) self.nodes[0] = start_node(0, self.options.tmpdir, [ - "-debug", "-logtimemicros", + "-logtimemicros", "-minrelaytxfee=0.0001"]) assert_equal(len(self.nodes[0].getrawmempool()), 0) newbalance = self.nodes[0].getbalance() @@ -180,11 +178,11 @@ self.nodes[0].invalidateblock(self.nodes[0].getbestblockhash()) newbalance = self.nodes[0].getbalance() # assert_equal(newbalance, balance - Decimal("10")) - print( + self.log.info( "If balance has not declined after invalidateblock then out of mempool wallet tx which is no longer") - print( + self.log.info( "conflicted has not resumed causing its inputs to be seen as spent. See Issue #7315") - print(str(balance) + " -> " + str(newbalance) + " ?") + self.log.info(str(balance) + " -> " + str(newbalance) + " ?") if __name__ == '__main__': AbandonConflictTest().main() diff --git a/qa/rpc-tests/abc-cmdline.py b/qa/rpc-tests/abc-cmdline.py --- a/qa/rpc-tests/abc-cmdline.py +++ b/qa/rpc-tests/abc-cmdline.py @@ -45,10 +45,10 @@ assert(pattern.match(subversion)) def excessiveblocksize_test(self): - print("Testing -excessiveblocksize") + self.log.info("Testing -excessiveblocksize") - print(" Set to twice the default, i.e. %d bytes" % - (2 * LEGACY_MAX_BLOCK_SIZE)) + self.log.info(" Set to twice the default, i.e. %d bytes" % + (2 * LEGACY_MAX_BLOCK_SIZE)) stop_node(self.nodes[0], 0) self.extra_args = [["-excessiveblocksize=%d" % (2 * LEGACY_MAX_BLOCK_SIZE)]] @@ -58,8 +58,8 @@ # Check for EB correctness in the subver string self.check_subversion("/Bitcoin ABC:.*\(EB2\.0\)/") - print(" Attempt to set below legacy limit of 1MB - try %d bytes" % - LEGACY_MAX_BLOCK_SIZE) + self.log.info(" Attempt to set below legacy limit of 1MB - try %d bytes" % + LEGACY_MAX_BLOCK_SIZE) outputchecker = OutputChecker() stop_node(self.nodes[0], 0) try: @@ -77,7 +77,7 @@ raise AssertionError("Must not accept excessiveblocksize" " value < %d bytes" % LEGACY_MAX_BLOCK_SIZE) - print(" Attempt to set below blockmaxsize (mining limit)") + self.log.info(" Attempt to set below blockmaxsize (mining limit)") outputchecker = OutputChecker() try: self.extra_args = [['-blockmaxsize=1500000', diff --git a/qa/rpc-tests/abc-p2p-fullblocktest.py b/qa/rpc-tests/abc-p2p-fullblocktest.py --- a/qa/rpc-tests/abc-p2p-fullblocktest.py +++ b/qa/rpc-tests/abc-p2p-fullblocktest.py @@ -78,8 +78,7 @@ self.blocks = {} def setup_network(self): - self.extra_args = [['-debug', - '-norelaypriority', + self.extra_args = [['-norelaypriority', '-whitelist=127.0.0.1', '-limitancestorcount=9999', '-limitancestorsize=9999', diff --git a/qa/rpc-tests/abc-rpc.py b/qa/rpc-tests/abc-rpc.py --- a/qa/rpc-tests/abc-rpc.py +++ b/qa/rpc-tests/abc-rpc.py @@ -25,8 +25,7 @@ self.setup_clean_chain = True def setup_network(self): - self.extra_args = [['-debug', - '-norelaypriority', + self.extra_args = [['-norelaypriority', '-whitelist=127.0.0.1', '-par=1']] self.nodes = start_nodes(self.num_nodes, self.options.tmpdir, diff --git a/qa/rpc-tests/assumevalid.py b/qa/rpc-tests/assumevalid.py --- a/qa/rpc-tests/assumevalid.py +++ b/qa/rpc-tests/assumevalid.py @@ -78,7 +78,7 @@ # 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): @@ -160,7 +160,7 @@ # 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)) @@ -168,7 +168,7 @@ 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)) diff --git a/qa/rpc-tests/bip65-cltv-p2p.py b/qa/rpc-tests/bip65-cltv-p2p.py --- a/qa/rpc-tests/bip65-cltv-p2p.py +++ b/qa/rpc-tests/bip65-cltv-p2p.py @@ -45,8 +45,7 @@ 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', + extra_args=[['-whitelist=127.0.0.1', '-blockversion=3']], binary=[self.options.testbinary]) diff --git a/qa/rpc-tests/bip68-112-113-p2p.py b/qa/rpc-tests/bip68-112-113-p2p.py --- a/qa/rpc-tests/bip68-112-113-p2p.py +++ b/qa/rpc-tests/bip68-112-113-p2p.py @@ -104,8 +104,7 @@ 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', + extra_args=[['-whitelist=127.0.0.1', '-blockversion=4']], binary=[self.options.testbinary]) diff --git a/qa/rpc-tests/bip68-sequence.py b/qa/rpc-tests/bip68-sequence.py --- a/qa/rpc-tests/bip68-sequence.py +++ b/qa/rpc-tests/bip68-sequence.py @@ -32,11 +32,9 @@ def setup_network(self): self.nodes = [] self.nodes.append( - start_node(0, self.options.tmpdir, ["-debug", - "-blockprioritysize=0"])) + start_node(0, self.options.tmpdir, ["-blockprioritysize=0"])) self.nodes.append( - start_node(1, self.options.tmpdir, ["-debug", - "-blockprioritysize=0", + start_node(1, self.options.tmpdir, ["-blockprioritysize=0", "-acceptnonstdtxn=0"])) self.is_network_split = False self.relayfee = self.nodes[0].getnetworkinfo()["relayfee"] @@ -46,28 +44,29 @@ # 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("Verifying nVersion=2 transactions aren't standard") + self.log.info("Verifying nVersion=2 transactions aren't standard") self.test_version2_relay(before_activation=True) - print("Activating BIP68 (and 112/113)") + self.log.info("Activating BIP68 (and 112/113)") self.activateCSV() - print("Verifying nVersion=2 transactions are now standard") + self.log.info("Verifying nVersion=2 transactions are now standard") self.test_version2_relay(before_activation=False) - 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. diff --git a/qa/rpc-tests/bip9-softforks.py b/qa/rpc-tests/bip9-softforks.py --- a/qa/rpc-tests/bip9-softforks.py +++ b/qa/rpc-tests/bip9-softforks.py @@ -37,8 +37,7 @@ 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): diff --git a/qa/rpc-tests/bipdersig-p2p.py b/qa/rpc-tests/bipdersig-p2p.py --- a/qa/rpc-tests/bipdersig-p2p.py +++ b/qa/rpc-tests/bipdersig-p2p.py @@ -54,8 +54,7 @@ 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', + extra_args=[['-whitelist=127.0.0.1', '-blockversion=2']], binary=[self.options.testbinary]) diff --git a/qa/rpc-tests/fundrawtransaction.py b/qa/rpc-tests/fundrawtransaction.py --- a/qa/rpc-tests/fundrawtransaction.py +++ b/qa/rpc-tests/fundrawtransaction.py @@ -34,8 +34,6 @@ 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 diff --git a/qa/rpc-tests/getblocktemplate_longpoll.py b/qa/rpc-tests/getblocktemplate_longpoll.py --- a/qa/rpc-tests/getblocktemplate_longpoll.py +++ b/qa/rpc-tests/getblocktemplate_longpoll.py @@ -36,7 +36,7 @@ self.setup_clean_chain = False def run_test(self): - print( + self.log.info( "Warning: this test will take about 70 seconds in the best case. Be patient.") self.nodes[0].generate(10) templat = self.nodes[0].getblocktemplate() diff --git a/qa/rpc-tests/import-rescan.py b/qa/rpc-tests/import-rescan.py --- a/qa/rpc-tests/import-rescan.py +++ b/qa/rpc-tests/import-rescan.py @@ -6,7 +6,7 @@ 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 +In the first part of the test, node 0 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 @@ -126,7 +126,7 @@ 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: extra_args[i] += ["-prune=1"] diff --git a/qa/rpc-tests/importmulti.py b/qa/rpc-tests/importmulti.py --- a/qa/rpc-tests/importmulti.py +++ b/qa/rpc-tests/importmulti.py @@ -19,7 +19,7 @@ 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( @@ -52,7 +52,7 @@ # 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": { @@ -68,7 +68,7 @@ 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", @@ -80,7 +80,7 @@ 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'], @@ -94,7 +94,7 @@ 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'], @@ -110,7 +110,7 @@ assert_equal('timestamp' in address_assert, False) # 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": { @@ -126,7 +126,8 @@ assert_equal(address_assert['timestamp'], timestamp) # 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'], @@ -142,7 +143,7 @@ assert_equal(address_assert['timestamp'], timestamp) # ScriptPubKey + Public key + !internal - print( + self.log.info( "Should not import a scriptPubKey without internal and with public key") address = self.nodes[0].validateaddress(self.nodes[0].getnewaddress()) request = [{ @@ -161,7 +162,7 @@ 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": { @@ -177,7 +178,7 @@ assert_equal(address_assert['timestamp'], timestamp) # Address + Private key + watchonly - print( + 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([{ @@ -198,7 +199,7 @@ assert_equal('timestamp' in address_assert, False) # ScriptPubKey + Private key + internal - print( + 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([{ @@ -214,7 +215,7 @@ assert_equal(address_assert['timestamp'], timestamp) # ScriptPubKey + Private key + !internal - print( + 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([{ @@ -248,7 +249,7 @@ 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'] @@ -283,7 +284,7 @@ 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'] @@ -318,7 +319,7 @@ self.nodes[1].getbestblockhash())['mediantime'] transaction = self.nodes[1].gettransaction(transactionid) - print( + self.log.info( "Should import a p2sh with respective redeem script and private keys") result = self.nodes[1].importmulti([{ "scriptPubKey": { @@ -353,7 +354,7 @@ self.nodes[1].generate(1) transaction = self.nodes[1].gettransaction(transactionid) - print( + self.log.info( "Should import a p2sh with respective redeem script and private keys") result = self.nodes[1].importmulti([{ "scriptPubKey": { @@ -370,7 +371,7 @@ 'Incompatibility found between watchonly and keys') # 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([{ @@ -389,7 +390,7 @@ assert_equal('timestamp' in address_assert, False) # ScriptPubKey + Public key + internal + Wrong pubkey - print( + 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()) @@ -409,7 +410,7 @@ assert_equal('timestamp' in address_assert, False) # 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([{ @@ -428,7 +429,7 @@ assert_equal('timestamp' in address_assert, False) # ScriptPubKey + Private key + internal + Wrong private key - print( + 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()) @@ -456,7 +457,7 @@ 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, [{ diff --git a/qa/rpc-tests/importprunedfunds.py b/qa/rpc-tests/importprunedfunds.py --- a/qa/rpc-tests/importprunedfunds.py +++ b/qa/rpc-tests/importprunedfunds.py @@ -21,7 +21,7 @@ self.sync_all() def run_test(self): - print("Mining blocks...") + self.log.info("Mining blocks...") self.nodes[0].generate(101) self.sync_all() diff --git a/qa/rpc-tests/invalidateblock.py b/qa/rpc-tests/invalidateblock.py --- a/qa/rpc-tests/invalidateblock.py +++ b/qa/rpc-tests/invalidateblock.py @@ -21,29 +21,29 @@ def setup_network(self): self.nodes = [] self.is_network_split = False - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug"])) - self.nodes.append(start_node(1, self.options.tmpdir, ["-debug"])) - self.nodes.append(start_node(2, self.options.tmpdir, ["-debug"])) + self.nodes.append(start_node(0, self.options.tmpdir)) + self.nodes.append(start_node(1, self.options.tmpdir)) + self.nodes.append(start_node(2, self.options.tmpdir)) def run_test(self): - print( + self.log.info( "Make sure we repopulate setBlockIndexCandidates after InvalidateBlock:") - print("Mine 4 blocks on Node 0") + self.log.info("Mine 4 blocks on Node 0") self.nodes[0].generate(4) assert(self.nodes[0].getblockcount() == 4) besthash = self.nodes[0].getbestblockhash() - print("Mine competing 6 blocks on Node 1") + self.log.info("Mine competing 6 blocks on Node 1") self.nodes[1].generate(6) assert(self.nodes[1].getblockcount() == 6) - print("Connect nodes to force a reorg") + self.log.info("Connect nodes to force a reorg") connect_nodes_bi(self.nodes, 0, 1) sync_blocks(self.nodes[0:2]) assert(self.nodes[0].getblockcount() == 6) badhash = self.nodes[1].getblockhash(2) - print( + self.log.info( "Invalidate block 2 on node 0 and verify we reorg to node 0's original chain") self.nodes[0].invalidateblock(badhash) newheight = self.nodes[0].getblockcount() @@ -52,25 +52,23 @@ raise AssertionError( "Wrong tip for node0, hash %s, height %d" % (newhash, newheight)) - print("\nMake sure we won't reorg to a lower work chain:") + self.log.info("\nMake sure we won't reorg to a lower work chain:") connect_nodes_bi(self.nodes, 1, 2) - print("Sync node 2 to node 1 so both have 6 blocks") + self.log.info("Sync node 2 to node 1 so both have 6 blocks") sync_blocks(self.nodes[1:3]) assert(self.nodes[2].getblockcount() == 6) - print("Invalidate block 5 on node 1 so its tip is now at 4") + self.log.info("Invalidate block 5 on node 1 so its tip is now at 4") self.nodes[1].invalidateblock(self.nodes[1].getblockhash(5)) assert(self.nodes[1].getblockcount() == 4) - print("Invalidate block 3 on node 2, so its tip is now 2") + self.log.info("Invalidate block 3 on node 2, so its tip is now 2") self.nodes[2].invalidateblock(self.nodes[2].getblockhash(3)) assert(self.nodes[2].getblockcount() == 2) - print("..and then mine a block") + self.log.info("..and then mine a block") self.nodes[2].generate(1) - print("Verify all nodes are at the right height") + self.log.info("Verify all nodes are at the right height") time.sleep(5) - for i in range(3): - print(i, self.nodes[i].getblockcount()) - assert(self.nodes[2].getblockcount() == 3) - assert(self.nodes[0].getblockcount() == 4) + assert_equal(self.nodes[2].getblockcount(), 3) + assert_equal(self.nodes[0].getblockcount(), 4) node1height = self.nodes[1].getblockcount() if node1height < 4: raise AssertionError( diff --git a/qa/rpc-tests/listsinceblock.py b/qa/rpc-tests/listsinceblock.py --- a/qa/rpc-tests/listsinceblock.py +++ b/qa/rpc-tests/listsinceblock.py @@ -62,7 +62,7 @@ # generate on both sides lastblockhash = self.nodes[1].generate(6)[5] self.nodes[2].generate(7) - print('lastblockhash=%s' % (lastblockhash)) + self.log.info('lastblockhash=%s' % (lastblockhash)) self.sync_all() diff --git a/qa/rpc-tests/maxblocksinflight.py b/qa/rpc-tests/maxblocksinflight.py --- a/qa/rpc-tests/maxblocksinflight.py +++ b/qa/rpc-tests/maxblocksinflight.py @@ -6,7 +6,6 @@ from test_framework.mininode import * from test_framework.test_framework import BitcoinTestFramework from test_framework.util import * -import logging ''' In this test we connect to one node over p2p, send it numerous inv's, and @@ -34,7 +33,6 @@ def __init__(self): NodeConnCB.__init__(self) - self.log = logging.getLogger("BlockRelayTest") def add_new_connection(self, connection): self.connection = connection @@ -68,8 +66,8 @@ if total_requests > MAX_REQUESTS: raise AssertionError( "Error, too many blocks (%d) requested" % total_requests) - print("Round %d: success (total requests: %d)" % - (count, total_requests)) + self.log.info("Round %d: success (total requests: %d)" % + (count, total_requests)) self.disconnectOkay = True self.connection.disconnect_node() @@ -89,12 +87,13 @@ 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): test = TestManager() + # pass log handler through to the test manager object + test.log = self.log test.add_new_connection( NodeConn('127.0.0.1', p2p_port(0), self.nodes[0], test)) NetworkThread().start() # Start up network handling in another thread diff --git a/qa/rpc-tests/maxuploadtarget.py b/qa/rpc-tests/maxuploadtarget.py --- a/qa/rpc-tests/maxuploadtarget.py +++ b/qa/rpc-tests/maxuploadtarget.py @@ -100,7 +100,7 @@ self.nodes = [] self.nodes.append( start_node( - 0, self.options.tmpdir, ["-debug", "-maxuploadtarget=200"])) + 0, self.options.tmpdir, ["-maxuploadtarget=200"])) def run_test(self): # Before we connect anything, we first set the time on the node @@ -173,7 +173,8 @@ test_nodes[0].send_message(getdata_request) test_nodes[0].wait_for_disconnect() assert_equal(len(self.nodes[0].getpeerinfo()), 2) - print("Peer 0 disconnected after downloading old block too many times") + self.log.info( + "Peer 0 disconnected after downloading old block too many times") # Requesting the current block on test_nodes[1] should succeed indefinitely, # even when over the max upload target. @@ -184,7 +185,7 @@ test_nodes[1].sync_with_ping() assert_equal(test_nodes[1].block_receive_map[big_new_block], i + 1) - print("Peer 1 able to repeatedly download new block") + self.log.info("Peer 1 able to repeatedly download new block") # But if test_nodes[1] tries for an old block, it gets disconnected # too. @@ -193,9 +194,9 @@ test_nodes[1].wait_for_disconnect() assert_equal(len(self.nodes[0].getpeerinfo()), 1) - print("Peer 1 disconnected after trying to download old block") + self.log.info("Peer 1 disconnected after trying to download old block") - print("Advancing system time on node to clear counters...") + self.log.info("Advancing system time on node to clear counters...") # If we advance the time by 24 hours, then the counters should reset, # and test_nodes[2] should be able to retrieve the old block. @@ -205,15 +206,15 @@ test_nodes[2].sync_with_ping() assert_equal(test_nodes[2].block_receive_map[big_old_block], 1) - print("Peer 2 able to download old block") + self.log.info("Peer 2 able to download old block") [c.disconnect_node() for c in connections] # stop and start node 0 with 1MB maxuploadtarget, whitelist 127.0.0.1 - print("Restarting nodes with -whitelist=127.0.0.1") + self.log.info("Restarting nodes with -whitelist=127.0.0.1") stop_node(self.nodes[0], 0) self.nodes[0] = start_node(0, self.options.tmpdir, [ - "-debug", "-whitelist=127.0.0.1", "-maxuploadtarget=1"]) + "-whitelist=127.0.0.1", "-maxuploadtarget=1"]) # recreate/reconnect 3 test nodes test_nodes = [] @@ -242,7 +243,7 @@ # node is still connected because of the whitelist assert_equal(len(self.nodes[0].getpeerinfo()), 3) - print( + self.log.info( "Peer 1 still connected after trying to download old block (whitelisted)") [c.disconnect_node() for c in connections] diff --git a/qa/rpc-tests/mempool_limit.py b/qa/rpc-tests/mempool_limit.py --- a/qa/rpc-tests/mempool_limit.py +++ b/qa/rpc-tests/mempool_limit.py @@ -14,9 +14,8 @@ def setup_network(self): self.nodes = [] self.nodes.append( - start_node(0, self.options.tmpdir, ["-maxmempool=5", - "-spendzeroconfchange=0", - "-debug"])) + start_node(0, self.options.tmpdir, + ["-maxmempool=5", "-spendzeroconfchange=0"])) self.is_network_split = False self.sync_all() self.relayfee = self.nodes[0].getnetworkinfo()['relayfee'] diff --git a/qa/rpc-tests/mempool_packages.py b/qa/rpc-tests/mempool_packages.py --- a/qa/rpc-tests/mempool_packages.py +++ b/qa/rpc-tests/mempool_packages.py @@ -23,11 +23,10 @@ def setup_network(self): self.nodes = [] self.nodes.append( - start_node(0, self.options.tmpdir, ["-maxorphantx=1000", "-debug"])) + start_node(0, self.options.tmpdir, ["-maxorphantx=1000"])) self.nodes.append( start_node(1, self.options.tmpdir, ["-maxorphantx=1000", - "-limitancestorcount=5", - "-debug"])) + "-limitancestorcount=5"])) connect_nodes(self.nodes[0], 1) self.is_network_split = False self.sync_all() @@ -141,7 +140,7 @@ try: self.chain_transaction(self.nodes[0], txid, vout, value, fee, 1) except JSONRPCException as e: - print("too-long-ancestor-chain successfully rejected") + self.log.info("too-long-ancestor-chain successfully rejected") # Check that prioritising a tx before it's added to the mempool works # First clear the mempool by mining a block. @@ -199,9 +198,9 @@ assert_equal(mempool[parent_transaction][ 'descendantcount'], MAX_DESCENDANTS) except JSONRPCException as e: - print(e.error['message']) + self.log.info(e.error['message']) assert_equal(i, MAX_DESCENDANTS - 1) - print( + self.log.info( "tx that would create too large descendant package successfully rejected") # TODO: check that node1's mempool is as expected diff --git a/qa/rpc-tests/mempool_reorg.py b/qa/rpc-tests/mempool_reorg.py --- a/qa/rpc-tests/mempool_reorg.py +++ b/qa/rpc-tests/mempool_reorg.py @@ -24,7 +24,7 @@ alert_filename = None # Set by setup_network def setup_network(self): - args = ["-checkmempool", "-debug=mempool"] + args = ["-checkmempool"] self.nodes = [] self.nodes.append(start_node(0, self.options.tmpdir, args)) self.nodes.append(start_node(1, self.options.tmpdir, args)) diff --git a/qa/rpc-tests/mempool_resurrect_test.py b/qa/rpc-tests/mempool_resurrect_test.py --- a/qa/rpc-tests/mempool_resurrect_test.py +++ b/qa/rpc-tests/mempool_resurrect_test.py @@ -23,7 +23,7 @@ def setup_network(self): # Just need one node for this test - args = ["-checkmempool", "-debug=mempool"] + args = ["-checkmempool"] self.nodes = [] self.nodes.append(start_node(0, self.options.tmpdir, args)) self.is_network_split = False diff --git a/qa/rpc-tests/mempool_spendcoinbase.py b/qa/rpc-tests/mempool_spendcoinbase.py --- a/qa/rpc-tests/mempool_spendcoinbase.py +++ b/qa/rpc-tests/mempool_spendcoinbase.py @@ -28,7 +28,7 @@ def setup_network(self): # Just need one node for this test - args = ["-checkmempool", "-debug=mempool"] + args = ["-checkmempool"] self.nodes = [] self.nodes.append(start_node(0, self.options.tmpdir, args)) self.is_network_split = False diff --git a/qa/rpc-tests/merkle_blocks.py b/qa/rpc-tests/merkle_blocks.py --- a/qa/rpc-tests/merkle_blocks.py +++ b/qa/rpc-tests/merkle_blocks.py @@ -21,13 +21,12 @@ def setup_network(self): self.nodes = [] # Nodes 0/1 are "wallet" nodes - extra_args = ["-debug"] - self.nodes.append(start_node(0, self.options.tmpdir, extra_args)) - self.nodes.append(start_node(1, self.options.tmpdir, extra_args)) + self.nodes.append(start_node(0, self.options.tmpdir)) + self.nodes.append(start_node(1, self.options.tmpdir)) # Nodes 2/3 are used for testing - self.nodes.append(start_node(2, self.options.tmpdir, extra_args)) + self.nodes.append(start_node(2, self.options.tmpdir)) self.nodes.append( - start_node(3, self.options.tmpdir, ["-debug", "-txindex"])) + start_node(3, self.options.tmpdir, ["-txindex"])) connect_nodes(self.nodes[0], 1) connect_nodes(self.nodes[0], 2) connect_nodes(self.nodes[0], 3) @@ -36,7 +35,7 @@ self.sync_all() def run_test(self): - print("Mining blocks...") + self.log.info("Mining blocks...") self.nodes[0].generate(105) self.sync_all() diff --git a/qa/rpc-tests/nulldummy.py b/qa/rpc-tests/nulldummy.py --- a/qa/rpc-tests/nulldummy.py +++ b/qa/rpc-tests/nulldummy.py @@ -48,8 +48,7 @@ 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', + extra_args=[['-whitelist=127.0.0.1', '-walletprematurewitness']]) def run_test(self): @@ -67,7 +66,7 @@ self.lastblockheight = 429 self.lastblocktime = int(time.time()) + 429 - print ( + self.log.info( "Test 1: NULLDUMMY compliant base transactions should be accepted to mempool and mined before activation [430]") test1txs = [self.create_transaction( self.nodes[0], coinbase_txid[0], self.ms_address, 49)] @@ -77,14 +76,14 @@ txid2 = self.tx_submit(self.nodes[0], test1txs[1]) self.block_submit(self.nodes[0], test1txs, False, True) - print ( + self.log.info( "Test 2: Non-NULLDUMMY base multisig transaction should not be accepted to mempool before activation") test2tx = self.create_transaction( self.nodes[0], txid2, self.ms_address, 48) trueDummy(test2tx) txid4 = self.tx_submit(self.nodes[0], test2tx, NULLDUMMY_ERROR) - print ( + self.log.info( "Test 3: Non-NULLDUMMY base transactions should be accepted in a block before activation [431]") self.block_submit(self.nodes[0], [test2tx], False, True) diff --git a/qa/rpc-tests/p2p-acceptblock.py b/qa/rpc-tests/p2p-acceptblock.py --- a/qa/rpc-tests/p2p-acceptblock.py +++ b/qa/rpc-tests/p2p-acceptblock.py @@ -124,10 +124,10 @@ # from peers which are not whitelisted, while Node1 will be used for # the whitelisted case. self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug"], + self.nodes.append(start_node(0, self.options.tmpdir, binary=self.options.testbinary)) self.nodes.append(start_node(1, self.options.tmpdir, - ["-debug", "-whitelist=127.0.0.1"], + ["-whitelist=127.0.0.1"], binary=self.options.testbinary)) def run_test(self): @@ -168,7 +168,7 @@ [x.sync_with_ping() for x in [test_node, white_node]] assert_equal(self.nodes[0].getblockcount(), 2) assert_equal(self.nodes[1].getblockcount(), 2) - print("First height 2 block accepted by both nodes") + self.log.info("First height 2 block accepted by both nodes") # 3. Send another block that builds on the original tip. blocks_h2f = [] # Blocks at height 2 that fork off the main chain @@ -188,7 +188,8 @@ if x['hash'] == blocks_h2f[1].hash: assert_equal(x['status'], "valid-headers") - print("Second height 2 block accepted only from whitelisted peer") + self.log.info( + "Second height 2 block accepted only from whitelisted peer") # 4. Now send another block that builds on the forking chain. blocks_h3 = [] @@ -208,11 +209,13 @@ # But this block should be accepted by node0 since it has more work. self.nodes[0].getblock(blocks_h3[0].hash) - print("Unrequested more-work block accepted from non-whitelisted peer") + self.log.info( + "Unrequested more-work block accepted from non-whitelisted peer") # Node1 should have accepted and reorged. assert_equal(self.nodes[1].getblockcount(), 3) - print("Successfully reorged to length 3 chain from whitelisted peer") + self.log.info( + "Successfully reorged to length 3 chain from whitelisted peer") # 4b. Now mine 288 more blocks and deliver; all should be processed but # the last (height-too-high) on node0. Node1 should process the tip if @@ -245,7 +248,7 @@ white_node.send_message(msg_block(tips[1])) # Now deliver the tip white_node.sync_with_ping() self.nodes[1].getblock(tips[1].hash) - print( + self.log.info( "Unrequested block far ahead of tip accepted from whitelisted peer") # 5. Test handling of unrequested block on the node that didn't process @@ -260,7 +263,7 @@ # a getdata request for this block. test_node.sync_with_ping() assert_equal(self.nodes[0].getblockcount(), 2) - print( + self.log.info( "Unrequested block that would complete more-work chain was ignored") # 6. Try to get node to request the missing block. @@ -277,14 +280,15 @@ # Check that the getdata includes the right block assert_equal(getdata.inv[0].hash, blocks_h2f[0].sha256) - print("Inv at tip triggered getdata for unprocessed block") + self.log.info("Inv at tip triggered getdata for unprocessed block") # 7. Send the missing block for the third time (now it is requested) test_node.send_message(msg_block(blocks_h2f[0])) test_node.sync_with_ping() assert_equal(self.nodes[0].getblockcount(), 290) - print("Successfully reorged to longer chain from non-whitelisted peer") + self.log.info( + "Successfully reorged to longer chain from non-whitelisted peer") [c.disconnect_node() for c in connections] diff --git a/qa/rpc-tests/p2p-compactblocks.py b/qa/rpc-tests/p2p-compactblocks.py --- a/qa/rpc-tests/p2p-compactblocks.py +++ b/qa/rpc-tests/p2p-compactblocks.py @@ -128,8 +128,7 @@ # Start up two version 1 CB nodes. self.nodes = start_nodes(self.num_nodes, self.options.tmpdir, - [["-debug", "-logtimemicros=1"], - ["-debug", "-logtimemicros", "-txindex"]]) + [[], ["-txindex"]]) connect_nodes(self.nodes[0], 1) def build_block_on_tip(self, node): @@ -878,43 +877,43 @@ # We will need UTXOs to construct transactions in later tests. self.make_utxos() - print("Running tests:") + self.log.info("Running tests:") - print("\tTesting SENDCMPCT p2p message... ") + self.log.info("\tTesting SENDCMPCT p2p message... ") self.test_sendcmpct(self.nodes[0], self.test_node, 1) sync_blocks(self.nodes) self.test_sendcmpct( self.nodes[1], self.ex_softfork_node, 1, old_node=self.old_node) sync_blocks(self.nodes) - print("\tTesting compactblock construction...") + self.log.info("\tTesting compactblock construction...") self.test_compactblock_construction(self.nodes[0], self.test_node) sync_blocks(self.nodes) self.test_compactblock_construction( self.nodes[1], self.ex_softfork_node) sync_blocks(self.nodes) - print("\tTesting compactblock requests... ") + self.log.info("\tTesting compactblock requests... ") self.test_compactblock_requests(self.nodes[0], self.test_node, 1) sync_blocks(self.nodes) self.test_compactblock_requests( self.nodes[1], self.ex_softfork_node, 2) sync_blocks(self.nodes) - print("\tTesting getblocktxn requests...") + self.log.info("\tTesting getblocktxn requests...") self.test_getblocktxn_requests(self.nodes[0], self.test_node, 1) sync_blocks(self.nodes) self.test_getblocktxn_requests(self.nodes[1], self.ex_softfork_node, 2) sync_blocks(self.nodes) - print("\tTesting getblocktxn handler...") + self.log.info("\tTesting getblocktxn handler...") self.test_getblocktxn_handler(self.nodes[0], self.test_node, 1) sync_blocks(self.nodes) self.test_getblocktxn_handler(self.nodes[1], self.ex_softfork_node, 2) self.test_getblocktxn_handler(self.nodes[1], self.old_node, 1) sync_blocks(self.nodes) - print( + self.log.info( "\tTesting compactblock requests/announcements not at chain tip...") self.test_compactblocks_not_at_tip(self.nodes[0], self.test_node) sync_blocks(self.nodes) @@ -923,7 +922,7 @@ self.test_compactblocks_not_at_tip(self.nodes[1], self.old_node) sync_blocks(self.nodes) - print("\tTesting handling of incorrect blocktxn responses...") + self.log.info("\tTesting handling of incorrect blocktxn responses...") self.test_incorrect_blocktxn_response(self.nodes[0], self.test_node, 1) sync_blocks(self.nodes) self.test_incorrect_blocktxn_response( @@ -931,7 +930,7 @@ sync_blocks(self.nodes) # End-to-end block relay tests - print("\tTesting end-to-end block relay...") + self.log.info("\tTesting end-to-end block relay...") self.request_cb_announcements(self.test_node, self.nodes[0]) self.request_cb_announcements(self.old_node, self.nodes[1]) self.request_cb_announcements( @@ -941,18 +940,19 @@ self.test_end_to_end_block_relay( self.nodes[1], [self.ex_softfork_node, self.test_node, self.old_node]) - print("\tTesting handling of invalid compact blocks...") + self.log.info("\tTesting handling of invalid compact blocks...") self.test_invalid_tx_in_compactblock(self.nodes[0], self.test_node) self.test_invalid_tx_in_compactblock( self.nodes[1], self.ex_softfork_node) self.test_invalid_tx_in_compactblock(self.nodes[1], self.old_node) - print("\tTesting reconstructing compact blocks from all peers...") + self.log.info( + "\tTesting reconstructing compact blocks from all peers...") self.test_compactblock_reconstruction_multiple_peers( self.nodes[1], self.ex_softfork_node, self.old_node) sync_blocks(self.nodes) - print("\tTesting invalid index in cmpctblock message...") + self.log.info("\tTesting invalid index in cmpctblock message...") self.test_invalid_cmpctblock_message() diff --git a/qa/rpc-tests/p2p-feefilter.py b/qa/rpc-tests/p2p-feefilter.py --- a/qa/rpc-tests/p2p-feefilter.py +++ b/qa/rpc-tests/p2p-feefilter.py @@ -63,7 +63,7 @@ # Node1 will be used to generate txs which should be relayed from Node0 # to our test node self.nodes = [] - extra_args = ["-debug", "-logtimemicros"] + extra_args = ["-logtimemicros"] self.nodes.append( start_node(0, self.options.tmpdir, extra_args)) self.nodes.append( diff --git a/qa/rpc-tests/p2p-leaktests.py b/qa/rpc-tests/p2p-leaktests.py --- a/qa/rpc-tests/p2p-leaktests.py +++ b/qa/rpc-tests/p2p-leaktests.py @@ -36,7 +36,7 @@ def bad_message(self, message): self.unexpected_msg = True - print("should not have received message: %s" % message.command) + self.log.info("should not have received message: %s" % message.command) def on_open(self, conn): self.connected = True @@ -142,7 +142,7 @@ self.num_nodes = 1 def setup_network(self): - extra_args = [['-debug', '-banscore=' + str(banscore)] + extra_args = [['-banscore=' + str(banscore)] for i in range(self.num_nodes)] self.nodes = start_nodes( self.num_nodes, self.options.tmpdir, extra_args) diff --git a/qa/rpc-tests/p2p-mempool.py b/qa/rpc-tests/p2p-mempool.py --- a/qa/rpc-tests/p2p-mempool.py +++ b/qa/rpc-tests/p2p-mempool.py @@ -84,7 +84,7 @@ # Start a node with maxuploadtarget of 200 MB (/24h) self.nodes = [] self.nodes.append( - start_node(0, self.options.tmpdir, ["-debug", "-peerbloomfilters=0"])) + start_node(0, self.options.tmpdir, ["-peerbloomfilters=0"])) def run_test(self): # connect a mininode diff --git a/qa/rpc-tests/p2p-timeouts.py b/qa/rpc-tests/p2p-timeouts.py --- a/qa/rpc-tests/p2p-timeouts.py +++ b/qa/rpc-tests/p2p-timeouts.py @@ -57,8 +57,7 @@ self.nodes = [] # Start up node0 to be a version 1, pre-segwit node. - self.nodes = start_nodes(self.num_nodes, self.options.tmpdir, - [["-debug", "-logtimemicros=1"]]) + self.nodes = start_nodes(self.num_nodes, self.options.tmpdir) def run_test(self): # Setup the p2p connections and start up the network thread. diff --git a/qa/rpc-tests/p2p-versionbits-warning.py b/qa/rpc-tests/p2p-versionbits-warning.py --- a/qa/rpc-tests/p2p-versionbits-warning.py +++ b/qa/rpc-tests/p2p-versionbits-warning.py @@ -80,7 +80,7 @@ with open(self.alert_filename, 'w', encoding='utf8') as _: pass self.extra_args = [ - ["-debug", "-logtimemicros=1", "-alertnotify=echo %s >> \"" + self.alert_filename + "\""]] + ["-alertnotify=echo %s >> \"" + self.alert_filename + "\""]] self.nodes = start_nodes( self.num_nodes, self.options.tmpdir, self.extra_args) diff --git a/qa/rpc-tests/preciousblock.py b/qa/rpc-tests/preciousblock.py --- a/qa/rpc-tests/preciousblock.py +++ b/qa/rpc-tests/preciousblock.py @@ -47,13 +47,13 @@ super().__init__() self.setup_clean_chain = True self.num_nodes = 3 - self.extra_args = [["-debug"]] * self.num_nodes def setup_network(self): self.nodes = self.setup_nodes() def run_test(self): - print("Ensure submitblock can in principle reorg to a competing chain") + self.log.info( + "Ensure submitblock can in principle reorg to a competing chain") self.nodes[0].generate(1) assert_equal(self.nodes[0].getblockcount(), 1) (hashY, hashZ) = self.nodes[1].generate(2) @@ -61,64 +61,65 @@ node_sync_via_rpc(self.nodes[0:3]) assert_equal(self.nodes[0].getbestblockhash(), hashZ) - print("Mine blocks A-B-C on Node 0") + self.log.info("Mine blocks A-B-C on Node 0") (hashA, hashB, hashC) = self.nodes[0].generate(3) assert_equal(self.nodes[0].getblockcount(), 5) - print("Mine competing blocks E-F-G on Node 1") + self.log.info("Mine competing blocks E-F-G on Node 1") (hashE, hashF, hashG) = self.nodes[1].generate(3) assert_equal(self.nodes[1].getblockcount(), 5) assert(hashC != hashG) - print("Connect nodes and check no reorg occurs") + self.log.info("Connect nodes and check no reorg occurs") # Submit competing blocks via RPC so any reorg should occur before we # proceed (no way to wait on inaction for p2p sync) node_sync_via_rpc(self.nodes[0:2]) connect_nodes_bi(self.nodes, 0, 1) assert_equal(self.nodes[0].getbestblockhash(), hashC) assert_equal(self.nodes[1].getbestblockhash(), hashG) - print("Make Node0 prefer block G") + self.log.info("Make Node0 prefer block G") self.nodes[0].preciousblock(hashG) assert_equal(self.nodes[0].getbestblockhash(), hashG) - print("Make Node0 prefer block C again") + self.log.info("Make Node0 prefer block C again") self.nodes[0].preciousblock(hashC) assert_equal(self.nodes[0].getbestblockhash(), hashC) - print("Make Node1 prefer block C") + self.log.info("Make Node1 prefer block C") self.nodes[1].preciousblock(hashC) sync_chain(self.nodes[0:2]) # wait because node 1 may not have downloaded hashC assert_equal(self.nodes[1].getbestblockhash(), hashC) - print("Make Node1 prefer block G again") + self.log.info("Make Node1 prefer block G again") self.nodes[1].preciousblock(hashG) assert_equal(self.nodes[1].getbestblockhash(), hashG) - print("Make Node0 prefer block G again") + self.log.info("Make Node0 prefer block G again") self.nodes[0].preciousblock(hashG) assert_equal(self.nodes[0].getbestblockhash(), hashG) - print("Make Node1 prefer block C again") + self.log.info("Make Node1 prefer block C again") self.nodes[1].preciousblock(hashC) assert_equal(self.nodes[1].getbestblockhash(), hashC) - print("Mine another block (E-F-G-)H on Node 0 and reorg Node 1") + self.log.info( + "Mine another block (E-F-G-)H on Node 0 and reorg Node 1") self.nodes[0].generate(1) assert_equal(self.nodes[0].getblockcount(), 6) sync_blocks(self.nodes[0:2]) hashH = self.nodes[0].getbestblockhash() assert_equal(self.nodes[1].getbestblockhash(), hashH) - print("Node1 should not be able to prefer block C anymore") + self.log.info("Node1 should not be able to prefer block C anymore") self.nodes[1].preciousblock(hashC) assert_equal(self.nodes[1].getbestblockhash(), hashH) - print("Mine competing blocks I-J-K-L on Node 2") + self.log.info("Mine competing blocks I-J-K-L on Node 2") self.nodes[2].generate(4) assert_equal(self.nodes[2].getblockcount(), 6) hashL = self.nodes[2].getbestblockhash() - print("Connect nodes and check no reorg occurs") + self.log.info("Connect nodes and check no reorg occurs") node_sync_via_rpc(self.nodes[1:3]) connect_nodes_bi(self.nodes, 1, 2) connect_nodes_bi(self.nodes, 0, 2) assert_equal(self.nodes[0].getbestblockhash(), hashH) assert_equal(self.nodes[1].getbestblockhash(), hashH) assert_equal(self.nodes[2].getbestblockhash(), hashL) - print("Make Node1 prefer block L") + self.log.info("Make Node1 prefer block L") self.nodes[1].preciousblock(hashL) assert_equal(self.nodes[1].getbestblockhash(), hashL) - print("Make Node2 prefer block H") + self.log.info("Make Node2 prefer block H") self.nodes[2].preciousblock(hashH) assert_equal(self.nodes[2].getbestblockhash(), hashH) diff --git a/qa/rpc-tests/prioritise_transaction.py b/qa/rpc-tests/prioritise_transaction.py --- a/qa/rpc-tests/prioritise_transaction.py +++ b/qa/rpc-tests/prioritise_transaction.py @@ -28,7 +28,7 @@ self.is_network_split = False self.nodes.append( - start_node(0, self.options.tmpdir, ["-debug", "-printpriority=1"])) + start_node(0, self.options.tmpdir, ["-printpriority=1"])) self.relayfee = self.nodes[0].getnetworkinfo()['relayfee'] def run_test(self): @@ -70,7 +70,7 @@ self.nodes[0].generate(1) mempool = self.nodes[0].getrawmempool() - print("Assert that prioritised transaction was mined") + self.log.info("Assert that prioritised transaction was mined") assert(txids[0][0] not in mempool) assert(txids[0][1] in mempool) @@ -103,7 +103,8 @@ # High fee transaction should not have been mined, but other high fee rate # transactions should have been. mempool = self.nodes[0].getrawmempool() - print("Assert that de-prioritised transaction is still in mempool") + self.log.info( + "Assert that de-prioritised transaction is still in mempool") assert(high_fee_tx in mempool) for x in txids[2]: if (x != high_fee_tx): @@ -149,7 +150,7 @@ self.nodes[0].prioritisetransaction( tx2_id, 0, int(self.relayfee * COIN)) - print( + self.log.info( "Assert that prioritised free transaction is accepted to mempool") assert_equal(self.nodes[0].sendrawtransaction(tx2_hex), tx2_id) assert(tx2_id in self.nodes[0].getrawmempool()) diff --git a/qa/rpc-tests/proxy_test.py b/qa/rpc-tests/proxy_test.py --- a/qa/rpc-tests/proxy_test.py +++ b/qa/rpc-tests/proxy_test.py @@ -71,7 +71,7 @@ self.conf3.unauth = True self.conf3.auth = True else: - print("Warning: testing without local IPv6 support") + self.log.info("Warning: testing without local IPv6 support") self.serv1 = Socks5Server(self.conf1) self.serv1.start() @@ -86,16 +86,16 @@ # this is because the proxy to use is based on CService.GetNetwork(), # which return NET_UNROUTABLE for localhost args = [ - ['-listen', '-debug=net', '-debug=proxy', '-proxy=%s:%i' % + ['-listen', '-proxy=%s:%i' % (self.conf1.addr), '-proxyrandomize=1'], - ['-listen', '-debug=net', '-debug=proxy', '-proxy=%s:%i' % + ['-listen', '-proxy=%s:%i' % (self.conf1.addr), '-onion=%s:%i' % (self.conf2.addr), '-proxyrandomize=0'], - ['-listen', '-debug=net', '-debug=proxy', '-proxy=%s:%i' % + ['-listen', '-proxy=%s:%i' % (self.conf2.addr), '-proxyrandomize=1'], [] ] if self.have_ipv6: - args[3] = ['-listen', '-debug=net', '-debug=proxy', '-proxy=[%s]:%i' % + args[3] = ['-listen', '-proxy=[%s]:%i' % (self.conf3.addr), '-proxyrandomize=0', '-noonion'] return start_nodes(self.num_nodes, self.options.tmpdir, extra_args=args) diff --git a/qa/rpc-tests/pruning.py b/qa/rpc-tests/pruning.py --- a/qa/rpc-tests/pruning.py +++ b/qa/rpc-tests/pruning.py @@ -47,22 +47,19 @@ # Create nodes 0 and 1 to mine self.nodes.append( - start_node(0, self.options.tmpdir, ["-debug", - "-maxreceivebuffer=20000", + start_node(0, self.options.tmpdir, ["-maxreceivebuffer=20000", "-checkblocks=5", "-blockmaxsize=1000000"], timewait=900)) self.nodes.append( - start_node(1, self.options.tmpdir, ["-debug", - "-maxreceivebuffer=20000", + start_node(1, self.options.tmpdir, ["-maxreceivebuffer=20000", "-checkblocks=5", "-blockmaxsize=1000000"], timewait=900)) # Create node 2 to test pruning self.nodes.append( - start_node(2, self.options.tmpdir, ["-debug", - "-maxreceivebuffer=20000", + start_node(2, self.options.tmpdir, ["-maxreceivebuffer=20000", "-prune=550", "-blockmaxsize=1000000"], timewait=900)) @@ -71,20 +68,17 @@ # Create nodes 3 and 4 to test manual pruning (they will be re-started # with manual pruning later) self.nodes.append( - start_node(3, self.options.tmpdir, ["-debug=0", - "-maxreceivebuffer=20000", + start_node(3, self.options.tmpdir, ["-maxreceivebuffer=20000", "-blockmaxsize=1000000"], timewait=900)) self.nodes.append( - start_node(4, self.options.tmpdir, ["-debug=0", - "-maxreceivebuffer=20000", + start_node(4, self.options.tmpdir, ["-maxreceivebuffer=20000", "-blockmaxsize=1000000"], timewait=900)) # Create nodes 5 to test wallet in prune mode, but do not connect self.nodes.append( - start_node(5, self.options.tmpdir, ["-debug=0", - "-prune=550", + start_node(5, self.options.tmpdir, ["-prune=550", "-blockmaxsize=1000000"])) # Determine default relay fee @@ -111,10 +105,10 @@ def test_height_min(self): if not os.path.isfile(self.prunedir + "blk00000.dat"): raise AssertionError("blk00000.dat is missing, pruning too early") - print("Success") - print("Though we're already using more than 550MiB, current usage:", - calc_usage(self.prunedir)) - print( + self.log.info("Success") + self.log.info("Though we're already using more than 550MiB, current usage: %d" % + calc_usage(self.prunedir)) + self.log.info( "Mining 25 more blocks should cause the first block file to be pruned") # Pruning doesn't run until we're allocating another chunk, 20 full # blocks past the height cutoff will ensure this @@ -128,15 +122,15 @@ raise AssertionError( "blk00000.dat not pruned when it should be") - print("Success") + self.log.info("Success") usage = calc_usage(self.prunedir) - print("Usage should be below target:", usage) + self.log.info("Usage should be below target: %d" % usage) if (usage > 550): raise AssertionError("Pruning target not being met") def create_chain_with_staleblocks(self): # Create stale blocks in manageable sized chunks - print( + self.log.info( "Mine 24 (stale) blocks on Node 1, followed by 25 (main chain) block reorg from Node 0, for 12 rounds") for j in range(12): @@ -145,10 +139,10 @@ # Stopping node 0 also clears its mempool, so it doesn't have # node1's transactions to accidentally mine self.stop_node(0) - self.nodes[0] = start_node(0, self.options.tmpdir, ["-debug", - "-maxreceivebuffer=20000", - "-checkblocks=5", - "-blockmaxsize=1000000"], + self.nodes[0] = start_node( + 0, self.options.tmpdir, ["-maxreceivebuffer=20000", + "-checkblocks=5", + "-blockmaxsize=1000000"], timewait=900) # Mine 24 blocks in node 1 for i in range(24): @@ -168,8 +162,8 @@ connect_nodes(self.nodes[2], 0) sync_blocks(self.nodes[0:3]) - print("Usage can be over target because of high stale rate:", - calc_usage(self.prunedir)) + self.log.info("Usage can be over target because of high stale rate: %d" % + calc_usage(self.prunedir)) def reorg_test(self): # Node 1 will mine a 300 block chain starting 287 blocks back from Node @@ -179,19 +173,20 @@ # block max size so we don't keep mining all our big mempool # transactions (from disconnected blocks) self.stop_node(1) - self.nodes[1] = start_node(1, self.options.tmpdir, ["-debug", - "-maxreceivebuffer=20000", - "-blockmaxsize=5000", - "-checkblocks=5", - "-disablesafemode"], + self.nodes[1] = start_node( + 1, self.options.tmpdir, ["-maxreceivebuffer=20000", + "-blockmaxsize=5000", + "-checkblocks=5", + "-disablesafemode"], timewait=900, stderr_checker=OutputChecker()) height = self.nodes[1].getblockcount() - print("Current block height:", height) + self.log.info("Current block height: %d" % height) invalidheight = height - 287 badhash = self.nodes[1].getblockhash(invalidheight) - print("Invalidating block at height:", invalidheight, badhash) + self.log.info("Invalidating block %s at height %d" % + (badhash, invalidheight)) self.nodes[1].invalidateblock(badhash) # We've now switched to our previously mined-24 block fork on node 1, but thats not what we want. @@ -204,31 +199,32 @@ curhash = self.nodes[1].getblockhash(invalidheight - 1) assert(self.nodes[1].getblockcount() == invalidheight - 1) - print("New best height", self.nodes[1].getblockcount()) + self.log.info("New best height: %d" % self.nodes[1].getblockcount()) # Reboot node1 to clear those giant tx's from mempool self.stop_node(1) - self.nodes[1] = start_node(1, self.options.tmpdir, ["-debug", - "-maxreceivebuffer=20000", - "-blockmaxsize=5000", - "-checkblocks=5", - "-disablesafemode", - "-blockmaxsize=1000000"], + self.nodes[1] = start_node( + 1, self.options.tmpdir, ["-maxreceivebuffer=20000", + "-blockmaxsize=5000", + "-checkblocks=5", + "-disablesafemode", + "-blockmaxsize=1000000"], timewait=900, stderr_checker=OutputChecker()) - print("Generating new longer chain of 300 more blocks") + self.log.info("Generating new longer chain of 300 more blocks") self.nodes[1].generate(300) - print("Reconnect nodes") + self.log.info("Reconnect nodes") connect_nodes(self.nodes[0], 1) connect_nodes(self.nodes[2], 1) sync_blocks(self.nodes[0:3], timeout=120) - print("Verify height on node 2:", self.nodes[2].getblockcount()) - print("Usage possibly still high bc of stale blocks in block files:", - calc_usage(self.prunedir)) + self.log.info("Verify height on node 2: %d" % + self.nodes[2].getblockcount()) + self.log.info("Usage possibly still high bc of stale blocks in block files: %d" % + calc_usage(self.prunedir)) - print( + self.log.info( "Mine 220 more blocks so we have requisite history (some blocks will be big and cause pruning of previous chain)") for i in range(22): # This can be slow, so do this in multiple RPC calls to avoid @@ -238,7 +234,7 @@ sync_blocks(self.nodes[0:3], timeout=300) usage = calc_usage(self.prunedir) - print("Usage should be below target:", usage) + self.log.info("Usage should be below target: %d" % usage) if (usage > 550): raise AssertionError("Pruning target not being met") @@ -248,7 +244,7 @@ # Verify that a block on the old main chain fork has been pruned away assert_raises_jsonrpc( -1, "Block not available (pruned data)", self.nodes[2].getblock, self.forkhash) - print("Will need to redownload block", self.forkheight) + self.log.info("Will need to redownload block", self.forkheight) # Verify that we have enough history to reorg back to the fork point. # Although this is more than 288 blocks, because this chain was written @@ -274,15 +270,15 @@ # reorg. if self.nodes[2].getblockcount() < self.mainchainheight: blocks_to_mine = first_reorg_height + 1 - self.mainchainheight - print( - "Rewind node 0 to prev main chain to mine longer chain to trigger redownload. Blocks needed:", blocks_to_mine) + self.log.info( + "Rewind node 0 to prev main chain to mine longer chain to trigger redownload. Blocks needed: %d" % blocks_to_mine) self.nodes[0].invalidateblock(curchainhash) assert(self.nodes[0].getblockcount() == self.mainchainheight) assert(self.nodes[0].getbestblockhash() == self.mainchainhash2) goalbesthash = self.nodes[0].generate(blocks_to_mine)[-1] goalbestheight = first_reorg_height + 1 - print( + self.log.info( "Verify node 2 reorged back to the main chain, some blocks of which it had to redownload") waitstart = time.time() while self.nodes[2].getblockcount() < goalbestheight: @@ -298,7 +294,7 @@ # at this point, node has 995 blocks and has not yet run in prune mode node = self.nodes[node_number] = start_node( node_number, self.options.tmpdir, - ["-debug=0", "-blockmaxsize=1000000"], timewait=900) + ["-blockmaxsize=1000000"], timewait=900) assert_equal(node.getblockcount(), 995) assert_raises_jsonrpc( -1, "not in prune mode", node.pruneblockchain, 500) @@ -307,7 +303,7 @@ # now re-start in manual pruning mode node = self.nodes[node_number] = start_node( node_number, self.options.tmpdir, - ["-debug=0", "-prune=1", "-blockmaxsize=1000000"], timewait=900) + ["-prune=1", "-blockmaxsize=1000000"], timewait=900) assert_equal(node.getblockcount(), 995) def height(index): @@ -396,32 +392,32 @@ self.stop_node(node_number) self.nodes[node_number] = start_node( node_number, self.options.tmpdir, - ["-debug=0", "-prune=550", "-blockmaxsize=1000000"], timewait=900) + ["-prune=550", "-blockmaxsize=1000000"], timewait=900) - print("Success") + self.log.info("Success") def wallet_test(self): # check that the pruning node's wallet is still in good shape - print("Stop and start pruning node to trigger wallet rescan") + self.log.info("Stop and start pruning node to trigger wallet rescan") self.stop_node(2) - start_node(2, self.options.tmpdir, ["-debug=1", "-prune=550"]) - print("Success") + start_node(2, self.options.tmpdir, ["-prune=550"]) + self.log.info("Success") # check that wallet loads loads successfully when restarting a pruned node after IBD. # this was reported to fail in #7494. - print ("Syncing node 5 to test wallet") + self.log.info("Syncing node 5 to test wallet") connect_nodes(self.nodes[0], 5) nds = [self.nodes[0], self.nodes[5]] sync_blocks(nds, wait=5, timeout=300) # Stop and start to trigger rescan self.stop_node(5) - start_node(5, self.options.tmpdir, ["-debug=1", "-prune=550"]) - print ("Success") + start_node(5, self.options.tmpdir, ["-prune=550"]) + self.log.info("Success") def run_test(self): - print( + self.log.info( "Warning! This test requires 4GB of disk space and takes over 30 mins (up to 2 hours)") - print("Mining a big blockchain of 995 blocks") + self.log.info("Mining a big blockchain of 995 blocks") self.create_big_chain() # Chain diagram key: # * blocks on main chain @@ -436,13 +432,13 @@ self.stop_node(3) self.stop_node(4) - print( + self.log.info( "Check that we haven't started pruning yet because we're below PruneAfterHeight") self.test_height_min() # Extend this chain past the PruneAfterHeight # N0=N1=N2 **...*(1020) - print( + self.log.info( "Check that we'll exceed disk space target if we have a very high stale block rate") self.create_chain_with_staleblocks() # Disconnect N0 @@ -467,7 +463,7 @@ self.mainchainheight = self.nodes[2].getblockcount() # 1320 self.mainchainhash2 = self.nodes[2].getblockhash(self.mainchainheight) - print("Check that we can survive a 288 block reorg still") + self.log.info("Check that we can survive a 288 block reorg still") (self.forkheight, self.forkhash) = self.reorg_test() # (1033, ) # Now create a 288 block reorg by mining a longer chain on N1 # First disconnect N1 @@ -500,7 +496,7 @@ # \ # *...**(1320) - print( + self.log.info( "Test that we can rerequest a block we previously pruned if needed for a reorg") self.reorg_back() # Verify that N2 still has block 1033 on current chain (@), but not on main chain (*) @@ -521,16 +517,16 @@ # # N1 doesn't change because 1033 on main chain (*) is invalid - print("Test manual pruning with block indices") + self.log.info("Test manual pruning with block indices") self.manual_test(3, use_timestamp=False) - print("Test manual pruning with timestamps") + self.log.info("Test manual pruning with timestamps") self.manual_test(4, use_timestamp=True) - print("Test wallet re-scan") + self.log.info("Test wallet re-scan") self.wallet_test() - print("Done") + self.log.info("Done") if __name__ == '__main__': PruneTest().main() diff --git a/qa/rpc-tests/reindex.py b/qa/rpc-tests/reindex.py --- a/qa/rpc-tests/reindex.py +++ b/qa/rpc-tests/reindex.py @@ -29,14 +29,15 @@ self.nodes[0].generate(3) blockcount = self.nodes[0].getblockcount() stop_nodes(self.nodes) - extra_args = [ - ["-debug", "-reindex-chainstate" if justchainstate else "-reindex", "-checkblockindex=1"]] + extra_args = [[ + "-reindex-chainstate" if justchainstate else "-reindex", + "-checkblockindex=1"]] self.nodes = start_nodes( self.num_nodes, self.options.tmpdir, extra_args) while self.nodes[0].getblockcount() < blockcount: time.sleep(0.1) assert_equal(self.nodes[0].getblockcount(), blockcount) - print("Success") + self.log.info("Success") def run_test(self): self.reindex(False) diff --git a/qa/rpc-tests/rest.py b/qa/rpc-tests/rest.py --- a/qa/rpc-tests/rest.py +++ b/qa/rpc-tests/rest.py @@ -68,7 +68,7 @@ def run_test(self): url = urllib.parse.urlparse(self.nodes[0].url) - print("Mining blocks...") + self.log.info("Mining blocks...") self.nodes[0].generate(1) self.sync_all() diff --git a/qa/rpc-tests/rpcbind_test.py b/qa/rpc-tests/rpcbind_test.py --- a/qa/rpc-tests/rpcbind_test.py +++ b/qa/rpc-tests/rpcbind_test.py @@ -67,7 +67,7 @@ if non_loopback_ip is None: assert( not 'This test requires at least one non-loopback IPv4 interface') - print("Using interface %s for testing" % non_loopback_ip) + self.log.info("Using interface %s for testing" % non_loopback_ip) defaultport = rpc_port(0) diff --git a/qa/rpc-tests/sendheaders.py b/qa/rpc-tests/sendheaders.py --- a/qa/rpc-tests/sendheaders.py +++ b/qa/rpc-tests/sendheaders.py @@ -241,8 +241,7 @@ def setup_network(self): self.nodes = [] - self.nodes = start_nodes( - self.num_nodes, self.options.tmpdir, [["-debug", "-logtimemicros=1"]] * 2) + self.nodes = start_nodes(self.num_nodes, self.options.tmpdir) connect_nodes(self.nodes[0], 1) # mine count blocks and return the new tip @@ -302,7 +301,8 @@ # PART 1 # 1. Mine a block; expect inv announcements each time - print("Part 1: headers don't start before sendheaders message...") + self.log.info( + "Part 1: headers don't start before sendheaders message...") for i in range(4): old_tip = tip tip = self.mine_blocks(1) @@ -337,8 +337,8 @@ inv_node.clear_last_announcement() test_node.clear_last_announcement() - print("Part 1: success!") - print( + self.log.info("Part 1: success!") + self.log.info( "Part 2: announce blocks with headers after sendheaders message...") # PART 2 # 2. Send a sendheaders message and test that headers announcements @@ -404,9 +404,9 @@ height += 1 block_time += 1 - print("Part 2: success!") + self.log.info("Part 2: success!") - print( + self.log.info( "Part 3: headers announcements can stop after large reorg, and resume after headers/inv from peer...") # PART 3. Headers announcements can stop after large reorg, and resume after @@ -478,9 +478,9 @@ assert_equal( test_node.check_last_announcement(headers=[tip]), True) - print("Part 3: success!") + self.log.info("Part 3: success!") - print("Part 4: Testing direct fetch behavior...") + self.log.info("Part 4: Testing direct fetch behavior...") tip = self.mine_blocks(1) height = self.nodes[0].getblockcount() + 1 last_time = self.nodes[0].getblock( @@ -568,12 +568,12 @@ with mininode_lock: assert_equal(test_node.last_getdata, None) - print("Part 4: success!") + self.log.info("Part 4: success!") # Now deliver all those blocks we announced. [test_node.send_message(msg_block(x)) for x in blocks] - print("Part 5: Testing handling of unconnecting headers") + self.log.info("Part 5: Testing handling of unconnecting headers") # First we test that receipt of an unconnecting header doesn't prevent # chain sync. for i in range(10): @@ -645,7 +645,7 @@ with mininode_lock: self.last_getheaders = True - print("Part 5: success!") + self.log.info("Part 5: success!") # Finally, check that the inv node never received a getdata request, # throughout the test diff --git a/qa/rpc-tests/smartfees.py b/qa/rpc-tests/smartfees.py --- a/qa/rpc-tests/smartfees.py +++ b/qa/rpc-tests/smartfees.py @@ -22,6 +22,8 @@ # "OP_2 OP_DROP" SCRIPT_SIG = ["0451025175", "0451025275"] +global log + def small_txpuzzle_randfee(from_node, conflist, unconflist, amount, min_fee, fee_increment): ''' @@ -109,7 +111,8 @@ ''' all_estimates = [node.estimatefee(i) for i in range(1, 26)] if print_estimates: - print([str(all_estimates[e - 1]) for e in [1, 2, 3, 6, 15, 25]]) + log.info([str(all_estimates[e - 1]) + for e in [1, 2, 3, 6, 15, 25]]) delta = 1.0e-6 # account for rounding error last_e = max(fees_seen) for e in [x for x in all_estimates if x >= 0]: @@ -173,8 +176,8 @@ start_node(0, self.options.tmpdir, ["-maxorphantx=1000", "-whitelist=127.0.0.1"])) - print("This test is time consuming, please be patient") - print( + self.log.info("This test is time consuming, please be patient") + self.log.info( "Splitting inputs to small size so we can generate low priority tx's") self.txouts = [] self.txouts2 = [] @@ -202,7 +205,7 @@ while (len(self.nodes[0].getrawmempool()) > 0): self.nodes[0].generate(1) reps += 1 - print("Finished splitting") + self.log.info("Finished splitting") # Now we can connect the other nodes, didn't want to connect them earlier # so the estimates would not be affected by the splitting transactions @@ -212,7 +215,7 @@ # (17k is room enough for 110 or so transactions) self.nodes.append(start_node(1, self.options.tmpdir, ["-blockprioritysize=1500", "-blockmaxsize=17000", - "-maxorphantx=1000", "-debug=estimatefee"], + "-maxorphantx=1000"], stderr_checker=OutputChecker())) connect_nodes(self.nodes[1], 0) @@ -258,20 +261,24 @@ self.memutxo = newmem def run_test(self): + # Make log handler available to helper functions + global log + log = self.log + self.fees_per_kb = [] self.memutxo = [] self.confutxo = self.txouts # Start with the set of confirmed txouts after splitting - print("Will output estimates for 1/2/3/6/15/25 blocks") + self.log.info("Will output estimates for 1/2/3/6/15/25 blocks") for i in range(2): - print( + self.log.info( "Creating transactions and mining them with a block size that can't keep up") # Create transactions and mine 10 small blocks with node 2, but # create txs faster than we can mine self.transact_and_mine(10, self.nodes[2]) check_estimates(self.nodes[1], self.fees_per_kb, 14) - print( + self.log.info( "Creating transactions and mining them at a block size that is just big enough") # Generate transactions while mining 10 more blocks, this time with node1 # which mines blocks with capacity just above the rate that @@ -284,7 +291,7 @@ self.nodes[1].generate(1) sync_blocks(self.nodes[0:3], wait=.1) - print("Final estimates after emptying mempools") + self.log.info("Final estimates after emptying mempools") check_estimates(self.nodes[1], self.fees_per_kb, 2) if __name__ == '__main__': diff --git a/qa/rpc-tests/test_framework/blockstore.py b/qa/rpc-tests/test_framework/blockstore.py --- a/qa/rpc-tests/test_framework/blockstore.py +++ b/qa/rpc-tests/test_framework/blockstore.py @@ -11,7 +11,11 @@ from io import BytesIO import dbm.dumb as dbmd +logger = logging.getLogger("TestFramework.blockstore") + + class BlockStore(object): + def __init__(self, datadir): self.blockDB = dbmd.open(datadir + "/blocks", 'c') self.currentBlock = 0 @@ -60,7 +64,7 @@ return None response = msg_headers() - headersList = [ current_block_header ] + headersList = [current_block_header] maxheaders = 2000 while (headersList[0].sha256 not in locator.vHave): prevBlockHash = headersList[0].hashPrevBlock @@ -69,11 +73,11 @@ headersList.insert(0, prevBlockHeader) else: break - headersList = headersList[:maxheaders] # truncate if we have too many + headersList = headersList[:maxheaders] # truncate if we have too many hashList = [x.sha256 for x in headersList] index = len(headersList) if (hash_stop in hashList): - index = hashList.index(hash_stop)+1 + index = hashList.index(hash_stop) + 1 response.headers = headersList[:index] return response @@ -82,7 +86,7 @@ try: self.blockDB[repr(block.sha256)] = bytes(block.serialize()) except TypeError as e: - print("Unexpected error: ", sys.exc_info()[0], e.args) + logger.exception("Unexpected error") self.currentBlock = block.sha256 self.headers_map[block.sha256] = CBlockHeader(block) @@ -94,7 +98,7 @@ def get_blocks(self, inv): responses = [] for i in inv: - if (i.type == 2): # MSG_BLOCK + if (i.type == 2): # MSG_BLOCK data = self.get(i.hash) if data is not None: # Use msg_generic to avoid re-serialization @@ -121,7 +125,9 @@ locator.vHave = r return locator + class TxStore(object): + def __init__(self, datadir): self.txDB = dbmd.open(datadir + "/transactions", 'c') @@ -152,12 +158,12 @@ try: self.txDB[repr(tx.sha256)] = bytes(tx.serialize()) except TypeError as e: - print("Unexpected error: ", sys.exc_info()[0], e.args) + logger.exception("Unexpected error") def get_transactions(self, inv): responses = [] for i in inv: - if (i.type == 1): # MSG_TX + if (i.type == 1): # MSG_TX tx = self.get(i.hash) if tx is not None: responses.append(msg_generic(b"tx", tx)) diff --git a/qa/rpc-tests/test_framework/comptool.py b/qa/rpc-tests/test_framework/comptool.py --- a/qa/rpc-tests/test_framework/comptool.py +++ b/qa/rpc-tests/test_framework/comptool.py @@ -7,6 +7,10 @@ from .blockstore import BlockStore, TxStore from .util import p2p_port +import logging + +logger = logging.getLogger("TestFramework.comptool") + ''' This is a tool for comparing two or more bitcoinds to each other using a script provided. @@ -231,7 +235,6 @@ # --> error if not requested if not wait_until(blocks_requested, attempts=20 * num_blocks): - # print [ c.cb.block_request_map for c in self.connections ] raise AssertionError("Not all nodes requested block") # Send getheaders message @@ -254,7 +257,6 @@ # --> error if not requested if not wait_until(transaction_requested, attempts=20 * num_events): - # print [ c.cb.tx_request_map for c in self.connections ] raise AssertionError("Not all nodes requested transaction") # Get the mempool @@ -281,14 +283,14 @@ if c.cb.bestblockhash == blockhash: return False if blockhash not in c.cb.block_reject_map: - print('Block not in reject map: %064x' % (blockhash)) + logger.error( + 'Block not in reject map: %064x' % (blockhash)) return False if not outcome.match(c.cb.block_reject_map[blockhash]): - print('Block rejected with %s instead of expected %s: %064x' % - (c.cb.block_reject_map[blockhash], outcome, blockhash)) + logger.error('Block rejected with %s instead of expected %s: %064x' % + (c.cb.block_reject_map[blockhash], outcome, blockhash)) return False elif ((c.cb.bestblockhash == blockhash) != outcome): - # print c.cb.bestblockhash, blockhash, outcome return False return True @@ -304,20 +306,18 @@ if outcome is None: # Make sure the mempools agree with each other if c.cb.lastInv != self.connections[0].cb.lastInv: - # print c.rpc.getrawmempool() return False elif isinstance(outcome, RejectResult): # Check that tx was rejected w/ code if txhash in c.cb.lastInv: return False if txhash not in c.cb.tx_reject_map: - print('Tx not in reject map: %064x' % (txhash)) + logger.error('Tx not in reject map: %064x' % (txhash)) return False if not outcome.match(c.cb.tx_reject_map[txhash]): - print('Tx rejected with %s instead of expected %s: %064x' % - (c.cb.tx_reject_map[txhash], outcome, txhash)) + logger.error('Tx rejected with %s instead of expected %s: %064x' % + (c.cb.tx_reject_map[txhash], outcome, txhash)) return False elif ((txhash in c.cb.lastInv) != outcome): - # print c.rpc.getrawmempool(), c.cb.lastInv return False return True @@ -440,8 +440,7 @@ raise AssertionError( "Mempool test failed at test %d" % test_number) - print("Test %d: PASS" % - test_number, [c.rpc.getblockcount() for c in self.connections]) + logger.info("Test %d: PASS" % test_number) test_number += 1 [c.disconnect_node() for c in self.connections] diff --git a/qa/rpc-tests/test_framework/mininode.py b/qa/rpc-tests/test_framework/mininode.py --- a/qa/rpc-tests/test_framework/mininode.py +++ b/qa/rpc-tests/test_framework/mininode.py @@ -58,6 +58,8 @@ # Howmuch data will be read from the network at once READ_BUFFER_SIZE = 8192 +logger = logging.getLogger("TestFramework.mininode") + # Keep our own socket map for asyncore, so that we can track disconnects # ourselves (to workaround an issue with closing an asyncore socket when # using select) @@ -1575,8 +1577,7 @@ getattr(self, 'on_' + message.command.decode('ascii'))( conn, message) except: - print("ERROR delivering %s (%s)" % (repr(message), - sys.exc_info()[0])) + logger.exception("ERROR delivering %s" % repr(message)) def on_version(self, conn, message): if message.nVersion >= 209: @@ -1715,7 +1716,6 @@ def __init__(self, dstaddr, dstport, rpc, callback, net="regtest", services=NODE_NETWORK, send_version=True): asyncore.dispatcher.__init__(self, map=mininode_socket_map) - self.log = logging.getLogger("NodeConn(%s:%d)" % (dstaddr, dstport)) self.dstaddr = dstaddr self.dstport = dstport self.create_socket(socket.AF_INET, socket.SOCK_STREAM) @@ -1740,8 +1740,8 @@ vt.addrFrom.port = 0 self.send_message(vt, True) - print('MiniNode: Connecting to Bitcoin Node IP # ' + dstaddr + ':' - + str(dstport)) + logger.info('Connecting to Bitcoin Node: %s:%d' % + (self.dstaddr, self.dstport)) try: self.connect((dstaddr, dstport)) @@ -1749,18 +1749,15 @@ self.handle_close() self.rpc = rpc - def show_debug_msg(self, msg): - self.log.debug(msg) - def handle_connect(self): if self.state != "connected": - self.show_debug_msg("MiniNode: Connected & Listening: \n") + logger.debug("Connected & Listening: \n") self.state = "connected" self.cb.on_open(self) def handle_close(self): - self.show_debug_msg("MiniNode: Closing Connection to %s:%d... " - % (self.dstaddr, self.dstport)) + logger.debug("Closing Connection to %s:%d... " % + (self.dstaddr, self.dstport)) self.state = "closed" self.recvbuf = b"" self.sendbuf = b"" @@ -1845,8 +1842,8 @@ "got bad checksum " + repr(self.recvbuf)) self.recvbuf = self.recvbuf[4 + 12 + 4 + 4 + msglen:] if command not in self.messagemap: - self.show_debug_msg("Unknown command: '" + command + "' " + - repr(msg)) + logger.warning("Received unknown command from %s:%d: '%s' %s" % + (self.dstaddr, self.dstport, command, repr(msg))) return None f = BytesIO(msg) m = self.messagemap[command]() @@ -1854,14 +1851,13 @@ return m except Exception as e: - print('got_data:', repr(e)) - # import traceback - # traceback.print_tb(sys.exc_info()[2]) + logger.exception('got_data:', repr(e)) def send_message(self, message, pushbuf=False): if self.state != "connected" and not pushbuf: raise IOError('Not connected, no pushbuf') - self.show_debug_msg("Send %s" % repr(message)) + logger.debug("Send message to %s:%d: %s" % + (self.dstaddr, self.dstport, repr(message))) command = message.command data = message.serialize() tmsg = self.MAGIC_BYTES[self.network] @@ -1883,7 +1879,8 @@ self.messagemap[b'ping'] = msg_ping_prebip31 if self.last_sent + 30 * 60 < time.time(): self.send_message(self.messagemap[b'ping']()) - self.show_debug_msg("Recv %s" % repr(message)) + logger.debug("Received message from %s:%d: %s" % + (self.dstaddr, self.dstport, repr(message))) self.cb.deliver(self, message) def disconnect_node(self): diff --git a/qa/rpc-tests/test_framework/test_framework.py b/qa/rpc-tests/test_framework/test_framework.py --- a/qa/rpc-tests/test_framework/test_framework.py +++ b/qa/rpc-tests/test_framework/test_framework.py @@ -44,7 +44,7 @@ pass def setup_chain(self): - print("Initializing test directory " + self.options.tmpdir) + self.log.info("Initializing test directory " + self.options.tmpdir) if self.setup_clean_chain: initialize_chain_clean(self.options.tmpdir, self.num_nodes) else: @@ -126,6 +126,8 @@ parser.add_option( "--tmpdir", dest="tmpdir", default=tempfile.mkdtemp(prefix="test"), help="Root directory for datadirs") + parser.add_option("-l", "--loglevel", dest="loglevel", default="INFO", + help="log events at this level and higher to the console. Can be set to DEBUG, INFO, WARNING, ERROR or CRITICAL. Passing --loglevel DEBUG will output all logs to console. Note that logs at all levels are always written to the test_framework.log file in the temporary test directory.") parser.add_option( "--tracerpc", dest="trace_rpc", default=False, action="store_true", help="Print out all RPC calls as they are made") @@ -141,9 +143,6 @@ self.options.root, self.options.tmpdir = self.options.tmpdir, self.options.tmpdir + \ '/' + str(self.options.port_seed) - if self.options.trace_rpc: - logging.basicConfig(level=logging.DEBUG, stream=sys.stdout) - if self.options.coveragedir: enable_coverage(self.options.coveragedir) @@ -154,41 +153,42 @@ check_json_precision() + # Set up temp directory and start logging + os.makedirs(self.options.tmpdir, exist_ok=False) + self._start_logging() + success = False + try: - os.makedirs(self.options.tmpdir, exist_ok=False) self.setup_chain() self.setup_network() self.run_test() success = True except JSONRPCException as e: - print("JSONRPC error: " + e.error['message']) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("JSONRPC error") except AssertionError as e: - print("Assertion failed: " + str(e)) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("Assertion failed") except KeyError as e: - print("key not found: " + str(e)) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("Key error") except Exception as e: - print("Unexpected exception caught during testing: " + repr(e)) - traceback.print_tb(sys.exc_info()[2]) + self.log.exception("Unexpected exception caught during testing") except KeyboardInterrupt as e: - print("Exiting after " + repr(e)) + self.log.warning("Exiting after keyboard interrupt") if not self.options.noshutdown: - print("Stopping nodes") + self.log.info("Stopping nodes") stop_nodes(self.nodes) else: - print("Note: bitcoinds were not stopped and may still be running") + self.log.info( + "Note: bitcoinds were not stopped and may still be running") if not self.options.nocleanup and not self.options.noshutdown and success: - print("Cleaning up") + self.log.info("Cleaning up") shutil.rmtree(self.options.tmpdir) if not os.listdir(self.options.root): os.rmdir(self.options.root) else: - print("Not cleaning up dir %s" % self.options.tmpdir) + self.log.warning("Not cleaning up dir %s" % self.options.tmpdir) if os.getenv("PYTHON_DEBUG", ""): # Dump the end of the debug logs, to aid in debugging rare # travis failures. @@ -201,12 +201,46 @@ from collections import deque print("".join(deque(open(f), MAX_LINES_TO_PRINT))) if success: - print("Tests successful") + self.log.info("Tests successful") sys.exit(0) else: - print("Failed") + self.log.error( + "Test failed. Test logging available at %s/test_framework.log", self.options.tmpdir) + logging.shutdown() sys.exit(1) + def _start_logging(self): + # Add logger and logging handlers + self.log = logging.getLogger('TestFramework') + self.log.setLevel(logging.DEBUG) + # Create file handler to log all messages + fh = logging.FileHandler(self.options.tmpdir + '/test_framework.log') + fh.setLevel(logging.DEBUG) + # Create console handler to log messages to stderr. By default this + # logs only error messages, but can be configured with --loglevel. + ch = logging.StreamHandler(sys.stdout) + # User can provide log level as a number or string (eg DEBUG). loglevel + # was caught as a string, so try to convert it to an int + ll = int( + self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper() + ch.setLevel(ll) + # Format logs the same as bitcoind's debug.log with microprecision (so + # log files can be concatenated and sorted) + formatter = logging.Formatter( + fmt='%(asctime)s.%(msecs)03d000 %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%d %H:%M:%S') + fh.setFormatter(formatter) + ch.setFormatter(formatter) + + # add the handlers to the logger + self.log.addHandler(fh) + self.log.addHandler(ch) + + if self.options.trace_rpc: + rpc_logger = logging.getLogger("BitcoinRPC") + rpc_logger.setLevel(logging.DEBUG) + rpc_handler = logging.StreamHandler(sys.stdout) + rpc_handler.setLevel(logging.DEBUG) + rpc_logger.addHandler(rpc_handler) # Test framework for doing p2p comparison testing, which sets up some bitcoind # binaries: @@ -233,6 +267,6 @@ def setup_network(self): self.nodes = start_nodes( self.num_nodes, self.options.tmpdir, - extra_args=[['-debug', '-whitelist=127.0.0.1']] * self.num_nodes, + extra_args=[['-whitelist=127.0.0.1']] * self.num_nodes, binary=[self.options.testbinary] + [self.options.refbinary] * (self.num_nodes - 1)) diff --git a/qa/rpc-tests/test_framework/util.py b/qa/rpc-tests/test_framework/util.py --- a/qa/rpc-tests/test_framework/util.py +++ b/qa/rpc-tests/test_framework/util.py @@ -22,6 +22,7 @@ import time import re import errno +import logging from . import coverage from .authproxy import AuthServiceProxy, JSONRPCException @@ -30,6 +31,8 @@ DEFAULT_BITCOIND = 'bitcoind' COVERAGE_DIR = None +logger = logging.getLogger("TestFramework.utils") + # The maximum number of nodes a single test can spawn MAX_NODES = 8 # Don't assign rpc or p2p ports lower than this @@ -261,6 +264,7 @@ break if create_cache: + logger.debug("Creating data directories from cached datadir") # Find and delete old cache directories if any exist for i in range(MAX_NODES): @@ -275,12 +279,9 @@ if i > 0: args.append("-connect=127.0.0.1:" + str(p2p_port(0))) bitcoind_processes[i] = subprocess.Popen(args) - if os.getenv("PYTHON_DEBUG", ""): - print( - "initialize_chain: bitcoind started, waiting for RPC to come up") + logger.debug("Creating data directories from cached datadir") wait_for_bitcoind_start(bitcoind_processes[i], rpc_url(i), i) - if os.getenv("PYTHON_DEBUG", ""): - print("initialize_chain: RPC successfully started") + logger.debug("initialize_chain: RPC successfully started") rpcs = [] for i in range(MAX_NODES): @@ -390,7 +391,7 @@ if binary is None: binary = locate_bitcoind_binary() args = [binary, "-datadir=" + datadir, "-server", "-keypool=1", - "-discover=0", "-rest", "-mocktime=" + str(get_mocktime())] + "-discover=0", "-rest", "-logtimemicros", "-debug", "-mocktime=" + str(get_mocktime())] if extra_args is not None: args.extend(extra_args) if stderr_checker: @@ -400,12 +401,11 @@ stderr=stderr_checker.get_connector()) else: bitcoind_processes[i] = subprocess.Popen(args) - if os.getenv("PYTHON_DEBUG", ""): - print("start_node: bitcoind started, waiting for RPC to come up") + logger.debug( + "initialize_chain: bitcoind started, waiting for RPC to come up") url = rpc_url(i, rpchost) wait_for_bitcoind_start(bitcoind_processes[i], url, i) - if os.getenv("PYTHON_DEBUG", ""): - print("start_node: RPC successfully started") + logger.debug("initialize_chain: RPC successfully started") proxy = get_rpc_proxy(url, i, timeout=timewait) if COVERAGE_DIR: @@ -445,10 +445,11 @@ def stop_node(node, i): + logger.debug("Stopping node %d" % i) try: node.stop() except http.client.CannotSendRequest as e: - print("WARN: Unable to stop node: " + repr(e)) + logger.exception("Unable to stop node") return_code = bitcoind_processes[i].wait( timeout=BITCOIND_PROC_WAIT_TIMEOUT) assert_equal(return_code, 0) diff --git a/qa/rpc-tests/wallet-hd.py b/qa/rpc-tests/wallet-hd.py --- a/qa/rpc-tests/wallet-hd.py +++ b/qa/rpc-tests/wallet-hd.py @@ -61,7 +61,7 @@ self.sync_all() assert_equal(self.nodes[1].getbalance(), num_hd_adds + 1) - print("Restore backup ...") + self.log.info("Restore backup ...") self.stop_node(1) os.remove(self.options.tmpdir + "/node1/regtest/wallet.dat") shutil.copyfile( diff --git a/qa/rpc-tests/wallet.py b/qa/rpc-tests/wallet.py --- a/qa/rpc-tests/wallet.py +++ b/qa/rpc-tests/wallet.py @@ -37,7 +37,7 @@ assert_equal(len(self.nodes[1].listunspent()), 0) assert_equal(len(self.nodes[2].listunspent()), 0) - print("Mining blocks...") + self.log.info("Mining blocks...") self.nodes[0].generate(1) @@ -355,7 +355,7 @@ ] chainlimit = 6 for m in maintenance: - print("check " + m) + self.log.info("check " + m) stop_nodes(self.nodes) # set lower ancestor limit for later self.nodes = start_nodes(3, self.options.tmpdir, diff --git a/qa/rpc-tests/walletbackup.py b/qa/rpc-tests/walletbackup.py --- a/qa/rpc-tests/walletbackup.py +++ b/qa/rpc-tests/walletbackup.py @@ -36,9 +36,6 @@ from test_framework.test_framework import BitcoinTestFramework from test_framework.util import * from random import randint -import logging -logging.basicConfig( - format='%(levelname)s: %(message)s', level=logging.INFO, stream=sys.stdout) class WalletBackupTest(BitcoinTestFramework): @@ -106,7 +103,7 @@ os.remove(self.options.tmpdir + "/node2/regtest/wallet.dat") def run_test(self): - logging.info("Generating initial blockchain") + self.log.info("Generating initial blockchain") self.nodes[0].generate(1) sync_blocks(self.nodes) self.nodes[1].generate(1) @@ -121,12 +118,12 @@ assert_equal(self.nodes[2].getbalance(), 50) assert_equal(self.nodes[3].getbalance(), 0) - logging.info("Creating transactions") + self.log.info("Creating transactions") # Five rounds of sending each other transactions. for i in range(5): self.do_one_round() - logging.info("Backing up") + self.log.info("Backing up") tmpdir = self.options.tmpdir self.nodes[0].backupwallet(tmpdir + "/node0/wallet.bak") self.nodes[0].dumpwallet(tmpdir + "/node0/wallet.dump") @@ -135,7 +132,7 @@ self.nodes[2].backupwallet(tmpdir + "/node2/wallet.bak") self.nodes[2].dumpwallet(tmpdir + "/node2/wallet.dump") - logging.info("More transactions") + self.log.info("More transactions") for i in range(5): self.do_one_round() @@ -156,7 +153,7 @@ # # Test restoring spender wallets from backups # - logging.info("Restoring using wallet.dat") + self.log.info("Restoring using wallet.dat") self.stop_three() self.erase_three() @@ -172,7 +169,7 @@ shutil.copyfile( tmpdir + "/node2/wallet.bak", tmpdir + "/node2/regtest/wallet.dat") - logging.info("Re-starting nodes") + self.log.info("Re-starting nodes") self.start_three() sync_blocks(self.nodes) @@ -180,7 +177,7 @@ assert_equal(self.nodes[1].getbalance(), balance1) assert_equal(self.nodes[2].getbalance(), balance2) - logging.info("Restoring using dumped wallet") + self.log.info("Restoring using dumped wallet") self.stop_three() self.erase_three() diff --git a/qa/rpc-tests/zapwallettxes.py b/qa/rpc-tests/zapwallettxes.py --- a/qa/rpc-tests/zapwallettxes.py +++ b/qa/rpc-tests/zapwallettxes.py @@ -23,7 +23,7 @@ self.sync_all() def run_test(self): - print("Mining blocks...") + self.log.info("Mining blocks...") self.nodes[0].generate(1) self.sync_all() self.nodes[1].generate(101) diff --git a/qa/rpc-tests/zmq_test.py b/qa/rpc-tests/zmq_test.py --- a/qa/rpc-tests/zmq_test.py +++ b/qa/rpc-tests/zmq_test.py @@ -41,7 +41,7 @@ genhashes = self.nodes[0].generate(1) self.sync_all() - print("listen...") + self.log.info("listen...") msg = self.zmqSubSocket.recv_multipart() topic = msg[0] assert_equal(topic, b"hashtx")