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