File Sharing Example: Getter can't see providers

[MitchTurner]

Hey. I've been interested in learning more about Libp2p for work and for personal use. I thought I'd go through some of the examples and trying fidgeting with the code to understand how it works and add my own functionality.

I've been looking at the file-sharing example and I can't seem to get it to work. Just following the README instructions, the getter instance would start up but never receive the content of the desired file.

I started instrumenting the code (adding print statements) and found that the getter instance was stalling when asking for the providers. It appears that it is successfully asking for the providers, but the response back is FinishedWithNoAdditionalRecord instead of FoundProviders. Since the providers are never passed back through the channel, the client just awaits the providers response forever.

I've confirmed that a connection is being made between the getter instance and the provider instance. I've also confirmed that the provider is running start_providing, and it appears that it is--I can even print add get_providers and see that it's included. I guess that it's just not getting broadcasted to the getter instance?

I can keep fidgeting with this, but I kinda wonder if the example is broken? It's more likely PEBKAC :) but figured I'd check.

[mxinden]

Thanks for reporting @MitchTurner! Also happy that libp2p sparks your curiosity.

Would you mind posting the logs of the file provider and the file receiver here?

[MitchTurner]

Sure. I assume you mean the logs I'm printing out? Unless there are some built-in logs :)

FILE PROVIDER

Given file:

> cat /tmp/hello.txt
hello world!

When I run the command

cargo run -- --listen-address /ip4/127.0.0.1/tcp/40837 --secret-key-seed 1 provide --path /tmp/hello.txt --name hello

I get:

Waiting for events or commands.
Handling command: StartListening { addr: "/ip4/127.0.0.1/tcp/40837", sender: Sender { complete: false } }.
Waiting for events or commands.
Handling event: NewListenAddr { listener_id: ListenerId(1), address: "/ip4/127.0.0.1/tcp/40837" }.
Local node is listening on "/ip4/127.0.0.1/tcp/40837/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"
Waiting for events or commands.
Handling command: StartProviding { file_name: "hello", sender: Sender { complete: false } }.
Waiting for events or commands.
Handling event: Behaviour(Kademlia(OutboundQueryProgressed { id: QueryId(0), result: StartProviding(Ok(AddProviderOk { key: Key(b"hello") })), stats: QueryStats { requests: 0, success: 0, failure: 0, start: Some(Instant { tv_sec: 18029, tv_nsec: 698731275 }), end: Some(Instant { tv_sec: 18029, tv_nsec: 698731275 }) }, step: ProgressStep { count: 1, last: true } })).
Waiting for events or commands.

Then after I connect file receiver:

Handling event: IncomingConnection { connection_id: ConnectionId(1), local_addr: "/ip4/127.0.0.1/tcp/40837", send_back_addr: "/ip4/127.0.0.1/tcp/53268" }.
Waiting for events or commands.
Handling event: ConnectionEstablished { peer_id: PeerId("12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"), connection_id: ConnectionId(1), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/40837", send_back_addr: "/ip4/127.0.0.1/tcp/53268" }, num_established: 1, concurrent_dial_errors: None, established_in: 52.389063ms }.
Waiting for events or commands.

after which it times out after a few seconds:

Handling event: ConnectionClosed { peer_id: PeerId("12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"), connection_id: ConnectionId(1), endpoint: Listener { local_addr: "/ip4/127.0.0.1/tcp/40837", send_back_addr: "/ip4/127.0.0.1/tcp/53268" }, num_established: 0, cause: Some(IO(Custom { kind: Other, error: Error(Closed) })) }.
Waiting for events or commands.

FILE RECEIVER

When I run the command:

cargo run -- --peer /ip4/127.0.0.1/tcp/40837/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X get --name hello

I get:

Waiting for events or commands.
Handling command: StartListening { addr: "/ip4/0.0.0.0/tcp/0", sender: Sender { complete: false } }.
Waiting for events or commands.
Handling command: Dial { peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), peer_addr: "/ip4/127.0.0.1/tcp/40837/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", sender: Sender { complete: false } }.
Waiting for events or commands.
Handling event: Behaviour(Kademlia(RoutingUpdated { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), is_new_peer: true, addresses: ["/ip4/127.0.0.1/tcp/40837/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"], bucket_range: (Distance(57896044618658097711785492504343953926634992332820282019728792003956564819968), Distance(115792089237316195423570985008687907853269984665640564039457584007913129639935)), old_peer: None })).
Kademlia event not handled: RoutingUpdated { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), is_new_peer: true, addresses: ["/ip4/127.0.0.1/tcp/40837/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"], bucket_range: (Distance(57896044618658097711785492504343953926634992332820282019728792003956564819968), Distance(115792089237316195423570985008687907853269984665640564039457584007913129639935)), old_peer: None }.
Waiting for events or commands.
Handling event: NewListenAddr { listener_id: ListenerId(1), address: "/ip4/127.0.0.1/tcp/34381" }.
Local node is listening on "/ip4/127.0.0.1/tcp/34381/p2p/12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"
Waiting for events or commands.
Handling event: NewListenAddr { listener_id: ListenerId(1), address: "/ip4/192.168.0.183/tcp/34381" }.
Local node is listening on "/ip4/192.168.0.183/tcp/34381/p2p/12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"
Waiting for events or commands.
Handling event: NewListenAddr { listener_id: ListenerId(1), address: "/ip4/172.22.0.1/tcp/34381" }.
Local node is listening on "/ip4/172.22.0.1/tcp/34381/p2p/12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"
Waiting for events or commands.
Handling event: NewListenAddr { listener_id: ListenerId(1), address: "/ip4/172.23.0.1/tcp/34381" }.
Local node is listening on "/ip4/172.23.0.1/tcp/34381/p2p/12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"
Waiting for events or commands.
Handling event: NewListenAddr { listener_id: ListenerId(1), address: "/ip4/172.17.0.1/tcp/34381" }.
Local node is listening on "/ip4/172.17.0.1/tcp/34381/p2p/12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"
Waiting for events or commands.
Handling event: NewListenAddr { listener_id: ListenerId(1), address: "/ip4/172.27.0.1/tcp/34381" }.
Local node is listening on "/ip4/172.27.0.1/tcp/34381/p2p/12D3KooWQQRRrY4tXmJqBcjWZCNCbYv9FEvEJguGYCGhcgv5XE68"
Waiting for events or commands.
Handling event: ConnectionEstablished { peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection_id: ConnectionId(1), endpoint: Dialer { address: "/ip4/127.0.0.1/tcp/40837/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }, num_established: 1, concurrent_dial_errors: Some([]), established_in: 8.559749ms }.
Waiting for events or commands.
Getting file hello.
Getting providers for file "hello".
Handling command: GetProviders { file_name: "hello", sender: Sender { complete: false } }.
Query id: QueryId(0).
Waiting for events or commands.
Handling event: Behaviour(Kademlia(OutboundQueryProgressed { id: QueryId(0), result: GetProviders(Ok(FinishedWithNoAdditionalRecord { closest_peers: [] })), stats: QueryStats { requests: 1, success: 0, failure: 1, start: Some(Instant { tv_sec: 18073, tv_nsec: 666382686 }), end: Some(Instant { tv_sec: 18073, tv_nsec: 752764010 }) }, step: ProgressStep { count: 1, last: true } })).
Waiting for events or commands.

after which it will timeout after a few seconds:

Handling event: ConnectionClosed { peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection_id: ConnectionId(1), endpoint: Dialer { address: "/ip4/127.0.0.1/tcp/40837/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }, num_established: 0, cause: Some(KeepAliveTimeout) }.
Waiting for events or commands.

[MitchTurner]

Importantly. I'd like to point out

Handling event: Behaviour(Kademlia(OutboundQueryProgressed { id: QueryId(0), result: GetProviders(Ok(FinishedWithNoAdditionalRecord { closest_peers: [] })), stats: QueryStats { requests: 1, success: 0, failure: 1, start: Some(Instant { tv_sec: 18073, tv_nsec: 666382686 }), end: Some(Instant { tv_sec: 18073, tv_nsec: 752764010 }) }, step: ProgressStep { count: 1, last: true } })).

which I read as saying there are no providers.

[mxinden]

I am sorry for the delay here. Are you testing with #4197. If not, that should fix your problem.

In case it doesn't, please run with RUST_LOG=debug and post the logs here once more.

Thank you @MitchTurner.

[bhagdave]

I was having the same problem and patched from #4197 which fixed the problem.

[MitchTurner]

That works! Thank you!

[mxinden]

Great. Closing here. Thank you for reporting the issue.