Peer flooding block requests should get their reputation impacted

[crystalin]

Currently we are facing a case where a node (probably panicking and trying to import blocks in a loop) is flooding the network with block request.

This generates a permanent high traffic (100Mb/s) between the nodes.
Our current solution is to use the iptable to ban the ip of that node but a proper solution should be used.

I'd suggest to have the peer reputation impacted by that kind of behavior to avoid having the peer connected forever.

Exemple of logs:

Mar 03 14:01:28 localhost moonbase[1022024]: 2021-03-03 14:01:28.371  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:28 localhost moonbase[1022024]: 2021-03-03 14:01:28.397  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:28 localhost moonbase[1022024]: 2021-03-03 14:01:28.551  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:28 localhost moonbase[1022024]: 2021-03-03 14:01:28.599  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:28 localhost moonbase[1022024]: 2021-03-03 14:01:28.796  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:28 localhost moonbase[1022024]: 2021-03-03 14:01:28.811  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:28 localhost moonbase[1022024]: 2021-03-03 14:01:28.958  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:29 localhost moonbase[1022024]: 2021-03-03 14:01:29.193  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:29 localhost moonbase[1022024]: 2021-03-03 14:01:29.199  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
Mar 03 14:01:29 localhost moonbase[1022024]: 2021-03-03 14:01:29.223  TRACE tokio-runtime-worker peerset: Fleeting 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: 0 -> 0

[nuke-web3]

So you have triage (iptable balcklisting) for now, and are looking for a way to blacklist/deny libp2p connections in general in your node, before a better fix is implemented @crystalin?

You also reported:

• this is ongoing with nodes that you do not control at all, with no way to contact the node maintainers?
• The offending node generating the requests is a Paracahin Full node.
• The one sending the blocks are a mix of parachain collators and parachain full nodes

[crystalin]

@nukemandan Yes it would be great to support blacklisting peers directly, but also having an automatic flow in case this happens (a bad actor could also spam network with requests) by using reputation I suppose

[crystalin]

We were able to cherry-pick and deploy commit c4d564d into our nodes.
It took some time to get the bad peer to reconnect but it finally happened. The fix is working as the peer is not creating a high bandwidth for that node anymore.

Here are the logs:
node-basti-fix.log

(The culprit peer is 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m)
Here is the meaningful part of the logs:

2021-03-04 19:15:41.550  DEBUG tokio-runtime-worker block-request-handler: Handling block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: Starting at `BlockId::Number(77482)` with maximum blocks of `1` and direction `Ascending`.
2021-03-04 19:15:41.551  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
2021-03-04 19:15:41.717  DEBUG tokio-runtime-worker block-request-handler: Handling block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: Starting at `BlockId::Number(77482)` with maximum blocks of `1` and direction `Ascending`.
2021-03-04 19:15:41.718  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
2021-03-04 19:15:41.846  DEBUG tokio-runtime-worker block-request-handler: Handling block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: Starting at `BlockId::Number(79939)` with maximum blocks of `128` and direction `Descending`.
2021-03-04 19:15:41.874  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
2021-03-04 19:15:42.000  DEBUG tokio-runtime-worker block-request-handler: Handling block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: Starting at `BlockId::Number(77482)` with maximum blocks of `1` and direction `Ascending`.
2021-03-04 19:15:42.001  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.
2021-03-04 19:15:42.002  DEBUG tokio-runtime-worker peerset: Report 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
2021-03-04 19:15:42.078  DEBUG tokio-runtime-worker block-request-handler: Handling block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: Starting at `BlockId::Number(77482)` with maximum blocks of `1` and direction `Ascending`.
2021-03-04 19:15:42.079  DEBUG tokio-runtime-worker peerset: Report 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
2021-03-04 19:15:42.079  DEBUG tokio-runtime-worker block-request-handler: Handled block request from 12D3KooWJ8Z1u8kgKCvCMxXZLbMf89bnTG82phhtun73YLux8x7m.

This behavior however is repeated through time, so I think the peer is retrying to connect back every few seconds.

[crystalin]

There is however one problem with the current mechanism.

Mar 4, 2021 @ 15:15:41.114 | 2021-03-04 20:15:41.114  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:41.049 | 2021-03-04 20:15:41.049  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.984 | 2021-03-04 20:15:40.984  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.919 | 2021-03-04 20:15:40.919  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.854 | 2021-03-04 20:15:40.854  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.792 | 2021-03-04 20:15:40.792  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.728 | 2021-03-04 20:15:40.728  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.663 | 2021-03-04 20:15:40.663  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.599 | 2021-03-04 20:15:40.599  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting
Mar 4, 2021 @ 15:15:40.533 | 2021-03-04 20:15:40.532  DEBUG tokio-runtime-worker peerset: Report 12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss: -2147483648 to -2147483648. Reason: Same block request multiple times, Disconnecting

It seems to reconnect all the time very rapidly.

[tomaka]

@crystalin By curiosity, would it be possible for you to run with --log sub-libp2p=trace and find this line saying someting like Identified PeerId("12D3KooWGDWjstU8B5bHqzNntxRZGZ2v5hoKPct8MKeECwHkUmss") => ...?

It's not useful for your problem, but it would indicate the name and version of the node that is spamming you.

[crystalin]

@tomaka we know which node is acting weirdly, but we couldn't contact its owner (It also sends telemetry so we have the version associated)

[eskimor]

Re-opened as of #8308

[eskimor]

Gets only merged to rococo-v1, closing again.