From 549fcdaa1e39efe82f3f7b0156e3f52afbd2d1b2 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 | 62 ++++++++++ Cargo.toml | 1 + src/fmt/mod.rs | 325 +++++++++++++++++++++++++++++++++++++++++-------- src/logger.rs | 7 ++ 4 files changed, 343 insertions(+), 52 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 2bb97a6a..33369ad6 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -29,6 +29,16 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd" +[[package]] +name = "ctor" +version = "0.1.26" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6d2301688392eb071b0bf1a37be05c469d3cc4dbbd95df672fe28ab021e6a096" +dependencies = [ + "quote", + "syn", +] + [[package]] name = "env_logger" version = "0.10.1" @@ -117,6 +127,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "abb12e687cfb44aa40f41fc3978ef76448f9b6038cad6aef4259d3c095a2382e" dependencies = [ "cfg-if", + "value-bag", ] [[package]] @@ -125,6 +136,24 @@ version = "2.5.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2dffe52ecf27772e601905b7522cb4ef790d2cc203488bbd0e2fe85fcb74566d" +[[package]] +name = "proc-macro2" +version = "1.0.56" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2b63bdb0cd06f1f4dedf69b254734f9b45af66e4a031e42a7480257d9898b435" +dependencies = [ + "unicode-ident", +] + +[[package]] +name = "quote" +version = "1.0.26" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4424af4bf778aae2051a77b60283332f386554255d722233d09fbfc7e30da2fc" +dependencies = [ + "proc-macro2", +] + [[package]] name = "regex" version = "1.7.0" @@ -156,6 +185,17 @@ dependencies = [ "windows-sys", ] +[[package]] +name = "syn" +version = "1.0.109" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "72b64191b275b66ffe2469e8af2c1cfe3bafa67b529ead792a6d0160888b4237" +dependencies = [ + "proc-macro2", + "quote", + "unicode-ident", +] + [[package]] name = "termcolor" version = "1.1.3" @@ -165,6 +205,28 @@ dependencies = [ "winapi-util", ] +[[package]] +name = "unicode-ident" +version = "1.0.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e5464a87b239f13a63a501f2701565754bae92d243d4bb7eb12f6d57d2269bf4" + +[[package]] +name = "value-bag" +version = "1.0.0-alpha.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2209b78d1249f7e6f3293657c9779fe31ced465df091bbd433a1cf88e916ec55" +dependencies = [ + "ctor", + "version_check", +] + +[[package]] +name = "version_check" +version = "0.9.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "49874b5167b65d7193b8aba1567f5c7d93d001cafc34600cee003eda787e483f" + [[package]] name = "winapi" version = "0.3.9" diff --git a/Cargo.toml b/Cargo.toml index 7a1ae457..3d565de5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -42,6 +42,7 @@ color = ["dep:termcolor"] auto-color = ["dep:is-terminal", "color"] humantime = ["dep:humantime"] regex = ["dep:regex"] +kv_unstable = ["log/kv_unstable"] [dependencies] log = { version = "0.4.8", features = ["std"] } diff --git a/src/fmt/mod.rs b/src/fmt/mod.rs index ded40278..f6962e76 100644 --- a/src/fmt/mod.rs +++ b/src/fmt/mod.rs @@ -24,10 +24,27 @@ //! }); //! ``` //! +//! # Key Value arguments +//! +//! If the `kv_unstable` 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_value_style`] +//! with [`KVStyle::Hidden`]. +//! +//! ``` +//! use log::info; +//! env_logger::init(); +//! info!(x="45"; "Some message"); +//! info!(x="12"; "Another message {x}", x="12"); +//! ``` +//! +//! See . +//! //! [`Formatter`]: struct.Formatter.html //! [`Style`]: struct.Style.html //! [`Builder::format`]: ../struct.Builder.html#method.format //! [`Write`]: https://doc.rust-lang.org/stable/std/io/trait.Write.html +//! [`Builder::format_key_value_style`]: ../struct.Builder.html#method.format_key_value_style +//! [`KVStyle::Hidden`]: ../enum.KVStyle.html#variant.Hidden use std::cell::RefCell; use std::fmt::Display; @@ -35,6 +52,8 @@ use std::io::prelude::*; use std::rc::Rc; use std::{fmt, io, mem}; +#[cfg(feature = "kv_unstable")] +use log::kv; use log::Record; #[cfg(feature = "humantime")] @@ -68,6 +87,38 @@ pub enum TimestampPrecision { Nanos, } +/// Style for displaying key/value structured data +/// +/// This determines how key/value pairs are displayed in the log output. +/// The values can be suppressed, included in a trailer at the end of the line, or +/// included as multiple lines after the message. +#[derive(Copy, Clone, Debug, PartialEq, Eq)] +pub enum KVStyle { + /// Key/value pairs are not included in the output + Hidden, + /// Display the KV values at the end of the line + /// + /// After the message, any KV data is printed within curly braces on the same line. An "=" + /// is used to delimite the key from a value. + /// + /// For example: + /// ```txt + /// [INFO] log message { a=1 b=2 } + /// ``` + Inline, + /// Display the KV values on additional lines + /// + /// Each key/value pair is printed on its own line, with key and value delimited by ": ". + /// + /// For example: + /// ```txt + /// [INFO] log message + /// a: 1 + /// b: 2 + /// ``` + Multiline, +} + /// The default timestamp precision is seconds. impl Default for TimestampPrecision { fn default() -> Self { @@ -148,6 +199,7 @@ pub(crate) struct Builder { pub format_indent: Option, pub custom_format: Option, pub format_suffix: &'static str, + pub key_value_style: KVStyle, built: bool, } @@ -180,6 +232,7 @@ impl Builder { written_header_value: false, indent: built.format_indent, suffix: built.format_suffix, + key_value_style: built.key_value_style, buf, }; @@ -199,6 +252,7 @@ impl Default for Builder { format_indent: Some(4), custom_format: None, format_suffix: "\n", + key_value_style: KVStyle::Multiline, built: false, } } @@ -221,6 +275,7 @@ struct DefaultFormat<'a> { indent: Option, buf: &'a mut Formatter, suffix: &'a str, + key_value_style: KVStyle, } impl<'a> DefaultFormat<'a> { @@ -231,7 +286,9 @@ impl<'a> DefaultFormat<'a> { self.write_target(record)?; self.finish_header()?; - self.write_args(record) + self.write_args(record)?; + self.write_kv(record)?; + write!(self.buf, "{}", self.suffix) } fn subtle_style(&self, text: &'static str) -> SubtleStyle { @@ -341,7 +398,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 @@ -385,12 +442,72 @@ impl<'a> DefaultFormat<'a> { write!(wrapper, "{}", record.args())?; } - write!(self.buf, "{}", self.suffix)?; - Ok(()) } } } + + fn write_kv(&mut self, record: &Record) -> io::Result<()> { + #[cfg(feature = "kv_unstable")] + { + match self.key_value_style { + KVStyle::Hidden => Ok(()), + KVStyle::Multiline => record + .key_values() + .visit(&mut KVMultilineVisitor(self)) + .map_err(|e| io::Error::new(io::ErrorKind::Other, e)), + KVStyle::Inline => { + let kvs = record.key_values(); + if kvs.count() > 0 { + write!(self.buf, " {}", self.subtle_style("{"))?; + + kvs.visit(&mut KVInlineVisitor(self.buf)) + .map_err(|e| io::Error::new(io::ErrorKind::Other, e))?; + write!(self.buf, "{}", self.subtle_style(" }"))?; + } + Ok(()) + } + } + } + #[cfg(not(feature = "kv_unstable"))] + { + // avoid dead code lints + let _ = record; + let _ = self.key_value_style; + Ok(()) + } + } +} + +#[cfg(feature = "kv_unstable")] +struct KVInlineVisitor<'a>(&'a mut Formatter); + +#[cfg(feature = "kv_unstable")] +impl<'a, 'kvs> kv::Visitor<'kvs> for KVInlineVisitor<'a> { + fn visit_pair(&mut self, key: kv::Key<'kvs>, value: kv::Value<'kvs>) -> Result<(), kv::Error> { + write!(self.0, " {}={}", key, value).map_err(|e| e.into()) + } +} + +#[cfg(feature = "kv_unstable")] +struct KVMultilineVisitor<'a, 'fmt>(&'a mut DefaultFormat<'fmt>); + +#[cfg(feature = "kv_unstable")] +impl<'a, 'kvs, 'fmt> kv::Visitor<'kvs> for KVMultilineVisitor<'a, 'fmt> { + fn visit_pair(&mut self, key: kv::Key<'kvs>, value: kv::Value<'kvs>) -> Result<(), kv::Error> { + let indent = self.0.indent.unwrap_or(0); + write!( + self.0.buf, + // Always use a newline here, because suffix could be something else + // to separate entire records. + "\n{:width$}{}: {}", + "", + key, + value, + width = indent + )?; + Ok(()) + } } #[cfg(test)] @@ -426,19 +543,24 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: None, suffix: "\n", @@ -450,17 +572,14 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: None, suffix: "\n", @@ -472,17 +591,14 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: Some(4), suffix: "\n", @@ -494,17 +610,14 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: Some(0), suffix: "\n", @@ -516,17 +629,14 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: Some(4), suffix: "\n", @@ -538,17 +648,14 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: None, suffix: "\n\n", @@ -560,17 +667,14 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: Some(4), suffix: "\n\n", @@ -582,11 +686,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", @@ -595,6 +695,7 @@ mod tests { module_path: true, target: true, level: true, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: None, suffix: "\n", @@ -607,17 +708,14 @@ 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, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: None, suffix: "\n", @@ -629,11 +727,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", @@ -642,6 +736,7 @@ mod tests { module_path: true, target: false, level: true, + key_value_style: KVStyle::Hidden, written_header_value: false, indent: None, suffix: "\n", @@ -651,4 +746,130 @@ mod tests { assert_eq!("[INFO test::path] log\nmessage\n", written); } + + #[cfg(feature = "kv_unstable")] + #[test] + fn format_kv_trailer() { + 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, + key_value_style: KVStyle::Inline, + written_header_value: false, + indent: None, + suffix: "\n", + buf: &mut f, + }, + ); + + assert_eq!("[INFO ] log message { a=1 b=2 }\n", written); + } + + #[cfg(feature = "kv_unstable")] + #[test] + fn format_kv_trailer_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, + key_value_style: KVStyle::Inline, + 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 + ); + } + + #[cfg(feature = "kv_unstable")] + #[test] + fn format_kv_multiline() { + 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")) + .key_values(&kvs) + .build(); + + let written = write_record( + record, + DefaultFormat { + timestamp: None, + module_path: false, + target: false, + level: true, + key_value_style: KVStyle::Multiline, + written_header_value: false, + indent: None, + suffix: "\n", + buf: &mut f, + }, + ); + + assert_eq!("[INFO ] log\nmessage\na: 1\nb: 2\n", written); + } + + #[cfg(feature = "kv_unstable")] + #[test] + fn format_kv_multiline_indented() { + 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")) + .key_values(&kvs) + .build(); + + let written = write_record( + record, + DefaultFormat { + timestamp: None, + module_path: false, + target: false, + level: true, + key_value_style: KVStyle::Multiline, + written_header_value: false, + indent: Some(2), + suffix: "\n", + buf: &mut f, + }, + ); + + assert_eq!("[INFO ] log\n message\n a: 1\n b: 2\n", written); + } } diff --git a/src/logger.rs b/src/logger.rs index 6c8a00d4..c87841ab 100644 --- a/src/logger.rs +++ b/src/logger.rs @@ -312,6 +312,13 @@ impl Builder { self } + /// Configure the style for writing key/value pairs + #[cfg(feature = "kv_unstable")] + pub fn format_key_value_style(&mut self, style: fmt::KVStyle) -> &mut Self { + self.format.key_value_style = style; + self + } + /// Adds a directive to the filter for a specific module. /// /// # Examples