Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

dialing client raised Connection closed with error NoAddresses, relay server log is no protocol could be agreed upon for inbound stream #4007

Open
gongzhengyang opened this issue May 30, 2023 · 17 comments

Comments

@gongzhengyang
Copy link

gongzhengyang commented May 30, 2023

Summary

I started by the docs in libp2p/src/tutorials/hole_punching.rs.

The relay and listening client can connect successful, but the dialing client couldn't.

When dailing client try to dial, the relay server always has a debug level log is no protocol could be agreed upon for inbound stream, and return a bytes [8, 100] to dailing client, which means CONNECT (refer rust-libp2p/protocols/dcutr/src/generated/holepunch/pb.rs) for dailing client.

Dialing client error libp2p_swarm] Connection closed with error Handler(Left(Right(Left(Apply(Left(NoAddresses)))))) .

Expected behaviour

The listening client initiating a direct connection upgrade for the new relayed connection.

Actual behaviour

Dailing client raised an error Connection closed with error Handler(Left(Right(Left(Apply(Left(NoAddresses)))))), and the connection between Dailing client and relay server broken.

Relay Debug Output

$ sudo RUST_LOG=debug ./relay --secret-key-seed 0 --port 4001 
opt: Opt { use_ipv6: None, secret_key_seed: 0, port: 4001 }
Local peer id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN")
[2023-05-30T06:30:38Z DEBUG libp2p_tcp] listening on 0.0.0.0:4001
[2023-05-30T06:30:38Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:30:38Z DEBUG libp2p_tcp] New listen address: /ip4/127.0.0.1/tcp/4001
[2023-05-30T06:30:38Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/127.0.0.1/tcp/4001"
Listening on "/ip4/127.0.0.1/tcp/4001"
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:30:38Z DEBUG libp2p_tcp] New listen address: /ip4/10.0.8.14/tcp/4001
[2023-05-30T06:30:38Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/10.0.8.14/tcp/4001"
Listening on "/ip4/10.0.8.14/tcp/4001"
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:30:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:30:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
........
[2023-05-30T06:30:45Z DEBUG libp2p_tcp] Incoming connection from /ip4/115.216.2.224/tcp/27594 at /ip4/10.0.8.14/tcp/4001
[2023-05-30T06:30:45Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /noise
[2023-05-30T06:30:45Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /noise
[2023-05-30T06:30:45Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:30:45Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:30:45Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:30:45Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:30:45Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:30:45Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /yamux/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /yamux/1.0.0
[2023-05-30T06:30:46Z DEBUG yamux::connection] new connection: 0753d206 (Server)
[2023-05-30T06:30:46Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") Listener { local_addr: "/ip4/10.0.8.14/tcp/4001", send_back_addr: "/ip4/115.216.2.224/tcp/27594" }; Total (peer): 1.
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-05-30T06:30:46Z DEBUG yamux::connection] 0753d206: new outbound (Stream 0753d206/2) of (Connection 0753d206 Server (streams 0))
[2023-05-30T06:30:46Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:30:46Z DEBUG yamux::connection] 0753d206: new outbound (Stream 0753d206/4) of (Connection 0753d206 Server (streams 3))
[2023-05-30T06:30:46Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: rejecting protocol: /meshsub/1.1.0
BehaviourEvent: Sent { peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
[2023-05-30T06:30:46Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: rejecting protocol: /meshsub/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/circuit/relay/0.2.0/hop
BehaviourEvent: Received { 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.43.0", listen_addrs: ["/ip4/172.21.0.1/tcp/44415", "/ip4/192.168.160.1/tcp/44415", "/ip4/192.168.192.1/tcp/44415", "/ip4/172.17.0.1/tcp/44415", "/ip4/10.30.6.101/tcp/44415", "/ip4/127.0.0.1/tcp/44415", "/ip4/192.168.176.1/tcp/44415", "/ip4/172.22.0.1/tcp/44415", "/ip4/192.168.144.1/tcp/44415"], protocols: [StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }, StreamProtocol { inner: Right("/meshsub/1.0.0") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }, StreamProtocol { inner: Right("/libp2p/circuit/relay/0.2.0/stop") }, StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/meshsub/1.1.0") }], observed_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN" } }
[2023-05-30T06:30:46Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 179ms
[2023-05-30T06:30:46Z DEBUG yamux::connection::stream] 0753d206/5: eof
[2023-05-30T06:30:46Z DEBUG libp2p_swarm::connection] no protocol could be agreed upon for inbound stream
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/push/1.0.0
[2023-05-30T06:30:46Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/push/1.0.0
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(179.687047ms) }
BehaviourEvent: ReservationReqAccepted { src_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), renewed: false }
BehaviourEvent: Received { 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.43.0", listen_addrs: ["/ip4/172.21.0.1/tcp/44415", "/ip4/192.168.160.1/tcp/44415", "/ip4/192.168.192.1/tcp/44415", "/ip4/172.17.0.1/tcp/44415", "/ip4/10.30.6.101/tcp/44415", "/ip4/127.0.0.1/tcp/44415", "/ip4/192.168.176.1/tcp/44415", "/ip4/172.22.0.1/tcp/44415", "/ip4/192.168.144.1/tcp/44415"], protocols: [StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }, StreamProtocol { inner: Right("/libp2p/circuit/relay/0.2.0/stop") }, StreamProtocol { inner: Right("/ipfs/id/1.0.0") }], observed_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN" } }
[2023-05-30T06:31:01Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 143ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(143.976607ms) }
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:15Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:15Z DEBUG libp2p_tcp] Incoming connection from /ip4/115.216.2.224/tcp/33323 at /ip4/10.0.8.14/tcp/4001
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /noise
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /noise
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:15Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:15Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /yamux/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /yamux/1.0.0
[2023-05-30T06:31:15Z DEBUG yamux::connection] new connection: 73634848 (Server)
[2023-05-30T06:31:15Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") Listener { local_addr: "/ip4/10.0.8.14/tcp/4001", send_back_addr: "/ip4/115.216.2.224/tcp/33323" }; Total (peer): 1.
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: rejecting protocol: /meshsub/1.1.0
[2023-05-30T06:31:15Z DEBUG yamux::connection] 73634848: new outbound (Stream 73634848/2) of (Connection 73634848 Server (streams 1))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG yamux::connection] 73634848: new outbound (Stream 73634848/4) of (Connection 73634848 Server (streams 3))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
BehaviourEvent: Sent { peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: rejecting protocol: /meshsub/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/circuit/relay/0.2.0/hop
BehaviourEvent: Received { 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.43.0", listen_addrs: ["/ip4/172.17.0.1/tcp/35759", "/ip4/172.18.0.1/tcp/35759", "/ip4/10.30.6.152/tcp/35759", "/ip4/127.0.0.1/tcp/35759"], protocols: [StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/meshsub/1.1.0") }, StreamProtocol { inner: Right("/libp2p/circuit/relay/0.2.0/stop") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }, StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }, StreamProtocol { inner: Right("/meshsub/1.0.0") }], observed_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN" } }
[2023-05-30T06:31:15Z DEBUG libp2p_ping::handler] latency to 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 is 175ms
[2023-05-30T06:31:15Z DEBUG yamux::connection::stream] 73634848/1: eof
[2023-05-30T06:31:15Z DEBUG libp2p_swarm::connection] no protocol could be agreed upon for inbound stream
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/push/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/push/1.0.0
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(2), result: Ok(175.785608ms) }
[2023-05-30T06:31:15Z DEBUG yamux::connection] 0753d206: new outbound (Stream 0753d206/6) of (Connection 0753d206 Server (streams 2))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/stop
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/stop
BehaviourEvent: Received { 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.43.0", listen_addrs: ["/ip4/172.17.0.1/tcp/35759", "/ip4/172.18.0.1/tcp/35759", "/ip4/10.30.6.152/tcp/35759", "/ip4/127.0.0.1/tcp/35759"], protocols: [StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/libp2p/circuit/relay/0.2.0/stop") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }, StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }], observed_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN" } }
BehaviourEvent: CircuitReqAccepted { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
[2023-05-30T06:31:16Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 136ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(136.707858ms) }
[2023-05-30T06:31:26Z DEBUG yamux::connection] 73634848: socket eof
[2023-05-30T06:31:26Z DEBUG libp2p_swarm] Connection closed with error IO(Custom { kind: Other, error: Error(Closed) }): Connected { endpoint: Listener { local_addr: "/ip4/10.0.8.14/tcp/4001", send_back_addr: "/ip4/115.216.2.224/tcp/33323" }, peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }; Total (peer): 0.
BehaviourEvent: CircuitClosed { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), error: Some(Kind(ConnectionAborted)) }
[2023-05-30T06:31:31Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 114ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(114.897524ms) }
[2023-05-30T06:31:46Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 135ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(135.231272ms) }

Listening Client Debug Output

$ RUST_LOG=debug ./client --secret-key-seed 1 --mode listen --relay-address /ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:02Z INFO  client] Local peer id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
[2023-05-30T06:31:02Z DEBUG libp2p_gossipsub::behaviour] Subscribing to topic: test-net
[2023-05-30T06:31:02Z DEBUG libp2p_gossipsub::behaviour] Running JOIN for topic: TopicHash { hash: "test-net" }
[2023-05-30T06:31:02Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:02Z DEBUG libp2p_gossipsub::behaviour] JOIN: Inserting 0 random peers into the mesh
[2023-05-30T06:31:02Z DEBUG libp2p_gossipsub::behaviour] Completed JOIN for topic: TopicHash { hash: "test-net" }
[2023-05-30T06:31:02Z DEBUG libp2p_gossipsub::behaviour] Subscribed to topic: test-net
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] listening on 0.0.0.0:0
[2023-05-30T06:31:02Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
.........
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/127.0.0.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/127.0.0.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/127.0.0.1/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/10.30.6.101/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/10.30.6.101/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/10.30.6.101/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/10.30.6.101/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/10.30.6.101/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/10.30.6.101/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/172.22.0.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/172.22.0.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/172.22.0.1/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/172.17.0.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/172.17.0.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/172.17.0.1/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/172.21.0.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/172.21.0.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/172.21.0.1/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/192.168.144.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/192.168.144.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/192.168.144.1/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/192.168.160.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/192.168.160.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/192.168.160.1/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/192.168.176.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/192.168.176.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/192.168.176.1/tcp/44415"
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:02Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] handling requests
[2023-05-30T06:31:02Z DEBUG netlink_proto::connection] sending messages
[2023-05-30T06:31:02Z DEBUG libp2p_tcp] New listen address: /ip4/192.168.192.1/tcp/44415
[2023-05-30T06:31:02Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/192.168.192.1/tcp/44415"
[2023-05-30T06:31:02Z INFO  client] Listening on "/ip4/192.168.192.1/tcp/44415"
........
[2023-05-30T06:31:03Z DEBUG libp2p_dns] Dialing /ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:03Z DEBUG libp2p_tcp] dialing 114.132.71.142:4001
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /noise
[2023-05-30T06:31:03Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /noise
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /yamux/1.0.0
[2023-05-30T06:31:03Z DEBUG yamux::connection] new connection: f1a6b756 (Client)
[2023-05-30T06:31:03Z DEBUG yamux::connection] f1a6b756: new outbound (Stream f1a6b756/1) of (Connection f1a6b756 Client (streams 0))
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:03Z DEBUG yamux::connection] f1a6b756: new outbound (Stream f1a6b756/3) of (Connection f1a6b756 Client (streams 1))
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:03Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") Dialer { address: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }; Total (peer): 1.
[2023-05-30T06:31:03Z DEBUG libp2p_gossipsub::behaviour] New peer connected: 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:03Z DEBUG yamux::connection] f1a6b756: new outbound (Stream f1a6b756/5) of (Connection f1a6b756 Client (streams 2))
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /meshsub/1.1.0
[2023-05-30T06:31:03Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /yamux/1.0.0
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:03Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:03Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:03Z INFO  client] Relay told us our public address: "/ip4/115.216.2.224/tcp/27594"
[2023-05-30T06:31:03Z INFO  client] Told relay its public address.
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:03Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:03Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Received rejection of protocol: /meshsub/1.1.0
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /meshsub/1.0.0
[2023-05-30T06:31:03Z DEBUG yamux::connection] f1a6b756: new outbound (Stream f1a6b756/7) of (Connection f1a6b756 Client (streams 3))
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-05-30T06:31:03Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 179ms
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Received rejection of protocol: /meshsub/1.0.0
[2023-05-30T06:31:03Z DEBUG libp2p_gossipsub::handler] The remote peer does not support gossipsub on this connection
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-05-30T06:31:03Z DEBUG libp2p_identify::handler] Supported listen protocols changed from [/ipfs/id/push/1.0.0, /meshsub/1.0.0, /ipfs/ping/1.0.0, /libp2p/circuit/relay/0.2.0/stop, /ipfs/id/1.0.0, /meshsub/1.1.0] to [/ipfs/id/push/1.0.0, /ipfs/ping/1.0.0, /libp2p/circuit/relay/0.2.0/stop, /ipfs/id/1.0.0], pushing to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:03Z DEBUG yamux::connection] f1a6b756: new outbound (Stream f1a6b756/9) of (Connection f1a6b756 Client (streams 3))
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/push/1.0.0
[2023-05-30T06:31:03Z DEBUG libp2p_gossipsub::behaviour] Peer does not support gossipsub protocols. 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:03Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/push/1.0.0
[2023-05-30T06:31:03Z INFO  client] Pushed { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") }
[2023-05-30T06:31:03Z INFO  client] Relay accepted our reservation request.
[2023-05-30T06:31:03Z DEBUG libp2p_swarm] Listener ListenerId(2); New address: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"
[2023-05-30T06:31:03Z INFO  client] Listening on "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"
[2023-05-30T06:31:07Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:07Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:07Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:07Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:07Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:17Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:17Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:17Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:17Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:17Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:18Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 135ms
[2023-05-30T06:31:27Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:27Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:27Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:27Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:27Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/circuit/relay/0.2.0/stop
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/circuit/relay/0.2.0/stop
[2023-05-30T06:31:33Z INFO  client] InboundCircuitEstablished { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), limit: Some(Limit { duration: Some(120s), data_in_bytes: Some(131072) }) }
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /noise
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /noise
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /yamux/1.0.0
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /yamux/1.0.0
[2023-05-30T06:31:33Z DEBUG yamux::connection] new connection: f7c16b4d (Server)
[2023-05-30T06:31:33Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") Listener { local_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }; Total (peer): 1.
[2023-05-30T06:31:33Z DEBUG libp2p_gossipsub::behaviour] New peer connected: 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3
[2023-05-30T06:31:33Z INFO  client] Established connection to PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") via Listener { local_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /meshsub/1.1.0
[2023-05-30T06:31:33Z INFO  client] dcutr: InitiatedDirectConnectionUpgrade { remote_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), local_relayed_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit" }
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /meshsub/1.1.0
[2023-05-30T06:31:33Z DEBUG yamux::connection] f7c16b4d: new outbound (Stream f7c16b4d/2) of (Connection f7c16b4d Server (streams 1))
[2023-05-30T06:31:33Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /meshsub/1.1.0
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:33Z DEBUG libp2p_gossipsub::behaviour] New peer type found: Gossipsub v1.1 for peer: 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:33Z DEBUG yamux::connection] f7c16b4d: new outbound (Stream f7c16b4d/4) of (Connection f7c16b4d Server (streams 3))
[2023-05-30T06:31:33Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/dcutr
[2023-05-30T06:31:33Z INFO  client] Sent { peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:33Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:33Z DEBUG yamux::connection] f7c16b4d: new outbound (Stream f7c16b4d/6) of (Connection f7c16b4d Server (streams 4))
[2023-05-30T06:31:33Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:33Z DEBUG yamux::connection] f7c16b4d: new outbound (Stream f7c16b4d/8) of (Connection f7c16b4d Server (streams 5))
[2023-05-30T06:31:33Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:33Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 93ms
[2023-05-30T06:31:34Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /meshsub/1.1.0
[2023-05-30T06:31:34Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/dcutr
[2023-05-30T06:31:34Z DEBUG libp2p_gossipsub::behaviour] Handling subscriptions: [Subscription { action: Subscribe, topic_hash: TopicHash { hash: "test-net" } }], from source: 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3
[2023-05-30T06:31:34Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:34Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding gossip peer: 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 to topic: TopicHash { hash: "test-net" }
[2023-05-30T06:31:34Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding peer 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 to the mesh for topic TopicHash { hash: "test-net" }
[2023-05-30T06:31:34Z DEBUG libp2p_gossipsub::behaviour] Sending GRAFT to peer 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 for topic TopicHash { hash: "test-net" }
[2023-05-30T06:31:34Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:34Z INFO  client] Received { 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.43.0", listen_addrs: ["/ip4/10.30.6.152/tcp/35759", "/ip4/172.17.0.1/tcp/35759", "/ip4/172.18.0.1/tcp/35759", "/ip4/127.0.0.1/tcp/35759"], protocols: [StreamProtocol { inner: Right("/libp2p/dcutr") }, StreamProtocol { inner: Right("/meshsub/1.0.0") }, StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }, StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }, StreamProtocol { inner: Right("/meshsub/1.1.0") }], observed_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X" } }
[2023-05-30T06:31:37Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:37Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 1 needs: 5
[2023-05-30T06:31:37Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:37Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:37Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:43Z INFO  client] dcutr: DirectConnectionUpgradeFailed { remote_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), error: Handler(Timeout) }
[2023-05-30T06:31:47Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:47Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 1 needs: 5
[2023-05-30T06:31:47Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:47Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:47Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:49Z DEBUG yamux::connection::stream] f1a6b756/6: eof
[2023-05-30T06:31:49Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 133ms
[2023-05-30T06:31:49Z DEBUG yamux::connection] f7c16b4d: socket eof
[2023-05-30T06:31:49Z DEBUG libp2p_swarm] Connection closed with error IO(Custom { kind: Other, error: Error(Closed) }): Connected { endpoint: Listener { local_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }, peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }; Total (peer): 0.
[2023-05-30T06:31:49Z DEBUG libp2p_gossipsub::behaviour] Peer disconnected: 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3
[2023-05-30T06:31:57Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:57Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:57Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:57Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:57Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:32:04Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 135ms

Dailing Debug Output

$ RUST_LOG=debug ./client --secret-key-seed 2 --mode dial --relay-address /ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN --remote-peer-id 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
[2023-05-30T06:31:14Z INFO  client] Local peer id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3")
[2023-05-30T06:31:14Z DEBUG libp2p_gossipsub::behaviour] Subscribing to topic: test-net
[2023-05-30T06:31:14Z DEBUG libp2p_gossipsub::behaviour] Running JOIN for topic: TopicHash { hash: "test-net" }
[2023-05-30T06:31:14Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:14Z DEBUG libp2p_gossipsub::behaviour] JOIN: Inserting 0 random peers into the mesh
[2023-05-30T06:31:14Z DEBUG libp2p_gossipsub::behaviour] Completed JOIN for topic: TopicHash { hash: "test-net" }
[2023-05-30T06:31:14Z DEBUG libp2p_gossipsub::behaviour] Subscribed to topic: test-net
[2023-05-30T06:31:14Z DEBUG libp2p_tcp] listening on 0.0.0.0:0
[2023-05-30T06:31:14Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
[2023-05-30T06:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2023-05-30T06:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-05-30T06:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-05-30T06:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
......

[2023-05-30T06:31:15Z DEBUG libp2p_dns] Dialing /ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:15Z DEBUG libp2p_tcp] dialing 114.132.71.142:4001
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /noise
[2023-05-30T06:31:15Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /noise
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /yamux/1.0.0
[2023-05-30T06:31:15Z DEBUG yamux::connection] new connection: 95a3c808 (Client)
[2023-05-30T06:31:15Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") Dialer { address: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }; Total (peer): 1.
[2023-05-30T06:31:15Z DEBUG libp2p_gossipsub::behaviour] New peer connected: 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:15Z DEBUG yamux::connection] 95a3c808: new outbound (Stream 95a3c808/1) of (Connection 95a3c808 Client (streams 0))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /meshsub/1.1.0
[2023-05-30T06:31:15Z DEBUG yamux::connection] 95a3c808: new outbound (Stream 95a3c808/3) of (Connection 95a3c808 Client (streams 1))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:15Z DEBUG yamux::connection] 95a3c808: new outbound (Stream 95a3c808/5) of (Connection 95a3c808 Client (streams 2))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /yamux/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received rejection of protocol: /meshsub/1.1.0
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /meshsub/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:15Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:15Z INFO  client] Relay told us our public address: "/ip4/115.216.2.224/tcp/33323"
[2023-05-30T06:31:15Z INFO  client] Told relay its public address.
[2023-05-30T06:31:15Z DEBUG yamux::connection] 95a3c808: new outbound (Stream 95a3c808/7) of (Connection 95a3c808 Client (streams 3))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-05-30T06:31:15Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 175ms
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received rejection of protocol: /meshsub/1.0.0
[2023-05-30T06:31:15Z DEBUG libp2p_gossipsub::handler] The remote peer does not support gossipsub on this connection
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-05-30T06:31:15Z DEBUG libp2p_identify::handler] Supported listen protocols changed from [/ipfs/id/1.0.0, /meshsub/1.1.0, /libp2p/circuit/relay/0.2.0/stop, /ipfs/ping/1.0.0, /ipfs/id/push/1.0.0, /meshsub/1.0.0] to [/ipfs/id/1.0.0, /libp2p/circuit/relay/0.2.0/stop, /ipfs/ping/1.0.0, /ipfs/id/push/1.0.0], pushing to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:15Z DEBUG yamux::connection] 95a3c808: new outbound (Stream 95a3c808/9) of (Connection 95a3c808 Client (streams 3))
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/push/1.0.0
[2023-05-30T06:31:15Z DEBUG libp2p_gossipsub::behaviour] Peer does not support gossipsub protocols. 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:15Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/push/1.0.0
[2023-05-30T06:31:15Z INFO  client] Pushed { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") }
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /noise
[2023-05-30T06:31:16Z INFO  client] OutboundCircuitEstablished { relay_peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), limit: None }
[2023-05-30T06:31:16Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /noise
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /yamux/1.0.0
[2023-05-30T06:31:16Z DEBUG yamux::connection] new connection: 62f1cf94 (Client)
[2023-05-30T06:31:16Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") Dialer { address: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }; Total (peer): 1.
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] New peer connected: 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
[2023-05-30T06:31:16Z INFO  client] Established connection to PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") via Dialer { address: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }
[2023-05-30T06:31:16Z DEBUG yamux::connection] 62f1cf94: new outbound (Stream 62f1cf94/1) of (Connection 62f1cf94 Client (streams 0))
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /meshsub/1.1.0
[2023-05-30T06:31:16Z DEBUG yamux::connection] 62f1cf94: new outbound (Stream 62f1cf94/3) of (Connection 62f1cf94 Client (streams 1))
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:16Z DEBUG yamux::connection] 62f1cf94: new outbound (Stream 62f1cf94/5) of (Connection 62f1cf94 Client (streams 2))
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /yamux/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /meshsub/1.1.0
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /meshsub/1.1.0
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /meshsub/1.1.0
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/dcutr
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/dcutr
[2023-05-30T06:31:16Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:16Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] New peer type found: Gossipsub v1.1 for peer: 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
[2023-05-30T06:31:16Z INFO  client] Received { 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.43.0", listen_addrs: ["/ip4/10.30.6.101/tcp/44415", "/ip4/192.168.160.1/tcp/44415", "/ip4/192.168.192.1/tcp/44415", "/ip4/172.21.0.1/tcp/44415", "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", "/ip4/192.168.176.1/tcp/44415", "/ip4/127.0.0.1/tcp/44415", "/ip4/172.22.0.1/tcp/44415", "/ip4/192.168.144.1/tcp/44415", "/ip4/172.17.0.1/tcp/44415"], protocols: [StreamProtocol { inner: Right("/meshsub/1.0.0") }, StreamProtocol { inner: Right("/meshsub/1.1.0") }, StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }, StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }], observed_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" } }
[2023-05-30T06:31:16Z INFO  client] Sent { peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
[2023-05-30T06:31:16Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 272ms
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] Handling subscriptions: [Subscription { action: Subscribe, topic_hash: TopicHash { hash: "test-net" } }], from source: 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding gossip peer: 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X to topic: TopicHash { hash: "test-net" }
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding peer 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X to the mesh for topic TopicHash { hash: "test-net" }
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] Sending GRAFT to peer 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X for topic TopicHash { hash: "test-net" }
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] Handling GRAFT message for peer: 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] GRAFT: Received graft for peer PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") that is already in topic TopicHash { hash: "test-net" }
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] Completed GRAFT handling for peer: 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
[2023-05-30T06:31:16Z DEBUG libp2p_swarm] Connection closed with error Handler(Left(Right(Left(Apply(Left(NoAddresses)))))): Connected { endpoint: Dialer { address: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }, peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }; Total (peer): 0.
[2023-05-30T06:31:16Z DEBUG libp2p_gossipsub::behaviour] Peer disconnected: 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X
[2023-05-30T06:31:19Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:19Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:19Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:19Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:19Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:26Z DEBUG libp2p_swarm] Connection closed with error KeepAliveTimeout: Connected { endpoint: Dialer { address: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }, peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") }; Total (peer): 0.
[2023-05-30T06:31:26Z DEBUG libp2p_gossipsub::behaviour] Peer disconnected: 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-05-30T06:31:29Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:29Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:29Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:29Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:29Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:39Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:39Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:39Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:39Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:39Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:49Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:49Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:49Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:49Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:49Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:31:59Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:31:59Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:31:59Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:31:59Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:31:59Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:32:09Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:32:09Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:32:09Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:32:09Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:32:09Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:32:19Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:32:19Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5
[2023-05-30T06:32:19Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-05-30T06:32:19Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-05-30T06:32:19Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-05-30T06:32:29Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-05-30T06:32:29Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: test-net Contains: 0 needs: 5

Possible Solution

Version

  • rust-libp2p master@34e178049826789956dcab6aefe491e4b156a024 (Tue May 30 02:06:57 2023), and later master
  • I also tried the tag libp2p-v0.51.3, still failed.

Would you like to work on fixing this bug?

Yes

@gongzhengyang
Copy link
Author

gongzhengyang commented May 30, 2023

Version:
rust-libp2p master@34e178049826789956dcab6aefe491e4b156a024 (Tue May 30 02:06:57 2023)

client.rs is copy from https://github.com/libp2p/rust-libp2p/blob/master/examples/dcutr/src/main.rs
relay.rs is copy from https://github.com/libp2p/rust-libp2p/blob/master/examples/relay-server/src/main.rs

relay.rs add a line under the SwarmBuilder

let mut swarm = SwarmBuilder::without_executor(transport, behaviour, local_peer_id).build();
// need add specific external address for client connect correct
// https://github.com/libp2p/rust-libp2p/issues/2621#issuecomment-1127963348
swarm.add_external_address(
    "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"
        .parse()
        .unwrap(),
    );

@gongzhengyang
Copy link
Author

relay server is on a machine has a public IP114.132.71.142
listening client is on a machine different, and dial client on another

@gongzhengyang
Copy link
Author

图片
图片

@gongzhengyang
Copy link
Author

gongzhengyang commented May 31, 2023

maybe something happened when InboundUpgrade, if print the substream.next() bytes is [8, 100] , if print proto: HolePunch, I see HolePunch { type_pb: CONNECT, ObsAddrs: [] }. The relay error log is no protocol could be agreed upon for inbound stream
maybe something is related with #3591

@gongzhengyang gongzhengyang changed the title dial client error libp2p_swarm] Connection closed with error Handler(Left(Right(Left(Apply(Left(NoAddresses)))))) dialing client raised Connection closed with error NoAddresses, relay server log is no protocol could be agreed upon for inbound stream Jun 1, 2023
@gongzhengyang gongzhengyang changed the title dialing client raised Connection closed with error NoAddresses, relay server log is no protocol could be agreed upon for inbound stream dialing client raised Connection closed with error NoAddresses, relay server log is no protocol could be agreed upon for inbound stream Jun 1, 2023
@mxinden
Copy link
Member

mxinden commented Jun 1, 2023

Thanks for the detailed report.

Mind testing again now that #3982 is merged?

@gongzhengyang
Copy link
Author

Thanks for your help. I tried with the newest commit 87e863e8c9a116de79a9dd56fbacda7986bcdfe7, I execute cargo clean first and compile again. I also tried to rm Cargo.lock and again.

The debug log no protocol could be agreed upon for inbound stream which was in relay server logs, now is disappeared.

But the dailing client still failed with error Connection closed with error Handler(Right(Left(Apply(Left(NoAddresses)))))

relay server debug logs

[2023-06-01T05:44:07Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 119ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(119.819056ms) }
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] reading incoming messages
[2023-06-01T05:44:21Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] handling requests
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] sending messages
[2023-06-01T05:44:21Z DEBUG libp2p_tcp] Incoming connection from /ip4/125.119.189.52/tcp/29492 at /ip4/10.0.8.14/tcp/4002
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] reading incoming messages
[2023-06-01T05:44:21Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] handling requests
[2023-06-01T05:44:21Z DEBUG netlink_proto::connection] sending messages
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /noise
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /noise
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /yamux/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /yamux/1.0.0
[2023-06-01T05:44:21Z DEBUG yamux::connection] new connection: d554a025 (Server)
[2023-06-01T05:44:21Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") Listener { local_addr: "/ip4/10.0.8.14/tcp/4002", send_back_addr: "/ip4/125.119.189.52/tcp/29492" }; Total (peer): 1.
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z DEBUG yamux::connection] d554a025: new outbound (Stream d554a025/2) of (Connection d554a025 Server (streams 0))
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
BehaviourEvent: Sent { peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }
[2023-06-01T05:44:21Z DEBUG yamux::connection] d554a025: new outbound (Stream d554a025/4) of (Connection d554a025 Server (streams 2))
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/circuit/relay/0.2.0/hop
BehaviourEvent: Received { 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.43.0", listen_addrs: ["/ip4/192.168.80.1/tcp/35869", "/ip4/192.168.252.1/tcp/35869", "/ip4/172.31.0.1/tcp/35869", "/ip4/172.16.2.1/tcp/35869", "/ip4/172.16.67.1/tcp/35869", "/ip4/172.24.0.1/tcp/35869", "/ip4/192.168.144.1/tcp/35869", "/ip4/192.168.128.1/tcp/35869", "/ip4/192.168.176.1/tcp/35869", "/ip4/192.168.250.1/tcp/35869", "/ip4/172.29.0.1/tcp/35869", "/ip4/172.22.0.1/tcp/35869", "/ip4/127.0.0.1/tcp/35869", "/ip4/192.168.251.1/tcp/35869", "/ip4/172.25.0.1/tcp/35869", "/ip4/10.30.6.88/tcp/35869", "/ip4/172.26.0.1/tcp/35869", "/ip4/192.168.96.1/tcp/35869", "/ip4/172.17.0.1/tcp/35869", "/ip4/192.168.1.129/tcp/35869", "/ip4/192.168.122.1/tcp/35869", "/ip4/10.30.99.1/tcp/35869", "/ip4/172.19.0.1/tcp/35869", "/ip4/172.28.0.1/tcp/35869", "/ip4/172.27.0.1/tcp/35869", "/ip4/172.21.0.1/tcp/35869", "/ip4/172.18.0.1/tcp/35869"], protocols: [StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }, StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/libp2p/circuit/relay/0.2.0/stop") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }], observed_addr: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN" } }
[2023-06-01T05:44:21Z DEBUG libp2p_ping::handler] latency to 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 is 163ms
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(2), result: Ok(163.899586ms) }
[2023-06-01T05:44:21Z DEBUG yamux::connection] 5d87bab8: new outbound (Stream 5d87bab8/6) of (Connection 5d87bab8 Server (streams 2))
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/stop
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/stop
BehaviourEvent: CircuitReqAccepted { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
[2023-06-01T05:44:23Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 123ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(123.980962ms) }
[2023-06-01T05:44:32Z DEBUG yamux::connection] d554a025: socket eof
[2023-06-01T05:44:32Z DEBUG libp2p_swarm] Connection closed with error IO(Custom { kind: Other, error: Error(Closed) }): Connected { endpoint: Listener { local_addr: "/ip4/10.0.8.14/tcp/4002", send_back_addr: "/ip4/125.119.189.52/tcp/29492" }, peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }; Total (peer): 0.
BehaviourEvent: CircuitClosed { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), error: Some(Kind(ConnectionAborted)) }
[2023-06-01T05:44:38Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 123ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(123.768397ms) }
[2023-06-01T05:44:53Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 115ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(1), result: Ok(115.774774ms) }

dailing client debug logs


[2023-06-01T05:44:20Z INFO  client] Local peer id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3")
[2023-06-01T05:44:20Z DEBUG libp2p_tcp] listening on 0.0.0.0:0
[2023-06-01T05:44:20Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
... 
2023-06-01T05:44:20Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-06-01T05:44:20Z DEBUG netlink_proto::connection] handling requests
[2023-06-01T05:44:20Z DEBUG netlink_proto::connection] sending messages
[2023-06-01T05:44:20Z DEBUG netlink_proto::connection] reading incoming messages
[2023-06-01T05:44:20Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2023-06-01T05:44:20Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2023-06-01T05:44:20Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2023-06-01T05:44:20Z DEBUG netlink_proto::connection] handling requests
[2023-06-01T05:44:20Z DEBUG netlink_proto::connection] sending messages
[2023-06-01T05:44:21Z DEBUG libp2p_dns] Dialing /ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2023-06-01T05:44:21Z DEBUG libp2p_tcp] dialing 114.132.71.142:4002
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /noise
[2023-06-01T05:44:21Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /noise
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /yamux/1.0.0
[2023-06-01T05:44:21Z DEBUG yamux::connection] new connection: ed7b5d30 (Client)
[2023-06-01T05:44:21Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") Dialer { address: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }; Total (peer): 1.
[2023-06-01T05:44:21Z DEBUG yamux::connection] ed7b5d30: new outbound (Stream ed7b5d30/1) of (Connection ed7b5d30 Client (streams 0))
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z DEBUG yamux::connection] ed7b5d30: new outbound (Stream ed7b5d30/3) of (Connection ed7b5d30 Client (streams 1))
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /yamux/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:21Z INFO  client] Relay told us our public address: "/ip4/125.119.189.52/tcp/29492"
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:21Z INFO  client] Told relay its public address.
[2023-06-01T05:44:21Z DEBUG yamux::connection] ed7b5d30: new outbound (Stream ed7b5d30/5) of (Connection ed7b5d30 Client (streams 2))
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-06-01T05:44:21Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 159ms
[2023-06-01T05:44:21Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2023-06-01T05:44:22Z INFO  client] OutboundCircuitEstablished { relay_peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), limit: None }
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /noise
[2023-06-01T05:44:22Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /noise
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Expecting proposed protocol: /yamux/1.0.0
[2023-06-01T05:44:22Z DEBUG yamux::connection] new connection: 4dcb0cfd (Client)
[2023-06-01T05:44:22Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") Dialer { address: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }; Total (peer): 1.
[2023-06-01T05:44:22Z DEBUG yamux::connection] 4dcb0cfd: new outbound (Stream 4dcb0cfd/1) of (Connection 4dcb0cfd Client (streams 0))
[2023-06-01T05:44:22Z INFO  client] Established connection to PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") via Dialer { address: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:22Z DEBUG yamux::connection] 4dcb0cfd: new outbound (Stream 4dcb0cfd/3) of (Connection 4dcb0cfd Client (streams 1))
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:22Z DEBUG multistream_select::negotiated] Negotiated: Received confirmation for protocol: /yamux/1.0.0
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:22Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/dcutr
[2023-06-01T05:44:22Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/dcutr
[2023-06-01T05:44:22Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:22Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:22Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:22Z INFO  client] Received { 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.43.0", listen_addrs: ["/ip4/192.168.144.1/tcp/43327", "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", "/ip4/172.22.0.1/tcp/43327", "/ip4/172.21.0.1/tcp/43327", "/ip4/192.168.176.1/tcp/43327", "/ip4/192.168.192.1/tcp/43327", "/ip4/192.168.160.1/tcp/43327", "/ip4/172.17.0.1/tcp/43327", "/ip4/10.30.6.101/tcp/43327", "/ip4/127.0.0.1/tcp/43327"], protocols: [StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }, StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }], observed_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" } }
[2023-06-01T05:44:22Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:22Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:22Z INFO  client] Sent { peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
[2023-06-01T05:44:22Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 239ms
[2023-06-01T05:44:22Z DEBUG libp2p_swarm] Connection closed with error Handler(Right(Left(Apply(Left(NoAddresses))))): Connected { endpoint: Dialer { address: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }, peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }; Total (peer): 0.
[2023-06-01T05:44:32Z DEBUG libp2p_swarm] Connection closed with error KeepAliveTimeout: Connected { endpoint: Dialer { address: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }, peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") }; Total (peer): 0.

listening client debug logs

[2023-06-01T05:44:38Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/circuit/relay/0.2.0/stop
[2023-06-01T05:44:38Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/circuit/relay/0.2.0/stop
[2023-06-01T05:44:38Z INFO  client] InboundCircuitEstablished { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), limit: Some(Limit { duration: Some(120s), data_in_bytes: Some(131072) }) }
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /noise
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /noise
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /yamux/1.0.0
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /yamux/1.0.0
[2023-06-01T05:44:39Z DEBUG yamux::connection] new connection: 91ea2edc (Server)
[2023-06-01T05:44:39Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") Listener { local_addr: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }; Total (peer): 1.
[2023-06-01T05:44:39Z INFO  client] Established connection to PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") via Listener { local_addr: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }
[2023-06-01T05:44:39Z INFO  client] InitiatedDirectConnectionUpgrade { remote_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), local_relayed_addr: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit" }
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:39Z DEBUG yamux::connection] 91ea2edc: new outbound (Stream 91ea2edc/2) of (Connection 91ea2edc Server (streams 0))
[2023-06-01T05:44:39Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/dcutr
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:39Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:39Z DEBUG yamux::connection] 91ea2edc: new outbound (Stream 91ea2edc/4) of (Connection 91ea2edc Server (streams 2))
[2023-06-01T05:44:39Z INFO  client] Sent { peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }
[2023-06-01T05:44:39Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:39Z DEBUG yamux::connection] 91ea2edc: new outbound (Stream 91ea2edc/6) of (Connection 91ea2edc Server (streams 3))
[2023-06-01T05:44:39Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:39Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/dcutr
[2023-06-01T05:44:39Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2023-06-01T05:44:39Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2023-06-01T05:44:39Z INFO  client] Received { 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.43.0", listen_addrs: ["/ip4/192.168.122.1/tcp/35869", "/ip4/172.22.0.1/tcp/35869", "/ip4/192.168.251.1/tcp/35869", "/ip4/192.168.80.1/tcp/35869", "/ip4/10.30.6.88/tcp/35869", "/ip4/172.18.0.1/tcp/35869", "/ip4/127.0.0.1/tcp/35869", "/ip4/172.17.0.1/tcp/35869", "/ip4/172.27.0.1/tcp/35869", "/ip4/172.31.0.1/tcp/35869", "/ip4/172.26.0.1/tcp/35869", "/ip4/192.168.176.1/tcp/35869", "/ip4/10.30.99.1/tcp/35869", "/ip4/172.28.0.1/tcp/35869", "/ip4/172.19.0.1/tcp/35869", "/ip4/192.168.1.129/tcp/35869", "/ip4/172.21.0.1/tcp/35869", "/ip4/172.25.0.1/tcp/35869", "/ip4/192.168.128.1/tcp/35869", "/ip4/192.168.96.1/tcp/35869", "/ip4/172.16.2.1/tcp/35869", "/ip4/172.16.67.1/tcp/35869", "/ip4/172.24.0.1/tcp/35869", "/ip4/192.168.250.1/tcp/35869", "/ip4/192.168.252.1/tcp/35869", "/ip4/192.168.144.1/tcp/35869", "/ip4/172.29.0.1/tcp/35869"], protocols: [StreamProtocol { inner: Right("/ipfs/id/1.0.0") }, StreamProtocol { inner: Right("/libp2p/dcutr") }, StreamProtocol { inner: Right("/ipfs/id/push/1.0.0") }, StreamProtocol { inner: Right("/ipfs/ping/1.0.0") }], observed_addr: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X" } }
[2023-06-01T05:44:39Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 119ms
[2023-06-01T05:44:49Z INFO  client] DirectConnectionUpgradeFailed { remote_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), error: Handler(Timeout) }
[2023-06-01T05:44:49Z DEBUG libp2p_swarm] Connection closed with error KeepAliveTimeout: Connected { endpoint: Listener { local_addr: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }, peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }; Total (peer): 0.
[2023-06-01T05:44:54Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 124ms
[2023-06-01T05:45:10Z DEBUG libp2p_ping::handler] latency to 12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN is 119ms

@gongzhengyang
Copy link
Author

gongzhengyang commented Jun 1, 2023

图片
if added some code at here, then the dialing client logs will changed into

--------------------hole punch received: [8, 100]
[2023-06-01T06:19:00Z DEBUG libp2p_swarm] Connection closed with error Handler(Right(Left(Apply(Left(NoAddresses))))): Connected { endpoint: Dialer { address: "/ip4/114.132.71.142/tcp/4002/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", role_override: Dialer }, peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }; Total (peer): 0.

according to the code in protocols/dcutr/src/protocol/inbound.rs
图片
and the code in protocols/dcutr/src/generated/holepunch/pb.rs
图片
I guess maybe the relay server should return some bytes like [.....,18, ......], a lot of bytes, rather than [8, 100]

@thomaseizinger
Copy link
Contributor

These code lines are generated from the protobuf definition (hence they are in the generated/ directory).

I did recently test the hole punching setup for QUIC and it worked (albeit not on the first try but hole punches aren't guaranteed to succeed).

Can you confirm that your relay is always running? Can you try to restart the dialer and listener example several times but leave the relay running?

@gongzhengyang
Copy link
Author

gongzhengyang commented Jun 20, 2023

Thanks for help. I tried to leave the relay running, and restart the listener and dialer for above ten times, but every time the error info is the same. I also tried to use root privilege.
Maybe is the dialer has some error

relay log

[2023-06-20T02:24:02Z DEBUG libp2p_ping::handler] latency to 12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3 is 155ms
[2023-06-20T02:24:02Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/circuit/relay/0.2.0/hop
[2023-06-20T02:24:02Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/circuit/relay/0.2.0/hop
BehaviourEvent: Event { peer: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), connection: ConnectionId(20), result: Ok(155.846101ms) }
[2023-06-20T02:24:02Z DEBUG yamux::connection] 5c181255: new outbound (Stream 5c181255/8) of (Connection 5c181255 Server (streams 2))
[2023-06-20T02:24:02Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/stop
[2023-06-20T02:24:02Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/stop
BehaviourEvent: CircuitReqAccepted { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }
[2023-06-20T02:24:06Z DEBUG yamux::connection::stream] 5c181255/8: eof
[2023-06-20T02:24:06Z DEBUG libp2p_ping::handler] latency to 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X is 123ms
BehaviourEvent: Event { peer: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), connection: ConnectionId(18), result: Ok(123.392937ms) }
[2023-06-20T02:24:07Z DEBUG yamux::connection::stream] 740f9fa9/5: eof
[2023-06-20T02:24:07Z DEBUG yamux::connection::stream] 5c181255/8: eof
BehaviourEvent: CircuitClosed { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), error: None }
[2023-06-20T02:24:14Z DEBUG yamux::connection] 740f9fa9: socket eof
[2023-06-20T02:24:14Z DEBUG libp2p_swarm] Connection closed with error IO(Custom { kind: Other, error: Error(Closed) }): Connected { endpoint: Listener { local_addr: "/ip4/10.0.8.14/tcp/4001", send_back_addr: "/ip4/115.220.250.9/tcp/12716" }, peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }; Total (peer): 0.

dialer log

[2023-06-20T02:21:32Z DEBUG libp2p_dns] Dial error: Transport(Left(Left(Left(Right(Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }))))).
[2023-06-20T02:21:32Z DEBUG libp2p_swarm] Connection attempt to PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") failed with Transport([("/ip4/115.220.250.9/tcp/20332/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", Other(Custom { kind: Other, error: Transport(Left(Left(Left(Right(Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }))))) }))]).
[2023-06-20T02:21:32Z INFO  dcutr] Outgoing connection error to Some(PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")): Transport([("/ip4/115.220.250.9/tcp/20332/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", Other(Custom { kind: Other, error: Transport(Left(Left(Left(Right(Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }))))) }))])

listener log

[2023-06-20T02:24:04Z DEBUG libp2p_swarm] Connection closed with error KeepAliveTimeout: Connected { endpoint: Listener { local_addr: "/ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit", send_back_addr: "/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3" }, peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") }; Total (peer): 0.
[2023-06-20T02:24:04Z DEBUG libp2p_dns] Dialing /ip4/115.220.250.9/tcp/12716/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3
[2023-06-20T02:24:04Z DEBUG libp2p_tcp] dialing 115.220.250.9:12716
[2023-06-20T02:24:04Z DEBUG libp2p_dns] Dial error: Transport(Left(Left(Left(Right(Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }))))).
[2023-06-20T02:24:04Z DEBUG libp2p_swarm] Connection attempt to PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3") failed with Transport([("/ip4/115.220.250.9/tcp/12716/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3", Other(Custom { kind: Other, error: Transport(Left(Left(Left(Right(Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }))))) }))]).
[2023-06-20T02:24:04Z INFO  dcutr] Outgoing connection error to Some(PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3")): Transport([("/ip4/115.220.250.9/tcp/12716/p2p/12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3", Other(Custom { kind: Other, error: Transport(Left(Left(Left(Right(Os { code: 111, kind: ConnectionRefused, message: "Connection refused" }))))) }))])

@thomaseizinger
Copy link
Contributor

What commands are you using to run the dialer and listener?

@gongzhengyang
Copy link
Author

relay at 114.132.71.142

sudo RUST_LOG=debug ./relay-server-example --secret-key-seed 0 --port 4001

listener

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

dialer

 RUST_LOG=debug ./dcutr --secret-key-seed 2 --mode dial --relay-address /ip4/114.132.71.142/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN --remote-peer-id 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X

@gongzhengyang
Copy link
Author

listener/dialer build from rust-libp2p/examples/dcutr/, relay build from rust-libp2p/examples/relay-server/

@mxinden
Copy link
Member

mxinden commented Jun 20, 2023

Drive-by suggestion, are you testing with #4052 @gongzhengyang?

@thomaseizinger
Copy link
Contributor

Dialer and listener are running on different machines, yes?

@gongzhengyang
Copy link
Author

gongzhengyang commented Jun 21, 2023

Drive-by suggestion, are you testing with #4052 @gongzhengyang?

yeah, I always pull the latest master branch, recompile again and test the code, I hope maybe something changed could fix my problem. Yesterday I use the master branch with git commit 8776fa8.

@gongzhengyang
Copy link
Author

Dialer and listener are running on different machines, yes?

I tried dialer and listener always on different machines, both in a same network behind nat and in different network.

@thomaseizinger
Copy link
Contributor

Dialer and listener are running on different machines, yes?

I tried dialer and listener always on different machines, both in a same network behind nat and in different network.

That is rather odd. I am working on automated tests for hole punching at the moment so we can hopefully resolve this soon.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants