Desynced node does not sends block invs #8797

issue johnjacksonbtc opened this issue on September 22, 2016

johnjacksonbtc commented at 7:46 PM on September 22, 2016: none

I have two nodes bound to loopback interface address 127.0.0.1, one node is configured to only connect to other one. Unfortunately it is unable to download any blocks from other node. -debug=net on both reveals a bunch of details.

Client node debug.log (duplicate entries dropped):

2016-09-22 19:25:15 Added connection peer=268
2016-09-22 19:25:15 connection from 127.0.0.1:54414 accepted
2016-09-22 19:25:18 received: version (102 bytes) peer=268
2016-09-22 19:25:18 send version message: version 70012, blocks=287903, us=0.0.0.0:8333, peer=268
2016-09-22 19:25:18 sending: version (101 bytes) peer=268
2016-09-22 19:25:18 sending: verack (0 bytes) peer=268
2016-09-22 19:25:18 receive version message: /Satoshi:0.12.1/: version 70012, blocks=415389, us=0.0.0.0:0, peer=268
2016-09-22 19:25:18 sending: ping (8 bytes) peer=268
2016-09-22 19:25:18 initial getheaders (421144) to peer=268 (startheight:415389)
2016-09-22 19:25:19 sending: getheaders (997 bytes) peer=268
2016-09-22 19:25:20 received: verack (0 bytes) peer=268
2016-09-22 19:25:20 sending: sendheaders (0 bytes) peer=268
2016-09-22 19:25:20 received: getaddr (0 bytes) peer=268
2016-09-22 19:25:20 received: ping (8 bytes) peer=268
2016-09-22 19:25:20 sending: pong (8 bytes) peer=268
2016-09-22 19:25:20 received: sendheaders (0 bytes) peer=268
2016-09-22 19:25:20 received: pong (8 bytes) peer=268
2016-09-22 19:25:21 trying connection 127.0.0.1:8333 lastseen=0.0hrs
2016-09-22 19:25:21 Added connection peer=269
2016-09-22 19:25:21 send version message: version 70012, blocks=287903, us=0.0.0.0:8333, peer=269
2016-09-22 19:25:21 sending: version (101 bytes) peer=269
2016-09-22 19:25:21 socket recv error An established connection was aborted by the software in your host machine.  (10053)
2016-09-22 19:25:21 disconnecting peer=269
2016-09-22 19:25:56 sending: addr (12153 bytes) peer=268
2016-09-22 19:27:18 sending: ping (8 bytes) peer=268
2016-09-22 19:27:18 received: pong (8 bytes) peer=268
2016-09-22 19:27:18 pong peer=268: Timing mishap, 28da2f9c49955968 expected, 28da2f9c49955968 received, 8 bytes
2016-09-22 19:27:18 received: ping (8 bytes) peer=268
2016-09-22 19:27:18 sending: pong (8 bytes) peer=268
2016-09-22 19:27:27 trying connection 127.0.0.1:8333 lastseen=0.0hrs
2016-09-22 19:27:27 Added connection peer=291
2016-09-22 19:27:27 send version message: version 70012, blocks=287903, us=0.0.0.0:8333, peer=291
2016-09-22 19:27:27 sending: version (101 bytes) peer=291
2016-09-22 19:27:27 socket recv error An established connection was aborted by the software in your host machine.  (10053)
2016-09-22 19:27:27 disconnecting peer=291
2016-09-22 19:29:18 sending: ping (8 bytes) peer=268
2016-09-22 19:29:18 received: pong (8 bytes) peer=268
2016-09-22 19:29:18 pong peer=268: Timing mishap, 3ec10460bf8bca87 expected, 3ec10460bf8bca87 received, 8 bytes
2016-09-22 19:29:18 received: ping (8 bytes) peer=268
2016-09-22 19:29:18 sending: pong (8 bytes) peer=268
2016-09-22 19:29:22 trying connection 127.0.0.1:8333 lastseen=0.0hrs
2016-09-22 19:29:22 Added connection peer=311
2016-09-22 19:29:22 send version message: version 70012, blocks=287903, us=0.0.0.0:8333, peer=311
2016-09-22 19:29:22 sending: version (101 bytes) peer=311
2016-09-22 19:29:22 socket recv error An established connection was aborted by the software in your host machine.  (10053)
2016-09-22 19:29:22 disconnecting peer=311
2016-09-22 19:31:18 sending: ping (8 bytes) peer=268
2016-09-22 19:31:23 trying connection 127.0.0.1:8333 lastseen=0.0hrs
2016-09-22 19:31:23 Added connection peer=332
2016-09-22 19:31:23 send version message: version 70012, blocks=287903, us=0.0.0.0:8333, peer=332
2016-09-22 19:31:23 sending: version (101 bytes) peer=332
2016-09-22 19:31:23 socket recv error An established connection was aborted by the software in your host machine.  (10053)
2016-09-22 19:31:23 disconnecting peer=332
2016-09-22 19:31:29 trying connection 127.0.0.1:8333 lastseen=0.0hrs
2016-09-22 19:31:29 Added connection peer=333
2016-09-22 19:31:29 send version message: version 70012, blocks=287903, us=0.0.0.0:8333, peer=333
2016-09-22 19:31:29 sending: version (101 bytes) peer=333
2016-09-22 19:31:29 socket recv error An established connection was aborted by the software in your host machine.  (10053)
2016-09-22 19:31:29 disconnecting peer=333

Host (proxy) node debug.log:

2016-09-22 19:25:15 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:15 trying connection 127.0.0.1:8343 lastseen=0.0hrs
2016-09-22 19:25:15 Added connection to 127.0.0.1:8343 peer=1
2016-09-22 19:25:15 send version message: version 70012, blocks=415389, us=0.0.0.0:8333, them=0.0.0.0:0, peer=1
2016-09-22 19:25:15 sending: version (102 bytes) peer=1
2016-09-22 19:25:18 received: version (101 bytes) peer=1
2016-09-22 19:25:18 sending: verack (0 bytes) peer=1
2016-09-22 19:25:18 sending: getaddr (0 bytes) peer=1
2016-09-22 19:25:18 receive version message: /Classic:1.1.1/: version 70012, blocks=287903, us=0.0.0.0:0, peer=1, peeraddr=127.0.0.1:8343
2016-09-22 19:25:18 added time data, samples 2, offset +0 (+0 minutes)
2016-09-22 19:25:18 sending: ping (8 bytes) peer=1
2016-09-22 19:25:18 received: verack (0 bytes) peer=1
2016-09-22 19:25:18 sending: sendheaders (0 bytes) peer=1
2016-09-22 19:25:18 received: ping (8 bytes) peer=1
2016-09-22 19:25:18 sending: pong (8 bytes) peer=1
2016-09-22 19:25:19 received: getheaders (997 bytes) peer=1
2016-09-22 19:25:19 Ignoring getheaders from peer=1 because node is in initial block download
2016-09-22 19:25:20 received: sendheaders (0 bytes) peer=1
2016-09-22 19:25:20 received: pong (8 bytes) peer=1
2016-09-22 19:25:21 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:26 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:32 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:38 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:44 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:50 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:55 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:25:56 received: addr (12153 bytes) peer=1
2016-09-22 19:26:01 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:05 connection to 71.96.128.213:8333 timeout
2016-09-22 19:26:05 trying connection 61.192.153.112:8333 lastseen=4957.4hrs
2016-09-22 19:26:07 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:13 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:18 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:24 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:30 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:36 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:41 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:47 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:53 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:26:59 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:04 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:05 connection to 61.192.153.112:8333 timeout
2016-09-22 19:27:06 trying connection 89.46.74.198:8333 lastseen=3293.1hrs
2016-09-22 19:27:10 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:16 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:18 received: ping (8 bytes) peer=1
2016-09-22 19:27:18 sending: pong (8 bytes) peer=1
2016-09-22 19:27:18 sending: ping (8 bytes) peer=1
2016-09-22 19:27:18 received: pong (8 bytes) peer=1
2016-09-22 19:27:18 pong peer=1: Timing mishap, eb132390474fe64e expected, eb132390474fe64e received, 8 bytes
2016-09-22 19:27:22 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:27 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:33 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:39 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:45 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:50 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:27:56 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:02 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:06 connection to 89.46.74.198:8333 timeout
2016-09-22 19:28:06 trying connection 167.160.36.104:8333 lastseen=0.7hrs
2016-09-22 19:28:07 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:08 Added connection to 167.160.36.104:8333 peer=2
2016-09-22 19:28:08 send version message: version 70012, blocks=415389, us=0.0.0.0:8333, them=167.160.36.104:8333, peer=2
2016-09-22 19:28:08 sending: version (102 bytes) peer=2
2016-09-22 19:28:08 trying connection 52.192.133.208:8333 lastseen=4903.4hrs
2016-09-22 19:28:08 received: version (122 bytes) peer=2
2016-09-22 19:28:08 sending: verack (0 bytes) peer=2
2016-09-22 19:28:08 sending: getaddr (0 bytes) peer=2
2016-09-22 19:28:08 receive version message: /BitcoinUnlimited:0.12.1(EB16; AD4)/: version 80002, blocks=431021, us=85.254.73.225:39984, peer=2, peeraddr=167.160.36.104:8333
2016-09-22 19:28:08 added time data, samples 3, offset +9 (+0 minutes)
2016-09-22 19:28:08 sending: ping (8 bytes) peer=2
2016-09-22 19:28:08 initial getheaders (431019) to peer=2 (startheight:431021)
2016-09-22 19:28:08 sending: getheaders (997 bytes) peer=2
2016-09-22 19:28:08 received: verack (0 bytes) peer=2
2016-09-22 19:28:08 sending: sendheaders (0 bytes) peer=2
2016-09-22 19:28:08 received: ping (8 bytes) peer=2
2016-09-22 19:28:08 sending: pong (8 bytes) peer=2
2016-09-22 19:28:08 received: addr (31 bytes) peer=2
2016-09-22 19:28:09 received: pong (8 bytes) peer=2
2016-09-22 19:28:10 received: headers (163 bytes) peer=2
2016-09-22 19:28:10 Requesting block 0000000000000000031a5aacde68a9c10ab102fc0706582f8a2e92982986f1e0 (415390) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000003e42583356cda7652363ed5087c324cb2f3ab26d139d747 (415391) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000003e4cebd4f63a40487aaba72eb9ec0c804cec6ad8a42b6a4 (415392) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000003590b54627291773f30c83610dd28661b288c31ac2794ca (415393) peer=2
2016-09-22 19:28:10 Requesting block 0000000000000000010537a0e115b881d81f3a7757975fe69386d57a5cad3d39 (415395) peer=2
2016-09-22 19:28:10 Requesting block 00000000000000000084b245f3536ac27b8970a8b24790aa1586d8c327694f0a (415396) peer=2
2016-09-22 19:28:10 Requesting block 0000000000000000047d3c54778f24f16fd7545deeb4b86951c6412353756725 (415397) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000005623a54c1768fa302fc0ff56981fe161112c56c8460daa0 (415398) peer=2
2016-09-22 19:28:10 Requesting block 0000000000000000050525e49d0241e6d7d11181f882c2cbb6dd4fcc5303fa74 (415400) peer=2
2016-09-22 19:28:10 Requesting block 0000000000000000001856e119c0b08cf3f570eea01c761bfebad81679a28fee (415401) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000004698e6ecd0a4a7962f6d615b165c4d65da1ed2131e1b8db (415402) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000001f53ea440b6e4ef89d783003e1365345bf117f354747349 (415404) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000000ad413022c571a06611d3b41de5c9a204a588e54de423cd (415405) peer=2
2016-09-22 19:28:10 Requesting block 000000000000000000f0747d8703317b2648ccd4e04e9aff6c5782ae153a29ca (415406) peer=2
2016-09-22 19:28:10 Requesting block 00000000000000000042f4a5ad3e11a780de12aff12cc6db0d859cf4490e5e2e (415408) peer=2
2016-09-22 19:28:10 Requesting block 00000000000000000072292ffaeb4336b66259b9a19450f240dfda5ab90c2444 (415410) peer=2
2016-09-22 19:28:10 sending: getdata (577 bytes) peer=2
2016-09-22 19:28:13 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:19 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:25 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:30 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:36 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:42 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:48 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:54 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:28:59 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:05 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:08 connection to 52.192.133.208:8333 timeout
2016-09-22 19:29:09 trying connection 52.26.169.121:8333 lastseen=2648.8hrs
2016-09-22 19:29:11 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:17 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:18 received: ping (8 bytes) peer=1
2016-09-22 19:29:18 sending: pong (8 bytes) peer=1
2016-09-22 19:29:18 sending: ping (8 bytes) peer=1
2016-09-22 19:29:19 received: pong (8 bytes) peer=1
2016-09-22 19:29:19 pong peer=1: Timing mishap, 3ec0de2a3ab3bc73 expected, 3ec0de2a3ab3bc73 received, 8 bytes
2016-09-22 19:29:22 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:28 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:34 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:40 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:45 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:51 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:29:57 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:03 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:08 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:09 sending: ping (8 bytes) peer=2
2016-09-22 19:30:09 connection to 52.26.169.121:8333 timeout
2016-09-22 19:30:09 trying connection 72.192.73.43:8333 lastseen=3113.8hrs
2016-09-22 19:30:14 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:19 received: block (999837 bytes) peer=2
2016-09-22 19:30:19 received block 0000000000000000031a5aacde68a9c10ab102fc0706582f8a2e92982986f1e0 peer=2
2016-09-22 19:30:20 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:26 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:31 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:37 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:43 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:49 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:30:54 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:31:00 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:31:06 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:31:09 connection to 72.192.73.43:8333 timeout
2016-09-22 19:31:10 trying connection 52.26.170.72:8333 lastseen=167.8hrs
2016-09-22 19:31:10 Added connection to 52.26.170.72:8333 peer=3
2016-09-22 19:31:12 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:31:17 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:31:23 failed to find an eviction candidate - connection dropped (full)
2016-09-22 19:31:29 failed to find an eviction candidate - connection dropped (full)

Doesn't that means if all nodes are tricked into desynced or initial sync state bitcoin network might halt completely?

laanwj added the label P2P on Sep 25, 2016
rebroad commented at 10:31 AM on October 12, 2016: contributor

Anyway, your node is not downloading from your proxy node as your proxy node is still in Initial Block Download so won't serve blocks until it has caught up with the chain. There was an issue (#6971) raised for this, but it got closed in December 2015 for some bizarre reason.

A solution would be to make make your local node whitelisted to your proxy node, then it will continue to serve blocks to it, however, since it's running Classic 1.1.1, I don't think this is currently a feature it can do.
laanwj commented at 9:35 PM on October 13, 2016: member
This is indeed a good case for using whitelisting. I opened a similar issue here: #6971.

Doesn't that means if all nodes are tricked into desynced or initial sync state bitcoin network might halt completely?

Yes, if all nodes are tricked into thinking they are behind, bad things will happen. But you will have some trouble doing this. Here is the logic for IsInitialBlockDownload: https://github.com/bitcoin/bitcoin/blob/master/src/main.cpp#L1716

This tricking would involve either:
- Current tip is 24*6 blocks behind the best header chain
- Current tip is older than 24 hours behind current time (configurable with -maxtipage)
In addition to this, all nodes would have to restart: after the IsInitialBlockDownload call returns false it latches to false for the rest of the run, so a running node will never revert to IBD status.

I (and I think most others too) have lways been slightly uncomfortable with having many things depending on this heuristic, but these measures exist to prevent bandwidth waste (fetching transactions during IBD) as well as IIRC to prevent some fingerprinting attacks.
laanwj commented at 10:59 AM on October 24, 2016: member

Closing the issue as it is more of a question, and the "Desynced node does not sends block invs" behavior is intended.
laanwj closed this on Oct 24, 2016
DrahtBot locked this on Sep 8, 2021

Contributors

Labels