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

Node can send multiple same block requests while syncing from other nodes #531

Open
2 tasks done
liuchengxu opened this issue Jun 22, 2022 · 16 comments
Open
2 tasks done

Comments

@liuchengxu
Copy link
Contributor

Is there an existing issue?

  • I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

  • This is not a support question.

Description of bug

Let's say node A is trying to sync from B, the block requests from A are not protected from sending the same block request multiple times, which can cause the B to mark A as a bad node sending the same requests over and over again and then send back an error result which will be considered as Refused on the side A.

From node_A.log, you can see the same block request was sent dozens of times.

$ cat node_A.log | grep 'New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, .* BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }'
2022-06-22 16:36:32.202 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150023, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:36:42.787 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150024, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:36:54.317 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150026, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:37:04.543 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150030, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:37:15.808 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150030, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:37:28.596 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150032, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:37:40.292 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150034, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:37:50.816 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150035, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:38:02.211 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150036, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:38:14.312 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150041, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:38:26.220 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150044, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:38:36.866 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150046, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:38:48.553 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150046, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:39:00.230 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150046, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:39:11.379 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150048, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
2022-06-22 16:39:22.507 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150050, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }
.....

If I read it correctly, once the request was processed for the first time, with 2 more same requests, the reputation would change, Err(()) will be returned, on the side of node A, Err(()) will be converted as RequestFailure::Refused. Those two nodes will disconnect from each other afterwards.

https://github.com/paritytech/substrate/blob/3c99545cb062fbc56b84e2f3e44def3b933123cd/client/network/sync/src/block_request_handler.rs#L216

https://github.com/paritytech/substrate/blob/3c99545cb062fbc56b84e2f3e44def3b933123cd/client/network/src/request_responses.rs#L662

2022-06-22 16:39:46.896 TRACE tokio-runtime-worker sync: [PrimaryChain] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:150056, common:2918) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(2982), to: None, direction: Descending, max: Some(64) }    
2022-06-22 16:39:47.438 DEBUG tokio-runtime-worker sync: [PrimaryChain] Request to peer PeerId("12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP") failed: Refused.

Steps to reproduce

No response

@arkpar
Copy link
Member

arkpar commented Jun 22, 2022

What's the reply sent back to all these requests?
A thinks that common block with B is 2982 and B advertises to have more blocks, therefore the request is sent. If B replies with no useful new blocks, it's reputation should decrease. Maybe that does not happen fast enough.

@liuchengxu
Copy link
Contributor Author

liuchengxu commented Jun 22, 2022

Here is node_B.log, it's running in Docker with --log=sync=trace,sub-libp2p=trace, unfortunately, the sync log does not seem to display the result of the response. Let me know if I can provide more info.

$ cat node_B.log | grep 'block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh'
{"log":"2022-06-22 08:34:56.712 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh: Starting at `BlockId::Number(2854)` with maximum blocks of `1`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-22T08:34:56.730348545Z"}
{"log":"2022-06-22 08:34:56.712 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh.    \n","stream":"stderr","time":"2022-06-22T08:34:56.730353307Z"}
{"log":"2022-06-22 08:34:57.622 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh: Starting at `BlockId::Number(2918)` with maximum blocks of `64`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-22T08:34:57.633748356Z"}
{"log":"2022-06-22 08:34:57.625 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh.    \n","stream":"stderr","time":"2022-06-22T08:34:57.633750961Z"}
{"log":"2022-06-22 08:35:02.606 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh: Starting at `BlockId::Number(2982)` with maximum blocks of `64`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-22T08:35:02.649238914Z"}
{"log":"2022-06-22 08:35:02.608 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh.    \n","stream":"stderr","time":"2022-06-22T08:35:02.649277629Z"}
{"log":"2022-06-22 08:35:28.043 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh: Starting at `BlockId::Number(2918)` with maximum blocks of `1`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-22T08:35:28.082550206Z"}
{"log":"2022-06-22 08:35:28.043 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh.    \n","stream":"stderr","time":"2022-06-22T08:35:28.082553911Z"}
{"log":"2022-06-22 08:35:29.563 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWRkb1h3RqQ8aMNLoNvfNsceBKftMcRuTnS8bTnDphAewh: Starting at `BlockId::Number(2982)` with maximum blocks of `64`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-22T08:35:29.586889696Z"}
......

@arkpar
Copy link
Member

arkpar commented Jun 22, 2022

Block response handling could use more logging indeed. Could it be that there's a block over 16Mb in size?

@liuchengxu
Copy link
Contributor Author

Could it be that there's a block over 16Mb in size?

Hmm, I don't think so. The other node C on the same machine with node A can sync from B without any issue. This edge case could be largely caused by the network uncertainty, but I believe there is something we can do to avoid the duplicate block requests.

@bkchr
Copy link
Member

bkchr commented Jun 22, 2022

Maybe this one here: paritytech/substrate#11094 ?

@nazar-pc
Copy link
Contributor

Might be, I thought that one was long time merged already 😂

@liuchengxu
Copy link
Contributor Author

paritytech/substrate#11094 is related, but might be incomplete? With paritytech/substrate#11094 applied, I still see the duplicated requests([Patched] prefix in the log is to ensure I'm using the patched substrate).

2022-06-23 10:08:18.863 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160744, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:08:32.241 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160745, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:08:44.571 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160747, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:08:56.764 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160750, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:09:09.101 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160751, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:09:21.841 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160753, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:09:33.636 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160755, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:09:44.761 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160756, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:09:57.058 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160759, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }
2022-06-23 10:10:08.117 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:160760, common:5376) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(5440), to: None, direction: Descending, max: Some(64) }

@arkpar
Copy link
Member

arkpar commented Jun 23, 2022

I don't think paritytech/substrate#11094 is related here.

Duplicate requests are not the issue. They are to be expected. Node requests blocks, but for some reason can not receive them. This lowers the reputatons and disconnects the nodes. Normally this means that the nodes will select a peer with better reputation for this slot. But in your case the same peers keep reconnecting. Probably because there are no other peers to choose from, as the number of slots is higher than the number of known peers on the network. After thy reconnect, the same request is issued and the cycle repeats.

What I'd like to figure out is why handling the block request fails, and if this happens on the receiving side or the sending side.
Could you maybe add some logging here to check the result of the block response handling, and also trace the size of the response (block_response.encoded_len())?

@liuchengxu
Copy link
Contributor Author

An interesting thing is that, with paritytech/substrate#11094 now each restart will be able to sync a number of blocks before getting stuck again, restarting the node is not much helpful before.

Yes, it's a small internal experimental network at present, only one bootnode is available.

Could you maybe add some logging here to check the result of the block response handling, and also trace the size of the response (block_response.encoded_len())?

The link points to nowhere :(, I think you meant this result of the block response.

https://github.com/paritytech/substrate/blob/d45e3837bc89338c6eae1ff5dc250d01e1cae0e6/client/network/sync/src/block_request_handler.rs#L240

Will add more logs to collect more info both on the sending and receiving side and update here.

@liuchengxu
Copy link
Contributor Author

node A keeps sending the duplicated block request from 12309

$ cat node_A.log | grep 'block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP'
2022-06-24 16:19:05.173 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179130, common:12117) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12181), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:11.889 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179132, common:12245) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12373), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:14.062 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179132, common:12373) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12501), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:15.690 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179132, common:12437) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12373), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:17.856 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179132, common:12437) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12565), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:22.355 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179135, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:25.877 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179136, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12373), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:36.557 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179136, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:40.638 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179136, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12565), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:19:52.857 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179138, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:20:03.845 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179139, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:20:14.846 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179141, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:20:25.840 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179141, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:20:37.328 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179142, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:20:47.847 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179142, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:20:58.615 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179143, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:21:09.304 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179144, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
2022-06-24 16:21:19.595 TRACE tokio-runtime-worker sync: [PrimaryChain] [Patched] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:179146, common:12565) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(12309), to: None, direction: Descending, max: Some(64) }
...

node_B.log will send Err(()) if the same block request situation is confirmed.

$ cat node_A.log | grep 'block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd'
{"log":"2022-06-24 08:19:05.081 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12117)` with maximum blocks of `1`, reputation_change: `None`, small_request: `true`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:05.092538788Z"}
{"log":"2022-06-24 08:19:05.081 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12117)`, result: Ok(4664)    \n","stream":"stderr","time":"2022-06-24T08:19:05.092542725Z"}
{"log":"2022-06-24 08:19:05.081 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:05.092564665Z"}
{"log":"2022-06-24 08:19:05.373 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12181)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:05.393528267Z"}
{"log":"2022-06-24 08:19:05.376 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12181)`, result: Ok(327695)    \n","stream":"stderr","time":"2022-06-24T08:19:05.393554477Z"}
{"log":"2022-06-24 08:19:05.376 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:05.393557751Z"}
{"log":"2022-06-24 08:19:12.090 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12373)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:12.112546201Z"}
{"log":"2022-06-24 08:19:12.093 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12373)`, result: Ok(327872)    \n","stream":"stderr","time":"2022-06-24T08:19:12.112573456Z"}
{"log":"2022-06-24 08:19:12.093 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:12.112606314Z"}
{"log":"2022-06-24 08:19:14.261 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12501)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:14.269399896Z"}
{"log":"2022-06-24 08:19:14.263 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12501)`, result: Ok(327962)    \n","stream":"stderr","time":"2022-06-24T08:19:14.269403399Z"}
{"log":"2022-06-24 08:19:14.263 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:14.269418575Z"}
{"log":"2022-06-24 08:19:15.888 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12373)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:15.924827365Z"}
{"log":"2022-06-24 08:19:15.890 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12373)`, result: Ok(327872)    \n","stream":"stderr","time":"2022-06-24T08:19:15.924870229Z"}
{"log":"2022-06-24 08:19:15.890 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:15.924873635Z"}
{"log":"2022-06-24 08:19:18.056 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:18.085313777Z"}
{"log":"2022-06-24 08:19:18.059 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)`, result: Ok(328049)    \n","stream":"stderr","time":"2022-06-24T08:19:18.085318608Z"}
{"log":"2022-06-24 08:19:18.059 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:18.085322827Z"}
{"log":"2022-06-24 08:19:22.555 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:22.60043567Z"}
{"log":"2022-06-24 08:19:22.557 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)`, result: Ok(328139)    \n","stream":"stderr","time":"2022-06-24T08:19:22.600470371Z"}
{"log":"2022-06-24 08:19:22.557 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:22.600476003Z"}
{"log":"2022-06-24 08:19:26.078 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12373)` with maximum blocks of `64`, reputation_change: `Some(ReputationChange { value: -2147483648, reason: \"Same block request multiple times\" })`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:26.108638441Z"}
{"log":"2022-06-24 08:19:26.078 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12373)`, result: Err(())    \n","stream":"stderr","time":"2022-06-24T08:19:26.108733106Z"}
{"log":"2022-06-24 08:19:26.078 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:26.108741966Z"}
{"log":"2022-06-24 08:19:36.214 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)` with maximum blocks of `1`, reputation_change: `None`, small_request: `true`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:36.239935326Z"}
{"log":"2022-06-24 08:19:36.214 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)`, result: Ok(4664)    \n","stream":"stderr","time":"2022-06-24T08:19:36.239939052Z"}
{"log":"2022-06-24 08:19:36.214 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:36.239942865Z"}
{"log":"2022-06-24 08:19:36.759 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:36.791388166Z"}
{"log":"2022-06-24 08:19:36.761 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)`, result: Ok(328139)    \n","stream":"stderr","time":"2022-06-24T08:19:36.791427574Z"}
{"log":"2022-06-24 08:19:36.761 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:36.791433222Z"}
{"log":"2022-06-24 08:19:41.313 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:41.354468583Z"}
{"log":"2022-06-24 08:19:41.315 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)`, result: Ok(328049)    \n","stream":"stderr","time":"2022-06-24T08:19:41.354545238Z"}
{"log":"2022-06-24 08:19:41.315 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:41.354549247Z"}
{"log":"2022-06-24 08:19:53.056 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)` with maximum blocks of `64`, reputation_change: `Some(ReputationChange { value: -2147483648, reason: \"Same block request multiple times\" })`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:53.089630645Z"}
{"log":"2022-06-24 08:19:53.056 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)`, result: Err(())    \n","stream":"stderr","time":"2022-06-24T08:19:53.089635238Z"}
{"log":"2022-06-24 08:19:53.056 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:19:53.089638997Z"}
{"log":"2022-06-24 08:20:03.488 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)` with maximum blocks of `1`, reputation_change: `None`, small_request: `true`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:20:03.522101613Z"}
{"log":"2022-06-24 08:20:03.488 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)`, result: Ok(4664)    \n","stream":"stderr","time":"2022-06-24T08:20:03.522131969Z"}
{"log":"2022-06-24 08:20:03.488 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:20:03.522137457Z"}
{"log":"2022-06-24 08:20:04.044 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)` with maximum blocks of `64`, reputation_change: `Some(ReputationChange { value: -2147483648, reason: \"Same block request multiple times\" })`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:20:04.073650415Z"}
{"log":"2022-06-24 08:20:04.044 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)`, result: Err(())    \n","stream":"stderr","time":"2022-06-24T08:20:04.073676916Z"}
{"log":"2022-06-24 08:20:04.044 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:20:04.073681428Z"}
{"log":"2022-06-24 08:20:14.496 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)` with maximum blocks of `1`, reputation_change: `Some(ReputationChange { value: -1024, reason: \"same small block request multiple times\" })`, small_request: `true`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:20:14.509653045Z"}
{"log":"2022-06-24 08:20:14.496 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)`, result: Ok(4664)    \n","stream":"stderr","time":"2022-06-24T08:20:14.509710058Z"}
{"log":"2022-06-24 08:20:14.496 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:20:14.509713502Z"}
{"log":"2022-06-24 08:20:15.046 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)` with maximum blocks of `64`, reputation_change: `Some(ReputationChange { value: -2147483648, reason: \"Same block request multiple times\" })`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:20:15.061164119Z"}
{"log":"2022-06-24 08:20:15.046 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)`, result: Err(())    \n","stream":"stderr","time":"2022-06-24T08:20:15.061170648Z"}
{"log":"2022-06-24 08:20:15.046 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:20:15.061172941Z"}
{"log":"2022-06-24 08:20:25.770 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)` with maximum blocks of `1`, reputation_change: `Some(ReputationChange { value: -1024, reason: \"same small block request multiple times\" })`, small_request: `true`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:20:25.790731618Z"}
{"log":"2022-06-24 08:20:25.770 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12565)`, result: Ok(4664)    \n","stream":"stderr","time":"2022-06-24T08:20:25.790737002Z"}
{"log":"2022-06-24 08:20:25.770 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd.    \n","stream":"stderr","time":"2022-06-24T08:20:25.790740899Z"}
{"log":"2022-06-24 08:20:26.038 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)` with maximum blocks of `64`, reputation_change: `Some(ReputationChange { value: -2147483648, reason: \"Same block request multiple times\" })`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:20:26.041837394Z"}
...

@arkpar Let me know if more info is needed.

@arkpar
Copy link
Member

arkpar commented Jun 24, 2022

So the very first request for 12309 was handled correctly on B and did not fail.

{"log":"2022-06-24 08:19:22.555 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)` with maximum blocks of `64`, reputation_change: `None`, small_request: `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.    \n","stream":"stderr","time":"2022-06-24T08:19:22.60043567Z"}
{"log":"2022-06-24 08:19:22.557 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooWNZXXSuDT1kea1Nt4SafvNG7F2kuV464znPx98boCLySd: Starting at `BlockId::Number(12309)`, result: Ok(328139)    \n","stream":"stderr","time":"2022-06-24T08:19:22.600470371Z"}

It is not clear why A could not import it. Could you attach the full log for A as well?

@liuchengxu
Copy link
Contributor Author

@arkpar Here is the full node_A.log Hmm, looks like A imported 12309 successfully and was even able to proceed to a higher block...

2022-06-24 16:19:14.455 TRACE tokio-runtime-worker sync: [PrimaryChain] Block imported successfully Some(12309) (0x9db3…2f89)

@arkpar
Copy link
Member

arkpar commented Jun 30, 2022

@liuchengxu Could you check again with paritytech/substrate#11763 merged?

@liuchengxu
Copy link
Contributor Author

@arkpar It's fine to only patch the node on the sending side, right?

@arkpar
Copy link
Member

arkpar commented Jun 30, 2022

@liuchengxu Yes, it should be fine

@liuchengxu
Copy link
Contributor Author

@arkpar Hmm, no good progress with paritytech/substrate#11763, not sure if it's caused by some other problem :(

From the log, looks like node B sent back the block requests for the first time, but due to the network timeout, node A wasn't able to receive and import these blocks but keep duplicating the requests.

$ cat node_A.log | grep 'Request to peer PeerId("12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP")'
2022-06-30 23:46:38.272 DEBUG tokio-runtime-worker sync: [PrimaryChain] Request to peer PeerId("12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP") failed: Network(Timeout).
2022-06-30 23:50:42.701 DEBUG tokio-runtime-worker sync: [PrimaryChain] Request to peer PeerId("12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP") failed: Network(Timeout).
2022-06-30 23:50:56.739 DEBUG tokio-runtime-worker sync: [PrimaryChain] Request to peer PeerId("12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP") failed: Refused.


$ cat node_A.log | grep 'New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP'
2022-06-30 23:46:18.269 TRACE tokio-runtime-worker sync: [PrimaryChain] [PR-11763] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:270989, common:69421) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(69485), to: None, direction: Descending, max: Some(64) }
2022-06-30 23:50:22.699 TRACE tokio-runtime-worker sync: [PrimaryChain] [PR-11763] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:271030, common:69421) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(69485), to: None, direction: Descending, max: Some(64) }
2022-06-30 23:50:56.201 TRACE tokio-runtime-worker sync: [PrimaryChain] [PR-11763] New block request for 12D3KooWMkto1n3dJ7mu8zUiokrjkwcUzEveeyyrk9gJeLNQ5PWP, (best:271038, common:69421) BlockRequest { id: 0, fields: HEADER | BODY | JUSTIFICATION, from: Number(69485), to: None, direction: Descending, max: Some(64) }

node_A.log
node_B.log

bkchr referenced this issue in paritytech/substrate Jul 28, 2022
Add more info to the log to help debug the issue like
https://github.com/paritytech/substrate/issues/11732.

Co-authored-by: Bastian Köcher <info@kchr.de>
DaviRain-Su referenced this issue in octopus-network/substrate Aug 23, 2022
Add more info to the log to help debug the issue like
https://github.com/paritytech/substrate/issues/11732.

Co-authored-by: Bastian Köcher <info@kchr.de>
ark0f referenced this issue in gear-tech/substrate Feb 27, 2023
Add more info to the log to help debug the issue like
https://github.com/paritytech/substrate/issues/11732.

Co-authored-by: Bastian Köcher <info@kchr.de>
@altonen altonen transferred this issue from paritytech/substrate Aug 24, 2023
helin6 pushed a commit to boolnetwork/polkadot-sdk that referenced this issue Feb 5, 2024
* Account for `pallet_ethereum::on_initialize` weight

* Account for `pallet_ethereum::on_finalize` weight

* Account for `pallet_ethereum::on_runtime_upgrade` weight
github-merge-queue bot pushed a commit that referenced this issue Aug 5, 2024
…g the same request multiple times (#5029)

This PR avoids submitting the same block or state request multiple times
to the same slow peer.

Previously, we submitted the same request to the same slow peer, which
resulted in reputation bans on the slow peer side.
Furthermore, the strategy selected the same slow peer multiple times to
submit queries to, although a better candidate may exist.

Instead, in this PR we:
- introduce a `DisconnectedPeers` via LRU with 512 peer capacity to only
track the state of disconnected peers with a request in flight
- when the `DisconnectedPeers` detects a peer disconnected with a
request in flight, the peer is backed off
  - on the first disconnection: 60 seconds
  - on second disconnection: 120 seconds
- on the third disconnection the peer is banned, and the peer remains
banned until the peerstore decays its reputation
  
This PR lifts the pressure from overloaded nodes that cannot process
requests in due time.
And if a peer is detected to be slow after backoffs, the peer is banned.

Theoretically, submitting the same request multiple times can still
happen when:
- (a) we backoff and ban the peer 
- (b) the network does not discover other peers -- this may also be a
test net
- (c) the peer gets reconnected after the reputation decay and is still
slow to respond



Aims to improve:
- #4924
- #531

Next Steps:
- Investigate the network after this is deployed, possibly bumping the
keep-alive timeout or seeing if there's something else misbehaving




This PR builds on top of:
- #4987


### Testing Done
- Added a couple of unit tests where test harness were set in place

- Local testnet

```bash
13:13:25.102 DEBUG tokio-runtime-worker sync::persistent_peer_state: Added first time peer 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD

13:14:39.102 DEBUG tokio-runtime-worker sync::persistent_peer_state: Remove known peer 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD state: DisconnectedPeerState { num_disconnects: 2, last_disconnect: Instant { tv_sec: 93355, tv_nsec: 942016062 } }, should ban: false

13:16:49.107 DEBUG tokio-runtime-worker sync::persistent_peer_state: Remove known peer 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD state: DisconnectedPeerState { num_disconnects: 3, last_disconnect: Instant { tv_sec: 93485, tv_nsec: 947551051 } }, should ban: true

13:16:49.108  WARN tokio-runtime-worker peerset: Report 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD: -2147483648 to -2147483648. Reason: Slow peer after backoffs. Banned, disconnecting.
```

cc @paritytech/networking

---------

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>
dharjeezy pushed a commit to dharjeezy/polkadot-sdk that referenced this issue Aug 28, 2024
…g the same request multiple times (paritytech#5029)

This PR avoids submitting the same block or state request multiple times
to the same slow peer.

Previously, we submitted the same request to the same slow peer, which
resulted in reputation bans on the slow peer side.
Furthermore, the strategy selected the same slow peer multiple times to
submit queries to, although a better candidate may exist.

Instead, in this PR we:
- introduce a `DisconnectedPeers` via LRU with 512 peer capacity to only
track the state of disconnected peers with a request in flight
- when the `DisconnectedPeers` detects a peer disconnected with a
request in flight, the peer is backed off
  - on the first disconnection: 60 seconds
  - on second disconnection: 120 seconds
- on the third disconnection the peer is banned, and the peer remains
banned until the peerstore decays its reputation
  
This PR lifts the pressure from overloaded nodes that cannot process
requests in due time.
And if a peer is detected to be slow after backoffs, the peer is banned.

Theoretically, submitting the same request multiple times can still
happen when:
- (a) we backoff and ban the peer 
- (b) the network does not discover other peers -- this may also be a
test net
- (c) the peer gets reconnected after the reputation decay and is still
slow to respond



Aims to improve:
- paritytech#4924
- paritytech#531

Next Steps:
- Investigate the network after this is deployed, possibly bumping the
keep-alive timeout or seeing if there's something else misbehaving




This PR builds on top of:
- paritytech#4987


### Testing Done
- Added a couple of unit tests where test harness were set in place

- Local testnet

```bash
13:13:25.102 DEBUG tokio-runtime-worker sync::persistent_peer_state: Added first time peer 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD

13:14:39.102 DEBUG tokio-runtime-worker sync::persistent_peer_state: Remove known peer 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD state: DisconnectedPeerState { num_disconnects: 2, last_disconnect: Instant { tv_sec: 93355, tv_nsec: 942016062 } }, should ban: false

13:16:49.107 DEBUG tokio-runtime-worker sync::persistent_peer_state: Remove known peer 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD state: DisconnectedPeerState { num_disconnects: 3, last_disconnect: Instant { tv_sec: 93485, tv_nsec: 947551051 } }, should ban: true

13:16:49.108  WARN tokio-runtime-worker peerset: Report 12D3KooWHdiAxVd8uMQR1hGWXccidmfCwLqcMpGwR6QcTP6QRMuD: -2147483648 to -2147483648. Reason: Slow peer after backoffs. Banned, disconnecting.
```

cc @paritytech/networking

---------

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
Status: In Progress 🛠
Development

No branches or pull requests

6 participants