mirui/core/log/
mod.rs

1extern crate alloc;
2
3use alloc::boxed::Box;
4use alloc::vec::Vec;
5use core::sync::atomic::{AtomicU8, Ordering};
6
7pub mod sinks;
8
9#[derive(Clone, Copy, Debug, PartialEq, Eq, PartialOrd, Ord)]
10#[repr(u8)]
11pub enum Level {
12    Error = 1,
13    Warn = 2,
14    Info = 3,
15    Debug = 4,
16    Trace = 5,
17}
18
19impl Level {
20    pub fn as_str(self) -> &'static str {
21        match self {
22            Level::Error => "ERROR",
23            Level::Warn => "WARN",
24            Level::Info => "INFO",
25            Level::Debug => "DEBUG",
26            Level::Trace => "TRACE",
27        }
28    }
29}
30
31pub struct Metadata {
32    pub level: Level,
33    pub target: &'static str,
34}
35
36pub struct Event<'a> {
37    pub meta: &'static Metadata,
38    pub time_ns: u64,
39    pub args: &'a core::fmt::Arguments<'a>,
40}
41
42#[derive(Clone, Copy)]
43pub struct SpanRecord {
44    pub name: &'static str,
45    pub start_ns: u64,
46    pub end_ns: u64,
47    pub depth: u8,
48}
49
50impl SpanRecord {
51    pub fn elapsed_ns(&self) -> u64 {
52        self.end_ns.saturating_sub(self.start_ns)
53    }
54}
55
56pub trait Sink: Send + Sync {
57    fn emit(&self, event: &Event<'_>);
58    fn emit_span(&self, _span: &SpanRecord) {}
59    fn enabled(&self, _level: Level, _target: &'static str) -> bool {
60        true
61    }
62    fn flush(&self) {}
63}
64
65static MAX_LEVEL: AtomicU8 = AtomicU8::new(Level::Info as u8);
66
67pub fn set_max_level(level: Level) {
68    MAX_LEVEL.store(level as u8, Ordering::Relaxed);
69}
70
71pub fn max_level() -> Level {
72    match MAX_LEVEL.load(Ordering::Relaxed) {
73        1 => Level::Error,
74        2 => Level::Warn,
75        3 => Level::Info,
76        4 => Level::Debug,
77        _ => Level::Trace,
78    }
79}
80
81pub const STATIC_MAX_LEVEL: u8 = static_max_level();
82
83const fn static_max_level() -> u8 {
84    if cfg!(feature = "log-max-level-off") {
85        0
86    } else if cfg!(feature = "log-max-level-error") {
87        Level::Error as u8
88    } else if cfg!(feature = "log-max-level-warn") {
89        Level::Warn as u8
90    } else if cfg!(feature = "log-max-level-info") {
91        Level::Info as u8
92    } else if cfg!(feature = "log-max-level-debug") {
93        Level::Debug as u8
94    } else if cfg!(feature = "log-max-level-trace") {
95        Level::Trace as u8
96    } else {
97        u8::MAX
98    }
99}
100
101#[inline]
102pub fn level_enabled(level: Level, _target: &'static str) -> bool {
103    (level as u8) <= MAX_LEVEL.load(Ordering::Relaxed)
104}
105
106#[cfg(feature = "std")]
107mod registry {
108    use super::*;
109    use std::sync::{OnceLock, RwLock};
110
111    static REGISTRY: OnceLock<RwLock<Vec<Box<dyn Sink>>>> = OnceLock::new();
112
113    fn slots() -> &'static RwLock<Vec<Box<dyn Sink>>> {
114        REGISTRY.get_or_init(|| RwLock::new(Vec::new()))
115    }
116
117    pub fn install(sink: Box<dyn Sink>) {
118        slots().write().expect("log registry poisoned").push(sink);
119    }
120
121    pub fn clear() {
122        slots().write().expect("log registry poisoned").clear();
123    }
124
125    pub fn dispatch_to_all(event: &Event<'_>) {
126        let guard = slots().read().expect("log registry poisoned");
127        for sink in guard.iter() {
128            if sink.enabled(event.meta.level, event.meta.target) {
129                sink.emit(event);
130            }
131        }
132    }
133
134    pub fn dispatch_span_to_all(span: &SpanRecord) {
135        let guard = slots().read().expect("log registry poisoned");
136        for sink in guard.iter() {
137            sink.emit_span(span);
138        }
139    }
140}
141
142#[cfg(not(feature = "std"))]
143mod registry {
144    use super::*;
145
146    struct State {
147        sinks: Vec<Box<dyn Sink>>,
148    }
149
150    static mut STATE: State = State { sinks: Vec::new() };
151
152    fn with_state<R>(f: impl FnOnce(&mut State) -> R) -> R {
153        critical_section::with(|_| {
154            #[allow(static_mut_refs)]
155            unsafe {
156                f(&mut STATE)
157            }
158        })
159    }
160
161    pub fn install(sink: Box<dyn Sink>) {
162        with_state(|s| s.sinks.push(sink));
163    }
164
165    pub fn clear() {
166        with_state(|s| s.sinks.clear());
167    }
168
169    pub fn dispatch_to_all(event: &Event<'_>) {
170        with_state(|s| {
171            for sink in s.sinks.iter() {
172                if sink.enabled(event.meta.level, event.meta.target) {
173                    sink.emit(event);
174                }
175            }
176        });
177    }
178
179    pub fn dispatch_span_to_all(span: &SpanRecord) {
180        with_state(|s| {
181            for sink in s.sinks.iter() {
182                sink.emit_span(span);
183            }
184        });
185    }
186}
187
188pub fn install_sink(sink: Box<dyn Sink>) {
189    registry::install(sink);
190}
191
192pub fn clear_sinks() {
193    registry::clear();
194}
195
196pub fn dispatch(meta: &'static Metadata, args: core::fmt::Arguments<'_>) {
197    let event = Event {
198        meta,
199        time_ns: clock_now_ns(),
200        args: &args,
201    };
202    registry::dispatch_to_all(&event);
203}
204
205pub fn dispatch_span(span: &SpanRecord) {
206    registry::dispatch_span_to_all(span);
207}
208
209fn clock_now_ns() -> u64 {
210    crate::core::time::clock_now_ns()
211}
212
213#[macro_export]
214macro_rules! __mirui_log {
215    (target: $target:expr, $lvl:expr, $($arg:tt)+) => {{
216        static META: $crate::core::log::Metadata = $crate::core::log::Metadata {
217            level: $lvl,
218            target: $target,
219        };
220        if (META.level as u8) <= $crate::core::log::STATIC_MAX_LEVEL
221            && $crate::core::log::level_enabled(META.level, META.target)
222        {
223            $crate::core::log::dispatch(&META, ::core::format_args!($($arg)+));
224        }
225    }};
226    ($lvl:expr, $($arg:tt)+) => {{
227        static META: $crate::core::log::Metadata = $crate::core::log::Metadata {
228            level: $lvl,
229            target: ::core::module_path!(),
230        };
231        if (META.level as u8) <= $crate::core::log::STATIC_MAX_LEVEL
232            && $crate::core::log::level_enabled(META.level, META.target)
233        {
234            $crate::core::log::dispatch(&META, ::core::format_args!($($arg)+));
235        }
236    }};
237}
238
239#[macro_export]
240macro_rules! error {
241    (target: $target:expr, $($arg:tt)+) => (
242        $crate::__mirui_log!(target: $target, $crate::core::log::Level::Error, $($arg)+)
243    );
244    ($($arg:tt)+) => (
245        $crate::__mirui_log!($crate::core::log::Level::Error, $($arg)+)
246    );
247}
248
249#[macro_export]
250macro_rules! warn {
251    (target: $target:expr, $($arg:tt)+) => (
252        $crate::__mirui_log!(target: $target, $crate::core::log::Level::Warn, $($arg)+)
253    );
254    ($($arg:tt)+) => (
255        $crate::__mirui_log!($crate::core::log::Level::Warn, $($arg)+)
256    );
257}
258
259#[macro_export]
260macro_rules! info {
261    (target: $target:expr, $($arg:tt)+) => (
262        $crate::__mirui_log!(target: $target, $crate::core::log::Level::Info, $($arg)+)
263    );
264    ($($arg:tt)+) => (
265        $crate::__mirui_log!($crate::core::log::Level::Info, $($arg)+)
266    );
267}
268
269#[macro_export]
270macro_rules! debug {
271    (target: $target:expr, $($arg:tt)+) => (
272        $crate::__mirui_log!(target: $target, $crate::core::log::Level::Debug, $($arg)+)
273    );
274    ($($arg:tt)+) => (
275        $crate::__mirui_log!($crate::core::log::Level::Debug, $($arg)+)
276    );
277}
278
279#[macro_export]
280macro_rules! trace {
281    (target: $target:expr, $($arg:tt)+) => (
282        $crate::__mirui_log!(target: $target, $crate::core::log::Level::Trace, $($arg)+)
283    );
284    ($($arg:tt)+) => (
285        $crate::__mirui_log!($crate::core::log::Level::Trace, $($arg)+)
286    );
287}
288
289#[cfg(test)]
290mod tests {
291    use super::*;
292    use alloc::string::{String, ToString};
293    use alloc::sync::Arc;
294    use core::fmt::Write;
295    use std::sync::Mutex;
296
297    struct CaptureSink {
298        rows: Arc<Mutex<Vec<String>>>,
299    }
300
301    impl Sink for CaptureSink {
302        fn emit(&self, event: &Event<'_>) {
303            let mut msg = String::new();
304            write!(&mut msg, "{}", event.args).unwrap();
305            self.rows.lock().unwrap().push(alloc::format!(
306                "{}:{}:{}",
307                event.meta.level.as_str(),
308                event.meta.target,
309                msg
310            ));
311        }
312    }
313
314    fn install_capture() -> Arc<Mutex<Vec<String>>> {
315        clear_sinks();
316        let rows: Arc<Mutex<Vec<String>>> = Arc::new(Mutex::new(Vec::new()));
317        install_sink(Box::new(CaptureSink { rows: rows.clone() }));
318        rows
319    }
320
321    #[test]
322    fn static_max_level_default_is_open() {
323        assert_eq!(STATIC_MAX_LEVEL, u8::MAX);
324    }
325
326    #[test]
327    fn level_ordering() {
328        assert!(Level::Error < Level::Warn);
329        assert!(Level::Warn < Level::Info);
330        assert!(Level::Info < Level::Debug);
331        assert!(Level::Debug < Level::Trace);
332    }
333
334    #[test]
335    fn info_reaches_sink() {
336        let _lock = TEST_MUTEX.lock().unwrap();
337        set_max_level(Level::Info);
338        let rows = install_capture();
339        crate::info!("hello {}", 42);
340        let captured = rows.lock().unwrap().clone();
341        assert_eq!(captured.len(), 1);
342        assert!(captured[0].starts_with("INFO:"));
343        assert!(captured[0].ends_with(":hello 42"));
344    }
345
346    #[test]
347    fn debug_gated_by_max_level() {
348        let _lock = TEST_MUTEX.lock().unwrap();
349        set_max_level(Level::Info);
350        let rows = install_capture();
351        crate::debug!("shhh {}", 7);
352        assert!(rows.lock().unwrap().is_empty());
353        set_max_level(Level::Debug);
354        crate::debug!("now {}", 8);
355        assert_eq!(rows.lock().unwrap().len(), 1);
356    }
357
358    #[test]
359    fn filter_miss_short_circuits_args() {
360        let _lock = TEST_MUTEX.lock().unwrap();
361        set_max_level(Level::Error);
362        install_capture();
363        let mut side_effect = 0;
364        crate::info!("{}", {
365            side_effect += 1;
366            "boom"
367        });
368        assert_eq!(side_effect, 0, "format_args should not evaluate when gated");
369    }
370
371    #[test]
372    fn debug_format_works() {
373        let _lock = TEST_MUTEX.lock().unwrap();
374        set_max_level(Level::Info);
375        let rows = install_capture();
376        let v = alloc::vec![1u32, 2, 3];
377        crate::info!("{:?}", v);
378        let captured = rows.lock().unwrap().clone();
379        assert!(captured[0].ends_with(":[1, 2, 3]"), "got {:?}", captured);
380    }
381
382    #[test]
383    fn custom_target() {
384        let _lock = TEST_MUTEX.lock().unwrap();
385        set_max_level(Level::Info);
386        let rows = install_capture();
387        crate::warn!(target: "mirui::custom", "x");
388        let captured = rows.lock().unwrap().clone();
389        assert!(
390            captured[0].starts_with("WARN:mirui::custom:"),
391            "got {:?}",
392            captured
393        );
394    }
395
396    #[test]
397    fn dispatch_fans_out_to_all_sinks() {
398        let _lock = TEST_MUTEX.lock().unwrap();
399        set_max_level(Level::Info);
400        clear_sinks();
401        let a: Arc<Mutex<Vec<String>>> = Arc::new(Mutex::new(Vec::new()));
402        let b: Arc<Mutex<Vec<String>>> = Arc::new(Mutex::new(Vec::new()));
403        install_sink(Box::new(CaptureSink { rows: a.clone() }));
404        install_sink(Box::new(CaptureSink { rows: b.clone() }));
405        crate::info!("fan-out {}", 1);
406        assert_eq!(a.lock().unwrap().len(), 1);
407        assert_eq!(b.lock().unwrap().len(), 1);
408    }
409
410    #[test]
411    fn span_dispatch_reaches_sinks() {
412        let _lock = TEST_MUTEX.lock().unwrap();
413        set_max_level(Level::Info);
414
415        struct SpanCapture(Arc<Mutex<Vec<(&'static str, u64)>>>);
416        impl Sink for SpanCapture {
417            fn emit(&self, _: &Event<'_>) {}
418            fn emit_span(&self, span: &SpanRecord) {
419                self.0.lock().unwrap().push((span.name, span.elapsed_ns()));
420            }
421        }
422
423        clear_sinks();
424        let rows: Arc<Mutex<Vec<(&'static str, u64)>>> = Arc::new(Mutex::new(Vec::new()));
425        install_sink(Box::new(SpanCapture(rows.clone())));
426
427        crate::core::perf::set_enabled(true);
428        {
429            let _g = crate::core::perf::enter("test.span");
430        }
431        crate::core::perf::set_enabled(false);
432        let _ = crate::core::perf::drain_events();
433
434        let captured = rows.lock().unwrap().clone();
435        assert_eq!(captured.len(), 1);
436        assert_eq!(captured[0].0, "test.span");
437    }
438
439    #[test]
440    fn sink_enabled_gate_skips_emit() {
441        let _lock = TEST_MUTEX.lock().unwrap();
442        set_max_level(Level::Trace);
443
444        struct MinInfo(Arc<Mutex<Vec<String>>>);
445        impl Sink for MinInfo {
446            fn emit(&self, event: &Event<'_>) {
447                self.0
448                    .lock()
449                    .unwrap()
450                    .push(event.meta.level.as_str().to_string());
451            }
452            fn enabled(&self, level: Level, _target: &'static str) -> bool {
453                level <= Level::Info
454            }
455        }
456
457        clear_sinks();
458        let rows: Arc<Mutex<Vec<String>>> = Arc::new(Mutex::new(Vec::new()));
459        install_sink(Box::new(MinInfo(rows.clone())));
460        crate::info!("keep");
461        crate::debug!("drop");
462        let captured = rows.lock().unwrap().clone();
463        assert_eq!(captured, alloc::vec!["INFO".to_string()]);
464    }
465
466    static TEST_MUTEX: std::sync::Mutex<()> = std::sync::Mutex::new(());
467}
mirui/core/log/mod.rs

mirui/core/log/
mod.rs
