A larger data payload in the response of a block request can't be sent back due to KeepAliveTimeout and then peer disconnected
Author: liuchengxuCreated Aug 25, 2022Updated Aug 24, 2023
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
When a node requests a chunk of blocks from another node, if these blocks happen to be huge, the block request is successfully handled on the server node but failed to be sent back to the requester due to the error KeepAliveTimeout
2022-08-24 17:33:04.394 DEBUG tokio-runtime-worker libp2p_swarm: [PrimaryChain] Connection closed with error KeepAliveTimeout: Connected { endpoint: Listener { local_addr: "/ip4/192.168.1.2/tcp/30333", send_back_addr: "/ip4/85.41.34.50/tcp/55227" }, peer_id: PeerId("12D3KooWG87xHK71UEKkw4pLCAkaa2C4vCnAsk5hVYD6dzQdua6G") }; Total (peer): 0.
2022-08-24 17:33:04.394 DEBUG tokio-runtime-worker sub-libp2p: [PrimaryChain] Libp2p => Disconnected(PeerId("12D3KooWG87xHK71UEKkw4pLCAkaa2C4vCnAsk5hVYD6dzQdua6G"), Some(KeepAliveTimeout)) Here is the server node log, we can see the byte size of the first request result is 299402, which is sent successfully, the second request result size is 10534306 which failed to be sent back. The reason is that there are some data store transactions after block 64, causing the block size to increase significantly.
2022-08-24 17:28:48.407 DEBUG tokio-runtime-worker libp2p_dns: [PrimaryChain] Dialing /ip4/172.19.0.1/tcp/21000/p2p/12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS
2022-08-24 17:28:52.713 DEBUG tokio-runtime-worker libp2p_swarm: [PrimaryChain] Connection established: PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS") Listener { local_addr: "/ip4/192.168.1.2/tcp/30333", send_back_addr: "/ip4/125.121.39.96/tcp/34940" }; Total (peer): 1. Total non-banned (peer): 1
2022-08-24 17:28:52.713 DEBUG tokio-runtime-worker sub-libp2p: [PrimaryChain] Libp2p => Connected(PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS"))
2022-08-24 17:28:53.318 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping sent to PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:28:53.319 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping received from PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:28:53.930 DEBUG tokio-runtime-worker sync: [PrimaryChain] Connected 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS
2022-08-24 17:28:54.983 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS: Starting at `BlockId::Number(64)` with maximum blocks of `64`, reputation_change: `None`, small_request `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.
2022-08-24 17:28:55.054 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS starting at `BlockId::Number(64)`: blocks: Some(64), data: Some(299402)
2022-08-24 17:28:55.055 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS.
2022-08-24 17:28:57.831 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS: Starting at `BlockId::Number(128)` with maximum blocks of `64`, reputation_change: `None`, small_request `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.
2022-08-24 17:28:57.837 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS starting at `BlockId::Number(128)`: blocks: Some(3), data: Some(10534306)
2022-08-24 17:28:57.840 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS.
2022-08-24 17:29:08.407 DEBUG tokio-runtime-worker libp2p_kad::behaviour: [PrimaryChain] Address '/ip4/172.19.0.1/tcp/21000/p2p/12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS' removed from peer '12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS' due to error.
2022-08-24 17:29:08.407 DEBUG tokio-runtime-worker libp2p_swarm: [PrimaryChain] Connection attempt to PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS") failed with Transport([("/ip4/172.19.0.1/tcp/21000/p2p/12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS", Other(Custom { kind: Other, error: Timeout }))]).
2022-08-24 17:29:09.122 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping received from PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:29:11.989 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping sent to PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:29:26.115 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS: Starting at `BlockId::Number(64)` with maximum blocks of `1`, reputation_change: `None`, small_request `true`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.
2022-08-24 17:29:26.115 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS starting at `BlockId::Number(64)`: blocks: Some(1), data: Some(4664)
2022-08-24 17:29:26.115 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS.
2022-08-24 17:29:26.760 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS: Starting at `BlockId::Number(128)` with maximum blocks of `64`, reputation_change: `None`, small_request `false`, direction `Descending` and attributes `HEADER | BODY | JUSTIFICATION`.
2022-08-24 17:29:26.767 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS starting at `BlockId::Number(128)`: blocks: Some(3), data: Some(10534306)
2022-08-24 17:29:26.770 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS.
2022-08-24 17:29:26.989 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping received from PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:29:41.875 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping sent to PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:29:56.875 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping received from PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:30:01.218 DEBUG tokio-runtime-worker libp2p_ping: [PrimaryChain] Ping sent to PeerId("12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS")
2022-08-24 17:30:01.721 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS: Starting at `BlockId::Number(64)` with maximum blocks of `1`, reputation_change: `None`, small_request `true`, direction `Ascending` and attributes `HEADER | JUSTIFICATION`.
2022-08-24 17:30:01.721 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS starting at `BlockId::Number(64)`: blocks: Some(1), data: Some(4664)
2022-08-24 17:30:01.721 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS.
2022-08-24 17:30:02.747 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handling block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS: Starting at `BlockId::Number(128)` 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`.
2022-08-24 17:30:02.747 DEBUG tokio-runtime-worker sync: [PrimaryChain] Sending result of block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS starting at `BlockId::Number(128)`: blocks: None, data: None
2022-08-24 17:30:02.747 DEBUG tokio-runtime-worker sync: [PrimaryChain] Handled block request from 12D3KooW9rwH7iqBbynXERRrGHxYn4UbCieByXxnkPGJ3R7wShdS.
2022-08-24 17:30:02.747 DEBUG tokio-runtime-worker peerset: [PrimaryChain] Report With interior networking and large blocks which are normal for a storage chain, this issue can occur quite often. I see a few ways to help this:
- Allow increasing the timeout, both request and response. If a chain can have a lot of large blocks, a larger timeout should be used.
- Send back just one block of data if the data result is huge. 10534306 is actually for 3 blocks, reducing it to one will help a lot. Furthermore, a chain has a nature block size limit, once configurable, the timeout may be adjusted based on this value.
I think https://github.com/paritytech/polkadot-sdk/issues/531 is related, after Timeout, we see a flood of duplicated block requests, maybe we can also do something to improve that.
Steps to reproduce
No response
Source: paritytech/substrate