Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

error message 'No sync peer candidates available' when 7 are available #138

Closed
carryforward opened this issue Jun 11, 2014 · 8 comments
Closed

Comments

@carryforward
Copy link
Contributor

I have observed an interesting log message which may be indicative of a bug. When btcd connects to the first node, it starts syncing to it. It then connected to 7 other nodes. All notes are from outbound connections. It gets all the blocks then loses connectivity to the first node. It complains that it cannot sync the blockchain, because there are no peer candidates available, even though it is connected to 7 others. Only after it connects to a new node does it claims to restart syncing.

This is running from the latest commits as of today.

Feel free to close this if it is expected behavior.

user@computer:~$ btcd
18:32:07 2014-06-10 [INF] BTCD: Version 0.8.0-beta
18:32:07 2014-06-10 [INF] BTCD: Loading block database from '/home/user/.btcd/data/mainnet/blocks_leveldb'
18:32:07 2014-06-10 [INF] BTCD: Block database loaded with block height 305063
18:32:07 2014-06-10 [INF] BMGR: Generating initial block node index.  This may take a while...
18:32:09 2014-06-10 [INF] BMGR: Block index generation complete
18:32:09 2014-06-10 [INF] RPCS: RPC server listening on 127.0.0.1:8334
18:32:09 2014-06-10 [INF] SRVR: Server listening on [::]:8333
18:32:09 2014-06-10 [INF] SRVR: Server listening on 0.0.0.0:8333
18:32:09 2014-06-10 [INF] AMGR: Loaded 12004 addresses from '/home/user/.btcd/data/mainnet/peers.json'
18:32:43 2014-06-10 [INF] BMGR: New valid peer 74.103.125.183:8333 (outbound) (/Satoshi:0.8.3/)
18:32:43 2014-06-10 [INF] BMGR: Syncing to block height 305175 from peer 74.103.125.183:8333
18:32:44 2014-06-10 [INF] BMGR: New valid peer 204.27.61.162:8333 (outbound) (/Satoshi:0.9.1/)
18:32:44 2014-06-10 [INF] BMGR: New valid peer 74.194.16.86:8333 (outbound) (/Satoshi:0.9.1/)
18:32:44 2014-06-10 [INF] BMGR: New valid peer 62.45.21.149:8333 (outbound) (/Satoshi:0.9.1/)
18:32:44 2014-06-10 [INF] BMGR: New valid peer 70.185.114.205:8333 (outbound) (/Satoshi:0.8.6/)
18:32:46 2014-06-10 [INF] BMGR: Processed 1 block in the last 38.62s (181 transactions, height 305064, 2014-06-10 02:35:56 -0400 EDT)
...
18:37:21 2014-06-10 [INF] BMGR: Processed 1 block in the last 22.88s (246 transactions, height 305137, 2014-06-10 13:25:30 -0400 EDT)
18:37:21 2014-06-10 [INF] BMGR: New valid peer 76.74.178.173:8333 (outbound) (/Satoshi:0.8.99/)
18:37:21 2014-06-10 [INF] BMGR: New valid peer 65.74.81.132:8333 (outbound) (/Satoshi:0.9.1/)
18:37:54 2014-06-10 [INF] BMGR: Processed 1 block in the last 33.08s (360 transactions, height 305138, 2014-06-10 13:32:31 -0400 EDT)
...
18:39:19 2014-06-10 [INF] BMGR: Processed 1 block in the last 11.42s (421 transactions, height 305142, 2014-06-10 13:56:20 -0400 EDT)
18:39:19 2014-06-10 [INF] BMGR: New valid peer 67.167.146.65:8333 (outbound) (/Satoshi:0.8.5/)
18:39:43 2014-06-10 [INF] BMGR: Processed 2 blocks in the last 23.65s (711 transactions, height 305144, 2014-06-10 14:04:19 -0400 EDT)
...
18:41:45 2014-06-10 [INF] BMGR: Processed 5 blocks in the last 13.8s (1909 transactions, height 305176, 2014-06-10 18:37:25 -0400 EDT)
18:41:45 2014-06-10 [INF] BMGR: Lost peer 204.27.61.162:8333 (outbound)
18:41:45 2014-06-10 [INF] BMGR: Lost peer 74.194.16.86:8333 (outbound)
18:41:45 2014-06-10 [INF] BMGR: New valid peer 96.41.176.102:8333 (outbound) (/Satoshi:0.9.1/)
18:41:45 2014-06-10 [INF] BMGR: Lost peer 62.45.21.149:8333 (outbound)
18:41:45 2014-06-10 [INF] BMGR: New valid peer 106.186.23.245:8333 (outbound) (/Satoshi:0.9.1/)
18:51:22 2014-06-10 [INF] BMGR: Processed 2 blocks in the last 9m36.32s (537 transactions, height 305178, 2014-06-10 18:50:34 -0400 EDT)
19:00:19 2014-06-10 [WRN] PEER: Peer 65.74.81.132:8333 (outbound) no answer for 5 minutes, disconnecting
19:00:19 2014-06-10 [INF] BMGR: Lost peer 65.74.81.132:8333 (outbound)
19:02:26 2014-06-10 [INF] BMGR: New valid peer 194.36.10.160:8333 (outbound) (/Satoshi:0.8.1/)
19:06:05 2014-06-10 [INF] BMGR: New valid peer 192.249.87.250:8333 (outbound) (/Satoshi:0.9.1/)
19:13:44 2014-06-10 [INF] BMGR: Processed 1 block in the last 22m22.35s (761 transactions, height 305179, 2014-06-10 19:13:25 -0400 EDT)
...
19:48:12 2014-06-10 [INF] BMGR: Processed 1 block in the last 26m26.04s (828 transactions, height 305182, 2014-06-10 19:47:22 -0400 EDT)
19:50:12 2014-06-10 [INF] BMGR: Lost peer 74.103.125.183:8333 (outbound)
19:50:12 2014-06-10 [WRN] BMGR: No sync peer candidates available
19:52:20 2014-06-10 [INF] BMGR: New valid peer 62.32.228.96:8333 (outbound) (/Satoshi:0.8.6/)
19:52:20 2014-06-10 [INF] BMGR: Syncing to block height 305182 from peer 62.32.228.96:8333
19:54:56 2014-06-10 [INF] BMGR: Processed 1 block in the last 6m43.95s (38 transactions, height 305183, 2014-06-10 19:43:35 -0400 EDT)
@carryforward
Copy link
Contributor Author

There is a possibility all 7 others were loading the blockchain, but my upload bandwidth did not show very much data being sent after the 74.103.125.183 peer was lost.

@davecgh
Copy link
Member

davecgh commented Jun 11, 2014

Thanks for the report. I'll look through it, but my first thought is that it might be the fact that the other nodes are not yet known to be at the same block height as the current height, so it doesn't see them as valid sync peer candidates.

@carryforward
Copy link
Contributor Author

this behavior is reproducible. This log shows it happened again.

15:35:59 2014-06-13 [INF] BTCD: Version 0.8.0-beta
15:35:59 2014-06-13 [INF] BTCD: Loading block database from '/home/user/.btcd/data/mainnet/blocks_leveldb'
15:35:59 2014-06-13 [INF] BTCD: Block database loaded with block height 305603
15:35:59 2014-06-13 [INF] BMGR: Generating initial block node index.  This may take a while...
15:36:03 2014-06-13 [INF] BMGR: Block index generation complete
15:36:03 2014-06-13 [INF] SRVR: Server listening on 0.0.0.0:8333
15:36:03 2014-06-13 [INF] RPCS: RPC server listening on 127.0.0.1:8334
15:36:03 2014-06-13 [INF] SRVR: Server listening on [::]:8333
15:36:03 2014-06-13 [INF] AMGR: Loaded 13673 addresses from '/home/user/.btcd/data/mainnet/peers.json'
15:36:39 2014-06-13 [INF] BMGR: New valid peer 176.9.192.241:8333 (outbound) (/Satoshi:0.9.1/)
15:36:39 2014-06-13 [INF] BMGR: Syncing to block height 305628 from peer 176.9.192.241:8333
15:36:39 2014-06-13 [INF] BMGR: New valid peer 106.186.23.245:8333 (outbound) (/Satoshi:0.9.1/)
15:36:43 2014-06-13 [INF] BMGR: Processed 1 block in the last 44.38s (512 transactions, height 305604, 2014-06-13 12:51:57 -0400 EDT)
15:36:43 2014-06-13 [INF] BMGR: New valid peer 87.207.48.177:8333 (outbound) (/Satoshi:0.8.5/)
15:36:55 2014-06-13 [INF] BMGR: Processed 6 blocks in the last 11.52s (1437 transactions, height 305610, 2014-06-13 13:07:56 -0400 EDT)
15:37:05 2014-06-13 [INF] BMGR: Processed 4 blocks in the last 10.02s (1994 transactions, height 305614, 2014-06-13 13:46:17 -0400 EDT)
15:37:21 2014-06-13 [INF] BMGR: Processed 5 blocks in the last 16.19s (2173 transactions, height 305619, 2014-06-13 14:17:06 -0400 EDT)
15:37:31 2014-06-13 [INF] BMGR: Processed 5 blocks in the last 10.2s (2277 transactions, height 305624, 2014-06-13 15:00:10 -0400 EDT)
15:38:17 2014-06-13 [INF] BMGR: Processed 5 blocks in the last 45.94s (1725 transactions, height 305629, 2014-06-13 15:38:00 -0400 EDT)
15:40:53 2014-06-13 [INF] BMGR: New valid peer 5.231.54.240:8333 (outbound) (/Satoshi:0.9.1/)
15:40:56 2014-06-13 [INF] BMGR: New valid peer 210.65.11.5:8333 (outbound) (/Satoshi:0.9.1/)
15:41:28 2014-06-13 [INF] BMGR: Processed 1 block in the last 3m11.04s (181 transactions, height 305630, 2014-06-13 15:41:18 -0400 EDT)
15:43:02 2014-06-13 [INF] BMGR: New valid peer 118.244.207.6:8333 (outbound) (/Satoshi:0.8.6/)
15:43:31 2014-06-13 [INF] BMGR: New valid peer 199.15.252.189:8333 (outbound) (/Satoshi:0.8.1/)
15:47:10 2014-06-13 [INF] BMGR: Processed 1 block in the last 5m41.79s (264 transactions, height 305631, 2014-06-13 15:46:29 -0400 EDT)
15:51:30 2014-06-13 [INF] BMGR: New valid peer 82.40.61.121:8333 (outbound) (/Satoshi:0.9.1/)
15:51:59 2014-06-13 [INF] BMGR: Processed 1 block in the last 4m49.33s (242 transactions, height 305632, 2014-06-13 15:51:50 -0400 EDT)
15:52:27 2014-06-13 [INF] BMGR: Processed 1 block in the last 28.03s (60 transactions, height 305633, 2014-06-13 15:52:01 -0400 EDT)
16:01:07 2014-06-13 [INF] BMGR: Lost peer 176.9.192.241:8333 (outbound)
16:01:07 2014-06-13 [WRN] BMGR: No sync peer candidates available
16:05:22 2014-06-13 [INF] BMGR: New valid peer 176.9.104.178:8333 (outbound) (/Satoshi:0.8.4/)
16:05:22 2014-06-13 [INF] BMGR: Syncing to block height 305633 from peer 176.9.104.178:8333

@davecgh davecgh added the bug label Jun 13, 2014
@davecgh
Copy link
Member

davecgh commented Jun 13, 2014

Yep I know what the issue is. I've marked it as bug. We'll get it fixed. Thanks for the reconfirm.

@davecgh
Copy link
Member

davecgh commented Jul 4, 2014

As an update to this, I've been busy with higher prio tickets, but I'll put the issue here in case somebody else gets to it first.

In short, when a peer connects, it reports its height. This information is then used to disqualify peers that are lower than your current height as sync peers since they don't have blocks you need. However, there are no further updates to the height after initial connect. Thus, your local height eventually overtakes the static height in the peer which disqualifies it as a sync candidate.

The correct fix here would be to not rely on the reported height at all since the remote peer could lie about their height anyways.

@ghost
Copy link

ghost commented Sep 17, 2014

I just installed btcd as a bitcoind replacement. Full sync took 26 hours which is great. Seems rather more efficient in CPU and memory than bitcoind also which nice.

As soon as the sync was completed I'm getting continous new peers connecting and then disconnecting similar to the above issue (log below).

Is this common for all or does it only occur in certain situations? Just wanted to confirm if this would be causing 'bad behaviour' on the network as I don't want to be causing any issue for other nodes. But if it's not going to be an issue for others then no problem.

16:25:17 2014-09-17 [INF] BMGR: Processed 1 block in the last 10m24.02s (620 transactions, height 321187, 2014-09-17 16:24:53 +0000 UTC)
16:25:54 2014-09-17 [INF] BMGR: New valid peer 148.251.238.178:34281 (inbound) (/getaddr.bitnodes.io:0.1/)
16:25:55 2014-09-17 [INF] BMGR: Lost peer 148.251.238.178:34281 (inbound)
16:27:01 2014-09-17 [INF] BMGR: New valid peer 192.33.90.253:58331 (inbound) (/Snoopy:0.1/)
16:27:01 2014-09-17 [INF] BMGR: Lost peer 192.33.90.253:58331 (inbound)
16:29:22 2014-09-17 [INF] BMGR: New valid peer [2a03:b0c0:1:d0::91:9001]:57664 (inbound) (/bitcoin-seeder:0.01/)
16:29:32 2014-09-17 [INF] BMGR: Lost peer [2a03:b0c0:1:d0::91:9001]:57664 (inbound)

@jrick
Copy link
Member

jrick commented Sep 17, 2014

That's normal. There are a lot of programs out there (seeders, network mappers, etc.) that inbound to full nodes but are not full nodes or SPV wallets themselves.

For example, that getaddr.bitnodes.io peer you saw is what powers the website by the same name: https://getaddr.bitnodes.io/

@davecgh
Copy link
Member

davecgh commented Sep 17, 2014

That is normal. Look at the node user agents. They are network mappers, seeders, etc. They connect up to gather statistics, then disconnect. You'll see them reconnect periodically (typically every few minutes) as well.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants