1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
// (c) 2023-present, IO Rust. All rights reserved.
// See the file LICENSE for licensing terms.

//! # Structured Logger
//!
//! A logging implementation for the [`log`] crate that logs structured values
//! either synchronous or asynchronous, as JSON, CBOR, or any other format,
//! into a file, stderr, stdout, or any other destination.
//! To initialize the logger use the [`Builder`] struct.
//! It is inspired by [std-logger](https://github.com/Thomasdezeeuw/std-logger).
//!
//! This crate provides only a logging implementation. To do actual logging use
//! the [`log`] crate and it's various macros.
//!
//! ## Crate features
//!
//! This crate has three features:
//! * `log-panic`, enabled by default.
//!
//! ### Log-panic feature
//!
//! The `log-panic` feature will log all panics using the `error` severity,
//! rather then using the default panic handler. It will log the panic message
//! as well as the location and a backtrace, see the log output for an
//! [`panic_log`] example.
//!
//! ## Examples
//!
//! * Log panics example: <https://github.com/iorust/structured-logger/blob/main/examples/panic_log.rs>
//! * Async log example: <https://github.com/iorust/structured-logger/blob/main/examples/async_log.rs>
//!
//! Muilti writers example:
//! ```rust
//! use serde::Serialize;
//! use std::{fs::File, io::stdout};
//! use structured_logger::{json::new_writer, unix_ms, Builder};
//!
//! fn main() {
//!     // Initialize the logger.
//!     // Optional: create a file to write logs to.
//!     let log_file = File::options()
//!         .create(true)
//!         .append(true)
//!         .open("app.log")
//!         .unwrap();
//!
//!     // Builder::with_level("debug")
//!     Builder::new()
//!         // Optional: set a specific writer (format to JSON, write to stdout) for target "api".
//!         .with_target_writer("api", new_writer(stdout()))
//!         // Optional: set a specific writer (format to JSON, write to app.log file) for target "file".
//!         .with_target_writer("file", new_writer(log_file))
//!         .init();
//!
//!     let kv = ContextLog {
//!         uid: "user123".to_string(),
//!         action: "upate_book".to_string(),
//!     };
//!
//!     log::info!("hello world");
//!     // This log will be written to stderr (default writer):
//!     // {"level":"INFO","message":"hello world","target":"simple","timestamp":1679745592127}
//!
//!     log::info!(target: "api",
//!         method = "GET",
//!         path = "/hello",
//!         status = 200_u16,
//!         start = unix_ms(),
//!         elapsed = 10_u64,
//!         kv = log::as_serde!(kv);
//!         "",
//!     );
//!     // This log will be written to stdout:
//!     // {"elapsed":10,"kv":{"uid":"user123","action":"upate_book"},"level":"INFO","message":"","method":"GET","path":"/hello","start":1679745592127,"status":200,"target":"api","timestamp":1679745592127}
//!
//!     log::info!(target: "file",
//!         method = "GET",
//!         path = "/hello",
//!         status = 200_u16,
//!         start = unix_ms(),
//!         elapsed = 10_u64,
//!         kv = log::as_serde!(kv);
//!         "",
//!     );
//!     // This log will be written to file "app.log":
//!     // {"elapsed":10,"kv":{"uid":"user123","action":"upate_book"},"level":"INFO","message":"","method":"GET","path":"/hello","start":1679745592127,"status":200,"target":"file","timestamp":1679745592127}
//! }
//!
//! #[derive(Serialize)]
//! struct ContextLog {
//!     uid: String,
//!     action: String,
//! }
//! ```
//!
//! [`panic_log`]: https://github.com/iorust/structured-logger/blob/main/examples/panic_log.rs
//! [`log`]: https://crates.io/crates/log
//!

#![doc(html_root_url = "https://docs.rs/structured-logger/latest")]
#![allow(clippy::needless_doctest_main)]

use log::{
    kv::Error, kv::Key, kv::Value, kv::Visitor, Level, LevelFilter, Metadata, Record,
    SetLoggerError,
};
use std::{
    collections::BTreeMap,
    env, io,
    time::{SystemTime, UNIX_EPOCH},
};

// /// A type alias for BTreeMap<Key<'a>, Value<'a>>.
// /// BTreeMap is used to keep the order of the keys.
// type Log<'a> = BTreeMap<Key<'a>, Value<'a>>;

/// A trait that defines how to write a log. You can implement this trait for your custom formatting and writing destination.
///
/// Implementation examples:
/// * <https://github.com/iorust/structured-logger/blob/main/src/json.rs>
/// * <https://github.com/iorust/structured-logger/blob/main/src/async_json.rs>
pub trait Writer {
    /// Writes a structured log to the underlying io::Write instance.
    fn write_log(&self, value: &BTreeMap<Key, Value>) -> Result<(), io::Error>;
}

pub mod async_json;
pub mod json;
use json::new_writer;

/// A struct to initialize the logger.
pub struct Builder {
    filter: LevelFilter,
    default_writer: Box<dyn Writer>,
    writers: BTreeMap<&'static str, Box<dyn Writer>>,
}

impl Default for Builder {
    fn default() -> Self {
        Self::new()
    }
}

impl Builder {
    /// Returns a new Logger with default configuration.
    /// The default configuration is:
    /// - level filter: get from the environment variable by `get_env_level()`.
    /// - default writer: write to stderr in JSON format.
    pub fn new() -> Self {
        Builder {
            filter: get_env_level(),
            default_writer: new_writer(io::stderr()),
            writers: BTreeMap::new(),
        }
    }

    /// Returns a new Logger with a given level filter.
    /// `level` is a string that can be parsed to `log::LevelFilter`.
    /// Such as "OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE", ignore ascii case.
    pub fn with_level(level: &str) -> Self {
        Builder {
            filter: level.parse().unwrap_or(LevelFilter::Info),
            default_writer: new_writer(io::stderr()),
            writers: BTreeMap::new(),
        }
    }

    /// Returns a new Logger with a given `target` and `writer`.
    /// `target` is a string that be used as a log target.
    /// `writer` is a struct that implements the `Writer` trait.
    /// You can call this method multiple times to add multiple writers.
    pub fn with_target_writer(self, target: &'static str, writer: Box<dyn Writer>) -> Self {
        let mut cfg = Builder {
            filter: self.filter,
            default_writer: self.default_writer,
            writers: self.writers,
        };
        cfg.writers.insert(target, writer);
        cfg
    }

    /// Initialize the logger.
    ///
    /// See the [crate level documentation] for more.
    ///
    /// [crate level documentation]: index.html
    ///
    /// # Panics
    ///
    /// This will panic if the logger fails to initialize. Use [`Builder::try_init`] if
    /// you want to handle the error yourself.
    pub fn init(self) {
        self.try_init()
            .unwrap_or_else(|err| panic!("failed to initialize the logger: {err}"));
    }

    /// Try to initialize the logger.
    ///
    /// Unlike [`Builder::init`] this doesn't panic when the logger fails to initialize.
    /// See the [crate level documentation] for more.
    ///
    /// [`init`]: fn.init.html
    /// [crate level documentation]: index.html
    pub fn try_init(self) -> Result<(), SetLoggerError> {
        let logger = Box::new(Logger {
            filter: self.filter,
            default_writer: self.default_writer,
            writers: self.writers,
        });
        log::set_boxed_logger(logger)?;
        log::set_max_level(self.filter);

        #[cfg(feature = "log-panic")]
        std::panic::set_hook(Box::new(log_panic));
        Ok(())
    }
}

/// Returns the current unix timestamp in milliseconds.
pub fn unix_ms() -> u64 {
    let ts = SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .expect("system time before Unix epoch");
    ts.as_millis() as u64
}

/// Returns the log level from the environment variables.
pub fn get_env_level() -> LevelFilter {
    for var in &["LOG", "LOG_LEVEL"] {
        if let Ok(level) = env::var(var) {
            if let Ok(level) = level.parse() {
                return level;
            }
        }
    }

    if env::var("TRACE").is_ok() {
        LevelFilter::Trace
    } else if env::var("DEBUG").is_ok() {
        LevelFilter::Debug
    } else {
        LevelFilter::Info
    }
}

struct Logger {
    filter: LevelFilter,
    default_writer: Box<dyn Writer>,
    writers: BTreeMap<&'static str, Box<dyn Writer>>,
}

impl Logger {
    fn get_writer(&self, target: &str) -> &dyn Writer {
        if let Some(writer) = self.writers.get(target) {
            writer.as_ref()
        } else {
            self.default_writer.as_ref()
        }
    }

    fn try_log(&self, record: &Record) -> Result<(), io::Error> {
        let kvs = record.key_values();
        let mut visitor = KeyValueVisitor(BTreeMap::new());
        let _ = kvs.visit(&mut visitor);

        visitor
            .0
            .insert(Key::from("target"), Value::from(record.target()));

        let args = record.args();
        let msg: String;
        if let Some(msg) = args.as_str() {
            visitor.0.insert(Key::from("message"), Value::from(msg));
        } else {
            msg = args.to_string();
            visitor.0.insert(Key::from("message"), Value::from(&msg));
        }

        let level = record.level();
        visitor
            .0
            .insert(Key::from("level"), Value::from(level.as_str()));

        if level <= Level::Warn {
            if let Some(val) = record.module_path() {
                visitor.0.insert(Key::from("module"), Value::from(val));
            }
            if let Some(val) = record.file() {
                visitor.0.insert(Key::from("file"), Value::from(val));
            }
            if let Some(val) = record.line() {
                visitor.0.insert(Key::from("line"), Value::from(val));
            }
        }

        visitor
            .0
            .insert(Key::from("timestamp"), Value::from(unix_ms()));
        self.get_writer(record.target()).write_log(&visitor.0)?;
        Ok(())
    }
}

unsafe impl Sync for Logger {}
unsafe impl Send for Logger {}

impl log::Log for Logger {
    fn enabled(&self, metadata: &Metadata) -> bool {
        self.filter >= metadata.level()
    }

    fn log(&self, record: &Record) {
        if self.enabled(record.metadata()) {
            if let Err(err) = self.try_log(record) {
                // should never happen, but if it does, we log it.
                eprintln!(
                    "{{\"level\":\"ERROR\",\"message\":\"failed to write log: {}\",\"target\":\"Logger\",\"timestamp\":{}}}",
                     err, unix_ms(),
                );
            }
        }
    }

    fn flush(&self) {}
}

struct KeyValueVisitor<'kvs>(BTreeMap<Key<'kvs>, Value<'kvs>>);

impl<'kvs> Visitor<'kvs> for KeyValueVisitor<'kvs> {
    fn visit_pair(&mut self, key: Key<'kvs>, value: Value<'kvs>) -> Result<(), Error> {
        self.0.insert(key, value);
        Ok(())
    }
}

/// Panic hook that logs the panic using [`log::error!`].
#[cfg(feature = "log-panic")]
fn log_panic(info: &std::panic::PanicInfo<'_>) {
    use std::backtrace::Backtrace;
    use std::thread;

    let mut record = log::Record::builder();
    let thread = thread::current();
    let thread_name = thread.name().unwrap_or("unnamed");
    let backtrace = Backtrace::force_capture();

    let key_values = [
        ("backtrace", Value::capture_display(&backtrace)),
        ("thread_name", Value::from(thread_name)),
    ];
    let key_values = key_values.as_slice();

    let _ = record
        .level(log::Level::Error)
        .target("panic")
        .key_values(&key_values);

    if let Some(location) = info.location() {
        let _ = record
            .file(Some(location.file()))
            .line(Some(location.line()));
    };

    log::logger().log(
        &record
            .args(format_args!("thread '{thread_name}' {info}"))
            .build(),
    );
}

#[cfg(test)]
mod tests {
    use super::*;
    use tokio::task::JoinSet;

    #[tokio::test(flavor = "multi_thread", worker_threads = 3)]
    async fn multiple_threads_works() {
        Builder::new().init();

        let mut set = JoinSet::new();

        for i in 0..1000 {
            set.spawn(async move {
                log::info!("hello {}", i);
                i
            });
        }

        let mut seen = [false; 1000];
        while let Some(res) = set.join_next().await {
            let idx = res.unwrap();
            seen[idx] = true;
        }

        for i in 0..1000 {
            assert!(seen[i]);
        }
    }
}