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

Hole-punching tutorial appears to trigger panic in listening client, preventing completion #2621

Closed
Foemass opened this issue Apr 26, 2022 · 18 comments

Comments

@Foemass
Copy link

Foemass commented Apr 26, 2022

Summary

Hello, I'm new to your wonderful library, apologies if I've made some rookie mistake. I'm encountering a frustrating issue with the hole-punching tutorial here wherein the listening client panics with the following message:

thread 'main' panicked at 'ListenerClosed { listener_id: ListenerId(2), addresses: [], reason: Ok(()) }', protocols/dcutr/examples/client.rs:217:26

To the best of my knowledge I've followed the tutorial word for word, with an exception of completing the address used for libp2p-lookup.

I've compiled both the "client" and "relay_v2" with:

rustc 1.60.0 (7737e0b5c 2022-04-04)
on Linux Mint 20.3 Una (base: Ubuntu 20.04 focal)

and deployed relay_v2 to this kind of AWS Lightsail virtual server:

Ubuntu 20.04 LTS
512 MB RAM, 1 vCPU, 20 GB SSD
London, Zone A (eu-west-2a)

And opened the following in the AWS firewall:

ICMP 8 0
TCP 4001

So that the suggested ping, telnet, libp2p-lookup tests can complete. (And I've checked them, they all complete successfully).

Skimming through the github issues it's evident other people are getting further in the tutorial, so I'm hoping somebody can help me figure out what's different in my case .

Expected behavior

Presumably the listening client should continue to run instead of panicking.

Actual behavior

The listening client panics with the aforementioned message. Full logs for both "client" and "relay_v2" follow:

RUST_LOG=info ./relay_v2 --port 4001 --secret-key-seed 0

Debug Output

opt: Opt { use_ipv6: None, secret_key_seed: 0, port: 4001 }
Local peer id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN")
Listening on "/ip4/127.0.0.1/tcp/4001"
Listening on "/ip4/172.26.3.110/tcp/4001"
ReservationReqAccepted { src_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), renewed: false }

RUST_LOG=info RUST_BACKTRACE=full ./client --secret-key-seed 1 --mode listen --relay-address /ip4/[relay ip removed by me only here on github]/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN

Debug Output

[2022-04-26T11:11:32Z INFO  client] Local peer id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
[2022-04-26T11:11:32Z INFO  client] Listening on "/ip4/127.0.0.1/tcp/40855"
[2022-04-26T11:11:32Z INFO  client] Listening on "/ip4/192.168.1.21/tcp/40855"
thread 'main' panicked at 'ListenerClosed { listener_id: ListenerId(2), addresses: [], reason: Ok(()) }', protocols/dcutr/examples/client.rs:217:26
stack backtrace:
   0:     0x5611173af79d - std::backtrace_rs::backtrace::libunwind::trace::hee598835bc88d35b
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x5611173af79d - std::backtrace_rs::backtrace::trace_unsynchronized::h9cdc730ba5cf5d72
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x5611173af79d - std::sys_common::backtrace::_print_fmt::h75aeaf7ed30e43fa
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5
   3:     0x5611173af79d - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h606862f787600875
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22
   4:     0x5611173cfb4c - core::fmt::write::he803f0f418caf762
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17
   5:     0x5611173a8e38 - std::io::Write::write_fmt::h70bc45872f37e7bb
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15
   6:     0x5611173b1c77 - std::sys_common::backtrace::_print::h64d038cf8ac3e13e
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5
   7:     0x5611173b1c77 - std::sys_common::backtrace::print::h359300b4a7fccf65
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9
   8:     0x5611173b1c77 - std::panicking::default_hook::{{closure}}::hf51be35e2f510149
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22
   9:     0x5611173b1940 - std::panicking::default_hook::h03ca0f22e1d2d25e
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9
  10:     0x5611173b23c9 - std::panicking::rust_panic_with_hook::h3b7380e99b825b63
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17
  11:     0x5611173b20b7 - std::panicking::begin_panic_handler::{{closure}}::h8e849d0710154ce0
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13
  12:     0x5611173afc64 - std::sys_common::backtrace::__rust_end_short_backtrace::hedcdaddbd4c46cc5
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18
  13:     0x5611173b1dc9 - rust_begin_unwind
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5
  14:     0x5611167acbd3 - core::panicking::panic_fmt::he1bbc7336d49a357
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14
  15:     0x561116818ec7 - client::main::{{closure}}::hedaaaebe5fc581f6
                               at /home/user/IdeaProjects/rust-libp2p-0.44.0/protocols/dcutr/examples/client.rs:217:26
  16:     0x56111693137b - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h2f80e8bbae70e903
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/future/mod.rs:84:19
  17:     0x5611167b13d3 - futures_executor::local_pool::block_on::{{closure}}::h08ad678015348e06
                               at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.21/src/local_pool.rs:315:23
  18:     0x5611167b0de3 - futures_executor::local_pool::run_executor::{{closure}}::haa21ff67dac7cc5b
                               at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.21/src/local_pool.rs:90:37
  19:     0x56111681f8e1 - std::thread::local::LocalKey<T>::try_with::h467f9ae3dee277d2
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:413:16
  20:     0x56111681f5a3 - std::thread::local::LocalKey<T>::with::h3b780bacb38f875e
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/thread/local.rs:389:9
  21:     0x5611167b0bfd - futures_executor::local_pool::run_executor::hc4dc37b6662f625d
                               at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.21/src/local_pool.rs:86:5
  22:     0x5611167b129a - futures_executor::local_pool::block_on::h91c66026be49affb
                               at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-executor-0.3.21/src/local_pool.rs:315:5
  23:     0x5611168e3c8b - client::main::h30c5dcad6cb56c4f
                               at /home/user/IdeaProjects/rust-libp2p-0.44.0/protocols/dcutr/examples/client.rs:201:5
  24:     0x56111696bb5b - core::ops::function::FnOnce::call_once::hd3072571bb273c2d
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:227:5
  25:     0x5611168349ae - std::sys_common::backtrace::__rust_begin_short_backtrace::h1b926b1b239e1fbc
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:122:18
  26:     0x561116925dd1 - std::rt::lang_start::{{closure}}::h13b08e8db7eff325
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:145:18
  27:     0x5611173aee81 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::hb7014f43484a8b4e
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:259:13
  28:     0x5611173aee81 - std::panicking::try::do_call::h7bc9dc436daeb8c7
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40
  29:     0x5611173aee81 - std::panicking::try::h653d68a27ff5f175
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19
  30:     0x5611173aee81 - std::panic::catch_unwind::h9d739f9f59895e68
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14
  31:     0x5611173aee81 - std::rt::lang_start_internal::{{closure}}::hf006f2bc7ce22bbe
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:48
  32:     0x5611173aee81 - std::panicking::try::do_call::hfb39d6df61a2e69f
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40
  33:     0x5611173aee81 - std::panicking::try::h13e2d225134958ac
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19
  34:     0x5611173aee81 - std::panic::catch_unwind::h3bd49b5a5dfb1a50
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14
  35:     0x5611173aee81 - std::rt::lang_start_internal::h2ba92edce36c035e
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:20
  36:     0x561116925da0 - std::rt::lang_start::hcfeca0efa51552de
                               at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:144:17
  37:     0x5611168e68ec - main
  38:     0x7fe6b23d60b3 - __libc_start_main
  39:     0x5611167ade9e - _start
  40:                0x0 - <unknown>

Version

  • I'm using unaltered rust-libp2p-0.44.0 source downloaded from here

Would you like to work on fixing this bug?

Maybe. (Assuming there actually is a bug and this isn't all some rookie mistake on my part I'm completely willing to assist in anyway I can, but I haven't got nearly enough experience in Rust or libp2p to take point on the matter.)

@Foemass Foemass changed the title Hole-punching tutorial appears trigger panic in listening client, preventing completion Hole-punching tutorial appears to trigger panic in listening client, preventing completion Apr 26, 2022
@Foemass
Copy link
Author

Foemass commented Apr 30, 2022

In retrospect, I did a pretty bad job at skimming through the existing github issues, as my issue is clearly just a duplicate of this pre-existing issue here: #2601.

At least its not just me. I'll have another poke around this weekend, though I can't imagine I'm going to uncover anything more productive then the information already in that issue.

@Foemass
Copy link
Author

Foemass commented May 2, 2022

Out of curiosity I recompiled the rust-libp2p-0.44.0 examples using both:
1.59.0-x86_64-unknown-linux-gnu and 1.58.1-x86_64-unknown-linux-gnu
both had the exact same issue I was having with the latest stable rustc (1.60.0)

I even tried compiling the older rust-libp2p-0.43.0 examples with 1.58.1-x86_64-unknown-linux-gnu, but they still result in the same panic. The tutorial must have worked back when it was posted (when 1.58.1 was the latest stable) so I'm guessing the rogue element here is... the OS? I notice mathiversen over in the other issue is, like me, using both Ubuntu for the Server and Listener.

Sorry to bother you @mxinden, but could you let me know what OS these examples were originally tested on? (If you know that is.)

If its just a matter of me having a different OS on my relay then maybe I can use that and keep on learning libp2p despite this issue.

@mxinden
Copy link
Member

mxinden commented May 3, 2022

Sorry, late reply here. Thanks @Foemass for the detailed report!

I am running with 1.59.0 on stable-x86_64-unknown-linux-gnu. My intuition tells me that this a rust-libp2p issue and not a Rust issue.

Would you mind running once more with the change below to understand which listener is failing?

modified   protocols/dcutr/examples/client.rs
@@ -172,8 +172,8 @@ fn main() -> Result<(), Box<dyn Error>> {
             futures::select! {
                 event = swarm.next() => {
                     match event.unwrap() {
-                        SwarmEvent::NewListenAddr { address, .. } => {
-                            info!("Listening on {:?}", address);
+                        SwarmEvent::NewListenAddr { address, listener_id } => {
+                            info!("Listening on {:?}, listener ID {:?}.", address, listener_id);
                         }
                         event => panic!("{:?}", event),
                     }

In case you ignore the listener closing event, what is the behavior of the code after that?

modified   protocols/dcutr/examples/client.rs
@@ -214,6 +214,7 @@ fn main() -> Result<(), Box<dyn Error>> {
                     info!("Observed address: {:?}", observed_addr);
                     break;
                 }
+                e @ SwarmEvent::ListenerClosed { .. } => info!("{:?}", e),
                 event => panic!("{:?}", event),
             }
         }

Do you see the same behavior when running in a different environment, e.g. your laptop?

@mxinden
Copy link
Member

mxinden commented May 3, 2022

Start client 1 in listening mode -> "Observed address" (Now it works)

Seems like @mathiversen has fixed this particular issue on their side. Mind sharing what the problem was?

@Foemass
Copy link
Author

Foemass commented May 3, 2022

Hi, thanks for the help!

I've run it with both your code edits, here's the client log:

RUST_LOG=info ./client --secret-key-seed 2 --mode dial --relay-address /ip4/18.135.28.182/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN --remote-peer-id 12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X

Debug Output
[2022-05-03T22:09:24Z INFO  client] Local peer id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3")
[2022-05-03T22:09:24Z INFO  client] Listening on "/ip4/127.0.0.1/tcp/35425", listener ID ListenerId(1).
[2022-05-03T22:09:24Z INFO  client] Listening on "/ip4/192.168.1.21/tcp/35425", listener ID ListenerId(1).
[2022-05-03T22:09:26Z INFO  client] Observed address: "/ip4/86.163.210.52/tcp/35425"
[2022-05-03T22:09:26Z INFO  client] OutboundCircuitReqFailed { relay_peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), error: Upgrade(Apply(NoReservation)) }
[2022-05-03T22:09:26Z INFO  client] Outgoing connection error to Some(PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")): Transport([("/ip4/18.135.28.182/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", Other(Custom { kind: Other, error: A(A(A(Connect))) }))])

And here's another run of the same code with a "debug" log:

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

Debug Output
[2022-05-03T22:31:12Z INFO  client] Local peer id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3")
[2022-05-03T22:31:12Z DEBUG libp2p_tcp] listening on 0.0.0.0:0
[2022-05-03T22:31:12Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG libp2p_tcp] New listen address: /ip4/127.0.0.1/tcp/41811
[2022-05-03T22:31:12Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/127.0.0.1/tcp/41811"
[2022-05-03T22:31:12Z INFO  client] Listening on "/ip4/127.0.0.1/tcp/41811", listener ID ListenerId(1).
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG libp2p_tcp] New listen address: /ip4/192.168.1.21/tcp/41811
[2022-05-03T22:31:12Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/192.168.1.21/tcp/41811"
[2022-05-03T22:31:12Z INFO  client] Listening on "/ip4/192.168.1.21/tcp/41811", listener ID ListenerId(1).
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:12Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:12Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:13Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:13Z DEBUG libp2p_dns] Dialing /ip4/18.170.79.157/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2022-05-03T22:31:13Z DEBUG libp2p_tcp] dialing 18.170.79.157:4001
[2022-05-03T22:31:13Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2022-05-03T22:31:13Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /noise
[2022-05-03T22:31:13Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-03T22:31:13Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2022-05-03T22:31:13Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /yamux/1.0.0
[2022-05-03T22:31:13Z DEBUG yamux::connection] new connection: c4622268 (Client)
[2022-05-03T22:31:13Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:13Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:13Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") Dialer { address: "/ip4/18.170.79.157/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }; Total (peer): 1. Total non-banned (peer): 1
[2022-05-03T22:31:13Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:13Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:13Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:13Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:13Z DEBUG libp2p_ping::protocol] Waiting for ping ...
[2022-05-03T22:31:13Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:13Z DEBUG yamux::connection] c4622268: new outbound (Stream c4622268/1) of (Connection c4622268 Client (streams 1))
[2022-05-03T22:31:13Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2022-05-03T22:31:14Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2022-05-03T22:31:14Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-03T22:31:14Z DEBUG libp2p_ping::protocol] Sending pong for [47, 86, 118, 155, 218, 96, 236, 110, 9, 170, 96, 172, 73, 252, 104, 197, 220, 175, 81, 220, 148, 242, 158, 154, 94, 181, 28, 132, 254, 83, 125, 121]
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG libp2p_ping::protocol] Waiting for ping ...
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG libp2p_ping::protocol] Preparing ping payload [103, 236, 72, 192, 234, 170, 8, 112, 7, 238, 160, 169, 144, 204, 208, 186, 252, 241, 164, 209, 13, 46, 55, 141, 151, 231, 72, 186, 207, 145, 23, 48]
[2022-05-03T22:31:14Z DEBUG libp2p_ping::protocol] Awaiting pong for [103, 236, 72, 192, 234, 170, 8, 112, 7, 238, 160, 169, 144, 204, 208, 186, 252, 241, 164, 209, 13, 46, 55, 141, 151, 231, 72, 186, 207, 145, 23, 48]
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG yamux::connection] c4622268: new outbound (Stream c4622268/3) of (Connection c4622268 Client (streams 2))
[2022-05-03T22:31:14Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/id/1.0.0
[2022-05-03T22:31:14Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/id/1.0.0
[2022-05-03T22:31:14Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/id/1.0.0
[2022-05-03T22:31:14Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-03T22:31:14Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/id/1.0.0
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z INFO  client] Observed address: "/ip4/86.163.210.52/tcp/41811"
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG yamux::connection] c4622268: new outbound (Stream c4622268/5) of (Connection c4622268 Client (streams 2))
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-03T22:31:14Z DEBUG libp2p_core::upgrade::apply] Failed to apply negotiated protocol
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z INFO  client] OutboundCircuitReqFailed { relay_peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), error: Upgrade(Apply(NoReservation)) }
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG libp2p_swarm] Connection attempt to PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") failed with Transport([("/ip4/18.170.79.157/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", Other(Custom { kind: Other, error: A(A(A(Connect))) }))]).
[2022-05-03T22:31:14Z INFO  client] Outgoing connection error to Some(PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")): Transport([("/ip4/18.170.79.157/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN/p2p-circuit/p2p/12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X", Other(Custom { kind: Other, error: A(A(A(Connect))) }))])
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:14Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:14Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 0, port: 0 })
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 0, port: 0 })
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 0, port: 0 })
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:19Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:19Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:23Z DEBUG yamux::connection] c4622268: socket eof
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:23Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:23Z DEBUG libp2p_swarm] Connection closed with error IO(Custom { kind: Other, error: Closed }): Connected { endpoint: Dialer { address: "/ip4/18.170.79.157/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }, peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") }; Total (peer): 0.
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:23Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:23Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 0, port: 0 })
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 0, port: 0 })
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 0, port: 0 })
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] sending messages
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-03T22:31:52Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] handling requests
[2022-05-03T22:31:52Z DEBUG netlink_proto::connection] sending messages

And here's the relay log (no code edits since last time):

./relay_v2 --port 4001 --secret-key-seed 0

Debug Output
opt: Opt { use_ipv6: None, secret_key_seed: 0, port: 4001 }
Local peer id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN")
Listening on "/ip4/127.0.0.1/tcp/4001"
Listening on "/ip4/172.26.3.110/tcp/4001"
CircuitReqDenied { src_peer_id: PeerId("12D3KooWH3uVF6wv47WnArKHk5p6cvgCJEb74UTmxztmQDc298L3"), dst_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }

My laptop is nearly identical in terms of environment, but I'll try the client on it tomorrow and get back to you. I might also be able to try the client on a windows install at some point to see if that makes a difference.

@Foemass
Copy link
Author

Foemass commented May 7, 2022

Sorry for the delay, I had a crazy busy workweek. I've now compiled and run the client in a bunch of different environments, with some curious results.

Device OS Connection Result
Laptop Linux Mint 20.3 Una WiFi connection which indirectly leads to router/gateway thread 'main' panicked at 'ListenerClosed
Laptop Linux Mint 20.3 Una Direct Ethernet cable connection to router/gateway thread 'main' panicked at 'ListenerClosed
PC Linux Mint 20.3 Una My normal labyrinthine arrangement of Ethernet cables and switches thread 'main' panicked at 'ListenerClosed
PC Linux Mint 20.3 Una WiFi connection direct to router/gateway thread 'main' panicked at 'ListenerClosed
PC Windows 10 My normal labyrinthine arrangement of Ethernet cables and switches thread 'main' panicked at 'ListenerClosed
PC Linux Mint 20.3 Una WiFi connection to iPhone hotspot (Mobile 4G) ENTIRE EXAMPLE WORKED PERFECTLY

It should be noted that, (just like mathiversen observed,) only the listener is touchy about connecting, the dialer should connect fine in any of the above scenarios.

I'm not really sure what to make of the listener working fine through an iPhone hotspot, because I have no idea how strict the firewall is on an iOS mobile hotspot. But I suppose this could be an indicator that my generic un-configured ISP-provided router is somehow too strict for NAT punch-through?

any thoughts @mxinden?

@mxinden
Copy link
Member

mxinden commented May 11, 2022

Thanks for providing all the details above @Foemass!

I think the relevant log line is the below from the dialing client:

[2022-05-03T22:31:14Z INFO  client] OutboundCircuitReqFailed { relay_peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), error: Upgrade(Apply(NoReservation)) }

In other words, the relay tells the dialing client that it has not (yet) received a reservation request from the listening client.

Just to double check, does the listening client print ReservationReqAccepted before you start the dialing client?

mxinden added a commit to mxinden/rust-libp2p that referenced this issue May 11, 2022
When in listening mode, wait for the relay to accept our reservation
request. Only then can a client in dialing mode establish a relayed
connection to us via the relay.

See also
libp2p#2621 (comment)
@mxinden
Copy link
Member

mxinden commented May 11, 2022

See #2642 which helps to see whether the relay accepted our reservation request.

@Foemass
Copy link
Author

Foemass commented May 11, 2022

Thanks for that mxinden,

Sorry I only just realized I must have had some kind of brain fart 8 days ago. My brain thought I was running/logging the listening client, but apparently I copy and pasted the line for the dialing client instead and never ran the listener that night, facepalm well that's late night debugging for you.

I've now actually run the listening client with your previous changes from 9 days ago (not the more recent ones directly above) and it doesn't print "ReservationReqAccepted". Here's the logs I -should- have posted 8 days ago.

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

Debug Output
[2022-05-11T21:48:42Z INFO  client] Local peer id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
[2022-05-11T21:48:42Z INFO  client] Listening on "/ip4/127.0.0.1/tcp/37581", listener ID ListenerId(1).
[2022-05-11T21:48:42Z INFO  client] Listening on "/ip4/192.168.1.21/tcp/37581", listener ID ListenerId(1).
[2022-05-11T21:48:43Z INFO  client] ListenerClosed { listener_id: ListenerId(2), addresses: [], reason: Ok(()) }
thread 'main' panicked at 'ConnectionClosed { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), endpoint: Dialer { address: "/ip4/3.10.152.248/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }, num_established: 0, cause: Some(Handler(A(A(A(Left(Upgrade(Apply(B(NoAddressesInReservation))))))))) }', protocols/dcutr/examples/client.rs:219:26
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

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

Debug Output
[2022-05-11T21:51:25Z INFO  client] Local peer id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
[2022-05-11T21:51:25Z DEBUG libp2p_tcp] listening on 0.0.0.0:0
[2022-05-11T21:51:25Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG libp2p_tcp] New listen address: /ip4/127.0.0.1/tcp/37033
[2022-05-11T21:51:25Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/127.0.0.1/tcp/37033"
[2022-05-11T21:51:25Z INFO  client] Listening on "/ip4/127.0.0.1/tcp/37033", listener ID ListenerId(1).
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG libp2p_tcp] New listen address: /ip4/192.168.1.21/tcp/37033
[2022-05-11T21:51:25Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/192.168.1.21/tcp/37033"
[2022-05-11T21:51:25Z INFO  client] Listening on "/ip4/192.168.1.21/tcp/37033", listener ID ListenerId(1).
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:25Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:25Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:26Z DEBUG libp2p_dns] Dialing /ip4/3.10.152.248/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:26Z DEBUG libp2p_tcp] dialing 3.10.152.248:4001
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:26Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2022-05-11T21:51:26Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /noise
[2022-05-11T21:51:26Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-11T21:51:26Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2022-05-11T21:51:26Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /yamux/1.0.0
[2022-05-11T21:51:26Z DEBUG yamux::connection] new connection: 1ba81f62 (Client)
[2022-05-11T21:51:26Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:26Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") Dialer { address: "/ip4/3.10.152.248/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }; Total (peer): 1. Total non-banned (peer): 1
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:26Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:26Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2022-05-11T21:51:26Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:26Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2022-05-11T21:51:26Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-11T21:51:26Z DEBUG libp2p_ping::protocol] Waiting for ping ...
[2022-05-11T21:51:26Z DEBUG yamux::connection] 1ba81f62: new outbound (Stream 1ba81f62/1) of (Connection 1ba81f62 Client (streams 1))
[2022-05-11T21:51:26Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2022-05-11T21:51:26Z DEBUG yamux::connection] 1ba81f62: new outbound (Stream 1ba81f62/3) of (Connection 1ba81f62 Client (streams 2))
[2022-05-11T21:51:26Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-11T21:51:27Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2022-05-11T21:51:27Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-11T21:51:27Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-11T21:51:27Z DEBUG libp2p_ping::protocol] Sending pong for [220, 143, 6, 79, 84, 71, 36, 161, 46, 199, 45, 162, 18, 108, 94, 229, 93, 141, 202, 198, 58, 99, 215, 62, 114, 14, 4, 20, 128, 0, 78, 114]
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:27Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:27Z DEBUG libp2p_ping::protocol] Waiting for ping ...
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:27Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:27Z DEBUG libp2p_ping::protocol] Preparing ping payload [85, 89, 50, 71, 158, 207, 93, 41, 202, 166, 59, 89, 204, 147, 118, 232, 173, 101, 200, 95, 230, 158, 201, 140, 51, 145, 177, 2, 192, 136, 226, 152]
[2022-05-11T21:51:27Z DEBUG libp2p_ping::protocol] Awaiting pong for [85, 89, 50, 71, 158, 207, 93, 41, 202, 166, 59, 89, 204, 147, 118, 232, 173, 101, 200, 95, 230, 158, 201, 140, 51, 145, 177, 2, 192, 136, 226, 152]
[2022-05-11T21:51:27Z DEBUG libp2p_core::upgrade::apply] Failed to apply negotiated protocol
[2022-05-11T21:51:27Z DEBUG libp2p_swarm] Listener ListenerId(2); Closed by Ok(()).
[2022-05-11T21:51:27Z INFO  client] ListenerClosed { listener_id: ListenerId(2), addresses: [], reason: Ok(()) }
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-11T21:51:27Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] handling requests
[2022-05-11T21:51:27Z DEBUG netlink_proto::connection] sending messages
[2022-05-11T21:51:27Z DEBUG libp2p_swarm] Connection closed with error Handler(A(A(A(Left(Upgrade(Apply(B(NoAddressesInReservation)))))))): Connected { endpoint: Dialer { address: "/ip4/3.10.152.248/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }, peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") }; Total (peer): 0.
thread 'main' panicked at 'ConnectionClosed { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), endpoint: Dialer { address: "/ip4/3.10.152.248/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }, num_established: 0, cause: Some(Handler(A(A(A(Left(Upgrade(Apply(B(NoAddressesInReservation))))))))) }', protocols/dcutr/examples/client.rs:219:26
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Regarding my latest layman theory of "my router is somehow too strict for NAT punch-through" I managed to successfully do NAT punch/passthrough on my network earlier today with a C# library, so that can't be the case.

Anyway, i'll give your new pull request a go sometime this week and get back to you. It's late over here so i'm going to have another brain fart if I try it now.

@Foemass
Copy link
Author

Foemass commented May 15, 2022

Hi @mxinden

I pulled the master branch and (after dealing with the new cmake requirement) added your altered client.rs (protocols/dcutr/examples/client.rs)

In most circumstances your changes don’t seem to make much difference. See the resulting logs below. (Since it was a new pull I haven’t included your changes from #2621 (comment), so you might find the logs at #2621 (comment) more useful)

Client (Listener):

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

Debug Output
[2022-05-15T22:08:37Z INFO  client] Local peer id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
[2022-05-15T22:08:37Z DEBUG libp2p_tcp] listening on 0.0.0.0:0
[2022-05-15T22:08:37Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG libp2p_tcp] New listen address: /ip4/127.0.0.1/tcp/46167
[2022-05-15T22:08:37Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/127.0.0.1/tcp/46167"
[2022-05-15T22:08:37Z INFO  client] Listening on "/ip4/127.0.0.1/tcp/46167"
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG libp2p_tcp] New listen address: /ip4/192.168.1.21/tcp/46167
[2022-05-15T22:08:37Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/192.168.1.21/tcp/46167"
[2022-05-15T22:08:37Z INFO  client] Listening on "/ip4/192.168.1.21/tcp/46167"
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:37Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:37Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG libp2p_dns] Dialing /ip4/35.178.83.160/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG libp2p_tcp] dialing 35.178.83.160:4001
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /noise
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /noise
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /yamux/1.0.0
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /yamux/1.0.0
[2022-05-15T22:08:38Z DEBUG yamux::connection] new connection: 484d0ad7 (Client)
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN") Dialer { address: "/ip4/35.178.83.160/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }; Total (peer): 1. Total non-banned (peer): 1
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG yamux::connection] 484d0ad7: new outbound (Stream 484d0ad7/1) of (Connection 484d0ad7 Client (streams 1))
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-15T22:08:38Z DEBUG yamux::connection] 484d0ad7: new outbound (Stream 484d0ad7/3) of (Connection 484d0ad7 Client (streams 2))
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG libp2p_ping] Ping received from PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN")
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Failed to apply negotiated protocol
[2022-05-15T22:08:38Z DEBUG libp2p_swarm] Listener ListenerId(2); Closed by Ok(()).
thread 'main' panicked at 'ListenerClosed { listener_id: ListenerId(2), addresses: [], reason: Ok(()) }', protocols/dcutr/examples/client.rs:227:26
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Relay:

RUST_LOG=debug ./relay_v2 --port 4001 --secret-key-seed 0

Debug Output
opt: Opt { use_ipv6: None, secret_key_seed: 0, port: 4001 }
Local peer id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN")
[2022-05-15T22:07:29Z DEBUG libp2p_tcp] listening on 0.0.0.0:4001
[2022-05-15T22:07:29Z DEBUG netlink_proto::handle] handle: forwarding new request to connection
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 1, port: 0 })
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::protocol::protocol] done handling response to request RequestId { sequence_number: 1, port: 0 }
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG libp2p_tcp] New listen address: /ip4/127.0.0.1/tcp/4001
[2022-05-15T22:07:29Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/127.0.0.1/tcp/4001"
Listening on "/ip4/127.0.0.1/tcp/4001"
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG libp2p_tcp] New listen address: /ip4/172.26.3.110/tcp/4001
[2022-05-15T22:07:29Z DEBUG libp2p_swarm] Listener ListenerId(1); New address: "/ip4/172.26.3.110/tcp/4001"
Listening on "/ip4/172.26.3.110/tcp/4001"
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:07:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:07:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:29Z DEBUG netlink_proto::protocol::protocol] handling messages (request id = RequestId { sequence_number: 0, port: 0 })
[2022-05-15T22:08:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:29Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:29Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG libp2p_tcp] Incoming connection from /ip4/86.163.210.52/tcp/37176 at /ip4/172.26.3.110/tcp/4001
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /noise
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /noise
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /yamux/1.0.0
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /yamux/1.0.0
[2022-05-15T22:08:38Z DEBUG yamux::connection] new connection: 04ad4332 (Server)
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") Listener { local_addr: "/ip4/172.26.3.110/tcp/4001", send_back_addr: "/ip4/86.163.210.52/tcp/37176" }; Total (peer): 1. Total non-banned (peer): 1
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG yamux::connection] 04ad4332: new outbound (Stream 04ad4332/2) of (Connection 04ad4332 Server (streams 0))
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Proposed protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /libp2p/circuit/relay/0.2.0/hop
[2022-05-15T22:08:38Z DEBUG multistream_select::dialer_select] Dialer: Received confirmation for protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: confirming protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG multistream_select::listener_select] Listener: sent confirmed protocol: /ipfs/ping/1.0.0
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG libp2p_core::upgrade::apply] Successfully applied negotiated protocol
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
ReservationReqAccepted { src_peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X"), renewed: false }
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG libp2p_ping] Ping received from PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG libp2p_ping] Ping sent to PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X")
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages
[2022-05-15T22:08:38Z DEBUG yamux::connection] 04ad4332: socket eof
[2022-05-15T22:08:38Z DEBUG libp2p_swarm] Connection closed with error IO(Custom { kind: Other, error: Closed }): Connected { endpoint: Listener { local_addr: "/ip4/172.26.3.110/tcp/4001", send_back_addr: "/ip4/86.163.210.52/tcp/37176" }, peer_id: PeerId("12D3KooWPjceQrSwdWXPyLLeABRXmuqt69Rg3sBYbU1Nft9HyQ6X") }; Total (peer): 0.
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] reading incoming messages
[2022-05-15T22:08:38Z DEBUG netlink_proto::codecs] NetlinkCodec: decoding next message
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwarding unsolicited messages to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] forwaring responses to previous requests to the connection handle
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] handling requests
[2022-05-15T22:08:38Z DEBUG netlink_proto::connection] sending messages

The listener -doesn't- panic if I act fast and run the listener while the relay is only displaying its inital batch of logs. (So in the example above i'd need to run whilst only the logs marked with 2022-05-15T22:07:29Z were visible.) This weird timing trick also only works when using RUST_LOG=debug, without debug logging the listener still panics (nomatter how fast I connect). When I use this trick and the listener doesn't panic I can’t seem to connect to it with a dialling client and get no log saying the relay actually accepted the reservation request, so I've probably just discovered a different unrelated way to upset the relay.

Incidently I’m not having any luck using webrtc.rs to perform hole-punching either. Looks like fate (or more likely my own ignorance) is determined to force me back to .NET where hole punching, unaccountably, works on my network.

@mxinden
Copy link
Member

mxinden commented May 16, 2022

Thanks for the logs! Very helpful.

thread 'main' panicked at 'ConnectionClosed { peer_id: PeerId("12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN"), endpoint: Dialer { address: "/ip4/3.10.152.248/tcp/4001/p2p/12D3KooWDpJ7As7BWAwRMfu1VU2WCqNjvq387JEYKDBj4kx6nXTN", role_override: Dialer }, num_established: 0, cause: Some(Handler(A(A(A(Left(Upgrade(Apply(B(NoAddressesInReservation))))))))) }', protocols/dcutr/examples/client.rs:219:26

This is the relevant part. More specifically NoAddressesInReservation.

The Relay needs to return a set of addresses, via which the Relay is reachable, to the listening client. In case the Relay does not yet know under which addresses it is reachable, it will provide none. Providing none will make the listening client error:

if reservation.addrs.is_empty() {
return Err(FatalUpgradeError::NoAddressesInReservation.into());
}

The listening client announces itself as "listening for incoming connections via the relay". If it doesn't know the public addresses of the relay, it can not announce itself.

How to make sure the relay knows its public addresses:

  • Call Swarm::add_external_address explicitly in the relay/examples/relay_v2.rs code. You could pass in the public IP as a command line flag.
  • Use https://github.com/mxinden/rust-libp2p-server/ with --enable-kademlia and let it run for a bit before connecting. That way, other nodes within the IPFS Kademlia DHT will tell the Relay under which addresses they observe the relay.
  • Connect to the Relay e.g. via some other implementation that speaks the identify protocol, thus telling the relay of its addresses.

I will propose a patch similar to #2642 but on the relay side, to make this more prominent in the Relay logs, and likely to be able to pass the address as a flag.

@Foemass
Copy link
Author

Foemass commented May 16, 2022

Ah-ha! Well that makes perfect sense... now somebody has explained it to me ;). Thanks @mxinden, you've made my day.

This also explains mathiversen's observation in the other issue (that doing a failed dialing first causes everything to work.)

Given I should ideally run the AutoNAT protocol on my client first to see if using a relay is even necessary... Perhaps having the relay serve as the other end for that initial check could "hit two birds with one stone"? Would connecting to perform AutoNat first have the side effect of speaking the identify protocol and thus telling the relay its own address?

@mxinden
Copy link
Member

mxinden commented May 17, 2022

Thanks for bearing with us!

This also explains mathiversen's observation in the other issue (that doing a failed dialing first causes everything to work.)

Pinging @mathiversen directly, in case the above is helpful.

Would connecting to perform AutoNat first have the side effect of speaking the identify protocol and thus telling the relay its own address?

Yes, that would be a good option. Will see what I can do in the example code.

@mxinden
Copy link
Member

mxinden commented May 17, 2022

Also note #2651 discovered by @Pj50 which needs fixing before current master works again. (Only on master, not the latest release.)

mxinden added a commit that referenced this issue May 19, 2022
…#2642)

When in listening mode, wait for the relay to accept our reservation
request. Only then can a client in dialing mode establish a relayed
connection to us via the relay.

See also
#2621 (comment)
@Foemass
Copy link
Author

Foemass commented May 22, 2022

Thanks again for the help @mxinden, I've tested the latest client.rs with libp2p 0.44.0 and its working wonderfully.

Just thought I'd confirm it so you know I'm happy for this issue to be closed whenever, (be that now or when v0.45.0 is released.)

@mxinden
Copy link
Member

mxinden commented May 23, 2022

Thanks again for the help @mxinden, I've tested the latest client.rs with libp2p 0.44.0 and its working wonderfully.

This is great news. Thanks for following up @Foemass! Just for the sake of completeness, all issues on the various environments you tested in are resolved? 🎉

@Foemass
Copy link
Author

Foemass commented Jun 12, 2022

@mxinden, Sorry for the delay.

Yes I can confirm all my issues above are resolved, they all ultimately shared the same cause.

@mxinden
Copy link
Member

mxinden commented Jun 12, 2022

Great. Closing then. Happy to hear what you are building in case you want to share @Foemass.

@mxinden mxinden closed this as completed Jun 12, 2022
santos227 added a commit to santos227/rustlib that referenced this issue Jun 20, 2022
… (#2642)

When in listening mode, wait for the relay to accept our reservation
request. Only then can a client in dialing mode establish a relayed
connection to us via the relay.

See also
libp2p/rust-libp2p#2621 (comment)
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

2 participants