[Bug Report] AsyncPoolSink may lose the last log records and panic on program exit #64
Description
Context: #63
Minimum reproducible example
use std::sync::Arc;
use spdlog::{
prelude::*,
sink::{AsyncPoolSink, FileSink},
};
fn main() -> Result<(), Box<dyn std::error::Error>> {
const LOG_FILE: &str = "/tmp/async_file_sink.log";
let file_sink = Arc::new(FileSink::builder().path(LOG_FILE).truncate(true).build()?);
let async_pool_sink = Arc::new(AsyncPoolSink::builder().sink(file_sink).build()?);
let logger = Arc::new(Logger::builder().sink(async_pool_sink).build()?);
logger.set_flush_level_filter(LevelFilter::All);
spdlog::set_default_logger(logger);
info!("hello async_pool_sink");
// Workaround, adding these 2 lines at the end of `main` function
//
// std::thread::sleep(std::time::Duration::from_millis(100));
// spdlog::default_logger().flush();
Ok(())
}Expected to see a log record in /tmp/async_file_sink.log but nothing there.
A guess is because the main function returns before AsyncPoolSink receives the last log task.
Another problem is that if we don't explicitly flush at the end, flush will be called in the atexit callback on program exit then there is a probability of panic.
thread '<unnamed>' panicked at library/std/src/thread/mod.rs:713:35:
use of std::thread::current() is not possible after the thread's local data has been destroyed
stack backtrace:
0: rust_begin_unwind
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/panicking.rs:645:5
1: core::panicking::panic_fmt
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panicking.rs:72:14
2: core::panicking::panic_display
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panicking.rs:178:5
3: core::panicking::panic_str
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/panicking.rs:152:5
4: core::option::expect_failed
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/option.rs:1985:5
5: core::option::Option<T>::expect
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/option.rs:894:21
6: std::thread::current
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/thread/mod.rs:713:35
7: crossbeam_channel::waker::current_thread_id::THREAD_ID::__init
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/crossbeam-channel-0.5.11/src/waker.rs:280:38
8: crossbeam_channel::waker::current_thread_id::THREAD_ID::__getit::{{closure}}
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/sys/common/thread_local/fast_local.rs:99:25
9: std::sys::common::thread_local::lazy::LazyKeyInner<T>::initialize
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/sys/common/thread_local/mod.rs:54:25
10: std::sys::common::thread_local::fast_local::Key<T>::try_initialize
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/sys/common/thread_local/fast_local.rs:190:27
11: std::sys::common::thread_local::fast_local::Key<T>::get
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/sys/common/thread_local/fast_local.rs:173:25
12: crossbeam_channel::waker::current_thread_id::THREAD_ID::__getit
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/sys/common/thread_local/fast_local.rs:91:21
13: std::thread::local::LocalKey<T>::try_with
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/thread/local.rs:269:32
14: crossbeam_channel::waker::current_thread_id
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/crossbeam-channel-0.5.11/src/waker.rs:283:5
15: crossbeam_channel::waker::Waker::try_select
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/crossbeam-channel-0.5.11/src/waker.rs:83:29
16: crossbeam_channel::waker::SyncWaker::notify
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/crossbeam-channel-0.5.11/src/waker.rs:224:17
17: crossbeam_channel::flavors::array::Channel<T>::write
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/crossbeam-channel-0.5.11/src/flavors/array.rs:226:9
18: crossbeam_channel::flavors::array::Channel<T>::send
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/crossbeam-channel-0.5.11/src/flavors/array.rs:343:40
19: crossbeam_channel::channel::Sender<T>::send
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/crossbeam-channel-0.5.11/src/channel.rs:437:42
20: spdlog::thread_pool::ThreadPool::assign_task
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/spdlog-rs-0.3.13/src/thread_pool.rs:68:38
21: spdlog::sink::async_sink::async_pool_sink::AsyncPoolSink::assign_task
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/spdlog-rs-0.3.13/src/sink/async_sink/async_pool_sink.rs:60:9
22: <spdlog::sink::async_sink::async_pool_sink::AsyncPoolSink as spdlog::sink::Sink>::flush
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/spdlog-rs-0.3.13/src/sink/async_sink/async_pool_sink.rs:81:9
23: spdlog::logger::Logger::flush_sinks::{{closure}}
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/spdlog-rs-0.3.13/src/logger.rs:404:31
24: <core::slice::iter::Iter<T> as core::iter::traits::iterator::Iterator>::for_each
at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/slice/iter/macros.rs:254:21
25: spdlog::logger::Logger::flush_sinks
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/spdlog-rs-0.3.13/src/logger.rs:403:9
26: spdlog::logger::Logger::flush
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/spdlog-rs-0.3.13/src/logger.rs:160:9
27: spdlog::flush_default_logger_at_exit::handler
at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/spdlog-rs-0.3.13/src/lib.rs:656:13
28: <unknown>
29: exit
30: <unknown>
31: __libc_start_main
32: _start
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
fatal runtime error: failed to initiate panic, error 5
fish: Job 1, 'RUST_BACKTRACE=1 cargo run' terminated by signal SIGABRT (Abort)
This might be a bit hard to fix (the reason may be related to signal-safety, see #18 (comment)), but it shouldn't happen and is worth mentioning here and giving it a try.