Panicking in Client call

[xrl]

I am sending requests to AWS Kinesis. Because of the small size of requests I have to generate many concurrent requests. I am using the futures stream::BufferUnordered to put a cap on concurrent requests. Now I have an issue where after ~30 seconds the tokio core panics and goes away. I'm creating on the order of 1000 concurrent requests.

Here is the backtrace:

# cargo build --release; RUST_BACKTRACE=full ./target/release/kinesis-hyper-bug
    Finished release [optimized + debuginfo] target(s) in 0.0 secs
thread '<unnamed>' panicked at 'called `Result::unwrap()` on an `Err` value: SendError("...")', libcore/result.rs:916:5
stack backtrace:
   0:       0x5917cfe83b - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::h01c1934f65de6f6a
                               at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:       0x5917d04451 - std::sys_common::backtrace::print::h87cc6ba9b94fa155
                               at libstd/sys_common/backtrace.rs:68
                               at libstd/sys_common/backtrace.rs:57
   2:       0x5917cfade0 - std::panicking::default_hook::{{closure}}::hd04a5cd906658fa2
                               at libstd/panicking.rs:381
   3:       0x5917cfa915 - std::panicking::default_hook::h13d81f39b4233c4b
                               at libstd/panicking.rs:397
   4:       0x5917cfb22b - std::panicking::rust_panic_with_hook::hafca86651ef244e6
                               at libstd/panicking.rs:577
   5:       0x5917cfb0ee - std::panicking::begin_panic::h5e76eba7233d4218
                               at libstd/panicking.rs:538
   6:       0x5917cfafea - std::panicking::begin_panic_fmt::hff38b5bd065c125a
                               at libstd/panicking.rs:522
   7:       0x5917cfaf82 - rust_begin_unwind
                               at libstd/panicking.rs:498
   8:       0x5917d53730 - core::panicking::panic_fmt::h2b19f39e7a539ec5
                               at libcore/panicking.rs:71
   9:       0x5917bd533d - core::result::unwrap_failed::h5671d77bb13dd94c
                               at /checkout/src/libcore/macros.rs:23
  10:       0x5917bbf38d - <futures::future::chain::Chain<A, B, C>>::poll::h3bb254ec3dfd880b
                               at /checkout/src/libcore/result.rs:782
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.11.15/src/client/mod.rs:226
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/and_then.rs:34
                               at /checkout/src/libcore/result.rs:468
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/and_then.rs:33
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/chain.rs:39
  11:       0x5917babf1d - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::hdc170a02017dfce5
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/and_then.rs:32
  12:       0x5917cc4f45 - <hyper::client::FutureResponse as futures::future::Future>::poll::h4ce4ebd5cd641777
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/mod.rs:113
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.11.15/src/client/mod.rs:147
  13:       0x5917bb03b3 - <rusoto_core::request::ClientFuture as futures::future::Future>::poll::hadcebab3f0932233
                               at /root/.cargo/git/checkouts/rusoto-async-35a81945dd339d5f/eeddeab/rusoto/core/src/request.rs:189
  14:       0x5917bbf720 - <futures::future::chain::Chain<A, B, C>>::poll::h3bf5afb35f09f954
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/chain.rs:26
  15:       0x5917bb7794 - <futures::future::lazy::Lazy<F, R> as futures::future::Future>::poll::h76822e873224c5c5
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/then.rs:32
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/lazy.rs:82
  16:       0x5917cd18ac - futures::task_impl::std::set::h8bc2ee5269bbd68e
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/mod.rs:113
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:289
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:363
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/std/mod.rs:78
  17:       0x5917cd054e - <futures::task_impl::Spawn<T>>::poll_future_notify::h0ff7795838505ee3
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:363
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:289
  18:       0x5917cd43ac - tokio_core::reactor::Core::poll::hc54e92f60d70a7d1
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.12/src/reactor/mod.rs:359
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/scoped-tls-0.1.0/src/lib.rs:135
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.12/src/reactor/mod.rs:358
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.12/src/reactor/mod.rs:319
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.12/src/reactor/mod.rs:307
  19:       0x5917cd3961 - tokio_core::reactor::Core::turn::h802af95fae6f34c8
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.12/src/reactor/mod.rs:254
  20:       0x5917bf3968 - std::sys_common::backtrace::__rust_begin_short_backtrace::h319e1ff7df31b72b
                               at /root/.cargo/git/checkouts/rusoto-async-35a81945dd339d5f/eeddeab/rusoto/core/src/reactor.rs:63
                               at /checkout/src/libstd/sys_common/backtrace.rs:133
  21:       0x5917d1683e - __rust_maybe_catch_panic
                               at libpanic_unwind/lib.rs:102
  22:       0x5917bb61d8 - <F as alloc::boxed::FnBox<A>>::call_box::h9776122b160b44e4
                               at /checkout/src/libstd/panicking.rs:459
                               at /checkout/src/libstd/panic.rs:365
                               at /checkout/src/libstd/thread/mod.rs:405
                               at /checkout/src/liballoc/boxed.rs:817
  23:       0x5917d06e37 - std::sys_common::thread::start_thread::had16748b9c5dacc9
                               at /checkout/src/liballoc/boxed.rs:827
                               at libstd/sys_common/thread.rs:24
  24:       0x5917d0a3a8 - std::sys::unix::thread::Thread::new::thread_start::h1458f52276ce60d4
                               at libstd/sys/unix/thread.rs:90
  25:     0x7f8056062063 - start_thread
  26:     0x7f8055b8162c - clone
  27:                0x0 - <unknown>
thread '<unnamed>' panicked at 'failed to retrieve response from reactor: Canceled', libcore/result.rs:916:5
stack backtrace:
   0:       0x5917cfe83b - std::sys::unix::backtrace::tracing::imp::unwind_backtrace::h01c1934f65de6f6a
                               at libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1:       0x5917d04451 - std::sys_common::backtrace::print::h87cc6ba9b94fa155
                               at libstd/sys_common/backtrace.rs:68
                               at libstd/sys_common/backtrace.rs:57
   2:       0x5917cfade0 - std::panicking::default_hook::{{closure}}::hd04a5cd906658fa2
                               at libstd/panicking.rs:381
   3:       0x5917cfa915 - std::panicking::default_hook::h13d81f39b4233c4b
                               at libstd/panicking.rs:397
   4:       0x5917cfb22b - std::panicking::rust_panic_with_hook::hafca86651ef244e6
                               at libstd/panicking.rs:577
   5:       0x5917cfb0ee - std::panicking::begin_panic::h5e76eba7233d4218
                               at libstd/panicking.rs:538
   6:       0x5917cfafea - std::panicking::begin_panic_fmt::hff38b5bd065c125a
                               at libstd/panicking.rs:522
   7:       0x5917cfaf82 - rust_begin_unwind
                               at libstd/panicking.rs:498
   8:       0x5917d53730 - core::panicking::panic_fmt::h2b19f39e7a539ec5
                               at libcore/panicking.rs:71
   9:       0x5917bd4f6b - core::result::unwrap_failed::h070b919d720b3625
                               at /checkout/src/libcore/macros.rs:23
  10:       0x5917bf27b4 - <rusoto_core::reactor::RequestDispatcherFuture as futures::future::Future>::poll::he84fa4d26a52e903
                               at /checkout/src/libcore/result.rs:809
                               at /root/.cargo/git/checkouts/rusoto-async-35a81945dd339d5f/eeddeab/rusoto/core/src/reactor.rs:95
  11:       0x5917b94370 - <rusoto_core::client_inner::SignAndDispatch<P, D, E> as futures::future::Future>::poll::h6a6fd39619677f61
                               at /root/.cargo/git/checkouts/rusoto-async-35a81945dd339d5f/eeddeab/rusoto/core/src/client_inner.rs:88
  12:       0x5917b7d5ec - <futures::future::chain::Chain<A, B, C>>::poll::hf500c48ed800ad80
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/chain.rs:26
  13:       0x5917b8c60d - <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll::h01293d6dbd13f74e
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/and_then.rs:32
  14:       0x5917b7d0f8 - <futures::future::chain::Chain<A, B, C>>::poll::hc7a513298383395f
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/mod.rs:113
                               at /root/.cargo/git/checkouts/rusoto-async-35a81945dd339d5f/eeddeab/rusoto/core/src/future.rs:30
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/chain.rs:26
  15:       0x5917b93536 - futures::task_impl::with_notify::h9a5a02c0a7eaac30
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/future/then.rs:32
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/stream/futures_unordered.rs:363
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/std/mod.rs:78
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:480
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:45
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:471
  16:       0x5917b91b0f - <futures::stream::futures_unordered::FuturesUnordered<T> as futures::stream::Stream>::poll::h8dba88ca9c256e3b
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/stream/futures_unordered.rs:362
  17:       0x5917b93d2f - <futures::stream::buffer_unordered::BufferUnordered<S> as futures::stream::Stream>::poll::h3b8f49dcb85d7dc6
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/stream/buffer_unordered.rs:96
  18:       0x5917b92e9c - <futures::task_impl::Spawn<T>>::poll_stream_notify::h97f3d5e19952b5ac
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:301
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:363
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/std/mod.rs:78
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:363
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/mod.rs:301
  19:       0x5917b96447 - <std::thread::local::LocalKey<T>>::with::hbfb095580dfabd73
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/std/mod.rs:302
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/std/mod.rs:506
                               at /checkout/src/libstd/thread/local.rs:377
                               at /checkout/src/libstd/thread/local.rs:288
  20:       0x5917b7fa57 - std::sys_common::backtrace::__rust_begin_short_backtrace::h88bff9b603612577
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/std/mod.rs:506
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/task_impl/std/mod.rs:299
                               at /root/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.18/src/stream/wait.rs:51
                               at src/main.rs:166
                               at /checkout/src/libstd/sys_common/backtrace.rs:133
  21:       0x5917b963a4 - std::panicking::try::do_call::h2a76888acf58fa3f
                               at /checkout/src/libstd/thread/mod.rs:406
                               at /checkout/src/libstd/panic.rs:300
                               at /checkout/src/libstd/panicking.rs:480
  22:       0x5917d1683e - __rust_maybe_catch_panic
                               at libpanic_unwind/lib.rs:102
  23:       0x5917b9747d - <F as alloc::boxed::FnBox<A>>::call_box::h81e80e87d1bf9702
                               at /checkout/src/libstd/panicking.rs:459
                               at /checkout/src/libstd/panic.rs:365
                               at /checkout/src/libstd/thread/mod.rs:405
                               at /checkout/src/liballoc/boxed.rs:817
  24:       0x5917d06e37 - std::sys_common::thread::start_thread::had16748b9c5dacc9
                               at /checkout/src/liballoc/boxed.rs:827
                               at libstd/sys_common/thread.rs:24
  25:       0x5917d0a3a8 - std::sys::unix::thread::Thread::new::thread_start::h1458f52276ce60d4
                               at libstd/sys/unix/thread.rs:90
  26:     0x7f8056062063 - start_thread
  27:     0x7f8055b8162c - clone
  28:                0x0 - <unknown>

You can reproduce the error by cloning down https://github.com/tureus/kinesis-hyper . You will need AWS credentials and a single test stream already created. The code will take it from there and start issuing many concurrent requests.

[xrl]

This issue was first brought up the rusoto project: rusoto/rusoto#914

[seanmonstar]

As noticed, the panic is in client/mod.rs, the call to start_send().unwrap(). It's wrong to assume that the sender can always send. This should probably be changed to not unwrap, but to realize that the pooled connected has died, and to try a new one.

[xrl]

Thanks! This fixed the issue for me. Things are rock solid from my initial testing.

[xrl]

@seanmonstar when can this be put out in a release?

[seanmonstar]

Should be published soon (today?). I'd like to get in some documentation fixes as well (separate from this issue).

[matthewkmayer]

Thank you for the exceptionally quick turnaround time on these fixes, @seanmonstar . 😄

[xrl]

@seanmonstar my tool appears more resilient now. I can run it at full speed without the reactor dying from a panic. I do see regular outputs of the new IO error you added:

root@doit-1800981089-sz6zt:~/kinesis-hyper-bug# cargo build --release && RUST_LOG=error RUST_BACKTRACE=full ./target/release/kinesis-hyper-bug
    Finished release [optimized + debuginfo] target(s) in 0.0 secs
ERROR 2018-01-31T17:10:32Z: hyper::client: pooled connection was not ready, this is a hyper bug
ERROR 2018-01-31T17:11:49Z: hyper::client: pooled connection was not ready, this is a hyper bug
ERROR 2018-01-31T17:15:16Z: hyper::client: pooled connection was not ready, this is a hyper bug
ERROR 2018-01-31T17:15:58Z: hyper::client: pooled connection was not ready, this is a hyper bug
ERROR 2018-01-31T17:16:00Z: hyper::client: pooled connection was not ready, this is a hyper bug

Should I create a new ticket for this error?

[seanmonstar]

@xrl yea, definitely. Bummer. The connection pooling code in hyper hasn't seen much love, and is complicated and apparently fragile 😢.