test: resyncing to tip of blocks generated after invalidateblock

jonatack commented at 4:15 pm on June 27, 2020: member

This commit picks up #17335 to add an updated version of a test by Suhas Daftuar in issue #5806 to demonstrate a block propagation issue for the first coinbase following an invalidateblock. As Suhas reported: "[only] the first 16 [blocks] will make it, because of the call to getdata on processing each inv, which occurs until we’ve maxed out the number of blocks in flight to that peer."

Here we test that after running invalidateblock, on the first coinbase transaction nodes will resync to a new lower chain tip, but for the non-mining node only reliably up to the number of blocks equal to the value (16) of MAX_BLOCKS_IN_TRANSIT_PER_PEER. We then check that it catches up to the chain tip with the next coinbase transactions.

Reviewers may test this by running the test with different values of BLOCKS in the test and with rebuilding using different values of MAX_BLOCKS_IN_TRANSIT_PER_PEER in net_processing.cpp.

in test/functional/p2p_invalidateblock.py:19 in 8d27e73bc7 outdated

14+N = MAX_BLOCKS_IN_TRANSIT_PER_PEER     -> succeeds for both nodes
15+N = MAX_BLOCKS_IN_TRANSIT_PER_PEER + 1 -> node0 succeeds, node1 severely degraded
16+
17+"""
18+from test_framework.test_framework import BitcoinTestFramework
19+from test_framework.mininode import P2PInterface

jonatack commented at 4:21 pm on June 27, 2020:

This line is a leftover remnant, will remove.

jonatack force-pushed on Jun 27, 2020

DrahtBot added the label Tests on Jun 27, 2020

jonatack force-pushed on Jun 27, 2020

jnewbery commented at 6:11 pm on June 27, 2020: member

Concept ACK. Thanks for picking this up, Jon!

jonatack force-pushed on Jun 27, 2020

jonatack force-pushed on Jun 28, 2020

jonatack commented at 8:40 am on June 28, 2020: member

Concept ACK. Thanks for picking this up, Jon!

Thanks, John. The interesting thing is, unlike the PR17335 description, the original issue reported by @sdaftuar still appears to be unresolved.

jonatack force-pushed on Jun 29, 2020

jonatack commented at 3:15 am on June 29, 2020: member

Rebased to add more tests to verify that the non-mining node does catch up to the chain tip on the next coinbase transactions after the first one.

Add tests for block propagation after invalidateblock c48c680993

jonatack force-pushed on Jun 29, 2020

jnewbery commented at 3:39 pm on June 29, 2020: member

Thanks for digging into this more, @jonatack . I’ve run the test with the assert catching removed to reproduce the error. I’ve attached a combined log (best viewed with less -r). Here’s what’s happening:

If we invalidate MAX_BLOCKS_IN_TRANSIT_PER_PEER + 2 blocks and then regenerate MAX_BLOCKS_IN_TRANSIT_PER_PEER + 1 blocks on node0, node0 doesn’t announce those new blocks to the peer using compact blocks because of this logic in NewPoWValidBlock():

https://github.com/bitcoin/bitcoin/blob/1269cab21a9ac32f9ee8adfb9041950756eff3e4/src/net_processing.cpp#L1270-L1272

(ie the new block isn’t as high as a block node0 has previously announced via compact blocks)

Instead, node0 relies on block inventory sending in SendMessages():

https://github.com/bitcoin/bitcoin/blob/1269cab21a9ac32f9ee8adfb9041950756eff3e4/src/net_processing.cpp#L3956-L3971

We’re generating the blocks on the RPC thread (httpworker.x), but this block inventory relay happens on the MessageHandler thread. The timing windows for those two threads is the reason for the intermittency of this test failing.

In my failing case, all 17 blocks are generated while the message handler thread is sleeping. Here’s the sleep on the message handler thread:

https://github.com/bitcoin/bitcoin/blob/1269cab21a9ac32f9ee8adfb9041950756eff3e4/src/net.cpp#L2118

Here it is waking up to send the blocks:

0node0 2020-06-29T14:27:10.231122Z [msghand] SendMessages: sending inv peer=0 hash=3dafa6054777a53fd32abcb6f6eefe67591e93c275d23d07696313efed464ebe 
1node0 2020-06-29T14:27:10.231172Z [msghand] sending inv (37 bytes) peer=0

and here is the first of the 17 blocks being generated:

0test  2020-06-29T14:27:10.213000Z TestFramework (INFO):  Generate an alternate chain of 17 blocks on node0 
1 node0 2020-06-29T14:27:10.214362Z [http] Received a POST request for / from 127.0.0.1:42502 
2 node0 2020-06-29T14:27:10.214565Z [httpworker.3] ThreadRPCServer method=generatetoaddress user=__cookie__ 
3 node0 2020-06-29T14:27:10.214736Z [httpworker.3] CreateNewBlock(): block weight: 904 txs: 0 fees: 0 sigops 400

(ie all block generation happens in the 0.1s message handler sleep)

When node0 gets to the logic in SendMessages(), it reverts to sending the first MAX_BLOCKS_IN_TRANSIT_PER_PEER by INV instead of by HEADERS:

https://github.com/bitcoin/bitcoin/blob/1269cab21a9ac32f9ee8adfb9041950756eff3e4/src/net_processing.cpp#L3956-L3971

Here it is in the log:

0node0 2020-06-29T14:27:10.231122Z [msghand] SendMessages: sending inv peer=0 hash=3dafa6054777a53fd32abcb6f6eefe67591e93c275d23d07696313efed464ebe 
1 node0 2020-06-29T14:27:10.231172Z [msghand] sending inv (37 bytes) peer=0 
2 node1 2020-06-29T14:27:10.231360Z [msghand] received: inv (37 bytes) peer=0 
3 node1 2020-06-29T14:27:10.231392Z [msghand] got inv: block 3dafa6054777a53fd32abcb6f6eefe67591e93c275d23d07696313efed464ebe  new peer=0 
4 node1 2020-06-29T14:27:10.231411Z [msghand] sending getheaders (645 bytes) peer=0

The next time node0 goes through SendMessages(), it sends the final block to announce as a compact block:

0 node0 2020-06-29T14:27:10.232052Z [msghand] SendMessages sending header-and-ids 7dd48d289ad0eaaae4d0912686d4af94ebf7de371af02adfa78d2b7538ad9615 to peer=0 
1 node0 2020-06-29T14:27:10.232227Z [msghand] sending cmpctblock (264 bytes) peer=0

which node1 receives:

0 node1 2020-06-29T14:27:10.233481Z [msghand] received: cmpctblock (264 bytes) peer=0

I’d expect that to trigger node1 to send a getheaders for that block:

https://github.com/bitcoin/bitcoin/blob/1269cab21a9ac32f9ee8adfb9041950756eff3e4/src/net_processing.cpp#L2956-L2961

But it doesn’t. node1 doesn’t do any processing or requesting for the final block, which is why it never syncs to the same tip as node0. I haven’t dug into which logic path node1 takes through the CMPCTBLOCK processing.

As the test demonstrates, if node0 then generates and announces another block, then node1 will be able to sync to it.

I’m not sure what to do with this. It seems like a very limited edge-case, so maybe we can just document it and move on. Perhaps @sdaftuar or @TheBlueMatt have an opinion?

pr19397.log

jonatack commented at 5:15 pm on July 23, 2020: member

No ACKs. Closing.

jonatack closed this on Jul 23, 2020

DrahtBot locked this on Feb 15, 2022

test: resyncing to tip of blocks generated after invalidateblock #19397