Skip to content

Commit

Permalink
Fix rare timing-related failures in dsproof functional tests
Browse files Browse the repository at this point in the history
Summary
---

As described in issue Bitcoin-ABC#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=<str>`. If this kwarg is specified, then
the test will proceed as normal without raising an exception, should
`<std>` match the expected `JSONRPCException` message.

Closes issue Bitcoin-ABC#291.

Test Plan
---

- `ninja all check check-functional`

OPTIONAL:

- Try and reproduce the failures described in Bitcoin-ABC#291 on master. Then try this
  MR and see it no longer fail.
  - May require a similar setup to Bitcoin-ABC#291.
  - A "poor man's hack" for reproducing Bitcoin-ABC#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.
  • Loading branch information
cculianu committed Apr 18, 2021
1 parent 9ea057b commit 4f1cc47
Show file tree
Hide file tree
Showing 3 changed files with 37 additions and 13 deletions.
15 changes: 7 additions & 8 deletions test/functional/bchn-feature-doublespend-proof.py
Expand Up @@ -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,
Expand Down Expand Up @@ -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(
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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,
Expand All @@ -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,
Expand Down Expand Up @@ -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')
Expand Down
12 changes: 8 additions & 4 deletions test/functional/bchn-rpc-dsproof.py
Expand Up @@ -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)
Expand All @@ -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
Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -353,7 +358,6 @@ def check(len_noorphans, len_orphans):
timeout=90
)


def run_test(self):
self.basic_check()
self.paths_check()
Expand Down
23 changes: 22 additions & 1 deletion test/functional/test_framework/test_node.py
Expand Up @@ -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:
Expand All @@ -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=<str>` where <str> 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()

Expand Down

0 comments on commit 4f1cc47

Please sign in to comment.