From 9d26ad586ef5d6b4f77b0b3752dc7b624e82d29b Mon Sep 17 00:00:00 2001 From: Thayne McCombs Date: Mon, 1 Jul 2019 17:58:22 -0600 Subject: [PATCH] feat: Add support for Key-Value data in log records See https://github.com/rust-lang-nursery/log/issues/328 --- Cargo.lock | 18 ++--- Cargo.toml | 1 + src/fmt/kv.rs | 47 ++++++++++++ src/fmt/mod.rs | 193 ++++++++++++++++++++++++++++++++++++------------- src/logger.rs | 19 +++++ 5 files changed, 217 insertions(+), 61 deletions(-) create mode 100644 src/fmt/kv.rs diff --git a/Cargo.lock b/Cargo.lock index eb4cb6a..39eb55d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -59,12 +59,6 @@ dependencies = [ "windows-sys", ] -[[package]] -name = "cfg-if" -version = "1.0.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd" - [[package]] name = "colorchoice" version = "1.0.0" @@ -98,11 +92,11 @@ checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" [[package]] name = "log" -version = "0.4.17" +version = "0.4.20" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "abb12e687cfb44aa40f41fc3978ef76448f9b6038cad6aef4259d3c095a2382e" +checksum = "b5e6163cb8c49088c2c36f57875e58ccd8c87c7427f7fbd50ea6710b2f3f2e8f" dependencies = [ - "cfg-if", + "value-bag", ] [[package]] @@ -134,6 +128,12 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "711b9620af191e0cdc7468a8d14e709c3dcdb115b36f838e601583af800a370a" +[[package]] +name = "value-bag" +version = "1.6.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7cdbaf5e132e593e9fc1de6a15bbec912395b11fb9719e061cf64f804524c503" + [[package]] name = "windows-sys" version = "0.52.0" diff --git a/Cargo.toml b/Cargo.toml index ad6619e..beb4a7f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -52,6 +52,7 @@ color = ["dep:anstream", "dep:anstyle"] auto-color = ["color", "anstream/auto"] humantime = ["dep:humantime"] regex = ["env_filter/regex"] +unstable-kv = ["log/kv_unstable"] [dependencies] log = { version = "0.4.8", features = ["std"] } diff --git a/src/fmt/kv.rs b/src/fmt/kv.rs new file mode 100644 index 0000000..bd2cae3 --- /dev/null +++ b/src/fmt/kv.rs @@ -0,0 +1,47 @@ +use std::io::{self, Write}; + +use super::Formatter; +use log::kv::{source::Source, Error, Key, Value, Visitor}; + +/// Format function for serializing key/value pairs +/// +/// This function determines how key/value pairs for structured logs are serialized within the default +/// format. +pub(crate) type KvFormatFn = dyn Fn(&mut Formatter, &dyn Source) -> io::Result<()> + Sync + Send; + +/// Null Key Value Format +/// +/// This function is intended to be passed to +/// [`Builder::format_key_values`](crate::Builder::format_key_values). +/// +/// This key value format simply ignores any key/value fields and doesn't include them in the +/// output. +pub fn hidden_kv_format(_formatter: &mut Formatter, _fields: &dyn Source) -> io::Result<()> { + Ok(()) +} + +/// Default Key Value Format +/// +/// This function is intended to be passed to +/// [`Builder::format_key_values`](crate::Builder::format_key_values). +/// +/// This is the default key/value format. Which uses an "=" as the separator between the key and +/// value and a " " between each pair. +/// +/// For example: `ip=127.0.0.1 port=123456 path=/example` +pub fn default_kv_format(formatter: &mut Formatter, fields: &dyn Source) -> io::Result<()> { + fields + .visit(&mut DefaultVisitor(formatter)) + .map_err(|e| io::Error::new(io::ErrorKind::Other, e)) +} + +struct DefaultVisitor<'a>(&'a mut Formatter); + +impl<'a, 'kvs> Visitor<'kvs> for DefaultVisitor<'a> { + fn visit_pair(&mut self, key: Key, value: Value<'kvs>) -> Result<(), Error> { + // TODO: add styling + // tracing-subscriber uses italic for the key and dimmed for the = + write!(self.0, " {}={}", key, value)?; + Ok(()) + } +} diff --git a/src/fmt/mod.rs b/src/fmt/mod.rs index 883f943..b7472e3 100644 --- a/src/fmt/mod.rs +++ b/src/fmt/mod.rs @@ -30,8 +30,27 @@ //! }); //! ``` //! +//! # Key Value arguments +//! +//! If the `unstable-kv` feature is enabled, then the default format will include key values from +//! the log by default, but this can be disabled by calling [`Builder::format_key_values`] +//! with [`hidden_kv_format`] as the format function. +//! +//! The way these keys and values are formatted can also be customized with a separate format +//! function that is called by the default format with [`Builder::format_key_values`]. +//! +//! ``` +//! use log::info; +//! env_logger::init(); +//! info!(x="45"; "Some message"); +//! info!(x="12"; "Another message {x}", x="12"); +//! ``` +//! +//! See . +//! //! [`Builder::format`]: crate::Builder::format //! [`Write`]: std::io::Write +//! [`Builder::format_key_values`]: crate::Builder::format_key_values use std::cell::RefCell; use std::fmt::Display; @@ -45,6 +64,8 @@ use log::Record; #[cfg(feature = "humantime")] mod humantime; +#[cfg(feature = "unstable-kv")] +mod kv; pub(crate) mod writer; #[cfg(feature = "color")] @@ -52,6 +73,8 @@ pub use anstyle as style; #[cfg(feature = "humantime")] pub use self::humantime::Timestamp; +#[cfg(feature = "unstable-kv")] +pub use self::kv::*; pub use self::writer::Target; pub use self::writer::WriteStyle; @@ -181,6 +204,8 @@ pub(crate) struct Builder { pub format_indent: Option, pub custom_format: Option, pub format_suffix: &'static str, + #[cfg(feature = "unstable-kv")] + pub kv_format: Option>, built: bool, } @@ -213,6 +238,8 @@ impl Builder { written_header_value: false, indent: built.format_indent, suffix: built.format_suffix, + #[cfg(feature = "unstable-kv")] + kv_format: built.kv_format.as_deref().unwrap_or(&default_kv_format), buf, }; @@ -232,6 +259,8 @@ impl Default for Builder { format_indent: Some(4), custom_format: None, format_suffix: "\n", + #[cfg(feature = "unstable-kv")] + kv_format: None, built: false, } } @@ -275,6 +304,8 @@ struct DefaultFormat<'a> { indent: Option, buf: &'a mut Formatter, suffix: &'a str, + #[cfg(feature = "unstable-kv")] + kv_format: &'a KvFormatFn, } impl<'a> DefaultFormat<'a> { @@ -285,7 +316,10 @@ impl<'a> DefaultFormat<'a> { self.write_target(record)?; self.finish_header()?; - self.write_args(record) + self.write_args(record)?; + #[cfg(feature = "unstable-kv")] + self.write_kv(record)?; + write!(self.buf, "{}", self.suffix) } fn subtle_style(&self, text: &'static str) -> SubtleStyle { @@ -401,7 +435,7 @@ impl<'a> DefaultFormat<'a> { fn write_args(&mut self, record: &Record) -> io::Result<()> { match self.indent { // Fast path for no indentation - None => write!(self.buf, "{}{}", record.args(), self.suffix), + None => write!(self.buf, "{}", record.args()), Some(indent_count) => { // Create a wrapper around the buffer only if we have to actually indent the message @@ -445,12 +479,16 @@ impl<'a> DefaultFormat<'a> { write!(wrapper, "{}", record.args())?; } - write!(self.buf, "{}", self.suffix)?; - Ok(()) } } } + + #[cfg(feature = "unstable-kv")] + fn write_kv(&mut self, record: &Record) -> io::Result<()> { + let format = self.kv_format; + format(self.buf, record.key_values()) + } } #[cfg(test)] @@ -486,19 +524,25 @@ mod tests { write_target("", fmt) } - #[test] - fn format_with_header() { + fn formatter() -> Formatter { let writer = writer::Builder::new() .write_style(WriteStyle::Never) .build(); - let mut f = Formatter::new(&writer); + Formatter::new(&writer) + } + + #[test] + fn format_with_header() { + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: true, target: false, level: true, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: None, suffix: "\n", @@ -510,17 +554,15 @@ mod tests { #[test] fn format_no_header() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: false, target: false, level: false, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: None, suffix: "\n", @@ -532,17 +574,15 @@ mod tests { #[test] fn format_indent_spaces() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: true, target: false, level: true, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: Some(4), suffix: "\n", @@ -554,17 +594,15 @@ mod tests { #[test] fn format_indent_zero_spaces() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: true, target: false, level: true, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: Some(0), suffix: "\n", @@ -576,17 +614,15 @@ mod tests { #[test] fn format_indent_spaces_no_header() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: false, target: false, level: false, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: Some(4), suffix: "\n", @@ -598,17 +634,15 @@ mod tests { #[test] fn format_suffix() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: false, target: false, level: false, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: None, suffix: "\n\n", @@ -620,17 +654,15 @@ mod tests { #[test] fn format_suffix_with_indent() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: false, target: false, level: false, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: Some(4), suffix: "\n\n", @@ -642,11 +674,7 @@ mod tests { #[test] fn format_target() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write_target( "target", @@ -655,6 +683,8 @@ mod tests { module_path: true, target: true, level: true, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: None, suffix: "\n", @@ -667,17 +697,15 @@ mod tests { #[test] fn format_empty_target() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write(DefaultFormat { timestamp: None, module_path: true, target: true, level: true, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: None, suffix: "\n", @@ -689,11 +717,7 @@ mod tests { #[test] fn format_no_target() { - let writer = writer::Builder::new() - .write_style(WriteStyle::Never) - .build(); - - let mut f = Formatter::new(&writer); + let mut f = formatter(); let written = write_target( "target", @@ -702,6 +726,8 @@ mod tests { module_path: true, target: false, level: true, + #[cfg(feature = "unstable-kv")] + kv_format: &hidden_kv_format, written_header_value: false, indent: None, suffix: "\n", @@ -711,4 +737,67 @@ mod tests { assert_eq!("[INFO test::path] log\nmessage\n", written); } + + #[cfg(feature = "unstable-kv")] + #[test] + fn format_kv_default() { + let kvs = &[("a", 1u32), ("b", 2u32)][..]; + let mut f = formatter(); + let record = Record::builder() + .args(format_args!("log message")) + .level(Level::Info) + .module_path(Some("test::path")) + .key_values(&kvs) + .build(); + + let written = write_record( + record, + DefaultFormat { + timestamp: None, + module_path: false, + target: false, + level: true, + kv_format: &default_kv_format, + written_header_value: false, + indent: None, + suffix: "\n", + buf: &mut f, + }, + ); + + assert_eq!("[INFO ] log message a=1 b=2\n", written); + } + + #[cfg(feature = "unstable-kv")] + #[test] + fn format_kv_default_full() { + let kvs = &[("a", 1u32), ("b", 2u32)][..]; + let mut f = formatter(); + let record = Record::builder() + .args(format_args!("log\nmessage")) + .level(Level::Info) + .module_path(Some("test::path")) + .target("target") + .file(Some("test.rs")) + .line(Some(42)) + .key_values(&kvs) + .build(); + + let written = write_record( + record, + DefaultFormat { + timestamp: None, + module_path: true, + target: true, + level: true, + kv_format: &default_kv_format, + written_header_value: false, + indent: None, + suffix: "\n", + buf: &mut f, + }, + ); + + assert_eq!("[INFO test::path target] log\nmessage a=1 b=2\n", written); + } } diff --git a/src/logger.rs b/src/logger.rs index 18bfe9f..509c299 100644 --- a/src/logger.rs +++ b/src/logger.rs @@ -313,6 +313,25 @@ impl Builder { self } + /// Set the format for structured key/value pairs in the log record + /// + /// With the default format, this function is called for each record and should format + /// the structured key-value pairs as returned by [`log::Record::key_values`]. + /// + /// The format function is expected to output the string directly to the `Formatter` so that + /// implementations can use the [`std::fmt`] macros, similar to the main format function. + /// + /// The default format uses a space to separte each key-value pair, with an "=" between + /// the key and value. + #[cfg(feature = "unstable-kv")] + pub fn format_key_values(&mut self, format: F) -> &mut Self + where + F: Fn(&mut Formatter, &dyn log::kv::source::Source) -> io::Result<()> + Sync + Send, + { + self.format.kv_format = Some(Box::new(format)); + self + } + /// Adds a directive to the filter for a specific module. /// /// # Examples