qa: Block sync timed out in `rpc_rawtransaction.py`

[hebasto]

https://travis-ci.org/github/bitcoin/bitcoin/jobs/695312544#L5030

[S3RK]

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

1. A block is generated on node2, but it only sends inv to only one out of two peers peer=0. But peer=1 is also connected as we see other messages from it. In my local tests I see inv sent to both peers.
2. Even after receiving inv message node1 doesn'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 

[maflcko]

Due to a race, node 1 never asks node 2 for the block in the download logic

[maflcko]

Is this still an issue with a recent version of Bitcoin Core? If yes, what are the steps to reproduce?