diff --git a/Cargo.toml b/Cargo.toml index a8bf0abb9..5a67bdce6 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -59,6 +59,7 @@ sval = { version = "=1.0.0-alpha.5", optional = true, default-features = false } value-bag = { version = "=1.0.0-alpha.8", optional = true, default-features = false } [dev-dependencies] +rustversion = "1.0" serde = { version = "1.0", features = ["derive"] } serde_test = "1.0" sval = { version = "=1.0.0-alpha.5", features = ["derive"] } diff --git a/README.md b/README.md index 8a7c1eea3..a26192778 100644 --- a/README.md +++ b/README.md @@ -24,7 +24,7 @@ This version is explicitly tested in CI and may be bumped in any release as need ## Usage -## In libraries +### In libraries Libraries should link only to the `log` crate, and use the provided macros to log whatever information will be useful to downstream consumers: @@ -55,7 +55,7 @@ pub fn shave_the_yak(yak: &mut Yak) { } ``` -## In executables +### In executables In order to produce log output, executables have to use a logger implementation compatible with the facade. There are many available implementations to choose from, here are some of the most popular ones: @@ -87,3 +87,28 @@ function to do this. Any log messages generated before the logger is initialized will be ignored. The executable itself may use the `log` crate to log as well. + +## Structured logging + +If you enable the `kv_unstable` feature, you can associate structured data with your log records: + +```rust +use log::{info, trace, warn, as_serde, as_error}; + +pub fn shave_the_yak(yak: &mut Yak) { + trace!(target = "yak_events", yak = as_serde!(yak); "Commencing yak shaving"); + + loop { + match find_a_razor() { + Ok(razor) => { + info!(razor = razor; "Razor located"); + yak.shave(razor); + break; + } + Err(err) => { + warn!(err = as_error!(err); "Unable to locate a razor, retrying"); + } + } + } +} +``` diff --git a/src/kv/value.rs b/src/kv/value.rs index 4cbbca583..c349b8c85 100644 --- a/src/kv/value.rs +++ b/src/kv/value.rs @@ -37,6 +37,49 @@ impl<'v> ToValue for Value<'v> { } } +/// Get a value from a type implementing `std::fmt::Debug`. +#[macro_export] +macro_rules! as_debug { + ($capture:expr) => { + $crate::kv::Value::from_debug(&$capture) + }; +} + +/// Get a value from a type implementing `std::fmt::Display`. +#[macro_export] +macro_rules! as_display { + ($capture:expr) => { + $crate::kv::Value::from_display(&$capture) + }; +} + +/// Get a value from an error. +#[cfg(feature = "kv_unstable_std")] +#[macro_export] +macro_rules! as_error { + ($capture:expr) => { + $crate::kv::Value::from_dyn_error(&$capture) + }; +} + +#[cfg(feature = "kv_unstable_serde")] +/// Get a value from a type implementing `serde::Serialize`. +#[macro_export] +macro_rules! as_serde { + ($capture:expr) => { + $crate::kv::Value::from_serde(&$capture) + }; +} + +/// Get a value from a type implementing `sval::value::Value`. +#[cfg(feature = "kv_unstable_sval")] +#[macro_export] +macro_rules! as_sval { + ($capture:expr) => { + $crate::kv::Value::from_sval(&$capture) + }; +} + /// A value in a structured key-value pair. /// /// # Capturing values diff --git a/src/lib.rs b/src/lib.rs index 58c636b92..373745579 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -24,7 +24,7 @@ //! though that default may be overridden. Logger implementations typically use //! the target to filter requests based on some user configuration. //! -//! # Use +//! # Usage //! //! The basic use of the log crate is through the five logging macros: [`error!`], //! [`warn!`], [`info!`], [`debug!`] and [`trace!`] @@ -86,6 +86,42 @@ //! //! The logging system may only be initialized once. //! +//! ## Structured logging +//! +//! If you enable the `kv_unstable` feature you can associate structured values +//! with your log records. If we take the example from before, we can include +//! some additional context besides what's in the formatted message: +//! +//! ```edition2018 +//! # #[macro_use] extern crate serde; +//! # #[derive(Debug, Serialize)] pub struct Yak(String); +//! # impl Yak { fn shave(&mut self, _: u32) {} } +//! # fn find_a_razor() -> Result { Ok(1) } +//! # #[cfg(feature = "kv_unstable_serde")] +//! # fn main() { +//! use log::{info, warn, as_serde, as_error}; +//! +//! pub fn shave_the_yak(yak: &mut Yak) { +//! info!(target: "yak_events", yak = as_serde!(yak); "Commencing yak shaving"); +//! +//! loop { +//! match find_a_razor() { +//! Ok(razor) => { +//! info!(razor = razor; "Razor located"); +//! yak.shave(razor); +//! break; +//! } +//! Err(err) => { +//! warn!(err = as_error!(err); "Unable to locate a razor, retrying"); +//! } +//! } +//! } +//! } +//! # } +//! # #[cfg(not(feature = "kv_unstable_serde"))] +//! # fn main() {} +//! ``` +//! //! # Available logging implementations //! //! In order to produce log output executables have to use diff --git a/src/macros.rs b/src/macros.rs index a90feef34..d1177c99a 100644 --- a/src/macros.rs +++ b/src/macros.rs @@ -29,17 +29,20 @@ /// ``` #[macro_export(local_inner_macros)] macro_rules! log { - (target: $target:expr, $lvl:expr, $($key:ident = $value:expr),* ; $fmt:expr, $($arg:tt)+) => ({ + // log!(target: "my_target", Level::Info; key1 = 42, key2 = true; "a {} event", "log"); + (target: $target:expr, $lvl:expr, $($key:ident = $value:expr),+; $($arg:tt)+) => ({ let lvl = $lvl; if lvl <= $crate::STATIC_MAX_LEVEL && lvl <= $crate::max_level() { $crate::__private_api_log( - __log_format_args!($fmt, $($arg)+), + __log_format_args!($($arg)+), lvl, &($target, __log_module_path!(), __log_file!(), __log_line!()), - Some(&[$((__log_stringify!($key), &$value)),*]) + Some(&[$((__log_stringify!($key), &$value)),+]) ); } }); + + // log!(target: "my_target", Level::Info; "a {} event", "log"); (target: $target:expr, $lvl:expr, $($arg:tt)+) => ({ let lvl = $lvl; if lvl <= $crate::STATIC_MAX_LEVEL && lvl <= $crate::max_level() { @@ -51,7 +54,9 @@ macro_rules! log { ); } }); - ($lvl:expr, $($arg:tt)+) => (log!(target: __log_module_path!(), $lvl, $($arg)+)) + + // log!(Level::Info, "a log event") + ($lvl:expr, $($arg:tt)+) => (log!(target: __log_module_path!(), $lvl, $($arg)+)); } /// Logs a message at the error level. @@ -70,12 +75,12 @@ macro_rules! log { /// ``` #[macro_export(local_inner_macros)] macro_rules! error { - (target: $target:expr, $($arg:tt)+) => ( - log!(target: $target, $crate::Level::Error, $($arg)+) - ); - ($($arg:tt)+) => ( - log!($crate::Level::Error, $($arg)+) - ) + // error!(target: "my_target", key1 = 42, key2 = true; "a {} event", "log") + // error!(target: "my_target", "a {} event", "log") + (target: $target:expr, $($arg:tt)+) => (log!(target: $target, $crate::Level::Error, $($arg)+)); + + // error!("a {} event", "log") + ($($arg:tt)+) => (log!($crate::Level::Error, $($arg)+)) } /// Logs a message at the warn level. @@ -94,12 +99,12 @@ macro_rules! error { /// ``` #[macro_export(local_inner_macros)] macro_rules! warn { - (target: $target:expr, $($arg:tt)+) => ( - log!(target: $target, $crate::Level::Warn, $($arg)+) - ); - ($($arg:tt)+) => ( - log!($crate::Level::Warn, $($arg)+) - ) + // warn!(target: "my_target", key1 = 42, key2 = true; "a {} event", "log") + // warn!(target: "my_target", "a {} event", "log") + (target: $target:expr, $($arg:tt)+) => (log!(target: $target, $crate::Level::Warn, $($arg)+)); + + // warn!("a {} event", "log") + ($($arg:tt)+) => (log!($crate::Level::Warn, $($arg)+)) } /// Logs a message at the info level. @@ -120,12 +125,12 @@ macro_rules! warn { /// ``` #[macro_export(local_inner_macros)] macro_rules! info { - (target: $target:expr, $($arg:tt)+) => ( - log!(target: $target, $crate::Level::Info, $($arg)+) - ); - ($($arg:tt)+) => ( - log!($crate::Level::Info, $($arg)+) - ) + // info!(target: "my_target", key1 = 42, key2 = true; "a {} event", "log") + // info!(target: "my_target", "a {} event", "log") + (target: $target:expr, $($arg:tt)+) => (log!(target: $target, $crate::Level::Info, $($arg)+)); + + // info!("a {} event", "log") + ($($arg:tt)+) => (log!($crate::Level::Info, $($arg)+)) } /// Logs a message at the debug level. @@ -145,12 +150,12 @@ macro_rules! info { /// ``` #[macro_export(local_inner_macros)] macro_rules! debug { - (target: $target:expr, $($arg:tt)+) => ( - log!(target: $target, $crate::Level::Debug, $($arg)+) - ); - ($($arg:tt)+) => ( - log!($crate::Level::Debug, $($arg)+) - ) + // debug!(target: "my_target", key1 = 42, key2 = true; "a {} event", "log") + // debug!(target: "my_target", "a {} event", "log") + (target: $target:expr, $($arg:tt)+) => (log!(target: $target, $crate::Level::Debug, $($arg)+)); + + // debug!("a {} event", "log") + ($($arg:tt)+) => (log!($crate::Level::Debug, $($arg)+)) } /// Logs a message at the trace level. @@ -172,12 +177,12 @@ macro_rules! debug { /// ``` #[macro_export(local_inner_macros)] macro_rules! trace { - (target: $target:expr, $($arg:tt)+) => ( - log!(target: $target, $crate::Level::Trace, $($arg)+) - ); - ($($arg:tt)+) => ( - log!($crate::Level::Trace, $($arg)+) - ) + // trace!(target: "my_target", key1 = 42, key2 = true; "a {} event", "log") + // trace!(target: "my_target", "a {} event", "log") + (target: $target:expr, $($arg:tt)+) => (log!(target: $target, $crate::Level::Trace, $($arg)+)); + + // trace!("a {} event", "log") + ($($arg:tt)+) => (log!($crate::Level::Trace, $($arg)+)) } /// Determines if a message logged at the specified level in that module will diff --git a/tests/Cargo.toml b/tests/Cargo.toml index cb6b8600f..25ac12bec 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -9,3 +9,6 @@ std = ["log/std"] [dependencies.log] path = ".." + +[dev-dependencies.rustversion] +version = "1.0" diff --git a/tests/macros.rs b/tests/macros.rs index 0ccb64028..4bb73da52 100644 --- a/tests/macros.rs +++ b/tests/macros.rs @@ -2,46 +2,151 @@ #[macro_use] extern crate log; +macro_rules! all_log_macros { + ($($arg:tt)*) => ({ + trace!($($arg)*); + debug!($($arg)*); + info!($($arg)*); + warn!($($arg)*); + error!($($arg)*); + }); +} + +#[test] +fn no_args() { + for lvl in log::Level::iter() { + log!(lvl, "hello"); + log!(lvl, "hello",); + + log!(target: "my_target", lvl, "hello"); + log!(target: "my_target", lvl, "hello",); + + log!(lvl, "hello"); + log!(lvl, "hello",); + } + + all_log_macros!("hello"); + all_log_macros!("hello",); + + all_log_macros!(target: "my_target", "hello"); + all_log_macros!(target: "my_target", "hello",); +} + +#[test] +fn anonymous_args() { + for lvl in log::Level::iter() { + log!(lvl, "hello {}", "world"); + log!(lvl, "hello {}", "world",); + + log!(target: "my_target", lvl, "hello {}", "world"); + log!(target: "my_target", lvl, "hello {}", "world",); + + log!(lvl, "hello {}", "world"); + log!(lvl, "hello {}", "world",); + } + + all_log_macros!("hello {}", "world"); + all_log_macros!("hello {}", "world",); + + all_log_macros!(target: "my_target", "hello {}", "world"); + all_log_macros!(target: "my_target", "hello {}", "world",); +} + #[test] -fn base() { - info!("hello"); - info!("hello",); +fn named_args() { + for lvl in log::Level::iter() { + log!(lvl, "hello {world}", world = "world"); + log!(lvl, "hello {world}", world = "world",); + + log!(target: "my_target", lvl, "hello {world}", world = "world"); + log!(target: "my_target", lvl, "hello {world}", world = "world",); + + log!(lvl, "hello {world}", world = "world"); + log!(lvl, "hello {world}", world = "world",); + } + + all_log_macros!("hello {world}", world = "world"); + all_log_macros!("hello {world}", world = "world",); + + all_log_macros!(target: "my_target", "hello {world}", world = "world"); + all_log_macros!(target: "my_target", "hello {world}", world = "world",); } #[test] -fn base_expr_context() { - let _ = info!("hello"); +fn enabled() { + for lvl in log::Level::iter() { + let _enabled = if log_enabled!(target: "my_target", lvl) { + true + } else { + false + }; + } } #[test] -fn with_args() { - info!("hello {}", "cats"); - info!("hello {}", "cats",); - info!("hello {}", "cats",); +fn expr() { + for lvl in log::Level::iter() { + let _ = log!(lvl, "hello"); + } } #[test] -fn with_args_expr_context() { - match "cats" { - cats => info!("hello {}", cats), - }; +#[cfg(feature = "kv_unstable")] +fn kv_no_args() { + for lvl in log::Level::iter() { + log!(target: "my_target", lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello"); + + log!(lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello"); + } + + all_log_macros!(target: "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello"); + all_log_macros!(target = "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello"); + all_log_macros!(cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello"); +} + +#[test] +#[cfg(feature = "kv_unstable")] +fn kv_expr_args() { + for lvl in log::Level::iter() { + log!(target: "my_target", lvl, cat_math = { let mut x = 0; x += 1; x + 1 }; "hello"); + + log!(lvl, target = "my_target", cat_math = { let mut x = 0; x += 1; x + 1 }; "hello"); + log!(lvl, cat_math = { let mut x = 0; x += 1; x + 1 }; "hello"); + } + + all_log_macros!(target: "my_target", cat_math = { let mut x = 0; x += 1; x + 1 }; "hello"); + all_log_macros!(target = "my_target", cat_math = { let mut x = 0; x += 1; x + 1 }; "hello"); + all_log_macros!(cat_math = { let mut x = 0; x += 1; x + 1 }; "hello"); } #[test] -fn with_named_args() { - let cats = "cats"; +#[cfg(feature = "kv_unstable")] +fn kv_anonymous_args() { + for lvl in log::Level::iter() { + log!(target: "my_target", lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {}", "world"); + log!(lvl, target = "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {}", "world"); + + log!(lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {}", "world"); + } - info!("hello {cats}", cats = cats); - info!("hello {cats}", cats = cats,); - info!("hello {cats}", cats = cats,); + all_log_macros!(target: "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {}", "world"); + all_log_macros!(target = "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {}", "world"); + all_log_macros!(cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {}", "world"); } #[test] #[cfg(feature = "kv_unstable")] -fn kv() { - info!(cat_1 = "chashu", cat_2 = "nori"; "hello {}", "cats"); - info!(target: "my_target", cat_1 = "chashu", cat_2 = "nori"; "hello {}", "cats"); - log!(target: "my_target", log::Level::Warn, cat_1 = "chashu", cat_2 = "nori"; "hello {}", "cats"); +fn kv_named_args() { + for lvl in log::Level::iter() { + log!(target: "my_target", lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world"); + log!(lvl, target = "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world"); + + log!(lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world"); + } + + all_log_macros!(target: "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world"); + all_log_macros!(target = "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world"); + all_log_macros!(cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}", world = "world"); } #[test] @@ -53,3 +158,50 @@ fn kv_expr_context() { } }; } + +#[test] +fn implicit_named_args() { + #[rustversion::since(1.58)] + fn _check() { + let world = "world"; + + for lvl in log::Level::iter() { + log!(lvl, "hello {world}"); + log!(lvl, "hello {world}",); + + log!(target: "my_target", lvl, "hello {world}"); + log!(target: "my_target", lvl, "hello {world}",); + + log!(lvl, "hello {world}"); + log!(lvl, "hello {world}",); + } + + all_log_macros!("hello {world}"); + all_log_macros!("hello {world}",); + + all_log_macros!(target: "my_target", "hello {world}"); + all_log_macros!(target: "my_target", "hello {world}",); + + all_log_macros!(target = "my_target"; "hello {world}"); + all_log_macros!(target = "my_target"; "hello {world}",); + } +} + +#[test] +#[cfg(feature = "kv_unstable")] +fn kv_implicit_named_args() { + #[rustversion::since(1.58)] + fn _check() { + let world = "world"; + + for lvl in log::Level::iter() { + log!(target: "my_target", lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}"); + + log!(lvl, cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}"); + } + + all_log_macros!(target: "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}"); + all_log_macros!(target = "my_target", cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}"); + all_log_macros!(cat_1 = "chashu", cat_2 = "nori", cat_count = 2; "hello {world}"); + } +}