https://travis-ci.org/github/bitcoin/bitcoin/jobs/695312544#L5030
qa: Block sync timed out in `rpc_rawtransaction.py` #19187
issue hebasto opened this issue on June 6, 2020-
hebasto commented at 11:31 AM on June 6, 2020: member
- hebasto added the label Bug on Jun 6, 2020
-
S3RK commented at 11:24 AM on June 26, 2020: contributor
I was trying to investigate this intermittent failure and noticed a few strange things in the travis log. For reference, we have this networks setup:
node2 -> node1 -> node0 -> node2- A block is generated on
node2, but it only sendsinvto only one out of two peerspeer=0. Butpeer=1is also connected as we see other messages from it. In my local tests I seeinvsent to both peers. - Even after receiving
invmessagenode1doesn't continue with requesting a full block. This is consistent with my local tests, but it doesn't lead to any problems because the block got relayed through the other node.
Just looking at the code I've got no idea where to continue from here. I'm happy to continue to investigate If anybody has any ideas where to dig deeper.
Relevant part of travis log:
node2 2020-06-06T07:27:22.792741Z [default wallet] AddToWallet 1cb98edcc7174ac53d8db2f247e7eca1c99e0d4b3e17d5cc042bf6969a533881 new node2 2020-06-06T07:27:22.792974Z UpdatedBlockTip: new block hash=7d0c45f695f13af6b62d7b33af10fb20306b54df9e5e287eec516ed1d9ebbe43 fork block hash=0f9188f13cb7b2c71f2a335e3a4fc328bf5beb436012afca590b1a11466e2206 (in IBD=false) node2 2020-06-06T07:27:22.793104Z SendMessages: sending inv peer=0 hash=7d0c45f695f13af6b62d7b33af10fb20306b54df9e5e287eec516ed1d9ebbe43 node2 2020-06-06T07:27:22.793133Z sending inv (37 bytes) peer=0 node1 2020-06-06T07:27:22.793327Z received: inv (37 bytes) peer=1 node1 2020-06-06T07:27:22.793357Z got inv: block 7d0c45f695f13af6b62d7b33af10fb20306b54df9e5e287eec516ed1d9ebbe43 new peer=1 node1 2020-06-06T07:27:22.793377Z sending getheaders (69 bytes) peer=1 node1 2020-06-06T07:27:22.793418Z getheaders (0) 7d0c45f695f13af6b62d7b33af10fb20306b54df9e5e287eec516ed1d9ebbe43 to peer=1 node0 2020-06-06T07:27:22.794203Z Received a POST request for / from 127.0.0.1:33816 node0 2020-06-06T07:27:22.794265Z ThreadRPCServer method=getbestblockhash user=__cookie__ node1 2020-06-06T07:27:22.794935Z Received a POST request for / from 127.0.0.1:55724 node1 2020-06-06T07:27:22.794998Z ThreadRPCServer method=getbestblockhash user=__cookie__ node2 2020-06-06T07:27:22.795620Z Received a POST request for / from 127.0.0.1:59670 node2 2020-06-06T07:27:22.795680Z ThreadRPCServer method=getbestblockhash user=__cookie__ node2 2020-06-06T07:27:22.796357Z received: getheaders (69 bytes) peer=0 node2 2020-06-06T07:27:22.796399Z getheaders 1 to 7d0c45f695f13af6b62d7b33af10fb20306b54df9e5e287eec516ed1d9ebbe43 from peer=0 node2 2020-06-06T07:27:22.796421Z sending headers (82 bytes) peer=0 node1 2020-06-06T07:27:22.796607Z received: headers (82 bytes) peer=1 node1 2020-06-06T07:27:22.796681Z Synchronizing blockheaders, height: 1 (~100.00%) node1 2020-06-06T07:27:22.796711Z initial getheaders (0) to peer=1 (startheight:0) node1 2020-06-06T07:27:22.796728Z sending getheaders (69 bytes) peer=1 node2 2020-06-06T07:27:22.796885Z received: verack (0 bytes) peer=1 node2 2020-06-06T07:27:22.796903Z sending sendheaders (0 bytes) peer=1 node2 2020-06-06T07:27:22.796944Z sending sendcmpct (9 bytes) peer=1 node2 2020-06-06T07:27:22.796979Z sending sendcmpct (9 bytes) peer=1 node2 2020-06-06T07:27:22.797025Z sending ping (8 bytes) peer=1 node2 2020-06-06T07:27:22.797111Z initial getheaders (0) to peer=1 (startheight:0) node2 2020-06-06T07:27:22.797129Z sending getheaders (69 bytes) peer=1 node0 2020-06-06T07:27:22.797147Z received: sendheaders (0 bytes) peer=1 node0 2020-06-06T07:27:22.797217Z received: sendcmpct (9 bytes) peer=1 node2 2020-06-06T07:27:22.797242Z sending feefilter (8 bytes) peer=1 node0 2020-06-06T07:27:22.797279Z received: sendcmpct (9 bytes) peer=1 node2 2020-06-06T07:27:22.797312Z received: getaddr (0 bytes) peer=1 node0 2020-06-06T07:27:22.797351Z received: ping (8 bytes) peer=1 node0 2020-06-06T07:27:22.797370Z sending pong (8 bytes) peer=1 node2 2020-06-06T07:27:22.797378Z received: sendheaders (0 bytes) peer=1 node2 2020-06-06T07:27:22.797437Z received: sendcmpct (9 bytes) peer=1 node2 2020-06-06T07:27:22.797516Z received: sendcmpct (9 bytes) peer=1 node2 2020-06-06T07:27:22.797575Z received: ping (8 bytes) peer=1 node2 2020-06-06T07:27:22.797590Z sending pong (8 bytes) peer=1 node0 2020-06-06T07:27:22.797843Z received: getheaders (69 bytes) peer=1 node0 2020-06-06T07:27:22.797866Z Ignoring getheaders from peer=1 because node is in initial block download node2 2020-06-06T07:27:22.797881Z received: getheaders (69 bytes) peer=0 node2 2020-06-06T07:27:22.797907Z getheaders 1 to end from peer=0 node0 2020-06-06T07:27:22.797924Z received: feefilter (8 bytes) peer=1 node2 2020-06-06T07:27:22.797929Z sending headers (82 bytes) peer=0 node0 2020-06-06T07:27:22.797945Z received: feefilter of 0.00001000 BTC/kB from peer=1 node0 2020-06-06T07:27:22.798004Z received: pong (8 bytes) peer=1 node1 2020-06-06T07:27:22.798116Z received: headers (82 bytes) peer=1 node2 2020-06-06T07:27:22.798250Z received: feefilter (8 bytes) peer=1 node2 2020-06-06T07:27:22.798271Z received: feefilter of 0.00001000 BTC/kB from peer=1 node2 2020-06-06T07:27:22.798325Z received: pong (8 bytes) peer=1 - A block is generated on
-
MarcoFalke commented at 12:41 PM on June 26, 2020: member
Due to a race, node 1 never asks node 2 for the block in the download logic
- hebasto renamed this:
test: Block sync timed out in rpc_rawtransaction.py
qa: Block sync timed out in rpc_rawtransaction.py
on Nov 6, 2020 - hebasto renamed this:
qa: Block sync timed out in rpc_rawtransaction.py
qa: Block sync timed out in `rpc_rawtransaction.py`
on Jun 27, 2022 -
MarcoFalke commented at 1:59 PM on August 14, 2022: member
Is this still an issue with a recent version of Bitcoin Core? If yes, what are the steps to reproduce?
- MarcoFalke closed this on Aug 14, 2022
- MarcoFalke added the label Tests on Aug 14, 2022
- bitcoin locked this on Aug 14, 2023
Contributors