structured_logger/
lib.rs

1// (c) 2023-present, IO Rust. All rights reserved.
2// See the file LICENSE for licensing terms.
3
4//! # Structured Logger
5//!
6//! A logging implementation for the [`log`] crate that logs structured values
7//! either synchronous or asynchronous, in JSON, CBOR, or any other format,
8//! to a file, stderr, stdout, or any other destination.
9//! To initialize the logger use the [`Builder`] struct.
10//! It is inspired by [std-logger](https://github.com/Thomasdezeeuw/std-logger).
11//!
12//! This crate provides only a logging implementation. To do actual logging use
13//! the [`log`] crate and it's various macros.
14//!
15//! ## Limiting logging targets
16//! You can use [`Builder::with_target_writer`] method to log messages related specific target to a specific writer.
17//!
18//! ## Crate features
19//!
20//! This crate has three features:
21//! * `log-panic`, enabled by default.
22//!
23//! ### Log-panic feature
24//!
25//! The `log-panic` feature will log all panics using the `error` severity,
26//! rather then using the default panic handler. It will log the panic message
27//! as well as the location and a backtrace, see the log output for an
28//! [`panic_log`] example.
29//!
30//! ## Examples
31//!
32//! * Log panics example: <https://github.com/iorust/structured-logger/blob/main/examples/panic_log.rs>
33//! * Async log example: <https://github.com/iorust/structured-logger/blob/main/examples/async_log.rs>
34//!
35//! Simple example:
36//! ```rust
37//! use serde::Serialize;
38//! use structured_logger::{async_json::new_writer, unix_ms, Builder};
39//!
40//! #[tokio::main]
41//! async fn main() {
42//!     // Initialize the logger.
43//!     Builder::with_level("info")
44//!         .with_target_writer("*", new_writer(tokio::io::stdout()))
45//!         .init();
46//!
47//!     let kv = ContextLog {
48//!         uid: "user123".to_string(),
49//!         action: "upate_book".to_string(),
50//!     };
51//!
52//!     log::info!("hello world");
53//!     // This log will be written to stdout:
54//!     // {"level":"INFO","message":"hello world","target":"simple","timestamp":1679745592127}
55//!
56//!     log::info!(target: "api",
57//!         method = "GET",
58//!         path = "/hello",
59//!         status = 200_u16,
60//!         start = unix_ms(),
61//!         elapsed = 10_u64,
62//!         kv = log::as_serde!(kv);
63//!         "",
64//!     );
65//!     // This log will be written to stdout:
66//!     // {"elapsed":10,"kv":{"uid":"user123","action":"upate_book"},"level":"INFO","message":"","method":"GET","path":"/hello","start":1679745592127,"status":200,"target":"api","timestamp":1679745592127}
67//! }
68//!
69//! #[derive(Serialize)]
70//! struct ContextLog {
71//!     uid: String,
72//!     action: String,
73//! }
74//! ```
75//!
76//! [`panic_log`]: https://github.com/iorust/structured-logger/blob/main/examples/panic_log.rs
77//! [`log`]: https://crates.io/crates/log
78//!
79
80#![doc(html_root_url = "https://docs.rs/structured-logger/latest")]
81#![allow(clippy::needless_doctest_main)]
82
83use log::{
84    kv::Error, kv::Key, kv::Value, kv::Visitor, Level, LevelFilter, Metadata, Record,
85    SetLoggerError,
86};
87use std::{
88    collections::BTreeMap,
89    env, io,
90    time::{SystemTime, UNIX_EPOCH},
91};
92
93// /// A type alias for BTreeMap<Key<'a>, Value<'a>>.
94// /// BTreeMap is used to keep the order of the keys.
95// type Log<'a> = BTreeMap<Key<'a>, Value<'a>>;
96
97/// A trait that defines how to write a log. You can implement this trait for your custom formatting and writing destination.
98///
99/// Implementation examples:
100/// * <https://github.com/iorust/structured-logger/blob/main/src/json.rs>
101/// * <https://github.com/iorust/structured-logger/blob/main/src/async_json.rs>
102pub trait Writer {
103    /// Writes a structured log to the underlying io::Write instance.
104    fn write_log(&self, value: &BTreeMap<Key, Value>) -> Result<(), io::Error>;
105}
106
107pub mod async_json;
108pub mod json;
109use json::new_writer;
110
111/// A struct to initialize the logger for [`log`] crate.
112pub struct Builder {
113    filter: LevelFilter,
114    default_writer: Box<dyn Writer>,
115    writers: Vec<(Target, Box<dyn Writer>)>,
116}
117
118impl Default for Builder {
119    fn default() -> Self {
120        Self::new()
121    }
122}
123
124impl Builder {
125    /// Returns a [`Builder`] with default configuration.
126    /// The default configuration is:
127    /// - level filter: get from the environment variable by `get_env_level()`.
128    /// - default writer: write to stderr in JSON format.
129    pub fn new() -> Self {
130        Builder {
131            filter: get_env_level(),
132            default_writer: new_writer(io::stderr()),
133            writers: Vec::new(),
134        }
135    }
136
137    /// Returns a [`Builder`] with a given level filter.
138    /// `level` is a string that can be parsed to `log::LevelFilter`.
139    /// Such as "OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE", ignore ascii case.
140    pub fn with_level(level: &str) -> Self {
141        Builder {
142            filter: level.parse().unwrap_or(LevelFilter::Info),
143            default_writer: new_writer(io::stderr()),
144            writers: Vec::new(),
145        }
146    }
147
148    /// Returns a [`Builder`] with a given `writer` as default writer.
149    pub fn with_default_writer(self, writer: Box<dyn Writer>) -> Self {
150        Builder {
151            filter: self.filter,
152            default_writer: writer,
153            writers: self.writers,
154        }
155    }
156
157    /// Returns a [`Builder`] with a given `targets` pattern and `writer`.
158    /// `targets` is a pattern that be used to test log target, if true, the log will be written to the `writer`.
159    /// `writer` is a boxed struct that implements the `Writer` trait.
160    /// You can call this method multiple times in order to add multiple writers.
161    ///
162    /// `targets` pattern examples:
163    /// - `"api"`: match the target "api".
164    /// - `"api,db"`: match the target "api" or "db".
165    /// - `"api*,db"`: match the target "db", "api", "api::v1", "api::v2", etc.
166    /// - `"*"`: match all targets.
167    pub fn with_target_writer(self, targets: &str, writer: Box<dyn Writer>) -> Self {
168        let mut cfg = Builder {
169            filter: self.filter,
170            default_writer: self.default_writer,
171            writers: self.writers,
172        };
173
174        cfg.writers.push((Target::from(targets), writer));
175        cfg
176    }
177
178    /// Initialize the logger for [`log`] crate.
179    ///
180    /// See the [crate level documentation] for more.
181    ///
182    /// [crate level documentation]: index.html
183    ///
184    /// # Panics
185    ///
186    /// This will panic if the logger fails to initialize. Use [`Builder::try_init`] if
187    /// you want to handle the error yourself.
188    pub fn init(self) {
189        self.try_init()
190            .unwrap_or_else(|err| panic!("failed to initialize the logger: {}", err));
191    }
192
193    /// Try to initialize the logger for [`log`] crate.
194    ///
195    /// Unlike [`Builder::init`] this doesn't panic when the logger fails to initialize.
196    /// See the [crate level documentation] for more.
197    ///
198    /// [`init`]: fn.init.html
199    /// [crate level documentation]: index.html
200    pub fn try_init(self) -> Result<(), SetLoggerError> {
201        let logger = Box::new(Logger {
202            filter: self.filter,
203            default_writer: self.default_writer,
204            writers: self
205                .writers
206                .into_iter()
207                .map(|(t, w)| (InnerTarget::from(t), w))
208                .collect(),
209        });
210        log::set_boxed_logger(logger)?;
211        log::set_max_level(self.filter);
212
213        #[cfg(feature = "log-panic")]
214        std::panic::set_hook(Box::new(log_panic));
215        Ok(())
216    }
217}
218
219/// Returns the current unix timestamp in milliseconds.
220#[inline]
221pub fn unix_ms() -> u64 {
222    let ts = SystemTime::now()
223        .duration_since(UNIX_EPOCH)
224        .expect("system time before Unix epoch");
225    ts.as_millis() as u64
226}
227
228/// Returns the log level from the environment variables: `LOG`, `LOG_LEVEL`, `RUST_LOG`, `TRACE` or `DEBUG`.
229/// Default is `INFO`.
230pub fn get_env_level() -> LevelFilter {
231    for var in &["LOG", "LOG_LEVEL", "RUST_LOG"] {
232        if let Ok(level) = env::var(var) {
233            if let Ok(level) = level.parse() {
234                return level;
235            }
236        }
237    }
238
239    if env::var("TRACE").is_ok() {
240        LevelFilter::Trace
241    } else if env::var("DEBUG").is_ok() {
242        LevelFilter::Debug
243    } else {
244        LevelFilter::Info
245    }
246}
247
248struct Logger {
249    filter: LevelFilter,
250    default_writer: Box<dyn Writer>,
251    writers: Box<[(InnerTarget, Box<dyn Writer>)]>,
252}
253
254impl Logger {
255    fn get_writer(&self, target: &str) -> &dyn Writer {
256        for t in self.writers.iter() {
257            if t.0.test(target) {
258                return t.1.as_ref();
259            }
260        }
261
262        self.default_writer.as_ref()
263    }
264
265    fn try_log(&self, record: &Record) -> Result<(), io::Error> {
266        let kvs = record.key_values();
267        let mut visitor = KeyValueVisitor(BTreeMap::new());
268        let _ = kvs.visit(&mut visitor);
269
270        visitor
271            .0
272            .insert(Key::from("target"), Value::from(record.target()));
273
274        let args = record.args();
275        let msg: String;
276        if let Some(msg) = args.as_str() {
277            visitor.0.insert(Key::from("message"), Value::from(msg));
278        } else {
279            msg = args.to_string();
280            visitor.0.insert(Key::from("message"), Value::from(&msg));
281        }
282
283        let level = record.level();
284        visitor
285            .0
286            .insert(Key::from("level"), Value::from(level.as_str()));
287
288        if level <= Level::Warn {
289            if let Some(val) = record.module_path() {
290                visitor.0.insert(Key::from("module"), Value::from(val));
291            }
292            if let Some(val) = record.file() {
293                visitor.0.insert(Key::from("file"), Value::from(val));
294            }
295            if let Some(val) = record.line() {
296                visitor.0.insert(Key::from("line"), Value::from(val));
297            }
298        }
299
300        visitor
301            .0
302            .insert(Key::from("timestamp"), Value::from(unix_ms()));
303        self.get_writer(record.target()).write_log(&visitor.0)?;
304        Ok(())
305    }
306}
307
308unsafe impl Sync for Logger {}
309unsafe impl Send for Logger {}
310
311impl log::Log for Logger {
312    fn enabled(&self, metadata: &Metadata) -> bool {
313        self.filter >= metadata.level()
314    }
315
316    fn log(&self, record: &Record) {
317        if self.enabled(record.metadata()) {
318            if let Err(err) = self.try_log(record) {
319                // should never happen, but if it does, we log it.
320                log_failure(format!("Logger failed to log: {}", err).as_str());
321            }
322        }
323    }
324
325    fn flush(&self) {}
326}
327
328struct Target {
329    all: bool,
330    prefix: Vec<String>,
331    items: Vec<String>,
332}
333
334impl Target {
335    fn from(targets: &str) -> Self {
336        let mut target = Target {
337            all: false,
338            prefix: Vec::new(),
339            items: Vec::new(),
340        };
341        for t in targets.split(',') {
342            let t = t.trim();
343            if t == "*" {
344                target.all = true;
345                break;
346            } else if t.ends_with('*') {
347                target.prefix.push(t.trim_end_matches('*').to_string());
348            } else {
349                target.items.push(t.to_string());
350            }
351        }
352        target
353    }
354}
355
356struct InnerTarget {
357    all: bool,
358    prefix: Box<[Box<str>]>,
359    items: Box<[Box<str>]>,
360}
361
362impl InnerTarget {
363    fn from(t: Target) -> Self {
364        InnerTarget {
365            all: t.all,
366            prefix: t.prefix.into_iter().map(|s| s.into_boxed_str()).collect(),
367            items: t.items.into_iter().map(|s| s.into_boxed_str()).collect(),
368        }
369    }
370
371    fn test(&self, target: &str) -> bool {
372        if self.all {
373            return true;
374        }
375        if self.items.iter().any(|i| i.as_ref() == target) {
376            return true;
377        }
378        if self.prefix.iter().any(|p| target.starts_with(p.as_ref())) {
379            return true;
380        }
381        false
382    }
383}
384
385struct KeyValueVisitor<'kvs>(BTreeMap<Key<'kvs>, Value<'kvs>>);
386
387impl<'kvs> Visitor<'kvs> for KeyValueVisitor<'kvs> {
388    #[inline]
389    fn visit_pair(&mut self, key: Key<'kvs>, value: Value<'kvs>) -> Result<(), Error> {
390        self.0.insert(key, value);
391        Ok(())
392    }
393}
394
395/// A fallback logging function that is used in case of logging failure in [`Writer`] implementation.
396/// It will write failure information in JSON to `stderr`.
397pub fn log_failure(msg: &str) {
398    match serde_json::to_string(msg) {
399        Ok(msg) => {
400            eprintln!(
401                "{{\"level\":\"ERROR\",\"message\":{},\"target\":\"structured_logger\",\"timestamp\":{}}}",
402                &msg,
403                unix_ms()
404            );
405        }
406        Err(err) => {
407            // should never happen
408            panic!("log_failure serialize error: {}", err)
409        }
410    }
411}
412
413/// Panic hook that logs the panic using [`log::error!`].
414#[cfg(feature = "log-panic")]
415fn log_panic(info: &std::panic::PanicInfo<'_>) {
416    use std::backtrace::Backtrace;
417    use std::thread;
418
419    let mut record = log::Record::builder();
420    let thread = thread::current();
421    let thread_name = thread.name().unwrap_or("unnamed");
422    let backtrace = Backtrace::force_capture();
423
424    let key_values = [
425        ("backtrace", Value::capture_display(&backtrace)),
426        ("thread_name", Value::from(thread_name)),
427    ];
428    let key_values = key_values.as_slice();
429
430    let _ = record
431        .level(log::Level::Error)
432        .target("panic")
433        .key_values(&key_values);
434
435    if let Some(location) = info.location() {
436        let _ = record
437            .file(Some(location.file()))
438            .line(Some(location.line()));
439    };
440
441    log::logger().log(
442        &record
443            .args(format_args!("thread '{thread_name}' {info}"))
444            .build(),
445    );
446}
447
448#[cfg(test)]
449mod tests {
450    use super::*;
451    use gag::BufferRedirect;
452    use serde_json::{de, value};
453    use std::io::Read;
454
455    #[test]
456    fn unix_ms_works() {
457        let now = unix_ms();
458        assert!(now > 1670123456789_u64);
459    }
460
461    #[test]
462    fn get_env_level_works() {
463        assert_eq!(Level::Info, get_env_level());
464
465        env::set_var("LOG", "error");
466        assert_eq!(Level::Error, get_env_level());
467        env::remove_var("LOG");
468
469        env::set_var("LOG_LEVEL", "Debug");
470        assert_eq!(Level::Debug, get_env_level());
471        env::remove_var("LOG_LEVEL");
472
473        env::set_var("RUST_LOG", "WARN");
474        assert_eq!(Level::Warn, get_env_level());
475        env::remove_var("RUST_LOG");
476
477        env::set_var("TRACE", "");
478        assert_eq!(Level::Trace, get_env_level());
479        env::remove_var("TRACE");
480
481        env::set_var("DEBUG", "");
482        assert_eq!(Level::Debug, get_env_level());
483        env::remove_var("DEBUG");
484    }
485
486    #[test]
487    fn target_works() {
488        let target = InnerTarget::from(Target::from("*"));
489        assert!(target.test(""));
490        assert!(target.test("api"));
491        assert!(target.test("hello"));
492
493        let target = InnerTarget::from(Target::from("api*, file,db"));
494        assert!(!target.test(""));
495        assert!(!target.test("apx"));
496        assert!(!target.test("err"));
497        assert!(!target.test("dbx"));
498        assert!(target.test("api"));
499        assert!(target.test("apiinfo"));
500        assert!(target.test("apierr"));
501        assert!(target.test("file"));
502        assert!(target.test("db"));
503
504        let target = InnerTarget::from(Target::from("api*, file, *"));
505        assert!(target.test(""));
506        assert!(target.test("apx"));
507        assert!(target.test("err"));
508        assert!(target.test("api"));
509        assert!(target.test("apiinfo"));
510        assert!(target.test("apierr"));
511        assert!(target.test("error"));
512    }
513
514    #[test]
515    fn log_failure_works() {
516        let cases: Vec<&str> = vec!["", "\"", "hello", "\"hello >", "hello\n", "hello\r"];
517        for case in cases {
518            let buf = BufferRedirect::stderr().unwrap();
519            log_failure(case);
520            let mut msg: String = String::new();
521            buf.into_inner().read_to_string(&mut msg).unwrap();
522            let msg = msg.as_str();
523            // println!("JSON: {}", msg);
524            assert_eq!('\n', msg.chars().last().unwrap());
525
526            let res = de::from_str::<BTreeMap<String, value::Value>>(msg);
527            assert!(res.is_ok());
528            let res = res.unwrap();
529            assert_eq!("ERROR", res.get("level").unwrap());
530            assert_eq!(case, res.get("message").unwrap());
531            assert_eq!("structured_logger", res.get("target").unwrap());
532            assert!(unix_ms() - 999 <= res.get("timestamp").unwrap().as_u64().unwrap());
533        }
534    }
535}