Multiple file requests at once failing

[snowmead]

I have a setup of 3 nodes with the identity and request_response protocols configured in my behaviour.

When 2 nodes initiate a file request at the same time from 1 node, the connection hangs for a bit and both nodes that initiated the request fails with the following error.

Node 1 and 2 failed to request file from 12D3KooWFHNBwTxUgeHRcD3g4ieiXBmZGVyp6TKGWRKKEqYgCC1C:

2023-12-08T20:02:43.957136Z  INFO storagehub_client: Established new connection peer=12D3KooWFHNBwTxUgeHRcD3g4ieiXBmZGVyp6TKGWRKKEqYgCC1C endpoint=Dialer { address: "/ip4/127.0.0.1/tcp/44913/p2p/12D3KooWFHNBwTxUgeHRcD3g4ieiXBmZGVyp6TKGWRKKEqYgCC1C", role_override: Dialer }
2023-12-08T20:02:44.044806Z  INFO storagehub_client: Identify sent to PeerId("12D3KooWFHNBwTxUgeHRcD3g4ieiXBmZGVyp6TKGWRKKEqYgCC1C")
2023-12-08T20:02:44.045030Z  INFO storagehub_client: Identify received: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): 513523c8b48319b649d7d4d4e613232fd9c13f4129d4bc5f74d6eceb91afe9f) }, protocol_version: "/storagehub/0.1.0", agent_version: "rust-libp2p/0.44.0", listen_addrs: ["/ip4/127.0.0.1/tcp/44913", "/ip4/172.28.164.193/tcp/44913"], protocols: ["/ipfs/id/push/1.0.0", "/ipfs/id/1.0.0", "/storagehub/0.1.0"], observed_addr: "/ip4/127.0.0.1/tcp/49632" }
2023-12-08T20:02:44.045096Z  INFO storagehub_client: New external address candidate /ip4/127.0.0.1/tcp/35435
2023-12-08T20:02:53.996037Z ERROR storagehub_client::runtimes::local: Failed to request file: IO error on outbound stream: Eof { name: "array", expect: Small(1) }

Node 3 that should have responded with the file does not complete:

023-12-08T20:01:54.511378Z  INFO libp2p_swarm: local_peer_id=12D3KooWFHNBwTxUgeHRcD3g4ieiXBmZGVyp6TKGWRKKEqYgCC1C
2023-12-08T20:01:54.512129Z  INFO storagehub_client: Multiaddr listening on /ip4/127.0.0.1/tcp/44913/p2p/12D3KooWFHNBwTxUgeHRcD3g4ieiXBmZGVyp6TKGWRKKEqYgCC1C
2023-12-08T20:01:54.512218Z  INFO storagehub_client: Multiaddr listening on /ip4/172.28.164.193/tcp/44913/p2p/12D3KooWFHNBwTxUgeHRcD3g4ieiXBmZGVyp6TKGWRKKEqYgCC1C
2023-12-08T20:02:43.994755Z  INFO storagehub_client: Established new connection peer=12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X endpoint=Listener { local_addr: "/ip4/127.0.0.1/tcp/44913", send_back_addr: "/ip4/127.0.0.1/tcp/49632" }
2023-12-08T20:02:43.994915Z  INFO storagehub_client: Established new connection peer=12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 endpoint=Listener { local_addr: "/ip4/127.0.0.1/tcp/44913", send_back_addr: "/ip4/127.0.0.1/tcp/49642" }
2023-12-08T20:02:43.995143Z  INFO storagehub_client: Identify sent to PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
2023-12-08T20:02:43.995185Z  INFO storagehub_client: Identify sent to PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3")
2023-12-08T20:02:44.094829Z  INFO storagehub_client: InboundRequest SwarmEvent request=FileRequest("lorem")
2023-12-08T20:02:44.094946Z  INFO storagehub_client::network: InboundRequest network event file_id="lorem"
2023-12-08T20:02:44.094959Z  INFO storagehub_client: InboundRequest SwarmEvent request=FileRequest("lorem")

Theres 2 things I notice:

• The identity was sent to both peers that connected to the node.
• After this log output from the InboundRequest network event, 2023-12-08T20:02:44.094946Z INFO storagehub_client::network: InboundRequest network event file_id="lorem", the respond_file method did not panic, so I can only assume that the sender.send(Command::RespondFile { file, channel }) worked.

match network_events.next().await {
    // Reply with the content of the file on incoming requests.
    Some(Event::InboundRequest { file_id, channel }) => {
        info!(file_id = ?file_id, "InboundRequest network event");
        self.respond_file(
            std::fs::read(format!("{}/{}", self.upload_path, file_id)).unwrap(),
            channel,
        )
        .await;

        info!("Responded to inbound request for file {}", file_id);
    }
...

/// Respond with the provided file content to the given request.
pub(crate) async fn respond_file(
    &mut self,
    file: Vec<u8>,
    channel: ResponseChannel<FileResponse>,
) {
    self.sender
        .send(Command::RespondFile { file, channel })
        .await
        .expect("Command receiver not to be dropped.");
}

I tried with only a single node requesting the file and it works like a charm. As soon as I introduce other nodes requesting the same file in parallel, I get this error.

This is my swarm configuration.

/// Defines max_negotiating_inbound_streams constant for the swarm.
/// It must be set for large plots.
const SWARM_MAX_NEGOTIATING_INBOUND_STREAMS: usize = 100000;
/// How long will connection be allowed to be open without any usage
const IDLE_CONNECTION_TIMEOUT: Duration = Duration::from_secs(10);

 let mut swarm = libp2p::SwarmBuilder::with_existing_identity(id_keys)
        .with_async_std()
        .with_tcp(
            tcp::Config::default(),
            noise::Config::new,
            yamux::Config::default,
        )?
        .with_behaviour(|key| {
            Ok(Behaviour {
                identify: identify::Behaviour::new(identify::Config::new(
                    "/storagehub/0.1.0".to_string(),
                    key.public(),
                )),
                request_response: request_response::cbor::Behaviour::new(
                    [(
                        StreamProtocol::new("/storagehub/0.1.0"),
                        ProtocolSupport::Full,
                    )],
                    request_response::Config::default(),
                ),
            })
        })?
        .with_swarm_config(|config| {
            config
                .with_max_negotiating_inbound_streams(SWARM_MAX_NEGOTIATING_INBOUND_STREAMS)
                .with_idle_connection_timeout(IDLE_CONNECTION_TIMEOUT)
        })
        .build();

How can I debug this further?

[thomaseizinger]

How big is that file? std::fs are thread-blocking APIs so they will stall your executor thread.