debug_assert! triggered in tracing-appender in the RollingFileAppender

[adumbidiot]

Bug Report

Version

tracing v0.1.32
tracing-attributes v0.1.20
tracing-core v0.1.23
tracing-futures v0.2.5
tracing-appender v0.2.1
tracing-subscriber v0.3.9
tracing-log v0.1.2
tracing-opentelemetry v0.17.2

Platform

Windows 10 64 bit 21H2

Crates

tracing-appender 0.2.1

Description

I get intermittent panics from a debug assert in one of my projects from tracing-appender. Here's a backtrace:

thread '<unnamed>' panicked at 'if we have &mut access to the appender, no other thread can have advanced the timestamp...', C:\Users\nathaniel\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-appender-0.2.1\src\rolling.rs:176:13
stack backtrace:
   0:     0x7ff687f7c91f - std::backtrace_rs::backtrace::dbghelp::trace
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\..\..\backtrace\src\backtrace\dbghelp.rs:98
   1:     0x7ff687f7c91f - std::backtrace_rs::backtrace::trace_unsynchronized
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2:     0x7ff687f7c91f - std::sys_common::backtrace::_print_fmt
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\sys_common\backtrace.rs:66
   3:     0x7ff687f7c91f - std::sys_common::backtrace::_print::impl$0::fmt
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\sys_common\backtrace.rs:45
   4:     0x7ff687f95bfa - core::fmt::write
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\core\src\fmt\mod.rs:1190
   5:     0x7ff687f75499 - std::io::Write::write_fmt<std::sys::windows::stdio::Stderr>
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\io\mod.rs:1655
   6:     0x7ff687f7f09b - std::sys_common::backtrace::_print
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\sys_common\backtrace.rs:48
   7:     0x7ff687f7f09b - std::sys_common::backtrace::print
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\sys_common\backtrace.rs:35
   8:     0x7ff687f7f09b - std::panicking::default_hook::closure$1
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\panicking.rs:295
   9:     0x7ff687f7ec8e - std::panicking::default_hook
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\panicking.rs:314
  10:     0x7ff687f7f691 - std::panicking::rust_panic_with_hook
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\panicking.rs:698
  11:     0x7ff687c982c3 - std::panicking::begin_panic::closure$0<str>
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\panicking.rs:617
  12:     0x7ff687c9e17f - std::sys_common::backtrace::__rust_end_short_backtrace<std::panicking::begin_panic::closure_env$0<str>,never$>
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\sys_common\backtrace.rs:138
  13:     0x7ff687c981df - std::panicking::begin_panic<str>
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\panicking.rs:616
  14:     0x7ff6867e2fbd - tracing_appender::rolling::impl$1::write
                               at C:\Users\nathaniel\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-appender-0.2.1\src\rolling.rs:176
  15:     0x7ff685f4b565 - std::io::Write::write_all<tracing_appender::rolling::RollingFileAppender>
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\io\mod.rs:1515
  16:     0x7ff6861bbab2 - tracing_appender::worker::Worker<tracing_appender::rolling::RollingFileAppender>::handle_recv<tracing_appender::rolling::RollingFileAppender>
                               at C:\Users\nathaniel\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-appender-0.2.1\src\worker.rs:33
  17:     0x7ff6861bbfad - tracing_appender::worker::Worker<tracing_appender::rolling::RollingFileAppender>::work<tracing_appender::rolling::RollingFileAppender>
                               at C:\Users\nathaniel\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-appender-0.2.1\src\worker.rs:58
  18:     0x7ff6861bbb7d - tracing_appender::worker::impl$0::worker_thread::closure$0<tracing_appender::rolling::RollingFileAppender>
                               at C:\Users\nathaniel\.cargo\registry\src\github.com-1ecc6299db9ec823\tracing-appender-0.2.1\src\worker.rs:73
  19:     0x7ff686244344 - std::sys_common::backtrace::__rust_begin_short_backtrace<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<> >
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\sys_common\backtrace.rs:122
  20:     0x7ff686182024 - std::thread::impl$0::spawn_unchecked_::closure$1::closure$0<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<> >
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\thread\mod.rs:498
  21:     0x7ff685f85944 - core::panic::unwind_safe::impl$23::call_once<tuple$<>,std::thread::impl$0::spawn_unchecked_::closure$1::closure_env$0<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<> > >
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\core\src\panic\unwind_safe.rs:271
  22:     0x7ff6861cfe51 - std::panicking::try::do_call<core::panic::unwind_safe::AssertUnwindSafe<std::thread::impl$0::spawn_unchecked_::closure$1::closure_env$0<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<>
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\panicking.rs:492
  23:     0x7ff6861d66a3 - std::panicking::try::do_catch<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::impl$1::complete::closure_env$0<tokio::runtime::blocking::task::BlockingTask<async_rusqlite::impl$2::open::async_fn$0::closure_env$0<pikadick::database
  24:     0x7ff6861c9c0b - std::panicking::try<tuple$<>,core::panic::unwind_safe::AssertUnwindSafe<std::thread::impl$0::spawn_unchecked_::closure$1::closure_env$0<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<>
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\panicking.rs:456
  25:     0x7ff686186524 - std::panic::catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<std::thread::impl$0::spawn_unchecked_::closure$1::closure_env$0<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<> > >
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\panic.rs:137
  26:     0x7ff686181a6f - std::thread::impl$0::spawn_unchecked_::closure$1<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<> >
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\std\src\thread\mod.rs:497
  27:     0x7ff68606879e - core::ops::function::FnOnce::call_once<std::thread::impl$0::spawn_unchecked_::closure_env$1<tracing_appender::worker::impl$0::worker_thread::closure_env$0<tracing_appender::rolling::RollingFileAppender>,tuple$<> >,tuple$<> >
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\core\src\ops\function.rs:227
  28:     0x7ff687f82dcc - alloc::boxed::impl$44::call_once
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\alloc\src\boxed.rs:1853
  29:     0x7ff687f82dcc - alloc::boxed::impl$44::call_once
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\library\alloc\src\boxed.rs:1853
  30:     0x7ff687f82dcc - std::sys::windows::thread::impl$0::new::thread_start
                               at /rustc/335ffbfa547df94ac236f5c56130cecf99c8d82b\/library\std\src\sys\windows\thread.rs:57
  31:     0x7ff93a4d7034 - BaseThreadInitThunk
  32:     0x7ff93c4a2651 - RtlUserThreadStart

I would expect this assert to not be triggered.

[davidbarsky]

Sorry about that. This issue was resolved in #1989, but it wasn't released. I'll backport that change and open a PR fixing this issue.

In the meantime, I'l close this issue as it's a dupe of #1987.