Client panics with 'handler not in queue for key'

[arkpar]

Using latest master. I have a Client that sends HTTP POST requests to the same URL from multiple threads and sometime this happens:

2016-06-29 19:39:49 TRACE:hyper::client: on_incoming MessageHead { version: Http11, subject: RawStatus(200, "OK"), headers: Headers { Date: Wed, 29 Jun 2016 17:39:49 GMT, Content-Type: text/html; charset=utf-8, Transfer-Encoding: chunked, Connection: keep-alive, Set-Cookie: __cfduid=d7fc357ba132c654f5d1ff011ddf8f45c1467221989; expires=Thu, 29-Jun-17 17:39:49 GMT; path=/; domain=.requestb.in; HttpOnly, Sponsored-By: https://www.runscope.com, Via: 1.1 vegur, Server: cloudflare-nginx, CF-RAY: 2bab28f85afc2696-FRA, } }
2016-06-29 19:39:49 TRACE:hyper::client::response: Response::new
2016-06-29 19:39:49 DEBUG:hyper::client::response: version=Http11, status=Ok
2016-06-29 19:39:49 DEBUG:hyper::client::response: headers=Headers { Date: Wed, 29 Jun 2016 17:39:49 GMT, Content-Type: text/html; charset=utf-8, Transfer-Encoding: chunked, Connection: keep-alive, Set-Cookie: __cfduid=d7fc357ba132c654f5d1ff011ddf8f45c1467221989; expires=Thu, 29-Jun-17 17:39:49 GMT; path=/; domain=.requestb.in; HttpOnly, Sponsored-By: https://www.runscope.com, Via: 1.1 vegur, Server: cloudflare-nginx, CF-RAY: 2bab28f85afc2696-FRA, }
2016-06-29 19:39:49 TRACE:hyper::http::conn: handler.on_incoming() -> Next::End
2016-06-29 19:39:49 TRACE:hyper::http::conn: Conn.on_readable State::Http1 completed, new state = Closed
2016-06-29 19:39:49 TRACE:hyper::http::conn: on_readable <- Closed
2016-06-29 19:39:49 TRACE:hyper::http::conn: removing transport
2016-06-29 19:39:49 DEBUG:hyper::http::conn: on_remove
2016-06-29 19:39:49 TRACE:hyper::http::conn: Conn::ready events='Writable', blocked=None
2016-06-29 19:39:49 TRACE:hyper::http::conn: on_writable -> Init
thread 'hyper-client' panicked at 'handler not in queue for key', ../src/libcore/option.rs:700
stack backtrace:
   1:        0x10df189a8 - std::sys::backtrace::tracing::imp::write::h4c73fcd3363076f5
   2:        0x10df1d695 - std::panicking::default_hook::_$u7b$$u7b$closure$u7d$$u7d$::h0422dbb3077e6747
   3:        0x10df1d2ce - std::panicking::default_hook::haac48fa641db8fa2
   4:        0x10df042a6 - std::sys_common::unwind::begin_unwind_inner::h39d40f52add53ef7
   5:        0x10df0512e - std::sys_common::unwind::begin_unwind_fmt::h64c0ff793199cc1b
   6:        0x10df17c77 - rust_begin_unwind
   7:        0x10df44650 - core::panicking::panic_fmt::h73bf9d7e8e891a73
   8:        0x10df4ba05 - core::option::expect_failed::h076bf2c39f982c10
   9:        0x10d15bff7 - _<std..option..Option<T>>::expect::h4d371225682cdf33
  10:        0x10d15bde8 - _<hyper..client..Context<K, H>>::pop_queue::h9f1ca6f87b02e137
  11:        0x10d17f2c8 - _<hyper..client..Context<K, H> as hyper..http..conn..MessageHandlerFactory<K, T>>::create::h72fe55a18cf094e1
  12:        0x10d1838d1 - _<hyper..http..conn..ConnInner<K, T, H>>::write::h27233c439f264973
  13:        0x10d1833e7 - _<hyper..http..conn..ConnInner<K, T, H>>::on_writable::hf0fc8b494309b678
  14:        0x10d16a117 - _<hyper..http..conn..Conn<K, T, H>>::ready::hcd9a5057a4a978bb
  15:        0x10d168d34 - _<hyper..client..ClientFsm<C, H> as rotor..machine..Machine>::ready::h18d7b4b8c2b1d861
  16:        0x10d156a2a - _<rotor..handler..Handler<M> as mio..handler..Handler>::ready::_$u7b$$u7b$closure$u7d$$u7d$::hd97c848ac2d5a15f
  17:        0x10d154829 - rotor::handler::machine_loop::_$u7b$$u7b$closure$u7d$$u7d$::hc30baa823bb27586
  18:        0x10d153bdf - _<slab..Slab<T, I>>::replace_with::h33450c53ecf92861
  19:        0x10d153373 - rotor::handler::machine_loop::h9cb7d33db670d5d7
  20:        0x10d153267 - _<rotor..handler..Handler<M> as mio..handler..Handler>::ready::h710fa45b2de72561
  21:        0x10d15320f - _<mio..event_loop..EventLoop<H>>::io_event::h03b152c8f8e13717
  22:        0x10d153138 - _<mio..event_loop..EventLoop<H>>::io_process::h181871cbb835ee55
  23:        0x10d152720 - _<mio..event_loop..EventLoop<H>>::run_once::h3d9fc897d97966a0
  24:        0x10d151f6b - _<mio..event_loop..EventLoop<H>>::run::hb65bd25c79b9dbbf
  25:        0x10d151e87 - _<rotor..creator..LoopInstance<M>>::run::he20d485afc7f963f
  26:        0x10d151da8 - _<rotor..creator..LoopCreator<M>>::run::h0cc8a75bbdd8303c
  27:        0x10d151819 - _<hyper..Client<H>>::configured::_$u7b$$u7b$closure$u7d$$u7d$::h8f30494177b18b6d
  28:        0x10d1511d3 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h4b89e9fded2ad991
  29:        0x10d151148 - std::sys_common::unwind::try::try_fn::h4a08d65f9221d375
  30:        0x10df17c0b - __rust_try
  31:        0x10df17b93 - std::sys_common::unwind::inner_try::h9eebd8dc83f388a6
  32:        0x10d151085 - std::sys_common::unwind::try::h3a06944618b15d43
  33:        0x10d150eb1 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::hcec021c16765064b
  34:        0x10d151a57 - _<F as std..boxed..FnBox<A>>::call_box::h861041a9a27a885d
  35:        0x10df1c828 - std::sys::thread::Thread::new::thread_start::h471ad90789353b5b
  36:     0x7fff9549f99c - _pthread_body
  37:     0x7fff9549f919 - _pthread_start

OS X 10.11.5

[lopuhin]

I'm still getting this error on 220d09f:

thread 'hyper-client' panicked at 'handler not in queue for key', ../src/libcore/option.rs:699
stack backtrace:
   1:        0x101062fab - std::sys::backtrace::tracing::imp::write::h3800f45f421043b8
   2:        0x101065135 - std::panicking::default_hook::_$u7b$$u7b$closure$u7d$$u7d$::h0ef6c8db532f55dc
   3:        0x101064d6e - std::panicking::default_hook::hf3839060ccbb8764
   4:        0x101058d57 - std::panicking::rust_panic_with_hook::h5dd7da6bb3d06020
   5:        0x1010656f6 - std::panicking::begin_panic::h9bf160aee246b9f6
   6:        0x101059ba8 - std::panicking::begin_panic_fmt::haf08a9a70a097ee1
   7:        0x10106534f - rust_begin_unwind
   8:        0x10108b260 - core::panicking::panic_fmt::h93df64e7370b5253
   9:        0x10108cb95 - core::option::expect_failed::h03c4c03f58c1633f
  10:        0x100e6be37 - _<std..option..Option<T>>::expect::h904cc49f34fb7126
  11:        0x100e6bc28 - _<hyper..client..Context<K, H>>::pop_queue::ha385db4d7e271633
  12:        0x100e94848 - _<hyper..client..Context<K, H> as hyper..http..conn..MessageHandlerFactory<K, T>>::create::hdab9d8df17821a8b
  13:        0x100e99731 - _<hyper..http..conn..ConnInner<K, T, H>>::write::h8bf0793167db4de5
  14:        0x100e991e7 - _<hyper..http..conn..ConnInner<K, T, H>>::on_writable::h23c7a4038164366b
  15:        0x100e838a3 - _<hyper..http..conn..Conn<K, T, H>>::ready::ha7943110f672e530
  16:        0x100e826bb - _<hyper..client..ClientFsm<C, H> as rotor..machine..Machine>::ready::h12d8e10694517c93
  17:        0x100e64172 - _<rotor..handler..Handler<M> as mio..handler..Handler>::ready::_$u7b$$u7b$closure$u7d$$u7d$::h23e72b149b40a114
  18:        0x100e61f39 - rotor::handler::machine_loop::_$u7b$$u7b$closure$u7d$$u7d$::h236e9fcf74f8593f
  19:        0x100e612d3 - _<slab..Slab<T, I>>::replace_with::h360746f6793e2f7f
  20:        0x100e60ab7 - rotor::handler::machine_loop::h95bcdc235462b1b1
  21:        0x100e6098f - _<rotor..handler..Handler<M> as mio..handler..Handler>::ready::h63fa883c90431441
  22:        0x100e6092f - _<mio..event_loop..EventLoop<H>>::io_event::h134e5ea52ae4ecee
  23:        0x100e60838 - _<mio..event_loop..EventLoop<H>>::io_process::h0b3c112a870fd570
  24:        0x100e5fc50 - _<mio..event_loop..EventLoop<H>>::run_once::h2c2a794cc3a3077f
  25:        0x100e5f49b - _<mio..event_loop..EventLoop<H>>::run::h28c2d6d411bbd2f1
  26:        0x100e5f3ba - _<rotor..creator..LoopInstance<M>>::run::h10df6fe28ea10bfb
  27:        0x100e5f2e0 - _<rotor..creator..LoopCreator<M>>::run::hd70222702ee8783e
  28:        0x100e5e550 - _<hyper..Client<H>>::configured::_$u7b$$u7b$closure$u7d$$u7d$::hf7f94e2f06fe4a88
  29:        0x100e5e407 - _<std..panic..AssertUnwindSafe<F> as std..ops..FnOnce<()>>::call_once::h02b88cb629f75f13
  30:        0x100e5e35e - std::panicking::try::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::hd5b87ecaef035883
  31:        0x100e5eb24 - std::panicking::try::call::h7ab4dd542e8f0d6d
  32:        0x101067ceb - __rust_try
  33:        0x101067c85 - __rust_maybe_catch_panic
  34:        0x100e5dfed - std::panicking::try::_$u7b$$u7b$closure$u7d$$u7d$::h8e4abf05d797c710
  35:        0x100e5debf - _<std..thread..LocalKey<T>>::with::h2d2e8e9c5ad81465
  36:        0x100e5dcef - std::panicking::try::h174a46106ff9d681
  37:        0x100e5dbce - std::panic::catch_unwind::h1e31bf21058af93e
  38:        0x100e5da41 - std::thread::Builder::spawn::_$u7b$$u7b$closure$u7d$$u7d$::hc9a714b59d9b1d07
  39:        0x100e5ed77 - _<F as std..boxed..FnBox<A>>::call_box::hede04a1363ea441c
  40:        0x101064398 - std::sys::thread::Thread::new::thread_start::h9e5bde00f3b3e2e2
  41:     0x7fff91d5999c - _pthread_body
  42:     0x7fff91d59919 - _pthread_start

I can provide a simple script to reproduce the error (based on client example).

[seanmonstar]

@lopuhin yea, I'd really appreciate an example. I've altered the client example locally to spawn several threads and make a bunch of requests to the same web page, and I don't get any panics...

[lopuhin]

Thanks for looking into it! Here is an example that reliably reproduces the crash for me:

git clone https://github.com/lopuhin/rust-broad-crawl.git
cd rust-broad-crawl
git checkout 069c7e0aaa8efeb92bd9c81585614d21b4cba4e6
cargo run top-1k.txt

Note that this will make about 1000 requests to top 1000 sites from Alexa 1m (I hope there is nothing scary there). It will be making requests for about 10 seconds printing headers, then timeouts will arrive, and then the crash, so the end of the output looks like this:

ERROR: Timeout
ERROR: Timeout
ERROR: Timeout
Received ()
thread 'hyper-client' panicked at 'handler not in queue for key', ../src/libcore/option.rs:699
note: Run with `RUST_BACKTRACE=1` for a backtrace.

Rust version rustc 1.10.0 (cfcb716cf 2016-07-03) on OS X (I can try to reproduce on ubuntu too).

[seanmonstar]

@lopuhin oh! its not a race condition in this case, it's incorrect handling of a connect timeout.

Resolving the DNS took longer than the timeout allowed, which removed the handler, but the DNS did eventually resolve, and tried to continue where a handler no longer exists.