From 4f1cc4788227b5f655b736d19c7b34ca1f72a1e7 Mon Sep 17 00:00:00 2001 From: Calin Culianu Date: Sat, 17 Apr 2021 23:53:30 -0400 Subject: [PATCH] Fix rare timing-related failures in dsproof functional tests Summary --- As described in issue #291, these tests sometimes fail when they shouldn't. The errors turn out to be timing-related. It's possible for e.g. node0 to send the `firstDSTx` to node1 via the p2p network before we can issue the `secondDSTx` to node1 ourselves from the Python side via RPC. When this happens -- the test would throw a `JSONRPCException` for `txn-mempool-conflict`. The fix is to allow for this rare timing-related event and just catch the exception and proceed. In either case (no exception or exception), a dsproof will be generated (which is what we are testing for in this test). In order to implement the fix we extended the `TestNode` interface in the python test framework with a new method, `call_rpc` which takes an optional kwarg `ignore_error=`. If this kwarg is specified, then the test will proceed as normal without raising an exception, should `` match the expected `JSONRPCException` message. Closes issue #291. Test Plan --- - `ninja all check check-functional` OPTIONAL: - Try and reproduce the failures described in #291 on master. Then try this MR and see it no longer fail. - May require a similar setup to #291. - A "poor man's hack" for reproducing #291 on a non-slow machine would be to add `time.sleep(1)` calls in the bchn-feature-doublespend-proof test manually after `firstDSTx` is sent but before `secondDSTx` is sent (on master). Then, try the same with this MR in the same places and see it never fail. --- .../bchn-feature-doublespend-proof.py | 15 ++++++------ test/functional/bchn-rpc-dsproof.py | 12 ++++++---- test/functional/test_framework/test_node.py | 23 ++++++++++++++++++- 3 files changed, 37 insertions(+), 13 deletions(-) diff --git a/test/functional/bchn-feature-doublespend-proof.py b/test/functional/bchn-feature-doublespend-proof.py index 63ced6e478..b6ebec464c 100755 --- a/test/functional/bchn-feature-doublespend-proof.py +++ b/test/functional/bchn-feature-doublespend-proof.py @@ -87,7 +87,7 @@ def run_test(self): # Submit to two different nodes, because a node would simply reject # a double spend submitted through RPC firstDSTxId = self.nodes[0].sendrawtransaction(firstDSTx) - self.nodes[1].sendrawtransaction(secondDSTx) + self.nodes[1].call_rpc('sendrawtransaction', secondDSTx, ignore_error='txn-mempool-conflict') wait_until( lambda: dspReceiver.message_count["dsproof-beta"] == 1, lock=mininode_lock, @@ -130,7 +130,7 @@ def run_test(self): # IE if a valid proof is known, no new proofs will be constructed # We submit a _triple_ spend transaction to the third node connect_nodes(self.nodes[0], self.nodes[2]) - self.nodes[2].sendrawtransaction(thirdDSTx) + self.nodes[2].call_rpc('sendrawtransaction', thirdDSTx, ignore_error='txn-mempool-conflict') # Await for a new dsp to be relayed to the node # if such a dsp (or the double or triple spending tx) arrives, the test fails assert_raises( @@ -159,7 +159,7 @@ def run_test(self): secondDSTx = create_tx_with_script(tx, 0, b'', int(49.90 * COIN), CScript([OP_FALSE])) self.nodes[0].sendrawtransaction(ToHex(firstDSTx)) - self.nodes[1].sendrawtransaction(ToHex(secondDSTx)) + self.nodes[1].call_rpc('sendrawtransaction', ToHex(secondDSTx), ignore_error='txn-mempool-conflict') assert_raises( AssertionError, @@ -178,7 +178,7 @@ def run_test(self): secondDSTx = create_raw_transaction(self.nodes[0], unconfirmedtx, self.nodes[0].getnewaddress(), 24.9) self.nodes[0].sendrawtransaction(firstDSTx) - self.nodes[1].sendrawtransaction(secondDSTx) + self.nodes[1].call_rpc('sendrawtransaction', secondDSTx, ignore_error='txn-mempool-conflict') wait_until( lambda: dspReceiver.message_count["dsproof-beta"] == 2, @@ -217,7 +217,7 @@ def run_test(self): firstDSTx = create_raw_transaction(self.nodes[0], txid1, self.nodes[0].getnewaddress(), 48.9, vout1) secondDSTx = create_raw_transaction(self.nodes[0], txid1, self.nodes[1].getnewaddress(), 48.9, vout1) self.nodes[0].sendrawtransaction(firstDSTx) - self.nodes[1].sendrawtransaction(secondDSTx) + self.nodes[1].call_rpc('sendrawtransaction', secondDSTx, ignore_error='txn-mempool-conflict') # We still get a dsproof, showing that not all ancestors have # to be P2PKH. @@ -258,7 +258,7 @@ def run_test(self): firstDSTx = create_raw_transaction(self.nodes[1], txid, self.nodes[0].getnewaddress(), 49.98, vout2) secondDSTx = create_raw_transaction(self.nodes[1], txid, self.nodes[1].getnewaddress(), 49.98, vout2) self.nodes[0].sendrawtransaction(firstDSTx) - self.nodes[1].sendrawtransaction(secondDSTx) + self.nodes[1].call_rpc('sendrawtransaction', secondDSTx, ignore_error='txn-mempool-conflict') # We get a dsproof. wait_until( lambda: dspReceiver.message_count["dsproof-beta"] == 4, @@ -282,7 +282,7 @@ def run_test(self): firstDSTx = create_raw_transaction(self.nodes[0], fundingtxid, self.nodes[0].getnewaddress(), 48.9, vout) secondDSTx = create_raw_transaction(self.nodes[0], fundingtxid, self.nodes[1].getnewaddress(), 48.9, vout) self.nodes[0].sendrawtransaction(firstDSTx) - self.nodes[1].sendrawtransaction(secondDSTx) + self.nodes[1].call_rpc('sendrawtransaction', secondDSTx, ignore_error='txn-mempool-conflict') # No dsproof is generated. assert_raises( AssertionError, @@ -323,7 +323,6 @@ def run_test(self): timeout=5 ) - # Finally, ensure that the non-dsproof node has the messages we expect in its log # (this checks that dsproof was disabled for this node) debug_log = os.path.join(non_dsproof_node.datadir, 'regtest', 'debug.log') diff --git a/test/functional/bchn-rpc-dsproof.py b/test/functional/bchn-rpc-dsproof.py index e6b47d8f3f..8c6d5b209f 100644 --- a/test/functional/bchn-rpc-dsproof.py +++ b/test/functional/bchn-rpc-dsproof.py @@ -38,7 +38,7 @@ def basic_check(self): second_ds_tx = create_raw_transaction(self.nodes[0], funding_txid, self.nodes[0].getnewaddress(), 49.95) first_ds_tx_id = self.nodes[0].sendrawtransaction(first_ds_tx) - second_ds_tx_id = self.nodes[1].sendrawtransaction(second_ds_tx) + second_ds_tx_id = self.nodes[1].call_rpc('sendrawtransaction', second_ds_tx, ignore_error='txn-mempool-conflict') vout = find_output(self.nodes[0], first_ds_tx_id, Decimal('49.95')) child = create_raw_transaction(self.nodes[0], first_ds_tx_id, self.nodes[0].getnewaddress(), 49.90, vout) @@ -63,7 +63,12 @@ def basic_check(self): dsp_node1 = self.nodes[1].getdsproof(dsplist[0]) # each node has the same dsproof, but associated with the txid it sees in mempool assert_equal(dsp["txid"], first_ds_tx_id) - assert_equal(dsp_node1["txid"], second_ds_tx_id) + if second_ds_tx_id is not None: + # common case where node1 saw the RPC tx2 before the p2p tx1 + assert_equal(dsp_node1["txid"], second_ds_tx_id) + else: + # node1 happened to see the first tx via p2p first + assert_equal(dsp_node1["txid"], first_ds_tx_id) # we expect this dsp tx to invalidate 3 tx's total (parent, child, and grandchild) assert_equal(len(dsp["descendants"]), 3) # Check that the dsp has the "outpoint" key and it is what we expect @@ -166,7 +171,7 @@ def paths_check(self): self.nodes[0].getnewaddress(), 49.97, 0) transaction_2outputs_id = self.nodes[0].sendrawtransaction(transaction_2_outputs) - self.nodes[1].sendrawtransaction(doublespendingtransaction) + self.nodes[1].call_rpc('sendrawtransaction', doublespendingtransaction, ignore_error='txn-mempool-conflict') paths[0].insert(0, transaction_2outputs_id) # root of both possible paths paths[1].insert(0, transaction_2outputs_id) @@ -353,7 +358,6 @@ def check(len_noorphans, len_orphans): timeout=90 ) - def run_test(self): self.basic_check() self.paths_check() diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py index 3ef1840542..c1802953c6 100755 --- a/test/functional/test_framework/test_node.py +++ b/test/functional/test_framework/test_node.py @@ -163,7 +163,11 @@ def __del__(self): self.process.kill() def __getattr__(self, name): - """Dispatches any unrecognised messages to the RPC connection or a CLI instance.""" + """Dispatches any unrecognised method name to the RPC connection or a CLI instance.""" + return self._get_rpc_or_cli_method(name) + + def _get_rpc_or_cli_method(self, name): + """Returns the CLI or RPC connection method 'name'.""" if self.use_cli: return getattr(self.cli, name) else: @@ -173,6 +177,23 @@ def __getattr__(self, name): "Error: No RPC connection") return getattr(self.rpc, name) + def call_rpc(self, name: str, *args, **kwargs): + """Wrapper for any rpc or cli call that optionally accepts the kwarg + `ignore_error=` where is some error message substring we + tolerate as a JSONRPCException. If no exception is raised or if no + `ignore_error` kwarg is present, returns the result of calling rpc + `name`. If `ignore_error` is specified and there is a matching + exception message, returns None. This wrapper was originally designed + to facilitate dsproof tests.""" + ignore_error = kwargs.pop('ignore_error', None) + try: + return self._get_rpc_or_cli_method(name)(*args, **kwargs) + except JSONRPCException as exc: + if ignore_error is None or ignore_error not in str(exc): + raise exc + self.log.info("call_rpc: Ignoring exception from '{}': {}".format(name, repr(exc))) + return None + def clear_default_args(self): self.default_args.clear()