tenant.openagents/omega

1//! # logger
2pub use log as log_impl;
3
4mod env_config;
5pub mod filter;
6pub mod sink;
7
8pub use sink::{flush, init_output_file, init_output_stderr, init_output_stdout};
9
10pub const SCOPE_DEPTH_MAX: usize = 4;
11
12pub fn init() {
13    if let Err(err) = try_init(None) {
14        log::error!("{err}");
15        eprintln!("{err}");
16    }
17}
18
19pub fn try_init(filter: Option<String>) -> anyhow::Result<()> {
20    log::set_logger(&ZLOG)?;
21    log::set_max_level(log::LevelFilter::max());
22    process_env(filter);
23    filter::refresh_from_settings(&std::collections::HashMap::default());
24    Ok(())
25}
26
27pub fn init_test() {
28    if get_env_config().is_some() && try_init(None).is_ok() {
29        init_output_stdout();
30    }
31}
32
33fn get_env_config() -> Option<String> {
34    std::env::var("ZED_LOG")
35        .or_else(|_| std::env::var("RUST_LOG"))
36        .ok()
37        .or_else(|| {
38            if std::env::var("CI").is_ok() {
39                Some("info".to_owned())
40            } else {
41                None
42            }
43        })
44}
45
46pub fn process_env(filter: Option<String>) {
47    let Some(env_config) = get_env_config().or(filter) else {
48        return;
49    };
50    match env_config::parse(&env_config) {
51        Ok(filter) => {
52            filter::init_env_filter(filter);
53        }
54        Err(err) => {
55            eprintln!("Failed to parse log filter: {}", err);
56        }
57    }
58}
59
60static ZLOG: Zlog = Zlog {};
61
62pub struct Zlog {}
63
64impl log::Log for Zlog {
65    fn enabled(&self, metadata: &log::Metadata) -> bool {
66        filter::is_possibly_enabled_level(metadata.level())
67    }
68
69    fn log(&self, record: &log::Record) {
70        if !self.enabled(record.metadata()) {
71            return;
72        }
73        let module_path = record.module_path().or(record.file());
74        let (crate_name_scope, module_scope) = match module_path {
75            Some(module_path) => {
76                let crate_name = private::extract_crate_name_from_module_path(module_path);
77                let crate_name_scope = private::scope_ref_new(&[crate_name]);
78                let module_scope = private::scope_ref_new(&[module_path]);
79                (crate_name_scope, module_scope)
80            }
81            None => {
82                // TODO: when do we hit this
83                (private::scope_new(&[]), private::scope_new(&["*unknown*"]))
84            }
85        };
86        let level = record.metadata().level();
87        if !filter::is_scope_enabled(&crate_name_scope, Some(record.target()), level) {
88            return;
89        }
90        sink::submit(sink::Record {
91            scope: module_scope,
92            level,
93            message: record.args(),
94            // PERF(batching): store non-static paths in a cache + leak them and pass static str here
95            module_path,
96            line: record.line(),
97        });
98    }
99
100    fn flush(&self) {
101        sink::flush();
102    }
103}
104
105#[macro_export]
106macro_rules! log {
107    ($logger:expr, $level:expr, $($arg:tt)+) => {
108        let level = $level;
109        let logger = $logger;
110        let enabled = $crate::filter::is_scope_enabled(&logger.scope, Some(module_path!()), level);
111        if enabled {
112            $crate::sink::submit($crate::sink::Record {
113                scope: logger.scope,
114                level,
115                message: &format_args!($($arg)+),
116                module_path: Some(module_path!()),
117                line: Some(line!()),
118            });
119        }
120    }
121}
122
123#[macro_export]
124macro_rules! trace {
125    ($logger:expr => $($arg:tt)+) => {
126        $crate::log!($logger, $crate::log_impl::Level::Trace, $($arg)+);
127    };
128    ($($arg:tt)+) => {
129        $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Trace, $($arg)+);
130    };
131}
132
133#[macro_export]
134macro_rules! debug {
135    ($logger:expr => $($arg:tt)+) => {
136        $crate::log!($logger, $crate::log_impl::Level::Debug, $($arg)+);
137    };
138    ($($arg:tt)+) => {
139        $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Debug, $($arg)+);
140    };
141}
142
143#[macro_export]
144macro_rules! info {
145    ($logger:expr => $($arg:tt)+) => {
146        $crate::log!($logger, $crate::log_impl::Level::Info, $($arg)+);
147    };
148    ($($arg:tt)+) => {
149        $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Info, $($arg)+);
150    };
151}
152
153#[macro_export]
154macro_rules! warn {
155    ($logger:expr => $($arg:tt)+) => {
156        $crate::log!($logger, $crate::log_impl::Level::Warn, $($arg)+);
157    };
158    ($($arg:tt)+) => {
159        $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Warn, $($arg)+);
160    };
161}
162
163#[macro_export]
164macro_rules! error {
165    ($logger:expr => $($arg:tt)+) => {
166        $crate::log!($logger, $crate::log_impl::Level::Error, $($arg)+);
167    };
168    ($($arg:tt)+) => {
169        $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Error, $($arg)+);
170    };
171}
172
173/// Creates a timer that logs the duration it was active for either when
174/// it is dropped, or when explicitly stopped using the `end` method.
175/// Logs at the `trace` level.
176/// Note that it will include time spent across await points
177/// (i.e. should not be used to measure the performance of async code)
178/// However, this is a feature not a bug, as it allows for a more accurate
179/// understanding of how long the action actually took to complete, including
180/// interruptions, which can help explain why something may have timed out,
181/// why it took longer to complete than it would have had the await points resolved
182/// immediately, etc.
183#[macro_export]
184macro_rules! time {
185    ($logger:expr => $name:expr) => {
186        $crate::Timer::new($logger, $name)
187    };
188    ($name:expr) => {
189        $crate::time!($crate::default_logger!() => $name)
190    };
191}
192
193#[macro_export]
194macro_rules! scoped {
195    ($parent:expr => $name:expr) => {{
196        $crate::scoped_logger($parent, $name)
197    }};
198    ($name:expr) => {
199        $crate::scoped!($crate::default_logger!() => $name)
200    };
201}
202
203pub const fn scoped_logger(parent: Logger, name: &'static str) -> Logger {
204    let mut scope = parent.scope;
205    let mut index = 1; // always have crate/module name
206    while index < scope.len() && !scope[index].is_empty() {
207        index += 1;
208    }
209    if index >= scope.len() {
210        #[cfg(debug_assertions)]
211        {
212            panic!("Scope overflow trying to add scope... ignoring scope");
213        }
214    }
215    scope[index] = name;
216    Logger { scope }
217}
218
219#[macro_export]
220macro_rules! default_logger {
221    () => {
222        $crate::Logger {
223            scope: $crate::private::scope_new(&[$crate::crate_name!()]),
224        }
225    };
226}
227
228#[macro_export]
229macro_rules! crate_name {
230    () => {
231        $crate::private::extract_crate_name_from_module_path(module_path!())
232    };
233}
234
235/// functions that are used in macros, and therefore must be public,
236/// but should not be used directly
237pub mod private {
238    use super::*;
239
240    pub const fn extract_crate_name_from_module_path(module_path: &str) -> &str {
241        let mut i = 0;
242        let mod_path_bytes = module_path.as_bytes();
243        let mut index = mod_path_bytes.len();
244        while i + 1 < mod_path_bytes.len() {
245            if mod_path_bytes[i] == b':' && mod_path_bytes[i + 1] == b':' {
246                index = i;
247                break;
248            }
249            i += 1;
250        }
251        let Some((crate_name, _)) = module_path.split_at_checked(index) else {
252            return module_path;
253        };
254        crate_name
255    }
256
257    pub const fn scope_new(scopes: &[&'static str]) -> Scope {
258        scope_ref_new(scopes)
259    }
260
261    pub const fn scope_ref_new<'a>(scopes: &[&'a str]) -> ScopeRef<'a> {
262        assert!(scopes.len() <= SCOPE_DEPTH_MAX);
263        let mut scope = [""; SCOPE_DEPTH_MAX];
264        let mut i = 0;
265        while i < scopes.len() {
266            scope[i] = scopes[i];
267            i += 1;
268        }
269        scope
270    }
271
272    pub fn scope_alloc_new(scopes: &[&str]) -> ScopeAlloc {
273        assert!(scopes.len() <= SCOPE_DEPTH_MAX);
274        let mut scope = [""; SCOPE_DEPTH_MAX];
275        scope[0..scopes.len()].copy_from_slice(scopes);
276        scope.map(|s| s.to_string())
277    }
278
279    pub fn scope_to_alloc(scope: &Scope) -> ScopeAlloc {
280        scope.map(|s| s.to_string())
281    }
282}
283
284pub type Scope = [&'static str; SCOPE_DEPTH_MAX];
285pub type ScopeRef<'a> = [&'a str; SCOPE_DEPTH_MAX];
286pub type ScopeAlloc = [String; SCOPE_DEPTH_MAX];
287const SCOPE_STRING_SEP_STR: &str = ".";
288const SCOPE_STRING_SEP_CHAR: char = '.';
289
290#[derive(Clone, Copy, Debug, PartialEq, Eq)]
291pub struct Logger {
292    pub scope: Scope,
293}
294
295impl log::Log for Logger {
296    fn enabled(&self, metadata: &log::Metadata) -> bool {
297        filter::is_possibly_enabled_level(metadata.level())
298    }
299
300    fn log(&self, record: &log::Record) {
301        if !self.enabled(record.metadata()) {
302            return;
303        }
304        let level = record.metadata().level();
305        if !filter::is_scope_enabled(&self.scope, Some(record.target()), level) {
306            return;
307        }
308        sink::submit(sink::Record {
309            scope: self.scope,
310            level,
311            message: record.args(),
312            module_path: record.module_path(),
313            line: record.line(),
314        });
315    }
316
317    fn flush(&self) {
318        sink::flush();
319    }
320}
321
322pub struct Timer {
323    pub logger: Logger,
324    pub start_time: std::time::Instant,
325    pub name: &'static str,
326    pub warn_if_longer_than: Option<std::time::Duration>,
327    pub done: bool,
328}
329
330impl Drop for Timer {
331    fn drop(&mut self) {
332        self.finish();
333    }
334}
335
336impl Timer {
337    #[must_use = "Timer will stop when dropped, the result of this function should be saved in a variable prefixed with `_` if it should stop when dropped"]
338    pub fn new(logger: Logger, name: &'static str) -> Self {
339        Self {
340            logger,
341            name,
342            start_time: std::time::Instant::now(),
343            warn_if_longer_than: None,
344            done: false,
345        }
346    }
347
348    pub fn warn_if_gt(mut self, warn_limit: std::time::Duration) -> Self {
349        self.warn_if_longer_than = Some(warn_limit);
350        self
351    }
352
353    pub fn end(mut self) {
354        self.finish();
355    }
356
357    fn finish(&mut self) {
358        if self.done {
359            return;
360        }
361        let elapsed = self.start_time.elapsed();
362        if let Some(warn_limit) = self.warn_if_longer_than
363            && elapsed > warn_limit
364        {
365            crate::warn!(
366                self.logger =>
367                "Timer '{}' took {:?}. Which was longer than the expected limit of {:?}",
368                self.name,
369                elapsed,
370                warn_limit
371            );
372            self.done = true;
373            return;
374        }
375        crate::trace!(
376            self.logger =>
377            "Timer '{}' finished in {:?}",
378            self.name,
379            elapsed
380        );
381        self.done = true;
382    }
383}
384
385#[cfg(test)]
386mod tests {
387    use super::*;
388
389    #[test]
390    fn test_crate_name() {
391        assert_eq!(crate_name!(), "zlog");
392        assert_eq!(
393            private::extract_crate_name_from_module_path("my_speedy_⚡️_crate::some_module"),
394            "my_speedy_⚡️_crate"
395        );
396        assert_eq!(
397            private::extract_crate_name_from_module_path("my_speedy_crate_⚡️::some_module"),
398            "my_speedy_crate_⚡️"
399        );
400        assert_eq!(
401            private::extract_crate_name_from_module_path("my_speedy_crate_:⚡️:some_module"),
402            "my_speedy_crate_:⚡️:some_module"
403        );
404        assert_eq!(
405            private::extract_crate_name_from_module_path("my_speedy_crate_::⚡️some_module"),
406            "my_speedy_crate_"
407        );
408    }
409}
410