test: Implicitly sync after generate* to preempt races and intermittent test failures

MarcoFalke commented at 2:39 pm on November 10, 2020: member

The most frequent failure in functional tests are intermittent races. Fixing such bugs is cumbersome because it involves:

Noticing the failure
Fetching and reading the log to determine the test case that failed
Adding a self.sync_all() where it was forgotten
Spamming out a pr and waiting for review, which is already sparse

Also, writing a linter to catch those is not possible, nor is review effective in finding these bugs prior to merge.

Fix all future intermittent races caused by a missing sync_block call by calling sync_all implicitly after each generate*, unless opted out. This ensures that the code is race-free (with regards to blocks) when the tests pass once, instead of our current approach where the code can never be guaranteed to be race-free.

DrahtBot commented at 3:43 pm on November 10, 2020: 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:

#22567 (test: Implicitly sync after generate* to preempt races and intermittent test failures by MarcoFalke)
#22437 (test, refactor: add GetTransaction() coverage, improve rpc_rawtransaction by jonatack)
#22364 (wallet: Make a tr() descriptor by default by achow101)
#22229 (test: consolidate to f-strings (part 1) by fanquake)
#21283 (Implement BIP 370 PSBTv2 by achow101)
#10102 ([experimental] Multiprocess bitcoin by ryanofsky)

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.

practicalswift commented at 3:53 pm on November 10, 2020: contributor

Concept ACK: thanks for doing this - intermittent test failures are the worst!

Bike shed nit: fn or func might be more unambiguous (but less fun) abbreviations than fun :)

DrahtBot added the label Tests on Nov 10, 2020

MarcoFalke force-pushed on Nov 10, 2020

MarcoFalke force-pushed on Nov 12, 2020

in test/functional/test_framework/test_node.py:303 in faf4ef6b4b outdated

295@@ -296,9 +296,27 @@ def wait_for_cookie_credentials(self):
296             time.sleep(1.0 / poll_per_s)
297         self._raise_assertion_error("Unable to retrieve cookie credentials after {}s".format(self.rpc_timeout))
298 
299-    def generate(self, nblocks, maxtries=1000000):
300+    def generateblock(self, *args, sync_fun=True, **kwargs):

promag commented at 10:44 am on November 14, 2020:

faf4ef6b4bd8955ff5a9b714bc17b179a80a8b75

An alternative to “overload” these generate* is to add a generic _rpc_dispatch_and_sync (__getattr__ -> _rpc_dispatch_and_sync -> _rpc_dispatch).

It would be cool to keep the last generate* extract_stack that when a related error occurs we could print it.

MarcoFalke commented at 7:35 am on November 15, 2020:

That would make calling code tremendously verbose, no?

MarcoFalke commented at 6:36 am on June 23, 2021:

Maybe I am misunderstanding. Do you have a working diff that I can steal?

in test/functional/test_framework/test_framework.py:459 in fa014d2ce4 outdated

455@@ -456,6 +456,7 @@ def get_bin_from_version(version, bin_name, bin_default):
456         assert_equal(len(binary_cli), num_nodes)
457         for i in range(num_nodes):
458             test_node_i = TestNode(
459+                self,

promag commented at 10:49 am on November 14, 2020:

fa014d2ce4b37f04cdecf8f318cb0cf98f30c050

An alternative to avoid this circular dependency is to refactor as self.generate(nodes[1], 1) or self.generate(1, 1) , similarly to self.start_node(0).

MarcoFalke commented at 7:34 am on November 15, 2020:

I didn’t do that because self.generate(1, 1) looks unreadable. Enforcing named args makes everything verbose.

promag commented at 12:45 pm on December 4, 2020:

Agree, you can resolve this.

promag commented at 10:26 pm on December 4, 2020:

See 8f8df56949e5e6558ff7b38bea51fee7acbcc129 where self.sync_all is passed to TestNode instead of self.

promag commented at 11:00 am on November 14, 2020: member

Concept ACK.

How about for now:

0try_dispatch_with_sync
1    try
2        dispatch
3    except
4        sync_all
5        dispatch
6        log with print_stack

amitiuttarwar commented at 6:34 pm on November 15, 2020: contributor

Concept ACK!

very nice, thank you

DrahtBot added the label Needs rebase on Nov 16, 2020

MarcoFalke force-pushed on Nov 16, 2020

DrahtBot removed the label Needs rebase on Nov 16, 2020

DrahtBot added the label Needs rebase on Nov 17, 2020

MarcoFalke force-pushed on Nov 17, 2020

DrahtBot removed the label Needs rebase on Nov 17, 2020

laanwj commented at 3:55 am on November 20, 2020: member

Concept ACK, rooting out a cause of intermittent issues (due to test flakiness) is great.

DrahtBot added the label Needs rebase on Nov 25, 2020

MarcoFalke force-pushed on Nov 25, 2020

DrahtBot removed the label Needs rebase on Nov 25, 2020

laanwj added this to the "Blockers" column in a project

jonasschnelli commented at 8:31 am on December 7, 2020: contributor

Nice! utACK faeef7a61307b99654a445dffe05b4aed561639d

DrahtBot added the label Needs rebase on Dec 10, 2020

MarcoFalke force-pushed on Dec 10, 2020

MarcoFalke commented at 9:31 am on December 10, 2020: member

Rebased. Should be trivial to re-ACK

DrahtBot removed the label Needs rebase on Dec 10, 2020

MarcoFalke force-pushed on Dec 10, 2020

in test/functional/test_framework/test_node.py:72 in fa43c23234 outdated

69         Kwargs:
70             start_perf (bool): If True, begin profiling the node with `perf` as soon as
71                 the node starts.
72         """
73 
74+        self.framework = framework

sipa commented at 9:37 pm on December 18, 2020:

It seems a bit ugly to have this bidirectional reference between the framework and the test nodes. Would it be sufficient to instead pass and store a lambda “sync function”?

MarcoFalke commented at 9:44 am on December 19, 2020:

Thanks, done

MarcoFalke force-pushed on Dec 19, 2020

MarcoFalke removed this from the "Blockers" column in a project

DrahtBot added the label Needs rebase on Feb 5, 2021

jonatack commented at 4:58 pm on March 12, 2021: member

Code review ACK, needs rebase.

MarcoFalke force-pushed on Jun 23, 2021

DrahtBot removed the label Needs rebase on Jun 23, 2021

MarcoFalke force-pushed on Jun 23, 2021

MarcoFalke commented at 7:30 am on June 23, 2021: member

Rebased. Should be trivial to re-ACK, as most conflicts were in the scripted diff.

DrahtBot added the label Needs rebase on Jun 24, 2021

MarcoFalke force-pushed on Jun 24, 2021

DrahtBot removed the label Needs rebase on Jun 24, 2021

MarcoFalke force-pushed on Jul 7, 2021

MarcoFalke force-pushed on Jul 14, 2021

MarcoFalke force-pushed on Jul 21, 2021

DrahtBot added the label Needs rebase on Jul 22, 2021

MarcoFalke force-pushed on Jul 23, 2021

DrahtBot removed the label Needs rebase on Jul 23, 2021

jnewbery commented at 2:00 pm on July 23, 2021: member

Concept ACK

jnewbery commented at 12:40 pm on July 26, 2021: member

What do you think about adding a generate() method to TestFramework that takes the index of the node that you want to generate on? It seems strange to pass a TestFramework function to the constructor of the TestNode.

MarcoFalke commented at 1:01 pm on July 26, 2021: member

That would require changing all calls to generate* and also disable TestNode::generate* to avoid races creeping in by accident. Happy to do that refactor if reviewers think it is worth it. I am mostly interested in the functional changes here.

jnewbery commented at 3:39 pm on July 26, 2021: member

Happy to do that refactor if reviewers think it is worth it.

I think it’s worth it, to avoid adding an implicit dependency from TestNode onto TestFramework.

MarcoFalke commented at 9:32 am on July 28, 2021: member

Done in #22567. (Different pr, because the discussion here wasn’t substantial, mostly GitHubs own spam, and I wanted to keep this version in case someone decides against #22567).

DrahtBot added the label Needs rebase on Jul 28, 2021

test: Pass default_sync_fun to TestNode constructor fa891ebded

test: Create TestNode._rpc_dispatch method fac2235c5b

test: Implicitly sync after generate*, unless opted out faa93599e1

scripted-diff: Remove redundant sync_all

-BEGIN VERIFY SCRIPT-
perl -0777 -pi -e 's/(generate[^\n]*\)[^\n]*)(\n|\s)+self.sync_.*\(\)\n/\1\n/g' $(git grep -l generate ./test)
-END VERIFY SCRIPT-

fa77478d56

MarcoFalke force-pushed on Jul 28, 2021

DrahtBot removed the label Needs rebase on Jul 28, 2021

DrahtBot added the label Needs rebase on Aug 18, 2021

DrahtBot commented at 9:00 pm on August 18, 2021: member

🐙 This pull request conflicts with the target branch and needs rebase.

Want to unsubscribe from rebase notifications on this pull request? Just convert this pull request to a “draft”.

MarcoFalke closed this on Aug 19, 2021

MarcoFalke deleted the branch on Aug 19, 2021

DrahtBot locked this on Aug 19, 2022

test: Implicitly sync after generate* to preempt races and intermittent test failures #20362

Conflicts