Honest peer banning after `set_sync_fork_request`

[DamianStraszak]

Context: we are AlephZero and develop a substrate node with our custom finality gadget AlephBFT (in place of GRANDPA). We run at low block-time (1sec) and with AURA. Otherwise our spec is pretty standard. We currently depend on the polkadot-v0.9.13 branch.

We have been performing some simulated high-latency network tests and run into serious issues with the network reputation system. With low blocktime, and high network latency it is quite common to encounter forks and chain reorgs. In such cases our finality gadget occasionally requires importing some blocks which are out of the main branch, using the NetworkService::set_sync_fork_request call. This is completely analogous to GRANDPA, which also uses this call to fetch unknown blocks that are encountered during voting rounds.

The issue is that these calls make the nodes ban each other, here is how it looks like in logs:
2022-02-03 13:44:55.010 DEBUG tokio-runtime-worker peerset: Report 12D3KooWP3nEfSdusNZrAH7aZnwLkKizt1cmS5dR6LaM3vwEkLic: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
After that happens, the nodes stop talking to each other, and unsuprisingly the finalization stalls, because there are not enough nodes to achieve consensus.

Internally we don't even call NetworkService::set_sync_fork_request multiple times on the same block. The ban is a result of some internal retries in the sync protocol. As a result, honest nodes ban each other (there are typically a lots of these bans happening).

Is there a way for us to get around this issue without making changes to the sync protocol?

[arkpar]

Looks like an issue indeed. For starters, duplicate block request should not result in immediate ban, but in more gradual reputation decrease.
As for why this is happening in the first place, is there a test that demonstrate the issue?

[DamianStraszak]

For our node the kind of scenarios in which bad things related to the reputation system happen always start with high network latency or high cpu load, they cause a considerable number of forks to pop up (this is still normal and expected, due to our small blocktime) and then this triggers fork requests between nodes and then banning at the network layer shuts down the consensus for good.

We don't have a proper infrastructure to test it for a substrate node with grandpa, but instead we managed to replicate this in a localhost node with simulated network delay. This works both for our node and for substrate node as well.

The rough steps to reproduce with a substrate node (credit goes to @Yithis ) would be as follows:

1. Run 4 nodes (2 is probably enough, but we tested 4) Alice, Bob, Charlie, Dave
   ./target/release/substrate --base-path /tmp/alice --chain local --alice --port 30333 --ws-port 9945 --rpc-port 9933 --telemetry-url "wss://telemetry.polkadot.io/submit/ 0" --validator -lsync=trace -lpeerset=trace 2> alice.log

the same for bob, charlie and dave.
2. Impose artificial network delay on localhost
sudo tc qdisc add dev lo root netem delay 3000ms
This delays all packets by 3s (again, arbitrary choice here, 1s likely works well too).
(NOTE: to turn this delay off later use sudo tc qdisc del dev lo root netem delay 3000ms)
3. Wait a few minutes. You should see 2022-03-09 19:41:09.070 DEBUG tokio-runtime-worker peerset: Report 12D3KooWFs33a38TemeyGHrUZsK7Y6qjTgRt9AyRV3ouD1W3MiG6: -2147483648 to -2147483243. Reason: Same block request multiple times, Disconnecting or something similar in the logs which causes a ban.

[mike1729]

Hi @arkpar any progress on the issue? Can we help you somehow?

[arkpar]

I'm on vacation till April 3rd. Anyone else is welcome to take a look in the meantime.

[nathanwhit]

I've been looking into this recently, as our network (Creditcoin) has been affected. So far I've identified three causes of duplicate requests, in decreasing order of prevalence/impact:

Ancestor search after disconnects
When a node has a spotty connection (though it can happen whenever there are disconnects), the following series of events can occur:

1. Node connects to peer
2. Node performs ancestor search, requesting some set of blocks in the process
3. Node disconnects from peer before sync is complete
4. Node reconnects
5. Node starts ancestor search from scratch, and happens to request a block that's in the set we requested in 2
6. Node gets banned because of the duplicate request, peer disconnects

If the node reconnects again, the set of blocks that we've already requested has likely grown so the chance we perform a duplicate request increases with each new sync attempt. The same issue occurs in the reverse direction, where the peer also makes duplicate requests over multiple ancestry searches, and then we ban the peer. This leads to a vicious cycle of banning that prevents the node from re-syncing with the chain.

I'm unsure of the best way forward here. Any thoughts @bkchr?

Ancestor binary search bug
The binary search part of ancestor search currently can search the same block twice. Fixed in #11067.

Bug in the sync code
Best explained by the following failing test case:

 #[test]
fn dont_duplicate_requests() {
	let mut bc = BlockCollection::new();
	assert!(is_empty(&bc));
	let peer = PeerId::random();

	let blocks = generate_blocks(10);

	// count = 5, peer_best = 50, common = 39, max_parallel = 0, max_ahead = 200
	assert_eq!(bc.needed_blocks(peer.clone(), 5, 50, 39, 0, 200), Some(40..45));

	// got a response on the request for `40..45`
	bc.clear_peer_download(&peer);
	bc.insert(40, blocks[..5].to_vec(), peer.clone());

	// our "node" started on a fork, with its current best = 47, which is > common && <
	// peer_best. on startup in `reset_sync_start_point` we set our `best_queued_number` to our
	// current best. when we receive the response for the first set of blocks, we
	// `drain_blocks(best_queued_number+1)`, which removes the just inserted blocks from the
	// collection
	let drained = bc.drain(48);
	assert_eq!(
		drained,
		blocks[..5]
			.iter()
			.map(|b| BlockData { block: b.clone(), origin: Some(peer.clone()) })
			.collect::<Vec<_>>()
	);

	// this fails because we've just deleted `40..45` from the collection, so here we return
	// `Some(40..45)` again, leading to a duplicate block request
	assert_eq!(bc.needed_blocks(peer.clone(), 5, 50, 39, 0, 200), Some(45..50));
}

We do want to import the blocks when we drain but in this case, we don't want them actually removed from the block collection. I'm still thinking on the cleanest way to fix this.

[bkchr]

Thank you for looking into this :)

Ancestor search after disconnects When a node has a spotty connection (though it can happen whenever there are disconnects), the following series of events can occur:

1. Node connects to peer

2. Node performs ancestor search, requesting some set of blocks in the process

3. Node disconnects from peer before sync is complete

4. Node reconnects

5. Node starts ancestor search from scratch, and happens to request a block that's in the set we requested in 2

6. Node gets banned because of the duplicate request, peer disconnects

If the node reconnects again, the set of blocks that we've already requested has likely grown so the chance we perform a duplicate request increases with each new sync attempt. The same issue occurs in the reverse direction, where the peer also makes duplicate requests over multiple ancestry searches, and then we ban the peer. This leads to a vicious cycle of banning that prevents the node from re-syncing with the chain.

I think we could do 2 things. Either we remove seen requests from a peer when a peer disconnected or we just allow duplicated requests for small requests as we have here with the ancestor request. So, if the other side only requests the header | justification we allow it.