AutoNAT V1 panic: Peer is connected #5570
Description
Summary
CC: nimiq/core-rs-albatross#2853
Full logs can be found here.
Note in the logs that just before AutoNAT reads from the connected collection to expect a peer, some connections are closed while sending over the sink due to an error.
Expected behavior
Execute the resolve_inbound_request without panicking.
Actual behavior
Logs around panic:
2024-08-20T22:01:50.404033808Z DEBUG swarm | Incoming connection error connection_id=5462 address=/ip4/91.107.192.212/tcp/52236/ws listen_address=/ip4/167.235.24.195/tcp/8444/ws error=Listen error: Failed to negotiate transport protocol(s)
2024-08-20T22:01:50.404073577Z DEBUG swarm | Incoming connection error connection_id=5463 address=/ip4/91.107.192.212/tcp/52244/ws listen_address=/ip4/167.235.24.195/tcp/8444/ws error=Listen error: Failed to negotiate transport protocol(s)
2024-08-20T22:01:50.404182884Z DEBUG swarm | Incoming connection error connection_id=5452 address=/ip4/159.223.165.251/tcp/8444/ws listen_address=/ip4/167.235.24.195/tcp/8444/ws error=Listen error: Failed to negotiate transport protocol(s)
2024-08-20T22:01:50.404351809Z DEBUG behaviour | Already have connections established to this peer peer_id=12D3KooWBw9vWGDjbpcHNGqn7njrxxDngMqB2wNtrQuT4zYwBJk4 connections=1
2024-08-20T22:01:50.404414683Z DEBUG swarm | Connection established connection_id=5453 peer_id=12D3KooWBw9vWGDjbpcHNGqn7njrxxDngMqB2wNtrQuT4zYwBJk4 address=/ip4/116.203.140.114/tcp/47300/ws direction="inbound" connections=2 established_in=12.749368481s
2024-08-20T22:01:50.404462138Z DEBUG swarm | Incoming connection error connection_id=5454 address=/ip4/116.203.140.114/tcp/47302/ws listen_address=/ip4/167.235.24.195/tcp/8444/ws error=Listen error: Denied: connection denied
2024-08-20T22:01:50.416394549Z WARN queue | Rejecting block as it doesn't come from a synced peer block=#3037472:MI:0340a4051e peer_id=12D3KooWQprQcMnrei1pKf6DSGoH7DEu3nEnjCbCtBUGLiX1ULHd
2024-08-20T22:01:50.438049236Z WARN queue | Rejecting block as it doesn't come from a synced peer block=#3037473:MI:d445bbd14e peer_id=12D3KooWBw9vWGDjbpcHNGqn7njrxxDngMqB2wNtrQuT4zYwBJk4
2024-08-20T22:01:50.440867211Z WARN queue | Rejecting block as it doesn't come from a synced peer block=#3037474:MI:91b7097f27 peer_id=12D3KooWJdQRtkrqJdEKKxtYjRMQi4Cpo15mCgTsYuoNKKrF1V1g
2024-08-20T22:01:50.443801221Z WARN queue | Rejecting block as it doesn't come from a synced peer block=#3037475:MI:9fef18de2b peer_id=12D3KooWJdQRtkrqJdEKKxtYjRMQi4Cpo15mCgTsYuoNKKrF1V1g
2024-08-20T22:01:50.446478377Z WARN queue | Rejecting block as it doesn't come from a synced peer block=#3037476:MI:d82d533969 peer_id=12D3KooWJdQRtkrqJdEKKxtYjRMQi4Cpo15mCgTsYuoNKKrF1V1g
2024-08-20T22:01:50.449052355Z WARN queue | Rejecting block as it doesn't come from a synced peer block=#3037477:MI:9f338b21e4 peer_id=12D3KooWQprQcMnrei1pKf6DSGoH7DEu3nEnjCbCtBUGLiX1ULHd
2024-08-20T22:01:50.455519019Z WARN queue | Rejecting block as it doesn't come from a synced peer block=#3037478:MI:7c724b1584 peer_id=12D3KooWJdQRtkrqJdEKKxtYjRMQi4Cpo15mCgTsYuoNKKrF1V1g
2024-08-20T22:01:50.457156729Z DEBUG queue | Received block via gossipsub block=#3037475:MI:9fef18de2b peer_id=12D3KooWFmkfcoNGCd1wLFZmmVs6vX7dp99MEs5HNAyQtpJdBLW1
2024-08-20T22:01:50.466560101Z INFO swarm | Connection closed with peer connection_id=5453 peer_id=12D3KooWBw9vWGDjbpcHNGqn7njrxxDngMqB2wNtrQuT4zYwBJk4 endpoint=Listener { local_addr: "/ip4/167.235.24.195/tcp/8444/ws", send_back_addr: "/ip4/116.203.140.114/tcp/47300/ws" } connections=1
2024-08-20T22:01:50.466626619Z INFO swarm | Connection closed because cause=Connection error: I/O error: i/o error: Error while sending over the sink, connection closed
2024-08-20T22:01:50.466727293Z INFO swarm | Connection closed with peer connection_id=5455 peer_id=12D3KooWQprQcMnrei1pKf6DSGoH7DEu3nEnjCbCtBUGLiX1ULHd endpoint=Listener { local_addr: "/ip4/167.235.24.195/tcp/8444/ws", send_back_addr: "/ip4/5.75.175.155/tcp/8443/ws" } connections=0
2024-08-20T22:01:50.466757926Z INFO swarm | Connection closed because cause=Connection error: I/O error: i/o error: Error while sending over the sink, connection closed
2024-08-20T22:01:50.466880779Z DEBUG block_request_compo… | Removing peer from live sync peer_id=12D3KooWQprQcMnrei1pKf6DSGoH7DEu3nEnjCbCtBUGLiX1ULHd
2024-08-20T22:01:50.479430808Z ERROR panic | thread 'tokio-runtime-worker' panicked at 'Peer is connected.': /home/nimiq/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libp2p-autonat-0.13.0/src/v1/behaviour/as_server.rs:304
0: <backtrace::capture::Backtrace as core::default::Default>::default
1: log_panics::Config::install_panic_hook::{{closure}}
2: std::panicking::rust_panic_with_hook
3: std::panicking::begin_panic_handler::{{closure}}
4: std::sys_common::backtrace::__rust_end_short_backtrace
5: rust_begin_unwind
6: core::panicking::panic_fmt
7: core::panicking::panic_display
8: core::option::expect_failed
9: <libp2p_autonat::v1::behaviour::as_server::AsServer as libp2p_autonat::v1::behaviour::HandleInnerEvent>::handle_event
10: <libp2p_autonat::v1::behaviour::Behaviour as libp2p_swarm::behaviour::NetworkBehaviour>::poll
11: <nimiq_network_libp2p::behaviour::Behaviour as libp2p_swarm::behaviour::NetworkBehaviour>::poll
12: libp2p_swarm::Swarm<TBehaviour>::poll_next_event
13: <tokio::future::poll_fn::PollFn<F> as core::future::future::Future>::poll
14: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
15: <core::pin::Pin<P> as core::future::future::Future>::poll
16: tokio::runtime::task::core::Core<T,S>::poll
17: tokio::runtime::task::harness::Harness<T,S>::poll
18: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
19: tokio::runtime::scheduler::multi_thread::worker::Context::run
20: tokio::runtime::context::scoped::Scoped<T>::set
21: tokio::runtime::context::runtime::enter_runtime
22: tokio::runtime::scheduler::multi_thread::worker::run
23: tokio::runtime::task::core::Core<T,S>::poll
24: tokio::runtime::task::harness::Harness<T,S>::poll
25: tokio::runtime::blocking::pool::Inner::run
26: std::sys_common::backtrace::__rust_begin_short_backtrace
27: core::ops::function::FnOnce::call_once{{vtable.shim}}
28: std::sys::pal::unix::thread::Thread::new::thread_start
29: <unknown>
30: <unknown>
Relevant log output
No response
Possible Solution
Not assume that you always find a connected peer.
Version
libp2p: 0.54.1
libp2p-autonat: 0.13.0