Close minor startup race between main and scheduler threads #22577

This is a low-priority bug fix. The scheduler thread runs CheckForStaleTipAndEvictPeers() every 45 seconds (EXTRA_PEER_CHECK_INTERVAL). If its first run happens before the active chain is set up (CChain::SetTip()), bitcoind will assert:

(...)
2021-07-28T22:16:49Z init message: Loading block index…
bitcoind: validation.cpp:4968: CChainState& ChainstateManager::ActiveChainstate() const: Assertion `m_active_chainstate' failed.
Aborted (core dumped)

I ran into this while using the debugger to investigate an unrelated problem. Single-stepping through threads with a debugger can cause the relative thread execution timing to be very different than usual. I don't think any automated tests are needed for this PR. I'll give reproduction steps in the next PR comment.

The easiest way to reproduce this problem is to apply this patch, and then start bitcoind normally. This delays the main thread from loading the block index for 60 seconds.

--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1343,6 +1343,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
         bilingual_str strLoadError;
 
         uiInterface.InitMessage(_("Loading block index…").translated);
+        UninterruptibleSleep(std::chrono::milliseconds{60000});
 
         do {
             const int64_t load_block_index_start_time = GetTimeMillis();

<!--e57a25ab6845829454e8d69fc972939a-->

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

<!--174a7506f384e20aa4161008e828411d-->

Conflicts

Reviewers, this pull request conflicts with the following ones:

• #20295 (rpc: getblockfrompeer by Sjors)

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.

I have also received this failure when running the functional tests under ASAN in parallel.

tested ACK c0f913de644bf5516bcfae0cc8a87c449ba80596 (in conjunction with sleep() in #22577 (comment))

Can confirm the assertion happens with bitcoind/bitcoin-qt with the sleep in place:

bitcoin-qt: validation.cpp:4992: CChainState& ChainstateManager::ActiveChainstate() const: Assertion `m_active_chainstate' failed.`

With patch + sleep in place, things run as expected.

ACK c0f913de644bf5516bcfae0cc8a87c449ba80596. Was able to reproduce the issue and this solves it.

Tested ACK https://github.com/bitcoin/bitcoin/pull/22577/commits/c0f913de644bf5516bcfae0cc8a87c449ba80596 with the patch that reproduces the problem.

Wouldn't it make more sense to delay scheduling until later? Identical to how Connman does it?

@MarcoFalke

Wouldn't it make more sense to delay scheduling until later? Identical to how Connman does it?

Good idea, thanks! After more investigation, I think the root problem is that the peer manager's background tasks are started from PeerManagerImpl() constructor. The new version separates the starting of these background tasks from the constructor. It's done from a new method, StartScheduledTasks(), which is called at the end of AppInitMain() (startup). It should always be safe to delay (within reason) anything that runs in the background.

Force-pushed (previous version).

Can we reproduce the crash with the new commit, or should it never occur now? I expected to see some removed code. Cheers.

You can reproduce the crash by running master plus the patch. This PR branch (either the first version or the current version) plus the patch should not reproduce the crash.

The reason there's no removed code (removing the first version) is because I did a force-push.

cr ACK 703b1e612a4bd4521e20ae21eb8fb7c19f4ef942

tested ACK 703b1e612a4bd4521e20ae21eb8fb7c19f4ef942

Approach ACK, prefer over the original changes conceptually. I find myself asking whether replacing a pointer check(https://github.com/bitcoin/bitcoin/commit/c0f913de644bf5516bcfae0cc8a87c449ba80596) with a whole new async task is worth it. Code-wise I think this adds a little abstraction, but it seems like the right direction, however.

Sgtm.

Downside: can't insert a wrench in this code to duplicate the original bad behavior, but that doesn't seem necessary.

@tryphe

... a whole new async task ...

It's not a new async task; all this PR does is move where the two peer-related async tasks are started to a later time during system initialization.

Downside: can't insert a wrench in this code to duplicate the original bad behavior ...

I'm unclear on what you mean, and same with your earlier comment:

... I'm wondering if there's a creative way to reproduce it against the new commit ...

The whole point of the PR is that even with the reproduction patch (the extra delay) that causes the failure on master, it shouldn't be possible for that patch, or any patch, to reproduce the problem with this PR's new (or even with its old) commit. Maybe I'm missing something?

ACK 703b1e612a4bd4521e20ae21eb8fb7c19f4ef942

Tested that master crashes with the patch from #22577 (comment) and that 703b1e612a4bd4521e20ae21eb8fb7c19f4ef942 does not crash anymore.

... I'm wondering if there's a creative way to reproduce it against the new commit ...

It should be possible to reproduce again by moving the node.peerman->StartScheduledTasks(*node.scheduler); to right after the make_unique.

code review ACK 703b1e612a4bd4521e20ae21eb8fb7c19f4ef942 - it makes sense to me to start peerman's background tasks here, after chainstate->LoadChainTip() and node.connman->Start() have been called.

Also used a sleep (https://github.com/bitcoin/bitcoin/pull/22577#issuecomment-888664132) to verify the race exists on master but not on this branch since peerman->StartScheduledTasks() isn't called until later

@tryphe, Marco's comment helped me understand what you're asking for. You're looking for a patch to apply to the latest code that will cause the failure.

<details> <summary>Here's the patch that Marco suggested that should reproduce the problem (apply to this PR)</summary>

--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1181,6 +1181,7 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
     assert(!node.peerman);
     node.peerman = PeerManager::make(chainparams, *node.connman, *node.addrman, node.banman.get(),
                                      chainman, *node.mempool, ignores_incoming_txs);
+    if (node.peerman) node.peerman->StartScheduledTasks(*node.scheduler);
     RegisterValidationInterface(node.peerman.get());
 
     // sanitize comments per BIP-0014, format user agent and check total size
@@ -1343,6 +1344,8 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
         bilingual_str strLoadError;
 
         uiInterface.InitMessage(_("Loading block index…").translated);
+        // This delay must be > EXTRA_PEER_CHECK_INTERVAL (45 seconds) to reproduce the failure
+        UninterruptibleSleep(std::chrono::seconds{60});
 
         do {
             const int64_t load_block_index_start_time = GetTimeMillis();
@@ -1789,8 +1792,6 @@ bool AppInitMain(NodeContext& node, interfaces::BlockAndHeaderTipInfo* tip_info)
         banman->DumpBanlist();
     }, DUMP_BANS_INTERVAL);
 
-    if (node.peerman) node.peerman->StartScheduledTasks(*node.scheduler);
-
 #if HAVE_SYSTEM
     StartupNotify(args);
 #endif

</details>

<!--cf906140f33d8803c4a75a2196329ecb-->

🐙 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".}

post-merge ACK 703b1e612a4bd4521e20ae21eb8fb7c19f4ef942

Nice find! Could reproduce the issue fixed with the patch proposed in #22577 (comment)

assertion "m_active_chainstate" failed: file "validation.cpp", line 4968, function "ActiveChainstate"
Abort trap (core dumped)

After moving back the StartScheduledTasks call to its original place in the PR but keeping the uninterrupted sleep after showing the "Loading block index...", the problem doesn't occur anymore. 👌