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

structured_logger/
lib.rs
