tokio-rs/tokio-core

BorrowMutError on HTTP request

donhcd opened this issue · 7 comments

donhcd commented

On tokio-core-0.1.10 I'm getting this BorrowMutError when calling borrow_mut() on this line, which comes from the future defined on this line, which is just supposed to perform an https request.

I'm really not sure how to debug this. In my test, I'm running a few post requests and it seems to always panic on the same one. I'm not entirely confident that this is the right repo to put this issue on, but it seems like a reasonable guess.

stacktrace:

note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:380
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:396
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:611
   5: std::panicking::begin_panic_new
             at /checkout/src/libstd/panicking.rs:553
   6: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:521
   7: rust_begin_unwind
             at /checkout/src/libstd/panicking.rs:497
   8: core::panicking::panic_fmt
             at /checkout/src/libcore/panicking.rs:92
   9: core::result::unwrap_failed
             at /checkout/src/libcore/macros.rs:41
  10: <core::result::Result<T, E>>::expect
             at /checkout/src/libcore/result.rs:762
  11: <core::cell::RefCell<T>>::borrow_mut
             at /checkout/src/libcore/cell.rs:668
  12: tokio_core::reactor::io_token::IoToken::new
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/io_token.rs:37
  13: <tokio_core::reactor::poll_evented::PollEvented<E>>::new
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/poll_evented.rs:89
  14: tokio_core::net::tcp::TcpStream::new
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/net/tcp.rs:266
  15: tokio_core::net::tcp::TcpStream::connect
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/net/tcp.rs:258
  16: hyper::client::connect::ConnectingTcp::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.11.6/src/client/connect.rs:225
  17: <hyper::client::connect::HttpConnecting as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.11.6/src/client/connect.rs:186
  18: <futures::future::chain::Chain<A, B, C>>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/chain.rs:26
  19: <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/and_then.rs:32
  20: <alloc::boxed::Box<F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/mod.rs:113
  21: <hyper_tls::client::HttpsConnecting<T> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-tls-0.1.2/src/client.rs:126
  22: <futures::future::map::Map<A, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/map.rs:30
  23: <futures::future::select::Select<A, B> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/select.rs:52
  24: <futures::future::map::Map<A, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/map.rs:30
  25: <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/map_err.rs:30
  26: <futures::future::chain::Chain<A, B, C>>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/chain.rs:26
  27: <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/and_then.rs:32
  28: <futures::future::map::Map<A, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/map.rs:30
  29: <alloc::boxed::Box<F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/mod.rs:113
  30: <hyper::client::FutureResponse as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.11.6/src/client/mod.rs:147
  31: <futures::future::chain::Chain<A, B, C>>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/chain.rs:26
  32: <futures::future::and_then::AndThen<A, B, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/and_then.rs:32
  33: <futures::future::map_err::MapErr<A, F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/map_err.rs:30
  34: <alloc::boxed::Box<F> as futures::future::Future>::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/future/mod.rs:113
  35: <futures::task_impl::Spawn<F>>::poll_future_notify::{{closure}}
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/task_impl/mod.rs:289
  36: <futures::task_impl::Spawn<T>>::enter::{{closure}}
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/task_impl/mod.rs:350
  37: futures::task_impl::std::set
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/task_impl/std/mod.rs:79
  38: <futures::task_impl::Spawn<T>>::enter
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/task_impl/mod.rs:350
  39: <futures::task_impl::Spawn<F>>::poll_future_notify
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/futures-0.1.16/src/task_impl/mod.rs:289
  40: tokio_core::reactor::Core::dispatch_task::{{closure}}
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:356
  41: <scoped_tls::ScopedKey<T>>::set
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/scoped-tls-0.1.0/src/lib.rs:135
  42: tokio_core::reactor::Core::dispatch_task
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:355
  43: tokio_core::reactor::Core::dispatch
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:316
  44: tokio_core::reactor::Core::poll
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:304
  45: tokio_core::reactor::Core::run
             at /home/travis/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-core-0.1.10/src/reactor/mod.rs:241
  46: tokio_gcp::client::GoogleCloudClient::new::{{closure}}
             at /home/travis/.cargo/git/checkouts/tokio-gcp-f94e4460b4e9dec0/b014e2c/src/client.rs:101
twmb commented

Is it possible to post a code snippet that you've found to reliably panic?

alexcrichton commented

Thanks for the report! Looking at the stack trace nothing jumps out to me as something that would cause this borrow error. Like @twmb mentioned, do you have a way I could reproduce locally? Similarly, did this happen recently? What compiler are you using?

donhcd commented

Thanks for the responses! Unfortunately I don't have an easy repro to share -- I only just found this behavior when adding a test, which is all tied up with GCP and therefore requires secrets and stuff. I could probably manage to set up a sharable repro, but it's a chunk of work and will take some time. About the compiler, I just noticed I was still on rustc 1.21.0-beta.2 (133aefc9f 2017-09-02). I just updated to rustc 1.21.0 (3b72af97e 2017-10-09) and I'm getting the same thing

donhcd commented

Okay! Putting together a repro actually wasn't as bad as I thought. This gist should have everything you need to repro. (I'm hoping I correctly configured the service account so that it doesn't any useful privileges.) You should be able to just copy/paste/run the contents of run.sh into your terminal as long as your directory doesn't already contain tokio-gcp.

It might be important that there are two different gcp::GoogleCloudClients being used, which means there are two reactor::Cores running. Is that okay?

alexcrichton commented

Thanks for the reproduction! Internally I see unsafe { &*HYPER_CLIENT.load(Ordering::SeqCst) }, could that be actually unsafe and causing a data race here?

twmb commented

My guess:

  • First GoogleCloudClient::new creates a thread and uses HYPER_CLIENT.store(... with Core(<for tok>)
  • Core(<for tok>).run(futures::empty) is called (which never returns) and falls into Core's internal poll (which does borrow_mut)
  • Second Goo..::new creates a thread and uses HYPER_CLIENT.store(... with Core(<for bq>)
  • Core(<for bq>).run(futures::empty) is called and falls into poll (borrow_mut)
  • tok_hub.access_token(... is called, which uses tok_client internally to make a request, but making a request calls HYPER_CLIENT.load
    • we would want this to be the Core created from tok_client, but this loads the second Core stored from bq_client because HYPER_CLIENT is not thread scoped
  • tok_hub.access_token(...'s internal request eventually gets into creating that IoToken, which calls borrow_mut on the Core.
    • this is the second borrow_mut, because bq_client's Core::run(futures::empty) is still waiting in poll

I think the fix would lie in making HYPER_CLIENT thread scoped.

donhcd commented

@twmb That makes sense to me. Thanks everyone for taking a look and debugging my code 😅 !