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