Substrate: Random peer disconnecting

[arkpar]

Setup a local network with two peers and make one sync off the other. Sometimes the connection is dropped for no good reason.
Sync log on peer 1

2018-12-27 23:21:21 tokio-runtime-worker-2 TRACE sync  Requesting blocks from 0, (3329 to 3457)
2018-12-27 23:21:21 tokio-runtime-worker-6 TRACE sync  BlockResponse 26 from 0 with 128 blocks (3329..3456)
2018-12-27 23:21:21 tokio-runtime-worker-6 TRACE sync  Updating peer 0 info, ours=3456, common=3328, their best=73673
2018-12-27 23:21:21 tokio-runtime-worker-6 TRACE sync  Too many blocks in the queue.
2018-12-27 23:21:21 tokio-runtime-worker-6 TRACE sync  Disconnecting 0: PeerId(QmS8PMVvyZA6NHaqyyKpjVwo7vh2JAHK21pU9jj2im9pL3) through Listener { listen_addr: "/ip4/0.0.0.0/tcp/30333", send_back_addr: "/ip4/127.0.0.1/tcp/54559" }
2018-12-27 23:21:21 tokio-runtime-worker-9 ERROR libp2p_yamux  connection error: decode error: i/o error: I/O error: Connection reset by peer (os error 54)

On peer 2:

2018-12-27 23:21:21 tokio-runtime-worker-8 TRACE sync  BlockRequest 26 from 2: from Number(3329) to None max Some(128)
2018-12-27 23:21:21 tokio-runtime-worker-8 TRACE sync  Sending BlockResponse with 128 blocks
2018-12-27 23:21:21 tokio-runtime-worker-10 TRACE sync  Disconnecting 2: PeerId(QmU6d2ASoGTdvaQSSqKQyj9KY1PbpHMZWPbSFuhCHYfCsp) through Listener { listen_addr: "/ip4/0.0.0.0/tcp/30306", send_back_addr: "/ip4/127.0.0.1/tcp/54537" }

[xlc]

I have similar issue.

I have 3 nodes network all running as validators in the cloud, and the fourth node from my local machine trying to join the network.

It keep dropping connection to boot nodes with error Verification failed: Header xxxx rejected: too far in the future. It imported few blocks, drop the connection, and reconnects, and repeat. It can import blocks but never catch up to latest block.

2018-12-28 16:05:20 main INFO substrate_service Best block: #167 2018-12-28 16:05:20 main INFO sub-libp2p Local node address is: /ip4/0.0.0.0/tcp/30333/p2p/QmcPNvr4zg3YCxwruQAFTUAkVX9MMsMgdDRbqFpUes8AbR 2018-12-28 16:05:20 ImportQueue TRACE sync Starting import thread 2018-12-28 16:05:20 tokio-runtime-worker-1 INFO substrate Idle (0 peers), best: #167 (0x51a1…0e1f) 2018-12-28 16:05:23 tokio-runtime-worker-3 TRACE sync Connected 0: PeerId(QmQZ8TjTqeDj3ciwr93EJ95hxfDsb9pEYDizUAbWpigtQN) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:23 tokio-runtime-worker-3 TRACE sync Connected 1: PeerId(QmYcHeEWuqtr6Gb5EbK7zEhnaCm5p6vA2kWcVjFKbhApaC) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:23 tokio-runtime-worker-1 TRACE sync Connected 2: PeerId(QmXiB3jqqn2rpiKU7k1h7NJYeBg8WNSx9DiTRKz9ti2KSK) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:23 tokio-runtime-worker-0 INFO sub-libp2p New external node address: /ip4/10.2.46.0/tcp/30333/p2p/QmcPNvr4zg3YCxwruQAFTUAkVX9MMsMgdDRbqFpUes8AbR 2018-12-28 16:05:23 tokio-runtime-worker-0 INFO sub-libp2p New external node address: /ip4/10.2.46.1/tcp/30333/p2p/QmcPNvr4zg3YCxwruQAFTUAkVX9MMsMgdDRbqFpUes8AbR 2018-12-28 16:05:23 tokio-runtime-worker-0 TRACE sync New peer 2 Status { version: 1, roles: AUTHORITY, best_number: 173, best_hash: 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315, genesis_hash: 0xdd026fbfd3d2b031fa66a5df3fcb167db4391412c2458ff2973ad06f5dbcba81, chain_status: [] } 2018-12-28 16:05:23 tokio-runtime-worker-0 DEBUG sync Connected 2 PeerId(QmXiB3jqqn2rpiKU7k1h7NJYeBg8WNSx9DiTRKz9ti2KSK) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:23 tokio-runtime-worker-0 DEBUG sync New peer with unknown best hash 0x8b8b…5315 (173), searching for common ancestor. 2018-12-28 16:05:23 tokio-runtime-worker-0 TRACE sync Requesting ancestry block #167 from 2 2018-12-28 16:05:23 tokio-runtime-worker-0 TRACE sync New peer 1 Status { version: 1, roles: AUTHORITY, best_number: 173, best_hash: 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315, genesis_hash: 0xdd026fbfd3d2b031fa66a5df3fcb167db4391412c2458ff2973ad06f5dbcba81, chain_status: [] } 2018-12-28 16:05:23 tokio-runtime-worker-0 DEBUG sync Connected 1 PeerId(QmYcHeEWuqtr6Gb5EbK7zEhnaCm5p6vA2kWcVjFKbhApaC) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:23 tokio-runtime-worker-0 DEBUG sync New peer with unknown best hash 0x8b8b…5315 (173), searching for common ancestor. 2018-12-28 16:05:23 tokio-runtime-worker-0 TRACE sync Requesting ancestry block #167 from 1 2018-12-28 16:05:23 tokio-runtime-worker-0 INFO sub-libp2p New external node address: /ip4/10.2.30.0/tcp/30333/p2p/QmcPNvr4zg3YCxwruQAFTUAkVX9MMsMgdDRbqFpUes8AbR 2018-12-28 16:05:23 tokio-runtime-worker-0 TRACE sync New peer 0 Status { version: 1, roles: AUTHORITY, best_number: 173, best_hash: 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315, genesis_hash: 0xdd026fbfd3d2b031fa66a5df3fcb167db4391412c2458ff2973ad06f5dbcba81, chain_status: [] } 2018-12-28 16:05:23 tokio-runtime-worker-0 DEBUG sync Connected 0 PeerId(QmQZ8TjTqeDj3ciwr93EJ95hxfDsb9pEYDizUAbWpigtQN) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:23 tokio-runtime-worker-0 DEBUG sync New peer with unknown best hash 0x8b8b…5315 (173), searching for common ancestor. 2018-12-28 16:05:23 tokio-runtime-worker-0 TRACE sync Requesting ancestry block #167 from 0 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync BlockResponse 0 from 1 with 1 blocks (167) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Got ancestry block #167 (0x51a1…0e1f) from peer 1 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Found common ancestor for peer 1: 0x51a1…0e1f (167) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Considering new block download from 1, common block is 167, best is 173 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Requesting blocks from 1, (168 to 174) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Peer 0 is busy 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Peer 2 is busy 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync BlockResponse 0 from 0 with 1 blocks (167) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Got ancestry block #167 (0x51a1…0e1f) from peer 0 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Found common ancestor for peer 0: 0x51a1…0e1f (167) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Peer 1 is busy 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Considering new block download from 0, common block is 167, best is 173 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Out of range for peer 0 (174 vs 173) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Nothing to request 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Peer 2 is busy 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync BlockResponse 0 from 2 with 1 blocks (167) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Got ancestry block #167 (0x51a1…0e1f) from peer 2 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Found common ancestor for peer 2: 0x51a1…0e1f (167) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Peer 1 is busy 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Considering new block download from 0, common block is 167, best is 173 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Out of range for peer 0 (174 vs 173) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Nothing to request 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Considering new block download from 2, common block is 167, best is 173 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Out of range for peer 2 (174 vs 173) 2018-12-28 16:05:24 tokio-runtime-worker-3 TRACE sync Nothing to request 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync BlockResponse 1 from 1 with 6 blocks (168..173) 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Drained 6 blocks 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Updating peer 1 info, ours=173, common=167, their best=173 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Updating peer 0 info, ours=173, common=167, their best=173 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Updating peer 2 info, ours=173, common=167, their best=173 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Considering new block download from 1, common block is 173, best is 173 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Out of range for peer 1 (174 vs 173) 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Nothing to request 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Considering new block download from 0, common block is 173, best is 173 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Out of range for peer 0 (174 vs 173) 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Nothing to request 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Considering new block download from 2, common block is 173, best is 173 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Out of range for peer 2 (174 vs 173) 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Nothing to request 2018-12-28 16:05:25 tokio-runtime-worker-1 TRACE sync Scheduling 6 blocks for import 2018-12-28 16:05:25 ImportQueue TRACE sync Starting import of 6 blocks (168..173) 2018-12-28 16:05:25 tokio-runtime-worker-2 DEBUG sync Propagating extrinsics 2018-12-28 16:05:25 tokio-runtime-worker-1 INFO substrate Idle (3 peers), best: #167 (0x51a1…0e1f) 2018-12-28 16:05:25 ImportQueue TRACE sync Block queued 168: 0xf08a2edbd625f82d0fc22c870442c8c516b80357edf352e4f20b4d7d0a62b846 2018-12-28 16:05:25 ImportQueue TRACE sync Block imported successfully 168 (0xf08a…b846) 2018-12-28 16:05:25 ImportQueue TRACE sync Block queued 169: 0xa56c997d3016a7cdd4686d3654c416f322836822e12bba2083020d02d93835b4 2018-12-28 16:05:25 ImportQueue TRACE sync Block imported successfully 169 (0xa56c…35b4) 2018-12-28 16:05:25 ImportQueue TRACE sync Verifying 170(0x13fc…ed8a) from 1 failed: Header 0x13fc1db40f693667974474ed7da9666c0e3f2692ccd52cdf3dda908bd5e3ed8a rejected: too far in the future 2018-12-28 16:05:25 ImportQueue TRACE sync Useless peer 1, Verification failed: Header 0x13fc1db40f693667974474ed7da9666c0e3f2692ccd52cdf3dda908bd5e3ed8a rejected: too far in the future 2018-12-28 16:05:25 ImportQueue INFO substrate_network::io Purposefully dropping 1 ; reason: Useless("Verification failed: Header 0x13fc1db40f693667974474ed7da9666c0e3f2692ccd52cdf3dda908bd5e3ed8a rejected: too far in the future") 2018-12-28 16:05:25 ImportQueue INFO sub-libp2p Dropped PeerId(QmYcHeEWuqtr6Gb5EbK7zEhnaCm5p6vA2kWcVjFKbhApaC) 2018-12-28 16:05:25 tokio-runtime-worker-3 TRACE sync Disconnecting 1: unknown 2018-12-28 16:05:25 tokio-runtime-worker-3 TRACE sync Considering new block download from 0, common block is 173, best is 173 2018-12-28 16:05:25 tokio-runtime-worker-3 TRACE sync Out of range for peer 0 (174 vs 173) 2018-12-28 16:05:25 tokio-runtime-worker-3 TRACE sync Nothing to request 2018-12-28 16:05:25 tokio-runtime-worker-3 TRACE sync Considering new block download from 2, common block is 173, best is 173 2018-12-28 16:05:25 tokio-runtime-worker-3 TRACE sync Out of range for peer 2 (174 vs 173) 2018-12-28 16:05:25 tokio-runtime-worker-3 TRACE sync Nothing to request 2018-12-28 16:05:27 tokio-runtime-worker-1 TRACE sync Considering new block announced from 0: 0xef99…65b9 Header { parent_hash: 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315, number: 174, state_root: 0x78ddb2c27e55fca8313e1541764b4c9348ff36f99df3f986b8f4e5ad55de1205, extrinsics_root: 0x4424c853be78f5d2b4b1b48bd5c2674839d2ccb2da72709a7fe3159b1c7465fe, digest: Digest { logs: [Seal(257661060, 0xd3332c66b3ffcde4b58b9dea3affe468b596a765c1ee48c1fbd20066d5db946f699099185f9ab84af65204bbf473fe15af7b76cb00402ab5c1b436ab31697e07)] } } 2018-12-28 16:05:27 tokio-runtime-worker-1 TRACE sync Considering new block download from 0, common block is 173, best is 174 2018-12-28 16:05:27 tokio-runtime-worker-1 TRACE sync Requesting blocks from 0, (174 to 175) 2018-12-28 16:05:27 tokio-runtime-worker-1 TRACE sync Considering new block announced from 2: 0xef99…65b9 Header { parent_hash: 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315, number: 174, state_root: 0x78ddb2c27e55fca8313e1541764b4c9348ff36f99df3f986b8f4e5ad55de1205, extrinsics_root: 0x4424c853be78f5d2b4b1b48bd5c2674839d2ccb2da72709a7fe3159b1c7465fe, digest: Digest { logs: [Seal(257661060, 0xd3332c66b3ffcde4b58b9dea3affe468b596a765c1ee48c1fbd20066d5db946f699099185f9ab84af65204bbf473fe15af7b76cb00402ab5c1b436ab31697e07)] } } 2018-12-28 16:05:27 tokio-runtime-worker-1 TRACE sync Considering new block download from 2, common block is 173, best is 174 2018-12-28 16:05:27 tokio-runtime-worker-1 TRACE sync Out of range for peer 2 (175 vs 174) 2018-12-28 16:05:27 tokio-runtime-worker-1 TRACE sync Nothing to request 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync BlockResponse 1 from 0 with 1 blocks (174) 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Drained 1 blocks 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Updating peer 0 info, ours=174, common=173, their best=174 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Updating peer 2 info, ours=174, common=173, their best=174 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Considering new block download from 0, common block is 174, best is 174 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Out of range for peer 0 (175 vs 174) 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Nothing to request 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Considering new block download from 2, common block is 174, best is 174 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Out of range for peer 2 (175 vs 174) 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Nothing to request 2018-12-28 16:05:27 tokio-runtime-worker-0 TRACE sync Scheduling 1 blocks for import 2018-12-28 16:05:27 ImportQueue TRACE sync Starting import of 1 blocks (174) 2018-12-28 16:05:27 ImportQueue TRACE sync Verifying 174(0xef99…65b9) from 0 failed: Could not fetch authorities at 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315: Error(UnknownBlock("Hash(0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315)"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }) 2018-12-28 16:05:27 ImportQueue TRACE sync Useless peer 0, Verification failed: Could not fetch authorities at 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315: Error(UnknownBlock("Hash(0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315)"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }) 2018-12-28 16:05:27 ImportQueue INFO substrate_network::io Purposefully dropping 0 ; reason: Useless("Verification failed: Could not fetch authorities at 0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315: Error(UnknownBlock(\"Hash(0x8b8b465f9fb229c205db202fa33f65067c2813e45925aa5b4aa26bee57635315)\"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })") 2018-12-28 16:05:27 ImportQueue INFO sub-libp2p Dropped PeerId(QmQZ8TjTqeDj3ciwr93EJ95hxfDsb9pEYDizUAbWpigtQN) 2018-12-28 16:05:27 tokio-runtime-worker-2 TRACE sync Disconnecting 0: unknown 2018-12-28 16:05:27 tokio-runtime-worker-2 TRACE sync Considering new block download from 2, common block is 174, best is 174 2018-12-28 16:05:27 tokio-runtime-worker-2 TRACE sync Out of range for peer 2 (175 vs 174) 2018-12-28 16:05:27 tokio-runtime-worker-2 TRACE sync Nothing to request 2018-12-28 16:05:30 tokio-runtime-worker-3 DEBUG sync Propagating extrinsics 2018-12-28 16:05:30 tokio-runtime-worker-2 INFO substrate Idle (1 peers), best: #169 (0xa56c…35b4) 2018-12-28 16:05:32 tokio-runtime-worker-2 TRACE sync Connected 3: PeerId(QmQZ8TjTqeDj3ciwr93EJ95hxfDsb9pEYDizUAbWpigtQN) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync New peer 3 Status { version: 1, roles: AUTHORITY, best_number: 174, best_hash: 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9, genesis_hash: 0xdd026fbfd3d2b031fa66a5df3fcb167db4391412c2458ff2973ad06f5dbcba81, chain_status: [] } 2018-12-28 16:05:33 tokio-runtime-worker-0 DEBUG sync Connected 3 PeerId(QmQZ8TjTqeDj3ciwr93EJ95hxfDsb9pEYDizUAbWpigtQN) through Dialer { address: "/dns4/network.dev/tcp/30333" } 2018-12-28 16:05:33 tokio-runtime-worker-0 DEBUG sync New peer with unknown best hash 0xef99…65b9 (174), searching for common ancestor. 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Requesting ancestry block #174 from 3 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync BlockResponse 0 from 3 with 1 blocks (174) 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Got ancestry block #174 (0xef99…65b9) from peer 3 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Ancestry block mismatch for peer 3: theirs: 0xef99…65b9 (174), ours: None 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Requesting ancestry block #173 from 3 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Considering new block announced from 2: 0x7a5e…341d Header { parent_hash: 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9, number: 175, state_root: 0xd30354c523496f6f4be1e415da4a1c24017e97bde23a8ecacd9c677e49c73854, extrinsics_root: 0xc5b4284ae85d96af009709a0b15d1053f1639411eef4b9291c60154319c3bb49, digest: Digest { logs: [Seal(257661061, 0xcd9a27f719ca924cfc4d1f7c53b40a37c610f57149c06565afa231bbe3f9ef8f5930a3df8c9a8a46c4ebfa701fec6aa059847b513e98a7455f8a1af10128e501)] } } 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Considering new block download from 2, common block is 174, best is 175 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Requesting blocks from 2, (175 to 176) 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync BlockResponse 1 from 3 with 1 blocks (173) 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Got ancestry block #173 (0x8b8b…5315) from peer 3 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Ancestry block mismatch for peer 3: theirs: 0x8b8b…5315 (173), ours: None 2018-12-28 16:05:33 tokio-runtime-worker-0 TRACE sync Requesting ancestry block #172 from 3 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync BlockResponse 1 from 2 with 1 blocks (175) 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Drained 1 blocks 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Updating peer 2 info, ours=175, common=174, their best=175 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Peer 3 is busy 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Considering new block download from 2, common block is 175, best is 175 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Out of range for peer 2 (176 vs 175) 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Nothing to request 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Scheduling 1 blocks for import 2018-12-28 16:05:34 ImportQueue TRACE sync Starting import of 1 blocks (175) 2018-12-28 16:05:34 ImportQueue TRACE sync Verifying 175(0x7a5e…341d) from 2 failed: Could not fetch authorities at 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9: Error(UnknownBlock("Hash(0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9)"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }) 2018-12-28 16:05:34 ImportQueue TRACE sync Useless peer 2, Verification failed: Could not fetch authorities at 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9: Error(UnknownBlock("Hash(0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9)"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }) 2018-12-28 16:05:34 ImportQueue INFO substrate_network::io Purposefully dropping 2 ; reason: Useless("Verification failed: Could not fetch authorities at 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9: Error(UnknownBlock(\"Hash(0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9)\"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })") 2018-12-28 16:05:34 ImportQueue INFO sub-libp2p Dropped PeerId(QmXiB3jqqn2rpiKU7k1h7NJYeBg8WNSx9DiTRKz9ti2KSK) 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Disconnecting 2: unknown 2018-12-28 16:05:34 tokio-runtime-worker-2 TRACE sync Peer 3 is busy 2018-12-28 16:05:34 tokio-runtime-worker-3 TRACE sync BlockResponse 2 from 3 with 1 blocks (172) 2018-12-28 16:05:34 tokio-runtime-worker-3 TRACE sync Got ancestry block #172 (0x0430…e9d0) from peer 3 2018-12-28 16:05:34 tokio-runtime-worker-3 TRACE sync Ancestry block mismatch for peer 3: theirs: 0x0430…e9d0 (172), ours: None 2018-12-28 16:05:34 tokio-runtime-worker-3 TRACE sync Requesting ancestry block #171 from 3 2018-12-28 16:05:35 tokio-runtime-worker-0 DEBUG sync Propagating extrinsics 2018-12-28 16:05:35 tokio-runtime-worker-1 INFO substrate Idle (1 peers), best: #169 (0xa56c…35b4) 2018-12-28 16:05:35 tokio-runtime-worker-0 TRACE sync BlockResponse 3 from 3 with 1 blocks (171) 2018-12-28 16:05:35 tokio-runtime-worker-0 TRACE sync Got ancestry block #171 (0xb012…5746) from peer 3 2018-12-28 16:05:35 tokio-runtime-worker-0 TRACE sync Ancestry block mismatch for peer 3: theirs: 0xb012…5746 (171), ours: None 2018-12-28 16:05:35 tokio-runtime-worker-0 TRACE sync Requesting ancestry block #170 from 3 2018-12-28 16:05:35 tokio-runtime-worker-3 TRACE sync BlockResponse 4 from 3 with 1 blocks (170)

[gavofyork]

@tomaka please assign someone else if there's a better candidate for sorting this

[tomaka]

The underlying issue seems to be "Could not fetch authorities":

2018-12-28 16:05:34 ImportQueue TRACE sync  Starting import of 1 blocks  (175)
2018-12-28 16:05:34 ImportQueue TRACE sync  Verifying 175(0x7a5e…341d) from 2 failed: Could not fetch authorities at 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9: Error(UnknownBlock("Hash(0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9)"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2018-12-28 16:05:34 ImportQueue TRACE sync  Useless peer 2, Verification failed: Could not fetch authorities at 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9: Error(UnknownBlock("Hash(0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9)"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })
2018-12-28 16:05:34 ImportQueue INFO substrate_network::io  Purposefully dropping 2 ; reason: Useless("Verification failed: Could not fetch authorities at 0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9: Error(UnknownBlock(\"Hash(0xef9999678aa2e8b677bb14d0851bae522e2f4c4d24db35371f1dd29abe8165b9)\"), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } })")

I can take a look as I need to become more familiar with this code, but someone else can probably fix it faster.

[arkpar]

My original report had nothing to do with fetching authorities. @xlc Has a different issue.

[tomaka]

I could reproduce a few times on the master branch, but couldn't reproduce after #1386.
After #1386, the fetching authorities error was way more common though.

[tomaka]

The underlying problem is the behaviour to adopt when two nodes connect to each other simultaneously.

If we dial a remote and immediately start sending packets on that connection, and at the same time the remote dials our local node and immediately starts sending packets on their connection, there's inevitably some kind of mess happening.

Right now, in order to simplify the usage, libp2p enforces that there's only one simultaneous connection to each peer (the sync layer of Substrate isn't capable of handling multiple connections at the moment anyway).

If two nodes dial each simultaneously, when the first connection gets open the API of libp2p will report it and the connection will start being used. Then when the second connection is actually open, the two peers agree on one connection to drop (the node with the lowest ID keeps its outgoing connection), and if it is the existing one, then the API of libp2p reports that the unique exposed connection has been closed. It will then report that it has been reopened.

The messages in the logs reflect that situation.

This is also, for a slightly different reason, why the tests in #1634 fail at the moment. We start making a discovery RPC query on a connection, but then the connection gets closed because of a duplicate, and we never receive the result of the query.

[tomaka]

That's why this issue is not critical: it only happens on a local network, where the lag is 0.

The problem in #1634 also doesn't tend to happen in --release mode. It only happens in debug, where opening a TCP/IP connection is quicker than we are able to process the queue of events.

[gavofyork]

Well, I'd like to close it one way or another. If it's predictable and well understood, maybe we can change the logs to ensure it's clear that the thing we're dropping is fine because it's redundant? Or if it's not certain that it's redundant, maybe we can identify it and handle this situation more gracefully?

[tomaka]

If it's predictable and well understood, maybe we can change the logs to ensure it's clear that the thing we're dropping is fine because it's redundant?

I'd go with this option, cc https://github.com/libp2p/rust-libp2p/issues/844

[gavofyork]

ok - i'll delay to next milestone as we wait for upstream.

[kenhuang]

We also encounter this error message in the recent version of the substrate, local node running in release mode with --pruning=archive, all validator node also start with --pruning=archive.

Every time restart local node, is able to sync further to the new block number, but stop with too far in the future msg.

Let me know if you need more debug logs.

Update:
This issue seems only happen to mac, can't reproduce it from Linux version.

2019-03-21 11:50:53 Node name: heartbreaking-legs-6939
2019-03-21 11:50:53 Roles: FULL
2019-03-21 11:50:53 Best block: #30
2019-03-21 11:50:53 Local node address is: /ip4/0.0.0.0/tcp/30333/p2p/QmUvmUyDhfUph6T8ZVi4vSpZoBu1q3YXEFTfS4rF4eFSEx
2019-03-21 11:50:53 Kademlia random query has yielded empty results
2019-03-21 11:50:53 Listening for new connections on 127.0.0.1:9944.
2019-03-21 11:50:53 Dropping 1 because "Verification failed: Header 0x2a63e2698cfadba66c6fd5cc316a0a62916f3d5f227cf3bbe4f04573b6527493 rejected: too far in the future"
2019-03-21 11:50:58 Idle (0 peers), best: #35 (0x3852…eaca), finalized #20 (0xffa5…dc1c), ⬇ 0.9kiB/s ⬆ 0.6kiB/s
2019-03-21 11:51:03 Idle (0 peers), best: #35 (0x3852…eaca), finalized #20 (0xffa5…dc1c), ⬇ 55 B/s ⬆ 46 B/s
2019-03-21 11:51:08 Idle (0 peers), best: #35 (0x3852…eaca), finalized #20 (0xffa5…dc1c), ⬇ 0.1kiB/s ⬆ 0.1kiB/s
2019-03-21 11:51:13 Idle (0 peers), best: #35 (0x3852…eaca), finalized #20 (0xffa5…dc1c), ⬇ 0.2kiB/s ⬆ 0.2kiB/s
2019-03-21 11:51:17 Dropping 3 because "Verification failed: Header 0xb7718f8d661add3b1d0abd6ffcad2c236817d2403c72e566854c75a73cac4d83 rejected: too far in the future"
2019-03-21 11:51:18 Idle (1 peers), best: #38 (0xefa8…4f96), finalized #35 (0x3852…eaca), ⬇ 1.4kiB/s ⬆ 1.1kiB/s
2019-03-21 11:51:23 Idle (1 peers), best: #38 (0xefa8…4f96), finalized #37 (0xa90c…3a99), ⬇ 0.7kiB/s ⬆ 0.3kiB/s
2019-03-21 11:51:24 Imported #39 (0xb771…4d83)
2019-03-21 11:51:24 Dropping 2 because "Verification failed: Header 0xae013913f117d74d4002f1ea4aaaa749bc15ce661f720207c230a380c91fdf76 rejected: too far in the future"
2019-03-21 11:51:28 Idle (0 peers), best: #39 (0xb771…4d83), finalized #37 (0xa90c…3a99), ⬇ 0.3kiB/s ⬆ 0.1kiB/s
2019-03-21 11:51:33 Idle (0 peers), best: #39 (0xb771…4d83), finalized #37 (0xa90c…3a99), ⬇ 0.4kiB/s ⬆ 0.4kiB/s
2019-03-21 11:51:38 Idle (0 peers), best: #39 (0xb771…4d83), finalized #37 (0xa90c…3a99), ⬇ 0 ⬆ 0

[arkpar]

@kenhuang Make sure your system clock is synced
https://time.is/

[gavofyork]

Will reopen if all the new networking refactoring doesn't solve it.