trying to sync new testnet node - failing due to "stalling block download"

[dooglus]

I've been trying to sync testnet for a few weeks now. It keeps getting stuck. The logs are full of messages about "stalling block download".

Here's an example:

2017-08-12 21:59:29 Loaded 31249 addresses from peers.dat  144ms
2017-08-12 21:59:29 init message: Loading banlist...
2017-08-12 21:59:30 init message: Starting network threads...
2017-08-12 21:59:30 net thread start
2017-08-12 21:59:30 dnsseed thread start
2017-08-12 21:59:30 addcon thread start
2017-08-12 21:59:30 init message: Done loading
2017-08-12 21:59:30 msghand thread start
2017-08-12 21:59:30 opencon thread start
2017-08-12 21:59:30 GUI: Platform customization: "other"
2017-08-12 21:59:30 GUI: PaymentServer::LoadRootCAs: Loaded  170  root certificates
2017-08-12 21:59:30 receive version message: /Satoshi:0.13.2/: version 70015, blocks=1176613, us=<my-ip>:32239, peer=0
2017-08-12 21:59:31 receive version message: /Satoshi:0.13.2/: version 70015, blocks=1176613, us=<my-ip>:15189, peer=1
2017-08-12 21:59:32 ProcessMessages(version, 102 bytes) FAILED peer=2
2017-08-12 21:59:32 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:16892, peer=3
2017-08-12 21:59:33 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:29573, peer=4
2017-08-12 21:59:33 Peer=0 is stalling block download, disconnecting
2017-08-12 21:59:34 receive version message: /Satoshi:0.14.0/: version 70015, blocks=1176613, us=<my-ip>:29163, peer=5
2017-08-12 21:59:34 connect() to [2602:306:3718:2560:31c5:6402:4150:fe74]:18333 failed: Network is unreachable (101)
2017-08-12 21:59:35 connect() to [2001:0:9d38:6abd:3c72:2f62:f5ff:fffb]:18333 failed: Network is unreachable (101)
2017-08-12 21:59:35 Peer=1 is stalling block download, disconnecting
2017-08-12 21:59:35 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:13541, peer=6
2017-08-12 21:59:36 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:31431, peer=7
2017-08-12 21:59:37 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:16946, peer=8
2017-08-12 21:59:37 receive version message: /Satoshi:0.14.1(UASF-SegWit-BIP148)/: version 70015, blocks=1176613, us=<my-ip>:1524, peer=9
2017-08-12 21:59:38 Peer=3 is stalling block download, disconnecting
2017-08-12 21:59:40 Peer=4 is stalling block download, disconnecting
2017-08-12 21:59:41 P2P peers available. Skipped DNS seeding.
2017-08-12 21:59:41 dnsseed thread exit
2017-08-12 21:59:42 Peer=5 is stalling block download, disconnecting
2017-08-12 21:59:44 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:19638, peer=10
2017-08-12 21:59:44 Peer=6 is stalling block download, disconnecting
2017-08-12 21:59:46 Peer=7 is stalling block download, disconnecting
2017-08-12 21:59:48 Peer=8 is stalling block download, disconnecting
2017-08-12 21:59:50 receive version message: /Satoshi:0.14.1/: version 70015, blocks=1176613, us=<my-ip>:31236, peer=11
2017-08-12 21:59:50 Peer=9 is stalling block download, disconnecting
2017-08-12 21:59:52 Peer=10 is stalling block download, disconnecting
2017-08-12 21:59:56 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:1951, peer=12
2017-08-12 21:59:57 receive version message: /Satoshi:0.13.2/: version 70015, blocks=1176613, us=<my-ip>:17679, peer=13
2017-08-12 21:59:57 receive version message: /Satoshi:0.14.0/: version 70015, blocks=1176613, us=<my-ip>:12698, peer=14
2017-08-12 21:59:58 connect() to [2001:0:9d38:6ab8:2c22:7efc:46f0:c0b2]:18333 failed: Network is unreachable (101)
2017-08-12 21:59:59 Peer=11 is stalling block download, disconnecting
2017-08-12 21:59:59 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:14820, peer=15
2017-08-12 21:59:59 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176613, us=<my-ip>:22808, peer=16
2017-08-12 22:00:00 receive version message: /Satoshi:0.13.0/: version 70014, blocks=1176614, us=<my-ip>:18306, peer=17
2017-08-12 22:00:01 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176614, us=<my-ip>:13932, peer=18
2017-08-12 22:00:01 Peer=12 is stalling block download, disconnecting
2017-08-12 22:00:01 connect() to [2001:0:5ef5:79fd:2826:209:d9b2:d42f]:18333 failed: Network is unreachable (101)
2017-08-12 22:00:03 Peer=13 is stalling block download, disconnecting
2017-08-12 22:00:05 Peer=14 is stalling block download, disconnecting
2017-08-12 22:00:07 connect() to [2001:0:9d38:90d7:3060:a2:ace1:d935]:18333 failed: Network is unreachable (101)
2017-08-12 22:00:07 Peer=15 is stalling block download, disconnecting
2017-08-12 22:00:08 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176614, us=<my-ip>:6427, peer=19
2017-08-12 22:00:09 receive version message: /Satoshi:0.14.0/: version 70015, blocks=1176614, us=<my-ip>:4919, peer=20
2017-08-12 22:00:09 receive version message: /Satoshi:0.13.0/: version 70014, blocks=1096309, us=<my-ip>:15127, peer=21
2017-08-12 22:00:09 Peer=16 is stalling block download, disconnecting
2017-08-12 22:00:10 receive version message: /Satoshi:0.14.1/: version 70015, blocks=1176614, us=<my-ip>:28165, peer=22
2017-08-12 22:00:11 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176614, us=<my-ip>:17486, peer=23
2017-08-12 22:00:11 receive version message: /Satoshi:0.13.2/: version 70015, blocks=1176614, us=<my-ip>:25716, peer=24
2017-08-12 22:00:12 Peer=17 is stalling block download, disconnecting
2017-08-12 22:00:12 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176614, us=<my-ip>:22900, peer=25
2017-08-12 22:00:14 Peer=18 is stalling block download, disconnecting
2017-08-12 22:00:16 Peer=19 is stalling block download, disconnecting
2017-08-12 22:00:18 Peer=20 is stalling block download, disconnecting

I built from source on Linux, against tag v0.14.2.

Three minutes later I've still not made any progress:

2017-08-12 22:02:56 Peer=74 is stalling block download, disconnecting
2017-08-12 22:02:57 receive version message: /Satoshi:0.13.99/: version 70015, blocks=1176617, us=<my-ip>:18117, peer=77
2017-08-12 22:02:59 Peer=75 is stalling block download, disconnecting
2017-08-12 22:03:01 Peer=76 is stalling block download, disconnecting
2017-08-12 22:03:03 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176617, us=<my-ip>:22069, peer=78
2017-08-12 22:03:04 receive version message: /bcoin:v1.0.0-beta.12/: version 70015, blocks=1166749, us=<my-ip>:26790, peer=79
2017-08-12 22:03:05 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176617, us=<my-ip>:29893, peer=80
2017-08-12 22:03:05 Peer=77 is stalling block download, disconnecting
2017-08-12 22:03:05 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176617, us=<my-ip>:13425, peer=81
2017-08-12 22:03:06 connect() to [2003:78:ef5f:4c00:55ab:d1f0:9b1d:ca53]:18333 failed: Network is unreachable (101)
2017-08-12 22:03:07 Peer=78 is stalling block download, disconnecting
2017-08-12 22:03:07 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176617, us=<my-ip>:29658, peer=82
2017-08-12 22:03:09 Peer=80 is stalling block download, disconnecting
2017-08-12 22:03:12 Peer=81 is stalling block download, disconnecting
2017-08-12 22:03:14 Peer=79 is stalling block download, disconnecting

Is this a problem with testnet? With having segregated witness activated? With my Internet being a bit laggy?

[maflcko]

Adding reference to #9213

[dooglus]

@MarcoFalke I see I already mentioned this in #9213. I forgot that I had done that.

I am running a mainnet Bitcoin Core node, also v0.14.2, and don't see this issue there. I also don't see it with my Bitcoin Cash node:

$ ls -lh ~/.bitcoin/debug.log
-rw------- 1 chris chris 15M Aug 12 15:09 /home/chris/.bitcoin/debug.log
$ grep 'stalling block download' ~/.bitcoin/debug.log
$ 

$ ls -lh ~/.bitcoin-cash/debug.log
-rw------- 1 chris chris 967K Aug 12 15:12 /home/chris/.bitcoin-cash/debug.log
$ grep 'stalling block download' ~/.bitcoin-cash/debug.log
$ 

I have made a copy of my testnet3 directory, and am willing to run any tests that could help diagnose the problem.

[sdaftuar]

If it's the same issue that I think is causing #9213 then I think you can bypass this behavior by restarting your bitcoind and limiting it to just one outbound peer (either with -connect= or -maxconnections=1 or equivalent).

My guess is that your node is in a state where it's missing fewer than 16 blocks out of a group of 1024 or whatever the current download window is, and so on startup it immediately tries to download all from the first peer, and then when the second connection comes up it marks the first peer as stalling, causing a very quick timeout, which then repeats...

If this guess is right then you'll see your node download a few blocks; the tip should advance by about 1000; and then all should be right with the world again if you restart without the outbound peer limitation.

[dooglus]

I'll try that, thanks.

So far I tried changing the timeout from 2 seconds to 10. It didn't help. It takes 10 seconds per peer to disconnect them, but still doesn't get any blocks:

2017-08-13 00:34:41 disconnecting peer=73
2017-08-13 00:34:41 trying connection <...>:18333 lastseen=2.8hrs
2017-08-13 00:34:41 Requesting block 0000000000003b574f8236ef7a501a15dd081e802436ac7b906687166f6c06c2 (949517) peer=74
2017-08-13 00:34:41 Requesting block 000000000000362d2a35a6fd1f7eac11f8ae69dfcef3822d7beb2acc73bc0626 (949518) peer=74
2017-08-13 00:34:41 Requesting block 000000000000252a3f81158c50fde7319e4ded74518cf2b8eb57975579f92188 (949519) peer=74
2017-08-13 00:34:41 Requesting block 0000000000002089d098bb3e13375fbd644fce3c6ab2fc7f418148dcbce86201 (949520) peer=74
2017-08-13 00:34:41 Requesting block 000000000000123d6d5d45ceb8b8ee7fd50db35683c0aa58dbe48a3f143b3f2d (949521) peer=74
2017-08-13 00:34:41 Requesting block 000000000000362be28b8a2098618e73fdc997517423a1e37dfdae291e7c9daa (949522) peer=74
2017-08-13 00:34:41 Requesting block 00000000000003996787ac4521eab881f83eacd246b61f3711bb30af539bb98a (949523) peer=74
2017-08-13 00:34:41 Requesting block 0000000000003e33ca98e7a5ec0f06eb54f38cac568cdfdca7be1ce517853d1e (949525) peer=74
2017-08-13 00:34:41 Requesting block 0000000003c386117351c9c1055d7cf44204f7293202a4e6b5376e191183a7a7 (950526) peer=74
2017-08-13 00:34:41 Requesting block 000000000000ac8c06080fe99268e2abe1ce27f54dd77a9ea26446fef0d42851 (950528) peer=74
2017-08-13 00:34:41 Requesting block 0000000000bc5b9a87cb585f87c5252da8e5ba71073ba3a9ec3f8d49d6e1d0fe (950529) peer=74
2017-08-13 00:34:41 Requesting block 0000000024f67fb24e2cce7b3c4d28211534bd4d043851767de9ce131687085a (950532) peer=74
2017-08-13 00:34:41 Requesting block 000000001d531674d97eccf31ddfcc112c0acc28a624ef6ec6855728fb5c0122 (950534) peer=74
2017-08-13 00:34:41 Requesting block 00000000237a61bd1b3c1e5691cfd2909246c6dd6f59b139a44f3202bcd6c8b1 (950536) peer=74
2017-08-13 00:34:41 Requesting block 000000001553a1f9a2c3c79f028c8c10affb401406716e5fb2bef94a45384b52 (950538) peer=74
2017-08-13 00:34:41 Requesting block 000000001f205b8e71f0fb634bc8b12e0684beb0ade2a05849b2f17dd39ddcc9 (950540) peer=74
2017-08-13 00:34:41 sending getdata (577 bytes) peer=74
2017-08-13 00:34:41 Stall started peer=74
2017-08-13 00:34:41 Added connection peer=77
2017-08-13 00:34:41 sending version (108 bytes) peer=77
2017-08-13 00:34:41 send version message: version 70015, blocks=949516, us=[::]:0, peer=77
2017-08-13 00:34:41 received: version (102 bytes) peer=77
2017-08-13 00:34:41 sending verack (0 bytes) peer=77
2017-08-13 00:34:41 sending getaddr (0 bytes) peer=77
2017-08-13 00:34:41 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176840, us=<my-ip>:6096, peer=77
2017-08-13 00:34:41 added time data, samples 79, offset +0 (+0 minutes)
2017-08-13 00:34:41 -8544797  -1130  -25  -21  -18  -6  -3  -2  -1  -1  -1  -1  -1  -1  -1  -1  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +1  +5  +7  +15  +39  +59  +73  +366  |  nTimeOffset = +0  (+0 minutes)
2017-08-13 00:34:41 received: verack (0 bytes) peer=77
2017-08-13 00:34:41 sending sendheaders (0 bytes) peer=77
2017-08-13 00:34:41 sending sendcmpct (9 bytes) peer=77
2017-08-13 00:34:41 sending sendcmpct (9 bytes) peer=77
2017-08-13 00:34:41 sending ping (8 bytes) peer=77
2017-08-13 00:34:41 initial getheaders (1176839) to peer=77 (startheight:1176840)
2017-08-13 00:34:41 sending getheaders (1061 bytes) peer=77
2017-08-13 00:34:41 sending feefilter (8 bytes) peer=77
2017-08-13 00:34:41 received: sendheaders (0 bytes) peer=77
2017-08-13 00:34:41 received: sendcmpct (9 bytes) peer=77
2017-08-13 00:34:41 received: sendcmpct (9 bytes) peer=77
2017-08-13 00:34:41 received: ping (8 bytes) peer=77
2017-08-13 00:34:41 sending pong (8 bytes) peer=77
2017-08-13 00:34:41 received: addr (31 bytes) peer=77
2017-08-13 00:34:41 received: getheaders (1061 bytes) peer=77
2017-08-13 00:34:41 Ignoring getheaders from peer=77 because node is in initial block download
2017-08-13 00:34:41 received: feefilter (8 bytes) peer=77
2017-08-13 00:34:41 received: feefilter of 0.00001000 BTC/kB from peer=77
2017-08-13 00:34:41 received: pong (8 bytes) peer=77
2017-08-13 00:34:41 received: headers (82 bytes) peer=77
2017-08-13 00:34:43 received: inv (37 bytes) peer=22
2017-08-13 00:34:43 got inv: tx 7fdc4daf560725973463d546bec406e3709c5c99940df7bb67ed7377b20f0949  new peer=22
2017-08-13 00:34:45 received: ping (8 bytes) peer=65
2017-08-13 00:34:45 sending pong (8 bytes) peer=65
2017-08-13 00:34:45 sending ping (8 bytes) peer=65
2017-08-13 00:34:45 received: pong (8 bytes) peer=65
2017-08-13 00:34:48 received: inv (37 bytes) peer=44
2017-08-13 00:34:48 got inv: tx 7fdc4daf560725973463d546bec406e3709c5c99940df7bb67ed7377b20f0949  new peer=44
2017-08-13 00:34:51 Peer=74 is stalling block download, disconnecting
2017-08-13 00:34:51 disconnecting peer=74
2017-08-13 00:34:51 Requesting block 0000000000003b574f8236ef7a501a15dd081e802436ac7b906687166f6c06c2 (949517) peer=75
2017-08-13 00:34:51 Requesting block 000000000000362d2a35a6fd1f7eac11f8ae69dfcef3822d7beb2acc73bc0626 (949518) peer=75
2017-08-13 00:34:51 Requesting block 000000000000252a3f81158c50fde7319e4ded74518cf2b8eb57975579f92188 (949519) peer=75
2017-08-13 00:34:51 Requesting block 0000000000002089d098bb3e13375fbd644fce3c6ab2fc7f418148dcbce86201 (949520) peer=75
2017-08-13 00:34:51 Requesting block 000000000000123d6d5d45ceb8b8ee7fd50db35683c0aa58dbe48a3f143b3f2d (949521) peer=75
2017-08-13 00:34:51 Requesting block 000000000000362be28b8a2098618e73fdc997517423a1e37dfdae291e7c9daa (949522) peer=75
2017-08-13 00:34:51 Requesting block 00000000000003996787ac4521eab881f83eacd246b61f3711bb30af539bb98a (949523) peer=75
2017-08-13 00:34:51 Requesting block 0000000000003e33ca98e7a5ec0f06eb54f38cac568cdfdca7be1ce517853d1e (949525) peer=75
2017-08-13 00:34:51 Requesting block 0000000003c386117351c9c1055d7cf44204f7293202a4e6b5376e191183a7a7 (950526) peer=75
2017-08-13 00:34:51 Requesting block 000000000000ac8c06080fe99268e2abe1ce27f54dd77a9ea26446fef0d42851 (950528) peer=75
2017-08-13 00:34:51 Requesting block 0000000000bc5b9a87cb585f87c5252da8e5ba71073ba3a9ec3f8d49d6e1d0fe (950529) peer=75
2017-08-13 00:34:51 Requesting block 0000000024f67fb24e2cce7b3c4d28211534bd4d043851767de9ce131687085a (950532) peer=75
2017-08-13 00:34:51 Requesting block 000000001d531674d97eccf31ddfcc112c0acc28a624ef6ec6855728fb5c0122 (950534) peer=75
2017-08-13 00:34:51 Requesting block 00000000237a61bd1b3c1e5691cfd2909246c6dd6f59b139a44f3202bcd6c8b1 (950536) peer=75
2017-08-13 00:34:51 Requesting block 000000001553a1f9a2c3c79f028c8c10affb401406716e5fb2bef94a45384b52 (950538) peer=75
2017-08-13 00:34:51 Requesting block 000000001f205b8e71f0fb634bc8b12e0684beb0ade2a05849b2f17dd39ddcc9 (950540) peer=75
2017-08-13 00:34:51 sending getdata (577 bytes) peer=75
2017-08-13 00:34:51 Stall started peer=75
2017-08-13 00:34:51 trying connection <...>:18333 lastseen=29.0hrs
2017-08-13 00:34:51 connect() to <...>:18333 failed: Network is unreachable (101)
2017-08-13 00:34:52 trying connection <...>:18333 lastseen=3.0hrs
2017-08-13 00:34:52 Added connection peer=78
2017-08-13 00:34:52 sending version (108 bytes) peer=78
2017-08-13 00:34:52 send version message: version 70015, blocks=949516, us=[::]:0, peer=78
2017-08-13 00:34:52 received: version (102 bytes) peer=78
2017-08-13 00:34:52 sending verack (0 bytes) peer=78
2017-08-13 00:34:52 sending getaddr (0 bytes) peer=78
2017-08-13 00:34:52 receive version message: /Satoshi:0.13.1/: version 70014, blocks=1176840, us=<my-ip>:21286, peer=78
2017-08-13 00:34:52 added time data, samples 80, offset +0 (+0 minutes)
2017-08-13 00:34:52 received: verack (0 bytes) peer=78
2017-08-13 00:34:52 sending sendheaders (0 bytes) peer=78
2017-08-13 00:34:52 sending sendcmpct (9 bytes) peer=78
2017-08-13 00:34:52 sending sendcmpct (9 bytes) peer=78
2017-08-13 00:34:52 sending ping (8 bytes) peer=78
2017-08-13 00:34:52 initial getheaders (1176839) to peer=78 (startheight:1176840)
2017-08-13 00:34:52 sending getheaders (1061 bytes) peer=78
2017-08-13 00:34:52 sending feefilter (8 bytes) peer=78
2017-08-13 00:34:52 received: ping (8 bytes) peer=78
2017-08-13 00:34:52 sending pong (8 bytes) peer=78
2017-08-13 00:34:52 received: addr (31 bytes) peer=78
2017-08-13 00:34:52 received: getheaders (1061 bytes) peer=78
2017-08-13 00:34:52 Ignoring getheaders from peer=78 because node is in initial block download
2017-08-13 00:34:52 received: sendheaders (0 bytes) peer=78
2017-08-13 00:34:52 received: sendcmpct (9 bytes) peer=78
2017-08-13 00:34:52 received: sendcmpct (9 bytes) peer=78
2017-08-13 00:34:52 received: pong (8 bytes) peer=78
2017-08-13 00:34:52 received: headers (82 bytes) peer=78
2017-08-13 00:34:53 received: addr (31 bytes) peer=65
2017-08-13 00:34:53 received: inv (37 bytes) peer=22
2017-08-13 00:34:53 got inv: tx dfacbac252b852e0b08a3024993e14c35e18504509c2698ae244f6288e1f33e5  new peer=22
2017-08-13 00:34:53 received: inv (37 bytes) peer=65
2017-08-13 00:34:53 got inv: tx dfacbac252b852e0b08a3024993e14c35e18504509c2698ae244f6288e1f33e5  new peer=65
2017-08-13 00:34:55 received: inv (37 bytes) peer=78
2017-08-13 00:34:55 got inv: tx dfacbac252b852e0b08a3024993e14c35e18504509c2698ae244f6288e1f33e5  new peer=78
2017-08-13 00:34:58 received: inv (37 bytes) peer=44
2017-08-13 00:34:58 got inv: tx dfacbac252b852e0b08a3024993e14c35e18504509c2698ae244f6288e1f33e5  new peer=44
2017-08-13 00:34:59 received: addr (30003 bytes) peer=77
2017-08-13 00:34:59 received: inv (37 bytes) peer=77
2017-08-13 00:34:59 got inv: tx dfacbac252b852e0b08a3024993e14c35e18504509c2698ae244f6288e1f33e5  new peer=77
2017-08-13 00:34:59 received: addr (31 bytes) peer=65
2017-08-13 00:35:00 sending addr (61 bytes) peer=22
2017-08-13 00:35:00 received: inv (37 bytes) peer=76
2017-08-13 00:35:00 got inv: tx dfacbac252b852e0b08a3024993e14c35e18504509c2698ae244f6288e1f33e5  new peer=76
2017-08-13 00:35:01 Peer=75 is stalling block download, disconnecting
2017-08-13 00:35:01 disconnecting peer=75
2017-08-13 00:35:01 Requesting block 0000000000003b574f8236ef7a501a15dd081e802436ac7b906687166f6c06c2 (949517) peer=76
2017-08-13 00:35:01 Requesting block 000000000000362d2a35a6fd1f7eac11f8ae69dfcef3822d7beb2acc73bc0626 (949518) peer=76
2017-08-13 00:35:01 Requesting block 000000000000252a3f81158c50fde7319e4ded74518cf2b8eb57975579f92188 (949519) peer=76
2017-08-13 00:35:01 Requesting block 0000000000002089d098bb3e13375fbd644fce3c6ab2fc7f418148dcbce86201 (949520) peer=76
2017-08-13 00:35:01 Requesting block 000000000000123d6d5d45ceb8b8ee7fd50db35683c0aa58dbe48a3f143b3f2d (949521) peer=76
2017-08-13 00:35:01 Requesting block 000000000000362be28b8a2098618e73fdc997517423a1e37dfdae291e7c9daa (949522) peer=76
2017-08-13 00:35:01 Requesting block 00000000000003996787ac4521eab881f83eacd246b61f3711bb30af539bb98a (949523) peer=76
2017-08-13 00:35:01 Requesting block 0000000000003e33ca98e7a5ec0f06eb54f38cac568cdfdca7be1ce517853d1e (949525) peer=76
2017-08-13 00:35:01 Requesting block 0000000003c386117351c9c1055d7cf44204f7293202a4e6b5376e191183a7a7 (950526) peer=76
2017-08-13 00:35:01 Requesting block 000000000000ac8c06080fe99268e2abe1ce27f54dd77a9ea26446fef0d42851 (950528) peer=76
2017-08-13 00:35:01 Requesting block 0000000000bc5b9a87cb585f87c5252da8e5ba71073ba3a9ec3f8d49d6e1d0fe (950529) peer=76
2017-08-13 00:35:01 Requesting block 0000000024f67fb24e2cce7b3c4d28211534bd4d043851767de9ce131687085a (950532) peer=76
2017-08-13 00:35:01 Requesting block 000000001d531674d97eccf31ddfcc112c0acc28a624ef6ec6855728fb5c0122 (950534) peer=76
2017-08-13 00:35:01 Requesting block 00000000237a61bd1b3c1e5691cfd2909246c6dd6f59b139a44f3202bcd6c8b1 (950536) peer=76
2017-08-13 00:35:01 Requesting block 000000001553a1f9a2c3c79f028c8c10affb401406716e5fb2bef94a45384b52 (950538) peer=76
2017-08-13 00:35:01 Requesting block 000000001f205b8e71f0fb634bc8b12e0684beb0ade2a05849b2f17dd39ddcc9 (950540) peer=76
2017-08-13 00:35:01 sending getdata (577 bytes) peer=76
2017-08-13 00:35:01 Stall started peer=76
2017-08-13 00:35:01 trying connection <...>:18333 lastseen=29.0hrs
2017-08-13 00:35:01 connect() to <...>:18333 failed: Network is unreachable (101)
2017-08-13 00:35:02 trying connection <...>:18333 lastseen=2.8hrs
2017-08-13 00:35:02 Added connection peer=79
2017-08-13 00:35:02 sending version (108 bytes) peer=79
2017-08-13 00:35:02 send version message: version 70015, blocks=949516, us=[::]:0, peer=79
2017-08-13 00:35:02 received: version (102 bytes) peer=79
2017-08-13 00:35:02 sending verack (0 bytes) peer=79
2017-08-13 00:35:02 sending getaddr (0 bytes) peer=79
2017-08-13 00:35:02 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176840, us=<my-ip>:1757, peer=79
2017-08-13 00:35:02 added time data, samples 81, offset +0 (+0 minutes)
2017-08-13 00:35:02 -8544797  -1130  -25  -21  -18  -6  -3  -2  -1  -1  -1  -1  -1  -1  -1  -1  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +0  +1  +5  +7  +15  +39  +59  +73  +366  |  nTimeOffset = +0  (+0 minutes)
2017-08-13 00:35:02 received: verack (0 bytes) peer=79
2017-08-13 00:35:02 sending sendheaders (0 bytes) peer=79
2017-08-13 00:35:02 sending sendcmpct (9 bytes) peer=79
2017-08-13 00:35:02 sending sendcmpct (9 bytes) peer=79
2017-08-13 00:35:02 sending ping (8 bytes) peer=79
2017-08-13 00:35:02 initial getheaders (1176839) to peer=79 (startheight:1176840)
2017-08-13 00:35:02 sending getheaders (1061 bytes) peer=79
2017-08-13 00:35:02 sending feefilter (8 bytes) peer=79
2017-08-13 00:35:02 received: sendheaders (0 bytes) peer=79
2017-08-13 00:35:02 received: sendcmpct (9 bytes) peer=79
2017-08-13 00:35:02 received: sendcmpct (9 bytes) peer=79
2017-08-13 00:35:02 received: ping (8 bytes) peer=79
2017-08-13 00:35:02 sending pong (8 bytes) peer=79
2017-08-13 00:35:02 received: addr (31 bytes) peer=79
2017-08-13 00:35:03 received: getheaders (1061 bytes) peer=79
2017-08-13 00:35:03 Ignoring getheaders from peer=79 because node is in initial block download
2017-08-13 00:35:03 received: feefilter (8 bytes) peer=79
2017-08-13 00:35:03 received: feefilter of 0.00001000 BTC/kB from peer=79
2017-08-13 00:35:03 received: pong (8 bytes) peer=79
2017-08-13 00:35:03 received: headers (82 bytes) peer=79
2017-08-13 00:35:04 received: inv (37 bytes) peer=78
2017-08-13 00:35:04 got inv: tx 7599b77aea3cd2361fb97838c3e16df37618284ef050a1d5d80a9262192aa7e4  new peer=78
2017-08-13 00:35:04 sending addr (31 bytes) peer=78
2017-08-13 00:35:05 received: inv (37 bytes) peer=22
2017-08-13 00:35:05 got inv: tx 7599b77aea3cd2361fb97838c3e16df37618284ef050a1d5d80a9262192aa7e4  new peer=22
2017-08-13 00:35:05 received: addr (30003 bytes) peer=78
2017-08-13 00:35:05 received: inv (37 bytes) peer=65
2017-08-13 00:35:05 got inv: tx 7599b77aea3cd2361fb97838c3e16df37618284ef050a1d5d80a9262192aa7e4  new peer=65
2017-08-13 00:35:06 received: ping (8 bytes) peer=44
2017-08-13 00:35:06 sending pong (8 bytes) peer=44
2017-08-13 00:35:06 sending ping (8 bytes) peer=44
2017-08-13 00:35:06 received: pong (8 bytes) peer=44
2017-08-13 00:35:08 received: addr (31 bytes) peer=44
2017-08-13 00:35:09 sending addr (31 bytes) peer=77
2017-08-13 00:35:09 received: inv (37 bytes) peer=77
2017-08-13 00:35:09 got inv: tx 7599b77aea3cd2361fb97838c3e16df37618284ef050a1d5d80a9262192aa7e4  new peer=77
2017-08-13 00:35:10 received: inv (37 bytes) peer=79
2017-08-13 00:35:10 got inv: tx 7599b77aea3cd2361fb97838c3e16df37618284ef050a1d5d80a9262192aa7e4  new peer=79
2017-08-13 00:35:11 Peer=76 is stalling block download, disconnecting
2017-08-13 00:35:11 disconnecting peer=76
2017-08-13 00:35:11 Requesting block 0000000000003b574f8236ef7a501a15dd081e802436ac7b906687166f6c06c2 (949517) peer=77
2017-08-13 00:35:11 Requesting block 000000000000362d2a35a6fd1f7eac11f8ae69dfcef3822d7beb2acc73bc0626 (949518) peer=77
2017-08-13 00:35:11 Requesting block 000000000000252a3f81158c50fde7319e4ded74518cf2b8eb57975579f92188 (949519) peer=77
2017-08-13 00:35:11 Requesting block 0000000000002089d098bb3e13375fbd644fce3c6ab2fc7f418148dcbce86201 (949520) peer=77
2017-08-13 00:35:11 Requesting block 000000000000123d6d5d45ceb8b8ee7fd50db35683c0aa58dbe48a3f143b3f2d (949521) peer=77
2017-08-13 00:35:11 Requesting block 000000000000362be28b8a2098618e73fdc997517423a1e37dfdae291e7c9daa (949522) peer=77
2017-08-13 00:35:11 Requesting block 00000000000003996787ac4521eab881f83eacd246b61f3711bb30af539bb98a (949523) peer=77
2017-08-13 00:35:11 Requesting block 0000000000003e33ca98e7a5ec0f06eb54f38cac568cdfdca7be1ce517853d1e (949525) peer=77
2017-08-13 00:35:11 Requesting block 0000000003c386117351c9c1055d7cf44204f7293202a4e6b5376e191183a7a7 (950526) peer=77
2017-08-13 00:35:11 Requesting block 000000000000ac8c06080fe99268e2abe1ce27f54dd77a9ea26446fef0d42851 (950528) peer=77
2017-08-13 00:35:11 Requesting block 0000000000bc5b9a87cb585f87c5252da8e5ba71073ba3a9ec3f8d49d6e1d0fe (950529) peer=77
2017-08-13 00:35:11 Requesting block 0000000024f67fb24e2cce7b3c4d28211534bd4d043851767de9ce131687085a (950532) peer=77
2017-08-13 00:35:11 Requesting block 000000001d531674d97eccf31ddfcc112c0acc28a624ef6ec6855728fb5c0122 (950534) peer=77
2017-08-13 00:35:11 Requesting block 00000000237a61bd1b3c1e5691cfd2909246c6dd6f59b139a44f3202bcd6c8b1 (950536) peer=77
2017-08-13 00:35:11 Requesting block 000000001553a1f9a2c3c79f028c8c10affb401406716e5fb2bef94a45384b52 (950538) peer=77
2017-08-13 00:35:11 Requesting block 000000001f205b8e71f0fb634bc8b12e0684beb0ade2a05849b2f17dd39ddcc9 (950540) peer=77
2017-08-13 00:35:11 sending getdata (577 bytes) peer=77
2017-08-13 00:35:11 Stall started peer=77
2017-08-13 00:35:12 trying connection <...>:18333 lastseen=1.6hrs
2017-08-13 00:35:12 Added connection peer=80
2017-08-13 00:35:12 sending version (108 bytes) peer=80
2017-08-13 00:35:12 send version message: version 70015, blocks=949516, us=[::]:0, peer=80
2017-08-13 00:35:12 received: version (102 bytes) peer=80
2017-08-13 00:35:12 sending verack (0 bytes) peer=80
2017-08-13 00:35:12 sending getaddr (0 bytes) peer=80
2017-08-13 00:35:12 receive version message: /Satoshi:0.14.2/: version 70015, blocks=1176840, us=<my-ip>:19155, peer=80
2017-08-13 00:35:12 added time data, samples 82, offset +0 (+0 minutes)
2017-08-13 00:35:12 received: verack (0 bytes) peer=80
2017-08-13 00:35:12 sending sendheaders (0 bytes) peer=80
2017-08-13 00:35:12 sending sendcmpct (9 bytes) peer=80
2017-08-13 00:35:12 sending sendcmpct (9 bytes) peer=80
2017-08-13 00:35:12 sending ping (8 bytes) peer=80
2017-08-13 00:35:12 initial getheaders (1176839) to peer=80 (startheight:1176840)
2017-08-13 00:35:12 sending getheaders (1061 bytes) peer=80
2017-08-13 00:35:12 sending feefilter (8 bytes) peer=80
2017-08-13 00:35:12 received: sendheaders (0 bytes) peer=80
2017-08-13 00:35:12 received: sendcmpct (9 bytes) peer=80
2017-08-13 00:35:12 received: sendcmpct (9 bytes) peer=80
2017-08-13 00:35:12 received: ping (8 bytes) peer=80
2017-08-13 00:35:12 sending pong (8 bytes) peer=80
2017-08-13 00:35:12 received: addr (31 bytes) peer=80
2017-08-13 00:35:12 received: getheaders (1061 bytes) peer=80
2017-08-13 00:35:12 Ignoring getheaders from peer=80 because node is in initial block download
2017-08-13 00:35:12 received: feefilter (8 bytes) peer=80
2017-08-13 00:35:12 received: feefilter of 0.00001000 BTC/kB from peer=80
2017-08-13 00:35:12 received: pong (8 bytes) peer=80
2017-08-13 00:35:12 received: headers (82 bytes) peer=80
2017-08-13 00:35:16 received: inv (37 bytes) peer=44
2017-08-13 00:35:16 got inv: tx 7599b77aea3cd2361fb97838c3e16df37618284ef050a1d5d80a9262192aa7e4  new peer=44
2017-08-13 00:35:21 received: addr (30003 bytes) peer=79

I can't accept incoming connections, if that's relevant. They're all outgoing.

And I have height=949516. It was height=949507 when I first posted this issue, but it did manage to grab 8 blocks when I disabled the disconnection altogether.

[dooglus]

maxconnections=1 seems to be working, albeit very slowly. I put BLOCK_STALLING_TIMEOUT back to 2. Notice the large gaps in the timestamps where I added blank lines:

2017-08-13 00:41:39 Bitcoin version v0.14.2.0-fc61c83-dirty
2017-08-13 00:41:39 InitParameterInteraction: parameter interaction: -listen=0 -> setting -discover=0
2017-08-13 00:41:39 InitParameterInteraction: parameter interaction: -listen=0 -> setting -listenonion=0
2017-08-13 00:41:39 InitParameterInteraction: parameter interaction: -whitelistforcerelay=1 -> setting -whitelistrelay=1
2017-08-13 00:41:39 Assuming ancestors of block 00000000000128796ee387cf110ccb9d2f36cffaf7f73079c995377c65ac0dcc have valid signatures.
2017-08-13 00:41:39 Default data directory /home/chris/.bitcoin
2017-08-13 00:41:39 Using data directory /home/chris/.bitcoin/testnet3
2017-08-13 00:41:39 Using config file /home/chris/.bitcoin/bitcoin.conf
2017-08-13 00:41:39 Using at most 1 automatic connections (65536 file descriptors available)
2017-08-13 00:41:39 Using 32 MiB out of 32 requested for signature cache, able to store 1048576 elements
2017-08-13 00:41:39 Using 2 threads for script verification
2017-08-13 00:41:39 scheduler thread start
2017-08-13 00:41:39 HTTP: creating work queue of depth 16
2017-08-13 00:41:39 Config options rpcuser and rpcpassword will soon be deprecated. Locally-run instances may remove rpcuser to use cookie-based auth, or may be replaced with rpcauth. Please see share/rpcuser for rpcauth auth generation.
2017-08-13 00:41:39 HTTP: starting 4 worker threads
2017-08-13 00:41:39 Using BerkeleyDB version Berkeley DB 5.3.28: (September  9, 2013)
2017-08-13 00:41:39 Using wallet wallet.dat
2017-08-13 00:41:39 init message: Verifying wallet...
2017-08-13 00:41:39 CDBEnv::Open: LogDir=/home/chris/.bitcoin/testnet3/database ErrorFile=/home/chris/.bitcoin/testnet3/db.log
2017-08-13 00:41:39 Cache configuration:
2017-08-13 00:41:39 * Using 56.2MiB for block index database
2017-08-13 00:41:39 * Using 8.0MiB for chain state database
2017-08-13 00:41:39 * Using 385.8MiB for in-memory UTXO set (plus up to 286.1MiB of unused mempool space)
2017-08-13 00:41:39 init message: Loading block index...
2017-08-13 00:41:39 Opening LevelDB in /home/chris/.bitcoin/testnet3/blocks/index
2017-08-13 00:41:45 Opened LevelDB successfully
2017-08-13 00:41:45 Using obfuscation key for /home/chris/.bitcoin/testnet3/blocks/index: 0000000000000000
2017-08-13 00:41:45 Opening LevelDB in /home/chris/.bitcoin/testnet3/chainstate
2017-08-13 00:41:45 Opened LevelDB successfully
2017-08-13 00:41:45 Using obfuscation key for /home/chris/.bitcoin/testnet3/chainstate: f8e53420fe1c49b2
2017-08-13 00:41:54 LoadBlockIndexDB: last block file = 56
2017-08-13 00:41:54 LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=3816, size=126781869, heights=946414...950539, time=2016-09-26...2016-09-29)
2017-08-13 00:41:54 Checking all blk files are present...
2017-08-13 00:41:54 LoadBlockIndexDB: transaction index enabled
2017-08-13 00:41:54 LoadBlockIndexDB: hashBestChain=0000000000000c079eb3a22ad5df821ad6e777e2b04119b3b7a08481b8f2177a height=949516 date=2016-09-29 19:24:48 progress=0.725056
2017-08-13 00:41:54 init message: Rewinding blocks...
2017-08-13 00:42:01 init message: Verifying blocks...
2017-08-13 00:42:01 Verifying last 1 blocks at level 3
2017-08-13 00:42:01 [0%]...[99%]...[DONE].
2017-08-13 00:42:01 No coin database inconsistencies in last 2 blocks (1825 transactions)
2017-08-13 00:42:01  block index           21748ms
2017-08-13 00:42:01 init message: Loading wallet...
2017-08-13 00:42:01 nFileVersion = 140200
2017-08-13 00:42:01 Keys: 102 plaintext, 0 encrypted, 102 w/ metadata, 102 total
2017-08-13 00:42:01  wallet                   93ms
2017-08-13 00:42:01 setKeyPool.size() = 100
2017-08-13 00:42:01 mapWallet.size() = 0
2017-08-13 00:42:01 mapAddressBook.size() = 1
2017-08-13 00:42:01 mapBlockIndex.size() = 1177849
2017-08-13 00:42:01 nBestHeight = 949516
2017-08-13 00:42:01 init message: Loading addresses...
2017-08-13 00:42:01 Imported mempool transactions from disk: 0 successes, 0 failed, 0 expired
2017-08-13 00:42:01 Loaded 31361 addresses from peers.dat  141ms
2017-08-13 00:42:01 init message: Loading banlist...
2017-08-13 00:42:01 Loaded 1 banned node ips/subnets from banlist.dat  0ms
2017-08-13 00:42:01 init message: Starting network threads...
2017-08-13 00:42:01 msghand thread start
2017-08-13 00:42:01 init message: Done loading
2017-08-13 00:42:01 addcon thread start
2017-08-13 00:42:01 opencon thread start
2017-08-13 00:42:01 dnsseed thread start
2017-08-13 00:42:01 net thread start
2017-08-13 00:42:01 GUI: Platform customization: "other"
2017-08-13 00:42:01 GUI: PaymentServer::LoadRootCAs: Loaded  170  root certificates
2017-08-13 00:42:02 trying connection <...>:18333 lastseen=0.2hrs
2017-08-13 00:42:02 Added connection peer=0
2017-08-13 00:42:02 sending version (108 bytes) peer=0
2017-08-13 00:42:02 send version message: version 70015, blocks=949516, us=[::]:0, peer=0
2017-08-13 00:42:02 received: version (102 bytes) peer=0
2017-08-13 00:42:02 sending verack (0 bytes) peer=0
2017-08-13 00:42:02 sending getaddr (0 bytes) peer=0
2017-08-13 00:42:02 receive version message: /Satoshi:0.14.1/: version 70015, blocks=1176848, us=<my-ip>:16689, peer=0
2017-08-13 00:42:02 added time data, samples 2, offset +0 (+0 minutes)
2017-08-13 00:42:02 received: verack (0 bytes) peer=0
2017-08-13 00:42:02 sending sendheaders (0 bytes) peer=0
2017-08-13 00:42:02 sending sendcmpct (9 bytes) peer=0
2017-08-13 00:42:02 sending sendcmpct (9 bytes) peer=0
2017-08-13 00:42:02 sending ping (8 bytes) peer=0
2017-08-13 00:42:02 initial getheaders (1176844) to peer=0 (startheight:1176848)
2017-08-13 00:42:02 sending getheaders (1061 bytes) peer=0
2017-08-13 00:42:02 sending feefilter (8 bytes) peer=0
2017-08-13 00:42:02 received: sendheaders (0 bytes) peer=0
2017-08-13 00:42:02 received: sendcmpct (9 bytes) peer=0
2017-08-13 00:42:02 received: sendcmpct (9 bytes) peer=0
2017-08-13 00:42:02 received: ping (8 bytes) peer=0
2017-08-13 00:42:02 sending pong (8 bytes) peer=0
2017-08-13 00:42:02 received: addr (31 bytes) peer=0
2017-08-13 00:42:02 received: getheaders (1061 bytes) peer=0
2017-08-13 00:42:02 Ignoring getheaders from peer=0 because node is in initial block download
2017-08-13 00:42:02 received: feefilter (8 bytes) peer=0
2017-08-13 00:42:02 received: feefilter of 0.00001000 BTC/kB from peer=0
2017-08-13 00:42:02 received: pong (8 bytes) peer=0
2017-08-13 00:42:02 received: headers (325 bytes) peer=0
2017-08-13 00:42:02 Requesting block 0000000000003b574f8236ef7a501a15dd081e802436ac7b906687166f6c06c2 (949517) peer=0
2017-08-13 00:42:02 Requesting block 000000000000362d2a35a6fd1f7eac11f8ae69dfcef3822d7beb2acc73bc0626 (949518) peer=0
2017-08-13 00:42:02 Requesting block 000000000000252a3f81158c50fde7319e4ded74518cf2b8eb57975579f92188 (949519) peer=0
2017-08-13 00:42:02 Requesting block 0000000000002089d098bb3e13375fbd644fce3c6ab2fc7f418148dcbce86201 (949520) peer=0
2017-08-13 00:42:02 Requesting block 000000000000123d6d5d45ceb8b8ee7fd50db35683c0aa58dbe48a3f143b3f2d (949521) peer=0
2017-08-13 00:42:02 Requesting block 000000000000362be28b8a2098618e73fdc997517423a1e37dfdae291e7c9daa (949522) peer=0
2017-08-13 00:42:02 Requesting block 00000000000003996787ac4521eab881f83eacd246b61f3711bb30af539bb98a (949523) peer=0
2017-08-13 00:42:02 Requesting block 0000000000003e33ca98e7a5ec0f06eb54f38cac568cdfdca7be1ce517853d1e (949525) peer=0
2017-08-13 00:42:02 Requesting block 0000000003c386117351c9c1055d7cf44204f7293202a4e6b5376e191183a7a7 (950526) peer=0
2017-08-13 00:42:02 Requesting block 000000000000ac8c06080fe99268e2abe1ce27f54dd77a9ea26446fef0d42851 (950528) peer=0
2017-08-13 00:42:02 Requesting block 0000000000bc5b9a87cb585f87c5252da8e5ba71073ba3a9ec3f8d49d6e1d0fe (950529) peer=0
2017-08-13 00:42:02 Requesting block 0000000024f67fb24e2cce7b3c4d28211534bd4d043851767de9ce131687085a (950532) peer=0
2017-08-13 00:42:02 Requesting block 000000001d531674d97eccf31ddfcc112c0acc28a624ef6ec6855728fb5c0122 (950534) peer=0
2017-08-13 00:42:02 Requesting block 00000000237a61bd1b3c1e5691cfd2909246c6dd6f59b139a44f3202bcd6c8b1 (950536) peer=0
2017-08-13 00:42:02 Requesting block 000000001553a1f9a2c3c79f028c8c10affb401406716e5fb2bef94a45384b52 (950538) peer=0
2017-08-13 00:42:02 Requesting block 000000001f205b8e71f0fb634bc8b12e0684beb0ade2a05849b2f17dd39ddcc9 (950540) peer=0
2017-08-13 00:42:02 sending getdata (577 bytes) peer=0
2017-08-13 00:42:12 Loading addresses from DNS seeds (could take a while)
2017-08-13 00:42:19 125 addresses found from DNS seeds
2017-08-13 00:42:19 dnsseed thread exit

2017-08-13 00:42:57 received: block (1805831 bytes) peer=0
2017-08-13 00:42:57 received block 0000000000003b574f8236ef7a501a15dd081e802436ac7b906687166f6c06c2 peer=0
2017-08-13 00:43:08 UpdateTip: new best=0000000000003b574f8236ef7a501a15dd081e802436ac7b906687166f6c06c2 height=949517 version=0x20000000 log2_work=68.521162 tx=11377378 date='2016-09-29 19:24:48' progress=0.725113 cache=1.5MiB(3658tx)
2017-08-13 00:43:08 received: inv (37 bytes) peer=0
2017-08-13 00:43:08 got inv: tx 824d730dbd151922307b67e477e32f87aed90932bd1b8b9ab2b71924305961cb  new peer=0
2017-08-13 00:43:08 Requesting block 0000000006e243a5d6c1debc5d546ecd1d832d7efb6c39a5b0cc5291a401ada3 (950541) peer=0
2017-08-13 00:43:08 sending getdata (37 bytes) peer=0
2017-08-13 00:43:08 received: headers (82 bytes) peer=0
2017-08-13 00:43:08 received: inv (73 bytes) peer=0
2017-08-13 00:43:08 got inv: tx 42adc1429e095344f09f07f9825c595b2a7759d2fc56428b3b865ab43a1f02d7  new peer=0
2017-08-13 00:43:08 got inv: tx a521a1c718110b3b648b472ab13e5de6327f049a7bd46dcfd3d10ba529754d01  new peer=0

2017-08-13 00:43:48 received: block (1805803 bytes) peer=0
2017-08-13 00:43:48 received block 000000000000362d2a35a6fd1f7eac11f8ae69dfcef3822d7beb2acc73bc0626 peer=0
2017-08-13 00:43:55 UpdateTip: new best=000000000000362d2a35a6fd1f7eac11f8ae69dfcef3822d7beb2acc73bc0626 height=949518 version=0x20000000 log2_work=68.521166 tx=11378289 date='2016-09-29 19:24:48' progress=0.725171 cache=2.9MiB(7048tx)
2017-08-13 00:43:55 received: headers (82 bytes) peer=0
2017-08-13 00:43:55 Requesting block 0000000002d1e82bd6c8c9f9adcf77da935ec7bcfbebd4a8dccd368a05c25983 (950542) peer=0
2017-08-13 00:43:55 sending getdata (37 bytes) peer=0
2017-08-13 00:43:55 received: addr (29943 bytes) peer=0
2017-08-13 00:43:55 received: inv (37 bytes) peer=0
2017-08-13 00:43:55 got inv: tx 6edede07ff4d8a709525006322c885429438b9bcf85dc8252a3eaf6987b8d9a9  new peer=0
2017-08-13 00:44:02 sending ping (8 bytes) peer=0

2017-08-13 00:44:24 received: block (1804774 bytes) peer=0
2017-08-13 00:44:24 received block 000000000000252a3f81158c50fde7319e4ded74518cf2b8eb57975579f92188 peer=0
2017-08-13 00:44:28 UpdateTip: new best=000000000000252a3f81158c50fde7319e4ded74518cf2b8eb57975579f92188 height=949519 version=0x20000000 log2_work=68.52117 tx=11379202 date='2016-09-29 19:24:48' progress=0.725229 cache=4.1MiB(10221tx)
2017-08-13 00:44:28 received: headers (82 bytes) peer=0
2017-08-13 00:44:28 Requesting block 00000000000afd6690a660dced9e422645a17113c05ac91e326172ba29e43193 (950543) peer=0
2017-08-13 00:44:28 sending getdata (37 bytes) peer=0
2017-08-13 00:44:28 received: inv (109 bytes) peer=0
2017-08-13 00:44:28 got inv: tx 4c0a274f1234459acdae247480e34bd33be04c035d9c655f7f907dc51d49b0ae  new peer=0
2017-08-13 00:44:28 got inv: tx 321b60e1f9e2924ec8179aab27912468a82306041a5f17c4ef538c5b56db2860  new peer=0
2017-08-13 00:44:28 got inv: tx 6a11f52e74e6ff3fa78bd12e22ed015a2ea1a07a3dd18eabdbd4e74bead9feb9  new peer=0
2017-08-13 00:44:28 received: ping (8 bytes) peer=0
2017-08-13 00:44:28 sending pong (8 bytes) peer=0
2017-08-13 00:44:28 received: headers (82 bytes) peer=0
2017-08-13 00:44:28 received: addr (121 bytes) peer=0
2017-08-13 00:44:28 received: inv (37 bytes) peer=0
2017-08-13 00:44:28 got inv: tx 552af958ffc6489bfbd0f55931b84ea0fa24af8ad89096dc54e22b30cabfab09  new peer=0
2017-08-13 00:44:28 received: headers (82 bytes) peer=0
2017-08-13 00:44:28 received: headers (82 bytes) peer=0
2017-08-13 00:44:28 received: inv (37 bytes) peer=0
2017-08-13 00:44:28 got inv: tx 56f272200e50cf61ea2657a9efd6d7558959db100f6184ad1037b083afb3ce2e  new peer=0

Is this going to be an issue on mainnet when segwit activates? Is there a fix for it?

[dooglus]

I notice the blocks are pretty big:

2017-08-13 00:42:57 received: block (1805831 bytes) peer=0

I can't download that much in 2 seconds. I wonder if that's the issue?

[dooglus]

Now that I'm past those big blocks I am able to sync the chain using more than 1 connection. I'm getting around 100 blocks per second again now.

[sdaftuar]

Ok great. Yeah it occurred to me that bigger blocks on testnet (post-segwit-activation there) could exacerbate this issue further, we should try to improve this behavior soon for mainnet...

[dooglus]

Any idea why I've never seen this on mainnet?

[dooglus]

It's stuck again.

It was flying through the blocks for a while:

2017-08-13 00:56:50 Requesting block 000000000000133efbf0144e33d03644bf720b007a0e58e0048a5dcf9ed4a050 (989889) peer=18
2017-08-13 00:56:50 sending getdata (37 bytes) peer=18
2017-08-13 00:56:50 received: block (303 bytes) peer=18
2017-08-13 00:56:50 received block 0000000000001e5801465663185499adf2074a833d386148d31d1d15479ad50b peer=18
2017-08-13 00:56:50 Requesting block 00000000001d318997a1216ddae8caf3da859bb3fcd7fa17618e0179fbb01244 (989890) peer=18
2017-08-13 00:56:50 sending getdata (37 bytes) peer=18
2017-08-13 00:56:50 received: block (558 bytes) peer=18
2017-08-13 00:56:50 received block 00000000000043cdecf1e12f4d7fe1db50bd6ca36dc2ca6bad60a2c5124f0b20 peer=18
2017-08-13 00:56:50 Requesting block 000000000000041c51f52c0a13495f295e8ba2ad601f616de811c5818747b2d5 (989891) peer=18
2017-08-13 00:56:50 sending getdata (37 bytes) peer=18
2017-08-13 00:56:50 received: block (262 bytes) peer=18
2017-08-13 00:56:50 received block 0000000000263e011679473c679df8d858e88af39850c54b7d5e0966d8bb9984 peer=18
2017-08-13 00:56:50 Requesting block 0000000000916886038c0c870189e48fccfdcba3425f9b9c4f6b6baede19b5cb (989892) peer=18
2017-08-13 00:56:50 sending getdata (37 bytes) peer=18
2017-08-13 00:56:50 received: block (2443 bytes) peer=17
2017-08-13 00:56:50 received block 0000000000003cfed13fb8853027747cae5382eb564528c896011146bd7f9fc2 peer=17
2017-08-13 00:56:50 UpdateTip: new best=0000000000003cfed13fb8853027747cae5382eb564528c896011146bd7f9fc2 height=989546 version=0x30000000 log2_work=68.573774 tx=11491999 date='2016-10-14 09:52:12' progress=0.732413 cache=31.2MiB(115688tx)
2017-08-13 00:56:50 Requesting block 0000000000000d3c5de06862c513cecfd7e6b574a5d5374857dcf6c85a969289 (989893) peer=17
2017-08-13 00:56:50 sending getdata (37 bytes) peer=17
2017-08-13 00:56:50 received: block (262 bytes) peer=17
[...]
2017-08-13 00:56:50 UpdateTip: new best=0000000000005f02e665830a8e69d43cf647a2b0771a22d4155e24b64df11540 height=989643 version=0x30000000 log2_work=68.573866 tx=11492575 date='2016-10-14 12:37:22' progress=0.732449 cache=31.3MiB(116063tx)
2017-08-13 00:56:50 UpdateTip: new best=0000000000b56cd3cdf8c0c347058b78b43e3cb81a7ece84951368ad17efd59b height=989644 version=0x20000000 log2_work=68.573866 tx=11492576 date='2016-10-14 12:57:40' progress=0.732450 cache=31.3MiB(116064tx)
2017-08-13 00:56:50 UpdateTip: new best=00000000000017001be1ac75122597caa007efa542c9d893fb14a3b35145c0c9 height=989645 version=0x20000000 log2_work=68.573868 tx=11492577 date='2016-10-14 12:56:55' progress=0.732450 cache=31.3MiB(116065tx)
2017-08-13 00:56:50 UpdateTip: new best=00000000000057f07ed156884ed02f83d7c7e64c4e2f54368b4c415779b09533 height=989646 version=0x30000000 log2_work=68.57387 tx=11492590 date='2016-10-14 12:56:55' progress=0.732450 cache=31.3MiB(116073tx)
2017-08-13 00:56:50 UpdateTip: new best=000000000000201fbb4594a80410f7fb05d23acf48c1176efffa31c2d363af9c height=989647 version=0x30000000 log2_work=68.573872 tx=11492592 date='2016-10-14 12:56:56' progress=0.732451 cache=31.3MiB(116075tx)
2017-08-13 00:56:50 UpdateTip: new best=0000000000004aff4f90a9dcb44b32e7f64948050cc050eeb544941b846f0c13 height=989648 version=0x30000000 log2_work=68.573874 tx=11492605 date='2016-10-14 12:56:56' progress=0.732451 cache=31.3MiB(116089tx)

but then it slowed way down again when it hit a big block:

2017-08-13 00:57:23 received: block (1917019 bytes) peer=19
2017-08-13 00:57:23 received block 0000000000004d18983eb16fb40d01feb7d0d68d8c7910ff87a28112aeca6fd3 peer=19
2017-08-13 00:57:24 UpdateTip: new best=0000000000004d18983eb16fb40d01feb7d0d68d8c7910ff87a28112aeca6fd3 height=989649 version=0x20000000 log2_work=68.573875 tx=11493258 date='2016-10-14 12:56:57' progress=0.732493 cache=35.5MiB(124897tx)

and then it started with the 'stalling' messages:

2017-08-13 00:57:44 Stall started peer=19
2017-08-13 00:57:46 Peer=19 is stalling block download, disconnecting
2017-08-13 00:57:46 Stall started peer=18
2017-08-13 00:57:48 Peer=18 is stalling block download, disconnecting
2017-08-13 00:57:48 Stall started peer=20
2017-08-13 00:57:50 Peer=20 is stalling block download, disconnecting

It's been over 20 minutes and I've not seen any more blocks. It's still disconnecting peers one at a time:

2017-08-13 01:21:14 Stall started peer=321
2017-08-13 01:21:16 Peer=321 is stalling block download, disconnecting

I guess I'll switch back to maxconnections=1 and let the sync complete, unless there's some diagnostic use in keeping my node unsynced for now.

[sdaftuar]

I'll need to dig into this more to better understand it but my guess is that mainnet isn't as bad because the blocks are probably more uniform in size and download speed -- I'd guess that most testnet blocks are close to empty, so you might be more likely to quickly download ~1000 blocks and think the peer who is stuck serving the handful of big blocks in the download window is stalling?

[dooglus]

Changing BLOCK_STALLING_TIMEOUT to 120 allowed me to sync the chain quickly using multiple peers, and solved the 'stalling' issue. I tried the workarounds posted in other threads and didn't find any of the helpful. Limiting to a single connection solved the problem but resulted in very slow syncing.

[sdaftuar]

@dooglus Thanks for reporting back, that is good to know.

[dooglus]

Any idea why I've never seen this on mainnet?

I doubt I've ever been 1024 blocks behind on mainnet. That would explain why I don't see this issue there.

./validation.h:static const unsigned int BLOCK_DOWNLOAD_WINDOW = 1024;

[dooglus]

@sdaftuar

I'll need to dig into this more to better understand

Here's my (hand-waving) understanding:

I had 8 peers. Each peer can only have 16 blocks "in flight" at a time, and we only download blocks which are within 1024 blocks of our best block. That means only 128 blocks can be "in flight" at a time, much less than the 1024 block window.

When the window gets full, ie. when we would be trying to fetch a block 1024 ahead of our tip, the peer which is currently trying to download the block at tip+1 gets 2 seconds to complete, and then is disconnected.

During normal (mainnet) operation, most blocks are about the same size, and take about the same time to download. We very rarely fill the 1024 block window, and so this stalling disconnect code very rarely runs.

On testnet however, we have the occasional 1.5 MB block followed by thousands of 200 byte blocks. While peer 0 is downloading a 1.5 MB block (at tip+1), the other peers can very quickly download a thousand 200 byte blocks, filling the 1024 block window, and causing peer 0 to get disconnected for "stalling".

The assumption seems to be that if other peers were able to download 1000 blocks before peer 0 was able to download one block, it must be that peer 0 was "stalling". However, in this case peer 0 wasn't being slow, the other peers were just lucky to all be downloading empty blocks and so got an easy ride to the end of the window.

This is unlikely to be an issue on mainnet, because we don't ever get lots of small/empty blocks in a row. If one peer does fall 1000 blocks behind the rest, it's likely that it is stalling and so should be disconnected.