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