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