1//! # logger
2pub use log as log_impl;
3
4pub const SCOPE_DEPTH_MAX: usize = 4;
5
6/// because we are currently just wrapping the `log` crate in `zlog`,
7/// we need to work around the fact that the `log` crate only provides a
8/// single global level filter. In order to have more precise control until
9/// we no longer wrap `log`, we bump up the priority of log level so that it
10/// will be logged, even if the actual level is lower
11/// This is fine for now, as we use a `info` level filter by default in releases,
12/// which hopefully won't result in confusion like `warn` or `error` levels might.
13pub fn min_printed_log_level(level: log_impl::Level) -> log_impl::Level {
14 // this logic is defined based on the logic used in the `log` crate,
15 // which checks that a logs level is <= both of these values,
16 // so we take the minimum of the two values to ensure that check passes
17 let level_min_static = log_impl::STATIC_MAX_LEVEL;
18 let level_min_dynamic = log_impl::max_level();
19 if level <= level_min_static && level <= level_min_dynamic {
20 return level;
21 }
22 return log_impl::LevelFilter::min(level_min_static, level_min_dynamic)
23 .to_level()
24 .unwrap_or(level);
25}
26
27#[macro_export]
28macro_rules! log {
29 ($logger:expr, $level:expr, $($arg:tt)+) => {
30 let level = $level;
31 let logger = $logger;
32 let (enabled, level) = $crate::scope_map::is_scope_enabled(&logger.scope, level);
33 if enabled {
34 $crate::log_impl::log!(level, "[{}]: {}", &logger.fmt_scope(), format!($($arg)+));
35 }
36 }
37}
38
39#[macro_export]
40macro_rules! trace {
41 ($logger:expr => $($arg:tt)+) => {
42 $crate::log!($logger, $crate::log_impl::Level::Trace, $($arg)+);
43 };
44 ($($arg:tt)+) => {
45 $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Trace, $($arg)+);
46 };
47}
48
49#[macro_export]
50macro_rules! debug {
51 ($logger:expr => $($arg:tt)+) => {
52 $crate::log!($logger, $crate::log_impl::Level::Debug, $($arg)+);
53 };
54 ($($arg:tt)+) => {
55 $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Debug, $($arg)+);
56 };
57}
58
59#[macro_export]
60macro_rules! info {
61 ($logger:expr => $($arg:tt)+) => {
62 $crate::log!($logger, $crate::log_impl::Level::Info, $($arg)+);
63 };
64 ($($arg:tt)+) => {
65 $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Info, $($arg)+);
66 };
67}
68
69#[macro_export]
70macro_rules! warn {
71 ($logger:expr => $($arg:tt)+) => {
72 $crate::log!($logger, $crate::log_impl::Level::Warn, $($arg)+);
73 };
74 ($($arg:tt)+) => {
75 $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Warn, $($arg)+);
76 };
77}
78
79#[macro_export]
80macro_rules! error {
81 ($logger:expr => $($arg:tt)+) => {
82 $crate::log!($logger, $crate::log_impl::Level::Error, $($arg)+);
83 };
84 ($($arg:tt)+) => {
85 $crate::log!($crate::default_logger!(), $crate::log_impl::Level::Error, $($arg)+);
86 };
87}
88
89/// Creates a timer that logs the duration it was active for either when
90/// it is dropped, or when explicitly stopped using the `end` method.
91/// Logs at the `trace` level.
92/// Note that it will include time spent across await points
93/// (i.e. should not be used to measure the performance of async code)
94/// However, this is a feature not a bug, as it allows for a more accurate
95/// understanding of how long the action actually took to complete, including
96/// interruptions, which can help explain why something may have timed out,
97/// why it took longer to complete than it would had the await points resolved
98/// immediately, etc.
99#[macro_export]
100macro_rules! time {
101 ($logger:expr => $name:expr) => {
102 $crate::Timer::new($logger, $name)
103 };
104 ($name:expr) => {
105 time!($crate::default_logger!() => $name)
106 };
107}
108
109#[macro_export]
110macro_rules! scoped {
111 ($parent:expr => $name:expr) => {{
112 let parent = $parent;
113 let name = $name;
114 let mut scope = parent.scope;
115 let mut index = 1; // always have crate/module name
116 while index < scope.len() && !scope[index].is_empty() {
117 index += 1;
118 }
119 if index >= scope.len() {
120 #[cfg(debug_assertions)]
121 {
122 panic!("Scope overflow trying to add scope {}", name);
123 }
124 #[cfg(not(debug_assertions))]
125 {
126 $crate::warn!(
127 parent =>
128 "Scope overflow trying to add scope {}... ignoring scope",
129 name
130 );
131 }
132 }
133 scope[index] = name;
134 $crate::Logger { scope }
135 }};
136 ($name:expr) => {
137 $crate::scoped!($crate::default_logger!() => $name)
138 };
139}
140
141#[macro_export]
142macro_rules! default_logger {
143 () => {
144 $crate::Logger {
145 scope: $crate::private::scope_new(&[$crate::crate_name!()]),
146 }
147 };
148}
149
150#[macro_export]
151macro_rules! crate_name {
152 () => {
153 $crate::private::extract_crate_name_from_module_path(module_path!())
154 };
155}
156
157/// functions that are used in macros, and therefore must be public,
158/// but should not be used directly
159pub mod private {
160 use super::*;
161
162 pub fn extract_crate_name_from_module_path(module_path: &'static str) -> &'static str {
163 return module_path
164 .split_once("::")
165 .map(|(crate_name, _)| crate_name)
166 .unwrap_or(module_path);
167 }
168
169 pub fn scope_new(scopes: &[&'static str]) -> Scope {
170 assert!(scopes.len() <= SCOPE_DEPTH_MAX);
171 let mut scope = [""; SCOPE_DEPTH_MAX];
172 scope[0..scopes.len()].copy_from_slice(scopes);
173 scope
174 }
175
176 pub fn scope_alloc_new(scopes: &[&str]) -> ScopeAlloc {
177 assert!(scopes.len() <= SCOPE_DEPTH_MAX);
178 let mut scope = [""; SCOPE_DEPTH_MAX];
179 scope[0..scopes.len()].copy_from_slice(scopes);
180 scope.map(|s| s.to_string())
181 }
182
183 pub fn scope_to_alloc(scope: &Scope) -> ScopeAlloc {
184 return scope.map(|s| s.to_string());
185 }
186}
187
188pub type Scope = [&'static str; SCOPE_DEPTH_MAX];
189pub type ScopeAlloc = [String; SCOPE_DEPTH_MAX];
190const SCOPE_STRING_SEP: &'static str = ".";
191
192#[derive(Clone, Copy, Debug, PartialEq, Eq)]
193pub struct Logger {
194 pub scope: Scope,
195}
196
197impl Logger {
198 pub fn fmt_scope(&self) -> String {
199 let mut last = 0;
200 for s in self.scope {
201 if s.is_empty() {
202 break;
203 }
204 last += 1;
205 }
206
207 return self.scope[0..last].join(SCOPE_STRING_SEP);
208 }
209}
210
211pub struct Timer {
212 pub logger: Logger,
213 pub start_time: std::time::Instant,
214 pub name: &'static str,
215 pub warn_if_longer_than: Option<std::time::Duration>,
216 pub done: bool,
217}
218
219impl Drop for Timer {
220 fn drop(&mut self) {
221 self.finish();
222 }
223}
224
225impl Timer {
226 #[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"]
227 pub fn new(logger: Logger, name: &'static str) -> Self {
228 return Self {
229 logger,
230 name,
231 start_time: std::time::Instant::now(),
232 warn_if_longer_than: None,
233 done: false,
234 };
235 }
236 pub fn warn_if_gt(mut self, warn_limit: std::time::Duration) -> Self {
237 self.warn_if_longer_than = Some(warn_limit);
238 return self;
239 }
240
241 pub fn end(mut self) {
242 self.finish();
243 }
244
245 fn finish(&mut self) {
246 if self.done {
247 return;
248 }
249 let elapsed = self.start_time.elapsed();
250 if let Some(warn_limit) = self.warn_if_longer_than {
251 if elapsed > warn_limit {
252 crate::warn!(
253 self.logger =>
254 "Timer '{}' took {:?}. Which was longer than the expected limit of {:?}",
255 self.name,
256 elapsed,
257 warn_limit
258 );
259 self.done = true;
260 return;
261 }
262 }
263 crate::trace!(
264 self.logger =>
265 "Timer '{}' finished in {:?}",
266 self.name,
267 elapsed
268 );
269 self.done = true;
270 }
271}
272
273pub mod scope_map {
274 use std::{
275 collections::{HashMap, VecDeque},
276 hash::{DefaultHasher, Hasher},
277 sync::{
278 RwLock,
279 atomic::{AtomicU64, Ordering},
280 },
281 usize,
282 };
283
284 use super::*;
285
286 static SCOPE_MAP: RwLock<Option<ScopeMap>> = RwLock::new(None);
287 static SCOPE_MAP_HASH: AtomicU64 = AtomicU64::new(0);
288
289 pub fn is_scope_enabled(scope: &Scope, level: log_impl::Level) -> (bool, log_impl::Level) {
290 let level_min = min_printed_log_level(level);
291 if level <= level_min {
292 // [FAST PATH]
293 // if the message is at or below the minimum printed log level
294 // (where error < warn < info etc) then always enable
295 return (true, level);
296 }
297
298 let Ok(map) = SCOPE_MAP.read() else {
299 // on failure, default to enabled detection done by `log` crate
300 return (true, level);
301 };
302
303 let Some(map) = map.as_ref() else {
304 // on failure, default to enabled detection done by `log` crate
305 return (true, level);
306 };
307
308 if map.is_empty() {
309 // if no scopes are enabled, default to enabled detection done by `log` crate
310 return (true, level);
311 }
312 let enabled_status = map.is_enabled(&scope, level);
313 match enabled_status {
314 EnabledStatus::NotConfigured => {
315 // if this scope isn't configured, default to enabled detection done by `log` crate
316 return (true, level);
317 }
318 EnabledStatus::Enabled => {
319 // if this scope is enabled, enable logging
320 // note: bumping level to min level that will be printed
321 // to work around log crate limitations
322 return (true, level_min);
323 }
324 EnabledStatus::Disabled => {
325 // if the configured level is lower than the requested level, disable logging
326 // note: err = 0, warn = 1, etc.
327 return (false, level);
328 }
329 }
330 }
331
332 fn hash_scope_map_settings(map: &HashMap<String, String>) -> u64 {
333 let mut hasher = DefaultHasher::new();
334 let mut items = map.iter().collect::<Vec<_>>();
335 items.sort();
336 for (key, value) in items {
337 Hasher::write(&mut hasher, key.as_bytes());
338 Hasher::write(&mut hasher, value.as_bytes());
339 }
340 return hasher.finish();
341 }
342
343 pub fn refresh(settings: &HashMap<String, String>) {
344 let hash_old = SCOPE_MAP_HASH.load(Ordering::Acquire);
345 let hash_new = hash_scope_map_settings(settings);
346 if hash_old == hash_new && hash_old != 0 {
347 return;
348 }
349 let map_new = ScopeMap::new_from_settings(settings);
350
351 if let Ok(_) = SCOPE_MAP_HASH.compare_exchange(
352 hash_old,
353 hash_new,
354 Ordering::Release,
355 Ordering::Relaxed,
356 ) {
357 let mut map = SCOPE_MAP.write().unwrap_or_else(|err| {
358 SCOPE_MAP.clear_poison();
359 err.into_inner()
360 });
361 *map = Some(map_new);
362 }
363 }
364
365 fn level_from_level_str(level_str: &String) -> Option<log_impl::Level> {
366 let level = match level_str.to_ascii_lowercase().as_str() {
367 "" => log_impl::Level::Trace,
368 "trace" => log_impl::Level::Trace,
369 "debug" => log_impl::Level::Debug,
370 "info" => log_impl::Level::Info,
371 "warn" => log_impl::Level::Warn,
372 "error" => log_impl::Level::Error,
373 "off" | "disable" | "no" | "none" | "disabled" => {
374 crate::warn!(
375 "Invalid log level \"{level_str}\", set to error to disable non-error logging. Defaulting to error"
376 );
377 log_impl::Level::Error
378 }
379 _ => {
380 crate::warn!("Invalid log level \"{level_str}\", ignoring");
381 return None;
382 }
383 };
384 return Some(level);
385 }
386
387 fn scope_alloc_from_scope_str(scope_str: &String) -> Option<ScopeAlloc> {
388 let mut scope_buf = [""; SCOPE_DEPTH_MAX];
389 let mut index = 0;
390 let mut scope_iter = scope_str.split(SCOPE_STRING_SEP);
391 while index < SCOPE_DEPTH_MAX {
392 let Some(scope) = scope_iter.next() else {
393 break;
394 };
395 if scope == "" {
396 continue;
397 }
398 scope_buf[index] = scope;
399 index += 1;
400 }
401 if index == 0 {
402 return None;
403 }
404 if let Some(_) = scope_iter.next() {
405 crate::warn!(
406 "Invalid scope key, too many nested scopes: '{scope_str}'. Max depth is {SCOPE_DEPTH_MAX}",
407 );
408 return None;
409 }
410 let scope = scope_buf.map(|s| s.to_string());
411 return Some(scope);
412 }
413
414 pub struct ScopeMap {
415 entries: Vec<ScopeMapEntry>,
416 root_count: usize,
417 }
418
419 pub struct ScopeMapEntry {
420 scope: String,
421 enabled: Option<log_impl::Level>,
422 descendants: std::ops::Range<usize>,
423 }
424
425 #[derive(Debug, Clone, Copy, PartialEq, Eq)]
426 pub enum EnabledStatus {
427 Enabled,
428 Disabled,
429 NotConfigured,
430 }
431
432 impl ScopeMap {
433 pub fn new_from_settings(items_input_map: &HashMap<String, String>) -> Self {
434 let mut items = items_input_map
435 .into_iter()
436 .filter_map(|(scope_str, level_str)| {
437 let scope = scope_alloc_from_scope_str(&scope_str)?;
438 let level = level_from_level_str(&level_str)?;
439 return Some((scope, level));
440 })
441 .collect::<Vec<_>>();
442
443 items.sort_by(|a, b| a.0.cmp(&b.0));
444
445 let mut this = Self {
446 entries: Vec::with_capacity(items.len() * SCOPE_DEPTH_MAX),
447 root_count: 0,
448 };
449
450 let items_count = items.len();
451
452 struct ProcessQueueEntry {
453 parent_index: usize,
454 depth: usize,
455 items_range: std::ops::Range<usize>,
456 }
457 let mut process_queue = VecDeque::new();
458 process_queue.push_back(ProcessQueueEntry {
459 parent_index: usize::MAX,
460 depth: 0,
461 items_range: 0..items_count,
462 });
463
464 let empty_range = 0..0;
465
466 while let Some(process_entry) = process_queue.pop_front() {
467 let ProcessQueueEntry {
468 items_range,
469 depth,
470 parent_index,
471 } = process_entry;
472 let mut cursor = items_range.start;
473 let res_entries_start = this.entries.len();
474 while cursor < items_range.end {
475 let sub_items_start = cursor;
476 cursor += 1;
477 let scope_name = &items[sub_items_start].0[depth];
478 while cursor < items_range.end && &items[cursor].0[depth] == scope_name {
479 cursor += 1;
480 }
481 let sub_items_end = cursor;
482 if scope_name == "" {
483 assert_eq!(sub_items_start + 1, sub_items_end);
484 assert_ne!(depth, 0);
485 assert_ne!(parent_index, usize::MAX);
486 assert!(this.entries[parent_index].enabled.is_none());
487 this.entries[parent_index].enabled = Some(items[sub_items_start].1);
488 continue;
489 }
490 let is_valid_scope = scope_name != "";
491 let is_last = depth + 1 == SCOPE_DEPTH_MAX || !is_valid_scope;
492 let mut enabled = None;
493 if is_last {
494 assert_eq!(sub_items_start + 1, sub_items_end);
495 enabled = Some(items[sub_items_start].1);
496 } else {
497 let entry_index = this.entries.len();
498 process_queue.push_back(ProcessQueueEntry {
499 items_range: sub_items_start..sub_items_end,
500 parent_index: entry_index,
501 depth: depth + 1,
502 });
503 }
504 this.entries.push(ScopeMapEntry {
505 scope: scope_name.to_owned(),
506 enabled,
507 descendants: empty_range.clone(),
508 });
509 }
510 let res_entries_end = this.entries.len();
511 if parent_index != usize::MAX {
512 this.entries[parent_index].descendants = res_entries_start..res_entries_end;
513 } else {
514 this.root_count = res_entries_end;
515 }
516 }
517
518 return this;
519 }
520
521 pub fn is_empty(&self) -> bool {
522 self.entries.is_empty()
523 }
524
525 pub fn is_enabled<S>(
526 &self,
527 scope: &[S; SCOPE_DEPTH_MAX],
528 level: log_impl::Level,
529 ) -> EnabledStatus
530 where
531 S: AsRef<str>,
532 {
533 let mut enabled = None;
534 let mut cur_range = &self.entries[0..self.root_count];
535 let mut depth = 0;
536
537 'search: while !cur_range.is_empty()
538 && depth < SCOPE_DEPTH_MAX
539 && scope[depth].as_ref() != ""
540 {
541 for entry in cur_range {
542 if entry.scope == scope[depth].as_ref() {
543 // note:
544 enabled = entry.enabled.or(enabled);
545 cur_range = &self.entries[entry.descendants.clone()];
546 depth += 1;
547 continue 'search;
548 }
549 }
550 break 'search;
551 }
552
553 return enabled.map_or(EnabledStatus::NotConfigured, |level_enabled| {
554 if level <= level_enabled {
555 EnabledStatus::Enabled
556 } else {
557 EnabledStatus::Disabled
558 }
559 });
560 }
561 }
562
563 #[cfg(test)]
564 mod tests {
565 use super::*;
566
567 fn scope_map_from_keys(kv: &[(&str, &str)]) -> ScopeMap {
568 let hash_map: HashMap<String, String> = kv
569 .iter()
570 .map(|(k, v)| (k.to_string(), v.to_string()))
571 .collect();
572 ScopeMap::new_from_settings(&hash_map)
573 }
574
575 #[test]
576 fn test_initialization() {
577 let map = scope_map_from_keys(&[("a.b.c.d", "trace")]);
578 assert_eq!(map.root_count, 1);
579 assert_eq!(map.entries.len(), 4);
580
581 let map = scope_map_from_keys(&[]);
582 assert_eq!(map.root_count, 0);
583 assert_eq!(map.entries.len(), 0);
584
585 let map = scope_map_from_keys(&[("", "trace")]);
586 assert_eq!(map.root_count, 0);
587 assert_eq!(map.entries.len(), 0);
588
589 let map = scope_map_from_keys(&[("foo..bar", "trace")]);
590 assert_eq!(map.root_count, 1);
591 assert_eq!(map.entries.len(), 2);
592
593 let map = scope_map_from_keys(&[
594 ("a.b.c.d", "trace"),
595 ("e.f.g.h", "debug"),
596 ("i.j.k.l", "info"),
597 ("m.n.o.p", "warn"),
598 ("q.r.s.t", "error"),
599 ]);
600 assert_eq!(map.root_count, 5);
601 assert_eq!(map.entries.len(), 20);
602 assert_eq!(map.entries[0].scope, "a");
603 assert_eq!(map.entries[1].scope, "e");
604 assert_eq!(map.entries[2].scope, "i");
605 assert_eq!(map.entries[3].scope, "m");
606 assert_eq!(map.entries[4].scope, "q");
607 }
608
609 fn scope_from_scope_str(scope_str: &'static str) -> Scope {
610 let mut scope_buf = [""; SCOPE_DEPTH_MAX];
611 let mut index = 0;
612 let mut scope_iter = scope_str.split(SCOPE_STRING_SEP);
613 while index < SCOPE_DEPTH_MAX {
614 let Some(scope) = scope_iter.next() else {
615 break;
616 };
617 if scope == "" {
618 continue;
619 }
620 scope_buf[index] = scope;
621 index += 1;
622 }
623 assert_ne!(index, 0);
624 assert!(scope_iter.next().is_none());
625 return scope_buf;
626 }
627
628 #[test]
629 fn test_is_enabled() {
630 let map = scope_map_from_keys(&[
631 ("a.b.c.d", "trace"),
632 ("e.f.g.h", "debug"),
633 ("i.j.k.l", "info"),
634 ("m.n.o.p", "warn"),
635 ("q.r.s.t", "error"),
636 ]);
637 use log_impl::Level;
638 assert_eq!(
639 map.is_enabled(&scope_from_scope_str("a.b.c.d"), Level::Trace),
640 EnabledStatus::Enabled
641 );
642 assert_eq!(
643 map.is_enabled(&scope_from_scope_str("a.b.c.d"), Level::Debug),
644 EnabledStatus::Enabled
645 );
646
647 assert_eq!(
648 map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Debug),
649 EnabledStatus::Enabled
650 );
651 assert_eq!(
652 map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Info),
653 EnabledStatus::Enabled
654 );
655 assert_eq!(
656 map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Trace),
657 EnabledStatus::Disabled
658 );
659
660 assert_eq!(
661 map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Info),
662 EnabledStatus::Enabled
663 );
664 assert_eq!(
665 map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Warn),
666 EnabledStatus::Enabled
667 );
668 assert_eq!(
669 map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Debug),
670 EnabledStatus::Disabled
671 );
672
673 assert_eq!(
674 map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Warn),
675 EnabledStatus::Enabled
676 );
677 assert_eq!(
678 map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Error),
679 EnabledStatus::Enabled
680 );
681 assert_eq!(
682 map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Info),
683 EnabledStatus::Disabled
684 );
685
686 assert_eq!(
687 map.is_enabled(&scope_from_scope_str("q.r.s.t"), Level::Error),
688 EnabledStatus::Enabled
689 );
690 assert_eq!(
691 map.is_enabled(&scope_from_scope_str("q.r.s.t"), Level::Warn),
692 EnabledStatus::Disabled
693 );
694 }
695 }
696}
697
698#[cfg(test)]
699mod tests {
700 use super::*;
701
702 #[test]
703 fn test_crate_name() {
704 assert_eq!(crate_name!(), "zlog");
705 }
706}