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

MarcoFalke commented at 9:30 am on July 28, 2021: 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.

MarcoFalke force-pushed on Jul 28, 2021

fanquake added the label Tests on Jul 28, 2021

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

This is exactly identical functionality like #20362 (comment), but implemented differently.

Here the sync happens in the test framework, which makes the diff larger. In the other pull the sync happens in the test node.

DrahtBot commented at 10:02 am on July 28, 2021: 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:

#23371 (test: MiniWallet: add P2TR support and use it per default by theStack)
#23365 (index: Fix backwards search for bestblock by mzumsande)
#23127 (tests: Use test framework utils where possible by vincenzopalazzo)
#23075 (refactoring: Fee estimation functional test cleanups by darosior)
#22364 (wallet: Make a tr() descriptor by default [DO NOT MERGE UNTIL TAPROOT ACTIVATES] by achow101)
#21726 (Improve Indices on pruned nodes via prune blockers by fjahr)
#21283 (Implement BIP 370 PSBTv2 by achow101)
#19461 (multiprocess: Add bitcoin-gui -ipcconnect option by ryanofsky)
#19460 (multiprocess: Add bitcoin-wallet -ipcconnect option by ryanofsky)
#10102 (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.

MarcoFalke force-pushed on Jul 28, 2021

DrahtBot added the label Needs rebase on Jul 28, 2021

MarcoFalke force-pushed on Jul 28, 2021

DrahtBot removed the label Needs rebase on Jul 28, 2021

practicalswift commented at 9:05 am on July 29, 2021: contributor

Strong Concept ACK

Intermittent test failures are the worst!

rajarshimaitra commented at 3:15 pm on July 29, 2021: contributor

Strong concept ACK.

But I am getting certain failures when I am running all the tests together with test/function/test_runner.py -j 10.

I am not sure if that’s something to do with this PR or it’s some issue at my end.

They are also happening in master.
Failed tests are passing when I run them independently.

Failure summary :

 0wallet_watchonly.py --legacy-wallet                | ✓ Passed  | 22 s
 1wallet_watchonly.py --usecli --legacy-wallet       | ✓ Passed  | 25 s
 2feature_backwards_compatibility.py --descriptors   | ○ Skipped | 0 s
 3feature_backwards_compatibility.py --legacy-wallet | ○ Skipped | 0 s
 4feature_taproot.py --previous_release              | ○ Skipped | 0 s
 5mempool_compatibility.py                           | ○ Skipped | 0 s
 6wallet_upgradewallet.py --legacy-wallet            | ○ Skipped | 0 s
 7feature_coinstatsindex.py                          | ✖ Failed  | 68 s
 8feature_config_args.py                             | ✖ Failed  | 28 s
 9rpc_invalidateblock.py                             | ✖ Failed  | 63 s
10wallet_backup.py --legacy-wallet                   | ✖ Failed  | 317 s
11wallet_dump.py --legacy-wallet                     | ✖ Failed  | 168 s

One sample failure log:

 0202/215 - feature_config_args.py failed, Duration: 28 s
 1
 2stdout:
 32021-07-29T13:11:46.329000Z TestFramework (INFO): Initializing test directory /tmp/test_runner_₿_🏃_20210729_182102/feature_config_args_9
 42021-07-29T13:12:00.419000Z TestFramework (INFO): Test config args logging
 52021-07-29T13:12:02.455000Z TestFramework (INFO): Test seed peers
 62021-07-29T13:12:12.318000Z TestFramework (ERROR): Assertion failed
 7Traceback (most recent call last):
 8  File "/home/raj/github-repo/mybitcoin/bitcoin/test/functional/test_framework/test_framework.py", line 128, in main
 9    self.run_test()
10  File "/home/raj/github-repo/mybitcoin/bitcoin/test/functional/feature_config_args.py", line 221, in run_test
11    self.test_seed_peers()
12  File "/home/raj/github-repo/mybitcoin/bitcoin/test/functional/feature_config_args.py", line 186, in test_seed_peers
13    self.start_node(0, extra_args=['-dnsseed=0', '-fixedseeds=1'])
14  File "/usr/lib/python3.8/contextlib.py", line 120, in __exit__
15    next(self.gen)
16  File "/home/raj/github-repo/mybitcoin/bitcoin/test/functional/test_framework/test_node.py", line 408, in assert_debug_log
17    self._raise_assertion_error('Expected messages "{}" does not partially match log:\n\n{}\n\n'.format(str(expected_msgs), print_log))
18  File "/home/raj/github-repo/mybitcoin/bitcoin/test/functional/test_framework/test_node.py", line 166, in _raise_assertion_error
19    raise AssertionError(self._node_msg(msg))
20AssertionError: [node 0] Expected messages "['Loaded 0 addresses from peers.dat', 'DNS seeding disabled', 'Adding fixed seeds as -dnsseed=0, -addnode is not provided and all -seednode(s) attempted\n']" does not partially match log:

tryphe commented at 4:08 am on July 30, 2021: contributor

Concept ACK

Is it correct to say the tests will be more upfront in catching syncing issues because, other than being race-free, the syncing happens within the test framework? Versus #20362. Just trying to understand the tradeoffs here despite the bigger diff.

Either way, I’m all in favor to merging this one ASAP to avoid an impending avalanche of conflicting PRs :)

MarcoFalke commented at 10:07 am on July 30, 2021: member

I am not sure if that’s something to do with this PR or it’s some issue at my end. They are also happening in master. Failed tests are passing when I run them independently.

If the tests also fail on master, then it can’t be due to this PR. You can file an issue and hope it makes someone fix the issue or fix the issue yourself.

Is it correct to say the tests will be more upfront in catching syncing issues because, other than being race-free, the syncing happens within the test framework? Versus #20362.

As explained in the first comment (https://github.com/bitcoin/bitcoin/pull/22567#issuecomment-888162973), the two are supposed to be functionally identical.

DrahtBot added the label Needs rebase on Jul 30, 2021

jonatack commented at 11:02 am on July 30, 2021: member

Concept ACK

theStack commented at 2:14 pm on July 30, 2021: member

Concept ACK

MarcoFalke force-pushed on Jul 31, 2021

DrahtBot removed the label Needs rebase on Jul 31, 2021

MarcoFalke force-pushed on Jul 31, 2021

DrahtBot added the label Needs rebase on Aug 18, 2021

MarcoFalke force-pushed on Aug 19, 2021

DrahtBot removed the label Needs rebase on Aug 19, 2021

MarcoFalke force-pushed on Aug 19, 2021

in test/functional/test_framework/test_node.py:304 in e2ca558a45 outdated

301+    def generate(self, nblocks, maxtries=1000000, **kwargs):
302         self.log.debug("TestNode.generate() dispatches `generate` call to `generatetoaddress`")
303-        return self.generatetoaddress(nblocks=nblocks, address=self.get_deterministic_priv_key().address, maxtries=maxtries)
304+        return self.generatetoaddress(nblocks=nblocks, address=self.get_deterministic_priv_key().address, maxtries=maxtries, **kwargs)
305+
306+    def generateblock(self, *args, invalid_call, **kwargs):

jnewbery commented at 3:14 pm on August 19, 2021:

This invalid_call argument seems a little bit hand-holdy. We’re all adults here - can we just leave a comment saying don’t call this from the individual tests?

MarcoFalke commented at 11:49 am on October 6, 2021:

I don’t think leaving a comment is enough. How do you ensure everyone reads the comment? Let’s continue the discussion in #23207 , though.

MarcoFalke marked this as a draft on Aug 19, 2021

MarcoFalke force-pushed on Aug 19, 2021

fanquake referenced this in commit eb09c26724 on Aug 24, 2021

MarcoFalke force-pushed on Aug 24, 2021

MarcoFalke commented at 9:48 am on August 24, 2021: member

Note to myself about the follow-up: #22741 (review) and commit fac7f6102feb1eb1c47ea8cb1c75c4f4dbf2f6b0

jonatack commented at 3:39 pm on September 4, 2021: member

Maybe name the sync_fun param simply sync; it seems just as clear (people will see what type of values are passed) and is shorter.

Looks like two tests needed updated copyrights; scripted-diff check fails in the last commit 09fbdc3085520c6:

 0$ test/lint/commit-script-check.sh f4e12fd..09fbdc3
 1
 2diff --git a/test/functional/rpc_signmessagewithprivkey.py b/test/functional/rpc_signmessagewithprivkey.py
 3index 27aee44d25..80555eab75 100755
 4--- a/test/functional/rpc_signmessagewithprivkey.py
 5+++ b/test/functional/rpc_signmessagewithprivkey.py
 6@@ -1,5 +1,5 @@
 7 #!/usr/bin/env python3
 8-# Copyright (c) 2016-2020 The Bitcoin Core developers
 9+# Copyright (c) 2016-2021 The Bitcoin Core developers
10 # Distributed under the MIT software license, see the accompanying
11 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
12 """Test RPC commands for signing messages with private key."""
13diff --git a/test/functional/wallet_signmessagewithaddress.py b/test/functional/wallet_signmessagewithaddress.py
14index bf6f95e3f1..74a8f2eef2 100755
15--- a/test/functional/wallet_signmessagewithaddress.py
16+++ b/test/functional/wallet_signmessagewithaddress.py
17@@ -1,5 +1,5 @@
18 #!/usr/bin/env python3
19-# Copyright (c) 2016-2019 The Bitcoin Core developers
20+# Copyright (c) 2016-2021 The Bitcoin Core developers
21 # Distributed under the MIT software license, see the accompanying
22 # file COPYING or http://www.opensource.org/licenses/mit-license.php.
23 """Test Wallet commands for signing and verifying messages."""
24Failed

MarcoFalke referenced this in commit a5d00d4baf on Sep 9, 2021

MarcoFalke force-pushed on Sep 9, 2021

MarcoFalke force-pushed on Oct 6, 2021

MarcoFalke referenced this in commit 2e82af46e2 on Oct 18, 2021

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

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-

ffff4ad894

test: Use 4 spaces for indentation fa745430e0

scripted-diff: Bump copyright headers

The previous diff touched most files in ./test/, so bump the headers to
avoid having to touch them again for a bump later.

-BEGIN VERIFY SCRIPT-
./contrib/devtools/copyright_header.py update ./test/
-END VERIFY SCRIPT-

fad9d451f1

MarcoFalke force-pushed on Oct 18, 2021

sidhujag referenced this in commit 0037d0a390 on Oct 18, 2021

MarcoFalke referenced this in commit 94db963de5 on Nov 9, 2021

MarcoFalke marked this as ready for review on Nov 9, 2021

MarcoFalke closed this on Nov 9, 2021

MarcoFalke deleted the branch on Nov 9, 2021

MarcoFalke restored the branch on Nov 9, 2021

MarcoFalke commented at 9:47 am on November 9, 2021: member

I’ve archived the discussion here and created a follow-up for the remaining (scripted-diff) changes: #23474

Maybe name the sync_fun param simply sync; it seems just as clear (people will see what type of values are passed) and is shorter.

Sounds acceptable. Should I add a scripted-diff for that to the other pull?

DrahtBot locked this on Nov 9, 2022

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

Conflicts