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