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}