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 atomic::{AtomicU64, Ordering},
279 RwLock,
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!("Invalid log level \"{level_str}\", set to error to disable non-error logging. Defaulting to error");
375 log_impl::Level::Error
376 }
377 _ => {
378 crate::warn!("Invalid log level \"{level_str}\", ignoring");
379 return None;
380 }
381 };
382 return Some(level);
383 }
384
385 fn scope_alloc_from_scope_str(scope_str: &String) -> Option<ScopeAlloc> {
386 let mut scope_buf = [""; SCOPE_DEPTH_MAX];
387 let mut index = 0;
388 let mut scope_iter = scope_str.split(SCOPE_STRING_SEP);
389 while index < SCOPE_DEPTH_MAX {
390 let Some(scope) = scope_iter.next() else {
391 break;
392 };
393 if scope == "" {
394 continue;
395 }
396 scope_buf[index] = scope;
397 index += 1;
398 }
399 if index == 0 {
400 return None;
401 }
402 if let Some(_) = scope_iter.next() {
403 crate::warn!(
404 "Invalid scope key, too many nested scopes: '{scope_str}'. Max depth is {SCOPE_DEPTH_MAX}",
405 );
406 return None;
407 }
408 let scope = scope_buf.map(|s| s.to_string());
409 return Some(scope);
410 }
411
412 pub struct ScopeMap {
413 entries: Vec<ScopeMapEntry>,
414 root_count: usize,
415 }
416
417 pub struct ScopeMapEntry {
418 scope: String,
419 enabled: Option<log_impl::Level>,
420 descendants: std::ops::Range<usize>,
421 }
422
423 #[derive(Debug, Clone, Copy, PartialEq, Eq)]
424 pub enum EnabledStatus {
425 Enabled,
426 Disabled,
427 NotConfigured,
428 }
429
430 impl ScopeMap {
431 pub fn new_from_settings(items_input_map: &HashMap<String, String>) -> Self {
432 let mut items = items_input_map
433 .into_iter()
434 .filter_map(|(scope_str, level_str)| {
435 let scope = scope_alloc_from_scope_str(&scope_str)?;
436 let level = level_from_level_str(&level_str)?;
437 return Some((scope, level));
438 })
439 .collect::<Vec<_>>();
440
441 items.sort_by(|a, b| a.0.cmp(&b.0));
442
443 let mut this = Self {
444 entries: Vec::with_capacity(items.len() * SCOPE_DEPTH_MAX),
445 root_count: 0,
446 };
447
448 let items_count = items.len();
449
450 struct ProcessQueueEntry {
451 parent_index: usize,
452 depth: usize,
453 items_range: std::ops::Range<usize>,
454 }
455 let mut process_queue = VecDeque::new();
456 process_queue.push_back(ProcessQueueEntry {
457 parent_index: usize::MAX,
458 depth: 0,
459 items_range: 0..items_count,
460 });
461
462 let empty_range = 0..0;
463
464 while let Some(process_entry) = process_queue.pop_front() {
465 let ProcessQueueEntry {
466 items_range,
467 depth,
468 parent_index,
469 } = process_entry;
470 let mut cursor = items_range.start;
471 let res_entries_start = this.entries.len();
472 while cursor < items_range.end {
473 let sub_items_start = cursor;
474 cursor += 1;
475 let scope_name = &items[sub_items_start].0[depth];
476 while cursor < items_range.end && &items[cursor].0[depth] == scope_name {
477 cursor += 1;
478 }
479 let sub_items_end = cursor;
480 if scope_name == "" {
481 assert_eq!(sub_items_start + 1, sub_items_end);
482 assert_ne!(depth, 0);
483 assert_ne!(parent_index, usize::MAX);
484 assert!(this.entries[parent_index].enabled.is_none());
485 this.entries[parent_index].enabled = Some(items[sub_items_start].1);
486 continue;
487 }
488 let is_valid_scope = scope_name != "";
489 let is_last = depth + 1 == SCOPE_DEPTH_MAX || !is_valid_scope;
490 let mut enabled = None;
491 if is_last {
492 assert_eq!(sub_items_start + 1, sub_items_end);
493 enabled = Some(items[sub_items_start].1);
494 } else {
495 let entry_index = this.entries.len();
496 process_queue.push_back(ProcessQueueEntry {
497 items_range: sub_items_start..sub_items_end,
498 parent_index: entry_index,
499 depth: depth + 1,
500 });
501 }
502 this.entries.push(ScopeMapEntry {
503 scope: scope_name.to_owned(),
504 enabled,
505 descendants: empty_range.clone(),
506 });
507 }
508 let res_entries_end = this.entries.len();
509 if parent_index != usize::MAX {
510 this.entries[parent_index].descendants = res_entries_start..res_entries_end;
511 } else {
512 this.root_count = res_entries_end;
513 }
514 }
515
516 return this;
517 }
518
519 pub fn is_empty(&self) -> bool {
520 self.entries.is_empty()
521 }
522
523 pub fn is_enabled<S>(
524 &self,
525 scope: &[S; SCOPE_DEPTH_MAX],
526 level: log_impl::Level,
527 ) -> EnabledStatus
528 where
529 S: AsRef<str>,
530 {
531 let mut enabled = None;
532 let mut cur_range = &self.entries[0..self.root_count];
533 let mut depth = 0;
534
535 'search: while !cur_range.is_empty()
536 && depth < SCOPE_DEPTH_MAX
537 && scope[depth].as_ref() != ""
538 {
539 for entry in cur_range {
540 if entry.scope == scope[depth].as_ref() {
541 // note:
542 enabled = entry.enabled.or(enabled);
543 cur_range = &self.entries[entry.descendants.clone()];
544 depth += 1;
545 continue 'search;
546 }
547 }
548 break 'search;
549 }
550
551 return enabled.map_or(EnabledStatus::NotConfigured, |level_enabled| {
552 if level <= level_enabled {
553 EnabledStatus::Enabled
554 } else {
555 EnabledStatus::Disabled
556 }
557 });
558 }
559 }
560
561 #[cfg(test)]
562 mod tests {
563 use super::*;
564
565 fn scope_map_from_keys(kv: &[(&str, &str)]) -> ScopeMap {
566 let hash_map: HashMap<String, String> = kv
567 .iter()
568 .map(|(k, v)| (k.to_string(), v.to_string()))
569 .collect();
570 ScopeMap::new_from_settings(&hash_map)
571 }
572
573 #[test]
574 fn test_initialization() {
575 let map = scope_map_from_keys(&[("a.b.c.d", "trace")]);
576 assert_eq!(map.root_count, 1);
577 assert_eq!(map.entries.len(), 4);
578
579 let map = scope_map_from_keys(&[]);
580 assert_eq!(map.root_count, 0);
581 assert_eq!(map.entries.len(), 0);
582
583 let map = scope_map_from_keys(&[("", "trace")]);
584 assert_eq!(map.root_count, 0);
585 assert_eq!(map.entries.len(), 0);
586
587 let map = scope_map_from_keys(&[("foo..bar", "trace")]);
588 assert_eq!(map.root_count, 1);
589 assert_eq!(map.entries.len(), 2);
590
591 let map = scope_map_from_keys(&[
592 ("a.b.c.d", "trace"),
593 ("e.f.g.h", "debug"),
594 ("i.j.k.l", "info"),
595 ("m.n.o.p", "warn"),
596 ("q.r.s.t", "error"),
597 ]);
598 assert_eq!(map.root_count, 5);
599 assert_eq!(map.entries.len(), 20);
600 assert_eq!(map.entries[0].scope, "a");
601 assert_eq!(map.entries[1].scope, "e");
602 assert_eq!(map.entries[2].scope, "i");
603 assert_eq!(map.entries[3].scope, "m");
604 assert_eq!(map.entries[4].scope, "q");
605 }
606
607 fn scope_from_scope_str(scope_str: &'static str) -> Scope {
608 let mut scope_buf = [""; SCOPE_DEPTH_MAX];
609 let mut index = 0;
610 let mut scope_iter = scope_str.split(SCOPE_STRING_SEP);
611 while index < SCOPE_DEPTH_MAX {
612 let Some(scope) = scope_iter.next() else {
613 break;
614 };
615 if scope == "" {
616 continue;
617 }
618 scope_buf[index] = scope;
619 index += 1;
620 }
621 assert_ne!(index, 0);
622 assert!(scope_iter.next().is_none());
623 return scope_buf;
624 }
625
626 #[test]
627 fn test_is_enabled() {
628 let map = scope_map_from_keys(&[
629 ("a.b.c.d", "trace"),
630 ("e.f.g.h", "debug"),
631 ("i.j.k.l", "info"),
632 ("m.n.o.p", "warn"),
633 ("q.r.s.t", "error"),
634 ]);
635 use log_impl::Level;
636 assert_eq!(
637 map.is_enabled(&scope_from_scope_str("a.b.c.d"), Level::Trace),
638 EnabledStatus::Enabled
639 );
640 assert_eq!(
641 map.is_enabled(&scope_from_scope_str("a.b.c.d"), Level::Debug),
642 EnabledStatus::Enabled
643 );
644
645 assert_eq!(
646 map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Debug),
647 EnabledStatus::Enabled
648 );
649 assert_eq!(
650 map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Info),
651 EnabledStatus::Enabled
652 );
653 assert_eq!(
654 map.is_enabled(&scope_from_scope_str("e.f.g.h"), Level::Trace),
655 EnabledStatus::Disabled
656 );
657
658 assert_eq!(
659 map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Info),
660 EnabledStatus::Enabled
661 );
662 assert_eq!(
663 map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Warn),
664 EnabledStatus::Enabled
665 );
666 assert_eq!(
667 map.is_enabled(&scope_from_scope_str("i.j.k.l"), Level::Debug),
668 EnabledStatus::Disabled
669 );
670
671 assert_eq!(
672 map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Warn),
673 EnabledStatus::Enabled
674 );
675 assert_eq!(
676 map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Error),
677 EnabledStatus::Enabled
678 );
679 assert_eq!(
680 map.is_enabled(&scope_from_scope_str("m.n.o.p"), Level::Info),
681 EnabledStatus::Disabled
682 );
683
684 assert_eq!(
685 map.is_enabled(&scope_from_scope_str("q.r.s.t"), Level::Error),
686 EnabledStatus::Enabled
687 );
688 assert_eq!(
689 map.is_enabled(&scope_from_scope_str("q.r.s.t"), Level::Warn),
690 EnabledStatus::Disabled
691 );
692 }
693 }
694}
695
696#[cfg(test)]
697mod tests {
698 use super::*;
699
700 #[test]
701 fn test_crate_name() {
702 assert_eq!(crate_name!(), "zlog");
703 }
704}