Incoming block downloads repeatedly freezing in 0.12 #7596

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 },

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

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

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 },

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.

@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.

setban is certainly not a solution for incoming Tor connections.

Somewhat improved in 0.12.1 by #7832

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.

#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).