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,
276 hash::{DefaultHasher, Hasher},
277 sync::{
278 atomic::{AtomicU64, Ordering},
279 RwLock,
280 },
281 };
282
283 use super::*;
284
285 type ScopeMap = HashMap<ScopeAlloc, log_impl::Level>;
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 mut scope_alloc = private::scope_to_alloc(scope);
313 let mut level_enabled = map.get(&scope_alloc);
314 if level_enabled.is_none() {
315 for i in (0..SCOPE_DEPTH_MAX).rev() {
316 if scope_alloc[i] == "" {
317 continue;
318 }
319 scope_alloc[i].clear();
320 if let Some(level) = map.get(&scope_alloc) {
321 level_enabled = Some(level);
322 break;
323 }
324 }
325 }
326 let Some(level_enabled) = level_enabled else {
327 // if this scope isn't configured, default to enabled detection done by `log` crate
328 return (true, level);
329 };
330 if level_enabled < &level {
331 // if the configured level is lower than the requested level, disable logging
332 // note: err = 0, warn = 1, etc.
333 return (false, level);
334 }
335
336 // note: bumping level to min level that will be printed
337 // to work around log crate limitations
338 return (true, level_min);
339 }
340
341 fn hash_scope_map_settings(map: &HashMap<String, String>) -> u64 {
342 let mut hasher = DefaultHasher::new();
343 let mut items = map.iter().collect::<Vec<_>>();
344 items.sort();
345 for (key, value) in items {
346 Hasher::write(&mut hasher, key.as_bytes());
347 Hasher::write(&mut hasher, value.as_bytes());
348 }
349 return hasher.finish();
350 }
351
352 pub fn refresh(settings: &HashMap<String, String>) {
353 let hash_old = SCOPE_MAP_HASH.load(Ordering::Acquire);
354 let hash_new = hash_scope_map_settings(settings);
355 if hash_old == hash_new && hash_old != 0 {
356 return;
357 }
358 // compute new scope map then atomically swap it, instead of
359 // updating in place to reduce contention
360 let mut map_new = ScopeMap::with_capacity(settings.len());
361 'settings: for (key, value) in settings {
362 let level = match value.to_ascii_lowercase().as_str() {
363 "" => log_impl::Level::Trace,
364 "trace" => log_impl::Level::Trace,
365 "debug" => log_impl::Level::Debug,
366 "info" => log_impl::Level::Info,
367 "warn" => log_impl::Level::Warn,
368 "error" => log_impl::Level::Error,
369 "off" | "disable" | "no" | "none" | "disabled" => {
370 crate::warn!("Invalid log level \"{value}\", set to error to disable non-error logging. Defaulting to error");
371 log_impl::Level::Error
372 }
373 _ => {
374 crate::warn!("Invalid log level \"{value}\", ignoring");
375 continue 'settings;
376 }
377 };
378 let mut scope_buf = [""; SCOPE_DEPTH_MAX];
379 for (index, scope) in key.split(SCOPE_STRING_SEP).enumerate() {
380 let Some(scope_ptr) = scope_buf.get_mut(index) else {
381 crate::warn!("Invalid scope key, too many nested scopes: '{key}'");
382 continue 'settings;
383 };
384 *scope_ptr = scope;
385 }
386 let scope = scope_buf.map(|s| s.to_string());
387 map_new.insert(scope, level);
388 }
389
390 if let Ok(_) = SCOPE_MAP_HASH.compare_exchange(
391 hash_old,
392 hash_new,
393 Ordering::Release,
394 Ordering::Relaxed,
395 ) {
396 let mut map = SCOPE_MAP.write().unwrap_or_else(|err| {
397 SCOPE_MAP.clear_poison();
398 err.into_inner()
399 });
400 *map = Some(map_new.clone());
401 // note: hash update done here to ensure consistency with scope map
402 }
403 eprintln!("Updated log scope settings :: map = {:?}", map_new);
404 }
405}
406
407#[cfg(test)]
408mod tests {
409 use super::*;
410
411 #[test]
412 fn test_crate_name() {
413 assert_eq!(crate_name!(), "zlog");
414 }
415}