ckb_logger_service/
lib.rs

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

ckb_logger_service/
lib.rs
