Panic | thread 'tokio-runtime-worker' panicked at 'SinkImpl::poll_ready called after error.'

[nibhar]

Observed in a recent devnet run in almost all nodes.

Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    0: log_panics::init::{{closure}}
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    1: std::panicking::rust_panic_with_hook
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:              at /rustc/3c17c84a386e7badf6b2c6018d172496b3a28a04/library/std/src/panicking.rs:702:17
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    2: std::panicking::begin_panic::{{closure}}
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    3: std::sys_common::backtrace::__rust_end_short_backtrace
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    4: std::panicking::begin_panic
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    5: <quicksink::SinkImpl<S,F,T,A,E> as futures_sink::Sink<A>>::poll_ready
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    6: <rw_stream_sink::RwStreamSink<S> as futures_io::if_std::AsyncWrite>::poll_write
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    7: <multistream_select::negotiated::Negotiated<TInner> as futures_io::if_std::AsyncWrite>::poll_write
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    8: <libp2p_noise::io::framed::NoiseFramed<T,S> as futures_sink::Sink<&alloc::vec::Vec<u8>>>::poll_ready
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:    9: <libp2p_noise::io::framed::NoiseFramed<T,S> as futures_sink::Sink<&alloc::vec::Vec<u8>>>::poll_flush
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   10: <libp2p_noise::io::NoiseOutput<T> as futures_io::if_std::AsyncWrite>::poll_flush
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   11: multistream_select::negotiated::Negotiated<TInner>::poll
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   12: <multistream_select::negotiated::Negotiated<TInner> as futures_io::if_std::AsyncWrite>::poll_close
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   13: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   14: <S as futures_core::stream::TryStream>::try_poll_next
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   15: <futures_util::stream::try_stream::ErrInto<St,E> as futures_core::stream::Stream>::poll_next
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   16: <libp2p_yamux::Yamux<S> as libp2p_core::muxing::StreamMuxer>::close
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   17: <libp2p_core::muxing::Wrap<T> as libp2p_core::muxing::StreamMuxer>::close
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   18: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   19: tokio::runtime::task::harness::poll_future
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   20: tokio::runtime::task::harness::Harness<T,S>::poll
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   21: std::thread::local::LocalKey<T>::with
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   22: tokio::runtime::thread_pool::worker::Context::run_task
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   23: tokio::runtime::thread_pool::worker::Context::run
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   24: tokio::macros::scoped_tls::ScopedKey<T>::set
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   25: tokio::runtime::thread_pool::worker::run
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   26: tokio::runtime::task::harness::Harness<T,S>::poll
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   27: tokio::runtime::blocking::pool::Inner::run
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   28: std::sys_common::backtrace::__rust_begin_short_backtrace
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   29: core::ops::function::FnOnce::call_once{{vtable.shim}}
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   30: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:              at /rustc/3c17c84a386e7badf6b2c6018d172496b3a28a04/library/alloc/src/boxed.rs:1853:9
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:       <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:              at /rustc/3c17c84a386e7badf6b2c6018d172496b3a28a04/library/alloc/src/boxed.rs:1853:9
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:       std::sys::unix::thread::Thread::new::thread_start
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:              at /rustc/3c17c84a386e7badf6b2c6018d172496b3a28a04/library/std/src/sys/unix/thread.rs:108:17
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   31: start_thread
Mar 24 02:52:40 ip-172-31-13-88 nimiq-client[36147]:   32: clone

[hrxi]

Grepping through all the source code compiled for this project, I could only find this line: https://docs.rs/quicksink/0.1.2/src/quicksink/lib.rs.html#158.

The only reverse dependency of quicksink seems to be libp2p-websocket:

$ cargo tree -p quicksink -i --depth 1
quicksink v0.1.2
└── libp2p-websocket v0.34.0

[hrxi]

I filed an upstream bug report, and created a PR: libp2p/rust-libp2p#2599.

[viquezclaudio]

The original issue was observed during low/no available memory left in some old nodes.
It has not been observed with the public and new internal devnet nodes, so Im closing this issue for now.

[hrxi]

It's now actually fixed in upstream: libp2p/rust-libp2p#2598.

[jsdanielh]

We have seen this again lately in the testnet:

2024-06-10T15:15:27.806153220Z ERROR panic                | thread 'tokio-runtime-worker' panicked at 'SinkImpl::poll_ready called after error.': /home/nimiq/.cargo/registry/src/index.crates.io-6f17d22bba15001f/libp2p-websocket-0.43.0/src/quicksink.rs:159
    0: <backtrace::capture::Backtrace as core::default::Default>::default
    1: log_panics::Config::install_panic_hook::{{closure}}
    2: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/alloc/src/boxed.rs:2021:9
       std::panicking::rust_panic_with_hook
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/std/src/panicking.rs:735:13
    3: std::panicking::begin_panic_handler::{{closure}}
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/std/src/panicking.rs:601:13
    4: std::sys_common::backtrace::__rust_end_short_backtrace
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/std/src/sys_common/backtrace.rs:170:18
    5: rust_begin_unwind
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/std/src/panicking.rs:597:5
    6: core::panicking::panic_fmt
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/core/src/panicking.rs:72:14
    7: <libp2p_websocket::quicksink::SinkImpl<S,F,T,A,E> as futures_sink::Sink<A>>::poll_ready
    8: <rw_stream_sink::RwStreamSink<S> as futures_io::if_std::AsyncWrite>::poll_write
    9: <asynchronous_codec::framed::Framed<T,U> as futures_sink::Sink<<U as asynchronous_codec::encoder::Encoder>::Item>>::poll_ready
   10: <libp2p_noise::io::Output<T> as futures_io::if_std::AsyncWrite>::poll_write
   11: <yamux::frame::io::Io<T> as futures_sink::Sink<yamux::frame::Frame<()>>>::poll_ready
   12: yamux::connection::Connection<T>::poll_next_inbound
   13: libp2p_yamux::Muxer<C>::poll_inner
   14: <libp2p_yamux::Muxer<C> as libp2p_core::muxing::StreamMuxer>::poll
   15: <libp2p_core::muxing::boxed::Wrap<T> as libp2p_core::muxing::StreamMuxer>::poll
   16: <libp2p_core::muxing::boxed::Wrap<T> as libp2p_core::muxing::StreamMuxer>::poll
   17: libp2p_swarm::connection::Connection<THandler>::poll
   18: <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll
   19: tokio::runtime::task::core::Core<T,S>::poll
   20: tokio::runtime::task::raw::poll
   21: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
   22: tokio::runtime::scheduler::multi_thread::worker::Context::run
   23: tokio::runtime::context::scoped::Scoped<T>::set
   24: tokio::runtime::context::runtime::enter_runtime
   25: tokio::runtime::scheduler::multi_thread::worker::run
   26: tokio::runtime::task::core::Core<T,S>::poll
   27: tokio::runtime::task::harness::Harness<T,S>::poll
   28: tokio::runtime::blocking::pool::Inner::run
   29: std::sys_common::backtrace::__rust_begin_short_backtrace
   30: core::ops::function::FnOnce::call_once{{vtable.shim}}
   31: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/alloc/src/boxed.rs:2007:9
       <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/alloc/src/boxed.rs:2007:9
       std::sys::unix::thread::Thread::new::thread_start
              at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/std/src/sys/unix/thread.rs:108:17
   32: <unknown>
   33: <unknown>