diff options
| author | MarcoFalke <falke.marco@gmail.com> | 2017-03-09 21:16:20 +0100 |
|---|---|---|
| committer | MarcoFalke <falke.marco@gmail.com> | 2017-03-09 21:16:39 +0100 |
| commit | 8910b4717e5bb946ee6988f7fe9fd461f53a5935 (patch) | |
| tree | 87dbf2ccfa73d4650556919e92108033b54fc9a7 | |
| parent | 5703dff0939f05c7457cebd6fc61d88ab13afe41 (diff) | |
| parent | 64c080051b932b3e53ece7638f199e48d0ad16c8 (diff) | |
Merge #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
53 files changed, 398 insertions, 394 deletions
diff --git a/qa/rpc-tests/abandonconflict.py b/qa/rpc-tests/abandonconflict.py index 5a860e4392..887dbebd4f 100755 --- a/qa/rpc-tests/abandonconflict.py +++ b/qa/rpc-tests/abandonconflict.py @@ -23,8 +23,8 @@ class AbandonConflictTest(BitcoinTestFramework): 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): @@ -81,7 +81,7 @@ class AbandonConflictTest(BitcoinTestFramework): # Restart the node with a higher min relay fee so the parent tx is no longer in mempool # TODO: redo with eviction 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) @@ -107,7 +107,7 @@ class AbandonConflictTest(BitcoinTestFramework): # 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) @@ -127,7 +127,7 @@ class AbandonConflictTest(BitcoinTestFramework): # 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")) @@ -158,9 +158,9 @@ class AbandonConflictTest(BitcoinTestFramework): 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() diff --git a/qa/rpc-tests/assumevalid.py b/qa/rpc-tests/assumevalid.py index b8dafff161..c60c8e6d1a 100755 --- a/qa/rpc-tests/assumevalid.py +++ b/qa/rpc-tests/assumevalid.py @@ -73,7 +73,7 @@ class SendHeadersTest(BitcoinTestFramework): # 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 @@ class SendHeadersTest(BitcoinTestFramework): # 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]) diff --git a/qa/rpc-tests/bip65-cltv-p2p.py b/qa/rpc-tests/bip65-cltv-p2p.py index ea9c3d73ab..63d05e8fc9 100755 --- a/qa/rpc-tests/bip65-cltv-p2p.py +++ b/qa/rpc-tests/bip65-cltv-p2p.py @@ -43,7 +43,7 @@ class BIP65Test(ComparisonTestFramework): 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): diff --git a/qa/rpc-tests/bip68-112-113-p2p.py b/qa/rpc-tests/bip68-112-113-p2p.py index 836267ea7f..0867f42585 100755 --- a/qa/rpc-tests/bip68-112-113-p2p.py +++ b/qa/rpc-tests/bip68-112-113-p2p.py @@ -99,7 +99,7 @@ class BIP68_112_113Test(ComparisonTestFramework): 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=4']], + extra_args=[['-whitelist=127.0.0.1', '-blockversion=4']], binary=[self.options.testbinary]) def run_test(self): diff --git a/qa/rpc-tests/bip68-sequence.py b/qa/rpc-tests/bip68-sequence.py index 3fe3b471f9..ffd461ccb0 100755 --- a/qa/rpc-tests/bip68-sequence.py +++ b/qa/rpc-tests/bip68-sequence.py @@ -24,8 +24,8 @@ class BIP68Test(BitcoinTestFramework): def setup_network(self): self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug"])) - self.nodes.append(start_node(1, self.options.tmpdir, ["-debug", "-acceptnonstdtxn=0"])) + self.nodes.append(start_node(0, self.options.tmpdir)) + self.nodes.append(start_node(1, self.options.tmpdir, ["-acceptnonstdtxn=0"])) self.is_network_split = False self.relayfee = self.nodes[0].getnetworkinfo()["relayfee"] connect_nodes(self.nodes[0], 1) @@ -34,26 +34,26 @@ class BIP68Test(BitcoinTestFramework): # 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 bitcoin 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. diff --git a/qa/rpc-tests/bip9-softforks.py b/qa/rpc-tests/bip9-softforks.py index 70d4be3f69..0dffd06e1a 100755 --- a/qa/rpc-tests/bip9-softforks.py +++ b/qa/rpc-tests/bip9-softforks.py @@ -35,7 +35,7 @@ class BIP9SoftForksTest(ComparisonTestFramework): 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 index b82ef89395..22bd39fbe5 100755 --- a/qa/rpc-tests/bipdersig-p2p.py +++ b/qa/rpc-tests/bipdersig-p2p.py @@ -50,7 +50,7 @@ class BIP66Test(ComparisonTestFramework): 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): diff --git a/qa/rpc-tests/bumpfee.py b/qa/rpc-tests/bumpfee.py index 68e9808ea5..69db197e7a 100755 --- a/qa/rpc-tests/bumpfee.py +++ b/qa/rpc-tests/bumpfee.py @@ -26,7 +26,7 @@ class BumpFeeTest(BitcoinTestFramework): self.setup_clean_chain = True def setup_network(self, split=False): - extra_args = [["-debug", "-prematurewitness", "-walletprematurewitness", "-walletrbf={}".format(i)] + extra_args = [["-prematurewitness", "-walletprematurewitness", "-walletrbf={}".format(i)] for i in range(self.num_nodes)] self.nodes = start_nodes(self.num_nodes, self.options.tmpdir, extra_args) @@ -45,7 +45,7 @@ class BumpFeeTest(BitcoinTestFramework): rbf_node_address = rbf_node.getnewaddress() # fund rbf node with 10 coins of 0.001 btc (100,000 satoshis) - print("Mining blocks...") + self.log.info("Mining blocks...") peer_node.generate(110) self.sync_all() for i in range(25): @@ -55,7 +55,7 @@ class BumpFeeTest(BitcoinTestFramework): self.sync_all() assert_equal(rbf_node.getbalance(), Decimal("0.025")) - print("Running tests") + self.log.info("Running tests") dest_address = peer_node.getnewaddress() test_small_output_fails(rbf_node, dest_address) test_dust_to_fee(rbf_node, dest_address) @@ -70,7 +70,7 @@ class BumpFeeTest(BitcoinTestFramework): test_unconfirmed_not_spendable(rbf_node, rbf_node_address) test_bumpfee_metadata(rbf_node, dest_address) test_locked_wallet_fails(rbf_node, dest_address) - print("Success") + self.log.info("Success") def test_simple_bumpfee_succeeds(rbf_node, peer_node, dest_address): diff --git a/qa/rpc-tests/fundrawtransaction.py b/qa/rpc-tests/fundrawtransaction.py index 1f86581297..fd330ef277 100755 --- a/qa/rpc-tests/fundrawtransaction.py +++ b/qa/rpc-tests/fundrawtransaction.py @@ -34,8 +34,6 @@ class RawTransactionsTest(BitcoinTestFramework): 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 index b73fea0695..dc17bbd7b3 100755 --- a/qa/rpc-tests/getblocktemplate_longpoll.py +++ b/qa/rpc-tests/getblocktemplate_longpoll.py @@ -29,7 +29,7 @@ class GetBlockTemplateLPTest(BitcoinTestFramework): 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.") self.nodes[0].generate(10) templat = self.nodes[0].getblocktemplate() longpollid = templat['longpollid'] diff --git a/qa/rpc-tests/import-rescan.py b/qa/rpc-tests/import-rescan.py index 64e0eec61e..0218a46168 100755 --- a/qa/rpc-tests/import-rescan.py +++ b/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 @@ class ImportRescanTest(BitcoinTestFramework): 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 index 015336effe..298b6e9b86 100755 --- a/qa/rpc-tests/importmulti.py +++ b/qa/rpc-tests/importmulti.py @@ -17,7 +17,7 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): # 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): # 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 @@ class ImportMultiTest (BitcoinTestFramework): # 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): 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 @@ class ImportMultiTest (BitcoinTestFramework): # 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 @@ class ImportMultiTest (BitcoinTestFramework): # 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 @@ class ImportMultiTest (BitcoinTestFramework): # 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 @@ class ImportMultiTest (BitcoinTestFramework): # 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 @@ class ImportMultiTest (BitcoinTestFramework): 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'], diff --git a/qa/rpc-tests/importprunedfunds.py b/qa/rpc-tests/importprunedfunds.py index 4e529951ed..b4c8ee6c70 100755 --- a/qa/rpc-tests/importprunedfunds.py +++ b/qa/rpc-tests/importprunedfunds.py @@ -21,7 +21,7 @@ class ImportPrunedFundsTest(BitcoinTestFramework): 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 index 92e65927d5..8c80b64003 100755 --- a/qa/rpc-tests/invalidateblock.py +++ b/qa/rpc-tests/invalidateblock.py @@ -18,53 +18,51 @@ class InvalidateTest(BitcoinTestFramework): 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("Make sure we repopulate setBlockIndexCandidates after InvalidateBlock:") - print("Mine 4 blocks on Node 0") + self.log.info("Make sure we repopulate setBlockIndexCandidates after InvalidateBlock:") + 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("Invalidate block 2 on node 0 and verify we reorg to node 0's original chain") + 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() newhash = self.nodes[0].getbestblockhash() if (newheight != 4 or newhash != besthash): 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("Make 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("Node 1 reorged to a lower height: %d"%node1height) diff --git a/qa/rpc-tests/listsinceblock.py b/qa/rpc-tests/listsinceblock.py index 88304af5b0..a75e66c8c4 100755 --- a/qa/rpc-tests/listsinceblock.py +++ b/qa/rpc-tests/listsinceblock.py @@ -62,7 +62,7 @@ class ListSinceBlockTest (BitcoinTestFramework): # 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 index 8ea405b4d5..564337d060 100755 --- a/qa/rpc-tests/maxblocksinflight.py +++ b/qa/rpc-tests/maxblocksinflight.py @@ -13,7 +13,6 @@ reach. [0.10 clients shouldn't request more than 16 from a single peer.] from test_framework.mininode import * from test_framework.test_framework import BitcoinTestFramework from test_framework.util import * -import logging MAX_REQUESTS = 128 @@ -33,7 +32,6 @@ class TestManager(NodeConnCB): def __init__(self): NodeConnCB.__init__(self) - self.log = logging.getLogger("BlockRelayTest") def add_new_connection(self, connection): self.connection = connection @@ -65,7 +63,7 @@ class TestManager(NodeConnCB): raise AssertionError("Error, test failed: block %064x requested more than once" % key) 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() @@ -84,7 +82,7 @@ class MaxBlocksInFlightTest(BitcoinTestFramework): 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/maxuploadtarget.py b/qa/rpc-tests/maxuploadtarget.py index 757aa60afd..40cd85c9ec 100755 --- a/qa/rpc-tests/maxuploadtarget.py +++ b/qa/rpc-tests/maxuploadtarget.py @@ -90,7 +90,7 @@ class MaxUploadTest(BitcoinTestFramework): def setup_network(self): # Start a node with maxuploadtarget of 200 MB (/24h) self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug", "-maxuploadtarget=800", "-blockmaxsize=999000"])) + self.nodes.append(start_node(0, self.options.tmpdir, ["-maxuploadtarget=800", "-blockmaxsize=999000"])) def run_test(self): # Before we connect anything, we first set the time on the node @@ -161,7 +161,7 @@ class MaxUploadTest(BitcoinTestFramework): 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. @@ -172,7 +172,7 @@ class MaxUploadTest(BitcoinTestFramework): 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. getdata_request.inv = [CInv(2, big_old_block)] @@ -180,9 +180,9 @@ class MaxUploadTest(BitcoinTestFramework): 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. @@ -192,14 +192,14 @@ class MaxUploadTest(BitcoinTestFramework): 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", "-blockmaxsize=999000"]) + self.nodes[0] = start_node(0, self.options.tmpdir, ["-whitelist=127.0.0.1", "-maxuploadtarget=1", "-blockmaxsize=999000"]) #recreate/reconnect 3 test nodes test_nodes = [] @@ -225,7 +225,7 @@ class MaxUploadTest(BitcoinTestFramework): test_nodes[1].wait_for_disconnect() assert_equal(len(self.nodes[0].getpeerinfo()), 3) #node is still connected because of the whitelist - print("Peer 1 still connected after trying to download old block (whitelisted)") + 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 index 8fae92ad2b..a7ca576aee 100755 --- a/qa/rpc-tests/mempool_limit.py +++ b/qa/rpc-tests/mempool_limit.py @@ -11,7 +11,7 @@ class MempoolLimitTest(BitcoinTestFramework): def setup_network(self): self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-maxmempool=5", "-spendzeroconfchange=0", "-debug"])) + self.nodes.append(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 index 3437c89ec7..915d174052 100755 --- a/qa/rpc-tests/mempool_packages.py +++ b/qa/rpc-tests/mempool_packages.py @@ -19,8 +19,8 @@ class MempoolPackagesTest(BitcoinTestFramework): def setup_network(self): self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-maxorphantx=1000", "-debug"])) - self.nodes.append(start_node(1, self.options.tmpdir, ["-maxorphantx=1000", "-limitancestorcount=5", "-debug"])) + self.nodes.append(start_node(0, self.options.tmpdir, ["-maxorphantx=1000"])) + self.nodes.append(start_node(1, self.options.tmpdir, ["-maxorphantx=1000", "-limitancestorcount=5"])) connect_nodes(self.nodes[0], 1) self.is_network_split = False self.sync_all() @@ -115,7 +115,7 @@ class MempoolPackagesTest(BitcoinTestFramework): 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. @@ -165,9 +165,9 @@ class MempoolPackagesTest(BitcoinTestFramework): mempool = self.nodes[0].getrawmempool(True) 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("tx that would create too large descendant package successfully rejected") + 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 index 2cd5573277..585e4147b2 100755 --- a/qa/rpc-tests/mempool_reorg.py +++ b/qa/rpc-tests/mempool_reorg.py @@ -21,7 +21,7 @@ class MempoolCoinbaseTest(BitcoinTestFramework): 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 index c7f37aaa44..727892d1f2 100755 --- a/qa/rpc-tests/mempool_resurrect_test.py +++ b/qa/rpc-tests/mempool_resurrect_test.py @@ -17,7 +17,7 @@ class MempoolCoinbaseTest(BitcoinTestFramework): 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 index da8485e2a2..4818ad8bda 100755 --- a/qa/rpc-tests/mempool_spendcoinbase.py +++ b/qa/rpc-tests/mempool_spendcoinbase.py @@ -25,7 +25,7 @@ class MempoolSpendCoinbaseTest(BitcoinTestFramework): 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 index c4b45425d7..5963f2e7b6 100755 --- a/qa/rpc-tests/merkle_blocks.py +++ b/qa/rpc-tests/merkle_blocks.py @@ -17,11 +17,11 @@ class MerkleBlockTest(BitcoinTestFramework): def setup_network(self): self.nodes = [] # Nodes 0/1 are "wallet" nodes - 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(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, ["-debug"])) - self.nodes.append(start_node(3, self.options.tmpdir, ["-debug", "-txindex"])) + self.nodes.append(start_node(2, self.options.tmpdir)) + self.nodes.append(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) @@ -30,7 +30,7 @@ class MerkleBlockTest(BitcoinTestFramework): 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 index b44a98bfd5..4b215a70b0 100755 --- a/qa/rpc-tests/nulldummy.py +++ b/qa/rpc-tests/nulldummy.py @@ -45,7 +45,7 @@ class NULLDUMMYTest(BitcoinTestFramework): 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', '-walletprematurewitness']]) + extra_args=[['-whitelist=127.0.0.1', '-walletprematurewitness']]) def run_test(self): self.address = self.nodes[0].getnewaddress() @@ -64,7 +64,7 @@ class NULLDUMMYTest(BitcoinTestFramework): self.lastblockheight = 429 self.lastblocktime = int(time.time()) + 429 - print ("Test 1: NULLDUMMY compliant base transactions should be accepted to mempool and mined before activation [430]") + 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)] txid1 = self.tx_submit(self.nodes[0], test1txs[0]) test1txs.append(self.create_transaction(self.nodes[0], txid1, self.ms_address, 48)) @@ -73,29 +73,29 @@ class NULLDUMMYTest(BitcoinTestFramework): txid3 = self.tx_submit(self.nodes[0], test1txs[2]) self.block_submit(self.nodes[0], test1txs, False, True) - print ("Test 2: Non-NULLDUMMY base multisig transaction should not be accepted to mempool before activation") + 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, 47) trueDummy(test2tx) txid4 = self.tx_submit(self.nodes[0], test2tx, NULLDUMMY_ERROR) - print ("Test 3: Non-NULLDUMMY base transactions should be accepted in a block before activation [431]") + 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) - print ("Test 4: Non-NULLDUMMY base multisig transaction is invalid after activation") + self.log.info("Test 4: Non-NULLDUMMY base multisig transaction is invalid after activation") test4tx = self.create_transaction(self.nodes[0], txid4, self.address, 46) test6txs=[CTransaction(test4tx)] trueDummy(test4tx) self.tx_submit(self.nodes[0], test4tx, NULLDUMMY_ERROR) self.block_submit(self.nodes[0], [test4tx]) - print ("Test 5: Non-NULLDUMMY P2WSH multisig transaction invalid after activation") + self.log.info("Test 5: Non-NULLDUMMY P2WSH multisig transaction invalid after activation") test5tx = self.create_transaction(self.nodes[0], txid3, self.wit_address, 48) test6txs.append(CTransaction(test5tx)) test5tx.wit.vtxinwit[0].scriptWitness.stack[0] = b'\x01' self.tx_submit(self.nodes[0], test5tx, NULLDUMMY_ERROR) self.block_submit(self.nodes[0], [test5tx], True) - print ("Test 6: NULLDUMMY compliant base/witness transactions should be accepted to mempool and in block after activation [432]") + self.log.info("Test 6: NULLDUMMY compliant base/witness transactions should be accepted to mempool and in block after activation [432]") for i in test6txs: self.tx_submit(self.nodes[0], i) self.block_submit(self.nodes[0], test6txs, True, True) diff --git a/qa/rpc-tests/p2p-acceptblock.py b/qa/rpc-tests/p2p-acceptblock.py index 4767dd8fe2..e1111da4ae 100755 --- a/qa/rpc-tests/p2p-acceptblock.py +++ b/qa/rpc-tests/p2p-acceptblock.py @@ -119,10 +119,10 @@ class AcceptBlockTest(BitcoinTestFramework): # 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): @@ -160,7 +160,7 @@ class AcceptBlockTest(BitcoinTestFramework): [ 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 @@ -179,7 +179,7 @@ class AcceptBlockTest(BitcoinTestFramework): 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 = [] @@ -198,11 +198,11 @@ class AcceptBlockTest(BitcoinTestFramework): # 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 @@ -232,7 +232,7 @@ class AcceptBlockTest(BitcoinTestFramework): 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("Unrequested block far ahead of tip accepted from whitelisted peer") + 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 # Should still not be processed (even though it has a child that has more @@ -246,7 +246,7 @@ class AcceptBlockTest(BitcoinTestFramework): # a getdata request for this block. test_node.sync_with_ping() assert_equal(self.nodes[0].getblockcount(), 2) - print("Unrequested block that would complete more-work chain was ignored") + self.log.info("Unrequested block that would complete more-work chain was ignored") # 6. Try to get node to request the missing block. # Poke the node with an inv for block at height 3 and see if that @@ -262,14 +262,14 @@ class AcceptBlockTest(BitcoinTestFramework): # 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 index 79561f35f7..1fc0312c34 100755 --- a/qa/rpc-tests/p2p-compactblocks.py +++ b/qa/rpc-tests/p2p-compactblocks.py @@ -120,8 +120,8 @@ class CompactBlocksTest(BitcoinTestFramework): # Start up node0 to be a version 1, pre-segwit node. self.nodes = start_nodes(self.num_nodes, self.options.tmpdir, - [["-debug", "-logtimemicros=1", "-bip9params=segwit:0:0"], - ["-debug", "-logtimemicros", "-txindex"]]) + [["-bip9params=segwit:0:0"], + ["-txindex"]]) connect_nodes(self.nodes[0], 1) def build_block_on_tip(self, node, segwit=False): @@ -846,102 +846,102 @@ class CompactBlocksTest(BitcoinTestFramework): # We will need UTXOs to construct transactions in later tests. self.make_utxos() - print("Running tests, pre-segwit activation:") + self.log.info("Running tests, pre-segwit activation:") - print("\tTesting SENDCMPCT p2p message... ") + self.log.info("Testing SENDCMPCT p2p message... ") self.test_sendcmpct(self.nodes[0], self.test_node, 1) sync_blocks(self.nodes) self.test_sendcmpct(self.nodes[1], self.segwit_node, 2, old_node=self.old_node) sync_blocks(self.nodes) - print("\tTesting compactblock construction...") + self.log.info("Testing compactblock construction...") self.test_compactblock_construction(self.nodes[0], self.test_node, 1, False) sync_blocks(self.nodes) self.test_compactblock_construction(self.nodes[1], self.segwit_node, 2, False) sync_blocks(self.nodes) - print("\tTesting compactblock requests... ") + self.log.info("Testing compactblock requests... ") self.test_compactblock_requests(self.nodes[0], self.test_node, 1, False) sync_blocks(self.nodes) self.test_compactblock_requests(self.nodes[1], self.segwit_node, 2, False) sync_blocks(self.nodes) - print("\tTesting getblocktxn requests...") + self.log.info("Testing 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.segwit_node, 2) sync_blocks(self.nodes) - print("\tTesting getblocktxn handler...") + self.log.info("Testing 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.segwit_node, 2) self.test_getblocktxn_handler(self.nodes[1], self.old_node, 1) sync_blocks(self.nodes) - print("\tTesting compactblock requests/announcements not at chain tip...") + self.log.info("Testing compactblock requests/announcements not at chain tip...") self.test_compactblocks_not_at_tip(self.nodes[0], self.test_node) sync_blocks(self.nodes) self.test_compactblocks_not_at_tip(self.nodes[1], self.segwit_node) 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("Testing 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(self.nodes[1], self.segwit_node, 2) sync_blocks(self.nodes) # End-to-end block relay tests - print("\tTesting end-to-end block relay...") + self.log.info("Testing end-to-end block relay...") self.request_cb_announcements(self.test_node, self.nodes[0], 1) self.request_cb_announcements(self.old_node, self.nodes[1], 1) self.request_cb_announcements(self.segwit_node, self.nodes[1], 2) self.test_end_to_end_block_relay(self.nodes[0], [self.segwit_node, self.test_node, self.old_node]) self.test_end_to_end_block_relay(self.nodes[1], [self.segwit_node, self.test_node, self.old_node]) - print("\tTesting handling of invalid compact blocks...") + self.log.info("Testing handling of invalid compact blocks...") self.test_invalid_tx_in_compactblock(self.nodes[0], self.test_node, False) self.test_invalid_tx_in_compactblock(self.nodes[1], self.segwit_node, False) self.test_invalid_tx_in_compactblock(self.nodes[1], self.old_node, False) - print("\tTesting reconstructing compact blocks from all peers...") + self.log.info("Testing reconstructing compact blocks from all peers...") self.test_compactblock_reconstruction_multiple_peers(self.nodes[1], self.segwit_node, self.old_node) sync_blocks(self.nodes) # Advance to segwit activation - print ("\nAdvancing to segwit activation\n") + self.log.info("Advancing to segwit activation") self.activate_segwit(self.nodes[1]) - print ("Running tests, post-segwit activation...") + self.log.info("Running tests, post-segwit activation...") - print("\tTesting compactblock construction...") + self.log.info("Testing compactblock construction...") self.test_compactblock_construction(self.nodes[1], self.old_node, 1, True) self.test_compactblock_construction(self.nodes[1], self.segwit_node, 2, True) sync_blocks(self.nodes) - print("\tTesting compactblock requests (unupgraded node)... ") + self.log.info("Testing compactblock requests (unupgraded node)... ") self.test_compactblock_requests(self.nodes[0], self.test_node, 1, True) - print("\tTesting getblocktxn requests (unupgraded node)...") + self.log.info("Testing getblocktxn requests (unupgraded node)...") self.test_getblocktxn_requests(self.nodes[0], self.test_node, 1) # Need to manually sync node0 and node1, because post-segwit activation, # node1 will not download blocks from node0. - print("\tSyncing nodes...") + self.log.info("Syncing nodes...") assert(self.nodes[0].getbestblockhash() != self.nodes[1].getbestblockhash()) while (self.nodes[0].getblockcount() > self.nodes[1].getblockcount()): block_hash = self.nodes[0].getblockhash(self.nodes[1].getblockcount()+1) self.nodes[1].submitblock(self.nodes[0].getblock(block_hash, False)) assert_equal(self.nodes[0].getbestblockhash(), self.nodes[1].getbestblockhash()) - print("\tTesting compactblock requests (segwit node)... ") + self.log.info("Testing compactblock requests (segwit node)... ") self.test_compactblock_requests(self.nodes[1], self.segwit_node, 2, True) - print("\tTesting getblocktxn requests (segwit node)...") + self.log.info("Testing getblocktxn requests (segwit node)...") self.test_getblocktxn_requests(self.nodes[1], self.segwit_node, 2) sync_blocks(self.nodes) - print("\tTesting getblocktxn handler (segwit node should return witnesses)...") + self.log.info("Testing getblocktxn handler (segwit node should return witnesses)...") self.test_getblocktxn_handler(self.nodes[1], self.segwit_node, 2) self.test_getblocktxn_handler(self.nodes[1], self.old_node, 1) @@ -949,18 +949,18 @@ class CompactBlocksTest(BitcoinTestFramework): # announcement to all peers. # (Post-segwit activation, blocks won't propagate from node0 to node1 # automatically, so don't bother testing a block announced to node0.) - print("\tTesting end-to-end block relay...") + self.log.info("Testing end-to-end block relay...") self.request_cb_announcements(self.test_node, self.nodes[0], 1) self.request_cb_announcements(self.old_node, self.nodes[1], 1) self.request_cb_announcements(self.segwit_node, self.nodes[1], 2) self.test_end_to_end_block_relay(self.nodes[1], [self.segwit_node, self.test_node, self.old_node]) - print("\tTesting handling of invalid compact blocks...") + self.log.info("Testing handling of invalid compact blocks...") self.test_invalid_tx_in_compactblock(self.nodes[0], self.test_node, False) self.test_invalid_tx_in_compactblock(self.nodes[1], self.segwit_node, True) self.test_invalid_tx_in_compactblock(self.nodes[1], self.old_node, True) - print("\tTesting invalid index in cmpctblock message...") + self.log.info("Testing 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 index 1c62961db0..d8f07700d0 100755 --- a/qa/rpc-tests/p2p-feefilter.py +++ b/qa/rpc-tests/p2p-feefilter.py @@ -53,8 +53,8 @@ class FeeFilterTest(BitcoinTestFramework): # Node1 will be used to generate txs which should be relayed from Node0 # to our test node self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug", "-logtimemicros"])) - self.nodes.append(start_node(1, self.options.tmpdir, ["-debug", "-logtimemicros"])) + self.nodes.append(start_node(0, self.options.tmpdir)) + self.nodes.append(start_node(1, self.options.tmpdir)) connect_nodes(self.nodes[0], 1) def run_test(self): diff --git a/qa/rpc-tests/p2p-leaktests.py b/qa/rpc-tests/p2p-leaktests.py index bf08ea32f4..3a843197fb 100755 --- a/qa/rpc-tests/p2p-leaktests.py +++ b/qa/rpc-tests/p2p-leaktests.py @@ -32,7 +32,7 @@ class CLazyNode(NodeConnCB): 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 @@ -102,7 +102,7 @@ class P2PLeakTest(BitcoinTestFramework): super().__init__() 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 index c6b1490211..0aa9c90e8f 100755 --- a/qa/rpc-tests/p2p-mempool.py +++ b/qa/rpc-tests/p2p-mempool.py @@ -85,7 +85,7 @@ class P2PMempoolTests(BitcoinTestFramework): def setup_network(self): # Start a node with maxuploadtarget of 200 MB (/24h) self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug", "-peerbloomfilters=0"])) + self.nodes.append(start_node(0, self.options.tmpdir, ["-peerbloomfilters=0"])) def run_test(self): #connect a mininode diff --git a/qa/rpc-tests/p2p-segwit.py b/qa/rpc-tests/p2p-segwit.py index 470a5398b6..0f844883b1 100755 --- a/qa/rpc-tests/p2p-segwit.py +++ b/qa/rpc-tests/p2p-segwit.py @@ -70,7 +70,6 @@ class TestNode(NodeConnCB): def on_reject(self, conn, message): self.last_reject = message - #print (message) # Syncing helpers def sync(self, test_function, timeout=60): @@ -195,13 +194,13 @@ class SegWitTest(BitcoinTestFramework): def setup_network(self): self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug", "-logtimemicros=1", "-whitelist=127.0.0.1"])) + self.nodes.append(start_node(0, self.options.tmpdir, ["-whitelist=127.0.0.1"])) # Start a node for testing IsStandard rules. - self.nodes.append(start_node(1, self.options.tmpdir, ["-debug", "-logtimemicros=1", "-whitelist=127.0.0.1", "-acceptnonstdtxn=0"])) + self.nodes.append(start_node(1, self.options.tmpdir, ["-whitelist=127.0.0.1", "-acceptnonstdtxn=0"])) connect_nodes(self.nodes[0], 1) # Disable segwit's bip9 parameter to simulate upgrading after activation. - self.nodes.append(start_node(2, self.options.tmpdir, ["-debug", "-whitelist=127.0.0.1", "-bip9params=segwit:0:0"])) + self.nodes.append(start_node(2, self.options.tmpdir, ["-whitelist=127.0.0.1", "-bip9params=segwit:0:0"])) connect_nodes(self.nodes[0], 2) ''' Helpers ''' @@ -224,7 +223,7 @@ class SegWitTest(BitcoinTestFramework): ''' Individual tests ''' def test_witness_services(self): - print("\tVerifying NODE_WITNESS service bit") + self.log.info("Verifying NODE_WITNESS service bit") assert((self.test_node.connection.nServices & NODE_WITNESS) != 0) @@ -233,7 +232,7 @@ class SegWitTest(BitcoinTestFramework): def test_non_witness_transaction(self): # Mine a block with an anyone-can-spend coinbase, # let it mature, then try to spend it. - print("\tTesting non-witness transaction") + self.log.info("Testing non-witness transaction") block = self.build_next_block(nVersion=1) block.solve() self.test_node.send_message(msg_block(block)) @@ -262,7 +261,7 @@ class SegWitTest(BitcoinTestFramework): # Verify that blocks with witnesses are rejected before activation. def test_unnecessary_witness_before_segwit_activation(self): - print("\tTesting behavior of unnecessary witnesses") + self.log.info("Testing behavior of unnecessary witnesses") # For now, rely on earlier tests to have created at least one utxo for # us to use assert(len(self.utxo) > 0) @@ -389,7 +388,7 @@ class SegWitTest(BitcoinTestFramework): # This test can only be run after segwit has activated def test_witness_commitments(self): - print("\tTesting witness commitments") + self.log.info("Testing witness commitments") # First try a correct witness commitment. block = self.build_next_block() @@ -478,7 +477,7 @@ class SegWitTest(BitcoinTestFramework): def test_block_malleability(self): - print("\tTesting witness block malleability") + self.log.info("Testing witness block malleability") # Make sure that a block that has too big a virtual size # because of a too-large coinbase witness is not permanently @@ -519,7 +518,7 @@ class SegWitTest(BitcoinTestFramework): def test_witness_block_size(self): - print("\tTesting witness block size limit") + self.log.info("Testing witness block size limit") # TODO: Test that non-witness carrying blocks can't exceed 1MB # Skipping this test for now; this is covered in p2p-fullblocktest.py @@ -636,7 +635,7 @@ class SegWitTest(BitcoinTestFramework): # Consensus tests of extra witness data in a transaction. def test_extra_witness_data(self): - print("\tTesting extra witness data in tx") + self.log.info("Testing extra witness data in tx") assert(len(self.utxo) > 0) @@ -712,7 +711,7 @@ class SegWitTest(BitcoinTestFramework): def test_max_witness_push_length(self): ''' Should only allow up to 520 byte pushes in witness stack ''' - print("\tTesting maximum witness push size") + self.log.info("Testing maximum witness push size") MAX_SCRIPT_ELEMENT_SIZE = 520 assert(len(self.utxo)) @@ -752,7 +751,7 @@ class SegWitTest(BitcoinTestFramework): def test_max_witness_program_length(self): # Can create witness outputs that are long, but can't be greater than # 10k bytes to successfully spend - print("\tTesting maximum witness program length") + self.log.info("Testing maximum witness program length") assert(len(self.utxo)) MAX_PROGRAM_LENGTH = 10000 @@ -801,7 +800,7 @@ class SegWitTest(BitcoinTestFramework): def test_witness_input_length(self): ''' Ensure that vin length must match vtxinwit length ''' - print("\tTesting witness input length") + self.log.info("Testing witness input length") assert(len(self.utxo)) witness_program = CScript([OP_DROP, OP_TRUE]) @@ -884,7 +883,7 @@ class SegWitTest(BitcoinTestFramework): def test_witness_tx_relay_before_segwit_activation(self): - print("\tTesting relay of witness transactions") + self.log.info("Testing relay of witness transactions") # Generate a transaction that doesn't require a witness, but send it # with a witness. Should be rejected for premature-witness, but should # not be added to recently rejected list. @@ -908,7 +907,7 @@ class SegWitTest(BitcoinTestFramework): # a witness transaction ought not result in a getdata. try: self.test_node.announce_tx_and_wait_for_getdata(tx, timeout=2) - print("Error: duplicate tx getdata!") + self.log.error("Error: duplicate tx getdata!") assert(False) except AssertionError as e: pass @@ -936,7 +935,7 @@ class SegWitTest(BitcoinTestFramework): # - accepts transactions with valid witnesses # and that witness transactions are relayed to non-upgraded peers. def test_tx_relay_after_segwit_activation(self): - print("\tTesting relay of witness transactions") + self.log.info("Testing relay of witness transactions") # Generate a transaction that doesn't require a witness, but send it # with a witness. Should be rejected because we can't use a witness # when spending a non-witness output. @@ -1025,7 +1024,7 @@ class SegWitTest(BitcoinTestFramework): # This is true regardless of segwit activation. # Also test that we don't ask for blocks from unupgraded peers def test_block_relay(self, segwit_activated): - print("\tTesting block relay") + self.log.info("Testing block relay") blocktype = 2|MSG_WITNESS_FLAG @@ -1113,7 +1112,7 @@ class SegWitTest(BitcoinTestFramework): # V0 segwit outputs should be standard after activation, but not before. def test_standardness_v0(self, segwit_activated): - print("\tTesting standardness of v0 outputs (%s activation)" % ("after" if segwit_activated else "before")) + self.log.info("Testing standardness of v0 outputs (%s activation)" % ("after" if segwit_activated else "before")) assert(len(self.utxo)) witness_program = CScript([OP_TRUE]) @@ -1190,7 +1189,7 @@ class SegWitTest(BitcoinTestFramework): # Verify that future segwit upgraded transactions are non-standard, # but valid in blocks. Can run this before and after segwit activation. def test_segwit_versions(self): - print("\tTesting standardness/consensus for segwit versions (0-16)") + self.log.info("Testing standardness/consensus for segwit versions (0-16)") assert(len(self.utxo)) NUM_TESTS = 17 # will test OP_0, OP1, ..., OP_16 if (len(self.utxo) < NUM_TESTS): @@ -1274,7 +1273,7 @@ class SegWitTest(BitcoinTestFramework): def test_premature_coinbase_witness_spend(self): - print("\tTesting premature coinbase witness spend") + self.log.info("Testing premature coinbase witness spend") block = self.build_next_block() # Change the output of the block to be a witness output. witness_program = CScript([OP_TRUE]) @@ -1309,7 +1308,7 @@ class SegWitTest(BitcoinTestFramework): def test_signature_version_1(self): - print("\tTesting segwit signature hash version 1") + self.log.info("Testing segwit signature hash version 1") key = CECKey() key.set_secretbytes(b"9") pubkey = CPubKey(key.get_pubkey()) @@ -1428,7 +1427,7 @@ class SegWitTest(BitcoinTestFramework): block = self.build_next_block() if (not used_sighash_single_out_of_bounds): - print("WARNING: this test run didn't attempt SIGHASH_SINGLE with out-of-bounds index value") + self.log.info("WARNING: this test run didn't attempt SIGHASH_SINGLE with out-of-bounds index value") # Test the transactions we've added to the block if (len(block.vtx) > 1): self.update_witness_block_with_transactions(block, []) @@ -1491,7 +1490,7 @@ class SegWitTest(BitcoinTestFramework): # Test P2SH wrapped witness programs. def test_p2sh_witness(self, segwit_activated): - print("\tTesting P2SH witness transactions") + self.log.info("Testing P2SH witness transactions") assert(len(self.utxo)) @@ -1564,7 +1563,7 @@ class SegWitTest(BitcoinTestFramework): # To enable this test, pass --oldbinary=<path-to-pre-segwit-bitcoind> to # the test. def test_upgrade_after_activation(self, node, node_id): - print("\tTesting software upgrade after softfork activation") + self.log.info("Testing software upgrade after softfork activation") assert(node_id != 0) # node0 is assumed to be a segwit-active bitcoind @@ -1573,7 +1572,7 @@ class SegWitTest(BitcoinTestFramework): # Restart with the new binary stop_node(node, node_id) - self.nodes[node_id] = start_node(node_id, self.options.tmpdir, ["-debug"]) + self.nodes[node_id] = start_node(node_id, self.options.tmpdir) connect_nodes(self.nodes[0], node_id) sync_blocks(self.nodes) @@ -1592,7 +1591,7 @@ class SegWitTest(BitcoinTestFramework): def test_witness_sigops(self): '''Ensure sigop counting is correct inside witnesses.''' - print("\tTesting sigops limit") + self.log.info("Testing sigops limit") assert(len(self.utxo)) @@ -1694,7 +1693,7 @@ class SegWitTest(BitcoinTestFramework): # TODO: test p2sh sigop counting def test_getblocktemplate_before_lockin(self): - print("\tTesting getblocktemplate setting of segwit versionbit (before lockin)") + self.log.info("Testing getblocktemplate setting of segwit versionbit (before lockin)") # Node0 is segwit aware, node2 is not. for node in [self.nodes[0], self.nodes[2]]: gbt_results = node.getblocktemplate() @@ -1746,7 +1745,7 @@ class SegWitTest(BitcoinTestFramework): # Uncompressed pubkeys are no longer supported in default relay policy, # but (for now) are still valid in blocks. def test_uncompressed_pubkey(self): - print("\tTesting uncompressed pubkeys") + self.log.info("Testing uncompressed pubkeys") # Segwit transactions using uncompressed pubkeys are not accepted # under default policy, but should still pass consensus. key = CECKey() @@ -1848,7 +1847,7 @@ class SegWitTest(BitcoinTestFramework): self.utxo.append(UTXO(tx5.sha256, 0, tx5.vout[0].nValue)) def test_non_standard_witness(self): - print("\tTesting detection of non-standard P2WSH witness") + self.log.info("Testing detection of non-standard P2WSH witness") pad = chr(1).encode('latin-1') # Create scripts for tests @@ -1972,7 +1971,7 @@ class SegWitTest(BitcoinTestFramework): # Test logic begins here self.test_node.wait_for_verack() - print("\nStarting tests before segwit lock in:") + self.log.info("Starting tests before segwit lock in:") self.test_witness_services() # Verifies NODE_WITNESS self.test_non_witness_transaction() # non-witness tx's are accepted @@ -1987,7 +1986,7 @@ class SegWitTest(BitcoinTestFramework): sync_blocks(self.nodes) # At lockin, nothing should change. - print("\nTesting behavior post lockin, pre-activation") + self.log.info("Testing behavior post lockin, pre-activation") self.advance_to_segwit_lockin() # Retest unnecessary witnesses @@ -2000,7 +1999,7 @@ class SegWitTest(BitcoinTestFramework): sync_blocks(self.nodes) # Now activate segwit - print("\nTesting behavior after segwit activation") + self.log.info("Testing behavior after segwit activation") self.advance_to_segwit_active() sync_blocks(self.nodes) diff --git a/qa/rpc-tests/p2p-timeouts.py b/qa/rpc-tests/p2p-timeouts.py index 7f596b6e4b..498acb23fe 100755 --- a/qa/rpc-tests/p2p-timeouts.py +++ b/qa/rpc-tests/p2p-timeouts.py @@ -53,8 +53,7 @@ class TimeoutsTest(BitcoinTestFramework): 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 index 8e3e361fc1..dc714e9a4a 100755 --- a/qa/rpc-tests/p2p-versionbits-warning.py +++ b/qa/rpc-tests/p2p-versionbits-warning.py @@ -72,7 +72,7 @@ class VersionBitsWarningTest(BitcoinTestFramework): # Open and close to create zero-length file with open(self.alert_filename, 'w', encoding='utf8') as _: pass - self.extra_args = [["-debug", "-logtimemicros=1", "-alertnotify=echo %s >> \"" + self.alert_filename + "\""]] + self.extra_args = [["-alertnotify=echo %s >> \"" + self.alert_filename + "\""]] self.nodes = start_nodes(self.num_nodes, self.options.tmpdir, self.extra_args) # Send numblocks blocks via peer with nVersionToUse set. diff --git a/qa/rpc-tests/preciousblock.py b/qa/rpc-tests/preciousblock.py index dde164f329..30b0b5a301 100755 --- a/qa/rpc-tests/preciousblock.py +++ b/qa/rpc-tests/preciousblock.py @@ -39,13 +39,12 @@ class PreciousTest(BitcoinTestFramework): 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) @@ -53,62 +52,62 @@ class PreciousTest(BitcoinTestFramework): 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 index 13be6eeead..10f596b2cb 100755 --- a/qa/rpc-tests/prioritise_transaction.py +++ b/qa/rpc-tests/prioritise_transaction.py @@ -21,7 +21,7 @@ class PrioritiseTransactionTest(BitcoinTestFramework): self.nodes = [] self.is_network_split = False - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug", "-printpriority=1"])) + self.nodes.append(start_node(0, self.options.tmpdir, ["-printpriority=1"])) self.relayfee = self.nodes[0].getnetworkinfo()['relayfee'] def run_test(self): @@ -56,7 +56,7 @@ class PrioritiseTransactionTest(BitcoinTestFramework): 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) @@ -88,7 +88,7 @@ class PrioritiseTransactionTest(BitcoinTestFramework): # 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): @@ -120,7 +120,7 @@ class PrioritiseTransactionTest(BitcoinTestFramework): # accepted. self.nodes[0].prioritisetransaction(tx_id, int(self.relayfee*COIN)) - print("Assert that prioritised free transaction is accepted to mempool") + self.log.info("Assert that prioritised free transaction is accepted to mempool") assert_equal(self.nodes[0].sendrawtransaction(tx_hex), tx_id) assert(tx_id in self.nodes[0].getrawmempool()) diff --git a/qa/rpc-tests/proxy_test.py b/qa/rpc-tests/proxy_test.py index e4e231f312..6b2a8ed1c7 100755 --- a/qa/rpc-tests/proxy_test.py +++ b/qa/rpc-tests/proxy_test.py @@ -83,13 +83,13 @@ class ProxyTest(BitcoinTestFramework): # Note: proxies are not used to connect to local nodes # 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' % (self.conf1.addr),'-proxyrandomize=1'], - ['-listen', '-debug=net', '-debug=proxy', '-proxy=%s:%i' % (self.conf1.addr),'-onion=%s:%i' % (self.conf2.addr),'-proxyrandomize=0'], - ['-listen', '-debug=net', '-debug=proxy', '-proxy=%s:%i' % (self.conf2.addr),'-proxyrandomize=1'], + ['-listen', '-proxy=%s:%i' % (self.conf1.addr),'-proxyrandomize=1'], + ['-listen', '-proxy=%s:%i' % (self.conf1.addr),'-onion=%s:%i' % (self.conf2.addr),'-proxyrandomize=0'], + ['-listen', '-proxy=%s:%i' % (self.conf2.addr),'-proxyrandomize=1'], [] ] if self.have_ipv6: - args[3] = ['-listen', '-debug=net', '-debug=proxy', '-proxy=[%s]:%i' % (self.conf3.addr),'-proxyrandomize=0', '-noonion'] + args[3] = ['-listen', '-proxy=[%s]:%i' % (self.conf3.addr),'-proxyrandomize=0', '-noonion'] return start_nodes(self.num_nodes, self.options.tmpdir, extra_args=args) def node_test(self, node, proxies, auth, test_onion=True): diff --git a/qa/rpc-tests/pruning.py b/qa/rpc-tests/pruning.py index 6d778cfc5e..c6a82b5fea 100755 --- a/qa/rpc-tests/pruning.py +++ b/qa/rpc-tests/pruning.py @@ -41,19 +41,19 @@ class PruneTest(BitcoinTestFramework): self.is_network_split = False # Create nodes 0 and 1 to mine - self.nodes.append(start_node(0, self.options.tmpdir, ["-debug","-maxreceivebuffer=20000","-blockmaxsize=999000", "-checkblocks=5"], timewait=900)) - self.nodes.append(start_node(1, self.options.tmpdir, ["-debug","-maxreceivebuffer=20000","-blockmaxsize=999000", "-checkblocks=5"], timewait=900)) + self.nodes.append(start_node(0, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=999000", "-checkblocks=5"], timewait=900)) + self.nodes.append(start_node(1, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=999000", "-checkblocks=5"], timewait=900)) # Create node 2 to test pruning - self.nodes.append(start_node(2, self.options.tmpdir, ["-debug","-maxreceivebuffer=20000","-prune=550"], timewait=900)) + self.nodes.append(start_node(2, self.options.tmpdir, ["-maxreceivebuffer=20000","-prune=550"], timewait=900)) self.prunedir = self.options.tmpdir+"/node2/regtest/blocks/" # 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","-blockmaxsize=999000"], timewait=900)) - self.nodes.append(start_node(4, self.options.tmpdir, ["-debug=0","-maxreceivebuffer=20000","-blockmaxsize=999000"], timewait=900)) + self.nodes.append(start_node(3, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=999000"], timewait=900)) + self.nodes.append(start_node(4, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=999000"], 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"])) + self.nodes.append(start_node(5, self.options.tmpdir, ["-prune=550"])) # Determine default relay fee self.relayfee = self.nodes[0].getnetworkinfo()["relayfee"] @@ -79,9 +79,9 @@ class PruneTest(BitcoinTestFramework): 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("Mining 25 more blocks should cause the first block file to be pruned") + self.log.info("Success") + self.log.info("Though we're already using more than 550MiB, current usage:", 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 for i in range(25): mine_large_block(self.nodes[0], self.utxo_cache_0) @@ -92,22 +92,22 @@ class PruneTest(BitcoinTestFramework): if time.time() - waitstart > 30: 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:", 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("Mine 24 (stale) blocks on Node 1, followed by 25 (main chain) block reorg from Node 0, for 12 rounds") + 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): # Disconnect node 0 so it can mine a longer reorg chain without knowing about node 1's soon-to-be-stale chain # Node 2 stays connected, so it hears about the stale blocks and then reorg's when node0 reconnects # 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","-blockmaxsize=999000", "-checkblocks=5"], timewait=900) + self.nodes[0]=start_node(0, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=999000", "-checkblocks=5"], timewait=900) # Mine 24 blocks in node 1 for i in range(24): if j == 0: @@ -124,7 +124,7 @@ class PruneTest(BitcoinTestFramework): 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:", calc_usage(self.prunedir)) def reorg_test(self): # Node 1 will mine a 300 block chain starting 287 blocks back from Node 0 and Node 2's tip @@ -132,14 +132,14 @@ class PruneTest(BitcoinTestFramework): # Reboot node 1 to clear its mempool (hopefully make the invalidate faster) # Lower the 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"], timewait=900) + self.nodes[1]=start_node(1, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=5000", "-checkblocks=5", "-disablesafemode"], timewait=900) height = self.nodes[1].getblockcount() - print("Current block height:", height) + self.log.info("Current block height:", height) invalidheight = height-287 badhash = self.nodes[1].getblockhash(invalidheight) - print("Invalidating block at height:",invalidheight,badhash) + self.log.info("Invalidating block at height:",invalidheight,badhash) 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 @@ -151,24 +151,24 @@ class PruneTest(BitcoinTestFramework): 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", 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"], timewait=900) + self.nodes[1]=start_node(1, self.options.tmpdir, ["-maxreceivebuffer=20000","-blockmaxsize=5000", "-checkblocks=5", "-disablesafemode"], timewait=900) - 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:",self.nodes[2].getblockcount()) + self.log.info("Usage possibly still high bc of stale blocks in block files:", calc_usage(self.prunedir)) - print("Mine 220 more blocks so we have requisite history (some blocks will be big and cause pruning of previous chain)") + 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 # RPC timeouts. @@ -176,7 +176,7 @@ class PruneTest(BitcoinTestFramework): 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:", usage) if (usage > 550): raise AssertionError("Pruning target not being met") @@ -185,7 +185,7 @@ class PruneTest(BitcoinTestFramework): def reorg_back(self): # 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 more recently @@ -209,14 +209,14 @@ class PruneTest(BitcoinTestFramework): # At this point node 2 is within 288 blocks of the fork point so it will preserve its ability to 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:", 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("Verify node 2 reorged back to the main chain, some blocks of which it had to redownload") + 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: time.sleep(0.1) @@ -228,13 +228,13 @@ class PruneTest(BitcoinTestFramework): def manual_test(self, node_number, use_timestamp): # 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"], timewait=900) + node = self.nodes[node_number] = start_node(node_number, self.options.tmpdir, timewait=900) assert_equal(node.getblockcount(), 995) assert_raises_jsonrpc(-1, "not in prune mode", node.pruneblockchain, 500) self.stop_node(node_number) # now re-start in manual pruning mode - node = self.nodes[node_number] = start_node(node_number, self.options.tmpdir, ["-debug=0","-prune=1"], timewait=900) + node = self.nodes[node_number] = start_node(node_number, self.options.tmpdir, ["-prune=1"], timewait=900) assert_equal(node.getblockcount(), 995) def height(index): @@ -308,30 +308,30 @@ class PruneTest(BitcoinTestFramework): # stop node, start back up with auto-prune at 550MB, make sure still runs self.stop_node(node_number) - self.nodes[node_number] = start_node(node_number, self.options.tmpdir, ["-debug=0","-prune=550"], timewait=900) + self.nodes[node_number] = start_node(node_number, self.options.tmpdir, ["-prune=550"], 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) self.stop_node(5) #stop and start to trigger rescan - 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("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("Warning! This test requires 4GB of disk space and takes over 30 mins (up to 2 hours)") + self.log.info("Mining a big blockchain of 995 blocks") self.create_big_chain() # Chain diagram key: # * blocks on main chain @@ -346,12 +346,12 @@ class PruneTest(BitcoinTestFramework): self.stop_node(3) self.stop_node(4) - print("Check that we haven't started pruning yet because we're below PruneAfterHeight") + 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("Check that we'll exceed disk space target if we have a very high stale block rate") + 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 # And mine a 24 block chain on N1 and a separate 25 block chain on N0 @@ -375,7 +375,7 @@ class PruneTest(BitcoinTestFramework): 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 @@ -408,7 +408,7 @@ class PruneTest(BitcoinTestFramework): # \ # *...**(1320) - print("Test that we can rerequest a block we previously pruned if needed for a reorg") + 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 (*) # Invalidate 1033 on current chain (@) on N2 and we should be able to reorg to @@ -428,16 +428,16 @@ class PruneTest(BitcoinTestFramework): # # 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 index 1b547a920f..0cebb0466f 100755 --- a/qa/rpc-tests/reindex.py +++ b/qa/rpc-tests/reindex.py @@ -31,12 +31,12 @@ class ReindexTest(BitcoinTestFramework): 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/replace-by-fee.py b/qa/rpc-tests/replace-by-fee.py index 51cbb4dc4c..8e2abea6a5 100755 --- a/qa/rpc-tests/replace-by-fee.py +++ b/qa/rpc-tests/replace-by-fee.py @@ -25,19 +25,15 @@ def make_utxo(node, amount, confirmed=True, scriptPubKey=CScript([1])): fee = 1*COIN while node.getbalance() < satoshi_round((amount + fee)/COIN): node.generate(100) - #print (node.getbalance(), amount, fee) new_addr = node.getnewaddress() - #print new_addr txid = node.sendtoaddress(new_addr, satoshi_round((amount+fee)/COIN)) tx1 = node.getrawtransaction(txid, 1) txid = int(txid, 16) i = None for i, txout in enumerate(tx1['vout']): - #print i, txout['scriptPubKey']['addresses'] if txout['scriptPubKey']['addresses'] == [new_addr]: - #print i break assert i is not None @@ -72,7 +68,7 @@ class ReplaceByFeeTest(BitcoinTestFramework): def setup_network(self): self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-maxorphantx=1000", "-debug", + self.nodes.append(start_node(0, self.options.tmpdir, ["-maxorphantx=1000", "-whitelist=127.0.0.1", "-limitancestorcount=50", "-limitancestorsize=101", @@ -84,34 +80,34 @@ class ReplaceByFeeTest(BitcoinTestFramework): def run_test(self): make_utxo(self.nodes[0], 1*COIN) - print("Running test simple doublespend...") + self.log.info("Running test simple doublespend...") self.test_simple_doublespend() - print("Running test doublespend chain...") + self.log.info("Running test doublespend chain...") self.test_doublespend_chain() - print("Running test doublespend tree...") + self.log.info("Running test doublespend tree...") self.test_doublespend_tree() - print("Running test replacement feeperkb...") + self.log.info("Running test replacement feeperkb...") self.test_replacement_feeperkb() - print("Running test spends of conflicting outputs...") + self.log.info("Running test spends of conflicting outputs...") self.test_spends_of_conflicting_outputs() - print("Running test new unconfirmed inputs...") + self.log.info("Running test new unconfirmed inputs...") self.test_new_unconfirmed_inputs() - print("Running test too many replacements...") + self.log.info("Running test too many replacements...") self.test_too_many_replacements() - print("Running test opt-in...") + self.log.info("Running test opt-in...") self.test_opt_in() - print("Running test prioritised transactions...") + self.log.info("Running test prioritised transactions...") self.test_prioritised_transactions() - print("Passed\n") + self.log.info("Passed") def test_simple_doublespend(self): """Simple doublespend""" @@ -460,7 +456,7 @@ class ReplaceByFeeTest(BitcoinTestFramework): except JSONRPCException as exp: assert_equal(exp.error['code'], -26) else: - print(tx1b_txid) + self.log.info(tx1b_txid) assert(False) tx1_outpoint = make_utxo(self.nodes[0], int(1.1*COIN)) diff --git a/qa/rpc-tests/rest.py b/qa/rpc-tests/rest.py index 9ca1cc187a..776211d301 100755 --- a/qa/rpc-tests/rest.py +++ b/qa/rpc-tests/rest.py @@ -58,7 +58,7 @@ class RESTTest (BitcoinTestFramework): 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 index 499fe33679..220bf4ddd0 100755 --- a/qa/rpc-tests/rpcbind_test.py +++ b/qa/rpc-tests/rpcbind_test.py @@ -61,7 +61,7 @@ class RPCBindTest(BitcoinTestFramework): break 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/segwit.py b/qa/rpc-tests/segwit.py index 761c00dc01..f480e5c3f9 100755 --- a/qa/rpc-tests/segwit.py +++ b/qa/rpc-tests/segwit.py @@ -82,9 +82,9 @@ class SegWitTest(BitcoinTestFramework): def setup_network(self): self.nodes = [] - self.nodes.append(start_node(0, self.options.tmpdir, ["-logtimemicros", "-debug", "-walletprematurewitness", "-rpcserialversion=0"])) - self.nodes.append(start_node(1, self.options.tmpdir, ["-logtimemicros", "-debug", "-blockversion=4", "-promiscuousmempoolflags=517", "-prematurewitness", "-walletprematurewitness", "-rpcserialversion=1"])) - self.nodes.append(start_node(2, self.options.tmpdir, ["-logtimemicros", "-debug", "-blockversion=536870915", "-promiscuousmempoolflags=517", "-prematurewitness", "-walletprematurewitness"])) + self.nodes.append(start_node(0, self.options.tmpdir, ["-walletprematurewitness", "-rpcserialversion=0"])) + self.nodes.append(start_node(1, self.options.tmpdir, ["-blockversion=4", "-promiscuousmempoolflags=517", "-prematurewitness", "-walletprematurewitness", "-rpcserialversion=1"])) + self.nodes.append(start_node(2, self.options.tmpdir, ["-blockversion=536870915", "-promiscuousmempoolflags=517", "-prematurewitness", "-walletprematurewitness"])) connect_nodes(self.nodes[1], 0) connect_nodes(self.nodes[2], 1) connect_nodes(self.nodes[0], 2) @@ -124,7 +124,7 @@ class SegWitTest(BitcoinTestFramework): def run_test(self): self.nodes[0].generate(161) #block 161 - print("Verify sigops are counted in GBT with pre-BIP141 rules before the fork") + self.log.info("Verify sigops are counted in GBT with pre-BIP141 rules before the fork") txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1) tmpl = self.nodes[0].getblocktemplate({}) assert(tmpl['sizelimit'] == 1000000) @@ -173,7 +173,7 @@ class SegWitTest(BitcoinTestFramework): self.nodes[0].generate(260) #block 423 sync_blocks(self.nodes) - print("Verify default node can't accept any witness format txs before fork") + self.log.info("Verify default node can't accept any witness format txs before fork") # unsigned, no scriptsig self.fail_accept(self.nodes[0], wit_ids[NODE_0][WIT_V0][0], False) self.fail_accept(self.nodes[0], wit_ids[NODE_0][WIT_V1][0], False) @@ -188,7 +188,7 @@ class SegWitTest(BitcoinTestFramework): self.fail_accept(self.nodes[0], p2sh_ids[NODE_0][WIT_V0][0], True) self.fail_accept(self.nodes[0], p2sh_ids[NODE_0][WIT_V1][0], True) - print("Verify witness txs are skipped for mining before the fork") + self.log.info("Verify witness txs are skipped for mining before the fork") self.skip_mine(self.nodes[2], wit_ids[NODE_2][WIT_V0][0], True) #block 424 self.skip_mine(self.nodes[2], wit_ids[NODE_2][WIT_V1][0], True) #block 425 self.skip_mine(self.nodes[2], p2sh_ids[NODE_2][WIT_V0][0], True) #block 426 @@ -196,19 +196,19 @@ class SegWitTest(BitcoinTestFramework): # TODO: An old node would see these txs without witnesses and be able to mine them - print("Verify unsigned bare witness txs in versionbits-setting blocks are valid before the fork") + self.log.info("Verify unsigned bare witness txs in versionbits-setting blocks are valid before the fork") self.success_mine(self.nodes[2], wit_ids[NODE_2][WIT_V0][1], False) #block 428 self.success_mine(self.nodes[2], wit_ids[NODE_2][WIT_V1][1], False) #block 429 - print("Verify unsigned p2sh witness txs without a redeem script are invalid") + self.log.info("Verify unsigned p2sh witness txs without a redeem script are invalid") self.fail_accept(self.nodes[2], p2sh_ids[NODE_2][WIT_V0][1], False) self.fail_accept(self.nodes[2], p2sh_ids[NODE_2][WIT_V1][1], False) - print("Verify unsigned p2sh witness txs with a redeem script in versionbits-settings blocks are valid before the fork") + self.log.info("Verify unsigned p2sh witness txs with a redeem script in versionbits-settings blocks are valid before the fork") self.success_mine(self.nodes[2], p2sh_ids[NODE_2][WIT_V0][1], False, addlength(witness_script(0, self.pubkey[2]))) #block 430 self.success_mine(self.nodes[2], p2sh_ids[NODE_2][WIT_V1][1], False, addlength(witness_script(1, self.pubkey[2]))) #block 431 - print("Verify previous witness txs skipped for mining can now be mined") + self.log.info("Verify previous witness txs skipped for mining can now be mined") assert_equal(len(self.nodes[2].getrawmempool()), 4) block = self.nodes[2].generate(1) #block 432 (first block with new rules; 432 = 144 * 3) sync_blocks(self.nodes) @@ -216,7 +216,7 @@ class SegWitTest(BitcoinTestFramework): segwit_tx_list = self.nodes[2].getblock(block[0])["tx"] assert_equal(len(segwit_tx_list), 5) - print("Verify block and transaction serialization rpcs return differing serializations depending on rpc serialization flag") + self.log.info("Verify block and transaction serialization rpcs return differing serializations depending on rpc serialization flag") assert(self.nodes[2].getblock(block[0], False) != self.nodes[0].getblock(block[0], False)) assert(self.nodes[1].getblock(block[0], False) == self.nodes[2].getblock(block[0], False)) for i in range(len(segwit_tx_list)): @@ -227,19 +227,19 @@ class SegWitTest(BitcoinTestFramework): assert(self.nodes[1].getrawtransaction(segwit_tx_list[i]) == self.nodes[2].gettransaction(segwit_tx_list[i])["hex"]) assert(self.nodes[0].getrawtransaction(segwit_tx_list[i]) == bytes_to_hex_str(tx.serialize_without_witness())) - print("Verify witness txs without witness data are invalid after the fork") + self.log.info("Verify witness txs without witness data are invalid after the fork") self.fail_mine(self.nodes[2], wit_ids[NODE_2][WIT_V0][2], False) self.fail_mine(self.nodes[2], wit_ids[NODE_2][WIT_V1][2], False) self.fail_mine(self.nodes[2], p2sh_ids[NODE_2][WIT_V0][2], False, addlength(witness_script(0, self.pubkey[2]))) self.fail_mine(self.nodes[2], p2sh_ids[NODE_2][WIT_V1][2], False, addlength(witness_script(1, self.pubkey[2]))) - print("Verify default node can now use witness txs") + self.log.info("Verify default node can now use witness txs") self.success_mine(self.nodes[0], wit_ids[NODE_0][WIT_V0][0], True) #block 432 self.success_mine(self.nodes[0], wit_ids[NODE_0][WIT_V1][0], True) #block 433 self.success_mine(self.nodes[0], p2sh_ids[NODE_0][WIT_V0][0], True) #block 434 self.success_mine(self.nodes[0], p2sh_ids[NODE_0][WIT_V1][0], True) #block 435 - print("Verify sigops are counted in GBT with BIP141 rules after the fork") + self.log.info("Verify sigops are counted in GBT with BIP141 rules after the fork") txid = self.nodes[0].sendtoaddress(self.nodes[0].getnewaddress(), 1) tmpl = self.nodes[0].getblocktemplate({'rules':['segwit']}) assert(tmpl['sizelimit'] >= 3999577) # actual maximum size is lower due to minimum mandatory non-witness data @@ -248,11 +248,11 @@ class SegWitTest(BitcoinTestFramework): assert(tmpl['transactions'][0]['txid'] == txid) assert(tmpl['transactions'][0]['sigops'] == 8) - print("Non-segwit miners are not able to use GBT response after activation.") + self.log.info("Non-segwit miners are not able to use GBT response after activation.") send_to_witness(1, self.nodes[0], find_unspent(self.nodes[0], 50), self.pubkey[0], False, Decimal("49.998")) assert_raises_jsonrpc(-8, "Support for 'segwit' rule requires explicit client support", self.nodes[0].getblocktemplate, {}) - print("Verify behaviour of importaddress, addwitnessaddress and listunspent") + self.log.info("Verify behaviour of importaddress, addwitnessaddress and listunspent") # Some public keys to be used later pubkeys = [ diff --git a/qa/rpc-tests/sendheaders.py b/qa/rpc-tests/sendheaders.py index 16ca4a4913..de7f5e0849 100755 --- a/qa/rpc-tests/sendheaders.py +++ b/qa/rpc-tests/sendheaders.py @@ -229,7 +229,7 @@ class SendHeadersTest(BitcoinTestFramework): 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 @@ -283,7 +283,7 @@ class SendHeadersTest(BitcoinTestFramework): # 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) @@ -314,8 +314,8 @@ class SendHeadersTest(BitcoinTestFramework): inv_node.clear_last_announcement() test_node.clear_last_announcement() - print("Part 1: success!") - print("Part 2: announce blocks with headers after sendheaders message...") + 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 # commence and keep working. @@ -376,9 +376,9 @@ class SendHeadersTest(BitcoinTestFramework): height += 1 block_time += 1 - print("Part 2: success!") + self.log.info("Part 2: success!") - print("Part 3: headers announcements can stop after large reorg, and resume after headers/inv from peer...") + 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 # getheaders or inv from peer. @@ -440,9 +440,9 @@ class SendHeadersTest(BitcoinTestFramework): assert_equal(inv_node.check_last_announcement(inv=[tip]), True) 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(self.nodes[0].getbestblockhash())['time'] @@ -523,12 +523,12 @@ class SendHeadersTest(BitcoinTestFramework): 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): @@ -595,7 +595,7 @@ class SendHeadersTest(BitcoinTestFramework): 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 index 9ce5b8e865..f7d692083c 100755 --- a/qa/rpc-tests/smartfees.py +++ b/qa/rpc-tests/smartfees.py @@ -99,7 +99,7 @@ def check_estimates(node, fees_seen, max_invalid, print_estimates = True): """ 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]]) + self.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]: @@ -159,8 +159,8 @@ class EstimateFeeTest(BitcoinTestFramework): self.nodes.append(start_node(0, self.options.tmpdir, ["-maxorphantx=1000", "-whitelist=127.0.0.1"])) - print("This test is time consuming, please be patient") - print("Splitting inputs so we can generate tx's") + self.log.info("This test is time consuming, please be patient") + self.log.info("Splitting inputs so we can generate tx's") self.txouts = [] self.txouts2 = [] # Split a coinbase into two transaction puzzle outputs @@ -185,7 +185,7 @@ class EstimateFeeTest(BitcoinTestFramework): 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 @@ -193,8 +193,7 @@ class EstimateFeeTest(BitcoinTestFramework): # NOTE: the CreateNewBlock code starts counting block size at 1,000 bytes, # (17k is room enough for 110 or so transactions) self.nodes.append(start_node(1, self.options.tmpdir, - ["-blockmaxsize=17000", - "-maxorphantx=1000", "-debug=estimatefee"])) + ["-blockmaxsize=17000", "-maxorphantx=1000"])) connect_nodes(self.nodes[1], 0) # Node2 is a stingy miner, that @@ -238,15 +237,15 @@ class EstimateFeeTest(BitcoinTestFramework): 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("Creating transactions and mining them with a block size that can't keep up") + 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("Creating transactions and mining them at a block size that is just big enough") + 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 transactions are being created self.transact_and_mine(10, self.nodes[1]) @@ -257,7 +256,7 @@ class EstimateFeeTest(BitcoinTestFramework): 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 index 5280d18cdc..4cfd682bb5 100644 --- a/qa/rpc-tests/test_framework/blockstore.py +++ b/qa/rpc-tests/test_framework/blockstore.py @@ -8,6 +8,8 @@ from .mininode import * from io import BytesIO import dbm.dumb as dbmd +logger = logging.getLogger("TestFramework.blockstore") + class BlockStore(object): """BlockStore helper class. @@ -86,7 +88,7 @@ class BlockStore(object): 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) @@ -156,7 +158,7 @@ class TxStore(object): 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 = [] diff --git a/qa/rpc-tests/test_framework/comptool.py b/qa/rpc-tests/test_framework/comptool.py index b617895cac..70d1d700ef 100755 --- a/qa/rpc-tests/test_framework/comptool.py +++ b/qa/rpc-tests/test_framework/comptool.py @@ -21,6 +21,10 @@ from .mininode import * from .blockstore import BlockStore, TxStore from .util import p2p_port +import logging + +logger=logging.getLogger("TestFramework.comptool") + global mininode_lock class RejectResult(object): @@ -209,7 +213,6 @@ class TestManager(object): # --> 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 @@ -231,7 +234,6 @@ class TestManager(object): # --> 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 @@ -258,13 +260,12 @@ class TestManager(object): 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 @@ -280,19 +281,17 @@ class TestManager(object): 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 @@ -402,7 +401,7 @@ class TestManager(object): if (not self.check_mempool(tx.sha256, tx_outcome)): 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 index b2292f6477..aace17a043 100755 --- a/qa/rpc-tests/test_framework/mininode.py +++ b/qa/rpc-tests/test_framework/mininode.py @@ -51,6 +51,8 @@ NODE_GETUTXO = (1 << 1) NODE_BLOOM = (1 << 2) NODE_WITNESS = (1 << 3) +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) @@ -1502,8 +1504,7 @@ class NodeConnCB(object): try: 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: @@ -1615,7 +1616,6 @@ class NodeConn(asyncore.dispatcher): 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) @@ -1640,8 +1640,7 @@ class NodeConn(asyncore.dispatcher): 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)) @@ -1649,18 +1648,14 @@ class NodeConn(asyncore.dispatcher): 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: %s:%d" % (self.dstaddr, self.dstport)) 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"" @@ -1742,17 +1737,14 @@ class NodeConn(asyncore.dispatcher): t.deserialize(f) self.got_message(t) else: - 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))) 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] @@ -1774,7 +1766,7 @@ class NodeConn(asyncore.dispatcher): 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 index c5e9c6a658..d7072fa78d 100755 --- a/qa/rpc-tests/test_framework/test_framework.py +++ b/qa/rpc-tests/test_framework/test_framework.py @@ -42,7 +42,7 @@ class BitcoinTestFramework(object): 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: @@ -112,6 +112,8 @@ class BitcoinTestFramework(object): help="Directory for caching pregenerated datadirs") 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") parser.add_option("--portseed", dest="port_seed", default=os.getpid(), type='int', @@ -124,9 +126,6 @@ class BitcoinTestFramework(object): # backup dir variable for removal at cleanup 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) @@ -136,41 +135,41 @@ class BitcoinTestFramework(object): 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. @@ -182,12 +181,39 @@ class BitcoinTestFramework(object): 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: @@ -213,6 +239,6 @@ class ComparisonTestFramework(BitcoinTestFramework): 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 index ba56fddd77..23ac324510 100644 --- a/qa/rpc-tests/test_framework/util.py +++ b/qa/rpc-tests/test_framework/util.py @@ -19,12 +19,15 @@ import tempfile import time import re import errno +import logging from . import coverage from .authproxy import AuthServiceProxy, JSONRPCException 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 @@ -237,6 +240,7 @@ def initialize_chain(test_dir, num_nodes, cachedir): 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): @@ -250,11 +254,9 @@ def initialize_chain(test_dir, num_nodes, cachedir): 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("initialize_chain: bitcoind started, waiting for RPC to come up") 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): @@ -313,15 +315,13 @@ def start_node(i, dirname, extra_args=None, rpchost=None, timewait=None, binary= datadir = os.path.join(dirname, "node"+str(i)) if binary is None: binary = os.getenv("BITCOIND", "bitcoind") - args = [ binary, "-datadir="+datadir, "-server", "-keypool=1", "-discover=0", "-rest", "-mocktime="+str(get_mocktime()) ] + args = [ binary, "-datadir="+datadir, "-server", "-keypool=1", "-discover=0", "-rest", "-logtimemicros", "-debug", "-mocktime="+str(get_mocktime()) ] if extra_args is not None: args.extend(extra_args) bitcoind_processes[i] = subprocess.Popen(args, stderr=stderr) - 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: @@ -367,10 +367,11 @@ def log_filename(dirname, n_node, logname): return os.path.join(dirname, "node"+str(n_node), "regtest", logname) 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) del bitcoind_processes[i] diff --git a/qa/rpc-tests/wallet-hd.py b/qa/rpc-tests/wallet-hd.py index 1dcfe5300f..c40662dc3d 100755 --- a/qa/rpc-tests/wallet-hd.py +++ b/qa/rpc-tests/wallet-hd.py @@ -68,7 +68,7 @@ class WalletHDTest(BitcoinTestFramework): 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(tmpdir + "/hd.bak", tmpdir + "/node1/regtest/wallet.dat") diff --git a/qa/rpc-tests/wallet.py b/qa/rpc-tests/wallet.py index ddeac657e5..00fe37563b 100755 --- a/qa/rpc-tests/wallet.py +++ b/qa/rpc-tests/wallet.py @@ -35,7 +35,7 @@ class WalletTest (BitcoinTestFramework): 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) @@ -332,7 +332,7 @@ class WalletTest (BitcoinTestFramework): ] 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, [[m, "-limitancestorcount="+str(chainlimit)]] * 3) diff --git a/qa/rpc-tests/walletbackup.py b/qa/rpc-tests/walletbackup.py index ea249096cf..af1718572f 100755 --- a/qa/rpc-tests/walletbackup.py +++ b/qa/rpc-tests/walletbackup.py @@ -34,8 +34,6 @@ and confirm again balances are correct. 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): @@ -100,7 +98,7 @@ class WalletBackupTest(BitcoinTestFramework): 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) @@ -115,12 +113,12 @@ class WalletBackupTest(BitcoinTestFramework): 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") @@ -129,7 +127,7 @@ class WalletBackupTest(BitcoinTestFramework): 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() @@ -150,7 +148,7 @@ class WalletBackupTest(BitcoinTestFramework): ## # 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() @@ -163,7 +161,7 @@ class WalletBackupTest(BitcoinTestFramework): shutil.copyfile(tmpdir + "/node1/wallet.bak", tmpdir + "/node1/regtest/wallet.dat") 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) @@ -171,7 +169,7 @@ class WalletBackupTest(BitcoinTestFramework): 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 index 9597d05f3a..ce446e44a3 100755 --- a/qa/rpc-tests/zapwallettxes.py +++ b/qa/rpc-tests/zapwallettxes.py @@ -32,7 +32,7 @@ class ZapWalletTXesTest (BitcoinTestFramework): 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 index 1e2f06bd54..e6f18b0b93 100755 --- a/qa/rpc-tests/zmq_test.py +++ b/qa/rpc-tests/zmq_test.py @@ -36,7 +36,7 @@ class ZMQTest (BitcoinTestFramework): 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") |