refactor(examples): use tokio instead of async-std in relay-server #5600

P1R · 2024-09-17T06:00:48Z

Description

Following on issue #4449
refactor: use tokio instead of async-std in the relay-servert example and remove unnecessary dependencies

Notes & open questions

Fails on testing with the whole punch tutorial possibly because of my networking topology. connection established event registered.

I will publish the logs and testing information as a comment

Change checklist

Removed unnecessary dependencies on examples/relay-server/Cargo.toml
Updated tokio version to "1.37.0"

I have performed a self-review of my own code
I have made corresponding changes to the documentation
I have added tests that prove my fix is effective or that my feature works
A changelog entry has been made in the appropriate crates

P1R · 2024-09-17T08:55:37Z

Issue 4449 relay-server (examples)

#4449

Code review and tests

the current PR

Refactor: use tokio instead of async-std in the relay-server example
Remove the block_on from futures::executor
Setup relay-server with open tcp port on 4001 at
Test libp2p-lookup
Test whole punching

Whole punching

Status: Cannot stablish the whole punching
Error: Outgoing Connection Failed: Timeout has been reached

Network Topology

The network topology used in this setup involves three key nodes:

Relay Server (/ip4/66.29.128.144/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN),
running in an Incus container with port forwarding enabled.
Listening Client (/ip4/10.162.235.31/tcp/36521/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X),
also running in an Incus container behind NAT using the same server that hosts the relay server (on a private IP address).
Dialing Client (/ip4/192.168.1.150/tcp/42045/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3),
running on a separate device behind a NAT.

Key Observations:

Relay server has public access and forwards connections on port 4001.
Listening client is behind NAT in an Incus container on the same LAN as the relay.
Dialing client attempts direct connectivity to the listening node using a relay but struggles due to timeouts.

Problem:

Hole punching isn't successfully establishing between the listening and dialing clients. Timeouts are being hit while trying to negotiate transport protocols over the relay.

Relay Server

Multiaddress: /ip4/66.29.128.144/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN

Executed command

./relay-server-example --port 4001 --secret-key-seed 0

Notice: the relay server is running in an incus container where the iptables
of the main server with the public ip address redirect the 4001 tcp in bouth
directions (forwarding enable).

Logs

p1r0@libp2p:~/rust-libp2p-bare/relay-server-example/target/debug$ ./relay-server-example --port 4001 --secret-key-seed 0
Listening on "/ip4/127.0.0.1/tcp/4001"
Listening on "/ip4/10.162.235.39/tcp/4001"
Listening on "/ip4/127.0.0.1/udp/4001/quic-v1"
Listening on "/ip4/10.162.235.39/udp/4001/quic-v1"
BehaviourEvent: Sent { connection_id: ConnectionId(1), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
BehaviourEvent: Received { connection_id: ConnectionId(1), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), info: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): cecc157dc1ddd7295951c29888f095adb944d1b73d696e6df65d683bd4fc) }, protocol_version: "/TODO/0.0.1", agent_version: "rust-libp2p/0.45.1", listen_addrs: ["/ip4/127.0.0.1/udp/39912/quic-v1", "/ip4/10.162.235.31/tcp/36521", "/ip4/127.0.0.1/tcp/36521", "/ip4/10.162.235.31/udp/39912/quic-v1"], protocols: ["/libp2p/circuit/relay/0.2.0/stop", "/ipfs/id/push/1.0.0", "/ipfs/id/1.0.0", "/ipfs/ping/1.0.0"], observed_addr: "/ip4/10.162.235.39/tcp/4001" } }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.550565ms) }
BehaviourEvent: ReservationReqAccepted { src_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), renewed: false }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.472772ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.874097ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(2.331323ms) }
BehaviourEvent: Sent { connection_id: ConnectionId(3), peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }
BehaviourEvent: Received { connection_id: ConnectionId(3), peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), info: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): 6b79c57e6a95239282c4818e96112f3f3a401ba97a564c23852a3f1ea5fc) }, protocol_version: "/TODO/0.0.1", agent_version: "rust-libp2p/0.45.1", listen_addrs: ["/ip4/127.0.0.1/tcp/42045", "/ip4/192.168.122.1/tcp/42045", "/ip4/192.168.122.1/udp/56226/quic-v1", "/ip4/192.168.1.150/tcp/42045", "/ip4/192.168.1.150/udp/56226/quic-v1", "/ip4/127.0.0.1/udp/56226/quic-v1"], protocols: ["/ipfs/id/1.0.0", "/ipfs/id/push/1.0.0", "/ipfs/ping/1.0.0", "/libp2p/circuit/relay/0.2.0/stop"], observed_addr: "/ip4/66.29.128.144/tcp/4001" } }
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(3), result: Ok(300.63699ms) }
BehaviourEvent: CircuitReqAccepted { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.357739ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(3), result: Ok(599.426206ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.850532ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(3), result: Ok(81.035919ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.396456ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(3), result: Ok(144.138389ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.365213ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(3), result: Ok(75.182587ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.865604ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(3), result: Ok(147.051367ms) }
BehaviourEvent: CircuitClosed { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), error: None }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(949.996µs) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.66916ms) }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(1.713821ms) }

Listening Client

Multiaddress: /ip4/10.162.235.31/tcp/33887/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6Xe4

Notice: the listening client is behind a incus NAT in a incus container where the host server is the
public ip address.

Executed command

RUST_LOG=info ./dcutr-example --secret-key-seed 1 --mode listen --relay-address /ip4/10.162.235.39/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN

Notice: this is my laptop running in my home network where there is a NAT and a basic firewall setup
in the gateway

Logs

p1r0@libp2pNode1:~/rust-libp2p-bare/relay-server-example/target/debug$ RUST_LOG=info ./dcutr-example --secret-key-seed 1 --mode listen --relay-address /ip4/10.162.235.39/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
2024-09-17T08:37:15.173682Z  INFO libp2p_swarm: local_peer_id=12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
2024-09-17T08:37:15.174558Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/tcp/36521
2024-09-17T08:37:15.174644Z  INFO dcutr_example: Listening on address address=/ip4/10.162.235.31/tcp/36521
2024-09-17T08:37:15.174892Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/udp/39912/quic-v1
2024-09-17T08:37:15.174989Z  INFO dcutr_example: Listening on address address=/ip4/10.162.235.31/udp/39912/quic-v1
2024-09-17T08:37:16.265139Z  INFO dcutr_example: Told relay its public address
2024-09-17T08:37:16.267471Z  INFO dcutr_example: Relay told us our observed address address=/ip4/10.162.235.31/tcp/36521
2024-09-17T08:37:16.315280Z  INFO dcutr_example: Relay accepted our reservation request
2024-09-17T08:37:16.315695Z  INFO dcutr_example: Listening on address address=/ip4/10.162.235.39/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
2024-09-17T08:38:02.255853Z  INFO dcutr_example: event=InboundCircuitEstablished { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), limit: Some(Limit { duration: Some(120s), data_in_bytes: Some(131072) }) }
2024-09-17T08:38:02.488581Z  INFO dcutr_example: Established new connection peer=12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 endpoint=Listener { local_addr: "/ip4/10.162.235.39/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }
2024-09-17T08:38:02.489372Z  INFO dcutr_example: event=Sent { connection_id: ConnectionId(2), peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }
2024-09-17T08:38:02.772861Z  INFO dcutr_example: event=Received { connection_id: ConnectionId(2), peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), info: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): 6b79c57e6a95239282c4818e96112f3f3a401ba97a564c23852a3f1ea5fc) }, protocol_version: "/TODO/0.0.1", agent_version: "rust-libp2p/0.45.1", listen_addrs: ["/ip4/127.0.0.1/tcp/42045", "/ip4/192.168.1.150/tcp/42045", "/ip4/127.0.0.1/udp/56226/quic-v1", "/ip4/192.168.122.1/udp/56226/quic-v1", "/ip4/192.168.1.150/udp/56226/quic-v1", "/ip4/192.168.122.1/tcp/42045"], protocols: ["/ipfs/ping/1.0.0", "/ipfs/id/push/1.0.0", "/ipfs/id/1.0.0", "/libp2p/dcutr"], observed_addr: "/ip4/66.29.128.144/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit" } }
2024-09-17T08:38:12.893833Z  INFO dcutr_example: Outgoing connection failed: Failed to negotiate transport protocol(s): [(/ip4/187.195.97.54/tcp/42045/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3: : Timeout has been reached)] peer=Some(PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"))
2024-09-17T08:38:23.472986Z  INFO dcutr_example: Outgoing connection failed: Failed to negotiate transport protocol(s): [(/ip4/187.195.97.54/tcp/42045/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3: : Timeout has been reached)] peer=Some(PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"))
2024-09-17T08:38:34.048308Z  INFO dcutr_example: Outgoing connection failed: Failed to negotiate transport protocol(s): [(/ip4/187.195.97.54/tcp/42045/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3: : Timeout has been reached)] peer=Some(PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"))
2024-09-17T08:38:34.048736Z  INFO dcutr_example: event=Event { remote_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), result: Err(Error { inner: AttemptsExceeded(3) }) }
2024-09-17T08:42:16.225777Z  INFO dcutr_example: event=Sent { connection_id: ConnectionId(1), peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") }
2024-09-17T08:42:16.227835Z  INFO dcutr_example: event=Received { connection_id: ConnectionId(1), peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), info: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): 3b6a27bcceb6a42d62a3a8d02a6fd73653215771de243a63ac048a18b59da29) }, protocol_version: "/TODO/0.0.1", agent_version: "rust-libp2p/0.45.1", listen_addrs: ["/ip4/10.162.235.39/tcp/4001", "/ip4/127.0.0.1/udp/4001/quic-v1", "/ip4/66.29.128.144/tcp/4001", "/ip4/10.162.235.39/udp/4001/quic-v1", "/ip4/127.0.0.1/tcp/4001"], protocols: ["/ipfs/id/1.0.0", "/ipfs/ping/1.0.0", "/libp2p/circuit/relay/0.2.0/hop", "/ipfs/id/push/1.0.0"], observed_addr: "/ip4/10.162.235.31/tcp/36521" } }

Dialing Client

Multiaddress: /ip4/192.168.1.150/tcp/42045/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3

Executed command

RUST_LOG=info ./dcutr-example --secret-key-seed 2 --mode dial --relay-address /ip4/66.29.128.144/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN --remote-peer-id 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6Xe4

Logs

└─(02:32:31 on relay-server-example)──> RUST_LOG=info ./dcutr-example --secret-key-seed 2 --mode dial --relay-address /ip4/66.29.128.144/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN --remote-peer-id 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
2024-09-17T08:32:43.043274Z  INFO libp2p_swarm: local_peer_id=12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3
2024-09-17T08:32:43.044208Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/tcp/42045
2024-09-17T08:32:43.044291Z  INFO dcutr_example: Listening on address address=/ip4/192.168.1.150/tcp/42045
2024-09-17T08:32:43.044358Z  INFO dcutr_example: Listening on address address=/ip4/192.168.122.1/tcp/42045
2024-09-17T08:32:43.044516Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/udp/56226/quic-v1
2024-09-17T08:32:43.044581Z  INFO dcutr_example: Listening on address address=/ip4/192.168.1.150/udp/56226/quic-v1
2024-09-17T08:32:43.044644Z  INFO dcutr_example: Listening on address address=/ip4/192.168.122.1/udp/56226/quic-v1
2024-09-17T08:32:44.860437Z  INFO dcutr_example: Told relay its public address
2024-09-17T08:32:44.862479Z  INFO dcutr_example: Relay told us our observed address address=/ip4/187.195.97.54/tcp/42045
2024-09-17T08:32:45.292991Z  INFO dcutr_example: event=OutboundCircuitEstablished { relay_peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), limit: Some(Limit { duration: Some(120s), data_in_bytes: Some(131072) }) }
2024-09-17T08:32:45.386709Z  INFO dcutr_example: Established new connection peer=12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X endpoint=Dialer { address: "/ip4/66.29.128.144/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer, port_use: Reuse }
2024-09-17T08:32:45.684082Z  INFO dcutr_example: event=Sent { connection_id: ConnectionId(2), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
2024-09-17T08:32:45.686354Z  INFO dcutr_example: event=Received { connection_id: ConnectionId(2), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), info: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): cecc157dc1ddd7295951c29888f095adb944d1b73d696e6df65d683bd4fc) }, protocol_version: "/TODO/0.0.1", agent_version: "rust-libp2p/0.45.1", listen_addrs: ["/ip4/10.162.235.31/udp/39912/quic-v1", "/ip4/10.162.235.31/tcp/36521", "/ip4/127.0.0.1/udp/39912/quic-v1", "/ip4/127.0.0.1/tcp/36521", "/ip4/10.162.235.39/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"], protocols: ["/ipfs/id/1.0.0", "/ipfs/ping/1.0.0", "/ipfs/id/push/1.0.0"], observed_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" } }
2024-09-17T08:32:56.045252Z  INFO dcutr_example: Outgoing connection failed: Failed to negotiate transport protocol(s): [(/ip4/10.162.235.31/tcp/36521/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X: : Timeout has been reached)] peer=Some(PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"))
2024-09-17T08:33:06.395826Z  INFO dcutr_example: Outgoing connection failed: Failed to negotiate transport protocol(s): [(/ip4/10.162.235.31/tcp/36521/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X: : Timeout has been reached)] peer=Some(PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"))
2024-09-17T08:33:16.971184Z  INFO dcutr_example: Outgoing connection failed: Failed to negotiate transport protocol(s): [(/ip4/10.162.235.31/tcp/36521/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X: : Timeout has been reached)] peer=Some(PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"))

Issue Considerations

I am not getting the tutorial logs in the dialing or listening clients some issues I could think of:

the incus container in the NAT might not resolve properly the public IP since it is also its gateway (yet DNS resolves it)
iptables configs for tcp forward has extra restrictions, yet the libp2p-lookup works.
My LAN resolves mostly on ipv6
code or sync issue.

Posible solutions

In case is network topology related:

check upd with quic-v1
Someone else has an network topology or environment to test this.
Someone can help me using their own NAT and LAN so that we can verify without the incus container and incus NAT

Others:

Code or sync issue?

References/Sources

dariusc93

Could you format the example?

P1R · 2024-09-20T07:11:45Z

UPDATE 1:

format added with cargo fmt.

UPDATE 2: testing with ../udp/4001/quic-v1/p2p..

Relay Server

Multiaddress: /ip4/66.29.128.144/udp/4001/quic-v1/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN

Executed command

./relay-server-example --port 4001 --secret-key-seed 0

Notice: the relay server is running in an incus container where the iptables
of the main server with the public ip address redirect the 4001 tcp in bouth
directions (forwarding enable).

Logs

p1r0@libp2p:~/rust-libp2p-bare/relay-server-example/target/debug$ ./relay-server-example --port 4001 --secret-key-seed 0
Listening on "/ip4/127.0.0.1/tcp/4001"
Listening on "/ip4/10.162.235.39/tcp/4001"
Listening on "/ip4/127.0.0.1/udp/4001/quic-v1"
Listening on "/ip4/10.162.235.39/udp/4001/quic-v1"
BehaviourEvent: Sent { connection_id: ConnectionId(12), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
BehaviourEvent: Error { connection_id: ConnectionId(12), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), error: Timeout }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(12), result: Err(Other { error: Custom { kind: NotConnected, error: ConnectionLost(TimedOut) } }) }
BehaviourEvent: Sent { connection_id: ConnectionId(13), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
BehaviourEvent: Error { connection_id: ConnectionId(13), peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), error: Timeout }
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(13), result: Err(Other { error: Custom { kind: NotConnected, error: ConnectionLost(TimedOut) } }) }
BehaviourEvent: Sent { connection_id: ConnectionId(15), peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }
BehaviourEvent: Received { connection_id: ConnectionId(15), peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), info: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): 6b79c57e6a95239282c4818e96112f3f3a401ba97a564c23852a3f1ea5fc) }, protocol_version: "/TODO/0.0.1", agent_version: "rust-libp2p/0.45.1", listen_addrs: ["/ip4/192.168.1.24/tcp/43971", "/ip4/127.0.0.1/tcp/43971", "/ip4/192.168.1.24/udp/60821/quic-v1", "/ip4/127.0.0.1/udp/60821/quic-v1"], protocols: ["/ipfs/id/1.0.0", "/ipfs/ping/1.0.0", "/ipfs/id/push/1.0.0", "/libp2p/circuit/relay/0.2.0/stop"], observed_addr: "/ip4/66.29.128.144/udp/4001/quic-v1" } }

Listening Client

Multiaddress: /ip4/10.162.235.39/udp/4001/quic-v1/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6Xe4

Notice: this time the client is running in a friend's LAN(NAT+Firewall )

Executed command

RUST_LOG=info ./dcutr-example --secret-key-seed 1 --mode listen --relay-address /ip4/10.162.235.39/udp/4001/quic-v1/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN

Logs

ahgala@rustbox ~/r/r/t/debug (relay-server-example) [101]> RUST_LOG=info ./dcutr-example --secret-key-seed 1 --mode listen --relay-address /ip4/66.29.128.144/udp/4001/quic-v1/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
2024-09-20T05:51:48.136817Z  INFO libp2p_swarm: local_peer_id=12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
2024-09-20T05:51:48.138042Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/tcp/34795
2024-09-20T05:51:48.138127Z  INFO dcutr_example: Listening on address address=/ip4/10.160.42.179/tcp/34795
2024-09-20T05:51:48.138359Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/udp/44072/quic-v1
2024-09-20T05:51:48.138442Z  INFO dcutr_example: Listening on address address=/ip4/10.160.42.179/udp/44072/quic-v1
2024-09-20T05:51:49.377339Z  INFO dcutr_example: Relay told us our observed address address=/ip4/201.102.167.194/udp/44072/quic-v1
thread 'main' panicked at examples/dcutr/src/main.rs:165:26:
NewExternalAddrOfPeer { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), address: "/ip4/10.162.235.39/udp/4001/quic-v1" }
note: run with RUST_BACKTRACE=1 environment variable to display a backtrace

Dialing Client

Multiaddress: /ip4/192.168.1.150/udp/4001/quic-v1/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3

Notice: this is my laptop running in my home network where there is a NAT and a basic firewall setup
in the gateway

Executed command

RUST_LOG=info ./dcutr-example --secret-key-seed 2 --mode dial --relay-address /ip4/66.29.128.144/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN --remote-peer-id 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6Xe4

Logs

┌─(...-libp2p-bare/relay-server-example/target/debug)───(p1r0@thoth:pts/4)─┐
└─(23:53:28 on relay-server-example)──> RUST_LOG=info ./dcutr-example --secret-key-seed 2 --mode dial --relay-address /ip4/66.29.128.144/udp/4001/quic-v1/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN --remote-peer-id 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X

2024-09-20T05:53:44.435972Z  INFO libp2p_swarm: local_peer_id=12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3
2024-09-20T05:53:44.436691Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/tcp/43971
2024-09-20T05:53:44.436723Z  INFO dcutr_example: Listening on address address=/ip4/192.168.1.24/tcp/43971
2024-09-20T05:53:44.436803Z  INFO dcutr_example: Listening on address address=/ip4/127.0.0.1/udp/60821/quic-v1
2024-09-20T05:53:44.436829Z  INFO dcutr_example: Listening on address address=/ip4/192.168.1.24/udp/60821/quic-v1
2024-09-20T05:53:45.677762Z  INFO dcutr_example: Relay told us our observed address address=/ip4/138.84.62.18/udp/2268/quic-v1
thread 'main' panicked at examples/dcutr/src/main.rs:165:26:
NewExternalAddrOfPeer { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), address: "/ip4/10.162.235.39/udp/4001/quic-v1" }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Issue Considerations

Given the error on bouth peers:

 'main' panicked at examples/dcutr/src/main.rs:165:26:
NewExternalAddrOfPeer { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), address: "/ip4/10.162.235.39/udp/4001/quic-v1" }

it seems that the line 164 is inside an block_on(Async as in using the futures block_on crate:

   23     block_on(async {
   22         let mut learned_observed_addr = false;
   21         let mut told_relay_observed_addr = false;
   20
   19         loop {
   18             match swarm.next().await.unwrap() {
   17                 SwarmEvent::NewListenAddr { .. } => {}
   16                 SwarmEvent::Dialing { .. } => {}
   15                 SwarmEvent::ConnectionEstablished { .. } => {}
   14                 SwarmEvent::Behaviour(BehaviourEvent::Ping(_)) => {}
   13                 SwarmEvent::Behaviour(BehaviourEvent::Identify(identify::Event::Sent {
   12                     ..
   11                 })) => {
   10                     tracing::info!("Told relay its public address");
    9                     told_relay_observed_addr = true;
    8                 }
    7                 SwarmEvent::Behaviour(BehaviourEvent::Identify(identify::Event::Received {
    6                     info: identify::Info { observed_addr, .. },
    5                     ..
    4                 })) => {
    3                     tracing::info!(address=%observed_addr, "Relay told us our observed address");
    2                     learned_observed_addr = true;
    1                 }
  165                 event => panic!("{event:?}"),
    1             }
    2
    3             if learned_observed_addr && told_relay_observed_addr {
    4                 break;
    5             }
    6         }
    7     });

NOTICE: In a previous call it was requested to remove this block_on section from the relay-server example

Could the issue be related to the block_on future not managed in the releay-server?

Posible solutions:

Remove the block_on from futures from the dcutr-example code as the clients and do the tests again.

David E. Perez Negron R. added 3 commits September 9, 2024 22:48

refactor: use tokio instead of async-std in the relay-server example

369b4a4

remove the block_on from futures::executor

2a57702

Merge branch 'master' into relay-server-example

6d8aecc

jxs changed the title ~~refactor(examples): use tokio instead of async-std in relay-server [Code Review]~~ refactor(examples): use tokio instead of async-std in relay-server Sep 17, 2024

dariusc93 approved these changes Sep 19, 2024

View reviewed changes

dariusc93 reviewed Sep 19, 2024

View reviewed changes

dariusc93 self-requested a review September 19, 2024 00:26

adding format

503af7b

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

refactor(examples): use tokio instead of async-std in relay-server #5600

refactor(examples): use tokio instead of async-std in relay-server #5600

P1R commented Sep 17, 2024

P1R commented Sep 17, 2024

dariusc93 left a comment

P1R commented Sep 20, 2024 •

edited

Loading

refactor(examples): use tokio instead of async-std in relay-server #5600

Are you sure you want to change the base?

refactor(examples): use tokio instead of async-std in relay-server #5600

Conversation

P1R commented Sep 17, 2024

Description

Notes & open questions

Change checklist

P1R commented Sep 17, 2024

Issue 4449 relay-server (examples)

Code review and tests

Whole punching

Network Topology

The network topology used in this setup involves three key nodes:

Key Observations:

Problem:

Relay Server

Executed command

Logs

Listening Client

Executed command

Logs

Dialing Client

Executed command

Logs

Issue Considerations

Posible solutions

References/Sources

dariusc93 left a comment

Choose a reason for hiding this comment

P1R commented Sep 20, 2024 • edited Loading

UPDATE 1:

UPDATE 2: testing with ../udp/4001/quic-v1/p2p..

Relay Server

Executed command

Logs

Listening Client

Executed command

Logs

Dialing Client

Executed command

Logs

Issue Considerations

Could the issue be related to the block_on future not managed in the releay-server?

Posible solutions:

P1R commented Sep 20, 2024 •

edited

Loading