Merge #18617: test: add factor option to adjust test timeouts

2742c34286 test: add factor option to adjust test timeouts (Harris)

Pull request description:

  This PR adds a new option **factor** that can be used to adjust timeouts in various functional tests.
  Several timeouts and functions from `authproxy`, `mininode`, `test_node` and `util` have been adapted to use this option. The factor-option definition is located in `test_framework.py`.

  Fixes https://github.com/bitcoin/bitcoin/issues/18266
  Also Fixes https://github.com/bitcoin/bitcoin/issues/18834

ACKs for top commit:
  MarcoFalke:
    Thanks! ACK 2742c34286

Tree-SHA512: 6d8421933ba2ac1b7db00b70cf2bc242d9842c48121c11aadc30b0985c4a174c86a127d6402d0cd73b993559d60d4f747872d21f9510cf4806e008349780d3ef
This commit is contained in:
MarcoFalke 2020-05-03 08:58:48 -04:00
commit ddc0a600b3
No known key found for this signature in database
GPG key ID: CE2B75697E69A548
5 changed files with 30 additions and 20 deletions

View file

@ -13,7 +13,7 @@ export NO_DEPENDS=1
if [[ "${TRAVIS}" == "true" && "${TRAVIS_REPO_SLUG}" != "bitcoin/bitcoin" ]]; then if [[ "${TRAVIS}" == "true" && "${TRAVIS_REPO_SLUG}" != "bitcoin/bitcoin" ]]; then
export TEST_RUNNER_EXTRA="wallet_disable" # Only run wallet_disable as a smoke test to not hit the 50 min travis time limit export TEST_RUNNER_EXTRA="wallet_disable" # Only run wallet_disable as a smoke test to not hit the 50 min travis time limit
else else
export TEST_RUNNER_EXTRA="--exclude rpc_bind" # Excluded for now, see https://github.com/bitcoin/bitcoin/issues/17765#issuecomment-602068547 export TEST_RUNNER_EXTRA="--exclude rpc_bind --factor=2" # Excluded for now, see https://github.com/bitcoin/bitcoin/issues/17765#issuecomment-602068547
fi fi
export GOAL="install" export GOAL="install"
export BITCOIN_CONFIG="--enable-zmq --with-incompatible-bdb --with-gui=no CC=clang CXX=clang++" # TODO enable GUI export BITCOIN_CONFIG="--enable-zmq --with-incompatible-bdb --with-gui=no CC=clang CXX=clang++" # TODO enable GUI

View file

@ -120,8 +120,9 @@ class P2PConnection(asyncio.Protocol):
def is_connected(self): def is_connected(self):
return self._transport is not None return self._transport is not None
def peer_connect(self, dstaddr, dstport, *, net): def peer_connect(self, dstaddr, dstport, *, net, factor):
assert not self.is_connected assert not self.is_connected
self.factor = factor
self.dstaddr = dstaddr self.dstaddr = dstaddr
self.dstport = dstport self.dstport = dstport
# The initial message to send after the connection was made: # The initial message to send after the connection was made:
@ -367,9 +368,12 @@ class P2PInterface(P2PConnection):
# Connection helper methods # Connection helper methods
def wait_until(self, test_function, timeout):
wait_until(test_function, timeout=timeout, lock=mininode_lock, factor=self.factor)
def wait_for_disconnect(self, timeout=60): def wait_for_disconnect(self, timeout=60):
test_function = lambda: not self.is_connected test_function = lambda: not self.is_connected
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
# Message receiving helper methods # Message receiving helper methods
@ -380,14 +384,14 @@ class P2PInterface(P2PConnection):
return False return False
return self.last_message['tx'].tx.rehash() == txid return self.last_message['tx'].tx.rehash() == txid
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
def wait_for_block(self, blockhash, timeout=60): def wait_for_block(self, blockhash, timeout=60):
def test_function(): def test_function():
assert self.is_connected assert self.is_connected
return self.last_message.get("block") and self.last_message["block"].block.rehash() == blockhash return self.last_message.get("block") and self.last_message["block"].block.rehash() == blockhash
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
def wait_for_header(self, blockhash, timeout=60): def wait_for_header(self, blockhash, timeout=60):
def test_function(): def test_function():
@ -397,7 +401,7 @@ class P2PInterface(P2PConnection):
return False return False
return last_headers.headers[0].rehash() == int(blockhash, 16) return last_headers.headers[0].rehash() == int(blockhash, 16)
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
def wait_for_merkleblock(self, blockhash, timeout=60): def wait_for_merkleblock(self, blockhash, timeout=60):
def test_function(): def test_function():
@ -407,7 +411,7 @@ class P2PInterface(P2PConnection):
return False return False
return last_filtered_block.merkleblock.header.rehash() == int(blockhash, 16) return last_filtered_block.merkleblock.header.rehash() == int(blockhash, 16)
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
def wait_for_getdata(self, hash_list, timeout=60): def wait_for_getdata(self, hash_list, timeout=60):
"""Waits for a getdata message. """Waits for a getdata message.
@ -421,7 +425,7 @@ class P2PInterface(P2PConnection):
return False return False
return [x.hash for x in last_data.inv] == hash_list return [x.hash for x in last_data.inv] == hash_list
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
def wait_for_getheaders(self, timeout=60): def wait_for_getheaders(self, timeout=60):
"""Waits for a getheaders message. """Waits for a getheaders message.
@ -435,7 +439,7 @@ class P2PInterface(P2PConnection):
assert self.is_connected assert self.is_connected
return self.last_message.get("getheaders") return self.last_message.get("getheaders")
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
def wait_for_inv(self, expected_inv, timeout=60): def wait_for_inv(self, expected_inv, timeout=60):
"""Waits for an INV message and checks that the first inv object in the message was as expected.""" """Waits for an INV message and checks that the first inv object in the message was as expected."""
@ -448,13 +452,13 @@ class P2PInterface(P2PConnection):
self.last_message["inv"].inv[0].type == expected_inv[0].type and \ self.last_message["inv"].inv[0].type == expected_inv[0].type and \
self.last_message["inv"].inv[0].hash == expected_inv[0].hash self.last_message["inv"].inv[0].hash == expected_inv[0].hash
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
def wait_for_verack(self, timeout=60): def wait_for_verack(self, timeout=60):
def test_function(): def test_function():
return self.message_count["verack"] return self.message_count["verack"]
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
# Message sending helper functions # Message sending helper functions
@ -470,7 +474,7 @@ class P2PInterface(P2PConnection):
assert self.is_connected assert self.is_connected
return self.last_message.get("pong") and self.last_message["pong"].nonce == self.ping_counter return self.last_message.get("pong") and self.last_message["pong"].nonce == self.ping_counter
wait_until(test_function, timeout=timeout, lock=mininode_lock) self.wait_until(test_function, timeout=timeout)
self.ping_counter += 1 self.ping_counter += 1
@ -586,7 +590,7 @@ class P2PDataStore(P2PInterface):
self.send_message(msg_block(block=b)) self.send_message(msg_block(block=b))
else: else:
self.send_message(msg_headers([CBlockHeader(block) for block in blocks])) self.send_message(msg_headers([CBlockHeader(block) for block in blocks]))
wait_until(lambda: blocks[-1].sha256 in self.getdata_requests, timeout=timeout, lock=mininode_lock) self.wait_until(lambda: blocks[-1].sha256 in self.getdata_requests, timeout=timeout)
if expect_disconnect: if expect_disconnect:
self.wait_for_disconnect(timeout=timeout) self.wait_for_disconnect(timeout=timeout)
@ -594,7 +598,7 @@ class P2PDataStore(P2PInterface):
self.sync_with_ping(timeout=timeout) self.sync_with_ping(timeout=timeout)
if success: if success:
wait_until(lambda: node.getbestblockhash() == blocks[-1].hash, timeout=timeout) self.wait_until(lambda: node.getbestblockhash() == blocks[-1].hash, timeout=timeout)
else: else:
assert node.getbestblockhash() != blocks[-1].hash assert node.getbestblockhash() != blocks[-1].hash

View file

@ -102,6 +102,7 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass):
self.bind_to_localhost_only = True self.bind_to_localhost_only = True
self.set_test_params() self.set_test_params()
self.parse_args() self.parse_args()
self.rpc_timeout = int(self.rpc_timeout * self.options.factor) # optionally, increase timeout by a factor
def main(self): def main(self):
"""Main function. This should not be overridden by the subclass test scripts.""" """Main function. This should not be overridden by the subclass test scripts."""
@ -168,6 +169,7 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass):
help="set a random seed for deterministically reproducing a previous test run") help="set a random seed for deterministically reproducing a previous test run")
parser.add_argument("--descriptors", default=False, action="store_true", parser.add_argument("--descriptors", default=False, action="store_true",
help="Run test using a descriptor wallet") help="Run test using a descriptor wallet")
parser.add_argument('--factor', type=float, default=1.0, help='adjust test timeouts by a factor')
self.add_options(parser) self.add_options(parser)
self.options = parser.parse_args() self.options = parser.parse_args()
@ -433,6 +435,7 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass):
chain=self.chain, chain=self.chain,
rpchost=rpchost, rpchost=rpchost,
timewait=self.rpc_timeout, timewait=self.rpc_timeout,
factor=self.options.factor,
bitcoind=binary[i], bitcoind=binary[i],
bitcoin_cli=binary_cli[i], bitcoin_cli=binary_cli[i],
version=versions[i], version=versions[i],
@ -579,6 +582,7 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass):
extra_args=['-disablewallet'], extra_args=['-disablewallet'],
rpchost=None, rpchost=None,
timewait=self.rpc_timeout, timewait=self.rpc_timeout,
factor=self.options.factor,
bitcoind=self.options.bitcoind, bitcoind=self.options.bitcoind,
bitcoin_cli=self.options.bitcoincli, bitcoin_cli=self.options.bitcoincli,
coverage_dir=None, coverage_dir=None,

View file

@ -62,7 +62,7 @@ class TestNode():
To make things easier for the test writer, any unrecognised messages will To make things easier for the test writer, any unrecognised messages will
be dispatched to the RPC connection.""" be dispatched to the RPC connection."""
def __init__(self, i, datadir, *, chain, rpchost, timewait, bitcoind, bitcoin_cli, coverage_dir, cwd, extra_conf=None, extra_args=None, use_cli=False, start_perf=False, use_valgrind=False, version=None, descriptors=False): def __init__(self, i, datadir, *, chain, rpchost, timewait, factor, bitcoind, bitcoin_cli, coverage_dir, cwd, extra_conf=None, extra_args=None, use_cli=False, start_perf=False, use_valgrind=False, version=None, descriptors=False):
""" """
Kwargs: Kwargs:
start_perf (bool): If True, begin profiling the node with `perf` as soon as start_perf (bool): If True, begin profiling the node with `perf` as soon as
@ -128,6 +128,7 @@ class TestNode():
self.perf_subprocesses = {} self.perf_subprocesses = {}
self.p2ps = [] self.p2ps = []
self.factor = factor
AddressKeyPair = collections.namedtuple('AddressKeyPair', ['address', 'key']) AddressKeyPair = collections.namedtuple('AddressKeyPair', ['address', 'key'])
PRIV_KEYS = [ PRIV_KEYS = [
@ -324,13 +325,13 @@ class TestNode():
return True return True
def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT): def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT):
wait_until(self.is_node_stopped, timeout=timeout) wait_until(self.is_node_stopped, timeout=timeout, factor=self.factor)
@contextlib.contextmanager @contextlib.contextmanager
def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2): def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2):
if unexpected_msgs is None: if unexpected_msgs is None:
unexpected_msgs = [] unexpected_msgs = []
time_end = time.time() + timeout time_end = time.time() + timeout * self.factor
debug_log = os.path.join(self.datadir, self.chain, 'debug.log') debug_log = os.path.join(self.datadir, self.chain, 'debug.log')
with open(debug_log, encoding='utf-8') as dl: with open(debug_log, encoding='utf-8') as dl:
dl.seek(0, 2) dl.seek(0, 2)
@ -487,7 +488,7 @@ class TestNode():
if 'dstaddr' not in kwargs: if 'dstaddr' not in kwargs:
kwargs['dstaddr'] = '127.0.0.1' kwargs['dstaddr'] = '127.0.0.1'
p2p_conn.peer_connect(**kwargs, net=self.chain)() p2p_conn.peer_connect(**kwargs, net=self.chain, factor=self.factor)()
self.p2ps.append(p2p_conn) self.p2ps.append(p2p_conn)
if wait_for_verack: if wait_for_verack:
# Wait for the node to send us the version and verack # Wait for the node to send us the version and verack

View file

@ -208,9 +208,10 @@ def str_to_b64str(string):
def satoshi_round(amount): def satoshi_round(amount):
return Decimal(amount).quantize(Decimal('0.00000001'), rounding=ROUND_DOWN) return Decimal(amount).quantize(Decimal('0.00000001'), rounding=ROUND_DOWN)
def wait_until(predicate, *, attempts=float('inf'), timeout=float('inf'), lock=None): def wait_until(predicate, *, attempts=float('inf'), timeout=float('inf'), lock=None, factor=1.0):
if attempts == float('inf') and timeout == float('inf'): if attempts == float('inf') and timeout == float('inf'):
timeout = 60 timeout = 60
timeout = timeout * factor
attempt = 0 attempt = 0
time_end = time.time() + timeout time_end = time.time() + timeout
@ -265,7 +266,7 @@ def get_rpc_proxy(url, node_number, *, timeout=None, coveragedir=None):
""" """
proxy_kwargs = {} proxy_kwargs = {}
if timeout is not None: if timeout is not None:
proxy_kwargs['timeout'] = timeout proxy_kwargs['timeout'] = int(timeout)
proxy = AuthServiceProxy(url, **proxy_kwargs) proxy = AuthServiceProxy(url, **proxy_kwargs)
proxy.url = url # store URL on proxy for info proxy.url = url # store URL on proxy for info