libp2p / libp2p/rust-libp2p

transport/webrtc: Short buffer to be filled

Open
#4,049 3 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Rust
Stars
5.6k
Forks
1.3k
Avg merge
8h 47m
Merged PRs (30d)
19

Description

Summary

Our integration test failed because on one node all peers had been disconnected due to "Short buffer to be filled" error. The read buffer capacity is set here. Error means that somewhere (?) we're sending/reading messages more than 16kB, which should not be possible if all nodes are using the same webrtc FRAMED transport.

Refs https://github.com/paritytech/substrate/pull/12529#issuecomment-1580604870

Expected behaviour

Expect nodes sending messages to respect the read buffer capacity.

Actual behaviour

2023-06-07 09:36:43.459 TRACE tokio-runtime-worker sub-libp2p: Handler(PeerId("12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby")) <= Sync notification    
2023-06-07 09:36:43.459 TRACE tokio-runtime-worker sub-libp2p: Handler(PeerId("12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby"), ConnectionId(4)]) => OpenDesiredByRemote(SetId(2))    
2023-06-07 09:36:43.459 TRACE tokio-runtime-worker sub-libp2p: PSM <= Incoming(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, IncomingIndex(2)).    
2023-06-07 09:36:43.459 TRACE tokio-runtime-worker sub-libp2p: PSM => Accept(IncomingIndex(2), 12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(2)): Enabling connections.    
2023-06-07 09:36:43.459 TRACE tokio-runtime-worker sub-libp2p: Handler(PeerId("12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby"), ConnectionId(4)) <= Open(SetId(2))    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: Handler(PeerId("12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby"), ConnectionId(4)]) => OpenDesiredByRemote(SetId(3))    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: PSM <= Incoming(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, IncomingIndex(3)).    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: PSM => Accept(IncomingIndex(3), 12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(3)): Enabling connections.    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: Handler(PeerId("12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby"), ConnectionId(4)) <= Open(SetId(3))    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: Handler(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, ConnectionId(3)) => OpenResultOk(SetId(2))    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: External API <= Open(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(2))    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: Handler(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, ConnectionId(4)) => OpenResultOk(SetId(2))    
2023-06-07 09:36:43.460 TRACE tokio-runtime-worker sub-libp2p: External API <= Open(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(2))    
2023-06-07 09:36:43.461 TRACE tokio-runtime-worker sub-libp2p: Handler(ConnectionId(4)) => Notification(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(1), 22 bytes)    
2023-06-07 09:36:43.461 TRACE tokio-runtime-worker sub-libp2p: External API <= Message(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(1))    
2023-06-07 09:36:43.461 TRACE tokio-runtime-worker sub-libp2p: Handler(ConnectionId(3)) => Notification(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(1), 22 bytes)    
2023-06-07 09:36:43.461 TRACE tokio-runtime-worker sub-libp2p: External API <= Message(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(1))    
2023-06-07 09:36:43.461 TRACE tokio-runtime-worker sub-libp2p: Handler(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, ConnectionId(4)) => OpenResultOk(SetId(3))    
2023-06-07 09:36:43.461 TRACE tokio-runtime-worker sub-libp2p: External API <= Open(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(3))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(0), ConnectionId(4)): Enabled.    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(0))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(0))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(1), ConnectionId(4)): Enabled.    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(1))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(1))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(2), ConnectionId(4)): Enabled.    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(2))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(2))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(3), ConnectionId(4)): Enabled.    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(3))    
2023-06-07 09:36:43.472 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby, SetId(3))    
2023-06-07 09:36:43.472 DEBUG tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(PeerId("12D3KooWRkZhiRhsqmrQ28rt73K7V3aCBpqKrLGSXmZ99PTcTZby"), Some(Handler(Right(Upgrade(Apply(Custom { kind: InvalidInput, error: Io(Custom { kind: InvalidData, error: Error(Custom { kind: Other, error: "Short buffer to be filled" }) }) }))))))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(0), ConnectionId(3)): Enabled.    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(0))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(0))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(1), ConnectionId(3)): Enabled.    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(1))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(1))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(2), ConnectionId(3)): Enabled.    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(2))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(2))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(3), ConnectionId(3)): Enabled.    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(3))    
2023-06-07 09:36:43.508 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S, SetId(3))    
2023-06-07 09:36:43.508 DEBUG tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(PeerId("12D3KooWPKzmmE2uYgF3z13xjpbFTp63g9dZFag8pG6MgnpSLF4S"), Some(Handler(Right(Upgrade(Apply(Custom { kind: InvalidInput, error: Io(Custom { kind: InvalidData, error: Error(Custom { kind: Other, error: "Short buffer to be filled" }) }) }))))))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(0), ConnectionId(1)): Enabled.    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(0))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(0))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(1), ConnectionId(1)): Enabled.    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(1))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(1))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(2), ConnectionId(1)): Enabled.    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(2))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(2))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(3), ConnectionId(1)): Enabled.    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: External API <= Closed(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(3))    
2023-06-07 09:36:43.525 TRACE tokio-runtime-worker sub-libp2p: PSM <= Dropped(12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm, SetId(3))    
2023-06-07 09:36:43.525 DEBUG tokio-runtime-worker sub-libp2p: Libp2p => Disconnected(PeerId("12D3KooWQCkBm1BYtkHpocxCwMgR8yjitEeHGx8spzcDLGt2gkBm"), Some(Handler(Right(Upgrade(Apply(Custom { kind: InvalidInput, error: Io(Custom { kind: InvalidData, error: Error(Custom { kind: Other, error: "Short buffer to be filled" }) }) }))))))

Possible Solution

https://github.com/webrtc-rs/webrtc/issues/273 although that requires more thinking... plus I think we want to switch to str0m https://github.com/libp2p/rust-libp2p/issues/3659

Version

  • libp2p version (version number, commit, or branch): 0.51.3

Would you like to work on fixing this bug?

Yes

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with transports/webrtc/src/tokio/substream/framed_dc.rs at the read-buffer capacity referenced in the issue, then investigate the reported integration-test failure and the WebRTC references. Determine why peers receive “Short buffer to be filled” despite the expected message limit. Done means the affected integration test no longer disconnects peers with this error.

Written by the indexing model from the issue text.

Assessment

Tech stack
rust
Domain
audio-video-rtc, networking
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.