net/libp2p: Enforce outbound request-response timeout limits #7222

lexnv · 2025-01-17T11:59:38Z

This PR enforces that outbound requests are finished within the specified protocol timeout.

The stable2412 version running libp2p 0.52.4 contains a bug which does not track request timeouts properly:

fix(request-response): Report dial IO errors to the user libp2p/rust-libp2p#5429

The issue has been detected while submitting libp2p -> litep2p requests in kusama. This aims to check that pending outbound requests have not timedout. Although the issue has been fixed in libp2p, there might be other cases where this may happen. For example:

fix(request-response): Report failure when streams are at capacity libp2p/rust-libp2p#5417

For more context see: #7076 (comment)

Ideally, the force-timeout mechanism in this PR should never be triggered in production. However, origin/stable2412 occasionally encounters this issue. When this happens, 2 warnings may be generated:

one warning introduced by this PR wrt force timeout terminating the request
possible one warning when the libp2p decides (if at all) to provide the response back to substrate (as mentioned by @alexggh here and here

This implementation does not propagate to the substrate service the RequestFinished { error: .. }. That event is only used internally by substrate to increment metrics. However, we don't have the peer information available to propagate the event properly when we force-timeout the request. Considering this should most likely not happen in production (origin/master) and that we'll be able to extract information by warnings, I would say this is a good tradeoff for code simplicity:

polkadot-sdk/substrate/client/network/src/service.rs

Line 1543 in 06e3b5c

RequestFailure::Network(OutboundFailure::Timeout) => "timeout",

Testing

Added a new test to ensure the timeout is reached properly, even if libp2p does not produce a response in due time.

I've also transitioned the tests to using tokio::test due to a limitation of CI

--- TRY 1 STDERR:        sc-network request_responses::tests::max_response_size_exceeded ---
thread 'request_responses::tests::max_response_size_exceeded' panicked at /usr/local/cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/time/interval.rs:139:26:
there is no reactor running, must be called from the context of a Tokio 1.x runtime

cc @paritytech/networking

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

substrate/client/network/src/request_responses.rs

alexggh

Overall, looks good to me, one thing I would do is burn it in on the kusama validator over the weekend, just to see if this triggers in real work conditions, our assumption it doesn't but we might be surprised.

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

substrate/client/network/src/request_responses.rs

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

alexggh

Looks alright to me.

alexggh · 2025-01-20T11:58:09Z

substrate/client/network/src/request_responses.rs

@@ -1086,10 +1164,10 @@ mod tests {
 	};
 	use std::{iter, time::Duration};

-	struct TokioExecutor(tokio::runtime::Runtime);
+	struct TokioExecutor;


I don't understand why we need this change.

Just a tiny change to not pass the runtime when building the swarm and let tokio::spawn below do the job

failure Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

…nv/enforce-timeouts

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

bkchr

I would change the collect & remove code path to a simple retain.

substrate/client/network/src/request_responses.rs

bkchr · 2025-01-20T20:09:27Z

substrate/client/network/src/request_responses.rs

+					.iter()
+					.filter_map(|(id, req)| {


Why not retain? Then we don't need collect & remove.

There's a tiny borrow-checker issue coming from the sender consuming self: retain will give us &mut req and the req.response oneshot::Sender consumes self when we send out the send(Err(RequestFailure::Network(OutboundFailure::Timeout))).

We could still avoid the extra alloc by adding an Option over the sender, will have a look if it complicates the code, thanks

bkchr · 2025-01-20T20:11:11Z

substrate/client/network/src/request_responses.rs

+					.collect();
+
+				if !timedout_requests.is_empty() {
+					log::warn!(


So this could only be triggered by a bug in libp2p/litep2p?

Yep this could be triggered only by a bug in libp2p (libp2p/rust-libp2p#5429). I expected that the latest libp2p version would solve this issue, however, I could reproduce it on our libp2p kusama validator (and locally):

2025-01-21 05:43:14.885 WARN tokio-runtime-worker sub-libp2p: Requests [(ProtocolRequestId { protocol: OnHeap("/b0a8d493285c2df73290dfb7e61f870f17b41801197a149ca93654499ea3dafe/sync/2"), request_id: OutboundRequestId(53207) }, Some(20.479579184s))] force detected as timeout. 2025-01-21 05:43:18.178 WARN tokio-runtime-worker sub-libp2p: Received `RequestResponseEvent::OutboundFailure` with unexpected request id OutboundRequestId(53207) error Timeout from PeerId("12D3KooWJZuPc7KPtJcbYurX7brn3booPwbK53ucJhhPmuc1zZPt")

In this case libp2p produces a timeout event ~4s after we have detected the request as timed out. I'll also have a look at our poll implementation, maybe there's something there

Co-authored-by: Bastian Köcher <git@kchr.de>

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

substrate/client/network/src/request_responses.rs

timeouts Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

paritytech-workflow-stopper · 2025-01-22T11:55:07Z

All GitHub workflows were cancelled due to failure one of the required jobs.
Failed workflow url: https://github.com/paritytech/polkadot-sdk/actions/runs/12907455229
Failed job name: cargo-clippy

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

paritytech-cmd-bot-polkadot-sdk · 2025-01-22T17:27:31Z

Created backport PR for stable2407:

[stable2407] Backport #7222 #7300 with remaining conflicts!

Please cherry-pick the changes locally and resolve any conflicts.

git fetch origin backport-7222-to-stable2407
git worktree add --checkout .worktree/backport-7222-to-stable2407 backport-7222-to-stable2407
cd .worktree/backport-7222-to-stable2407
git reset --hard HEAD^
git cherry-pick -x fd64a1e7768ba6e8676cbbf25c4e821a901c0a7f
git push --force-with-lease

paritytech-cmd-bot-polkadot-sdk · 2025-01-22T17:27:41Z

Created backport PR for stable2409:

[stable2409] Backport #7222 #7301 with remaining conflicts!

Please cherry-pick the changes locally and resolve any conflicts.

git fetch origin backport-7222-to-stable2409
git worktree add --checkout .worktree/backport-7222-to-stable2409 backport-7222-to-stable2409
cd .worktree/backport-7222-to-stable2409
git reset --hard HEAD^
git cherry-pick -x fd64a1e7768ba6e8676cbbf25c4e821a901c0a7f
git push --force-with-lease

paritytech-cmd-bot-polkadot-sdk · 2025-01-22T17:27:48Z

Created backport PR for stable2412:

stable2412/backport #7222: Enforce libp2p outbound request-response timeout limits #7302 with remaining conflicts!

Please cherry-pick the changes locally and resolve any conflicts.

git fetch origin backport-7222-to-stable2412
git worktree add --checkout .worktree/backport-7222-to-stable2412 backport-7222-to-stable2412
cd .worktree/backport-7222-to-stable2412
git reset --hard HEAD^
git cherry-pick -x fd64a1e7768ba6e8676cbbf25c4e821a901c0a7f
git push --force-with-lease

…imeout limits (#7302) Backport #7222 into `stable2412` from lexnv. See the [documentation](https://github.com/paritytech/polkadot-sdk/blob/master/docs/BACKPORT.md) on how to use this bot.  --------- Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io> Co-authored-by: Alexandru Vasile <60601340+lexnv@users.noreply.github.com> Co-authored-by: Alexandru Vasile <alexandru.vasile@parity.io>

lexnv added 2 commits January 17, 2025 11:57

net/req-resp: Introduce a new ProtocolDetails to hold protocol details

9f8ca21

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

net/req-resp: Evict timeout requests

190fe89

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

lexnv added T0-node This PR/Issue is related to the topic “node”. I2-bug The node fails to follow expected behavior. labels Jan 17, 2025

lexnv requested review from dmitry-markin and alexggh January 17, 2025 11:59

lexnv self-assigned this Jan 17, 2025

lexnv changed the title ~~net/libp2p: Enfore outbound request-response timeout limits~~ net/libp2p: Enforce outbound request-response timeout limits Jan 17, 2025

Add prdoc

c3b01da

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

lexnv added the A4-needs-backport Pull request must be backported to all maintained releases. label Jan 17, 2025

alexggh reviewed Jan 17, 2025

View reviewed changes

substrate/client/network/src/request_responses.rs Outdated Show resolved Hide resolved

alexggh reviewed Jan 17, 2025

View reviewed changes

substrate/client/network/src/request_responses.rs Show resolved Hide resolved

alexggh reviewed Jan 17, 2025

View reviewed changes

substrate/client/network/src/request_responses.rs Show resolved Hide resolved

alexggh reviewed Jan 17, 2025

View reviewed changes

lexnv added 3 commits January 17, 2025 17:14

net/req-resp: Fix cargo docs

48f0127

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

net/req-resp: Adjust logs

f8e89f4

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

Adjust PRdoc

050c166

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

alexggh reviewed Jan 20, 2025

View reviewed changes

substrate/client/network/src/request_responses.rs Outdated Show resolved Hide resolved

lexnv and others added 8 commits January 20, 2025 12:40

req-resp/tests: Add test to ensure timouts are forced

13d0094

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

req-resp: Remove debug asserts as libp2p might respond later

e862829

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

req-resp/tests: Refactor basic_request_response_works to use tokio

1ec4657

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

req-resp/tests: Refactor max_response_size_exceeded to use tokio

caa335d

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

req-resp/tests: Refactor request_id_collision to use tokio

f992c9c

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

req-resp/tests: Refactor request_fallback to use tokio

25891cc

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

Merge remote-tracking branch 'origin/master' into lexnv/enforce-timeouts

06e3b5c

Merge branch 'master' into lexnv/enforce-timeouts

4fff0f5

alexggh approved these changes Jan 20, 2025

View reviewed changes

lexnv added 3 commits January 20, 2025 16:27

req-resp: Fix old libp2p warn to distinguish between response and

d505321

failure Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

Merge remote-tracking branch 'origin/lexnv/enforce-timeouts' into lex…

7cdd47a

…nv/enforce-timeouts

Merge remote-tracking branch 'origin/master' into lexnv/enforce-timeouts

1e5edb2

req-resp: Log elapsed time since request started

7a7ee48

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

bkchr approved these changes Jan 20, 2025

View reviewed changes

lexnv and others added 2 commits January 21, 2025 11:49

Update substrate/client/network/src/request_responses.rs

b640010

Co-authored-by: Bastian Köcher <git@kchr.de>

req-resp: Introduce Option to wrap the oneshot::Sender

053d8ca

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

skunert approved these changes Jan 21, 2025

View reviewed changes

substrate/client/network/src/request_responses.rs Outdated Show resolved Hide resolved

req-resp/tests: Lower test time to 2s by stopping first swarm + reduce

4d33dfc

timeouts Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

lexnv added 2 commits January 22, 2025 14:22

req-resp/tests: Fix clippy

296156d

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

req-resp: Downgrade warnings to debug to not pollute validator logs

d13f9d7

Signed-off-by: Alexandru Vasile <alexandru.vasile@parity.io>

lexnv enabled auto-merge January 22, 2025 15:39

Merge branch 'master' into lexnv/enforce-timeouts

79ee2d8

lexnv added this pull request to the merge queue Jan 22, 2025

Merged via the queue into master with commit fd64a1e Jan 22, 2025
203 of 204 checks passed

lexnv deleted the lexnv/enforce-timeouts branch January 22, 2025 17:26

This was referenced Jan 22, 2025

[stable2407] Backport #7222 #7300

Closed

[stable2409] Backport #7222 #7301

Closed

paritytech-cmd-bot-polkadot-sdk bot mentioned this pull request Jan 22, 2025

stable2412/backport #7222: Enforce libp2p outbound request-response timeout limits #7302

Merged

lexnv mentioned this pull request Jan 23, 2025

[DO NOT MERGE] network/libp2p: Investigate requests that don't timeout #7154

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/libp2p: Enforce outbound request-response timeout limits #7222

net/libp2p: Enforce outbound request-response timeout limits #7222

lexnv commented Jan 17, 2025 •

edited

Loading

alexggh left a comment

alexggh left a comment

alexggh Jan 20, 2025

lexnv Jan 20, 2025

bkchr left a comment

bkchr Jan 20, 2025

lexnv Jan 21, 2025

bkchr Jan 20, 2025

lexnv Jan 21, 2025

paritytech-workflow-stopper bot commented Jan 22, 2025

paritytech-cmd-bot-polkadot-sdk bot commented Jan 22, 2025

paritytech-cmd-bot-polkadot-sdk bot commented Jan 22, 2025

paritytech-cmd-bot-polkadot-sdk bot commented Jan 22, 2025

net/libp2p: Enforce outbound request-response timeout limits #7222

net/libp2p: Enforce outbound request-response timeout limits #7222

Conversation

lexnv commented Jan 17, 2025 • edited Loading

Testing

alexggh left a comment

Choose a reason for hiding this comment

alexggh left a comment

Choose a reason for hiding this comment

alexggh Jan 20, 2025

Choose a reason for hiding this comment

lexnv Jan 20, 2025

Choose a reason for hiding this comment

bkchr left a comment

Choose a reason for hiding this comment

bkchr Jan 20, 2025

Choose a reason for hiding this comment

lexnv Jan 21, 2025

Choose a reason for hiding this comment

bkchr Jan 20, 2025

Choose a reason for hiding this comment

lexnv Jan 21, 2025

Choose a reason for hiding this comment

paritytech-workflow-stopper bot commented Jan 22, 2025

paritytech-cmd-bot-polkadot-sdk bot commented Jan 22, 2025

paritytech-cmd-bot-polkadot-sdk bot commented Jan 22, 2025

paritytech-cmd-bot-polkadot-sdk bot commented Jan 22, 2025

lexnv commented Jan 17, 2025 •

edited

Loading