Panic at already BorrowMutError

[rtyler]

I was doing some load testing on a small Rust application which is using async-std. At some threshold while load testing dipstick causes the application to panic.

I'm basically just using the statsd interface, and only have a few counters in the application. I don't have a great test case since this happens for the full application, but if the stacktrace below isn't sufficient, I can share the whole (open source) application with details on how to run the load test.

    let metrics = Arc::new(Statsd::send_to(&settings.global.metrics.statsd)
        .expect("Failed to create Statsd recorder")
        .named("hotdog")
        .metrics());

thread 'async-std/executor' panicked at 'already borrowed: BorrowMutError', /rustc/b8cedc00407a4c56a3bda1ed605c6fc166655447/src/libcore/cell.rs:878:9
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:77
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1052
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1426
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:204
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:224
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:472
  11: rust_begin_unwind
             at src/libstd/panicking.rs:380
  12: core::panicking::panic_fmt
             at src/libcore/panicking.rs:85
  13: core::option::expect_none_failed
             at src/libcore/option.rs:1199
  14: dipstick::output::statsd::StatsdScope::print
  15: <dipstick::output::statsd::StatsdScope as dipstick::core::output::OutputScope>::new_metric::{{closure}}
  16: <dipstick::core::locking::LockingOutput as dipstick::core::input::InputScope>::new_metric::{{closure}}
  17: dipstick::core::input::Counter::count
  18: <std::future::GenFuture<T> as core::future::future::Future>::poll
  19: async_task::raw::RawTask<F,R,S,T>::run
  20: std::thread::local::LocalKey<T>::with
  21: async_std::task::executor::pool::main_loop
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
thread 'main' panicked at 'LockingOutput: "PoisonError { inner: .. }"', /home/tyler/.cargo/registry/src/github.com-1ecc6299db9ec823/dipstick-0.7.11/src/core/locking.rs:44:26
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:77
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1052
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1426
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:204
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:224
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:472
  11: rust_begin_unwind
             at src/libstd/panicking.rs:380
  12: core::panicking::panic_fmt
             at src/libcore/panicking.rs:85
  13: core::option::expect_none_failed
             at src/libcore/option.rs:1199
  14: <dipstick::core::locking::LockingOutput as dipstick::core::input::InputScope>::new_metric::{{closure}}
  15: dipstick::core::input::Counter::count
  16: <std::future::GenFuture<T> as core::future::future::Future>::poll
  17: std::thread::local::LocalKey<T>::with
  18: std::thread::local::LocalKey<T>::with
  19: async_std::task::block_on::block_on
  20: hotdog::main
  21: std::rt::lang_start::{{closure}}
  22: std::rt::lang_start_internal::{{closure}}
             at src/libstd/rt.rs:52
  23: std::panicking::try::do_call
             at src/libstd/panicking.rs:305
  24: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:86
  25: std::panicking::try
             at src/libstd/panicking.rs:281
  26: std::panic::catch_unwind
             at src/libstd/panic.rs:394
  27: std::rt::lang_start_internal
             at src/libstd/rt.rs:51
  28: main
  29: __libc_start_main
  30: <unknown>
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

[fralalonde]

That's interesting, I had't tried it Dipstick yet on async. Doing so might have revealed a usage pattern that causes it to fail. I'll look into it, I suspect there was some overconfidence involved for the sake of insignificant performance gains.

[fralalonde]

I've released Dipstick v0.7.12, which uses RwLock instead of RefCell to hold statsd & graphite text buffers. I assume running under async breaked some thread safety or reentrance assumption. Let me know if this fixes it.

[rtyler]

Hah! I'm pleased to share @fralalonde that 0.7.12 does not panic under the same intense load testing 🌭

Thanks!