test: fix race condition in encrypted wallet rescan tests

ishaanam commented at 10:30 pm on March 4, 2023: contributor

This fixes #26347 (review)

DrahtBot commented at 1:14 am on March 5, 2023: contributor

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

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	MarcoFalke, achow101

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#22838 (descriptors: Be able to specify change and receiving in a single descriptor string by achow101)

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.

fanquake requested review from maflcko on Mar 5, 2023

fanquake commented at 9:43 am on March 5, 2023: member

Is this a draft because you haven’t tested under Valgrind yet? Could add to the PR description what needs doing.

fanquake commented at 9:47 pm on March 5, 2023: member

Worked for me under a recent Valgrind run.

ishaanam commented at 2:54 am on March 6, 2023: contributor

Is this a draft because you haven’t tested under Valgrind yet?

Yes, it was.

Worked for me under a recent Valgrind run.

Great, I will mark it as ready for review.

ishaanam marked this as ready for review on Mar 6, 2023

in test/functional/wallet_transactiontime_rescan.py:208 in a4278ad683 outdated

206-            batch.append(encrypted_wallet.rescanblockchain.get_request())
207+            t = threading.Thread(target=encrypted_wallet.rescanblockchain)
208+            t.start()
209 
210-            encrypted_wallet.batch(batch)
211+            minernode.cli('-rpcwallet="encrypted_wallet" walletlock')

maflcko commented at 9:12 am on March 6, 2023:

Any reason to use the cli, when the normal rpc can be used directly?

Also, I wonder if this introduces another race where the actual rescan in t.start() is scheduled after this call. Avoiding this race might be ugly, but I think it could be possible by using assert_debug_log with a timeout value to sync on the rescan actually starting?

ishaanam commented at 3:50 pm on March 6, 2023:

Any reason to use the cli, when the normal rpc can be used directly?

When I use the normal RPC directly, I get a CannotSendRequest error.

Also, I wonder if this introduces another race where the actual rescan in t.start() is scheduled after this call.

Yes, it does. I have used assert_debug_log with a timeout of 5 to fix this.

DrahtBot added the label Tests on Mar 6, 2023

ishaanam force-pushed on Mar 6, 2023

in test/functional/wallet_importdescriptors.py:696 in 92777b3dec outdated

695+        encrypted_wallet.walletpassphrase("passphrase", 99999)
696+        t = threading.Thread(target=encrypted_wallet.importdescriptors, args=([descriptor],))
697+
698+        t.start()
699+
700+        with self.nodes[0].assert_debug_log(expected_msgs=[f'Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)'], timeout=5):

maflcko commented at 12:50 pm on March 10, 2023:

You’ll have to do this sync on t.start, before walletlock, not after walletlock, no?

Otherwise this doesn’t achieve what you want and will fail anyway:

0AssertionError: [node 0] Expected messages "['Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)']" does not partially match log:

To test:

 0diff --git a/test/functional/wallet_importdescriptors.py b/test/functional/wallet_importdescriptors.py
 1index 3327c87626..cdc4d917a2 100755
 2--- a/test/functional/wallet_importdescriptors.py
 3+++ b/test/functional/wallet_importdescriptors.py
 4@@ -693,6 +693,7 @@ class ImportDescriptorsTest(BitcoinTestFramework):
 5         t = threading.Thread(target=encrypted_wallet.importdescriptors, args=([descriptor],))
 6 
 7         t.start()
 8+        import time;time.sleep(1)
 9 
10         with self.nodes[0].assert_debug_log(expected_msgs=[f'Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)'], timeout=5):
11             self.nodes[0].cli('-rpcwallet="encrypted_wallet" walletlock')

ishaanam commented at 4:42 pm on March 10, 2023:

This should be fixed now, thanks.

ishaanam force-pushed on Mar 10, 2023

fanquake commented at 9:56 am on March 11, 2023: member

Tested 308ea03d95786db674e8cce3e78a56b498cf119a rebased on master (c7f1d95f52883d7087b74f45f5e4ce1100d51149) and I’m no-longer seeing the issue in #27229: wallet_importdescriptors.py --descriptors | ✓ Passed | 652 s

in test/functional/wallet_transactiontime_rescan.py:208 in 308ea03d95 outdated

208 
209-            encrypted_wallet.batch(batch)
210+            with minernode.assert_debug_log(expected_msgs=[f'Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)'], timeout=5):
211+                t.start()
212+
213+            minernode.cli('-rpcwallet="encrypted_wallet" walletlock')

maflcko commented at 12:52 pm on March 13, 2023:

0            minernode.cli("-rpcwallet=encrypted_wallet").walletlock()

in test/functional/wallet_importdescriptors.py:698 in 308ea03d95 outdated

696+        t = threading.Thread(target=encrypted_wallet.importdescriptors, args=([descriptor],))
697+
698+        with self.nodes[0].assert_debug_log(expected_msgs=[f'Rescan started from block 0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206... (slow variant inspecting all blocks)'], timeout=5):
699+            t.start()
700+
701+        self.nodes[0].cli('-rpcwallet="encrypted_wallet" walletlock')

maflcko commented at 12:52 pm on March 13, 2023:

0        self.nodes[0].cli("-rpcwallet=encrypted_wallet").walletlock()

ishaanam commented at 7:22 pm on March 13, 2023:

Oh yes, walletlock never gets called here. However, implementing this change results in another CannotSendRequest.

maflcko commented at 8:58 am on March 14, 2023:

Are you sure? I tested my proposed change locally.

maflcko commented at 9:04 am on March 14, 2023:

Looks like it throws

test_framework.authproxy.JSONRPCException: Error: the wallet is currently being used to rescan the blockchain for related transactions. Please call

abortrescan before locking the wallet. (-4), which can be caught by assert_raises_rpc_error?

ishaanam commented at 4:24 pm on March 14, 2023:

‘assert_raises_rpc_error’ could be used here, but wouldn’t that introduce another race condition where this assertion will fail if the rescan has already been completed?

maflcko commented at 4:37 pm on March 14, 2023:

Right. Maybe just a try-catch-pass?

ishaanam commented at 3:45 am on March 15, 2023:

Yes, I have implemented this both for walletlock and walletpassphrasechange to ensure that this error is raised in both. However, it is important to note that this test now tests something slightly different than what it did previously. Previously this checked that the wallet was still able to complete a full rescan even if an attempt was made to relock the wallet (because of the timeout in walletpassphrase). This new test does not test this because other than using the walletpassphrase I can’t think of another method of deleting the passphrase from memory without having an error thrown. That being said, this adds coverage for something that was not previously tested (encryption RPCs throwing errors during a rescan, also introduced in #26347 ) and removes the race condition, so I think this is an improvement.

maflcko commented at 9:14 am on March 15, 2023:

walletpassphrase

If you want to keep coverage for that, you can add it as well (before walletlock) with a timeout of 1, which should override the previous timeout of 999999?

ishaanam commented at 9:28 pm on March 15, 2023:

I have now added test coverage for the lock as well.

maflcko commented at 9:53 am on March 16, 2023:

nice

maflcko changes_requested

maflcko commented at 12:56 pm on March 13, 2023: member

Calling the cli constructor does not dispatch the rpc.

Otherwise this looks really nice.

I’ve tested this with https://github.com/bitcoin/bitcoin/pull/26347/commits/6a5b348f2e526f048d0b448b01f6c4ab608569af#r1133856319

maflcko commented at 12:56 pm on March 13, 2023: member

looks nice, but there is a bug ACK 308ea03d95786db674e8cce3e78a56b498cf119a 🤠

Signature:

0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: looks nice, but there is a bug ACK 308ea03d95786db674e8cce3e78a56b498cf119a 🤠
3dsqqD3bytDg6ZUqhxFkcRuKux2dfw85m+3T2vlhaQUQ3b4l8EkXyTYeSWzPpfL9zx9/SGYpqZiYJTY2x8tWODA==

ishaanam force-pushed on Mar 15, 2023

maflcko commented at 12:54 pm on March 15, 2023: member

Didn’t re-test. Please advise maintainers if you want this merged or work on coverage for walletpassphrase a bit more (https://github.com/bitcoin/bitcoin/pull/27199#discussion_r1136502150)

review ACK 78cd77e17719d56366c483d5508cad7b0c5f1b5c 🏟

Signature:

0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: review ACK 78cd77e17719d56366c483d5508cad7b0c5f1b5c 🏟
3ubuVZMdV4ZjmXyRCN11JWS3wS1zS8LnQWZZ+XwYwYFJYNWZjDxuYeDZs+qThasZ8axW4+4HoP8NXTP6XZDDECQ==

test: fix race condition in encrypted wallet rescan tests dbeca792a9

ishaanam force-pushed on Mar 15, 2023

maflcko commented at 9:52 am on March 16, 2023: member

nice re-ACK dbeca792a9980085d00be0f9d78187ca3a4d7cdc 🚜

Signature:

0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: nice re-ACK dbeca792a9980085d00be0f9d78187ca3a4d7cdc  🚜
3JFDIenhS3ChvBHnr3YgwQFTqW9fJwU4I3gVtjnBatedP3Ch3CrUVWjy/1q1ieBV/KSwz3iW9aEPDNbR0SaAGBA==

maflcko assigned fanquake on Mar 16, 2023

maflcko assigned achow101 on Mar 16, 2023

maflcko commented at 10:15 am on March 16, 2023: member

Also, tested with my diff from #26347 (review)

achow101 commented at 9:19 pm on March 16, 2023: member

ACK dbeca792a9980085d00be0f9d78187ca3a4d7cdc

achow101 merged this on Mar 16, 2023

achow101 closed this on Mar 16, 2023

sidhujag referenced this in commit 5b7255486c on Mar 17, 2023

sidhujag referenced this in commit 4923d40056 on Mar 17, 2023

mzumsande commented at 9:28 pm on March 20, 2023: contributor

saw two fails of wallet_transactiontime_rescan.py --legacy-wallet today, both on master: https://cirrus-ci.com/task/6620294484328448 https://cirrus-ci.com/task/4914078427119616

fanquake commented at 9:36 am on March 21, 2023: member

@mzumsande see also #27282.

in test/functional/wallet_importdescriptors.py:703 in dbeca792a9

701+
702+        # Set the passphrase timeout to 1 to test that the wallet remains unlocked during the rescan
703+        self.nodes[0].cli("-rpcwallet=encrypted_wallet").walletpassphrase("passphrase", 1)
704+
705+        try:
706+            self.nodes[0].cli("-rpcwallet=encrypted_wallet").walletlock()

stickies-v commented at 2:09 pm on March 23, 2023:

It seems (?) we want this test to fail if walletlock succeeds, but that’s not currently the case - is that on purpose? Apologies if I’m misunderstanding, I didn’t dive super deep yet so feel free to keep your answer brief.

Edit: I suppose the main difficulty here is that walletlock can succeed if the rescan has already finished by the time walletlock is called, but then I think maybe the test needs a different setup?

ishaanam commented at 2:31 pm on March 23, 2023:

I suppose the main difficulty here is that walletlock can succeed if the rescan has already finished by the time walletlock is called

Yes, this issue here is that the rescan could have finished. For more context see: #27199 (review)

then I think maybe the test needs a different setup?

It would be great if there was a way that this test could behave the same regardless of speed. We haven’t been able to find a way to make that happen yet.

ishaanam deleted the branch on Nov 30, 2023

test: fix race condition in encrypted wallet rescan tests #27199

Reviews

Conflicts