test: fix rpc_setban.py race #16656

jonasschnelli commented at 3:33 PM on August 19, 2019: contributor

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

jonasschnelli added the label Tests on Aug 19, 2019

MarcoFalke commented at 3:48 PM on August 19, 2019: member

I'd rather do this without a sleep. Wouldn't creating a dummy connection and waiting for it to open synchronize as well?

jonasschnelli commented at 4:01 PM on August 19, 2019: contributor

Maybe the better way would be to add a timeout to assert_debug_log and check every second until the timeout is hit

emilengler commented at 4:10 PM on August 19, 2019: contributor

2 seconds are too much in my opinion. I don't know the CI performance but I would go for 0.5 seconds

MarcoFalke commented at 4:18 PM on August 19, 2019: member

Maybe the better way would be to add a timeout to assert_debug_log and check every second until the timeout is hit

I am fine with either. Though, I suggest to set the default timeout for assert_debug_log to 0, as all existing calls to it are already synchronized.

jonasschnelli force-pushed on Aug 20, 2019

jonasschnelli commented at 9:03 AM on August 20, 2019: contributor

Switch to a retry/timeout approach with no delay for existing calls.

DrahtBot commented at 12:14 PM on August 20, 2019: member

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#16673 (Relog configuration args on debug.log rotation by LarryRuane)
#16365 (Log RPC parameters (arguments) if -debug=rpcparams by LarryRuane)
#16115 (On bitcoind startup, write config args to debug.log by LarryRuane)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

jonasschnelli force-pushed on Aug 20, 2019

emilengler commented at 2:26 PM on August 20, 2019: contributor

0.05 seconds are definitely better. Concept ACK 6bdd6a0 Haven't tested it but the Travis linter is screaming around, you should check that out.

in test/functional/test_framework/test_node.py:332 in 6bdd6a0053 outdated

 341 | +                    if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
 342 | +                        found = False
 343 | +            if found:
 344 | +                return
 345 | +            if time.time() >= time_end:
 346 | +                break;

MarcoFalke commented at 2:34 PM on August 20, 2019:

test/functional/test_framework/test_node.py:332:22: E703 statement ends with a semicolon

in test/functional/test_framework/test_node.py:318 in 6bdd6a0053 outdated

 327 | -            print_log = " - " + "\n - ".join(log.splitlines())
 328 | -            for expected_msg in expected_msgs:
 329 | -                if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
 330 | -                    self._raise_assertion_error('Expected message "{}" does not partially match log:\n\n{}\n\n'.format(expected_msg, print_log))
 331 | +                dl.seek(0, 2)
 332 | +                prev_size = dl.tell()

MarcoFalke commented at 2:36 PM on August 20, 2019:

It looks like you are resetting prev_size in a loop, thus introducing another race where we just miss the debug log lines between .read() and .tell(), no?

jonasschnelli force-pushed on Aug 20, 2019

in test/functional/test_framework/test_node.py:320 in 62923111ab outdated

 329 | -                if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
 330 | -                    self._raise_assertion_error('Expected message "{}" does not partially match log:\n\n{}\n\n'.format(expected_msg, print_log))
 331 | +                dl.seek(0, 2)
 332 | +                prev_size = dl.tell()
 333 | +            try:
 334 | +                yield

NicolasDorier commented at 2:42 PM on August 20, 2019:

I don't understand this.

NicolasDorier commented at 2:45 PM on August 20, 2019:

Actually nevermind this was already there before. (Also I understand now, this is continuing when going out of the with block. Sweet.)

NicolasDorier commented at 2:45 PM on August 20, 2019: contributor

Sorry about that. Concept ACK, ~just I don't understand the yield part in the try block.~

NicolasDorier commented at 2:48 PM on August 20, 2019: contributor

@jonasschnelli the while true and the break conditions must be inside the finally block if the problem is that the log just comes too late.

jonasschnelli commented at 3:27 PM on August 20, 2019: contributor

the while true and the break conditions must be inside the finally block if the problem is that the log just comes too late.

Why? I guess we can get a fresh file position as well...

NicolasDorier commented at 3:39 PM on August 20, 2019: contributor

@jonasschnelli no you don't.

What you want to say is:

Open the log at position prev_size (before try/finally)
Do stuff (yield) the "stuff" is what is inside the with block of the caller.
Starting from prev_size, until the pattern is found in the log, read the rest of logs (finally),
repeat 3 until found or timeout

prev_size should not change at all from the time when the with block get open.

jonasschnelli commented at 4:17 PM on August 20, 2019: contributor

@NicolasDorier Oh. I see your point now. My understanding of pythons yield was incorrect. Will fix...

NicolasDorier commented at 4:28 PM on August 20, 2019: contributor

just discovered it myself. I wonder why we don't have this in C#... will complain to Microsoft. :p

fanquake renamed this:
~~QA: fix rpc_setban.py race~~
test: fix rpc_setban.py race
on Aug 21, 2019

jonasschnelli force-pushed on Aug 21, 2019

jonasschnelli commented at 10:27 AM on August 21, 2019: contributor

Fixed @NicolasDorier's point.

in test/functional/test_framework/test_node.py:327 in c3ce574131 outdated

 331 | +                    dl.seek(prev_size)
 332 | +                    log = dl.read()
 333 | +                print_log = " - " + "\n - ".join(log.splitlines())
 334 | +                for expected_msg in expected_msgs:
 335 | +                    if re.search(re.escape(expected_msg), log, flags=re.MULTILINE) is None:
 336 | +                        found = False

MarcoFalke commented at 11:01 AM on August 21, 2019:

How is this supposed to work?

found is latched to False and never set to True, so this will never succeed and always time out (unless it passed on the first try)

I think you can just use wait_until, so that you don't have to reinvent the wheel

jonasschnelli commented at 12:07 PM on August 21, 2019:

Argh. Right. Moved the found = True back into the loop. Fixed.

I'm happy if someone wants to further optimize this.

jonasschnelli force-pushed on Aug 21, 2019

in test/functional/test_framework/test_node.py:312 in cd4a90383f outdated

 306 | @@ -307,21 +307,31 @@ def wait_until_stopped(self, timeout=BITCOIND_PROC_WAIT_TIMEOUT):
 307 |          wait_until(self.is_node_stopped, timeout=timeout)
 308 |  
 309 |      @contextlib.contextmanager
 310 | -    def assert_debug_log(self, expected_msgs):
 311 | +    def assert_debug_log(self, expected_msgs, timeout=2):
 312 | +        time_end = time.time() + timeout
 313 | +        print_log = ""

MarcoFalke commented at 12:15 PM on August 21, 2019:

no need for this. python doesn't have scope blocks

jonasschnelli commented at 12:18 PM on August 21, 2019:

Fixed

in test/functional/test_framework/test_node.py:334 in cd4a90383f outdated

 337 | +                if found:
 338 | +                    return
 339 | +                if time.time() >= time_end:
 340 | +                    break
 341 | +                time.sleep(0.05)
 342 | +            self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msg), print_log))

MarcoFalke commented at 12:16 PM on August 21, 2019:

This will print only the last message

jonasschnelli commented at 12:18 PM on August 21, 2019:

Fixed

QA: fix rpc_setban.py race 6011c9d72d

jonasschnelli force-pushed on Aug 21, 2019

MarcoFalke referenced this in commit 6dfa9efa3f on Aug 21, 2019

MarcoFalke merged this on Aug 21, 2019

MarcoFalke closed this on Aug 21, 2019

NicolasDorier commented at 1:48 PM on August 21, 2019: contributor

ACK

deadalnix referenced this in commit cbe72ee6f9 on May 2, 2020

ftrader referenced this in commit 417258880d on Aug 17, 2020

vijaydasmp referenced this in commit 0ed2a8eb56 on Nov 17, 2021

vijaydasmp referenced this in commit b5831a4bd1 on Nov 21, 2021

vijaydasmp referenced this in commit 62af7fbfa1 on Nov 21, 2021

vijaydasmp referenced this in commit 31be7ebade on Nov 22, 2021

vijaydasmp referenced this in commit 0841836441 on Nov 25, 2021

MarcoFalke locked this on Dec 16, 2021