Skip to content

Commit

Permalink
test: feature_init: retain debug.log and improve detection
Browse files Browse the repository at this point in the history
This test sporadically fails due to the Python test missing log lines
for reasons that are poorly understood. The problem is made worse by the
fact that this test does not retain the log files from iteration to
iteration.

Change the test to do logline detection in a more robust manner (by
using `re.search` on the whole log content) in a way that is comparable
to the existing `assert_debug_log` utility, and retain all debug.log
content from case to case.
  • Loading branch information
jamesob authored and mzumsande committed Jan 17, 2022
1 parent d43cef3 commit cfa7297
Showing 1 changed file with 9 additions and 28 deletions.
37 changes: 9 additions & 28 deletions test/functional/feature_init.py
Original file line number Diff line number Diff line change
Expand Up @@ -44,8 +44,6 @@ def run_test(self):
def sigterm_node():
node.process.terminate()
node.process.wait()
node.debug_log_path.unlink()
node.debug_log_path.touch()

def check_clean_start():
"""Ensure that node restarts successfully after various interrupts."""
Expand All @@ -71,7 +69,7 @@ def check_clean_start():
'net thread start',
'addcon thread start',
'loadblk thread start',
# TODO: reenable - see above TODO
# TODO: re-enable - see above TODO
# 'txindex thread start',
'msghand thread start'
]
Expand All @@ -84,39 +82,21 @@ def check_clean_start():
# TODO: add -txindex=1 to fully test index initiatlization.
# extra_args=['-txindex=1'],
)
logfile = open(node.debug_log_path, 'r', encoding='utf8')

MAX_SECS_TO_WAIT = 30
start = time.time()
num_lines = 0

while True:
line = logfile.readline()
if line:
num_lines += 1

if line and terminate_line.lower() in line.lower():
self.log.debug(f"Terminating node after {num_lines} log lines seen")
sigterm_node()
break

if (time.time() - start) > MAX_SECS_TO_WAIT:
raise AssertionError(
f"missed line {terminate_line}; terminating now after {num_lines} lines")

if node.process.poll() is not None:
raise AssertionError(f"node failed to start (line: '{terminate_line}')")
num_total_logs = node.wait_for_debug_log([terminate_line], ignore_case=True)
self.log.debug(f"Terminating node after {num_total_logs} log lines seen")
sigterm_node()

check_clean_start()
num_total_logs = len(node.debug_log_path.read_text().splitlines())
self.stop_node(0)

self.log.info(
f"Terminate at some random point in the init process (max logs: {num_total_logs})")

for _ in range(40):
terminate_after = random.randint(1, num_total_logs)
self.log.debug(f"Starting node and will exit after {terminate_after} lines")
num_logs = len(Path(node.debug_log_path).read_text().splitlines())
additional_lines = random.randint(1, num_total_logs)
self.log.debug(f"Starting node and will exit after {additional_lines} lines")
node.start(
# TODO: add -txindex=1 to fully test index initiatlization.
# extra_args=['-txindex=1'],
Expand All @@ -132,7 +112,8 @@ def check_clean_start():
if line:
num_lines += 1

if num_lines >= terminate_after or (time.time() - start) > MAX_SECS_TO_WAIT:
if num_lines >= (num_logs + additional_lines) or \
(time.time() - start) > MAX_SECS_TO_WAIT:
self.log.debug(f"Terminating node after {num_lines} log lines seen")
sigterm_node()
break
Expand Down

0 comments on commit cfa7297

Please sign in to comment.