Incoming block downloads repeatedly freezing in 0.12

[jameshilliard]

I've been seeing a peer at IP 45.59.67.242 appear to repeatedly freeze incoming block downloads.
This appears to be timeout related as nearly exactly 20 minutes pass between the inv(2016-02-25 03:52:02.639084) and the download timeout(2016-02-25 04:12:02.649818).

I'm not seeing a "Requesting block" before the timeout on the block download that freezes however.

Best I can tell bitcoind thinks it's downloading a block starting at the inv but actually isn't at all.

I enabled debug=net and got the following log for that particular ip address and got logs for two peers:

2016-02-25 03:27:26.584941 Added connection to 45.59.67.242:23938 peer=5
2016-02-25 03:27:26.594339 received: version (102 bytes) peer=5
2016-02-25 03:27:26.594365 send version message: version 70012, blocks=399909, us=0.0.0.0:8333, them=45.59.67.242:23938, peer=5
2016-02-25 03:27:26.594381 sending: version (102 bytes) peer=5
2016-02-25 03:27:26.594420 sending: verack (0 bytes) peer=5
2016-02-25 03:27:26.594456 receive version message: /Satoshi:0.11.2/: version 70002, blocks=398961, us=0.0.0.0:0, peer=5, peeraddr=45.59.67.242:23938
2016-02-25 03:27:26.594492 sending: ping (8 bytes) peer=5
2016-02-25 03:27:26.594531 initial getheaders (399908) to peer=5 (startheight:398961)
2016-02-25 03:27:26.594557 sending: getheaders (997 bytes) peer=5
2016-02-25 03:27:26.670222 received: verack (0 bytes) peer=5
2016-02-25 03:27:26.745767 received: sendheaders (0 bytes) peer=5
2016-02-25 03:27:26.745816 received: pong (8 bytes) peer=5
2016-02-25 03:27:40.548265 SendMessages: sending inv peer=5 hash=0000000000000000055a8d660c231dc279ad443f9b9b4c0ce7871ca76fc2a26a
2016-02-25 03:27:40.548399 sending: inv (37 bytes) peer=5
2016-02-25 03:27:40.624387 received: getheaders (37 bytes) peer=5
2016-02-25 03:27:40.624421 getheaders 399910 to 0000000000000000055a8d660c231dc279ad443f9b9b4c0ce7871ca76fc2a26a from peer=5
2016-02-25 03:27:40.624443 sending: headers (82 bytes) peer=5
2016-02-25 03:29:26.638425 sending: ping (8 bytes) peer=5
2016-02-25 03:29:26.714478 received: pong (8 bytes) peer=5
2016-02-25 03:31:26.670357 sending: ping (8 bytes) peer=5
2016-02-25 03:31:26.746327 received: pong (8 bytes) peer=5
2016-02-25 03:33:26.719860 sending: ping (8 bytes) peer=5
2016-02-25 03:33:26.795763 received: pong (8 bytes) peer=5
2016-02-25 03:35:26.735255 sending: ping (8 bytes) peer=5
2016-02-25 03:35:26.811319 received: pong (8 bytes) peer=5
2016-02-25 03:35:44.727049 received: inv (37 bytes) peer=5
2016-02-25 03:35:44.727108 got inv: block 000000000000000005a43f5f8e3ba24d0c883f52c50fe1516d388c0beb82092e have peer=5
2016-02-25 03:37:26.768606 sending: ping (8 bytes) peer=5
2016-02-25 03:37:26.844447 received: pong (8 bytes) peer=5
2016-02-25 03:38:40.726377 received: inv (37 bytes) peer=5
2016-02-25 03:38:40.726424 got inv: block 000000000000000003863fc0e1f681ee116bc1969d83c6fd79b7236f461b3dc8 have peer=5
2016-02-25 03:39:26.852340 sending: ping (8 bytes) peer=5
2016-02-25 03:39:26.928320 received: pong (8 bytes) peer=5
2016-02-25 03:39:52.833825 received: inv (37 bytes) peer=5
2016-02-25 03:39:52.833875 got inv: block 0000000000000000048d37e2e2ee7cc251a55c6db98f93d30d9514fccb1e05b2 have peer=5
2016-02-25 03:39:52.909224 received: inv (37 bytes) peer=5
2016-02-25 03:39:52.909267 got inv: block 000000000000000006a553939f586b491f63d3158b3baee1fbdf06bd3c41becc have peer=5
2016-02-25 03:39:52.909498 received: inv (37 bytes) peer=5
2016-02-25 03:39:52.909532 got inv: block 0000000000000000040a1634cb04b7fc15fcbd497861f8c1e8ba2702aa0e5102 have peer=5
2016-02-25 03:40:29.195452 received: inv (37 bytes) peer=5
2016-02-25 03:40:29.195493 got inv: block 000000000000000006a553939f586b491f63d3158b3baee1fbdf06bd3c41becc have peer=5
2016-02-25 03:40:42.916763 sending: addr (31 bytes) peer=5
2016-02-25 03:41:26.872496 sending: ping (8 bytes) peer=5
2016-02-25 03:41:26.948482 received: pong (8 bytes) peer=5
2016-02-25 03:41:32.723481 SendMessages: sending header 0000000000000000045c976c3bf82c2799c71e6ea68906421d21919aec653ba1 to peer=5
2016-02-25 03:41:32.723507 sending: headers (82 bytes) peer=5
2016-02-25 03:42:27.600880 SendMessages: sending header 0000000000000000004b4641818e1a05201a590172e96827e331810e6f7ef285 to peer=5
2016-02-25 03:42:27.600899 sending: headers (82 bytes) peer=5
2016-02-25 03:43:26.905505 sending: ping (8 bytes) peer=5
2016-02-25 03:43:26.981511 received: pong (8 bytes) peer=5
2016-02-25 03:44:13.689181 SendMessages: sending header 000000000000000001293c1a8c0496976d5df54e880cbf2137696e0f0f289f3b to peer=5
2016-02-25 03:44:13.689209 sending: headers (82 bytes) peer=5
2016-02-25 03:44:31.887382 received: inv (37 bytes) peer=5
2016-02-25 03:44:31.887454 got inv: block 000000000000000006acbd2f1a0e688c5f88b9d6542f3168d709e7e0209c8776 have peer=5
2016-02-25 03:45:26.988531 sending: ping (8 bytes) peer=5
2016-02-25 03:45:27.064530 received: pong (8 bytes) peer=5
2016-02-25 03:47:27.015442 sending: ping (8 bytes) peer=5
2016-02-25 03:47:27.091397 received: pong (8 bytes) peer=5
2016-02-25 03:47:57.151362 received: inv (37 bytes) peer=5
2016-02-25 03:47:57.151426 got inv: block 000000000000000003863fc0e1f681ee116bc1969d83c6fd79b7236f461b3dc8 have peer=5
2016-02-25 03:49:27.023873 sending: ping (8 bytes) peer=5
2016-02-25 03:49:27.126229 received: pong (8 bytes) peer=5
2016-02-25 03:51:27.063346 sending: ping (8 bytes) peer=5
2016-02-25 03:51:27.139456 received: pong (8 bytes) peer=5
2016-02-25 03:52:02.639023 received: inv (37 bytes) peer=5
2016-02-25 03:52:02.639084 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf new peer=5
2016-02-25 03:52:02.639110 sending: getheaders (997 bytes) peer=5
2016-02-25 03:52:02.639167 getheaders (399913) 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf to peer=5
2016-02-25 03:52:02.639189 sending: getdata (37 bytes) peer=5
2016-02-25 03:52:20.407013 received: inv (37 bytes) peer=5
2016-02-25 03:52:20.407065 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 03:53:27.078588 sending: ping (8 bytes) peer=5
2016-02-25 03:53:27.155332 received: pong (8 bytes) peer=5
2016-02-25 03:55:27.094616 sending: ping (8 bytes) peer=5
2016-02-25 03:55:27.170600 received: pong (8 bytes) peer=5
2016-02-25 03:56:09.845746 received: inv (37 bytes) peer=5
2016-02-25 03:56:09.845785 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 03:57:22.595017 received: inv (37 bytes) peer=5
2016-02-25 03:57:22.595051 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 03:57:27.095494 sending: ping (8 bytes) peer=5
2016-02-25 03:57:27.175737 received: pong (8 bytes) peer=5
2016-02-25 03:57:59.312015 received: inv (37 bytes) peer=5
2016-02-25 03:57:59.312060 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 03:59:27.181473 sending: ping (8 bytes) peer=5
2016-02-25 03:59:27.257374 received: pong (8 bytes) peer=5
2016-02-25 04:01:27.190789 sending: ping (8 bytes) peer=5
2016-02-25 04:01:27.290189 received: pong (8 bytes) peer=5
2016-02-25 04:02:20.607148 received: inv (37 bytes) peer=5
2016-02-25 04:02:20.607200 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 04:02:34.403450 sending: addr (31 bytes) peer=5
2016-02-25 04:03:27.639512 sending: ping (8 bytes) peer=5
2016-02-25 04:03:27.715490 received: pong (8 bytes) peer=5
2016-02-25 04:03:57.964562 received: inv (37 bytes) peer=5
2016-02-25 04:03:57.964628 got inv: block 000000000000000006968c648240001fd7d856f9732646763225b084f72404eb have peer=5
2016-02-25 04:04:15.959001 received: inv (37 bytes) peer=5
2016-02-25 04:04:15.959043 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 04:05:27.663258 sending: ping (8 bytes) peer=5
2016-02-25 04:05:27.739294 received: pong (8 bytes) peer=5
2016-02-25 04:07:27.701216 sending: ping (8 bytes) peer=5
2016-02-25 04:07:27.777073 received: pong (8 bytes) peer=5
2016-02-25 04:08:26.259859 received: inv (37 bytes) peer=5
2016-02-25 04:08:26.259903 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 04:09:27.719881 sending: ping (8 bytes) peer=5
2016-02-25 04:09:27.795892 received: pong (8 bytes) peer=5
2016-02-25 04:10:21.115286 received: inv (37 bytes) peer=5
2016-02-25 04:10:21.115329 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 04:10:41.128117 received: inv (37 bytes) peer=5
2016-02-25 04:10:41.128176 got inv: block 000000000000000006a553939f586b491f63d3158b3baee1fbdf06bd3c41becc have peer=5
2016-02-25 04:10:47.314680 received: inv (37 bytes) peer=5
2016-02-25 04:10:47.314724 got inv: block 000000000000000003863fc0e1f681ee116bc1969d83c6fd79b7236f461b3dc8 have peer=5
2016-02-25 04:10:47.891925 received: inv (37 bytes) peer=5
2016-02-25 04:10:47.891975 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 04:11:27.721622 sending: ping (8 bytes) peer=5
2016-02-25 04:11:27.797602 received: pong (8 bytes) peer=5
2016-02-25 04:11:48.622047 received: inv (37 bytes) peer=5
2016-02-25 04:11:48.622095 got inv: block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf have peer=5
2016-02-25 04:12:02.649818 Timeout downloading block 000000000000000005d165e5f2f5e1755c5beacdb577516badddb70f735d8abf from peer=5, disconnecting
2016-02-25 04:12:02.650520 disconnecting peer=5

Second peer:
2016-02-25 03:27:26.585853 Added connection to 45.59.67.242:24096 peer=8
2016-02-25 03:27:26.594616 received: version (102 bytes) peer=8
2016-02-25 03:27:26.594644 send version message: version 70012, blocks=399909, us=0.0.0.0:8333, them=45.59.67.242:24096, peer=8
2016-02-25 03:27:26.594660 sending: version (102 bytes) peer=8
2016-02-25 03:27:26.594692 sending: verack (0 bytes) peer=8
2016-02-25 03:27:26.594727 receive version message: /Satoshi:0.11.2/: version 70002, blocks=398962, us=0.0.0.0:0, peer=8, peeraddr=45.59.67.242:24096
2016-02-25 03:27:26.594748 sending: ping (8 bytes) peer=8
2016-02-25 03:27:26.594784 initial getheaders (399908) to peer=8 (startheight:398962)
2016-02-25 03:27:26.594803 sending: getheaders (997 bytes) peer=8
2016-02-25 03:27:26.652033 received: verack (0 bytes) peer=8
2016-02-25 03:27:26.709122 received: getaddr (0 bytes) peer=8
2016-02-25 03:27:26.719489 received: pong (8 bytes) peer=8
2016-02-25 03:27:39.272680 sending: addr (6691 bytes) peer=8
2016-02-25 03:27:40.548476 SendMessages: sending inv peer=8 hash=0000000000000000055a8d660c231dc279ad443f9b9b4c0ce7871ca76fc2a26a
2016-02-25 03:27:40.548605 sending: inv (37 bytes) peer=8
2016-02-25 03:29:26.638499 sending: ping (8 bytes) peer=8
2016-02-25 03:29:26.695970 received: pong (8 bytes) peer=8
2016-02-25 03:31:26.670438 sending: ping (8 bytes) peer=8
2016-02-25 03:31:26.727856 received: pong (8 bytes) peer=8
2016-02-25 03:33:26.719910 sending: ping (8 bytes) peer=8
2016-02-25 03:33:26.777217 received: pong (8 bytes) peer=8
2016-02-25 03:35:26.735296 sending: ping (8 bytes) peer=8
2016-02-25 03:35:26.792777 received: pong (8 bytes) peer=8
2016-02-25 03:37:26.768651 sending: ping (8 bytes) peer=8
2016-02-25 03:37:26.826034 received: pong (8 bytes) peer=8
2016-02-25 03:39:26.852381 sending: ping (8 bytes) peer=8
2016-02-25 03:39:26.909663 received: pong (8 bytes) peer=8
2016-02-25 03:41:26.872553 sending: ping (8 bytes) peer=8
2016-02-25 03:41:26.929941 received: pong (8 bytes) peer=8
2016-02-25 03:41:32.723573 SendMessages: sending inv peer=8 hash=0000000000000000045c976c3bf82c2799c71e6ea68906421d21919aec653ba1
2016-02-25 03:41:32.723641 sending: inv (37 bytes) peer=8
2016-02-25 03:42:27.600944 SendMessages: sending inv peer=8 hash=0000000000000000004b4641818e1a05201a590172e96827e331810e6f7ef285
2016-02-25 03:42:27.625760 sending: inv (37 bytes) peer=8
2016-02-25 03:43:26.905566 sending: ping (8 bytes) peer=8
2016-02-25 03:43:26.963017 received: pong (8 bytes) peer=8
2016-02-25 03:44:13.689271 SendMessages: sending inv peer=8 hash=000000000000000001293c1a8c0496976d5df54e880cbf2137696e0f0f289f3b
2016-02-25 03:44:13.689335 sending: inv (37 bytes) peer=8
2016-02-25 03:45:26.988599 sending: ping (8 bytes) peer=8
2016-02-25 03:45:27.046023 received: pong (8 bytes) peer=8
2016-02-25 03:47:27.015494 sending: ping (8 bytes) peer=8
2016-02-25 03:47:27.072934 received: pong (8 bytes) peer=8
2016-02-25 03:49:27.023920 sending: ping (8 bytes) peer=8
2016-02-25 03:49:27.082058 received: pong (8 bytes) peer=8
2016-02-25 03:51:27.063410 sending: ping (8 bytes) peer=8
2016-02-25 03:51:27.120803 received: pong (8 bytes) peer=8
2016-02-25 03:53:20.479954 sending: addr (31 bytes) peer=8
2016-02-25 03:53:27.078641 sending: ping (8 bytes) peer=8
2016-02-25 03:53:27.136045 received: pong (8 bytes) peer=8
2016-02-25 03:55:27.094669 sending: ping (8 bytes) peer=8
2016-02-25 03:55:27.152122 received: pong (8 bytes) peer=8
2016-02-25 03:57:27.095562 sending: ping (8 bytes) peer=8
2016-02-25 03:57:27.156677 received: pong (8 bytes) peer=8
2016-02-25 03:58:17.120629 sending: addr (31 bytes) peer=8
2016-02-25 03:59:27.181538 sending: ping (8 bytes) peer=8
2016-02-25 03:59:27.238915 received: pong (8 bytes) peer=8
2016-02-25 04:01:27.190862 sending: ping (8 bytes) peer=8
2016-02-25 04:01:27.248246 received: pong (8 bytes) peer=8
2016-02-25 04:03:08.118377 sending: addr (31 bytes) peer=8
2016-02-25 04:03:27.639584 sending: ping (8 bytes) peer=8
2016-02-25 04:03:27.711646 received: pong (8 bytes) peer=8
2016-02-25 04:05:27.663313 sending: ping (8 bytes) peer=8
2016-02-25 04:05:27.720738 received: pong (8 bytes) peer=8
2016-02-25 04:07:27.701263 sending: ping (8 bytes) peer=8
2016-02-25 04:07:27.758529 received: pong (8 bytes) peer=8
2016-02-25 04:08:45.591612 sending: addr (31 bytes) peer=8
2016-02-25 04:09:27.719929 sending: ping (8 bytes) peer=8
2016-02-25 04:09:27.777268 received: pong (8 bytes) peer=8
2016-02-25 04:11:27.721667 sending: ping (8 bytes) peer=8
2016-02-25 04:11:27.779075 received: pong (8 bytes) peer=8

There appear to also be two connections from that same IP(this was taken after restarting bitcoind again):
{
"id": 4,
"addr": "45.59.67.242:64468",
"services": "0000000000000001",
"relaytxes": false,
"lastsend": 1456376513,
"lastrecv": 1456376447,
"bytessent": 7918,
"bytesrecv": 206,
"conntime": 1456376447,
"timeoffset": -92955,
"pingtime": 0.072335,
"minping": 0.072335,
"version": 70002,
"subver": "/Satoshi:0.11.2/",
"inbound": true,
"startingheight": 398962,
"banscore": 0,
"synced_headers": -1,
"synced_blocks": -1,
"inflight": [
],
"whitelisted": false
},
{
"id": 11,
"addr": "45.59.67.242:64537",
"services": "0000000000000001",
"relaytxes": false,
"lastsend": 1456376502,
"lastrecv": 1456376554,
"bytessent": 1319,
"bytesrecv": 572,
"conntime": 1456376447,
"timeoffset": -93290,
"pingtime": 0.07256899999999999,
"minping": 0.07256899999999999,
"version": 70002,
"subver": "/Satoshi:0.11.2/",
"inbound": true,
"startingheight": 398961,
"banscore": 0,
"synced_headers": 399923,
"synced_blocks": 399922,
"inflight": [
399923
],
"whitelisted": false
},

[jameshilliard]

I've also taken a packet capture for 45.59.67.242:23938 peer=5.

[jameshilliard]

Looks like someone else is having a similar issue with that exact same peer even on classiccoin.

[jameshilliard]

Interesting, so if you manually make an outbound connection to that IP you get a different subver.
{
"id": 2,
"addr": "45.59.67.242",
"addrlocal": "redacted:62167",
"services": "0000000000000001",
"relaytxes": true,
"lastsend": 1456384895,
"lastrecv": 1456384895,
"bytessent": 131736,
"bytesrecv": 1288853,
"conntime": 1456384364,
"timeoffset": -1,
"pingtime": 0.063569,
"minping": 0.063569,
"version": 70012,
"subver": "/Satoshi:0.12.99/",
"inbound": false,
"startingheight": 399938,
"banscore": 0,
"synced_headers": 399940,
"synced_blocks": 399940,
"inflight": [
],
"whitelisted": false
},

[zander]

A workaround I noticed is to disconnect a node from my 8 (allowing a new node to be connected to) after which a new block comes in. But just the one block. I didn't list IP addresses so I can't confirm the rest of the issue.

[jameshilliard]

@zander I just used setban on that IP address for now, but that's obviously not a long term solution for this sort of issue. I'm allowing incoming connections on this particular node.

[johnjacksonbtc]

setban is certainly not a solution for incoming Tor connections.

[sipa]

Somewhat improved in 0.12.1 by #7832

[johnjacksonbtc]

This stall happened twice in a row for same block using 0.12.1 for Tor peer and later for clearnet peer. 10 minutes between these log messages.

[rebroad]

#5099 I believe might fix the issue seen here. A semi-serious suggestion, given how old it is, but I am curious to know if it does solve it (despite being so old), as if it does it might warrant me getting it rebased (and better coded).