AutoNAT V1 panic: `Peer is connected`

[Eligioo]

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

[dariusc93]

Thanks for reporting. This is a interesting issue but I have not been able to reproduce myself. However, it is true that the peer could close the connection before it has a chance to respond to the request, though in this case it happened after the request is received while polling the request-response behaviour. I wonder if it goes back to something similar to #4870 where there could be inconsistencies (doubt thats the case). Regardless, a simple solution would probably be to drop or ignore the request if the peer is no longer connected (before we call resolve_inbound_request). Thoughts on this? I could also imagine maybe figuring out the direct cause of the closure too.

CC @jxs

[Eligioo]

I believe a simple fix for this would indeed be to check upfront if there still is a connection with the peer before calling resolve_inbound_request because apparently there is a flow in which the contract that the expect creates (to always find a connected peer), is not always true.

My knowledge of the protocol/libp2p crate limited so I would not be able to determine the root cause of this. However if you would accept a PR as described above, I can create it.

I could also imagine maybe figuring out the direct cause of the closure too
Don't understand what you mean with this statement.

[Eligioo]

Interestingly earlier today our CI also encountered the same panic.

spammer1.log