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