Compact Blocks can sometimes take an excruciatingly long time to request transactions #11769

Bitcoin version v0.15.99.0-a89221873

2017-11-27 03:00:03 Initialized PartiallyDownloadedBlock for block 0000000000000000000aadcaac65ce76f6d91f15fc15d31795a4616750101564 using a cmpctblock of size 15698
2017-11-27 03:00:03 Initialized PartiallyDownloadedBlock for block 0000000000000000000aadcaac65ce76f6d91f15fc15d31795a4616750101564 using a cmpctblock of size 15698
2017-11-27 03:00:07 Initialized PartiallyDownloadedBlock for block 0000000000000000000aadcaac65ce76f6d91f15fc15d31795a4616750101564 using a cmpctblock of size 15698
2017-11-27 03:00:08 85ec29374f60077d1e2062786d03b156d910bff699ddc768163be2d49fa132d8 from peer=4 was not accepted: non-final (code 64)
2017-11-27 03:00:08 ce31ea70a49a8e788a39dcdde0f605e6a9587f9496ea3daa677077df6ab7e975 from peer=4 was not accepted: non-final (code 64)
2017-11-27 03:00:08 b52c77de5855e4f6bc670f97b51398fd3c2c8863fb4a3cc1af32247b39b6f1a4 from peer=4 was not accepted: non-final (code 64)
2017-11-27 03:00:08 b52c77de5855e4f6bc670f97b51398fd3c2c8863fb4a3cc1af32247b39b6f1a4 from peer=5 was not accepted: non-final (code 64)
2017-11-27 03:00:09 b52c77de5855e4f6bc670f97b51398fd3c2c8863fb4a3cc1af32247b39b6f1a4 from peer=2 was not accepted: non-final (code 64)
2017-11-27 03:00:10 80e514b638181cb70d38412611d4b29b711696565bb33b2bef340471de00d404 from peer=3 was not accepted: non-final (code 64)
2017-11-27 03:00:10 b52c77de5855e4f6bc670f97b51398fd3c2c8863fb4a3cc1af32247b39b6f1a4 from peer=3 was not accepted: non-final (code 64)
2017-11-27 03:00:11 b52c77de5855e4f6bc670f97b51398fd3c2c8863fb4a3cc1af32247b39b6f1a4 from peer=1 was not accepted: non-final (code 64)
2017-11-27 03:00:11 771ec88c7eacaa578b9cf94fac7671498661f038aa73e5ae8626fdd2ecf6eb77 from peer=2 was not accepted: non-final (code 64)
2017-11-27 03:00:12 ecf7a3370ba72e9661947c96b10c251c4e7594e417521b7932d2cbb6c1aa0c47 from peer=1 was not accepted: non-final (code 64)
2017-11-27 03:00:15 b52c77de5855e4f6bc670f97b51398fd3c2c8863fb4a3cc1af32247b39b6f1a4 from peer=0 was not accepted: non-final (code 64)
2017-11-27 03:00:16 b073ba611849d315d3199f485c0ff46ab86ae9275451905929b42d0d8342529f from peer=3 was not accepted: non-final (code 64)
2017-11-27 03:00:18 22deca4b1896e76f84a9c853f740e8cdb513d1a96d1e5a605d71d6578101dcdb from peer=6 was not accepted: non-final (code 64)
2017-11-27 03:00:20 6c9782fc93f9c5a1923731c66660e1b0d4dd3f803a9d30ab4af00add76269fc7 from peer=3 was not accepted: non-final (code 64)
2017-11-27 03:00:22 817d9cf3a8089861402f735dd8279fa11333ba9f5ec1dedcfbd83eaefe4edb98 from peer=6 was not accepted: non-final (code 64)
2017-11-27 03:00:22 02aeb8541a880c901ebc01d800fcf9f6520673aa74204414c72479f5b40e1dd6 from peer=6 was not accepted: non-final (code 64)
2017-11-27 03:00:22 f73f1fa28d3a48352d999826b284a2cec66b2b0dab57f4fbc5e56f77d330b5b5 from peer=6 was not accepted: non-final (code 64)
2017-11-27 03:00:22 d325a493d6b18d9167a5cd8d4f5935ab0463bc9681027869dc387ec194618048 from peer=6 was not accepted: non-final (code 64)
2017-11-27 03:00:25 438644e38b4c7ae3d131c5c95454cc30375cbba0b8879a81b49a3f63d49d5d09 from peer=2 was not accepted: non-final (code 64)
2017-11-27 03:00:25 Successfully reconstructed block 0000000000000000000aadcaac65ce76f6d91f15fc15d31795a4616750101564 with 1 txn prefilled, 2473 txn from mempool (incl at least 24 from extra pool) and 85 txn requested
2017-11-27 03:00:25   - Load block from disk: 0.00ms [0.00s]
2017-11-27 03:00:25     - Sanity checks: 0.00ms [0.01s (0.49ms/blk)]
2017-11-27 03:00:25     - Fork checks: 0.04ms [0.00s (0.04ms/blk)]
2017-11-27 03:00:25       - Connect 2559 transactions: 27.19ms (0.011ms/tx, 0.005ms/txin) [0.35s (11.97ms/blk)]
2017-11-27 03:00:25     - Verify 4986 txins: 27.32ms (0.005ms/txin) [0.35s (12.03ms/blk)]
2017-11-27 03:00:25     - Index writing: 15.77ms [0.08s (2.80ms/blk)]
2017-11-27 03:00:25     - Callbacks: 0.07ms [0.00s (0.01ms/blk)]
2017-11-27 03:00:25   - Connect total: 43.79ms [0.21s (7.14ms/blk)]
2017-11-27 03:00:25   - Flush: 9.26ms [0.04s (1.45ms/blk)]
2017-11-27 03:00:25   - Writing chainstate: 0.04ms [0.00s (0.01ms/blk)]
2017-11-27 03:00:25 UpdateTip: new best=0000000000000000000aadcaac65ce76f6d91f15fc15d31795a4616750101564 height=496284 version=0x20000000 log2_work=87.539574 tx=275165181 date='2017-11-27 02:59:12' progress=0.999999 cache=33.2MiB(246275txo)
2017-11-27 03:00:25   - Connect postprocess: 30.21ms [1.55s (53.44ms/blk)]
2017-11-27 03:00:25 - Connect block: 83.30ms [1.80s (62.04ms/blk)]```

The rejections are for transactions which were not contained in the block reconstruction, but seem to be related.

It is not that requesting takes a long time, but that responding takes a long time. We currently are single-threaded in ProcessMessages and a node which receives a block will have its message processing thread blocked validating/connecting the block and will not be able to respond to a getblocktxn message until it finishes. While the spec allows us to fix this, and we should, doing so is a rather large change.

Is there a reason there's no obvious switch to turn this off for a high integrity mode? It's causing my nodes to fall behind by many minutes, seemingly regardless of what peers they're talking to.

2017-11-29 19:13:16.904552 Initialized PartiallyDownloadedBlock for block 000000000000000000a12d6acd91f0f09d1e816c7e31793020dc78680480f3fd using a cmpctblock of size 12601
2017-11-29 19:13:19.137350 Initialized PartiallyDownloadedBlock for block 000000000000000000a12d6acd91f0f09d1e816c7e31793020dc78680480f3fd using a cmpctblock of size 12601

....

2017-11-29 19:22:07.759980 00a5265fa3cf38115f42e94f2e0e267758af6cc7a240fc37cf9e77fcad1c42be from peer=2 was not accepted: non-final (code 64)

2017-11-29 19:23:16.971350 Timeout downloading block 000000000000000000a12d6acd91f0f09d1e816c7e31793020dc78680480f3fd from peer=10, disconnecting
2017-11-29 19:23:25.967184 UpdateTip: new best=000000000000000000a12d6acd91f0f09d1e816c7e31793020dc78680480f3fd height=496735 version=0x20000000 log2_work=87.556213 tx=276197095 date='2017-11-29 19:12:53' progress=0.999993 cache=239.5MiB(1755296txo) warning='1 of last 100 blocks have unexpected version'

That looks like a very different issue, and seems to indicate your peer is broken in some way, now that it was disconnected you should likely see the issue less. If it persists, maybe check if your node is repeatedly connecting to the same bad peer (eg via -connect or -addnode or otherwise compare getpeerinfo).

I understand why I'm seeing the non-final rejections, they're anti fee sniping transactions being broadcast with the expectation that I've already imported that block. The peer blocking the compact block reconstruction is a Tor exit, which makes it seem intentional.

Are you assuming the tor exit server is manipulating Bitcoin traffic? It could be a bad peer on the other end. In any case, not a ton we can do without blowing up bandwidth usage, #10984 will help resolve for the simple compact block case, so you may want to try with that.

@6784 - what's the current status of this issue? Are you still having problems?

Did you try running with #10984 as Matt suggested?

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