From 230f2ea58afcea94c3d690d44607faac22f4e367 Mon Sep 17 00:00:00 2001 From: ellttben Date: Wed, 20 Mar 2024 06:08:00 +0000 Subject: [PATCH] Add log::kv support --- Cargo.toml | 45 +++++++++++--- src/encode/json.rs | 65 ++++++++++++++++--- src/encode/pattern/mod.rs | 128 +++++++++++++++++++++++++++++++++++++- 3 files changed, 220 insertions(+), 18 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index fbc77abd..ed1e7692 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,7 +1,10 @@ [package] name = "log4rs" version = "1.3.0" -authors = ["Steven Fackler ", "Evan Simmons "] +authors = [ + "Steven Fackler ", + "Evan Simmons ", +] description = "A highly configurable multi-output logging implementation for the `log` facade" license = "MIT OR Apache-2.0" repository = "https://github.com/estk/log4rs" @@ -13,7 +16,13 @@ rust-version = "1.69" [features] default = ["all_components", "config_parsing", "yaml_format"] -config_parsing = ["humantime", "serde", "serde-value", "typemap-ors", "log/serde"] +config_parsing = [ + "humantime", + "serde", + "serde-value", + "typemap-ors", + "log/serde", +] yaml_format = ["serde_yaml"] json_format = ["serde_json"] toml_format = ["toml"] @@ -27,13 +36,21 @@ fixed_window_roller = [] size_trigger = [] time_trigger = ["rand"] onstartup_trigger = [] -json_encoder = ["serde", "serde_json", "chrono", "log-mdc", "log/serde", "thread-id"] +json_encoder = [ + "serde", + "serde_json", + "chrono", + "log-mdc", + "log/serde", + "thread-id", +] pattern_encoder = ["chrono", "log-mdc", "thread-id"] ansi_writer = [] console_writer = ["ansi_writer", "libc", "winapi"] simple_writer = [] threshold_filter = [] background_rotation = [] +log_kv = ["log/kv"] all_components = [ "console_appender", @@ -47,7 +64,7 @@ all_components = [ "onstartup_trigger", "json_encoder", "pattern_encoder", - "threshold_filter" + "threshold_filter", ] gzip = ["flate2"] @@ -58,7 +75,9 @@ harness = false [dependencies] arc-swap = "1.6" -chrono = { version = "0.4.23", optional = true, features = ["clock"], default-features = false } +chrono = { version = "0.4.23", optional = true, features = [ + "clock", +], default-features = false } flate2 = { version = "1.0", optional = true } fnv = "1.0" humantime = { version = "2.1", optional = true } @@ -72,14 +91,20 @@ serde_json = { version = "1.0", optional = true } serde_yaml = { version = "0.9", optional = true } toml = { version = "<0.8.10", optional = true } parking_lot = { version = "0.12.0", optional = true } -rand = { version = "0.8", optional = true} +rand = { version = "0.8", optional = true } thiserror = "1.0.15" anyhow = "1.0.28" derivative = "2.2" once_cell = "1.17.1" [target.'cfg(windows)'.dependencies] -winapi = { version = "0.3", optional = true, features = ["handleapi", "minwindef", "processenv", "winbase", "wincon"] } +winapi = { version = "0.3", optional = true, features = [ + "handleapi", + "minwindef", + "processenv", + "winbase", + "wincon", +] } [target.'cfg(not(windows))'.dependencies] libc = { version = "0.2", optional = true } @@ -98,7 +123,11 @@ required-features = ["json_encoder", "console_appender"] [[example]] name = "log_to_file" -required-features = ["console_appender", "file_appender", "rolling_file_appender"] +required-features = [ + "console_appender", + "file_appender", + "rolling_file_appender", +] [[example]] name = "compile_time_config" diff --git a/src/encode/json.rs b/src/encode/json.rs index 784a8739..53efae9c 100644 --- a/src/encode/json.rs +++ b/src/encode/json.rs @@ -24,6 +24,11 @@ //! } //! } //! ``` +//! If the `log_kv` feature is enabled, an additional `attributes` field will +//! contain a map of the record's [log::kv][log_kv] structured logging +//! attributes. +//! +//! [log_kv]: https://docs.rs/log/latest/log/kv/index.html use chrono::{ format::{DelayedFormat, Fixed, Item}, @@ -76,6 +81,8 @@ impl JsonEncoder { thread: thread.name(), thread_id: thread_id::get(), mdc: Mdc, + #[cfg(feature = "log_kv")] + attributes: kv::get_attributes(record.key_values())?, }; message.serialize(&mut serde_json::Serializer::new(&mut *w))?; w.write_all(NEWLINE.as_bytes())?; @@ -106,6 +113,8 @@ struct Message<'a> { thread: Option<&'a str>, thread_id: usize, mdc: Mdc, + #[cfg(feature = "log_kv")] + attributes: kv::Map, } fn ser_display(v: &T, s: S) -> Result @@ -162,6 +171,34 @@ impl Deserialize for JsonEncoderDeserializer { Ok(Box::::default()) } } +#[cfg(feature = "log_kv")] +mod kv { + use log::kv::VisitSource; + use std::collections::BTreeMap; + + pub(crate) type Map = BTreeMap; + + pub(crate) fn get_attributes(source: &dyn log::kv::Source) -> anyhow::Result { + struct Visitor { + inner: Map, + } + impl<'kvs> VisitSource<'kvs> for Visitor { + fn visit_pair( + &mut self, + key: log::kv::Key<'kvs>, + value: log::kv::Value<'kvs>, + ) -> Result<(), log::kv::Error> { + self.inner.insert(format!("{key}"), format!("{value}")); + Ok(()) + } + } + let mut visitor = Visitor { + inner: BTreeMap::new(), + }; + source.visit(&mut visitor)?; + Ok(visitor.inner) + } +} #[cfg(test)] #[cfg(feature = "simple_writer")] @@ -189,26 +226,35 @@ mod test { let encoder = JsonEncoder::new(); + let mut record_builder = Record::builder(); + record_builder + .level(level) + .target(target) + .module_path(Some(module_path)) + .file(Some(file)) + .line(Some(line)); + + #[cfg(feature = "log_kv")] + record_builder.key_values(&[("log_foo", "log_bar")]); + let mut buf = vec![]; encoder .encode_inner( &mut SimpleWriter(&mut buf), time, - &Record::builder() - .level(level) - .target(target) - .module_path(Some(module_path)) - .file(Some(file)) - .line(Some(line)) - .args(format_args!("{}", message)) - .build(), + &record_builder.args(format_args!("{}", message)).build(), ) .unwrap(); + #[cfg(feature = "log_kv")] + let expected_attributes = ",\"attributes\":{\"log_foo\":\"log_bar\"}"; + #[cfg(not(feature = "log_kv"))] + let expected_attributes = ""; + let expected = format!( "{{\"time\":\"{}\",\"level\":\"{}\",\"message\":\"{}\",\"module_path\":\"{}\",\ \"file\":\"{}\",\"line\":{},\"target\":\"{}\",\ - \"thread\":\"{}\",\"thread_id\":{},\"mdc\":{{\"foo\":\"bar\"}}}}", + \"thread\":\"{}\",\"thread_id\":{},\"mdc\":{{\"foo\":\"bar\"}}{}}}", time.to_rfc3339(), level, message, @@ -218,6 +264,7 @@ mod test { target, thread, thread_id::get(), + expected_attributes ); assert_eq!(expected, String::from_utf8(buf).unwrap().trim()); } diff --git a/src/encode/pattern/mod.rs b/src/encode/pattern/mod.rs index 5215f2ec..7c77f50f 100644 --- a/src/encode/pattern/mod.rs +++ b/src/encode/pattern/mod.rs @@ -73,6 +73,14 @@ //! defaults to the empty string. //! * `{X(user_id)}` - `123e4567-e89b-12d3-a456-426655440000` //! * `{X(nonexistent_key)(no mapping)}` - `no mapping` +//! * `K`, `key_value` - A value from a [log::kv][log_kv] structured logging +//! record attributes. The first argument specifies the key, and the second +//! argument specifies the default value if the key is not present in the +//! log record's attributes. The second argument is optional, and defaults +//! to the empty string. This formatter requires the `log_kv` feature to be +//! enabled. +//! * `{K(user_id)}` - `123e4567-e89b-12d3-a456-426655440000` +//! * `{K(nonexistent_key)(no mapping)}` - `no mapping` //! * An "unnamed" formatter simply formats its argument, applying the format //! specification. //! * `{({l} {m})}` - `INFO hello` @@ -120,6 +128,7 @@ //! level `DEBUG` will be truncated to `DEBUG hello, wo`. //! //! [MDC]: https://crates.io/crates/log-mdc +//! [log_kv]: https://docs.rs/log/latest/log/kv/index.html use chrono::{Local, Utc}; use derivative::Derivative; @@ -536,6 +545,47 @@ impl<'a> From> for Chunk { params: parameters, } } + #[cfg(feature = "log_kv")] + "K" | "key_value" => { + if formatter.args.len() > 2 { + return Chunk::Error("expected at most two arguments".to_owned()); + } + + let key = match formatter.args.first() { + Some(arg) => { + if let Some(arg) = arg.first() { + match arg { + Piece::Text(key) => key.to_owned(), + Piece::Error(ref e) => return Chunk::Error(e.clone()), + _ => return Chunk::Error("invalid log::kv key".to_owned()), + } + } else { + return Chunk::Error("invalid log::kv key".to_owned()); + } + } + None => return Chunk::Error("missing log::kv key".to_owned()), + }; + + let default = match formatter.args.get(1) { + Some(arg) => { + if let Some(arg) = arg.first() { + match arg { + Piece::Text(value) => value.to_owned(), + Piece::Error(ref e) => return Chunk::Error(e.clone()), + _ => return Chunk::Error("invalid log::kv default".to_owned()), + } + } else { + return Chunk::Error("invalid log::kv default".to_owned()); + } + } + None => "", + }; + + Chunk::Formatted { + chunk: FormattedChunk::Kv(key.into(), default.into()), + params: parameters, + } + } "" => { if formatter.args.len() != 1 { return Chunk::Error("expected exactly one argument".to_owned()); @@ -593,6 +643,8 @@ enum FormattedChunk { Debug(Vec), Release(Vec), Mdc(String, String), + #[cfg(feature = "log_kv")] + Kv(String, String), } impl FormattedChunk { @@ -666,6 +718,15 @@ impl FormattedChunk { FormattedChunk::Mdc(ref key, ref default) => { log_mdc::get(key, |v| write!(w, "{}", v.unwrap_or(default))) } + #[cfg(feature = "log_kv")] + FormattedChunk::Kv(ref key, ref default) => { + use log::kv::ToKey; + if let Some(v) = record.key_values().get(key.to_key()) { + write!(w, "{v}") + } else { + write!(w, "{default}") + } + } } } } @@ -751,7 +812,7 @@ mod tests { #[cfg(feature = "simple_writer")] use std::thread; - use super::{Chunk, PatternEncoder}; + use super::*; #[cfg(feature = "simple_writer")] use crate::encode::writer::simple::SimpleWriter; #[cfg(feature = "simple_writer")] @@ -1031,6 +1092,71 @@ mod tests { assert_eq!(buf, b"missing value"); } + #[test] + #[cfg(all(feature = "simple_writer", feature = "log_kv"))] + fn test_kv() { + let pw = PatternEncoder::new("{K(user_id)}"); + let kv = [("user_id", "kv value")]; + + let mut buf = vec![]; + pw.encode( + &mut SimpleWriter(&mut buf), + &Record::builder().key_values(&kv).build(), + ) + .unwrap(); + + assert_eq!(buf, b"kv value"); + } + + #[test] + #[cfg(all(feature = "simple_writer", feature = "log_kv"))] + fn test_kv_missing_default() { + let pw = PatternEncoder::new("{K(user_id)}"); + + let mut buf = vec![]; + pw.encode(&mut SimpleWriter(&mut buf), &Record::builder().build()) + .unwrap(); + + assert_eq!(buf, b""); + } + + #[test] + #[cfg(all(feature = "simple_writer", feature = "log_kv"))] + fn test_kv_missing_custom() { + let pw = PatternEncoder::new("{K(user_id)(missing value)}"); + + let mut buf = vec![]; + pw.encode(&mut SimpleWriter(&mut buf), &Record::builder().build()) + .unwrap(); + + assert_eq!(buf, b"missing value"); + } + + #[test] + #[cfg(feature = "log_kv")] + fn test_kv_from_piece_to_chunk() { + let tests = vec![ + ( + "[{K(user_id)(foobar)(test):<5.5}]", + "expected at most two arguments", + ), + ("[{K({l user_id):<5.5}]", "expected '}'"), + ("[{K({l} user_id):<5.5}]", "invalid log::kv key"), + ("[{K:<5.5}]", "missing log::kv key"), + ("[{K(user_id)({l):<5.5}]", "expected '}'"), + ("[{K(user_id)({l}):<5.5}]", "invalid log::kv default"), + ("[{K(user_id)():<5.5} {M}]", "invalid log::kv default"), + ]; + + for (pattern, error_msg) in tests { + let chunks: Vec = Parser::new(pattern).map(From::from).collect(); + match chunks.get(1).unwrap() { + Chunk::Error(err) => assert!(err.contains(error_msg)), + _ => panic!(), + } + } + } + #[test] #[cfg(feature = "simple_writer")] fn debug_release() {