Erroneous "Timeout downloading block" when said block is received by submitblock

[psgreco]

Log showing the problem:

2021-12-22T17:55:10Z Received a POST request for / from 127.0.0.1:42260
2021-12-22T17:55:10Z received: headers (613 bytes) peer=0
2021-12-22T17:55:10Z ThreadRPCServer method=submitblock user=rpcuser
2021-12-22T17:55:10Z Requesting block 84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 from  peer=0
2021-12-22T17:55:10Z sending getdata (37 bytes) peer=0
2021-12-22T17:55:10Z NewPoWValidBlock: block hash=84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4
2021-12-22T17:55:10Z   - Load block from disk: 0.02ms [0.00s]
2021-12-22T17:55:10Z     - Sanity checks: 0.01ms [0.00s (0.01ms/blk)]
2021-12-22T17:55:10Z     - Fork checks: 0.04ms [0.00s (0.04ms/blk)]
2021-12-22T17:55:10Z       - Connect 1 transactions: 0.04ms (0.045ms/tx, 0.000ms/txin) [0.00s (0.04ms/blk)]
2021-12-22T17:55:10Z     - Verify 0 txins: 0.08ms (0.000ms/txin) [0.00s (0.07ms/blk)]
2021-12-22T17:55:10Z     - Index writing: 0.11ms [0.00s (0.06ms/blk)]
2021-12-22T17:55:10Z     - Callbacks: 0.02ms [0.00s (0.01ms/blk)]
2021-12-22T17:55:10Z BlockChecked: block hash=84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 state=Valid
2021-12-22T17:55:10Z   - Connect total: 0.35ms [0.01s (0.26ms/blk)]
2021-12-22T17:55:10Z   - Flush: 0.02ms [0.00s (0.01ms/blk)]
2021-12-22T17:55:10Z   - Writing chainstate: 0.03ms [0.00s (0.02ms/blk)]
2021-12-22T17:55:10Z Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
2021-12-22T17:55:10Z UpdateTip: new best=84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 height=11 version=0x32000000 tx=12 date='2021-12-22T17:55:05Z' progress=1.000000 cache=0.0MiB(0txo)
2021-12-22T17:55:10Z 11 of last 100 blocks have unexpected version
2021-12-22T17:55:10Z   - Connect postprocess: 0.28ms [0.00s (0.15ms/blk)]
2021-12-22T17:55:10Z - Connect block: 0.70ms [0.01s (0.45ms/blk)]
2021-12-22T17:55:10Z Enqueuing BlockConnected: block hash=84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 block height=11
2021-12-22T17:55:10Z Enqueuing UpdatedBlockTip: new block hash=84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 fork block hash=88e6181d088ceed02f31979ac2e07d70f594edff9b999a4b75a36473e6111bda (in IBD=false)
2021-12-22T17:55:10Z BlockConnected: block hash=84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 block height=11
2021-12-22T17:55:10Z received: headers (613 bytes) peer=1
2021-12-22T17:55:10Z UpdatedBlockTip: new block hash=84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 fork block hash=88e6181d088ceed02f31979ac2e07d70f594edff9b999a4b75a36473e6111bda (in IBD=false)

......

2021-12-22T17:55:10Z received: cmpctblock (929 bytes) peer=0

......

2021-12-22T17:56:10Z Timeout downloading block 84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 from peer=0, disconnecting

Description:

Elements receives header for block 84413036116b0aa94fb841b4ff847a28a332e88d8c4f18d587448cd0846a98c4 by peer 0 and requests for the block, at the same time, it receives the full block via submitblock rpc. By the time peer 0 answers with the block, it has already been connected so the message is ignored, but the block is still marked as in-flight, so the error is logged and the peer is disconnected.

Possible solution is to remove the block from the in-flight list when message from peer 0 is ignored

[jhfrontz]

Just to confirm -- #1085 seems to also fix the "forced close" socket (observed from the peers of affected "timeout").