captains_log/
ring.rs

1use crate::{
2    config::{LogFormat, SinkConfigBuild, SinkConfigTrait},
3    log_impl::{LogSink, LogSinkTrait},
4    time::Timer,
5};
6use log::*;
7use ring_file::*;
8
9use std::cell::UnsafeCell;
10use std::hash::{Hash, Hasher};
11use std::io::Write;
12use std::mem::transmute;
13use std::path::{Path, PathBuf};
14use std::sync::atomic::{AtomicBool, Ordering};
15
16/// The LogRingFile sink is a tool for debugging deadlock or race condition,
17/// when the problem cannot be reproduce with ordinary log (because disk I/O will slow down the
18/// execution and prevent the bug to occur).
19///
20/// # Usage
21///
22/// Enable feature `ringfile` in your Cargo.toml.
23///
24/// Replace the log setup with the following [recipe::ring_file()](crate::recipe::ring_file()) in your test case:
25///
26///(Set the level to Info or higher, to turn off other debugging logs.)
27///
28/// ``` rust
29/// use captains_log::*;
30/// // the recipe already register signal and dynamic=true, do not use test(),
31/// // because test() will clear the signal.
32/// recipe::ring_file("/tmp/ring.log", 512*1024*1024, Level::Info,
33///     signal_consts::SIGHUP).build().expect("log setup");
34/// ```
35///
36/// Then add some high-level log to critical path in the code, try to reproduce the problem, and
37/// reduce the amount of log if the bug not occur.
38///
39/// On start-up, it will create a limited-size ring-buffer-like memory. The log content will be held within memory but
40/// not written to disk, old logs will be overwritten by new ones. Until specified signal arrives, the last
41/// part of log message will be dumped to the file, in time order.
42///
43/// Once your program hangs up completely, find your process PID and send a signal to it.
44///
45/// ``` shell
46/// kill -SIGHUP <pid>
47/// ```
48/// There will be messages printed to stdout:
49///
50/// ``` text
51/// RingFile: start dumping
52/// RingFile: dump complete
53/// ```
54///
55/// Then you can inspect your log content on disk (for this example `/tmp/ring.log`).
56///
57/// The backend is provided by [RingFile crate](https://docs.rs/ring-file). To ensure low
58/// latency, the buffer is protected by a spinlock instead of a mutex. After the program hangs, because
59/// no more messages will be written to the buffer, log content can be safely copied from the buffer area to disk.
60///
61/// Be aware that it did not use mlock to prevent memory from being swapping. (Swapping might make the
62/// code slow to prevent bug reproduction). When your memory is not enough, use a smaller buf_size and turn off the swap with `swapoff -a`.
63///
64/// A real-life debugging story can be found on <https://github.com/frostyplanet/crossfire-rs/issues/24>.
65#[derive(Hash)]
66pub struct LogRingFile {
67    pub file_path: Box<Path>,
68    pub level: Level,
69    pub format: LogFormat,
70    /// 0 < buf_size < i32::MAX
71    pub buf_size: i32,
72}
73
74impl LogRingFile {
75    pub fn new<P: Into<PathBuf>>(
76        file_path: P, buf_size: i32, max_level: Level, format: LogFormat,
77    ) -> Self {
78        assert!(buf_size > 0);
79        Self { buf_size, file_path: file_path.into().into_boxed_path(), level: max_level, format }
80    }
81}
82
83impl SinkConfigBuild for LogRingFile {
84    fn build(&self) -> LogSink {
85        LogSink::RingFile(LogSinkRingFile::new(self))
86    }
87}
88
89impl SinkConfigTrait for LogRingFile {
90    fn get_level(&self) -> Level {
91        self.level
92    }
93
94    fn get_file_path(&self) -> Option<Box<Path>> {
95        Some(self.file_path.clone())
96    }
97
98    fn write_hash(&self, hasher: &mut Box<dyn Hasher>) {
99        self.hash(hasher);
100        hasher.write(b"LogRingFile");
101    }
102}
103
104pub(crate) struct LogSinkRingFile {
105    max_level: Level,
106    inner: UnsafeCell<RingFile>,
107    formatter: LogFormat,
108    /// In order to be fast, use a spin lock instead of Mutex
109    locked: AtomicBool,
110}
111
112unsafe impl Send for LogSinkRingFile {}
113unsafe impl Sync for LogSinkRingFile {}
114
115impl LogSinkRingFile {
116    fn new(config: &LogRingFile) -> Self {
117        Self {
118            max_level: config.level,
119            inner: UnsafeCell::new(RingFile::new(config.buf_size, config.file_path.to_path_buf())),
120            formatter: config.format.clone(),
121            locked: AtomicBool::new(false),
122        }
123    }
124
125    #[inline(always)]
126    fn get_inner(&self) -> &RingFile {
127        unsafe { transmute(self.inner.get()) }
128    }
129
130    #[inline(always)]
131    fn get_inner_mut(&self) -> &mut RingFile {
132        unsafe { transmute(self.inner.get()) }
133    }
134}
135
136impl LogSinkTrait for LogSinkRingFile {
137    fn open(&self) -> std::io::Result<()> {
138        println!("ringfile is on");
139        Ok(())
140    }
141
142    fn reopen(&self) -> std::io::Result<()> {
143        println!("RingFile: start dumping");
144        if let Err(e) = self.get_inner().dump() {
145            println!("RingFile: dump error {:?}", e);
146            Err(e)
147        } else {
148            println!("RingFile: dump complete");
149            Ok(())
150        }
151    }
152
153    #[inline(always)]
154    fn log(&self, now: &Timer, r: &Record) {
155        if r.level() <= self.max_level {
156            let buf = self.formatter.process(now, r);
157            while self
158                .locked
159                .compare_exchange_weak(false, true, Ordering::SeqCst, Ordering::Relaxed)
160                .is_err()
161            {
162                std::hint::spin_loop();
163            }
164            let _ = self.get_inner_mut().write_all(buf.as_bytes());
165            self.locked.store(false, Ordering::Release);
166        }
167    }
168
169    #[inline(always)]
170    fn flush(&self) {}
171}
captains_log/ring.rs

captains_log/
ring.rs
