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