block download stall at 998938 #8971

Last new best was block 00000000009f9e3d0031fb6ba1d5ce398c74430d5f772a50046638016511e70e (998938).

Running on testnet, Bitcoin version v0.13.0.0-b248185-dirty

the first entry in debug.log for a block of height 998937 is:-

2016-10-19 06:02:18.179519 recv header 0000000000224e8e56f92315d1ca0584d6e8c09d443c480947e71c737ffc1580 (998937)

This is the first time this block hash is seen. It does not trigger a getdata block request. Instead another header is received, with a lower height, which does trigger a getdata and the block arriving:-

2016-10-19 06:02:19.762340 recv header 00000000001e98549fe7313de57caf4713e72c3a55b813261d0611ab09812028 (998695) 2016-10-19 06:02:19.762378 send getdata block 00000000001e98549fe7313de57caf4713e72c3a55b813261d0611ab09812028 (998695) 2016-10-19 06:02:20.023983 recv block 00000000001e98549fe7313de57caf4713e72c3a55b813261d0611ab09812028 (998695) 2016-10-19 06:02:20.024308 UpdateTip: new best=00000000001e98549fe7313de57caf4713e72c3a55b813261d0611ab09812028 (998695) ver=0x20000000 date=2016-10-19 08:02:02 tx=1 100.000215%

Then we see a header for a block with a higher height, but this doesn't trigger a getdata:-

2016-10-19 06:02:23.738059 recv header 00000000001cd44adf20b47ea48fbc8524c0516a87517814edcd51fb07f947fe (998938)

and following this, subsequent blocks increasing in height. So there seems to be more than one block of height 998938 so far.

The first time the block that is currently the new best is seen is at:-

2016-10-19 06:15:58.246604 recv header 00000000009f9e3d0031fb6ba1d5ce398c74430d5f772a50046638016511e70e (998938) 2016-10-19 06:15:58.246651 send getdata block 00000000009f9e3d0031fb6ba1d5ce398c74430d5f772a50046638016511e70e (998938) 2016-10-19 06:15:58.507754 recv block 00000000009f9e3d0031fb6ba1d5ce398c74430d5f772a50046638016511e70e (998938) 2016-10-19 06:15:58.508065 UpdateTip: new best=00000000009f9e3d0031fb6ba1d5ce398c74430d5f772a50046638016511e70e (998938) ver=0x20000000 date=2016-10-19 08:15:33 tx=1 100.000214%

and this is the last time my node sends a getdata block request.

The next time we see any mention of a block height of 998938 is at:-

2016-10-19 06:17:43.387921 recv header 00000000003f6d0285755d48676148792103833d8e5a97cd8e7a7953f16fb21e (998938)

which again is a different block hash (a 3rd one for this height) indicating at least 3 branches from an earlier block. The header above is seen in a block of headers from 000000000094b95002d22956ca9fd21a4cc08dc29c94458d5d818160491c6046 (998568) to 000000000074d98c42a13cb1203a40a27bb7f4db6c07013c935b9beba0980c5d (999104), all of which are already in the BlockIndex. The next header received is a new one (i.e. not in the BlockIndex), 000000000038dfcf8b810293acf32a6737bb3a025324b38693fdff3497fa0553 (999105).

Next a sequence of headers (already in the BlockIndex are received), 000000000094b95002d22956ca9fd21a4cc08dc29c94458d5d818160491c6046 (998568) to 000000000038dfcf8b810293acf32a6737bb3a025324b38693fdff3497fa0553 (999105), all from the same peer so far, but then a new header is received: 0000000000c0cedcecb5b226bf6775dd62d3c5ebbfb779c024e7d410d894cada (999106), followed by several more new headers until 0000000000ee976e05798ea2def35b444f5d02255ec858a019bedbda81d9d533 (999112).

Still debugging this to try to unravel what is going on....

Seems this might not be a problem, but perhaps highlights that some additional debug would help to see why no getdata blocks were sent.

With hindsight we can now see that block 00000000008de23f76f653be1dff8dd6ebc4bf5d6e5b915cc837734af498afb4 (998939) is the next block to follow, and this is not seen on the network until:-

2016-10-19 09:08:26.633713 recv header 00000000008de23f76f653be1dff8dd6ebc4bf5d6e5b915cc837734af498afb4 (998939)

which is then requested and becomes the new best:-

2016-10-19 09:08:32.180607 UpdateTip: new best=00000000008de23f76f653be1dff8dd6ebc4bf5d6e5b915cc837734af498afb4 (998939) ver=0x20000000 date=2016-10-19 09:08:37 tx=487 100.000000%

What was confusing is that other headers received after the new best 998938 with block height 998939 (but not the "official" 998939) are still shown in the debug but not distinguished as a different branch, e.g.:-

2016-10-19 06:02:24.018650 recv header 00000000001f7b5d22d081021658e78fb2cde7ff86ccae65d62f66ab916d38cb (998939) 2016-10-19 06:17:43.387935 recv header 00000000005c7500961a079c049c0bfb254585a7dd360364bf46ab3f0ef4e7a5 (998939)

which upon first glance make it appear that block fetching is broken. Will work on a PR that will add a debug message to distinguish between main chain and alt chains. Changing subject of this issue to signify that this is simply a debug ambiguity.