Fix lock order debugging and potential deadlocks

[jamescowens]

This address #779.

Some serious comments are in order here.

An assert should NEVER have been put in the potential_deadlock_detected to begin with. It is totally wrongheaded. The whole idea of that function, which is activated when a debug build is done, is to detect and provide to developers potential deadlocks. ASSERTs should only be used for an error condition so severe that the program should be stopped immediately. A potential deadlock condition is not one of those! In fact, in many cases the potential deadlock may not ever be encountered in practice. If you stop the program at the first one, it makes trying to find the universe of potential deadlocks almost impossible. You would have to troubleshoot and resolve them one at a time, recompiling and rerunning after each one. And that is assuming that you could actually fix them all.

Instead it is much better to just log the potential deadlock and keep going, so that all of them can be collected and analyzed in the debug log. Some of them may not be important and not affect program execution at all.

Because of this ASSERT, we have not been able to run debug builds which hampers the debugging information available to the developers.

Now the debug build works fine and just logs potential deadlocks.

I have also fixed the deadlock in #779, so I will close that issue. It turns out we have a few more left.

[jamescowens]

Here is a log before the change in lock order on SendMessages... (after the removal of the assert)...

$ tail -F -n 10000 debug.log|grep -A 12 -i "deadlock"
2019-12-14T23:02:45Z POTENTIAL DEADLOCK DETECTED
2019-12-14T23:02:45Z Previous lock order was:
2019-12-14T23:02:45Z (1)
2019-12-14T23:02:45Z pnode->cs_vSend net.cpp:2075 (TRY)
2019-12-14T23:02:45Z cs_main main.cpp:5274 (TRY)
2019-12-14T23:02:45Z (2)
2019-12-14T23:02:45Z cs_vNodes main.cpp:5325
2019-12-14T23:02:45Z Current lock order is:
2019-12-14T23:02:45Z (2)
2019-12-14T23:02:45Z cs_vNodes net.cpp:1113
2019-12-14T23:02:45Z (1)
2019-12-14T23:02:45Z pnode->cs_vSend net.cpp:1119 (TRY)
2019-12-14T23:02:45Z GUI: "registerShutdownBlockReason: Successfully registered: Gridcoin didn't yet exit safely..."

2019-12-14T23:08:59Z POTENTIAL DEADLOCK DETECTED
2019-12-14T23:08:59Z Previous lock order was:
2019-12-14T23:08:59Z (1)
2019-12-14T23:08:59Z pnode->cs_vSend net.cpp:2075 (TRY)
2019-12-14T23:08:59Z cs_main main.cpp:5274 (TRY)
2019-12-14T23:08:59Z (2)
2019-12-14T23:08:59Z cs_vNodes main.cpp:5325
2019-12-14T23:08:59Z Current lock order is:
2019-12-14T23:08:59Z (2)
2019-12-14T23:08:59Z cs_vNodes net.cpp:1113
2019-12-14T23:08:59Z (1)
2019-12-14T23:08:59Z pnode->cs_vSend net.cpp:1119 (TRY)
2019-12-14T23:08:59Z new manifest 0058c17467a5c51d12f95295c6603e2384ca06d82401209e73bf21618efb5b24 from 45.76.232.146:32748

2019-12-14T23:08:59Z POTENTIAL DEADLOCK DETECTED
2019-12-14T23:08:59Z Previous lock order was:
2019-12-14T23:08:59Z pnode->cs_vRecvMsg net.cpp:2064 (TRY)
2019-12-14T23:08:59Z (1)
2019-12-14T23:08:59Z CScraperManifest::cs_mapManifest main.cpp:5126
2019-12-14T23:08:59Z (2)
2019-12-14T23:08:59Z cs_main main.cpp:2044
2019-12-14T23:08:59Z Current lock order is:
2019-12-14T23:08:59Z pnode->cs_vRecvMsg net.cpp:2064 (TRY)
2019-12-14T23:08:59Z (2)
2019-12-14T23:08:59Z cs_main main.cpp:4643
2019-12-14T23:08:59Z (1)
2019-12-14T23:08:59Z CScraperManifest::cs_mapManifest main.cpp:4658

2019-12-14T23:14:49Z POTENTIAL DEADLOCK DETECTED
2019-12-14T23:14:49Z Previous lock order was:
2019-12-14T23:14:49Z pnode->cs_vRecvMsg net.cpp:2064 (TRY)
2019-12-14T23:14:49Z (1)
2019-12-14T23:14:49Z cs_main main.cpp:4643
2019-12-14T23:14:49Z (2)
2019-12-14T23:14:49Z cs_vSend net.h:456
2019-12-14T23:14:49Z Current lock order is:
2019-12-14T23:14:49Z (2)
2019-12-14T23:14:49Z pnode->cs_vSend net.cpp:2075 (TRY)
2019-12-14T23:14:49Z (1)
2019-12-14T23:14:49Z cs_main main.cpp:5274 (TRY)
2019-12-14T23:14:49Z getblocks -1 to 00000000000000000000 limit 500

2019-12-14T23:22:14Z POTENTIAL DEADLOCK DETECTED
2019-12-14T23:22:14Z Previous lock order was:
2019-12-14T23:22:14Z pnode->cs_vRecvMsg net.cpp:2064 (TRY)
2019-12-14T23:22:14Z (1)
2019-12-14T23:22:14Z cs_main main.cpp:4954
2019-12-14T23:22:14Z (2)
2019-12-14T23:22:14Z cs_vSend net.h:456
2019-12-14T23:22:14Z Current lock order is:
2019-12-14T23:22:14Z (2)
2019-12-14T23:22:14Z pnode->cs_vSend net.cpp:2075 (TRY)
2019-12-14T23:22:14Z (1)
2019-12-14T23:22:14Z cs_main main.cpp:5274 (TRY)
2019-12-14T23:22:14Z Received block 948838ab763496e3fcb9688554093d3498828c50239092d044fcef73da8a0716;

2019-12-14T23:47:35Z POTENTIAL DEADLOCK DETECTED
2019-12-14T23:47:35Z Previous lock order was:
2019-12-14T23:47:35Z pnode->cs_vRecvMsg net.cpp:2064 (TRY)
2019-12-14T23:47:35Z (1)
2019-12-14T23:47:35Z cs_main main.cpp:4643
2019-12-14T23:47:35Z (2)
2019-12-14T23:47:35Z cs_vSend net.h:456
2019-12-14T23:47:35Z Current lock order is:
2019-12-14T23:47:35Z (2)
2019-12-14T23:47:35Z pnode->cs_vSend net.cpp:2075 (TRY)
2019-12-14T23:47:35Z (1)
2019-12-14T23:47:35Z cs_main main.cpp:5274 (TRY)
2019-12-14T23:47:35Z getblocks -1 to 00000000000000000000 limit 500
tail: 'debug.log' has been replaced; following new file

[jamescowens]

Here is the log on the run after the lock order change.

Much better but not completely clear.

$ tail -F -n 10000 debug.log|grep -A 12 -i "deadlock"
2019-12-15T01:05:35Z POTENTIAL DEADLOCK DETECTED
2019-12-15T01:05:35Z Previous lock order was:
2019-12-15T01:05:35Z cs_main net.cpp:2083 (TRY)
2019-12-15T01:05:35Z (1)
2019-12-15T01:05:35Z pnode->cs_vSend net.cpp:2086 (TRY)
2019-12-15T01:05:35Z (2)
2019-12-15T01:05:35Z cs_vNodes main.cpp:5335
2019-12-15T01:05:35Z Current lock order is:
2019-12-15T01:05:35Z (2)
2019-12-15T01:05:35Z cs_vNodes net.cpp:1113
2019-12-15T01:05:35Z (1)
2019-12-15T01:05:35Z pnode->cs_vSend net.cpp:1119 (TRY)
2019-12-15T01:05:36Z refreshWallet

2019-12-15T01:05:36Z POTENTIAL DEADLOCK DETECTED
2019-12-15T01:05:36Z Previous lock order was:
2019-12-15T01:05:36Z pnode->cs_vRecvMsg net.cpp:2064 (TRY)
2019-12-15T01:05:36Z (1)
2019-12-15T01:05:36Z CScraperManifest::cs_mapManifest main.cpp:5126
2019-12-15T01:05:36Z (2)
2019-12-15T01:05:36Z cs_main main.cpp:2044
2019-12-15T01:05:36Z Current lock order is:
2019-12-15T01:05:36Z pnode->cs_vRecvMsg net.cpp:2064 (TRY)
2019-12-15T01:05:36Z (2)
2019-12-15T01:05:36Z cs_main main.cpp:4643
2019-12-15T01:05:36Z (1)
2019-12-15T01:05:36Z CScraperManifest::cs_mapManifest main.cpp:4658

[denravonska]

utACK. It looks legit but it it's difficult to grasp the entire scope indirectly covered by the changes.

[jamescowens]

Yep. And I can't solve the others yet. Really difficult. They don't seem to be causing a problem in actuality.

[cyrossignol]

Sorry, fell asleep waiting for this to build so I could review last night. The changes here make sense to me.

Regarding the assert() in potential_deadlock_detected(): our sync.cpp version is newer than most of our other Bitcoin code. Bitcoin added a strict assert() after the project cleaned up all of its potential lock ordering conflicts. Our older codebase still has these lock ordering issues, so it makes sense to avoid aborting the application by removing the assert().

I'd advocate for putting it back in the future if we manage to resolve the remaining locks in the same way—a potential deadlock condition could manifest from a rare state, and the assertion helps to bring attention to that for those that don't keep a close eye on the log.

[jamescowens]

I concur with that. We could also make it a configurable option to assert...