Merge #16656: test: fix rpc_setban.py race

6011c9d72d QA: fix rpc_setban.py race (Jonas Schnelli)

Pull request description:

  The new `rpc_setban.py` test failes regularly on CIs due to a race between injecting the ban and testing the log "on the other side".

  The problem is, that the test immediately after the `addnode` command on node0 checks for the `dropped (banned)` entry on node1 (without giving some time).

  Adding a 2 seconds sleep seems to solve the race (I guess there is no better event-driven delay).

  Example of a failed test: https://bitcoinbuilds.org/index.php?ansilog=bf743910-103f-4b54-9a97-960c471061bd.log#l2906

Top commit has no ACKs.

Tree-SHA512: 680f8ea3e5ddb07e93f824f1aeff4a459e25e6c14715a39fc7670e50506d7cf25925348672c5c2d8ba3e1243ccf5effbc2456bcd094fb96868349f8d26e008f1
This commit is contained in:
MarcoFalke 2019-08-21 08:21:54 -04:00
commit 6dfa9efa3f
No known key found for this signature in database
GPG key ID: D2EA4850E7528B25
2 changed files with 18 additions and 9 deletions

View file

@ -26,7 +26,7 @@ class SetBanTests(BitcoinTestFramework):
self.nodes[1].setban("127.0.0.1", "add") self.nodes[1].setban("127.0.0.1", "add")
# Node 0 should not be able to reconnect # Node 0 should not be able to reconnect
with self.nodes[1].assert_debug_log(expected_msgs=['dropped (banned)\n']): with self.nodes[1].assert_debug_log(expected_msgs=['dropped (banned)\n'],timeout=5):
self.restart_node(1, []) self.restart_node(1, [])
self.nodes[0].addnode("127.0.0.1:" + str(p2p_port(1)), "onetry") self.nodes[0].addnode("127.0.0.1:" + str(p2p_port(1)), "onetry")

View file

@ -307,7 +307,8 @@ class TestNode():
wait_until(self.is_node_stopped, timeout=timeout) wait_until(self.is_node_stopped, timeout=timeout)
@contextlib.contextmanager @contextlib.contextmanager
def assert_debug_log(self, expected_msgs): def assert_debug_log(self, expected_msgs, timeout=2):
time_end = time.time() + timeout
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)
@ -315,13 +316,21 @@ class TestNode():
try: try:
yield yield
finally: finally:
while True:
found = True
with open(debug_log, encoding='utf-8') as dl: with open(debug_log, encoding='utf-8') as dl:
dl.seek(prev_size) dl.seek(prev_size)
log = dl.read() log = dl.read()
print_log = " - " + "\n - ".join(log.splitlines()) print_log = " - " + "\n - ".join(log.splitlines())
for expected_msg in expected_msgs: for expected_msg in expected_msgs:
if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None: if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
self._raise_assertion_error('Expected message "{}" does not partially match log:\n\n{}\n\n'.format(expected_msg, print_log)) found = False
if found:
return
if time.time() >= time_end:
break
time.sleep(0.05)
self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
@contextlib.contextmanager @contextlib.contextmanager
def assert_memory_usage_stable(self, *, increase_allowed=0.03): def assert_memory_usage_stable(self, *, increase_allowed=0.03):