Seemingly second (very long) validation at the same height

hMsats commented at 9:18 am on October 23, 2025: none

Bitcoin Core 30.0

I automatically measure the verification time between “Saw new header” or “Saw new cmpctblock header” and “UpdateTip:” for the same height in debug.log. Almost always that time difference is 0 or 1 second. However, at block 920139 I see a huge spike of 443 seconds. Turns out there is something strange happening for block 920138. Here’s what debug.log reports for this block:

02025-10-21T17:17:37Z Saw new cmpctblock header hash=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 peer=96259
12025-10-21T17:17:37Z UpdateTip: new best=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 version=0x28000000 log2_work=95.892695 tx=1259718316 date='2025-10-21T17:17:24Z' progress=1.000000 cache=276.8MiB(2069960txo)
22025-10-21T17:17:37Z Saw new header hash=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 peer=92507
32025-10-21T17:27:00Z UpdateTip: new best=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 version=0x3227a000 log2_work=95.892695 tx=1259718525 date='2025-10-21T17:17:07Z' progress=0.999995 cache=276.8MiB(2071109txo)

So there’s a “Saw new cmpctblock header” and almost immediately the UpdateTip as usual. However, at the same time a “Saw new header” comes in for that same height and now the verification takes almost 10 minutes and progress falls from 1.000000 to 0.999995. This looks to me like a double verification for the same height where the second verification takes much longer. Maybe it has something to do with a reorg, maybe this is normal behavior but I wanted to report it here just to be sure.

Below what happens around height 920138 in debug.log:

 02025-10-21T16:59:13Z Saw new cmpctblock header hash=00000000000000000000f640d1940946015764ddcc37a631d8aebe69301a79d2 height=920135 peer=99563
 12025-10-21T16:59:13Z UpdateTip: new best=00000000000000000000f640d1940946015764ddcc37a631d8aebe69301a79d2 height=920135 version=0x20052000 log2_work=95.892658 tx=1259707764 date='2025-10-21T16:58:20Z' progress=1.000000 cache=276.8MiB(2053530txo)
 22025-10-21T17:00:56Z New block-relay-only v2 peer connected: version: 70016, blocks=920135, peer=160571
 32025-10-21T17:01:43Z Saw new header hash=00000000000000000001317b451e3306a1b62bb0ceb1b81524f90f95c6c95186 height=920136 peer=15656
 42025-10-21T17:01:44Z UpdateTip: new best=00000000000000000001317b451e3306a1b62bb0ceb1b81524f90f95c6c95186 height=920136 version=0x206b6000 log2_work=95.892671 tx=1259710624 date='2025-10-21T17:00:47Z' progress=1.000000 cache=276.8MiB(2057507txo)
 52025-10-21T17:06:52Z New block-relay-only v2 peer connected: version: 70016, blocks=920136, peer=160814
 62025-10-21T17:12:36Z New block-relay-only v2 peer connected: version: 70016, blocks=920136, peer=161247
 72025-10-21T17:14:46Z [net:info] portmap: Added mapping pcp:95.99.132.155:8333 -> 192.168.1.20:8333 (for 2400s)
 82025-10-21T17:14:46Z AddLocal(95.99.132.155:8333,3)
 92025-10-21T17:15:13Z Saw new cmpctblock header hash=000000000000000000004f08e2501645727550d7474400a3fa0ff7013dcd4ea9 height=920137 peer=21
102025-10-21T17:15:13Z UpdateTip: new best=000000000000000000004f08e2501645727550d7474400a3fa0ff7013dcd4ea9 height=920137 version=0x200de000 log2_work=95.892683 tx=1259713766 date='2025-10-21T17:14:48Z' progress=1.000000 cache=276.8MiB(2065321txo)
112025-10-21T17:17:37Z Saw new cmpctblock header hash=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 peer=96259
122025-10-21T17:17:37Z UpdateTip: new best=00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691 height=920138 version=0x28000000 log2_work=95.892695 tx=1259718316 date='2025-10-21T17:17:24Z' progress=1.000000 cache=276.8MiB(2069960txo)
132025-10-21T17:17:37Z Saw new header hash=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 peer=92507
142025-10-21T17:19:37Z Saw new header hash=0000000000000000000004f6eb492f1e998b569a1940f690d0b691a2f4ba2d00 height=920139 peer=27652
152025-10-21T17:25:54Z Saw new header hash=00000000000000000000c183ce29bb73ddf8e00419ce437bfc58f0abd8d1b161 height=920140 peer=27652
162025-10-21T17:27:00Z UpdateTip: new best=000000000000000000004f08e2501645727550d7474400a3fa0ff7013dcd4ea9 height=920137 version=0x200de000 log2_work=95.892683 tx=1259713766 date='2025-10-21T17:14:48Z' progress=0.999992 cache=276.8MiB(2066586txo)
172025-10-21T17:27:00Z UpdateTip: new best=000000000000000000002e852c1cb8e698df53a4c2646115fbb73d78298b5b2c height=920138 version=0x3227a000 log2_work=95.892695 tx=1259718525 date='2025-10-21T17:17:07Z' progress=0.999995 cache=276.8MiB(2071109txo)
182025-10-21T17:27:00Z UpdateTip: new best=0000000000000000000004f6eb492f1e998b569a1940f690d0b691a2f4ba2d00 height=920139 version=0x202e2000 log2_work=95.892708 tx=1259722731 date='2025-10-21T17:19:29Z' progress=0.999997 cache=277.3MiB(2074876txo)
192025-10-21T17:27:01Z UpdateTip: new best=00000000000000000000c183ce29bb73ddf8e00419ce437bfc58f0abd8d1b161 height=920140 version=0x2c542000 log2_work=95.892720 tx=1259726559 date='2025-10-21T17:25:32Z' progress=1.000000 cache=277.8MiB(2079466txo)
202025-10-21T17:27:01Z txindex is catching up on block notifications
212025-10-21T17:27:01Z txindex is catching up on block notifications
222025-10-21T17:28:03Z Flushed fee estimates to fee_estimates.dat.
232025-10-21T17:32:07Z Saw new header hash=0000000000000000000005d578e2ed197675684b0e9d57e19081b18879179804 height=920141 peer=105484
242025-10-21T17:32:08Z UpdateTip: new best=0000000000000000000005d578e2ed197675684b0e9d57e19081b18879179804 height=920141 version=0x26000000 log2_work=95.892732 tx=1259730043 date='2025-10-21T17:31:56Z' progress=1.000000 cache=277.8MiB(2037404txo)

blckbx commented at 3:35 pm on October 23, 2025: none

Maybe it has something to do with a reorg, maybe this is normal behavior but I wanted to report it here just to be sure.

https://mempool.space/block/00000000000000000000a0eb867d25dd2e5284750888c545607d30aecc48c691

There was a stale block which has been replaced.

hMsats commented at 3:53 pm on October 23, 2025: none

@blckbx great, thanks a lot. But why did the second verification take so long? Is that because all the transactions were removed from the mempool when the first one was verified?

instagibbs commented at 3:57 pm on October 23, 2025: member

@hMsats It appears your peer was unable or unwilling to give the block for about 6 minutes.

Eventually the block was received and processed as usual. Taking a harder look at the scenario to see what we can do to overcome this during reorg scenarios.

fanquake added the label P2P on Oct 24, 2025

hMsats commented at 8:47 am on October 24, 2025: none

@instagibbs I think this problem of a peer unable or unwilling to give a block occasionally happens independent of reorgs, which was just an extreme example. Occasionally (not often) there are spikes which are so much larger than usual (for example: 191 seconds for block 920057 instead of the usual 0 or 1 seconds):

02025-10-21T05:16:07Z Saw new cmpctblock header hash=00000000000000000000d7a021b12e8660fbb5914cab65f17a25e20e3de80e3a height=920057 peer=15656
12025-10-21T05:19:18Z UpdateTip: new best=00000000000000000000d7a021b12e8660fbb5914cab65f17a25e20e3de80e3a height=920057 version=0x20090000 log2_work=95.891694 tx=1259474079 date='2025-10-21T05:15:33Z' progress=1.000000 cache=263.2MiB(1960087txo)

In this case there is no reorg. A general solution would really improve the network in my opinion.

instagibbs commented at 8:58 am on October 24, 2025: member

Typically a warmed-up node will have up to three “high bandwidth” peers who are allowed to hand block data, even if one of them is being slow. During this reorg, it appears likely that all the high bandwidth peers were on the “losing side” of this reorg along with your node, and were unable to help unstuck the node. There is a fallback 10 minute timeout that would have eventually helped if the slow peer doesn’t give you the block in time (you may see “Timeout downloading block” log)

hMsats commented at 3:04 pm on October 25, 2025: none

I’m now running/testing my node (starting cold) with:

0std::chrono::seconds{consensusParams.nPowTargetSpacing}/10 * (BLOCK_DOWNLOAD_TIMEOUT_BASE + BLOCK_DOWNLOAD_TIMEOUT_PER_PEER * nOtherPeersWithValidatedDownloads))

in net_processing.cpp, where I introduced the division by a factor of 10. So based on 1 minute timeout instead of 10 minutes. When my node was warm, I could even base it on a 6 seconds timeout without problems (I’ve tested with 1 second to see if the timeout message was visible in debug.log, and it was).

This value of 10 is a bit extreme but my gut feeling is that a factor of 5 (2 minute timeout) would still be conservative these days and a factor of 2 (5 minute timeout) would at least be an improvement.

Of course, more sophisticated solutions are possible.

I will report back whether I see any timeouts for a 1 minute timeout starting cold (meaning I removed anchors.dat, banlist.json, fee_estimates.dat, mempool.dat, peers.dat)

hMsats commented at 2:59 pm on October 27, 2025: none

After more than 48 hours, not a single timeout for a division by 10 (based on 1 minute or 600/10=60 seconds) and a cold start. For height, verification time, time and date and peer see here.

mzumsande commented at 4:08 pm on October 27, 2025: contributor

One reason why we haven’t simply lowered the timeout from 10 minutes is to not change the minimum required bandwidth to keep up with the network. In principle, a synced -blocksonly node with a bandwith so slow that they can only download ~2-4MB every 10minutes should be able to keep up with the tip today. If we changed the timeout, the minimum required bandwidth would change. I also encountered this argument in #29664 (which is a slightly different scenario than the reorg here).

In my opinion, this is more of an ideological than a practical argument though, and it is becoming increasingly unrealistic for the huge majority of cases. Maybe it could make sense to both lower the default, and make it possible to provide the timeout as a startup option, so that nodes on normal connections don’t run into this, while extremely slow nodes still have an option to sync.

davidgumberg commented at 2:43 am on March 26, 2026: contributor

I believe I can report another instance of this happening during a recent block race to one of @achow101’s nodes. An unusually behaving peer (constantly INV’s block hashes but never seems to give blocks) did not respond to a GETDATA request for a block, and the node was unlucky enough to have all of it’s HB peers on one side of the block race (I assume) so the node did not update to the most work tip for ~10 minutes.

The two ways to mitigate this seem to me:

Allocating more HB compact block slots
Allowing parallel block requests when close to the tip (#29664)

Some more details:

https://bnoc.xyz/t/two-block-reorg-at-height-941880/97/19

ajtowns commented at 9:21 am on March 26, 2026: contributor

One reason why we haven’t simply lowered the timeout from 10 minutes is to not change the minimum required bandwidth to keep up with the network. In principle, a synced -blocksonly node with a bandwith so slow that they can only download ~2-4MB every 10minutes should be able to keep up with the tip today.

1Mbps seems fairly commonly available which would be ~6MB/minute, so reducing the base timeout to 1min is probably reasonable, particularly if it were made configurable. Having it vary based on nPowTargetSpacing doesn’t make sense to me; the important factor seems like it’s the max serialized block size. Adding a request rather than disconnecting when we’re roughly at tip seems like it would be nicer too.

(This logic was introduced in #5608 if anyone’s interested and doesn’t want to spelunk themselves)

murchandamus commented at 5:18 pm on March 26, 2026: member

This log from Stacker News also seems to show the same issue:

 0  2026-03-23T15:48:16.791695+00:00 Saw new header hash=0000000000000000000199a739b635c5707a2bda57231b8abe846216ca0cc989 height=941880
 1  2026-03-23T15:48:16.796508+00:00 Saw new cmpctblock header hash=0000000000000000000199a739b635c5707a2bda57231b8abe846216ca0cc989 peer=626053
 2  2026-03-23T15:48:17.042500+00:00 UpdateTip: new best=0000000000000000000199a739b635c5707a2bda57231b8abe846216ca0cc989 height=941880 version=0x2d2b0000 log2_work=96.137372 tx=1326996390 date='2026-03-23T15:48:05Z' progress=1.000000 cache=896.3MiB(6532054txo) warning='Miner violated version bit protocol'
 3  2026-03-23T15:49:55.015110+00:00 Saw new header hash=00000000000000000001b3ff8b13e57c3ec1eca3ba7d2937edbd9f219eb2d9f3 height=941881
 4  2026-03-23T15:49:55.015110+00:00 Saw new cmpctblock header hash=00000000000000000001b3ff8b13e57c3ec1eca3ba7d2937edbd9f219eb2d9f3 peer=622173
 5  2026-03-23T15:49:55.757105+00:00 UpdateTip: new best=00000000000000000001b3ff8b13e57c3ec1eca3ba7d2937edbd9f219eb2d9f3 height=941881 version=0x3092c000 log2_work=96.137382 tx=1327000957 date='2026-03-23T15:49:35Z' progress=1.000000 cache=896.3MiB(6537057txo) warning='Miner violated version bit protocol'
 6  2026-03-23T15:51:47.084828+00:00 Saw new header hash=00000000000000000000c81cbf94a12ca498e72eb8530f7061c8746cf9687b2e height=941882
 7  2026-03-23T15:51:47.084828+00:00 Saw new cmpctblock header hash=00000000000000000000c81cbf94a12ca498e72eb8530f7061c8746cf9687b2e peer=626053
 8 ⇒2026-03-23T15:51:47.110255+00:00 Saw new header hash=00000000000000000000bd4930a5982911e7749eb491886206e71abdc1ec0cc6 height=941881
 9  2026-03-23T15:51:47.206283+00:00 UpdateTip: new best=00000000000000000000c81cbf94a12ca498e72eb8530f7061c8746cf9687b2e height=941882 version=0x2008c000 log2_work=96.137391 tx=1327001829 date='2026-03-23T15:51:19Z' progress=1.000000 cache=896.3MiB(6538057txo) warning='Miner violated version bit protocol'
10  2026-03-23T15:55:01.310669+00:00 Saw new header hash=00000000000000000000724eac69a18c6699c9f7aaab24bcf18beb2723ccadd2 height=941882
11  2026-03-23T15:55:07.053713+00:00 Saw new header hash=000000000000000000009c9acd0bc3207fa181f79f8573bf27d8a81d1ef3aa8e height=941883
12 ⇒2026-03-23T16:01:47.135347+00:00 Timeout downloading block 00000000000000000000bd4930a5982911e7749eb491886206e71abdc1ec0cc6, disconnecting peer=622260
13  2026-03-23T16:01:47.831926+00:00 UpdateTip: new best=00000000000000000001b3ff8b13e57c3ec1eca3ba7d2937edbd9f219eb2d9f3 height=941881 version=0x3092c000 log2_work=96.137382 tx=1327000957 date='2026-03-23T15:49:35Z' progress=0.999996 cache=896.3MiB(6537472txo) warning='Miner violated version bit protocol'
14  2026-03-23T16:01:47.910707+00:00 UpdateTip: new best=0000000000000000000199a739b635c5707a2bda57231b8abe846216ca0cc989 height=941880 version=0x2d2b0000 log2_work=96.137372 tx=1326996390 date='2026-03-23T15:48:05Z' progress=0.999996 cache=896.3MiB(6532636txo) warning='Miner violated version bit protocol'
15 ⇒2026-03-23T16:01:47.987276+00:00 UpdateTip: new best=00000000000000000000bd4930a5982911e7749eb491886206e71abdc1ec0cc6 height=941881 version=0x22cd4000 log2_work=96.137382 tx=1327000861 date='2026-03-23T15:49:47Z' progress=0.999996 cache=896.3MiB(6537499txo) warning='Miner violated version bit protocol'
16  2026-03-23T16:01:48.061103+00:00 UpdateTip: new best=00000000000000000000724eac69a18c6699c9f7aaab24bcf18beb2723ccadd2 height=941882 version=0x3427e000 log2_work=96.137391 tx=1327005400 date='2026-03-23T15:51:25Z' progress=0.999997 cache=896.8MiB(6541493txo) warning='Miner violated version bit protocol'
17  2026-03-23T16:01:48.205432+00:00 UpdateTip: new best=000000000000000000009c9acd0bc3207fa181f79f8573bf27d8a81d1ef3aa8e height=941883 version=0x2fc2e000 log2_work=96.137401 tx=1327009788 date='2026-03-23T15:54:49Z' progress=0.999998 cache=897.3MiB(6546690txo) warning='Miner violated version bit protocol'

I was just asking myself as well, why the time-out is still so long when blocks generally reach most nodes within a few seconds. 60 seconds seems like a big improvement, but for most nodes 30 seconds might be more appropriate?

ajtowns commented at 0:35 am on March 27, 2026: contributor

I was just asking myself as well, why the time-out is still so long when blocks generally reach most nodes within a few seconds. 60 seconds seems like a big improvement, but for most nodes 30 seconds might be more appropriate?

I think it’s a tradeoff – 1Mbps is ~20s for a 2MB block (normal) but ~40s for a 4MB block (data heavy), so a 30s limit might cause slow nodes to not be able to sync data heavy blocks at all (they get 3MB of the data received, then disconnect and don’t process any of the data they received at all, then do the same thing again with a different peer). If the timeout behaviour after 30s was changed to “request from an additional peer” rather than disconnect, that might be more plausible though?

darosior commented at 6:47 pm on March 27, 2026: member

(This logic was introduced in #5608 if anyone’s interested and doesn’t want to spelunk themselves)

This PR mentions IRC discussions, which i have gathered in this gist if anyone’s interested and doesn’t want to ferret them out themselves.

murchandamus commented at 10:40 pm on March 27, 2026: member

Oh yeah, I meant request from an additional peer! And configurable seems like a good idea so people on slow lines can increase it.

Seemingly second (very long) validation at the same height #33687