diff --git a/Cargo.toml b/Cargo.toml index e278878d8..6828f5f44 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -22,6 +22,10 @@ features = ["std", "serde"] name = "filters" harness = false +[[test]] +name = "log_v" +harness = false + [features] max_level_off = [] max_level_error = [] diff --git a/src/lib.rs b/src/lib.rs index 49adba470..485f12b4c 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -15,36 +15,152 @@ //! by this crate, and the consumer of those libraries can choose the logging //! implementation that is most suitable for its use case. //! -//! If no logging implementation is selected, the facade falls back to a "noop" -//! implementation that ignores all log messages. The overhead in this case -//! is very small - just an integer load, comparison and jump. +//! If no logging implementation is selected, the facade falls back to a +//! _no-op_ implementation that ignores all log messages. The overhead in this +//! case is very small—just an integer load, comparison and jump. //! -//! A log request consists of a _target_, a _level_, and a _body_. A target is a -//! string which defaults to the module path of the location of the log request, -//! though that default may be overridden. Logger implementations typically use -//! the target to filter requests based on some user configuration. +//! A log `Record` includes a target, level, and message body. Logger +//! implementations typically use the target and level to filter records, +//! based on user configuration. //! -//! # Use +//! ## Logging macros //! -//! The basic use of the log crate is through the five logging macros: [`error!`], -//! [`warn!`], [`info!`], [`debug!`] and [`trace!`] -//! where `error!` represents the highest-priority log messages -//! and `trace!` the lowest. The log messages are filtered by configuring -//! the log level to exclude messages with a lower priority. -//! Each of these macros accept format strings similarly to [`println!`]. +//! The `log` crate is primarly used through logging [macros](#macros). These +//! include formatted logging macros for each of the supported levels, from +//! highest to lowest priority: `error!`, `warn!`, `info!`, `debug!` and +//! `trace!`. There is an additional set of “_-v_” suffix macros +//! (e.g. `debugv!`) that provide _inline expression and value_ logging. Both +//! sets of macros are described below, with examples using arbitrary log +//! levels. //! +//! ### Formatted logging //! -//! [`error!`]: ./macro.error.html -//! [`warn!`]: ./macro.warn.html -//! [`info!`]: ./macro.info.html -//! [`debug!`]: ./macro.debug.html -//! [`trace!`]: ./macro.trace.html -//! [`println!`]: https://doc.rust-lang.org/stable/std/macro.println.html +//! The formatted logging macros require a literal format string, supporting +//! the same syntax as `println!`, via [`std::fmt`]: //! -//! ## In libraries +//! ```rust +//! # #[macro_use] extern crate log; +//! # fn main() { +//! info!("Landing gear retracted"); +//! let altitude = 3000; +//! let target = 10500; +//! debug!("Altitude target: {}, current: {}", target, altitude); +//! # } +//! ``` +//! +//! If for example, the configured maximum logging level is `Info`, then the +//! above `debug!` statement does not log, and the cost of formatting the +//! message string is avoided. +//! +//! ### Testing for output +//! +//! The [`log_enabled!`](macro.log_enabled.html) macro may be used to +//! explicitly test if logging is enabled, and may be useful to avoid +//! expensive computations used only for logging. +//! +//! ```rust +//! # #[macro_use] extern crate log; +//! # struct Foo; +//! # impl Foo { +//! # fn volume(&self) -> f32 { 0.1 } +//! # fn mass(&self) -> f32 { 0.2 } +//! # } +//! # fn analyze(a: u32) -> Foo { Foo } +//! use log::Level::Debug; +//! # fn main() { +//! +//! # let asteroid = 1; +//! if log_enabled!(Debug) { +//! let e = analyze(asteroid); // expensive! +//! debug!("Asteroid volume: {}, mass: {}", e.volume(), e.mass()); +//! } +//! # } +//! ``` +//! +//! ### Inline expression and value logging +//! +//! The _-v_ macros support inline expression and value logging, as a superset +//! of the [`std::dbg!`] macro, for use with the logging system. A _single_ +//! expression argument is evaluated exactly once, regardless of if the +//! logging level is enabled, and its value is returned from the macro. Given +//! this code as a starting point: +//! +//! ```rust +//! use std::time::{Duration, Instant}; +//! # fn main() { +//! # let deadline = Instant::now() + Duration::new(0, 950_000); +//! +//! let remaining = deadline - Instant::now(); +//! # } +//! ``` +//! +//! A _-v_ macro may be inserted inline around any expression or +//! sub-expression: +//! +//! ```rust +//! # #[macro_use] extern crate log; +//! use std::time::{Duration, Instant}; +//! # fn main() { +//! # let deadline = Instant::now() + Duration::new(0, 950_000); //! -//! Libraries should link only to the `log` crate, and use the provided -//! macros to log whatever information will be useful to downstream consumers. +//! let remaining = debugv!(deadline - Instant::now()); +//! // ^-- debug log: deadline - Instant::now() → 950µs +//! debugv!(remaining); +//! // or ^-- debug log: remaining → 950µs +//! # } +//! ``` +//! +//! Note that the value of the expression is moved and then returned. If the +//! type does not implement `Copy`, ownership may be retained by borrowing by +//! reference, e.g. `debugv!(&expr)`. +//! +//! The _default_ format string for the _-v_ macros is `"{} → {:?}"`, where +//! the `stringify!`-ed expression and resulting value are passed, in that +//! order. If the log record is not filtered out, the `Debug` implementation +//! for the type of the given expression value is used (`{:?}`). A custom +//! format string can _also_ be passed to the _-v_ macros, for more flexible +//! output: +//! +//! ```rust +//! # #[macro_use] extern crate log; +//! # fn main() { +//! let i = 32; +//! infov!("{} → {}", i); // use `Display` instead of `Debug` +//! infov!("{} → {:#x}", i); // hexadecimal format value +//! infov!("{} → {:#?}", i); // use pretty, multi-line format +//! infov!("index {1:5?} ({0})", i); // prefix, value first with padding +//! # } +//! ``` +//! +//! ### Specifying the logging target +//! +//! For _all_ logging macros, the _target_ defaults to the module path of the +//! current location of use, but may be overridden with the `target:` marker +//! and string literal as the first argument: +//! +//! ```rust +//! # #[macro_use] extern crate log; +//! # fn stats() -> i32 { 33 } +//! # fn main() { +//! use log::Level::Info; +//! +//! let i = 33; +//! let j = warnv!(target: "maths", (i-1) / 2); +//! assert_eq!(j, 16); +//! +//! if log_enabled!(target: "special", Info) { +//! info!(target: "special", "{}", stats()); +//! } +//! # } +//! ``` +//! +//! [`std::fmt`]: https://doc.rust-lang.org/stable/std/fmt/index.html +//! [`std::dbg!`]: https://doc.rust-lang.org/std/macro.dbg.html +//! +//! ## Use 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. //! //! ### Examples //! @@ -75,25 +191,22 @@ //! # fn main() {} //! ``` //! -//! ## In executables -//! -//! Executables should choose a logging implementation and initialize it early in the -//! runtime of the program. Logging implementations will typically include a -//! function to do this. Any log messages generated before -//! the implementation is initialized will be ignored. +//! ## Use in executables //! -//! The executable itself may use the `log` crate to log as well. +//! Executables should choose a logging implementation and initialize it early +//! in the runtime of the program. Logging implementations will typically +//! include a function to do this. Any log messages generated before the +//! implementation is initialized will be ignored. //! -//! ### Warning +//! _Warning_: The logging system may only be initialized once. //! -//! The logging system may only be initialized once. +//! The executable may also use the `log` crate to log. //! -//! # Available logging implementations +//! ### Available logging implementations //! -//! 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: +//! 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: //! //! * Simple minimal loggers: //! * [env_logger] @@ -109,7 +222,7 @@ //! * [syslog] //! * [slog-stdlog] //! -//! # Implementing a Logger +//! ### Implementing a Logger //! //! Loggers implement the [`Log`] trait. Here's a very basic example that simply //! logs all messages at the [`Error`][level_link], [`Warn`][level_link] or @@ -173,7 +286,7 @@ //! Implementations that adjust their configurations at runtime should take care //! to adjust the maximum log level as well. //! -//! # Use with `std` +//! ### Use with `std` //! //! `set_logger` requires you to provide a `&'static Log`, which can be hard to //! obtain if your logger depends on some runtime configuration. The @@ -220,7 +333,7 @@ //! //! These features control the value of the `STATIC_MAX_LEVEL` constant. The logging macros check //! this value before logging a message. By default, no levels are disabled. -//! +//! //! Libraries should avoid using the max level features because they're global and can't be changed //! once they're set. //! @@ -679,7 +792,8 @@ impl LevelFilter { /// `Record` structures are passed as parameters to the [`log`][method.log] /// method of the [`Log`] trait. Logger implementors manipulate these /// structures in order to display log messages. `Record`s are automatically -/// created by the [`log!`] macro and so are not seen by log users. +/// created by the various logging macros and so are not typically seen +/// directly by `log` users. /// /// Note that the [`level()`] and [`target()`] accessors are equivalent to /// `self.metadata().level()` and `self.metadata().target()` respectively. @@ -1073,16 +1187,10 @@ pub fn set_max_level(level: LevelFilter) { /// Returns the current maximum log level. /// -/// The [`log!`], [`error!`], [`warn!`], [`info!`], [`debug!`], and [`trace!`] macros check -/// this value and discard any message logged at a higher level. The maximum -/// log level is set by the [`set_max_level`] function. +/// The logging macros check this value and discard any message logged at a +/// higher level. The maximum log level is set by the [`set_max_level`] +/// function. /// -/// [`log!`]: macro.log.html -/// [`error!`]: macro.error.html -/// [`warn!`]: macro.warn.html -/// [`info!`]: macro.info.html -/// [`debug!`]: macro.debug.html -/// [`trace!`]: macro.trace.html /// [`set_max_level`]: fn.set_max_level.html #[inline(always)] pub fn max_level() -> LevelFilter { diff --git a/src/macros.rs b/src/macros.rs index 06ce65a57..8272f4e81 100644 --- a/src/macros.rs +++ b/src/macros.rs @@ -8,10 +8,10 @@ // option. This file may not be copied, modified, or distributed // except according to those terms. -/// The standard logging macro. +/// Log formatted message at a specified level. /// -/// This macro will generically log with the specified `Level` and `format!` -/// based argument list. +/// This macro will log with the optional or default target, specified `Level` +/// and `format!` based arguments. /// /// # Examples /// @@ -26,7 +26,7 @@ /// /// log!(Level::Error, "Received errors: {}, {}", data.0, data.1); /// log!(target: "app_events", Level::Warn, "App warning: {}, {}, {}", -/// data.0, data.1, private_data); +/// data.0, data.1, private_data); /// # } /// ``` #[macro_export(local_inner_macros)] @@ -44,7 +44,48 @@ macro_rules! log { ($lvl:expr, $($arg:tt)+) => (log!(target: __log_module_path!(), $lvl, $($arg)+)) } -/// Logs a message at the error level. +/// Log an expression and its value at any specified level. +/// +/// Logs with the optional or default (module path of use) target, specified +/// `Level`, optional or default (`"{} → {:?}"`) format string, and a single +/// expression and value, which is returned. This is normally only used +/// through the _-v_ macros like `debugv!` or `tracev!`. +/// +/// Note that the value is moved and then returned. If the type does not +/// implement `Copy`, ownership may be retained by borrowing by reference +/// e.g. `debugv!(&expr)`. +/// +/// # Examples +/// +/// ```rust +/// # #[macro_use] extern crate log; +/// use log::Level; +/// +/// #[derive(Debug)] +/// struct Point { x: f32, y: f32 } +/// +/// fn circle(center: &Point, radius: f32) { /*...*/ } +/// +/// # fn main() { +/// let center = Point { x: 3.234, y: -1.223 }; +/// +/// circle(logv!(Level::Trace, ¢er), 7.3); +/// // ^-- trace level message: "¢er → Point { x: 3.234, y: -1.223 }" +/// circle(tracev!(¢er), 8.0); +/// // ^-- trace level message: "¢er → Point { x: 3.234, y: -1.223 }" +/// # } +/// ``` +#[macro_export(local_inner_macros)] +macro_rules! logv { + (target: $target:expr, $lvl:expr, $($arg:tt)+) => ( + __logv!($lvl, target: $target, $($arg)+) + ); + ($lvl:expr, $($arg:tt)+) => ( + __logv!($lvl, target: __log_module_path!(), $($arg)+) + ); +} + +/// Log a message at the error level. /// /// # Examples /// @@ -68,7 +109,7 @@ macro_rules! error { ) } -/// Logs a message at the warn level. +/// Log a message at the warn level. /// /// # Examples /// @@ -92,7 +133,7 @@ macro_rules! warn { ) } -/// Logs a message at the info level. +/// Log a message at the info level. /// /// # Examples /// @@ -118,7 +159,7 @@ macro_rules! info { ) } -/// Logs a message at the debug level. +/// Log a message at the debug level. /// /// # Examples /// @@ -143,7 +184,7 @@ macro_rules! debug { ) } -/// Logs a message at the trace level. +/// Log a message at the trace level. /// /// # Examples /// @@ -170,11 +211,41 @@ macro_rules! trace { ) } -/// Determines if a message logged at the specified level in that module will -/// be logged. +/// Log an expression at the error level, returning the value. +#[macro_export(local_inner_macros)] +macro_rules! errorv { + ($($arg:tt)+) => (__logv!($crate::Level::Error, $($arg)+)) +} + +/// Log an expression at the warn level, returning the value. +#[macro_export(local_inner_macros)] +macro_rules! warnv { + ($($arg:tt)+) => (__logv!($crate::Level::Warn, $($arg)+)) +} + +/// Log an expression at the info level, returning the value. +#[macro_export(local_inner_macros)] +macro_rules! infov { + ($($arg:tt)+) => (__logv!($crate::Level::Info, $($arg)+)) +} + +/// Log an expression at the debug level, returning the value. +#[macro_export(local_inner_macros)] +macro_rules! debugv { + ($($arg:tt)+) => (__logv!($crate::Level::Debug, $($arg)+)) +} + +/// Log an expression at the trace level, returning the value. +#[macro_export(local_inner_macros)] +macro_rules! tracev { + ($($arg:tt)+) => (__logv!($crate::Level::Trace, $($arg)+)) +} + +/// Return true if a log record will be logged for optional or default +/// _target_ and _level_. /// -/// This can be used to avoid expensive computation of log message arguments if -/// the message would be ignored anyway. +/// This can be used to avoid expensive computation of log message arguments +/// if the message would be ignored anyway. /// /// # Examples /// @@ -189,8 +260,8 @@ macro_rules! trace { /// debug!("expensive debug data: {} {}", data.x, data.y); /// } /// if log_enabled!(target: "Global", Debug) { -/// let data = expensive_call(); -/// debug!(target: "Global", "expensive debug data: {} {}", data.x, data.y); +/// let data = expensive_call(); +/// debug!(target: "Global", "expensive debug data: {} {}", data.x, data.y); /// } /// # } /// # struct Data { x: u32, y: u32 } @@ -210,12 +281,46 @@ macro_rules! log_enabled { }; } -// The log macro above cannot invoke format_args directly because it uses -// local_inner_macros. A format_args invocation there would resolve to -// $crate::format_args which does not exist. Instead invoke format_args here -// outside of local_inner_macros so that it resolves (probably) to -// core::format_args or std::format_args. Same for the several macros that -// follow. +// Helper macro for the -v macros, handling the permutations of optional +// parameters. Note: The required level paremeter is first here for +// convenience of internal use with variable-args. +#[doc(hidden)] +#[macro_export(local_inner_macros)] +macro_rules! __logv { + ($lvl:expr, target: $tgt:expr, $fmt:expr, $val:expr) => ( + __logv_eval!($tgt, $lvl, $fmt, $val) + ); + ($lvl:expr, target: $tgt:expr, $val:expr) => ( + __logv_eval!($tgt, $lvl, "{} → {:?}", $val) + ); + ($lvl:expr, $fmt:expr, $val:expr) => ( + __logv_eval!(__log_module_path!(), $lvl, $fmt, $val) + ); + ($lvl:expr, $val:expr) => ( + __logv_eval!(__log_module_path!(), $lvl, "{} → {:?}", $val) + ); +} + +// Inner helper macro for __logv. Evaluates expression exactly once, moves +// value and returns it. +#[doc(hidden)] +#[macro_export(local_inner_macros)] +macro_rules! __logv_eval { + ($tgt:expr, $lvl:expr, $fmt:expr, $exp:expr) => ( + match $exp { + vt => { + log!(target: $tgt, $lvl, $fmt, __log_stringify!($exp), &vt); + vt + } + } + ) +} + +// The macros above cannot invoke `format_args!` or other core/std macros +// directly when they use `local_inner_macros`. A `format_args!` invocation in +// these would resolve to `$crate::format_args` which does not exist. Instead +// invoke `format_args!` here outside of `local_inner_macros` so that it +// resolves (probably) to `core::format_args` or `std::format_args`. // // This is a workaround until we drop support for pre-1.30 compilers. At that // point we can remove use of local_inner_macros, use $crate:: when invoking @@ -251,3 +356,11 @@ macro_rules! __log_line { line!() }; } + +#[doc(hidden)] +#[macro_export] +macro_rules! __log_stringify { + ($($args:tt)*) => { + stringify!($($args)*) + }; +} diff --git a/tests/log_v.rs b/tests/log_v.rs new file mode 100644 index 000000000..5fd64c093 --- /dev/null +++ b/tests/log_v.rs @@ -0,0 +1,145 @@ +//! Stateful tests of *v (inline expression value) log macros (debugv, etc.) + +#[macro_use] +extern crate log; + +use std::sync::{Arc, Mutex}; +use log::{Level, LevelFilter, Log, Record, Metadata}; + +#[cfg(feature = "std")] +use log::set_boxed_logger; + +#[cfg(not(feature = "std"))] +fn set_boxed_logger(logger: Box) -> Result<(), log::SetLoggerError> { + log::set_logger(unsafe { &*Box::into_raw(logger) }) +} + +struct State { + last_log: Mutex>, +} + +fn last(state: &State) -> Option { + state.last_log.lock().unwrap().take() +} + +struct Logger(Arc); + +impl Log for Logger { + fn enabled(&self, _: &Metadata) -> bool { + true + } + + fn log(&self, record: &Record) { + let msg = format!("{}", record.args()); + *self.0.last_log.lock().unwrap() = Some(msg); + assert_eq!(record.file(), Some(file!())); + assert!(record.line().is_some()); + let t = record.target().to_owned(); + assert!(t == "log_v" || t == "special", t); + println!("{:5} {}", record.level(), record.args()); + } + + fn flush(&self) {} +} + +fn main() { + let me = Arc::new(State { last_log: Mutex::new(None) }); + let a = me.clone(); + set_boxed_logger(Box::new(Logger(me))).unwrap(); + + log::set_max_level(LevelFilter::Debug); + + info!("Start of test (test output follows)"); + + // Simplest use + let i = 32; + assert_eq!(debugv!(i), 32); + assert_eq!(last(&a), Some("i → 32".to_owned())); + + // More expression (note reformatting via `stringify!`) + assert_eq!(debugv!(i+1), 33); + assert_eq!(last(&a), Some("i + 1 → 33".to_owned())); + + // Use special target (note target assert in Logger::log) + assert_eq!(errorv!(target: "special", i), 32); + assert_eq!(last(&a), Some("i → 32".to_owned())); + + // Use custom format (note: Display format, hex output) + assert_eq!(warnv!("custom: {} → {:#x}", i), 32); + assert_eq!(last(&a), Some("custom: i → 0x20".to_owned())); + + // Use custom format with named specifiers (note: Display format) + assert_eq!(infov!("index: {1:5?} ({0})", i), 32); + assert_eq!(last(&a), Some("index: 32 (i)".to_owned())); + + // Use both special target and custom format + assert_eq!(errorv!(target: "special", "custom: {} → {:05}", i), 32); + assert_eq!(last(&a), Some("custom: i → 00032".to_owned())); + + // Explicit tuple for multiple expressions + let j = 19; + let (q, r) = debugv!((j/4, j%4)); + assert_eq!(q, 4); + assert_eq!(r, 3); + assert_eq!(last(&a), Some("(j / 4, j % 4) → (4, 3)".to_owned())); + // Explicit tuple and custom format + assert_eq!(debugv!("fifth {} → {:?}", (j/5, j%5)), (3, 4)); + assert_eq!(last(&a), Some("fifth (j / 5, j % 5) → (3, 4)".to_owned())); + + // Syntactic edge case of single value tuple + assert_eq!(debugv!((j,)), (19,)); + #[allow(unused_parens)] { + // A trailing comma is required for compiler to interpret as + // tuple. This is not a tuple! + assert_eq!(debugv!((j)), 19); + } + + // String and its default `Debug` formatting, by reference and move. + let vt = "foo"; + assert_eq!(infov!(&vt), &"foo"); + assert_eq!(last(&a), Some("&vt → \"foo\"".to_owned())); + assert_eq!(infov!(vt), "foo"); + assert_eq!(last(&a), Some("vt → \"foo\"".to_owned())); + + // Trace disabled, expression still returned, but no log + let i = 2; + assert_eq!(tracev!(i*4), 8); + assert_eq!(last(&a), None); + + // v* macros expand and evaluate the expression exactly _once_. + let mut o = Some(33); + assert_eq!(debugv!(o.take()), Some(33)); + assert_eq!(last(&a), Some("o.take() → Some(33)".to_owned())); + assert_eq!(debugv!(o.take()), None); + assert_eq!(last(&a), Some("o.take() → None".to_owned())); + + // Use `logv!` and special target (asserted in Logger::log) + let i = 3; + assert_eq!(logv!(target: "special", Level::Info, i), 3); + assert_eq!(last(&a), Some("i → 3".to_owned())); + + // logv, default target, tuple + assert_eq!(logv!(Level::Warn, (i+1, i+2)).1, 5); + assert_eq!(last(&a), Some("(i + 1, i + 2) → (4, 5)".to_owned())); + + // void function, statement position + fn fvoid() {} + debugv!(fvoid()); + assert_eq!(last(&a), Some("fvoid() → ()".to_owned())); + + // str function, with let binding. + fn fstr() -> String { "returned".to_owned() } + let s = debugv!(fstr()); + assert_eq!(s, "returned"); + assert_eq!(last(&a), Some("fstr() → \"returned\"".to_owned())); + + // wrapping assignments is possible, but not very interesting, given + // rust doesn't emit the value, even with Copy types. + let mut m = 1; + assert_eq!(m, 1); + infov!(m = 2); + assert_eq!(m, 2); + assert_eq!(last(&a), Some("m = 2 → ()".to_owned())); + + info!("End of test (passed)"); +}