Timeout downloading block

jhoenicke commented at 12:17 pm on January 29, 2018: none

When investigating my mempool statistics there are from time to time >15 minutes intervals without blocks followed immediately by two or three fast blocks and it happened too often to be just due to the high variance of exponential distributiion.

Looking into the logs revealed the culprit:

0grep Timeout -A1 debug.log | tail
12018-01-29 08:45:20 Timeout downloading block 00000000000000000031a8bf543031f89b7a2a445d5b872883b2b5375c251571 from peer=47947, disconnecting
22018-01-29 08:45:22 UpdateTip: new best=00000000000000000031a8bf543031f89b7a2a445d5b872883b2b5375c251571 height=506627 version=0x20000000 log2_work=87.990329 tx=296113862 date='2018-01-29 08:34:56' progress=0.999993 cache=85.3MiB(564264txo)
3--
42018-01-29 09:41:12 Timeout downloading block 000000000000000000254d01e7f0d550506ae1d23be0d255e9e650ecbe887e6a from peer=51377, disconnecting
52018-01-29 09:41:13 UpdateTip: new best=000000000000000000254d01e7f0d550506ae1d23be0d255e9e650ecbe887e6a height=506635 version=0x20000000 log2_work=87.990749 tx=296124995 date='2018-01-29 09:31:05' progress=0.999994 cache=88.7MiB(591588txo)
6--
72018-01-29 11:33:16 Timeout downloading block 00000000000000000064da61afd140ad94b973d5d355e653111c04edba9ea625 from peer=51664, disconnecting
82018-01-29 11:33:17 UpdateTip: new best=00000000000000000064da61afd140ad94b973d5d355e653111c04edba9ea625 height=506642 version=0x20000000 log2_work=87.991116 tx=296138316 date='2018-01-29 11:22:36' progress=0.999993 cache=94.6MiB(639913txo)

The peer seems to be always the same (IP addresses aren’t logged):

02018-01-29 09:42:12 receive version message: /ViaBTC:bitpeer.0.2.0/: version 70015, blocks=0, us=0.0.0.0:0, peer=51664

What behavior did you expect?

First, I’d expect a shorter timeout (it seems to be 10 minutes). While a 10 minutes timeout is not that critical for my node, it means that you shouldn’t use an unmodified bitcoin core for solo mining or you risk high orphan rate.

Also why is the node not banned? It is disconnected but it is allowed to immediately reconnect. Wouldn’t it be possible to exploit this behaviour to make the blocks of competitors relay slowly, by just sending the inv message for them but never delivering the content.

This is with bitcoin v0.15.1

fanquake added the label P2P on Jan 29, 2018

gmaxwell commented at 9:03 am on February 4, 2018: contributor

Generally the node is defended from block denial by the subscription to three peers in HB mode, resulting in getting up to four copies even in the face of malicious denial. It would be interesting to see your logs to see if CB reconstruction failed or if there was some other issue. @TheBlueMatt would fine this issue interesting

I previously saw these attacks from those nodes, and the improved CB reproduction seemed to solve them. Their mass connecting behavior got them listed on the blacklists my nodes use, so I haven’t seen them lately.

The timeout question is complicated. Too short a timeout and when you run bitcoin on a limited bandwidth link (or one under a sustained DOS attack that otherwise would have enough bandwidth to barely keep working) you will go into congestion collapse and be unable to continue syncing because just before finishing a block you terminate the peer and start anew. Even with the 10 minute time we’ve had problems with people reporting that. More correct would likely be an adaptive time which advances forward to 2x the last successful transfer and backs off exponentially on disconnection but these things are tricky to test and work out their effect network wide in the face of possible attacks, so it hasn’t been done yet– instead effort went into making better use of the redundant CB transmissions so far.

Similar applies on banning, you having a slow connection doesn’t mean the peer did anything wrong. One wouldn’t want third parties DOS attacking you to cause you to ban all honest peers.

Re mining: directly exposing a mining node to inbound connections to the public is not a good configuration. Standard advice is that a mining node should connect out to a couple of remote public nodes run by the miner as well as potentially a few other seemingly reliable nodes run by others. Its common to see miners DOS attacked and some attacks don’t admit any software defense (e.g. flooding you with traffic right when a block shows up on the network), so the most general defense is to keep a low profile. Obviously the software should be as resistant as possible too, but we need to avoid overly simple defenses turning into attack amplifiers.

TheBlueMatt commented at 5:14 pm on February 4, 2018: contributor

#10984 would make us somewhat more robust to this attack, though at this point we should consider just banning anything that says “bitpeer” in it…

jhoenicke commented at 1:45 pm on February 5, 2018: none

It would be interesting to see your logs to see if CB reconstruction failed or if there was some other issue.

I don’t see any compact block related logs in debug.log. I can try to run again with more debugging enabled if that helps. Is there an option to increase verbosity for CB?

I noticed that the bitpeer server banned itself by misbehaving from time to time, so this is why there is sometimes a period of more than 24 hours without any timeouts :). I currently ban it manually.

PRabahy commented at 3:53 am on April 25, 2018: contributor

I don’t want to hijack this issue, but I believe I just encountered a related issue. I had been offline for ~2 weeks and started my node. It was catching up nicely, but then it stalled for a very long time.

 02018-04-25 03:30:30 UpdateTip: new best=0000000000000000003923691e313442f52ebbb15e9c5bd7db976c34797487a0 height=519337 version=0x20000000 log2_work=88.642567 tx=311637316 date='2018-04-22 01:20:23' progress=0.997010 cache=42.2MiB(73404txo)
 12018-04-25 03:30:30 UpdateTip: new best=0000000000000000001822f09f1821deb6b3b74e36ea1de4e232e5c60fa30ed9 height=519338 version=0x20000000 log2_work=88.642616 tx=311637370 date='2018-04-22 01:25:30' progress=0.997014 cache=42.2MiB(73520txo)
 22018-04-25 03:30:30 UpdateTip: new best=00000000000000000031189ef2542d985552b4da05eb23cc88473ebdd223c02b height=519339 version=0x20000000 log2_work=88.642665 tx=311639023 date='2018-04-22 01:38:46' progress=0.997023 cache=43.0MiB(79805txo)
 32018-04-25 03:30:30 UpdateTip: new best=00000000000000000027264033979f0905e40513e1c207f9779a41e749474207 height=519340 version=0x20000000 log2_work=88.642714 tx=311639037 date='2018-04-22 01:38:52' progress=0.997023 cache=43.0MiB(79831txo)
 42018-04-25 03:30:31 UpdateTip: new best=000000000000000000139711f1aafcba0cb1c5478cd6750e67182585b99723c8 height=519341 version=0x20000000 log2_work=88.642764 tx=311640789 date='2018-04-22 01:57:17' progress=0.997035 cache=43.8MiB(86544txo)
 52018-04-25 03:30:31 UpdateTip: new best=0000000000000000001290bf95e6bcbe5e2ecc4254a8eb5918bd7c83ff862eed height=519342 version=0x20000000 log2_work=88.642813 tx=311640820 date='2018-04-22 01:57:38' progress=0.997035 cache=43.8MiB(86602txo)
 62018-04-25 03:30:31 UpdateTip: new best=00000000000000000033f93e3b264293c478b52c316815407a9e574f5f5f9526 height=519343 version=0x20000000 log2_work=88.642862 tx=311642602 date='2018-04-22 02:18:53' progress=0.997049 cache=44.6MiB(93215txo)
 72018-04-25 03:30:32 UpdateTip: new best=0000000000000000001284e7b52cf2f9329d2f2cc70957e6693a6b78d7e3fb4e height=519344 version=0x20000000 log2_work=88.642911 tx=311642967 date='2018-04-22 02:21:26' progress=0.997051 cache=44.8MiB(94933txo)
 82018-04-25 03:30:32 UpdateTip: new best=000000000000000000092a3d5d1f401afd767f8a878d448cc7ec959ac8eb2182 height=519345 version=0x20000000 log2_work=88.642961 tx=311643052 date='2018-04-22 02:22:00' progress=0.997052 cache=44.9MiB(95094txo)
 92018-04-25 03:30:32 Pre-allocating up to position 0x8000000 in blk01243.dat
102018-04-25 03:30:33 Leaving block file 1243: CBlockFileInfo(blocks=227, size=133602259, heights=519206...519508, time=2018-04-21...2018-04-23)
112018-04-25 03:30:34 Pre-allocating up to position 0x1000000 in blk01244.dat
122018-04-25 03:30:35 Pre-allocating up to position 0x2000000 in blk01244.dat
132018-04-25 03:30:35 Pre-allocating up to position 0x3000000 in blk01244.dat
142018-04-25 03:30:36 Pre-allocating up to position 0x4000000 in blk01244.dat
152018-04-25 03:30:37 Pre-allocating up to position 0x5000000 in blk01244.dat
162018-04-25 03:30:39 Pre-allocating up to position 0x6000000 in blk01244.dat
172018-04-25 03:30:40 Pre-allocating up to position 0x7000000 in blk01244.dat
182018-04-25 03:30:42 Pre-allocating up to position 0x8000000 in blk01244.dat
192018-04-25 03:30:44 Leaving block file 1244: CBlockFileInfo(blocks=161, size=133452832, heights=519455...519733, time=2018-04-22...2018-04-24)
202018-04-25 03:30:45 Pre-allocating up to position 0x1000000 in blk01245.dat
212018-04-25 03:30:45 Pre-allocating up to position 0x2000000 in blk01245.dat
222018-04-25 03:30:47 Pre-allocating up to position 0x3000000 in blk01245.dat
232018-04-25 03:30:48 Pre-allocating up to position 0x4000000 in blk01245.dat
242018-04-25 03:30:49 Pre-allocating up to position 0x5000000 in blk01245.dat
252018-04-25 03:30:51 Pre-allocating up to position 0x6000000 in blk01245.dat
262018-04-25 03:30:54 Pre-allocating up to position 0x7000000 in blk01245.dat
272018-04-25 03:30:58 Pre-allocating up to position 0x8000000 in blk01245.dat
282018-04-25 03:31:01 Leaving block file 1245: CBlockFileInfo(blocks=142, size=133160497, heights=519575...519825, time=2018-04-23...2018-04-25)
292018-04-25 03:31:02 Pre-allocating up to position 0x1000000 in blk01246.dat
302018-04-25 03:31:10 Pre-allocating up to position 0x2000000 in blk01246.dat
312018-04-25 03:32:08 New outbound peer connected: version: 70015, blocks=519825, peer=39
322018-04-25 03:32:31 socket recv error An existing connection was forcibly closed by the remote host.  (10054)
332018-04-25 03:35:59 Pre-allocating up to position 0x100000 in rev01246.dat
342018-04-25 03:36:00 UpdateTip: new best=00000000000000000013f1cca09ffd0858197acc2464de6431c4344590261a8c height=519346 version=0x20000000 log2_work=88.64301 tx=311643927 date='2018-04-22 02:31:50' progress=0.997054 cache=45.4MiB(99165txo)
352018-04-25 03:39:20 socket recv error An existing connection was forcibly closed by the remote host.  (10054)
362018-04-25 03:45:59 Timeout downloading block 00000000000000000014281bac3293465d9bf4d963e394dfa690b94cd0c8c823 from peer=33, disconnecting
372018-04-25 03:46:04 UpdateTip: new best=00000000000000000014281bac3293465d9bf4d963e394dfa690b94cd0c8c823 height=519347 version=0x20000000 log2_work=88.643059 tx=311645894 date='2018-04-22 02:55:03' progress=0.997063 cache=46.1MiB(105259txo)
382018-04-25 03:46:05 UpdateTip: new best=0000000000000000001e30f3d4592587aaa2f196dcec3f804f9f0d7ae8c48473 height=519348 version=0x20000000 log2_work=88.643108 tx=311646931 date='2018-04-22 03:05:58' progress=0.997071 cache=46.4MiB(107332txo)
392018-04-25 03:46:05 UpdateTip: new best=00000000000000000046fcfed8a197895e183d9f7847c12bae50d8bee326d9bc height=519349 version=0x20000000 log2_work=88.643157 tx=311647294 date='2018-04-22 03:09:57' progress=0.997073 cache=46.5MiB(108154txo)
402018-04-25 03:46:05 UpdateTip: new best=00000000000000000008a7be394ba2dd995937d5a34178c49ae8ea44f42370f1 height=519350 version=0x20000000 log2_work=88.643207 tx=311647536 date='2018-04-22 03:12:07' progress=0.997075 cache=46.5MiB(108266txo)

As you can see, as soon as the block timed out, it began immediately processing blocks quickly again.

devrandom commented at 11:50 pm on February 2, 2019: none

This is happening to us also, causing nodes to fall several minutes behind the rest of the network.

cryptozeny commented at 5:54 pm on October 11, 2019: none

same here. 0.16.3

ArmchairCryptologist commented at 12:08 pm on January 16, 2021: none

This is still an issue with 0.19.1, 0.20.1 and 0.21.0.

2021-01-16T10:39:39Z Bitcoin Core version v0.21.0 (release build) … 2021-01-16T10:39:59Z UpdateTip: new best=0000000000000000000265aabf47a3b5300ce0805a734eec3d292dbcd2e89b23 height=666315 version=0x20000000 log2_work=92.595927 tx=606832523 date=‘2021-01-16T10:39:27Z’ progress=1.000000 cache=1.5MiB(11452txo) … 2021-01-16T10:48:05Z Imported mempool transactions from disk: 40399 succeeded, 1298 failed, 0 expired, 163 already there, 0 waiting for initial broadcast 2021-01-16T10:48:05Z loadblk thread exit 2021-01-16T10:51:16Z Timeout downloading block 00000000000000000005607d0c14ae56e270c08c274c3fee4098b5fd72f078cd from peer=31, disconnecting 2021-01-16T10:51:17Z Pre-allocating up to position 0x600000 in rev02410.dat 2021-01-16T10:51:17Z UpdateTip: new best=00000000000000000005607d0c14ae56e270c08c274c3fee4098b5fd72f078cd height=666316 version=0x20400000 log2_work=92.595944 tx=606835067 date=‘2021-01-16T10:40:39Z’ progress=0.999996 cache=69.8MiB(515269txo) 2021-01-16T10:51:17Z UpdateTip: new best=00000000000000000003eb2a6832a160e81516d7ac19736ea30757d49f467b8e height=666317 version=0x20000000 log2_work=92.595961 tx=606836582 date=‘2021-01-16T10:44:50Z’ progress=0.999998 cache=70.2MiB(518353txo) 2021-01-16T10:51:18Z UpdateTip: new best=0000000000000000000d77200b5ec9931f1fd1ece25a9094e2f9ef6f1d58ae81 height=666318 version=0x20000000 log2_work=92.595978 tx=606838024 date=‘2021-01-16T10:49:31Z’ progress=0.999999 cache=70.6MiB(521729txo) 2021-01-16T10:51:18Z UpdateTip: new best=0000000000000000000a3611505f398c44691c9708b394e6cba9ea0f84d82997 height=666319 version=0x20006000 log2_work=92.595995 tx=606838504 date=‘2021-01-16T10:50:42Z’ progress=1.000000 cache=70.7MiB(522455txo)

Presumably you might be able to trigger this artificially, which could be a DoS vector. Of course you want to have your mining and/or financial nodes behind proxy nodes, but this should probably be made more robust anyway.

vostrnad commented at 11:18 pm on September 28, 2022: none

Still an issue in 23.0.0:

 02022-09-28T17:04:29Z Timeout downloading block 000000000000000000054983c3ecbf4ab64b6eaa24047283866641adf75e554d from peer=12, disconnecting
 12022-09-28T17:04:37Z UpdateTip: new best=000000000000000000054983c3ecbf4ab64b6eaa24047283866641adf75e554d height=756096 version=0x30910000 log2_work=93.754409 tx=768034487 date='2022-09-28T16:54:02Z' progress=0.999998 cache=1.9MiB(14439txo)
 22022-09-28T17:04:38Z UpdateTip: new best=0000000000000000000042e8e6b6930c51be915d00f25cf9e69f4275aef5d219 height=756097 version=0x23fac004 log2_work=93.754421 tx=768036470 date='2022-09-28T17:02:22Z' progress=0.999999 cache=3.1MiB(22348txo)
 3--
 42022-09-28T19:52:59Z Timeout downloading block 00000000000000000002655a29cce1bca01ad32b94cedbdc259713a7d317b26d from peer=127, disconnecting
 52022-09-28T19:53:01Z UpdateTip: new best=00000000000000000002655a29cce1bca01ad32b94cedbdc259713a7d317b26d height=756109 version=0x2be76004 log2_work=93.754560 tx=768069529 date='2022-09-28T19:42:20Z' progress=0.999998 cache=21.7MiB(165008txo)
 62022-09-28T19:53:02Z UpdateTip: new best=000000000000000000061bcd14e23c3257b4a7485a6833961edf6a2bfb5e35ad height=756110 version=0x20010000 log2_work=93.754572 tx=768073071 date='2022-09-28T19:50:30Z' progress=0.999999 cache=22.4MiB(170948txo)
 7--
 82022-09-28T22:41:07Z Timeout downloading block 000000000000000000050ec6c52f88d83bb83fcc5325a78ba988c1f4b5e3c0c9 from peer=1178, disconnecting
 92022-09-28T22:41:11Z UpdateTip: new best=000000000000000000050ec6c52f88d83bb83fcc5325a78ba988c1f4b5e3c0c9 height=756127 version=0x2a212004 log2_work=93.754770 tx=768107899 date='2022-09-28T22:30:42Z' progress=0.999998 cache=36.3MiB(272873txo)
10--
112022-09-28T22:52:42Z Timeout downloading block 00000000000000000001f5f02c6cfc085dcbf72976a97fb4499bb80b0b2acb18 from peer=2319, disconnecting
122022-09-28T22:52:53Z UpdateTip: new best=00000000000000000001f5f02c6cfc085dcbf72976a97fb4499bb80b0b2acb18 height=756128 version=0x20000004 log2_work=93.754781 tx=768109891 date='2022-09-28T22:42:12Z' progress=0.999998 cache=37.0MiB(278485txo)
13--
142022-09-28T23:15:34Z Timeout downloading block 0000000000000000000106bcea88f31ac3294e19f85f1b34c0b596ae8fed107d from peer=2387, disconnecting
152022-09-28T23:15:45Z UpdateTip: new best=0000000000000000000106bcea88f31ac3294e19f85f1b34c0b596ae8fed107d height=756129 version=0x20002000 log2_work=93.754793 tx=768112863 date='2022-09-28T23:04:58Z' progress=0.999998 cache=38.3MiB(289178txo)
162022-09-28T23:15:49Z UpdateTip: new best=00000000000000000004cb8821e68b93ebdffb41ff08837f5443b2ea7f6df2eb height=756130 version=0x20a00000 log2_work=93.754805 tx=768114095 date='2022-09-28T23:08:35Z' progress=0.999998 cache=38.5MiB(290610txo)
172022-09-28T23:15:49Z UpdateTip: new best=00000000000000000003304c1e41c94922187ecc7f218faf1a89cac0937b7d9d height=756131 version=0x20000000 log2_work=93.754816 tx=768114969 date='2022-09-28T23:13:20Z' progress=0.999999 cache=38.8MiB(292583txo)
18--
192022-09-28T23:30:45Z Timeout downloading block 00000000000000000007eccd8a8ec790378d3e87f5ba441fe449c437be5f5b6d from peer=2527, disconnecting
202022-09-28T23:30:46Z UpdateTip: new best=00000000000000000007eccd8a8ec790378d3e87f5ba441fe449c437be5f5b6d height=756132 version=0x27ffe000 log2_work=93.754828 tx=768116084 date='2022-09-28T23:20:26Z' progress=0.999998 cache=39.6MiB(299029txo)
21--
222022-09-28T23:42:52Z Timeout downloading block 000000000000000000064cd214a2ecb86e4c186c3ea3404ea406c9cde0e5c910 from peer=2606, disconnecting
232022-09-28T23:42:54Z UpdateTip: new best=000000000000000000064cd214a2ecb86e4c186c3ea3404ea406c9cde0e5c910 height=756134 version=0x20014000 log2_work=93.754851 tx=768117930 date='2022-09-28T23:32:22Z' progress=0.999998 cache=40.7MiB(307978txo)
242022-09-28T23:42:54Z UpdateTip: new best=000000000000000000055a919a7c8aa9a70a937cb12f7641ef2e7ed1cf727882 height=756135 version=0x2d0a6000 log2_work=93.754863 tx=768118304 date='2022-09-28T23:34:52Z' progress=0.999998 cache=40.7MiB(308630txo)

0xB10C commented at 8:55 am on January 18, 2024: contributor

Is this fixed with #27626?

cc @instagibbs

ArmchairCryptologist commented at 9:23 am on January 18, 2024: none

Looks good to me. Grepping the debug logs, I’m not seeing any block download timeouts on my public nodes with ~500 incoming connections each since updating to 26.0 early December, except for once on one node, which occurred shortly after startup and before the mempool had finished loading. It looks like it didn’t have a lot of peers when the block arrived, so that’s probably not a real concern.

instagibbs commented at 1:23 pm on January 18, 2024: member

@ArmchairCryptologist matches expectations. Any single stalling peer at chaintip should not stall node completely once your node is “warmed up” with compact block “high bandwidth” connections.

vostrnad commented at 1:50 pm on January 18, 2024: none

Looking through my logs, I’ve only had two block download timeouts since upgrading to 26.0, and both happened while synchronizing after a period of downtime. They did still cause the synchronization to stall for ~10 minutes each though.

Timeout downloading block #12291

What behavior did you expect?