test: Fix inconsistent lock order in wallet_tests/CreateWallet #19982

hebasto · 2020-09-20T09:10:54Z

This PR:

fixes test: Potential deadlock in wallet_tests/CreateWalletFromFile #19049 that was caused by Reverse cs_main, cs_wallet lock order and reduce cs_main locking #16426
removes wallet_tests::CreateWallet suppression from the test/sanitizer_suppressions/tsan

The example of the improved CheckLastCritical()/LEAVE_CRITICAL_SECTION() log (could be got when compiled without the last commit):

2020-09-20T08:34:28.429485Z [test] INCONSISTENT LOCK ORDER DETECTED
2020-09-20T08:34:28.429493Z [test] Current lock order (least recent first) is:
2020-09-20T08:34:28.429501Z [test]  'walletInstance->cs_wallet' in wallet/wallet.cpp:4007 (in thread 'test')
2020-09-20T08:34:28.429508Z [test]  'cs_wallets' in wallet/wallet.cpp:4089 (in thread 'test')

Currently, there are other "naked" LEAVE_CRITICAL_SECTION() in the code base:

bitcoin/src/rpc/mining.cpp

Line 698 in b99a163

LEAVE_CRITICAL_SECTION(cs_main);

bitcoin/src/checkqueue.h

Line 208 in b99a163

LEAVE_CRITICAL_SECTION(pqueue->ControlMutex);

DrahtBot · 2020-09-20T18:46:55Z

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

Conflicts

No conflicts as of last run.

promag · 2020-09-21T08:59:20Z

This change reveals a bug in the wallet_tests/CreateWalletFromFile test,
that will be fixed in the following commit.

@hebasto I'm not following, how is it revealed?

hebasto · 2020-09-21T09:18:48Z

@promag

This change reveals a bug in the wallet_tests/CreateWalletFromFile test,
that will be fixed in the following commit.

@hebasto I'm not following, how is it revealed?

$ git checkout 7ac14ec58740226af85401f879f37f09755b990b
$ ./autogen.sh && ./configure --enable-debug && make clean && make
$ src/test/test_bitcoin --run_test=wallet_tests/CreateWalletFromFile
Running 1 test case...
wallet/test/wallet_tests.cpp:786 wallet->wallet()->cs_wallet was not most recent critical section locked, details in debug log.
unknown location(0): fatal error: in "wallet_tests/CreateWalletFromFile": signal: SIGABRT (application abort requested)
wallet/test/wallet_tests.cpp(785): last checkpoint

*** 1 failure is detected in the test module "Bitcoin Core Test Suite"
^C
$ tail -4 '/tmp/test_common_Bitcoin Core/03a41ec8724b4ea8adc603b0dc139290a6f9c765607df0bc277823d7b0165c20/regtest/debug.log'
2020-09-21T09:16:36.739551Z [test] INCONSISTENT LOCK ORDER DETECTED
2020-09-21T09:16:36.739557Z [test] Current lock order (least recent first) is:
2020-09-21T09:16:36.739562Z [test]  'walletInstance->cs_wallet' in wallet/wallet.cpp:4007 (in thread 'test')
2020-09-21T09:16:36.739568Z [test]  'cs_wallets' in wallet/wallet.cpp:4089 (in thread 'test')

promag · 2020-09-21T09:25:08Z

Thanks @hebasto, I tried make check instead. I'd suggest to add [skip ci] to that commit body

hebasto · 2020-09-21T09:43:36Z

@promag

Thanks @hebasto, I tried make check instead.

$ make check
...
2020-09-21T09:41:56.850457Z [test] INCONSISTENT LOCK ORDER DETECTED
2020-09-21T09:41:56.850463Z [test] Current lock order (least recent first) is:
2020-09-21T09:41:56.850470Z [test]  'walletInstance->cs_wallet' in wallet/wallet.cpp:4007 (in thread 'test')
2020-09-21T09:41:56.850475Z [test]  'cs_wallets' in wallet/wallet.cpp:4089 (in thread 'test')
wallet/test/wallet_tests.cpp:786 wallet->wallet()->cs_wallet was not most recent critical section locked, details in debug log.
make[3]: *** [Makefile:20887: wallet/test/wallet_tests.cpp.test] Error 1
make[3]: Leaving directory '/home/hebasto/guix/GitHub/bitcoin/src'
make[2]: *** [Makefile:19327: check-am] Error 2
make[2]: Leaving directory '/home/hebasto/guix/GitHub/bitcoin/src'
make[1]: *** [Makefile:19012: check-recursive] Error 1
make[1]: Leaving directory '/home/hebasto/guix/GitHub/bitcoin/src'
make: *** [Makefile:798: check-recursive] Error 1

hebasto · 2020-09-21T09:53:58Z

Updated 283ddf1 -> d89c332 (pr19982.03 -> pr19982.04, diff):

addressed @promag's comment:

I'd suggest to add [skip ci] to that commit body

promag · 2020-09-21T10:08:22Z

Oh I did't have --enable-debug.

src/wallet/test/wallet_tests.cpp

ariard

Code Review ACK d89c332, feel free to take comments, thanks for fixing this.

AFAICT this deadlock wasn't catch by CI at #16426 merge because LEAVE_CRITICAL didn't call neither potential_deadlock_detected or CheckLastCritical. Otherwise if a new lock would have been taken in the rest of CreateWalletFromFile it should have been detected.

So this PR does improve deadlock detection by flagging any lock order inconsistency even if it didn't materialize in an effective one as this case sounds to suggest ?

src/sync.cpp

src/test/sync_tests.cpp

ariard · 2020-09-23T16:58:07Z

src/wallet/test/wallet_tests.cpp

            LEAVE_CRITICAL_SECTION(wallet->wallet()->cs_wallet);
            SyncWithValidationInterfaceQueue();
            ENTER_CRITICAL_SECTION(wallet->wallet()->cs_wallet);
+            ENTER_CRITICAL_SECTION(cs_wallets);


Okay I looked on, before this commit, behavior is :

TestLoadWallet() in src/wallet/test/wallet_tests.cpp L794.

Calling down CWallet::Create() which takes the cs_wallet lock in src/wallet/wallet.cpp L4007 then cs_wallets lock in src/wallet/wallet.cpp L4089

Calling down this handler, which attempt to leave the former first triggering a lock order inconsistency

For tracking the faultive commit is 6a72f26.

ryanofsky

Code review ACK d89c332. Impressive work by hebasto not only debugging and fixing the buggy wallet test, but also improving deadlock detection, and improving deadlock detection output, and writing new deadlock detection tests!

@hebasto if you feel like adding more information to #19049, I'd be curious to know more you debugged this, since I gave up there struggling to figure out which locks were involved

ryanofsky · 2020-10-27T20:31:10Z

Note to anyone else interested in reviewing this that the change is simpler than it probably looks.

The actual bugfix in the third commit is very straightforward and just two lines. The first two commits are just improvements to error handling and debug output in lock order code, ignoring a big whitespace diff in the first commit.

hebasto · 2020-10-27T20:50:57Z

@ryanofsky

@hebasto if you feel like adding more information to #19049, I'd be curious to know more you debugged this, since I gave up there struggling to figure out which locks were involved

Our own lock stack being printed at some points appears very useful for debugging.

hebasto · 2020-11-14T19:17:39Z

Rebased d89c332 -> e2dc75f (pr19982.04 -> pr19982.05) due to the conflict with #20285.

Also updated comments as requested by @ariard.

hebasto · 2020-11-28T20:16:21Z

Rebased d15646b -> f2933e7 (pr19982.06 -> pr19982.07) due to the conflict with #19337.

ryanofsky

Code review ACK f2933e7. Since last review just rebase updating test name and tweaking comments

ryanofsky · 2020-12-02T22:03:34Z

Notes that might be helpful to other reviewers: #19982 (comment).

The actual fix is very simple and contained in the third commit. The other two commits are error checking improvements.

vasild

ACK f2933e7

lock m1
lock m2
unlock m1
unlock m2

the above was allowed before this PR and is forbidden after the PR. Such code cannot cause deadlock or any other issue and is legit. However it looks strange, may be a signal of a problem elsewhere and better be avoided. In our code in particular it would also brick the debugging mechanisms because LeaveCritical() from unlock m1 would remove the wrong lock from the lock stack (m2).

I think it is ok to enforce "locks should be released in reverse order in which they were acquired"

src/test/reverselock_tests.cpp

src/test/sync_tests.cpp

hebasto · 2020-12-03T08:50:00Z

Updated f2933e7 -> 608e14a (pr19982.07 -> pr19982.08, diff):

addressed @vasild's comments

practicalswift · 2020-12-03T11:28:31Z

Concept ACK

Nice work!

promag

Tested ACK 608e14a.

As expected make check fails on 79bfd2e with ./configure --enable-debug.

vasild · 2020-12-03T14:31:44Z

ACK 608e14a

This commit adds actual lock stack logging if check fails.

This change reveals a bug in the wallet_tests/CreateWalletFromFile test, that will be fixed in the following commit.

hebasto · 2020-12-10T18:56:00Z

Rebased 608e14a -> e1e68b6 (pr19982.08 -> pr19982.09) due to the conflict with #19425.

maflcko · 2020-12-10T19:21:01Z

review ACK e1e68b6 💂

Show signature and timestamp

Signature:

Timestamp of file with hash b9199fb93572c3373d95d9880b18d20bf1295e74f013c4bf476dda6306523525 -

ryanofsky

Code review ACK e1e68b6. Just trivial rebase and suggested switch to BOOST_CHECK_EXCEPTION since last review

vasild

ACK e1e68b6

…s/CreateWallet e1e68b6 test: Fix inconsistent lock order in wallet_tests/CreateWallet (Hennadii Stepanov) cb23fe0 [skip ci] sync: Check precondition in LEAVE_CRITICAL_SECTION() macro (Hennadii Stepanov) c5e3e74 sync: Improve CheckLastCritical() (Hennadii Stepanov) Pull request description: This PR: - fixes bitcoin#19049 that was caused by bitcoin#16426 - removes `wallet_tests::CreateWallet` suppression from the `test/sanitizer_suppressions/tsan` The example of the improved `CheckLastCritical()`/`LEAVE_CRITICAL_SECTION()` log (could be got when compiled without the last commit): ``` 2020-09-20T08:34:28.429485Z [test] INCONSISTENT LOCK ORDER DETECTED 2020-09-20T08:34:28.429493Z [test] Current lock order (least recent first) is: 2020-09-20T08:34:28.429501Z [test] 'walletInstance->cs_wallet' in wallet/wallet.cpp:4007 (in thread 'test') 2020-09-20T08:34:28.429508Z [test] 'cs_wallets' in wallet/wallet.cpp:4089 (in thread 'test') ``` Currently, there are other "naked" `LEAVE_CRITICAL_SECTION()` in the code base: https://github.com/bitcoin/bitcoin/blob/b99a1633b270e0e89479b2bb2ae19a8a8dc0fa05/src/rpc/mining.cpp#L698 https://github.com/bitcoin/bitcoin/blob/b99a1633b270e0e89479b2bb2ae19a8a8dc0fa05/src/checkqueue.h#L208 ACKs for top commit: MarcoFalke: review ACK e1e68b6 💂 ryanofsky: Code review ACK e1e68b6. Just trivial rebase and suggested switch to BOOST_CHECK_EXCEPTION since last review vasild: ACK e1e68b6 Tree-SHA512: a627680eac3af4b4c02772473d68322ce8d3811bf6b035d3485ccc97d35755bef933cffabd3f20b126f89e3301eccecec3f769df34415fb7c426c967b6ce36e6

hebasto force-pushed the 200920-leave-cs branch 2 times, most recently from 26fa3f6 to 5dc811f Compare September 20, 2020 09:58

hebasto marked this pull request as ready for review September 20, 2020 10:32

DrahtBot added the Wallet label Sep 20, 2020

hebasto force-pushed the 200920-leave-cs branch 2 times, most recently from 186221d to 283ddf1 Compare September 20, 2020 12:37

hebasto mentioned this pull request Sep 20, 2020

Drop some TSan suppressions #19983

Merged

DrahtBot mentioned this pull request Sep 20, 2020

sync: detect double lock from the same thread #19337

Merged

hebasto force-pushed the 200920-leave-cs branch from 283ddf1 to d89c332 Compare September 21, 2020 09:48

promag reviewed Sep 21, 2020

View reviewed changes

src/wallet/test/wallet_tests.cpp Show resolved Hide resolved

ariard reviewed Sep 23, 2020

View reviewed changes

This was referenced Sep 25, 2020

refactor: Get rid of more redundant chain methods #19425

Merged

refactor: remove ::vpwallets and related global variables #19101

Merged

Wallet passive startup #15719

Closed

ryanofsky approved these changes Oct 27, 2020

View reviewed changes

DrahtBot mentioned this pull request Oct 31, 2020

Add missing thread safety annotations #20272

Closed

hebasto mentioned this pull request Nov 7, 2020

Remove references to CreateWalletFromFile #20285

Merged

DrahtBot added the Needs rebase label Nov 12, 2020

hebasto force-pushed the 200920-leave-cs branch from d89c332 to e2dc75f Compare November 14, 2020 19:12

DrahtBot removed the Needs rebase label Nov 14, 2020

DrahtBot added the Needs rebase label Nov 25, 2020

hebasto changed the title ~~test: Fix inconsistent lock order in wallet_tests/CreateWalletFromFile~~ test: Fix inconsistent lock order in wallet_tests/CreateWallet Nov 28, 2020

hebasto force-pushed the 200920-leave-cs branch from d15646b to f2933e7 Compare November 28, 2020 20:15

DrahtBot removed the Needs rebase label Nov 28, 2020

ryanofsky approved these changes Dec 2, 2020

View reviewed changes

fanquake requested review from ajtowns, ariard and vasild December 3, 2020 02:06

vasild approved these changes Dec 3, 2020

View reviewed changes

src/test/reverselock_tests.cpp Outdated Show resolved Hide resolved

src/test/sync_tests.cpp Outdated Show resolved Hide resolved

hebasto force-pushed the 200920-leave-cs branch from f2933e7 to 608e14a Compare December 3, 2020 08:47

promag reviewed Dec 3, 2020

View reviewed changes

DrahtBot added the Needs rebase label Dec 8, 2020

hebasto added 3 commits December 10, 2020 20:46

sync: Improve CheckLastCritical()

c5e3e74

This commit adds actual lock stack logging if check fails.

[skip ci] sync: Check precondition in LEAVE_CRITICAL_SECTION() macro

cb23fe0

This change reveals a bug in the wallet_tests/CreateWalletFromFile test, that will be fixed in the following commit.

test: Fix inconsistent lock order in wallet_tests/CreateWallet

e1e68b6

hebasto force-pushed the 200920-leave-cs branch from 608e14a to e1e68b6 Compare December 10, 2020 18:54

DrahtBot removed the Needs rebase label Dec 10, 2020

ryanofsky approved these changes Dec 10, 2020

View reviewed changes

vasild approved these changes Dec 10, 2020

View reviewed changes

fanquake merged commit 736eb4d into bitcoin:master Dec 11, 2020

hebasto deleted the 200920-leave-cs branch December 11, 2020 07:31

bitcoin locked as resolved and limited conversation to collaborators Feb 15, 2022

test: Fix inconsistent lock order in wallet_tests/CreateWallet #19982

test: Fix inconsistent lock order in wallet_tests/CreateWallet #19982

Uh oh!

Conversation

hebasto commented Sep 20, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Sep 20, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

promag commented Sep 21, 2020

Uh oh!

hebasto commented Sep 21, 2020

Uh oh!

promag commented Sep 21, 2020

Uh oh!

hebasto commented Sep 21, 2020

Uh oh!

hebasto commented Sep 21, 2020

Uh oh!

promag commented Sep 21, 2020

Uh oh!

Uh oh!

ariard left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

ariard Sep 23, 2020

Choose a reason for hiding this comment

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

ryanofsky commented Oct 27, 2020

Uh oh!

hebasto commented Oct 27, 2020

Uh oh!

hebasto commented Nov 14, 2020

Uh oh!

hebasto commented Nov 28, 2020

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

ryanofsky commented Dec 2, 2020

Uh oh!

vasild left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

hebasto commented Dec 3, 2020

Uh oh!

practicalswift commented Dec 3, 2020

Uh oh!

promag left a comment

Choose a reason for hiding this comment

Uh oh!

vasild commented Dec 3, 2020

Uh oh!

hebasto commented Dec 10, 2020

Uh oh!

maflcko commented Dec 10, 2020

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

vasild left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

hebasto commented Sep 20, 2020 •

edited

Loading

DrahtBot commented Sep 20, 2020 •

edited

Loading