ckb_logger_service/
lib.rs

1//! CKB logger and logging service.
2
3use backtrace::Backtrace;
4use ckb_channel::{self, unbounded};
5use env_logger::filter::{Builder, Filter};
6use log::{LevelFilter, Log, Metadata, Record, SetLoggerError};
7use regex::Regex;
8use std::collections::HashMap;
9use std::io::Write;
10use std::path::{Path, PathBuf};
11use std::sync::OnceLock;
12use std::{fs, panic, process, sync, thread};
13use time::{
14    OffsetDateTime,
15    format_description::{self, FormatItem},
16};
17
18use ckb_logger_config::Config;
19use ckb_util::{Mutex, RwLock, strings};
20use yansi::Paint;
21
22#[cfg(test)]
23mod tests;
24
25static CONTROL_HANDLE: OnceLock<ckb_channel::Sender<Message>> = OnceLock::new();
26static FORMAT: OnceLock<Vec<FormatItem<'static>>> = OnceLock::new();
27static RE: OnceLock<regex::Regex> = OnceLock::new();
28
29enum Message {
30    Record {
31        is_match: bool,
32        extras: Vec<String>,
33        data: String,
34    },
35    UpdateMainLogger {
36        filter: Option<Filter>,
37        to_stdout: Option<bool>,
38        to_file: Option<bool>,
39        color: Option<bool>,
40    },
41    UpdateExtraLogger(String, Filter),
42    RemoveExtraLogger(String),
43    Terminate,
44}
45
46/// The CKB logger which implements [log::Log].
47///
48/// When a CKB logger is created, a logging service will be started in a background thread.
49///
50/// [log::Log]: https://docs.rs/log/*/log/trait.Log.html
51pub struct Logger {
52    sender: ckb_channel::Sender<Message>,
53    handle: Mutex<Option<thread::JoinHandle<()>>>,
54    filter: sync::Arc<RwLock<Filter>>,
55    #[cfg(feature = "with_sentry")]
56    emit_sentry_breadcrumbs: bool,
57    extra_loggers: sync::Arc<RwLock<HashMap<String, ExtraLogger>>>,
58}
59
60struct MainLogger {
61    file_path: PathBuf,
62    file: Option<fs::File>,
63    to_stdout: bool,
64    to_file: bool,
65    color: bool,
66}
67
68struct ExtraLogger {
69    filter: Filter,
70}
71
72#[cfg(target_os = "windows")]
73fn enable_ansi_support() {
74    if !Paint::enable_windows_ascii() {
75        Paint::disable();
76    }
77}
78
79#[cfg(not(target_os = "windows"))]
80fn enable_ansi_support() {}
81
82// Parse crate name leniently in logger filter: convert "-" to "_".
83pub(crate) fn convert_compatible_crate_name(spec: &str) -> String {
84    let mut parts = spec.splitn(2, '/');
85    let first_part = parts.next();
86    let last_part = parts.next();
87    let mut mods = Vec::new();
88    if let Some(mods_part) = first_part {
89        for m in mods_part.split(',') {
90            mods.push(m.to_owned());
91            if m.contains('-') {
92                mods.push(m.replace('-', "_"));
93            }
94        }
95    }
96    if let Some(filter) = last_part {
97        [&mods.join(","), filter].join("/")
98    } else {
99        mods.join(",")
100    }
101}
102
103impl Logger {
104    fn new(env_opt: Option<&str>, config: Config) -> Logger {
105        for name in config.extra.keys() {
106            if let Err(err) = Self::check_extra_logger_name(name) {
107                eprintln!("Error: {err}");
108                process::exit(1);
109            }
110        }
111
112        let (sender, receiver) = unbounded();
113        CONTROL_HANDLE
114            .set(sender.clone())
115            .expect("CONTROL_HANDLE init once");
116
117        let Config {
118            color,
119            file,
120            log_dir,
121            log_to_file,
122            log_to_stdout,
123            ..
124        } = config;
125        let mut main_logger = {
126            let file_path = log_dir.join(file);
127            let file = if log_to_file {
128                match Self::open_log_file(&file_path) {
129                    Err(err) => {
130                        eprintln!("Error: {err}");
131                        process::exit(1);
132                    }
133                    Ok(file) => Some(file),
134                }
135            } else {
136                None
137            };
138            MainLogger {
139                file_path,
140                file,
141                to_stdout: log_to_stdout,
142                to_file: log_to_file,
143                color,
144            }
145        };
146
147        let filter = {
148            let filter = if let Some(Ok(ref env_filter)) = env_opt.map(std::env::var) {
149                Self::build_filter(env_filter)
150            } else if let Some(ref config_filter) = config.filter {
151                Self::build_filter(config_filter)
152            } else {
153                Self::build_filter("")
154            };
155            sync::Arc::new(RwLock::new(filter))
156        };
157        let filter_for_update = sync::Arc::clone(&filter);
158
159        let extra_loggers = {
160            let extra_loggers = config
161                .extra
162                .iter()
163                .map(|(name, extra)| {
164                    let filter = Self::build_filter(&extra.filter);
165                    let extra_logger = ExtraLogger { filter };
166                    (name.to_owned(), extra_logger)
167                })
168                .collect::<HashMap<_, _>>();
169            sync::Arc::new(RwLock::new(extra_loggers))
170        };
171        let extra_loggers_for_update = sync::Arc::clone(&extra_loggers);
172
173        let mut extra_files = {
174            let extra_files_res = config
175                .extra
176                .keys()
177                .map(|name| {
178                    let file_path = log_dir.clone().join(name.to_owned() + ".log");
179                    Self::open_log_file(&file_path).map(|file| (name.to_owned(), file))
180                })
181                .collect::<Result<HashMap<_, _>, _>>();
182            if let Err(err) = extra_files_res {
183                eprintln!("Error: {err}");
184                process::exit(1);
185            }
186            extra_files_res.unwrap()
187        };
188
189        let tb = thread::Builder::new()
190            .name("LogWriter".to_owned())
191            .spawn(move || {
192                enable_ansi_support();
193
194                loop {
195                    match receiver.recv() {
196                        Ok(Message::Record {
197                            is_match,
198                            extras,
199                            data,
200                        }) => {
201                            let removed_color = if (is_match
202                                && (!main_logger.color || main_logger.to_file))
203                                || !extras.is_empty()
204                            {
205                                sanitize_color(data.as_ref())
206                            } else {
207                                "".to_owned()
208                            };
209                            if is_match {
210                                if main_logger.to_stdout {
211                                    let output = if main_logger.color {
212                                        data.as_str()
213                                    } else {
214                                        removed_color.as_str()
215                                    };
216                                    println!("{output}");
217                                }
218                                if main_logger.to_file {
219                                    if let Some(mut file) = main_logger.file.as_ref() {
220                                        let _ = file.write_all(removed_color.as_bytes());
221                                        let _ = file.write_all(b"\n");
222                                    };
223                                }
224                            }
225                            for name in extras {
226                                if let Some(mut file) = extra_files.get(&name) {
227                                    let _ = file.write_all(removed_color.as_bytes());
228                                    let _ = file.write_all(b"\n");
229                                }
230                            }
231                            continue;
232                        }
233                        Ok(Message::UpdateMainLogger {
234                            filter,
235                            to_stdout,
236                            to_file,
237                            color,
238                        }) => {
239                            if let Some(filter) = filter {
240                                *filter_for_update.write() = filter;
241                            }
242                            if let Some(to_stdout) = to_stdout {
243                                main_logger.to_stdout = to_stdout;
244                            }
245                            if let Some(to_file) = to_file {
246                                main_logger.to_file = to_file;
247                                if main_logger.to_file {
248                                    if main_logger.file.is_none() {
249                                        main_logger.file =
250                                            Self::open_log_file(&main_logger.file_path).ok();
251                                    }
252                                } else {
253                                    main_logger.file = None;
254                                }
255                            }
256                            if let Some(color) = color {
257                                main_logger.color = color;
258                            }
259                        }
260                        Ok(Message::UpdateExtraLogger(name, filter)) => {
261                            let file = log_dir.clone().join(name.clone() + ".log");
262                            let file_res = Self::open_log_file(&file);
263                            if let Ok(file) = file_res {
264                                extra_files.insert(name.clone(), file);
265                                extra_loggers_for_update
266                                    .write()
267                                    .insert(name, ExtraLogger { filter });
268                            }
269                        }
270                        Ok(Message::RemoveExtraLogger(name)) => {
271                            extra_loggers_for_update.write().remove(&name);
272                            extra_files.remove(&name);
273                        }
274                        Ok(Message::Terminate) | Err(_) => {
275                            break;
276                        }
277                    }
278                    let max_level = Self::max_level_filter(
279                        &filter_for_update.read(),
280                        &extra_loggers_for_update.read(),
281                    );
282                    log::set_max_level(max_level);
283                }
284            })
285            .expect("Logger thread init should not fail");
286
287        Logger {
288            sender,
289            handle: Mutex::new(Some(tb)),
290            filter,
291            #[cfg(feature = "with_sentry")]
292            emit_sentry_breadcrumbs: config.emit_sentry_breadcrumbs.unwrap_or_default(),
293            extra_loggers,
294        }
295    }
296
297    fn open_log_file(file_path: &Path) -> Result<fs::File, String> {
298        fs::OpenOptions::new()
299            .append(true)
300            .create(true)
301            .open(file_path)
302            .map_err(|err| {
303                format!(
304                    "Cannot write to log file given: {:?} since {}",
305                    file_path.as_os_str(),
306                    err
307                )
308            })
309    }
310
311    fn build_filter(filter_str: &str) -> Filter {
312        Builder::new()
313            .parse(&convert_compatible_crate_name(filter_str))
314            .build()
315    }
316
317    fn max_level_filter(
318        main_filter: &Filter,
319        extra_loggers: &HashMap<String, ExtraLogger>,
320    ) -> LevelFilter {
321        extra_loggers
322            .values()
323            .fold(main_filter.filter(), |ret, curr| {
324                ret.max(curr.filter.filter())
325            })
326    }
327
328    fn filter(&self) -> LevelFilter {
329        Self::max_level_filter(&self.filter.read(), &self.extra_loggers.read())
330    }
331
332    fn send_message(message: Message) -> Result<(), String> {
333        CONTROL_HANDLE
334            .get()
335            .ok_or_else(|| "no sender for logger service".to_owned())
336            .and_then(|sender| {
337                sender
338                    .send(message)
339                    .map_err(|err| format!("failed to send message to logger service: {err}"))
340                    .map(|_| ())
341            })
342    }
343
344    /// Updates the main logger.
345    pub fn update_main_logger(
346        filter_str: Option<String>,
347        to_stdout: Option<bool>,
348        to_file: Option<bool>,
349        color: Option<bool>,
350    ) -> Result<(), String> {
351        let filter = filter_str.map(|s| Self::build_filter(&s));
352        let message = Message::UpdateMainLogger {
353            filter,
354            to_stdout,
355            to_file,
356            color,
357        };
358        Self::send_message(message)
359    }
360
361    /// Checks if the input extra logger name is valid.
362    pub fn check_extra_logger_name(name: &str) -> Result<(), String> {
363        strings::check_if_identifier_is_valid(name)
364    }
365
366    /// Updates an extra logger through it's name.
367    pub fn update_extra_logger(name: String, filter_str: String) -> Result<(), String> {
368        let filter = Self::build_filter(&filter_str);
369        let message = Message::UpdateExtraLogger(name, filter);
370        Self::send_message(message)
371    }
372
373    /// Removes an extra logger.
374    pub fn remove_extra_logger(name: String) -> Result<(), String> {
375        let message = Message::RemoveExtraLogger(name);
376        Self::send_message(message)
377    }
378}
379
380impl Log for Logger {
381    fn enabled(&self, metadata: &Metadata) -> bool {
382        self.filter.read().enabled(metadata)
383            || self
384                .extra_loggers
385                .read()
386                .values()
387                .any(|logger| logger.filter.enabled(metadata))
388    }
389
390    fn log(&self, record: &Record) {
391        // Check if the record is matched by the main filter
392        let is_match = self.filter.read().matches(record);
393        let extras = self
394            .extra_loggers
395            .read()
396            .iter()
397            .filter_map(|(name, logger)| {
398                if logger.filter.matches(record) {
399                    Some(name.to_owned())
400                } else {
401                    None
402                }
403            })
404            .collect::<Vec<_>>();
405        if is_match || !extras.is_empty() {
406            #[cfg(feature = "with_sentry")]
407            if self.emit_sentry_breadcrumbs {
408                use sentry::{add_breadcrumb, integrations::log::breadcrumb_from_record};
409                add_breadcrumb(|| breadcrumb_from_record(record));
410            }
411
412            let thread = thread::current();
413            let thread_name = thread.name().unwrap_or("*unnamed*");
414
415            let utc = OffsetDateTime::now_utc();
416            let fmt = FORMAT.get_or_init(|| {
417                format_description::parse(
418                    "[year]-[month]-[day] [hour]:[minute]:[second].[subsecond digits:3] \
419                    [offset_hour sign:mandatory]:[offset_minute]",
420                )
421                .expect("DateTime format_description")
422            });
423            if let Ok(dt) = utc.format(&fmt) {
424                let with_color = {
425                    let thread_name = format!("{}", Paint::blue(thread_name).bold());
426                    let date = format!("{}", Paint::rgb(47, 79, 79, dt).bold()); // darkslategrey
427                    format!(
428                        "{} {} {} {}  {}",
429                        date,
430                        thread_name,
431                        record.level(),
432                        record.target(),
433                        record.args()
434                    )
435                };
436                let _ = self.sender.send(Message::Record {
437                    is_match,
438                    extras,
439                    data: with_color,
440                });
441            }
442        }
443    }
444
445    fn flush(&self) {
446        let handle = self.handle.lock().take().expect("Logger flush only once");
447        let _ = self.sender.send(Message::Terminate);
448        let _ = handle.join();
449    }
450}
451
452fn sanitize_color(s: &str) -> String {
453    let re = RE.get_or_init(|| Regex::new("\x1b\\[[^m]+m").expect("Regex compile success"));
454    re.replace_all(s, "").to_string()
455}
456
457/// Flushes the logger when dropped.
458#[must_use]
459pub struct LoggerInitGuard;
460
461impl Drop for LoggerInitGuard {
462    fn drop(&mut self) {
463        flush();
464    }
465}
466
467/// Initializes the [Logger](struct.Logger.html) and run the logging service.
468pub fn init(env_opt: Option<&str>, config: Config) -> Result<LoggerInitGuard, SetLoggerError> {
469    setup_panic_logger();
470
471    let logger = Logger::new(env_opt, config);
472    let filter = logger.filter();
473    log::set_boxed_logger(Box::new(logger)).map(|_| {
474        log::set_max_level(filter);
475        LoggerInitGuard
476    })
477}
478
479/// Initializes the [SilentLogger](struct.SilentLogger.html).
480pub fn init_silent() -> Result<LoggerInitGuard, SetLoggerError> {
481    log::set_boxed_logger(Box::new(SilentLogger)).map(|_| LoggerInitGuard)
482}
483
484/// The SilentLogger which implements [log::Log].
485///
486/// Silent logger that does nothing.
487pub struct SilentLogger;
488
489impl Log for SilentLogger {
490    fn enabled(&self, _metadata: &Metadata) -> bool {
491        false
492    }
493
494    fn log(&self, _record: &Record) {}
495
496    fn flush(&self) {}
497}
498
499/// Flushes any buffered records.
500pub fn flush() {
501    log::logger().flush()
502}
503
504// Replace the default panic hook with logger hook, which prints panic info into logfile.
505// This function will replace all hooks that was previously registered, so make sure involving
506// before other register operations.
507fn setup_panic_logger() {
508    let panic_logger = |info: &panic::PanicHookInfo| {
509        let backtrace = Backtrace::new();
510        let thread = thread::current();
511        let name = thread.name().unwrap_or("unnamed");
512        let location = info.location().unwrap(); // The current implementation always returns Some
513        let msg = match info.payload().downcast_ref::<&'static str>() {
514            Some(s) => *s,
515            None => match info.payload().downcast_ref::<String>() {
516                Some(s) => s,
517                None => "Box<Any>",
518            },
519        };
520        log::error!(
521            target: "panic", "thread '{}' panicked at '{}': {}:{}{:?}",
522            name,
523            msg,
524            location.file(),
525            location.line(),
526            backtrace,
527        );
528    };
529    panic::set_hook(Box::new(panic_logger));
530}
531
532/// Only used by unit test
533/// Initializes the [Logger](struct.Logger.html) and run the logging service.
534pub fn init_for_test(filter: &str) -> Result<LoggerInitGuard, SetLoggerError> {
535    setup_panic_logger();
536    let config: Config = Config {
537        filter: Some(filter.to_string()),
538        color: true,
539        log_to_stdout: true,
540        log_to_file: false,
541
542        emit_sentry_breadcrumbs: None,
543        file: Default::default(),
544        log_dir: Default::default(),
545        extra: Default::default(),
546    };
547
548    let logger = Logger::new(None, config);
549    let filter = logger.filter();
550    log::set_boxed_logger(Box::new(logger)).map(|_| {
551        log::set_max_level(filter);
552        LoggerInitGuard
553    })
554}
ckb_logger_service/lib.rs

ckb_logger_service/
lib.rs
