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