RoxasShadow / rollbar-rs

Track and report errors, exceptions and messages from your Rust application to Rollbar.
BSD 2-Clause "Simplified" License
16 stars 9 forks source link

"dispatch dropped without returning error" #18

Open cstrahan-blueshift opened 3 years ago

cstrahan-blueshift commented 3 years ago

I believe we're running into a manifestation of this panic in hyper: https://github.com/hyperium/hyper/issues/2112

See the following Rollbar payload:

{
  "body": {
    "trace": {
      "frames": [
        {
          "lineno": 259, 
          "filename": "/root/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.12.36/src/client/conn.rs"
        }, 
        {
          "method": "actix::init_application::{{closure}}::{{closure}}::h03cddbc1bd61d1cf", 
          "filename": ""
        }, 
        {
          "method": "std::panicking::rust_panic_with_hook::h71e6a073d87de1f5", 
          "lineno": 595, 
          "filename": "/rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/panicking.rs"
        }, 
        {
          "method": "std::panicking::begin_panic::{{closure}}::h84a4ac6142ac8c51", 
          "filename": ""
        }, 
        {
          "method": "std::sys_common::backtrace::__rust_end_short_backtrace::h8df64b270704a2ee", 
          "filename": ""
        }, 
        {
          "method": "std::panicking::begin_panic::hbb31f5852bbdf237", 
          "filename": ""
        }, 
        {
          "method": "futures::future::chain::Chain<A,B,C>::poll::h3a95f13ed59d540e", 
          "filename": ""
        }, 
        {
          "method": "<futures::future::map_err::MapErr<A,F> as futures::future::Future>::poll::hfa0f91984607d4e8", 
          "filename": ""
        }, 
        {
          "method": "<futures::future::map::Map<A,F> as futures::future::Future>::poll::h4934b71eb53f71a3", 
          "filename": ""
        }, 
        {
          "method": "futures::future::chain::Chain<A,B,C>::poll::h71d6c440b50f4359", 
          "filename": ""
        }, 
        {
          "method": "futures::future::chain::Chain<A,B,C>::poll::hd3fe1a06fbd9db6b", 
          "filename": ""
        }, 
        {
          "method": "<futures::future::poll_fn::PollFn<F> as futures::future::Future>::poll::h84a35bb95baa4eaa", 
          "filename": ""
        }, 
        {
          "method": "<hyper::client::ResponseFuture as futures::future::Future>::poll::h9088ea04a6a9a727", 
          "filename": ""
        }, 
        {
          "method": "<futures::future::map::Map<A,F> as futures::future::Future>::poll::h3e432334c050d77b", 
          "filename": ""
        }, 
        {
          "method": "<futures::future::map_err::MapErr<A,F> as futures::future::Future>::poll::hfac78dc6d9fd7b21", 
          "filename": ""
        }, 
        {
          "method": "futures::task_impl::std::set::h7edfc0098bc68c22", 
          "filename": ""
        }, 
        {
          "method": "std::thread::local::LocalKey<T>::with::he853f51dd671a8e7", 
          "filename": ""
        }, 
        {
          "method": "tokio_current_thread::Entered<P>::block_on::hfce4221cafa84bff", 
          "filename": ""
        }, 
        {
          "method": "tokio_executor::global::with_default::h1b74ce8974ffcfbe", 
          "filename": ""
        }, 
        {
          "method": "tokio_timer::timer::handle::with_default::h5e10e3d7fcaffb21", 
          "filename": ""
        }, 
        {
          "method": "tokio_reactor::with_default::h65ab2eac53ad4746", 
          "filename": ""
        }, 
        {
          "method": "tokio::runtime::current_thread::runtime::Runtime::block_on::hf78c57ace46f88d2", 
          "filename": ""
        }, 
        {
          "method": "std::sys_common::backtrace::__rust_begin_short_backtrace::hf7994801795d86a3", 
          "filename": ""
        }, 
        {
          "method": "core::ops::function::FnOnce::call_once{{vtable.shim}}::h3052f9825eb4eaf4", 
          "filename": ""
        }, 
        {
          "method": "<alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h61144a2be4ee36d8", 
          "lineno": 1521, 
          "filename": "/rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/alloc/src/boxed.rs"
        }, 
        {
          "method": "<alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hcf5d395fdd120c17", 
          "lineno": 1521, 
          "filename": "/rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/alloc/src/boxed.rs"
        }, 
        {
          "method": "std::sys::unix::thread::Thread::new::thread_start::hb5e40d3d934ebb7a", 
          "lineno": 71, 
          "filename": "/rustc/2fd73fabe469357a12c2c974c140f67e7cdd76d0/library/std/src/sys/unix/thread.rs"
        }, 
        {
          "method": "start_thread", 
          "filename": ""
        }, 
        {
          "method": "clone", 
          "filename": ""
        }
      ], 
      "exception": {
        "message": "dispatch dropped without returning error", 
        "class": "<panic>", 
        "description": "dispatch dropped without returning error"
      }
    }
  }, 
  "uuid": "f4c92254bf3e416ab6fb8e7db0d9b4ce", 
  "language": "rust", 
  "level": "error", 
  "timestamp": 1630532885, 
  "title": "dispatch dropped without returning error", 
  "custom": {}, 
  "environment": "PRODUCTION", 
  "framework": "unknown", 
  "metadata": {}
}

We have an Actix app (the actix::init_application in the trace) that at the very start does report_panics!, and then when an error occurs during any of the endpoint handlers we do:

                rollbar.build_report()
                    .from_message(&format!("{}", error))
                    .with_level("error")
                    .with_metadata(metadata_json)
                    .send();

We aren't using hyper anywhere else, aside from indirectly through rollbar-rs, so from what I can gather from the above trace, the rollbar.build_report()...send(); code panics within hyper with the dispatch dropped without returning error message, and that panic is caught in the hook set up by report_panics! and then successfully sent to Rollbar.

In the aforementioned hyper issue, @seanmonstar states (IIUC) that this panic can arise when the tokio executer drops the background tasks spawned by the hyper client before those tasks have managed to determine if the connection was closed, and that this can happen when the client is used from multiple executers.

I see in https://github.com/RoxasShadow/rollbar-rs/blob/b4ad68a3b5ae575e442e1e202de39761875954bb/src/lib.rs#L521-L537

Maybe there's something about how the client is used in conjunction with tokio's current_thread::Runtime that's not safe when using the same rollbar client (which then in turn means reusing the same hyper client)?

seanmonstar commented 3 years ago

(Got pinged, so I'll just chime in, I don't know anything about this project in particular.)

Reusing a client with a runtime that starts up and shuts down is indeed causing that panic. If you don't want to deal with async at all, you could consider replacing your usage with reqwest::blocking, which takes care of having the async stuff run in a single runtime, and exposes all methods as regular blocking ones.

cstrahan-blueshift commented 3 years ago

@seanmonstar Thanks for confirming (and for your work on your libraries)! And thank you @RoxasShadow et al for this library :slightly_smiling_face: .

We're currently working around this by not reusing the same client. With this confirmation, I could look into switching this lib over to using reqwest::blocking (time permitting).

cstrahan-blueshift commented 1 year ago

Can't switch to reqwest::blocking, because it's possible that Rollbar client will be used within a Tokio runtime, and reqwest::blocking starts its own Tokio runtime, which would result in errors like: https://github.com/seanmonstar/reqwest/issues/1017