Reported here #12629 (comment) by @Empact. I’ve seen it now in a few different travis jobs, including:
https://travis-ci.org/bitcoin/bitcoin/jobs/366157920 https://travis-ci.org/bitcoin/bitcoin/jobs/366139851
From my initial investigation it seems like there may be an actual bug in block announcement, so I’m opening this issue to track.
I haven’t yet been able to reproduce. What I find most disturbing from staring at the debug logs in the travis failure (eg around here: https://travis-ci.org/bitcoin/bitcoin/jobs/366157920#L6672) is that the latest block generated on the node isn’t being relayed to any peers – neither the python mininode peers, nor the other bitcoind peer.
Not really sure how that can be happening (and only in this particular test? seems like a block relay problem of this sort would cause widespread testing failures). So hopefully I’m somehow just overlooking a particular quirk of the testing setup here.
I think I see what’s going on here. There are two nodes under test:
and three connections to those nodes:
The test is failing in the call to self.test_sendcmpct() on line 807. Before that:
self.test_sendcmpct() on line 805 is generating blocks on node0 and checking that they’re received by self.test_node.sync_blocks(self.nodes) on line 806 ensures that node1 is at the same tip as node0self.test_sendcmpct() on line generates blocks on node1 and checks that they’re received by self.segwit_node.Note that the call to sync_blocks on 806 has not ensured that the blocks have been propagated to self.segwit_node or self.old_node. The test fails because it drops into self.test_sendcmpct(), and calls generate on node1 before node1 has propagated the block from node0 to self.segwit_node. After generate is called, the test is waiting for node1 to send the newly generated block to self.segwit_node, but the next inv from node1 to self.segwit_node is for the block previously generated by node0:
0node0 2018-04-13T13:07:45.809404Z ThreadRPCServer method=generate user=__cookie__ <--------- generate to node0 from self.test_sendcmpct() on line 805
1[...]
2 node0 2018-04-13T13:07:45.812956Z CreateNewBlock(): block weight: 716 txs: 0 fees: 0 sigops 400
3[...]
4 node0 2018-04-13T13:07:45.815971Z UpdateTip: new best=23eb17fb1f4805b7c4adb768c250ff07a16aa16759839dc87c5ac98bd686705b height=111 version=0x20000000 log2_work=7.8073549 tx=113 date='2018-04-13T13:08:03Z' progress=1.000000 cache=0.0MiB(121txo)
5[...]
6 node0 2018-04-13T13:07:45.816646Z sending headers (82 bytes) peer=0
7[...]
8 node1 2018-04-13T13:07:45.817742Z received: headers (82 bytes) peer=0 <---- node1 receives block
9[...]
10 node1 2018-04-13T13:07:45.825341Z UpdateTip: new <--- node1 synced
11[...]
12 node1 2018-04-13T13:07:45.827344Z ThreadRPCServer method=generate user=__cookie__ <--------- generate to node1 from self.test_sendcmpct() on line 807
13[...]
14 node1 2018-04-13T13:07:45.830472Z UpdateTip: new best=7bfef9174d2d8c9bf165ce690b6eca7c2567fa52f3e6d9cb3d98d14327e87d33 height=112 version=0x20000000 log2_work=7.820179 tx=114 date='2018-04-13T13:08:03Z' progress=1.000000 cache=0.0MiB(122txo) <----------------- node1 tip advances. Test now waits for notification of block (check_announcement_of_new_block() on line 172)
15[...]
16 node1 2018-04-13T13:07:45.831909Z SendMessages: sending inv peer=2 hash=23eb17fb1f4805b7c4adb768c250ff07a16aa16759839dc87c5ac98bd686705b <---------- node1 sends the blockhash for the *old block* to segwit_node
17 node1 2018-04-13T13:07:45.831954Z sending inv (37 bytes) peer=2
18 test 2018-04-13T13:07:45.832000Z TestFramework.mininode (DEBUG): Received message from 127.0.0.1:11458: msg_inv(inv=[CInv(type=Block hash=23eb17fb1f4805b7c4adb768c250ff07a16aa16759839dc87c5ac98bd686705b)])
19[...]
20 test 2018-04-13T13:08:15.877000Z TestFramework.utils (ERROR): wait_until() failed. Predicate: ([' def received_hash():\n', ' return (block_hash in self.announced_blockhashes)\n'], 79) <-------- test times out waiting for new block
compare this with a passing case where the block from node0 is propagated to self.segwit_node before the generate call to node1.
It’d be nice to rewrite this test to not have so much state between the different nodes-under-test and test connections. If we fix this one timing issue, there’s no guarantee that there aren’t other similar issues that will be hit by travis.
Caught it! https://travis-ci.org/jnewbery/bitcoin/jobs/366281859
Looks like UpdatedBlockTip() is called in the wrong order:
0node1 2018-04-13T21:03:36.950443Z UpdateTip: new best=74fa99e8f6767f817000b9ddb050bb2fc53d329203d63f3a084d37300be894e9 height=111 version=0x20000000 log2_work=7.8073549 tx=113 date='2018-04-13T21:03:54Z' progress=1.000000 cache=0.0MiB(121txo)
1[...]
2 node1 2018-04-13T21:03:36.955464Z UpdateTip: new best=57a644748fb3e38c225972bd2e3b0fd45e7665498ebd1fcaf8e37aa6c07ac886 height=112 version=0x20000000 log2_work=7.820179 tx=114 date='2018-04-13T21:03:54Z' progress=1.000000 cache=0.0MiB(122txo)
but:
0node1 2018-04-13T21:03:36.955924Z UpdatedBlockTip callback: new block hash: 57a644748fb3e38c225972bd2e3b0fd45e7665498ebd1fcaf8e37aa6c07ac886
1[...]
2node1 2018-04-13T21:03:36.956569Z UpdatedBlockTip callback: new block hash: 74fa99e8f6767f817000b9ddb050bb2fc53d329203d63f3a084d37300be894e9
Had some offline conversations regarding this too. After @jnewbery’s insights above and a bit of reading - I think what’s happening is that cs_main is released in ActivateBestChain() between ActivateBestChainStep but before the UpdatedBlockTip callback has been enqueued.
In this particular case there are two threads now racing to enqueue an UpdatedBlockTip signal (the thread processing the block received over p2p and the thread which generated the block via rpc).
After adding a randomized sleep (see below) you can reproduce this issue a bit more reliably:
0 } // CS_MAIN RELEASED HERE
1 // When we reach this point, we switched to a new tip (stored in pindexNewTip).
2
3 // Notifications/callbacks that can run without cs_main
4 MilliSleep(GetRand(500));
5
6 // Notify external listeners about the new tip.
7 GetMainSignals().UpdatedBlockTip(pindexNewTip, pindexFork, fInitialDownload);
I think a potential fix is to hold cs_main until the UpdatedBlockTip signals are enqueued? Once safely enqueued they should be processed in correct order by the scheduler thread.
PeerLogicValidation::UpdatedBlockTip so that it would’t rewind? It could ignore out of order notifications if it’s not a reorg? It already handles blocks in between:
https://github.com/bitcoin/bitcoin/blob/0d6992168c2bda85b18fda8f6dea08da433a0dc9/src/net_processing.cpp#L923-L934
I think that the missed announcement is actually caused by the below (or maybe both)
0// Requires cs_main
1bool PeerHasHeader(CNodeState *state, const CBlockIndex *pindex)
2{
3 if (state->pindexBestKnownBlock && pindex == state->pindexBestKnownBlock->GetAncestor(pindex->nHeight))
4 return true;
5 if (state->pindexBestHeaderSent && pindex == state->pindexBestHeaderSent->GetAncestor(pindex->nHeight))
6 return true;
7 return false;
8}
But anyway - even fixing that (which would substantially complicate the logic) - its difficult to assess how many other dependencies there are on this signal being properly ordered
Should we add thread-safety analysis annotations to make sure the locking requirements are fulfilled going forward?
Are these the locks we want to be held?
0boost::signals2::signal<void (bool, const CBlockIndex *)> NotifyBlockTip
1 GUARDED_BY(cs_main);
2
3void UpdatedBlockTip(const CBlockIndex *, const CBlockIndex *, bool fInitialDownload)
4 EXCLUSIVE_LOCKS_REQUIRED(cs_main);
@practicalswift I don’t think that makes sense for the reason I gave here – we don’t just need to hold a lock while invoking the callback, we also need to not have let it go from when the tip was updated. I fear that adding checks on just holding the lock at the time the callbacks are called obscures the ordering requirement.
I do think that we should add testing to ensure the ordering requirement is met; I was thinking a unit-test might work but I’d love to hear other ideas.
Apart from the test we have now which fails (but only sporadically) - I’m struggling a bit to think about what sort of test to add that would positively identify this if it broke again - what did you have in mind?
I agree that adding a lock assert doesnt say much about what happened before the lock was acquired so doesn’t really guarantee anything about atomicity from chain update to event invocation. I think a different solution is to lock down event generation to certain paths (e.g. in this case ActivateBestChain) - I don’t think that breaks cleanliness of the interface - the interface is more to make it easy and generalized for subscribers, but event generation is still very context dependent. I don’t know of any way to accomplish this easily in c++ though - anything obvious come to mind?
Oh, also - I guess I should mention/shill this WIP pr #12934 I have out currently - its related. It creates a separate Validation thread and instead of threads calling directly into the validation layer - they just push messages onto a queue that the validation thread pulls from and processes completely and in order.
In addition to more cleanly defining the interfaces into validation paths - it also makes it a lot easier to reason about concurrency and parallelism because block validation paths become single threaded and well ordered. You also get the added benefit that you can more easily parallelize stuff that happens outside of validation by explicitly making validation interfaces asynchronous - but the main goal is to better define interfaces and simplify the concurrency model in the most logically complex validation paths.
Apart from the test we have now which fails (but only sporadically) - I’m struggling a bit to think about what sort of test to add that would positively identify this if it broke again - what did you have in mind?
I haven’t worked this out yet, but I was thinking that if we could mock out the scheduler that is used by the validationinterface, then we could play around with delays in callback enqueuing time to see if that breaks ordering when generating events from multiple threads?