-
Notifications
You must be signed in to change notification settings - Fork 37.9k
qa: Improvements to debug_assert_log + busy_wait_for_debug_log #33423
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
Changes from all commits
5c16e46
a902110
1e54125
a1f7623
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
Original file line number | Diff line number | Diff line change |
---|---|---|
|
@@ -546,54 +546,54 @@ def assert_debug_log(self, expected_msgs, unexpected_msgs=None, timeout=2): | |
unexpected_msgs = [] | ||
assert_equal(type(expected_msgs), list) | ||
assert_equal(type(unexpected_msgs), list) | ||
remaining_expected = list(expected_msgs) | ||
|
||
time_end = time.time() + timeout * self.timeout_factor | ||
prev_size = self.debug_log_size(encoding="utf-8") # Must use same encoding that is used to read() below | ||
|
||
def join_log(log): | ||
return " - " + "\n - ".join(log.splitlines()) | ||
|
||
yield | ||
|
||
while True: | ||
found = True | ||
with open(self.debug_log_path, encoding="utf-8", errors="replace") as dl: | ||
dl.seek(prev_size) | ||
log = dl.read() | ||
print_log = " - " + "\n - ".join(log.splitlines()) | ||
for unexpected_msg in unexpected_msgs: | ||
if re.search(re.escape(unexpected_msg), log, flags=re.MULTILINE): | ||
self._raise_assertion_error('Unexpected message "{}" partially matches log:\n\n{}\n\n'.format(unexpected_msg, print_log)) | ||
for expected_msg in expected_msgs: | ||
if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None: | ||
found = False | ||
if found: | ||
if unexpected_msg in log: | ||
self._raise_assertion_error(f'Unexpected message "{unexpected_msg}" ' | ||
f'found in log:\n\n{join_log(log)}\n\n') | ||
while remaining_expected and remaining_expected[-1] in log: | ||
remaining_expected.pop() | ||
if not remaining_expected: | ||
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)) | ||
remaining_expected = [e for e in remaining_expected if e not in log] | ||
self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} ' | ||
f'not found in log:\n\n{join_log(log)}\n\n') | ||
Comment on lines
+575
to
+576
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. that's not necessarily true, we have just stopped searching after the first failure, right? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Thanks for noticing this issue! Latest push inserts remaining_expected = [e for e in remaining_expected if e not in log] before the error reporting for it to be correct, meaning we only need to do the full search on failure. |
||
|
||
@contextlib.contextmanager | ||
def busy_wait_for_debug_log(self, expected_msgs, timeout=60): | ||
hodlinator marked this conversation as resolved.
Show resolved
Hide resolved
|
||
""" | ||
Block until we see a particular debug log message fragment or until we exceed the timeout. | ||
Return: | ||
the number of log lines we encountered when matching | ||
""" | ||
time_end = time.time() + timeout * self.timeout_factor | ||
prev_size = self.debug_log_size(mode="rb") # Must use same mode that is used to read() below | ||
remaining_expected = list(expected_msgs) | ||
|
||
yield | ||
|
||
while True: | ||
found = True | ||
with open(self.debug_log_path, "rb") as dl: | ||
dl.seek(prev_size) | ||
log = dl.read() | ||
|
||
for expected_msg in expected_msgs: | ||
if expected_msg not in log: | ||
found = False | ||
|
||
if found: | ||
while remaining_expected and remaining_expected[-1] in log: | ||
remaining_expected.pop() | ||
if not remaining_expected: | ||
return | ||
|
||
if time.time() >= time_end: | ||
|
@@ -603,9 +603,9 @@ def busy_wait_for_debug_log(self, expected_msgs, timeout=60): | |
# No sleep here because we want to detect the message fragment as fast as | ||
# possible. | ||
|
||
self._raise_assertion_error( | ||
'Expected messages "{}" does not partially match log:\n\n{}\n\n'.format( | ||
str(expected_msgs), print_log)) | ||
remaining_expected = [e for e in remaining_expected if e not in log] | ||
self._raise_assertion_error(f'Expected message(s) {remaining_expected!s} ' | ||
f'not found in log:\n\n{print_log}\n\n') | ||
|
||
@contextlib.contextmanager | ||
def wait_for_new_peer(self, timeout=5): | ||
|
Uh oh!
There was an error while loading. Please reload this page.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Seems this was always eagerly evaluated since fa3e9f7#diff-7f22a082e3a80ca2f212e36193f87dd80237035afedb7f15b116ef7fa265f3eeR245-R248 - the current approach of only calculating it once when the loop also terminates makes sense
nit: I know it's a long line but I would still prefer this merged to reduce the noise. I'm fine either way:
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Regarding nit: I sympathize with the way
busy_wait_for_debug_log()
on master puts the parameter to_raise_assertion_error()
on it's own line, so I would be tempted to do that for all of them - which makes me realize: if only I broke the message in two lines, I could raise up the first half and still keep close to 80 char width - and we're back with the current approach. Left unchanged in latest push.