diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 3efbefe7..db2deb9c 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -19,7 +19,7 @@ env: # - src/lib.rs # - Cargo.toml # - README.md - rust_minver: 1.60.0 + rust_minver: 1.61.0 defaults: run: @@ -49,7 +49,7 @@ jobs: fail-fast: false matrix: os: ['ubuntu-latest', 'windows-latest', 'macos-latest'] - fn_features: ['', 'log native libsystemd multi-thread runtime-pattern serde_json'] + fn_features: ['', 'log native libsystemd multi-thread runtime-pattern serde serde_json sval'] cfg_feature: ['', 'flexible-string', 'source-location'] runs-on: ${{ matrix.os }} steps: diff --git a/README.md b/README.md index bf018634..28a5885d 100644 --- a/README.md +++ b/README.md @@ -20,8 +20,9 @@ Fast, highly configurable Rust logging crate, inspired by the C++ logging librar - files (single file, rotating hourly, daily, periodically or by file size); - platform-specific (e.g. `journald` for Linux and `OutputDebugStringW` for Windows); - ... and able to implement one yourself. + - Structured logging. - Configuring via environment variables or TOML[^1]. - - More readable level filters. + - Readable level filters. [^1]: TOML deserialization support is working in progress, tracking issue [#25] @@ -46,7 +47,7 @@ When updating this, also update: - Cargo.toml --> -The current minimum supported Rust version is 1.60. +The current minimum supported Rust version is 1.61. `spdlog-rs` is built against the latest Rust stable release, it is not guaranteed to build on Rust versions earlier than the minimum supported version. diff --git a/spdlog-internal/Cargo.toml b/spdlog-internal/Cargo.toml index 529751d5..338f5b59 100644 --- a/spdlog-internal/Cargo.toml +++ b/spdlog-internal/Cargo.toml @@ -2,7 +2,7 @@ name = "spdlog-internal" version = "0.1.0" edition = "2021" -rust-version = "1.60" +rust-version = "1.61" description = "Internal private common code for crate \"spdlog-rs\"" repository = "https://github.com/SpriteOvO/spdlog-rs" license = "MIT OR Apache-2.0" diff --git a/spdlog-internal/src/pattern_parser/mod.rs b/spdlog-internal/src/pattern_parser/mod.rs index bfd8fbd3..7b5306da 100644 --- a/spdlog-internal/src/pattern_parser/mod.rs +++ b/spdlog-internal/src/pattern_parser/mod.rs @@ -86,6 +86,8 @@ pub enum BuiltInFormatterInner { LoggerName, #[strum(serialize = "payload")] Payload, + #[strum(serialize = "kv")] + KV, #[strum(serialize = "pid")] ProcessId, #[strum(serialize = "tid")] diff --git a/spdlog-macros/Cargo.toml b/spdlog-macros/Cargo.toml index 3374a427..59a00f64 100644 --- a/spdlog-macros/Cargo.toml +++ b/spdlog-macros/Cargo.toml @@ -2,7 +2,7 @@ name = "spdlog-macros" version = "0.2.0" edition = "2021" -rust-version = "1.60" +rust-version = "1.61" description = "Macros implementation of crate \"spdlog-rs\"" repository = "https://github.com/SpriteOvO/spdlog-rs" license = "MIT OR Apache-2.0" diff --git a/spdlog-macros/src/lib.rs b/spdlog-macros/src/lib.rs index cc1eec0d..6f579756 100644 --- a/spdlog-macros/src/lib.rs +++ b/spdlog-macros/src/lib.rs @@ -5,16 +5,17 @@ //! //! [`spdlog-rs`]: https://crates.io/crates/spdlog-rs +mod normalize_forward; mod pattern; use proc_macro::TokenStream; use proc_macro2::TokenStream as TokenStream2; -use spdlog_internal::pattern_parser::Result; +use quote::quote; #[proc_macro] pub fn pattern(input: TokenStream) -> TokenStream { let pattern = syn::parse_macro_input!(input); - into_or_error(pattern::pattern_impl(pattern)) + into_or_error(pattern::pattern_impl(pattern).map_err(Error::PatternParser)) } #[proc_macro] @@ -23,12 +24,42 @@ pub fn runtime_pattern(input: TokenStream) -> TokenStream { // token which is used in the custom patterns. let runtime_pattern = syn::parse_macro_input!(input); - into_or_error(pattern::runtime_pattern_impl(runtime_pattern)) + into_or_error(pattern::runtime_pattern_impl(runtime_pattern).map_err(Error::PatternParser)) } -fn into_or_error(result: Result) -> TokenStream { +// Example: +// +// ```rust +// normalize_forward!(callback => default[opt1: 1, opt2: {}, opt3: { 3 }, d], opt1: 10, a, b, c, opt3: { 30 }); +// // will be converted to +// spdlog::callback!(opt1: 10, opt2: {}, opt3: { 30 }, d, a, b, c); +// ``` +#[proc_macro] +pub fn normalize_forward(input: TokenStream) -> TokenStream { + let normalize = syn::parse_macro_input!(input); + into_or_error(normalize_forward::normalize(normalize).map_err(Error::NormalizeForward)) +} + +enum Error { + PatternParser(spdlog_internal::pattern_parser::Error), + NormalizeForward(syn::Error), +} + +impl Error { + fn emit(self) -> TokenStream2 { + match self { + Error::PatternParser(err) => { + let error = err.to_string(); + quote!(compile_error!(#error)) + } + Error::NormalizeForward(err) => err.to_compile_error(), + } + } +} + +fn into_or_error(result: Result) -> TokenStream { match result { Ok(stream) => stream.into(), - Err(err) => panic!("{}", err), + Err(err) => err.emit().into(), } } diff --git a/spdlog-macros/src/normalize_forward.rs b/spdlog-macros/src/normalize_forward.rs new file mode 100644 index 00000000..981f1675 --- /dev/null +++ b/spdlog-macros/src/normalize_forward.rs @@ -0,0 +1,233 @@ +use std::collections::HashSet; + +use proc_macro2::TokenStream; +use quote::{quote, ToTokens}; +use syn::{ + braced, bracketed, + parse::{discouraged::Speculative, Parse, ParseStream}, + Expr, Ident, Token, +}; + +pub struct Normalize { + callback: Ident, + default_list: DefaultArgsList, + args: Args, +} + +impl Parse for Normalize { + fn parse(input: ParseStream) -> syn::Result { + let callback = input.parse::()?; + input.parse::]>()?; + let default_list = DefaultArgsList::parse(input)?; + input.parse::()?; + let args = Args::parse(input)?; + Ok(Self { + callback, + default_list, + args, + }) + } +} + +struct DefaultArgsList(Vec); + +impl Parse for DefaultArgsList { + fn parse(input: ParseStream) -> syn::Result { + input.parse::()?; + let list; + bracketed!(list in input); + let list = list + .parse_terminated(Arg::parse, Token![,])? + .into_iter() + .collect(); + Ok(Self(list)) + } +} + +struct Args(Vec); + +impl Parse for Args { + fn parse(input: ParseStream) -> syn::Result { + let args = input.parse_terminated(Arg::parse, Token![,])?; + Ok(Self(args.into_iter().collect())) + } +} + +enum Arg { + Optional(OptionalArg), + Other(ArgValue), +} + +impl Arg { + fn as_optional(&self) -> Option<&OptionalArg> { + match self { + Self::Optional(arg) => Some(arg), + _ => None, + } + } + + fn as_optional_mut(&mut self) -> Option<&mut OptionalArg> { + match self { + Self::Optional(arg) => Some(arg), + _ => None, + } + } +} + +impl Parse for Arg { + fn parse(input: ParseStream) -> syn::Result { + let fork = input.fork(); + match OptionalArg::parse(&fork) { + Ok(opt_arg) => { + input.advance_to(&fork); + Ok(Self::Optional(opt_arg)) + } + Err(_) => Ok(Self::Other(ArgValue::parse(input)?)), + } + } +} + +struct OptionalArg { + name: Ident, + value: ArgValue, +} + +impl Parse for OptionalArg { + fn parse(input: ParseStream) -> syn::Result { + let name = input.parse::()?; + input.parse::()?; + let value = ArgValue::parse(input)?; + Ok(Self { name, value }) + } +} + +enum ArgValue { + Expr(Expr), + Braced(BraceAny), +} + +impl ArgValue { + fn into_token_stream(self) -> TokenStream { + match self { + Self::Expr(expr) => expr.into_token_stream(), + Self::Braced(braced) => braced.0, + } + } +} + +impl Parse for ArgValue { + fn parse(input: ParseStream) -> syn::Result { + let fork = input.fork(); + + match Expr::parse(&fork) { + Ok(expr) => { + input.advance_to(&fork); + Ok(Self::Expr(expr)) + } + Err(_) => Ok(BraceAny::parse(input).map(Self::Braced)?), + } + } +} + +struct BraceAny(TokenStream); + +impl Parse for BraceAny { + fn parse(input: ParseStream) -> syn::Result { + let content; + braced!(content in input); + let ts: TokenStream = content.parse()?; + Ok(Self(quote!({#ts}))) + } +} + +fn check_inputs(normalize: &Normalize) -> syn::Result<()> { + let mut seen_keys = HashSet::new(); + for arg in normalize.args.0.iter().filter_map(|arg| arg.as_optional()) { + if !seen_keys.insert(&arg.name) { + return Err(syn::Error::new( + arg.name.span(), + format!("found duplicate optional argument '{}'", arg.name), + )); + } + } + + let groups = normalize + .args + .0 + .split_inclusive(|arg| matches!(arg, Arg::Optional(_))) + .filter(|group| group.iter().any(|arg| !matches!(arg, Arg::Optional(_)))) + .collect::>(); + if groups.len() > 1 { + return Err(syn::Error::new( + groups + .first() + .and_then(|group| group.last()) + .and_then(|arg| arg.as_optional()) + .unwrap() + .name + .span(), + "optional arguments cannot occur in the middle of regular arguments", + )); + } + + Ok(()) +} + +pub fn normalize(normalize: Normalize) -> syn::Result { + check_inputs(&normalize)?; + + let mut default_args = normalize.default_list.0; + let mut other_args = vec![]; + + for input_arg in normalize.args.0 { + match input_arg { + Arg::Optional(input_arg) => { + let stored = default_args + .iter_mut() + .find_map(|allowed| { + allowed + .as_optional_mut() + .and_then(|allowed| (allowed.name == input_arg.name).then(|| allowed)) + }) + .ok_or_else(|| { + syn::Error::new( + input_arg.name.span(), + format!("unknown optional parameter '{}'", input_arg.name), + ) + })?; + stored.value = input_arg.value; + } + Arg::Other(input_arg) => { + other_args.push(input_arg); + } + } + } + + let callback = normalize.callback; + let default_args = default_args + .into_iter() + .map(|arg| match arg { + Arg::Optional(arg) => { + let name = arg.name; + let value = arg.value.into_token_stream(); + quote!(#name: #value) + } + Arg::Other(arg) => { + let value = arg.into_token_stream(); + quote!(#value) + } + }) + .collect::>(); + let other_args = other_args + .into_iter() + .map(|arg| { + let ts = arg.into_token_stream(); + quote!(#ts) + }) + .collect::>(); + + let emitted = quote! { + ::spdlog::#callback!(#(#default_args),*, #(#other_args),*) + }; + Ok(emitted) +} diff --git a/spdlog/Cargo.toml b/spdlog/Cargo.toml index b049e5a2..e2abb327 100644 --- a/spdlog/Cargo.toml +++ b/spdlog/Cargo.toml @@ -2,7 +2,7 @@ name = "spdlog-rs" version = "0.4.1" edition = "2021" -rust-version = "1.60" +rust-version = "1.61" description = "Fast, highly configurable Rust logging crate, inspired by the C++ logging library spdlog" repository = "https://github.com/SpriteOvO/spdlog-rs" license = "MIT OR Apache-2.0" @@ -37,7 +37,9 @@ native = [] libsystemd = ["libsystemd-sys"] multi-thread = ["crossbeam"] runtime-pattern = ["spdlog-internal"] +serde = ["dep:serde", "value-bag/serde"] serde_json = ["serde", "dep:serde_json"] +sval = ["value-bag/sval"] [dependencies] arc-swap = "1.5.1" @@ -49,7 +51,7 @@ dyn-clone = "1.0.14" flexible-string = { version = "0.1.0", optional = true } if_chain = "1.0.2" is-terminal = "0.4" -log = { version = "0.4.8", optional = true } +log = { version = "0.4.21", optional = true, features = ["kv"] } once_cell = "1.16.0" serde = { version = "1.0.163", optional = true, features = ["derive"] } serde_json = { version = "1.0.120", optional = true } @@ -57,6 +59,7 @@ spdlog-internal = { version = "=0.1.0", path = "../spdlog-internal", optional = spdlog-macros = { version = "=0.2.0", path = "../spdlog-macros" } spin = "0.9.8" thiserror = "1.0.37" +value-bag = { version = "1.11.1", features = ["owned", "inline-i128"] } [target.'cfg(windows)'.dependencies] winapi = { version = "0.3.9", features = ["consoleapi", "debugapi", "handleapi", "processenv", "processthreadsapi", "winbase", "wincon"] } @@ -73,6 +76,8 @@ crossbeam = "0.8.2" regex = "1.7.0" paste = "1.0.14" trybuild = "1.0.90" +sval = "2.14.0" +sval_derive = "2.14.0" # [bench-dependencies] log = "=0.4.22" @@ -117,6 +122,9 @@ name = "spdlog_rs_log_crate_proxy" path = "benches/spdlog-rs/log_crate_proxy.rs" required-features = ["log"] [[bench]] +name = "spdlog_rs_kv" +path = "benches/spdlog-rs/kv.rs" +[[bench]] name = "fast_log" path = "benches/fast_log/main.rs" harness = false diff --git a/spdlog/benches/spdlog-rs/kv.rs b/spdlog/benches/spdlog-rs/kv.rs new file mode 100644 index 00000000..ecb17426 --- /dev/null +++ b/spdlog/benches/spdlog-rs/kv.rs @@ -0,0 +1,56 @@ +#![feature(test)] + +extern crate test; + +#[path = "../common/mod.rs"] +mod common; + +use std::sync::Arc; + +use spdlog::{prelude::*, sink::*}; +use test::Bencher; + +include!(concat!( + env!("OUT_DIR"), + "/test_utils/common_for_integration_test.rs" +)); +use test_utils::*; + +fn logger(name: &str) -> Logger { + let path = common::BENCH_LOGS_PATH.join(format!("kv_{name}.log")); + let sink = Arc::new( + FileSink::builder() + .path(path) + .truncate(true) + .build() + .unwrap(), + ); + build_test_logger(|b| b.sink(sink)) +} + +#[bench] +fn bench_kv_str(bencher: &mut Bencher) { + let logger = logger("str"); + bencher.iter( + || info!(logger: logger, bench_log_message!(), kv: { k1 = "v1", k2 = "v2", k3 = "v3" }), + ) +} + +#[bench] +fn bench_kv_mixed(bencher: &mut Bencher) { + let logger = logger("mixed"); + let v = vec![1]; + bencher.iter(|| info!(logger: logger, bench_log_message!(), kv: { k1 = 1, k2: = 1.0, v:? })) +} + +#[bench] +fn bench_kv_many(bencher: &mut Bencher) { + let logger = logger("12_kv"); + bencher.iter(|| { + info!(logger: logger, bench_log_message!(), kv: { + k1 = "v1", k2 = "v2", k3 = "v3", k4 = "v4", + k5 = "v5", k6 = "v6", k7 = "v7", k8 = "v8", + k9 = "v9", k10 = "v10", k11 = "v11", k12 = "v12", + }) + }) +} diff --git a/spdlog/benches/spdlog-rs/log_crate_proxy.rs b/spdlog/benches/spdlog-rs/log_crate_proxy.rs index 67222b52..70da81c9 100644 --- a/spdlog/benches/spdlog-rs/log_crate_proxy.rs +++ b/spdlog/benches/spdlog-rs/log_crate_proxy.rs @@ -29,3 +29,9 @@ fn bench_log_crate_proxy(bencher: &mut Bencher) { init(); bencher.iter(|| log::info!(bench_log_message!())) } + +#[bench] +fn bench_log_crate_proxy_kv(bencher: &mut Bencher) { + init(); + bencher.iter(|| log::info!(key1 = 42, key2 = true; bench_log_message!())) +} diff --git a/spdlog/examples/01_macro.rs b/spdlog/examples/01_macro.rs index 5fedf92a..7572e82d 100644 --- a/spdlog/examples/01_macro.rs +++ b/spdlog/examples/01_macro.rs @@ -2,8 +2,8 @@ use spdlog::prelude::*; fn main() { - // Writes a log at "info" level with the info level, and this log will be - // processed by the global default logger - It will be output to `stdout`. + // Writes a log at "info" level, and this log will be processed by the global + // default logger - It will be output to `stdout`. info!("program started"); let file = "config.json"; @@ -17,4 +17,6 @@ fn main() { spdlog::default_logger().set_level_filter(LevelFilter::All); trace!("position x: {}, y: {}", 11.4, -5.14); + // Or if you prefer structured logging. + trace!("position", kv: { x = 11.4, y = -5.14 }); } diff --git a/spdlog/src/formatter/full_formatter.rs b/spdlog/src/formatter/full_formatter.rs index 11b6347f..5165b5f1 100644 --- a/spdlog/src/formatter/full_formatter.rs +++ b/spdlog/src/formatter/full_formatter.rs @@ -19,19 +19,19 @@ use crate::{ /// - Default: /// /// 
-///    [2022-11-02 09:23:12.263] [info] hello, world!
+///    [2022-11-02 09:23:12.263] [info] hello, world! { key1=value1 key2=value2 }
 ///
/// /// - If the logger has a name: /// /// 
-///    [2022-11-02 09:23:12.263] [logger-name] [info] hello, world!
+///    [2022-11-02 09:23:12.263] [logger-name] [info] hello, world! { key1=value1 key2=value2 }
 ///
/// /// - If crate feature `source-location` is enabled: /// /// 
-///    [2022-11-02 09:23:12.263] [logger-name] [info] [mod::path, src/main.rs:4] hello, world!
+///    [2022-11-02 09:23:12.263] [logger-name] [info] [mod::path, src/main.rs:4] hello, world! { key1=value1 key2=value2 }
 ///
#[derive(Clone)] pub struct FullFormatter { @@ -62,14 +62,18 @@ impl FullFormatter { } } - fmt_with_time(ctx, record, |mut time: TimeDate| { - dest.write_str("[")?; - dest.write_str(time.full_second_str())?; - dest.write_str(".")?; - write!(dest, "{:03}", time.millisecond())?; - dest.write_str("] [")?; - Ok(()) - })?; + fmt_with_time( + ctx, + record, + |mut time: TimeDate| -> Result<(), fmt::Error> { + dest.write_str("[")?; + dest.write_str(time.full_second_str())?; + dest.write_str(".")?; + write!(dest, "{:03}", time.millisecond())?; + dest.write_str("] [")?; + Ok(()) + }, + )?; if let Some(logger_name) = record.logger_name() { dest.write_str(logger_name)?; @@ -94,6 +98,8 @@ impl FullFormatter { dest.write_str("] ")?; dest.write_str(record.payload())?; + record.key_values().write_to(dest, true)?; + if self.with_eol { dest.write_str(__EOL)?; } @@ -126,11 +132,15 @@ mod tests { use chrono::prelude::*; use super::*; - use crate::{Level, __EOL}; + use crate::{kv, Level, __EOL}; #[test] fn format() { - let record = Record::new(Level::Warn, "test log content", None, None); + let kvs = [ + (kv::Key::__from_static_str("k1"), kv::Value::from(114)), + (kv::Key::__from_static_str("k2"), kv::Value::from("514")), + ]; + let record = Record::new(Level::Warn, "test log content", None, None, &kvs); let mut buf = StringBuf::new(); let mut ctx = FormatterContext::new(); FullFormatter::new() @@ -140,7 +150,7 @@ mod tests { let local_time: DateTime = record.time().into(); assert_eq!( format!( - "[{}] [warn] test log content{}", + "[{}] [warn] test log content {{ k1=114 k2=514 }}{}", local_time.format("%Y-%m-%d %H:%M:%S.%3f"), __EOL ), diff --git a/spdlog/src/formatter/journald_formatter.rs b/spdlog/src/formatter/journald_formatter.rs index 14ba53a4..a271c107 100644 --- a/spdlog/src/formatter/journald_formatter.rs +++ b/spdlog/src/formatter/journald_formatter.rs @@ -48,6 +48,9 @@ impl JournaldFormatter { dest.write_str("] ")?; dest.write_str(record.payload())?; + + record.key_values().write_to(dest, true)?; + dest.write_str(__EOL)?; ctx.set_style_range(Some(style_range_begin..style_range_end)); diff --git a/spdlog/src/formatter/json_formatter.rs b/spdlog/src/formatter/json_formatter.rs index dc3f6de0..f11ada11 100644 --- a/spdlog/src/formatter/json_formatter.rs +++ b/spdlog/src/formatter/json_formatter.rs @@ -5,7 +5,10 @@ use std::{ }; use cfg_if::cfg_if; -use serde::{ser::SerializeStruct, Serialize}; +use serde::{ + ser::{SerializeMap, SerializeStruct}, + Serialize, Serializer, +}; use crate::{ formatter::{Formatter, FormatterContext}, @@ -16,12 +19,12 @@ fn opt_to_num(opt: Option) -> usize { opt.map_or(0, |_| 1) } -struct JsonRecord<'a>(&'a Record<'a>); +struct JsonRecord<'a, 'b>(&'a Record<'b>); -impl Serialize for JsonRecord<'_> { +impl Serialize for JsonRecord<'_, '_> { fn serialize(&self, serializer: S) -> Result where - S: serde::Serializer, + S: Serializer, { let fields_len = 4 + opt_to_num(self.0.logger_name()) + opt_to_num(self.0.source_location()); @@ -40,6 +43,27 @@ impl Serialize for JsonRecord<'_> { .expect("invalid timestamp"), )?; record.serialize_field("payload", self.0.payload())?; + + if !self.0.key_values().is_empty() { + struct JsonKV<'a, 'b>(&'a Record<'b>); + + impl Serialize for JsonKV<'_, '_> { + fn serialize(&self, serializer: S) -> Result + where + S: Serializer, + { + let kv = self.0.key_values(); + let mut map = serializer.serialize_map(Some(kv.len()))?; + for (key, value) in kv { + map.serialize_entry(key.as_str(), &value)?; + } + map.end() + } + } + + record.serialize_field("kv", &JsonKV(self.0))?; + } + if let Some(logger_name) = self.0.logger_name() { record.serialize_field("logger", logger_name)?; } @@ -52,12 +76,6 @@ impl Serialize for JsonRecord<'_> { } } -impl<'a> From<&'a Record<'a>> for JsonRecord<'a> { - fn from(value: &'a Record<'a>) -> Self { - JsonRecord(value) - } -} - enum JsonFormatterError { Fmt(fmt::Error), Serialization(serde_json::Error), @@ -96,6 +114,7 @@ impl From for crate::Error { /// | `level` | String | The level of the log. Same as the return of [`Level::as_str`]. | /// | `timestamp` | Integer(u64) | The timestamp when the log was generated, in milliseconds since January 1, 1970 00:00:00 UTC. | /// | `payload` | String | The contents of the log. | +/// | `kv` | Object/Null | The key-values of the log. Null if kv is not specified. | /// | `logger` | String/Null | The name of the logger. Null if the logger has no name. | /// | `tid` | Integer(u64) | The thread ID when the log was generated. | /// | `source` | Object/Null | The source location of the log. See [`SourceLocation`] for its schema. Null if crate feature `source-location` is not enabled. | @@ -126,6 +145,13 @@ impl From for crate::Error { /// {"level":"error","timestamp":1722817541459,"payload":"something went wrong","logger":"app-component","tid":3478045} /// ``` /// +/// - If key-values are present: +/// +/// ```json +/// {"level":"info","timestamp":1722817541459,"payload":"hello, world!","kv":{"k1":123,"k2":"cool"},"tid":3478045} +/// {"level":"error","timestamp":1722817541459,"payload":"something went wrong","kv":{"k1":123,"k2":"cool"},"tid":3478045} +/// ``` +/// /// - If crate feature `source-location` is enabled: /// /// ```json @@ -157,13 +183,11 @@ impl JsonFormatter { } } - let json_record: JsonRecord = record.into(); - // TODO: https://github.com/serde-rs/json/issues/863 // // The performance can be significantly optimized here if the issue can be // solved. - dest.write_str(&serde_json::to_string(&json_record)?)?; + dest.write_str(&serde_json::to_string(&JsonRecord(record))?)?; dest.write_str(__EOL)?; @@ -193,13 +217,13 @@ mod tests { use chrono::prelude::*; use super::*; - use crate::{Level, SourceLocation, __EOL}; + use crate::{kv, Level, SourceLocation, __EOL}; #[test] fn should_format_json() { let mut dest = StringBuf::new(); let formatter = JsonFormatter::new(); - let record = Record::new(Level::Info, "payload", None, None); + let record = Record::new(Level::Info, "payload", None, None, &[]); let mut ctx = FormatterContext::new(); formatter.format(&record, &mut dest, &mut ctx).unwrap(); @@ -222,7 +246,7 @@ mod tests { fn should_format_json_with_logger_name() { let mut dest = StringBuf::new(); let formatter = JsonFormatter::new(); - let record = Record::new(Level::Info, "payload", None, Some("my-component")); + let record = Record::new(Level::Info, "payload", None, Some("my-component"), &[]); let mut ctx = FormatterContext::new(); formatter.format(&record, &mut dest, &mut ctx).unwrap(); @@ -250,6 +274,7 @@ mod tests { "payload", Some(SourceLocation::__new("module", "file.rs", 1, 2)), None, + &[], ); let mut ctx = FormatterContext::new(); formatter.format(&record, &mut dest, &mut ctx).unwrap(); @@ -268,4 +293,31 @@ mod tests { ) ); } + + #[test] + fn should_format_json_with_kv() { + let mut dest = StringBuf::new(); + let formatter = JsonFormatter::new(); + let kvs = [ + (kv::Key::__from_static_str("k1"), kv::Value::from(114)), + (kv::Key::__from_static_str("k2"), kv::Value::from("514")), + ]; + let record = Record::new(Level::Info, "payload", None, None, &kvs); + let mut ctx = FormatterContext::new(); + formatter.format(&record, &mut dest, &mut ctx).unwrap(); + + let local_time: DateTime = record.time().into(); + + assert_eq!(ctx.style_range(), None); + assert_eq!( + dest.to_string(), + format!( + r#"{{"level":"info","timestamp":{},"payload":"{}","kv":{{"k1":114,"k2":"514"}},"tid":{}}}{}"#, + local_time.timestamp_millis(), + "payload", + record.tid(), + __EOL + ) + ); + } } diff --git a/spdlog/src/formatter/pattern_formatter/mod.rs b/spdlog/src/formatter/pattern_formatter/mod.rs index e15d1c61..ad0e6ef5 100644 --- a/spdlog/src/formatter/pattern_formatter/mod.rs +++ b/spdlog/src/formatter/pattern_formatter/mod.rs @@ -331,6 +331,7 @@ use crate::{ /// | `{module_path}` | Source module path | `mod::module` [^1] | /// | `{logger}` | Logger name | `my-logger` | /// | `{payload}` | Log payload | `log message` | +/// | `{kv}` | Key-values | `k1=123 k2=text` | /// | `{pid}` | Process ID | `3824` | /// | `{tid}` | Thread ID | `3132` | /// | `{eol}` | End of line | `\n` (on non-Windows) or `\r\n` (on Windows) | @@ -1230,6 +1231,7 @@ mod tests { "record_payload", Some(SourceLocation::__new("module", "file", 10, 20)), Some("logger_name"), + &[], ) } diff --git a/spdlog/src/formatter/pattern_formatter/pattern/kv.rs b/spdlog/src/formatter/pattern_formatter/pattern/kv.rs new file mode 100644 index 00000000..c9959477 --- /dev/null +++ b/spdlog/src/formatter/pattern_formatter/pattern/kv.rs @@ -0,0 +1,21 @@ +use crate::{ + formatter::pattern_formatter::{Pattern, PatternContext}, + Error, Record, StringBuf, +}; + +#[derive(Clone, Default)] +pub struct KV; + +impl Pattern for KV { + fn format( + &self, + record: &Record, + dest: &mut StringBuf, + _ctx: &mut PatternContext, + ) -> crate::Result<()> { + record + .key_values() + .write_to(dest, false) + .map_err(Error::FormatRecord) + } +} diff --git a/spdlog/src/formatter/pattern_formatter/pattern/mod.rs b/spdlog/src/formatter/pattern_formatter/pattern/mod.rs index 0a6517f4..f374b256 100644 --- a/spdlog/src/formatter/pattern_formatter/pattern/mod.rs +++ b/spdlog/src/formatter/pattern_formatter/pattern/mod.rs @@ -3,6 +3,7 @@ mod datetime; mod eol; mod full; +mod kv; mod level; mod logger_name; mod payload; @@ -14,6 +15,7 @@ mod thread_id; pub use datetime::*; pub use eol::*; pub use full::*; +pub use kv::*; pub use level::*; pub use logger_name::*; pub use payload::*; diff --git a/spdlog/src/formatter/pattern_formatter/runtime.rs b/spdlog/src/formatter/pattern_formatter/runtime.rs index 8d643a26..8de9711c 100644 --- a/spdlog/src/formatter/pattern_formatter/runtime.rs +++ b/spdlog/src/formatter/pattern_formatter/runtime.rs @@ -253,6 +253,7 @@ fn build_builtin_pattern(builtin: &BuiltInFormatter) -> Box { SourceModulePath, LoggerName, Payload, + KV, ProcessId, ThreadId, Eol diff --git a/spdlog/src/include/doc/log-macro-named-opt-params.md b/spdlog/src/include/doc/log-macro-named-opt-params.md new file mode 100644 index 00000000..16b8544f --- /dev/null +++ b/spdlog/src/include/doc/log-macro-named-opt-params.md @@ -0,0 +1,12 @@ +# Named optional parameters + +Named optional parameters are parameters for logging macros to configure this log record. + +Each parameter is optional and no order is required. It can appear at the beginning or end of a log macro argument list, but cannot appear among the formatting arguments. + +| Name | Type / Basic Syntax | Description | +|--------|---------------------------|-----------------------------------------------------------------------------------| +| logger | `Arc` or `Logger` | If specified, the given logger will be used instead of the global default logger. | +| kv | `{ key = value }` | Key-value pairs for structured logs. See documentation of module [`kv`] for more. | + +[`kv`]: crate::kv diff --git a/spdlog/src/include/doc/log-macro-nameed-opt-params.md b/spdlog/src/include/doc/log-macro-nameed-opt-params.md deleted file mode 100644 index d0046542..00000000 --- a/spdlog/src/include/doc/log-macro-nameed-opt-params.md +++ /dev/null @@ -1,5 +0,0 @@ -# Named optional parameters - -| Name | Type | Description | -|--------|---------------------------|-----------------------------------------------------------------------------------| -| logger | `Arc` or `Logger` | If specified, the given logger will be used instead of the global default logger. | diff --git a/spdlog/src/kv.rs b/spdlog/src/kv.rs new file mode 100644 index 00000000..c103df72 --- /dev/null +++ b/spdlog/src/kv.rs @@ -0,0 +1,396 @@ +//! Structured logging. +//! +//! Structured logging enhances traditional text-based log records with +//! user-defined attributes. Structured logs can be analyzed using a variety of +//! data processing techniques, without needing to find and parse attributes +//! from unstructured text first. +//! +//! [`Key`]s are strings and [`Value`]s are a datum of any type that can be +//! formatted or serialized. Simple types like strings, booleans, and numbers +//! are supported, as well as arbitrarily complex structures involving nested +//! objects and sequences. +//! +//! [`Value`] uses [_value-bag_ crate] as the backend, which is an alias of +//! [`value_bag::ValueBag`]. +//! +//! KVs will be passed into a [`Record`] to be processed by [`Formatter`]s via +//! [`Record::key_values`] method. +//! +//! ## Examples +//! +//! #### Basic syntax +//! +//! In logging macros, an optional named parameter `kv` (like `logger`) is used +//! to add key-values to a log. +//! +//! ``` +//! # use spdlog::prelude::*; +//! info!("program started", kv: { pid = std::process::id() }); +//! +//! # let telemetry = spdlog::default_logger(); +//! trace!(logger: telemetry, "user logged in", kv: { username = "John" }); +//! +//! let ip = "1.1.1.1"; +//! trace!("DNS setup", kv: { ip }); +//! // ^^ Shorthand syntax, equivalent to `ip = ip` +//! ``` +//! +//! #### Modifier +//! +//! A value is stored directly with its type by default (after erasure, of +//! course), using _modifier_ if you want it to be stored in another format. +//! +//! | Modifier | Description | +//! |----------|---------------------------------------------------------------------------------------| +//! | | No modifier, capture the value directly | +//! | `:` | Capture the value using [`Display`] trait | +//! | `:?` | Capture the value using [`Debug`] trait | +//! | `:sval` | Capture the value using [`sval::Value`] trait, crate feature `sval` is required | +//! | `:serde` | Capture the value using [`serde::Serialize`] trait, crate feature `serde` is required | +//! +//! ``` +//! # use spdlog::prelude::*; +//! # fn main() -> Result<(), Box> { +//! # struct Url; +//! # impl Url { fn parse(_: &str) -> Result> { Ok(Self) } } +//! # impl std::fmt::Display for Url { +//! # fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { +//! # write!(f, "") +//! # } +//! # } +//! let url = Url::parse("https://example.com")?; +//! trace!("user browsed website", kv: { url: }); +//! // ^ Capture the value using `Display` trait +//! // ^^^^ Shorthand syntax, equivalent to `url: = url` +//! +//! let orders = vec!["coffee", "pizza", "soup"]; +//! info!("order received", kv: { orders:? }); +//! // ^^ Capture the value using `Debug` trait +//! // ^^^^^^^^ Shorthand syntax, equivalent to `orders:? = orders` +//! +//! #[derive(sval_derive::Value)] +//! struct Point { x: f32, y: f32 } +//! +//! let pos = Point { x: 11.4, y: 5.14 }; +//! # #[cfg(feature = "sval")] +//! trace!("user clicked", kv: { pos:sval }); +//! // ^^^^^ Capture the value using `sval::Value` trait +//! // ^^^^^^^^ Shorthand syntax, equivalent to `pos:sval = pos` +//! # Ok(()) } +//! ``` +//! [_value-bag_ crate]: https://crates.io/crates/value-bag +//! [`Record`]: crate::Record +//! [`Formatter`]: crate::formatter::Formatter +//! [`Display`]: std::fmt::Display +//! [`Record::key_values`]: crate::Record::key_values +//! +//! [`sval::Value`]: https://docs.rs/sval/latest/sval/trait.Value.html +// TODO: This above link annotation is unnecessary, but Rustdoc has bug: +// https://github.com/rust-lang/cargo/issues/3475 +// Remove it when the bug is fixed. +use std::{borrow::Cow, fmt, slice}; + +use value_bag::{OwnedValueBag, ValueBag}; + +#[derive(Debug, Clone, PartialEq, Eq)] +pub(crate) enum KeyInner<'a> { + Str(&'a str), + StaticStr(&'static str), +} + +/// Represents a key in a key-value pair. +#[derive(Debug, Clone)] +pub struct Key<'a>(KeyInner<'a>); + +impl Key<'_> { + /// Gets the key string. + pub fn as_str(&self) -> &str { + match &self.0 { + KeyInner::Str(s) => s, + KeyInner::StaticStr(s) => s, + } + } +} + +impl<'a> Key<'a> { + #[doc(hidden)] + pub fn __from_static_str(key: &'static str) -> Self { + Key(KeyInner::StaticStr(key)) + } + + pub(crate) fn from_str(key: &'a str) -> Self { + Key(KeyInner::Str(key)) + } + + pub(crate) fn to_owned(&self) -> KeyOwned { + let inner = match self.0 { + KeyInner::Str(s) => KeyOwnedInner::CowStr(Cow::Owned(s.to_string())), + KeyInner::StaticStr(s) => KeyOwnedInner::CowStr(Cow::Borrowed(s)), + }; + KeyOwned(inner) + } + + #[cfg(test)] + pub(crate) fn inner(&self) -> KeyInner<'a> { + self.0.clone() + } +} + +impl PartialEq for Key<'_> { + fn eq(&self, other: &Self) -> bool { + self.as_str() == other.as_str() + } +} + +#[derive(Debug, Clone)] +enum KeyOwnedInner { + CowStr(Cow<'static, str>), +} + +#[derive(Debug, Clone)] +pub(crate) struct KeyOwned(KeyOwnedInner); + +impl KeyOwned { + pub(crate) fn as_ref(&self) -> Key { + let inner = match &self.0 { + KeyOwnedInner::CowStr(s) => match s { + Cow::Borrowed(s) => KeyInner::StaticStr(s), + Cow::Owned(s) => KeyInner::Str(s), + }, + }; + Key(inner) + } +} + +/// Represents a value in a key-value pair. +pub type Value<'a> = ValueBag<'a>; +pub(crate) type ValueOwned = OwnedValueBag; + +enum KeyValuesInner<'a> { + Borrowed(&'a [Pair<'a>]), + Owned(&'a [(KeyOwned, ValueOwned)]), +} +enum KeyValuesIterInner<'a> { + Borrowed(slice::Iter<'a, Pair<'a>>), + Owned(slice::Iter<'a, (KeyOwned, ValueOwned)>), +} + +/// Represents a collection of key-value pairs. +/// +/// ## Examples +/// +/// ``` +/// use std::fmt::Write; +/// use spdlog::{ +/// formatter::{Formatter, FormatterContext}, +/// Record, StringBuf, +/// }; +/// +/// #[derive(Clone)] +/// struct MyFormatter; +/// +/// impl Formatter for MyFormatter { +/// fn format( +/// &self, +/// record: &Record, +/// dest: &mut StringBuf, +/// ctx: &mut FormatterContext, +/// ) -> spdlog::Result<()> { +/// dest.write_str(record.payload()) +/// .map_err(spdlog::Error::FormatRecord)?; +/// for (key, value) in record.key_values() { +/// write!(dest, " {}={}", key.as_str(), value).map_err(spdlog::Error::FormatRecord)?; +/// } +/// Ok(()) +/// } +/// } +/// ``` +pub struct KeyValues<'a>(KeyValuesInner<'a>); + +impl<'a> KeyValues<'a> { + /// Gets the number of key-value pairs. + pub fn len(&self) -> usize { + match self.0 { + KeyValuesInner::Borrowed(p) => p.len(), + KeyValuesInner::Owned(p) => p.len(), + } + } + + /// Checks if there are no key-value pairs. + pub fn is_empty(&self) -> bool { + match self.0 { + KeyValuesInner::Borrowed(p) => p.is_empty(), + KeyValuesInner::Owned(p) => p.is_empty(), + } + } + + /// Gets the value of the specified key. + pub fn get(&self, key: Key) -> Option> { + match self.0 { + KeyValuesInner::Borrowed(p) => { + p.iter() + .find_map(|(k, v)| if k == &key { Some(v.clone()) } else { None }) + } + KeyValuesInner::Owned(p) => p.iter().find_map(|(k, v)| { + if k.as_ref() == key { + Some(v.by_ref()) + } else { + None + } + }), + } + } + + /// Gets an iterator over the key-value pairs. + pub fn iter(&self) -> KeyValuesIter<'a> { + match &self.0 { + KeyValuesInner::Borrowed(p) => KeyValuesIter(KeyValuesIterInner::Borrowed(p.iter())), + KeyValuesInner::Owned(p) => KeyValuesIter(KeyValuesIterInner::Owned(p.iter())), + } + } + + pub(crate) fn with_borrowed(pairs: &'a [Pair<'a>]) -> Self { + Self(KeyValuesInner::Borrowed(pairs)) + } + + pub(crate) fn with_owned(pairs: &'a [(KeyOwned, ValueOwned)]) -> Self { + Self(KeyValuesInner::Owned(pairs)) + } + + pub(crate) fn write_to(&self, dest: &mut impl fmt::Write, brackets: bool) -> fmt::Result { + let mut iter = self.iter(); + let first = iter.next(); + if let Some((key, value)) = first { + if brackets { + dest.write_str(" { ")?; + } + + // Reduce branch prediction misses for performance + // So we manually process the first KV pair + dest.write_str(key.as_str())?; + dest.write_str("=")?; + write!(dest, "{}", value)?; + + for (key, value) in iter { + dest.write_str(" ")?; + dest.write_str(key.as_str())?; + dest.write_str("=")?; + write!(dest, "{}", value)?; + } + + if brackets { + dest.write_str(" }")?; + } + } + Ok(()) + } +} + +impl<'a> IntoIterator for KeyValues<'a> { + type Item = Pair<'a>; + type IntoIter = KeyValuesIter<'a>; + + fn into_iter(self) -> Self::IntoIter { + self.iter() + } +} + +/// Represents an iterator over key-value pairs. +pub struct KeyValuesIter<'a>(KeyValuesIterInner<'a>); + +impl<'a> Iterator for KeyValuesIter<'a> { + type Item = Pair<'a>; + + fn next(&mut self) -> Option { + match &mut self.0 { + // The 2 clones should be cheap + KeyValuesIterInner::Borrowed(iter) => iter.next().map(|(k, v)| (k.clone(), v.clone())), + KeyValuesIterInner::Owned(iter) => iter.next().map(|(k, v)| (k.as_ref(), v.by_ref())), + } + } + + fn size_hint(&self) -> (usize, Option) { + match &self.0 { + KeyValuesIterInner::Borrowed(iter) => iter.size_hint(), + KeyValuesIterInner::Owned(iter) => iter.size_hint(), + } + } +} + +pub(crate) type Pair<'a> = (Key<'a>, Value<'a>); + +#[cfg(feature = "log")] +pub(crate) struct LogCrateConverter<'a>(Vec<(log::kv::Key<'a>, ValueOwned)>); + +#[cfg(feature = "log")] +impl<'a> LogCrateConverter<'a> { + pub(crate) fn new(capacity: usize) -> Self { + Self(Vec::with_capacity(capacity)) + } + + pub(crate) fn finalize(self) -> Vec<(log::kv::Key<'a>, ValueOwned)> { + self.0 + } +} + +#[cfg(feature = "log")] +impl<'a> log::kv::VisitSource<'a> for LogCrateConverter<'a> { + fn visit_pair( + &mut self, + key: log::kv::Key<'a>, + value: log::kv::Value<'a>, + ) -> Result<(), log::kv::Error> { + struct Visitor(Option); + + macro_rules! visit_fn { + ( $($fn:ident: $ty:ty => $from:ident),+$(,)? ) => { + $(fn $fn(&mut self, value: $ty) -> Result<(), log::kv::Error> { + self.0 = Some(Value::$from(value).to_owned()); + Ok(()) + })+ + }; + } + + impl log::kv::VisitValue<'_> for Visitor { + fn visit_any(&mut self, value: log::kv::Value) -> Result<(), log::kv::Error> { + // Since we have no way to extract the underlying `&dyn Display`, we have to + // `to_owned()` here + self.0 = Some(Value::from_display(&value).to_owned()); + Ok(()) + } + + fn visit_null(&mut self) -> Result<(), log::kv::Error> { + self.0 = Some(Value::empty().to_owned()); + Ok(()) + } + + visit_fn! { + visit_u64: u64 => from_u64, + visit_i64: i64 => from_i64, + visit_u128: u128 => from_u128, + visit_i128: i128 => from_i128, + visit_f64: f64 => from_f64, + visit_bool: bool => from_bool, + visit_str: &str => from_str, + visit_borrowed_str: &str => from_str, + visit_char: char => from_char, + } + } + + let mut visitor = Visitor(None); + value.visit(&mut visitor)?; + self.0.push((key, visitor.0.unwrap())); + Ok(()) + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn key_partial_eq() { + assert_eq!(Key::from_str("a"), Key::__from_static_str("a")); + assert_ne!(Key::from_str("a"), Key::__from_static_str("b")); + } +} diff --git a/spdlog/src/lib.rs b/spdlog/src/lib.rs index 486bc424..ec96bd39 100644 --- a/spdlog/src/lib.rs +++ b/spdlog/src/lib.rs @@ -16,10 +16,12 @@ //! - [Configured via environment variable](init_env_level) //! - [Compile-time and runtime pattern formatter] //! - [Asynchronous support] +//! - [Structured logging] //! - [Compatible with log crate](LogCrateProxy) //! //! [Compile-time and runtime pattern formatter]: formatter/index.html#compile-time-and-runtime-pattern-formatter //! [Asynchronous support]: crate::sink::AsyncPoolSink +//! [Structured logging]: crate::kv //! //! # Getting started //! @@ -218,7 +220,7 @@ //! - README.md //! --> //! -//! The current minimum supported Rust version is 1.60. +//! The current minimum supported Rust version is 1.61. //! //! `spdlog-rs` is built against the latest Rust stable release, it is not //! guaranteed to build on Rust versions earlier than the minimum supported @@ -278,9 +280,14 @@ #![cfg_attr(all(doc, CHANNEL_NIGHTLY), feature(doc_auto_cfg))] #![warn(missing_docs)] +// Used for referencing from proc-macros +// Credits: https://stackoverflow.com/a/57049687 +extern crate self as spdlog; + mod env_level; pub mod error; pub mod formatter; +pub mod kv; mod level; #[cfg(feature = "log")] mod log_crate_proxy; @@ -307,6 +314,8 @@ pub use log_crate_proxy::*; pub use logger::*; pub use record::*; pub use source_location::*; +#[doc(hidden)] +pub use spdlog_macros::normalize_forward as __normalize_forward; pub use string_buf::StringBuf; #[cfg(feature = "multi-thread")] pub use thread_pool::*; @@ -783,6 +792,7 @@ pub fn __log( logger: &Logger, level: Level, srcloc: Option, + kvs: &[(kv::Key, kv::Value)], fmt_args: fmt::Arguments, ) { // Use `Cow` to avoid allocation as much as we can @@ -790,7 +800,7 @@ pub fn __log( .as_str() .map(Cow::Borrowed) // No format arguments, so it is a `&'static str` .unwrap_or_else(|| Cow::Owned(fmt_args.to_string())); - let record = Record::new(level, payload, srcloc, logger.name()); + let record = Record::new(level, payload, srcloc, logger.name(), kvs); logger.log(&record); } diff --git a/spdlog/src/log_crate_proxy.rs b/spdlog/src/log_crate_proxy.rs index ab20f3d1..b0bccc14 100644 --- a/spdlog/src/log_crate_proxy.rs +++ b/spdlog/src/log_crate_proxy.rs @@ -1,6 +1,6 @@ use std::time::SystemTime; -use crate::{default_logger, sync::*, Logger, Record}; +use crate::{default_logger, sync::*, LogCrateRecord, Logger}; /// Proxy layer for compatible [log crate]. /// @@ -76,8 +76,8 @@ impl log::Log for LogCrateProxy { fn log(&self, record: &log::Record) { let logger = self.logger(); - let record = Record::from_log_crate_record(&logger, record, SystemTime::now()); - logger.log(&record) + let record = LogCrateRecord::new(&logger, record, SystemTime::now()); + logger.log(&record.as_record()) } fn flush(&self) { diff --git a/spdlog/src/log_macros.rs b/spdlog/src/log_macros.rs index 0ab0f070..a95ad75d 100644 --- a/spdlog/src/log_macros.rs +++ b/spdlog/src/log_macros.rs @@ -2,7 +2,7 @@ /// /// This macro will generically log with the specified [`Level`] and `format!` /// based argument list. -#[doc = include_str!("./include/doc/log-macro-nameed-opt-params.md")] +#[doc = include_str!("./include/doc/log-macro-named-opt-params.md")] /// # Examples /// /// ``` @@ -12,28 +12,35 @@ /// let data = (42, "Forty-two"); /// /// // Using the global default logger -/// log!(Level::Info, "Received data: {}, {}", data.0, data.1); +/// log!(Level::Info, "received data: {}, {}", data.0, data.1); /// -/// // Or using the specified logger -/// log!(logger: app_events, Level::Info, "Received data: {}, {}", data.0, data.1); +/// // Or using the specified logger, and structured logging +/// log!(logger: app_events, Level::Info, "received data", kv: { data:? }); /// ``` /// /// [`Level`]: crate::Level #[macro_export] macro_rules! log { - (logger: $logger:expr, $level:expr, $($arg:tt)+) => ({ + ($($input:tt)+) => { + $crate::__normalize_forward!(__log_impl => default[logger: $crate::default_logger(), kv: {}], $($input)+) + }; +} + +#[doc(hidden)] +#[macro_export] +macro_rules! __log_impl { + (logger: $logger:expr, kv: $kv:tt, $level:expr, $($arg:tt)+) => ({ let logger = &$logger; const LEVEL: $crate::Level = $level; const SHOULD_LOG: bool = $crate::STATIC_LEVEL_FILTER.__test_const(LEVEL); if SHOULD_LOG && logger.should_log(LEVEL) { - $crate::__log(logger, LEVEL, $crate::source_location_current!(), format_args!($($arg)+)); + $crate::__log(logger, LEVEL, $crate::source_location_current!(), $crate::__kv!($kv), format_args!($($arg)+)); } }); - ($level:expr, $($arg:tt)+) => ($crate::log!(logger: $crate::default_logger(), $level, $($arg)+)) } /// Logs a message at the critical level. -#[doc = include_str!("./include/doc/log-macro-nameed-opt-params.md")] +#[doc = include_str!("./include/doc/log-macro-named-opt-params.md")] /// # Examples /// /// ``` @@ -43,23 +50,20 @@ macro_rules! log { /// let (left, right) = (true, false); /// /// // Using the global default logger -/// critical!("Runtime assertion failed. Left: `{}`, Right: `{}`", left, right); +/// critical!("runtime assertion failed. Left: `{}`, Right: `{}`", left, right); /// -/// // Or using the specified logger -/// critical!(logger: app_events, "Runtime assertion failed. Left: `{}`, Right: `{}`", left, right); +/// // Or using the specified logger, and structured logging +/// critical!(logger: app_events, "runtime assertion failed.", kv: { left, right }); /// ``` #[macro_export] macro_rules! critical { - (logger: $logger:expr, $($arg:tt)+) => ( - $crate::log!(logger: $logger, $crate::Level::Critical, $($arg)+) - ); - ($($arg:tt)+) => ( - $crate::log!($crate::Level::Critical, $($arg)+) - ) + ($($input:tt)+) => { + $crate::__normalize_forward!(__log_impl => default[logger: $crate::default_logger(), kv: {}, $crate::Level::Critical], $($input)+) + }; } /// Logs a message at the error level. -#[doc = include_str!("./include/doc/log-macro-nameed-opt-params.md")] +#[doc = include_str!("./include/doc/log-macro-named-opt-params.md")] /// # Examples /// /// ``` @@ -69,23 +73,20 @@ macro_rules! critical { /// let (err_info, port) = ("No connection", 22); /// /// // Using the global default logger -/// error!("Error: {} on port {}", err_info, port); +/// error!("error: {} on port {}", err_info, port); /// -/// // Or using the specified logger -/// error!(logger: app_events, "App Error: {}, Port: {}", err_info, port); +/// // Or using the specified logger, and structured logging +/// error!(logger: app_events, "app error", kv: { reason = err_info, port }); /// ``` #[macro_export] macro_rules! error { - (logger: $logger:expr, $($arg:tt)+) => ( - $crate::log!(logger: $logger, $crate::Level::Error, $($arg)+) - ); - ($($arg:tt)+) => ( - $crate::log!($crate::Level::Error, $($arg)+) - ) + ($($input:tt)+) => { + $crate::__normalize_forward!(__log_impl => default[logger: $crate::default_logger(), kv: {}, $crate::Level::Error], $($input)+) + }; } /// Logs a message at the warn level. -#[doc = include_str!("./include/doc/log-macro-nameed-opt-params.md")] +#[doc = include_str!("./include/doc/log-macro-named-opt-params.md")] /// # Examples /// /// ``` @@ -95,23 +96,20 @@ macro_rules! error { /// let warn_description = "Invalid Input"; /// /// // Using the global default logger -/// warn!("Warning! {}!", warn_description); +/// warn!("warning! {}!", warn_description); /// -/// // Or using the specified logger -/// warn!(logger: input_events, "App received warning: {}", warn_description); +/// // Or using the specified logger, and structured logging +/// warn!(logger: input_events, "app received warning", kv: { reason = warn_description }); /// ``` #[macro_export] macro_rules! warn { - (logger: $logger:expr, $($arg:tt)+) => ( - $crate::log!(logger: $logger, $crate::Level::Warn, $($arg)+) - ); - ($($arg:tt)+) => ( - $crate::log!($crate::Level::Warn, $($arg)+) - ) + ($($input:tt)+) => { + $crate::__normalize_forward!(__log_impl => default[logger: $crate::default_logger(), kv: {}, $crate::Level::Warn], $($input)+) + }; } /// Logs a message at the info level. -#[doc = include_str!("./include/doc/log-macro-nameed-opt-params.md")] +#[doc = include_str!("./include/doc/log-macro-named-opt-params.md")] /// # Examples /// /// ``` @@ -122,23 +120,20 @@ macro_rules! warn { /// let conn_info = Connection { port: 40, speed: 3.20 }; /// /// // Using the global default logger -/// info!("Connected to port {} at {} Mb/s", conn_info.port, conn_info.speed); +/// info!("connected to port {} at {} Mb/s", conn_info.port, conn_info.speed); /// -/// // Or using the specified logger -/// info!(logger: conn_events, "Successfull connection, port: {}, speed: {}", conn_info.port, conn_info.speed); +/// // Or using the specified logger, and structured logging +/// info!(logger: conn_events, "successfull connection", kv: { port = conn_info.port, speed = conn_info.speed }); /// ``` #[macro_export] macro_rules! info { - (logger: $logger:expr, $($arg:tt)+) => ( - $crate::log!(logger: $logger, $crate::Level::Info, $($arg)+) - ); - ($($arg:tt)+) => ( - $crate::log!($crate::Level::Info, $($arg)+) - ) + ($($input:tt)+) => { + $crate::__normalize_forward!(__log_impl => default[logger: $crate::default_logger(), kv: {}, $crate::Level::Info], $($input)+) + }; } /// Logs a message at the debug level. -#[doc = include_str!("./include/doc/log-macro-nameed-opt-params.md")] +#[doc = include_str!("./include/doc/log-macro-named-opt-params.md")] /// # Examples /// /// ``` @@ -149,23 +144,20 @@ macro_rules! info { /// let pos = Position { x: 3.234, y: -1.223 }; /// /// // Using the global default logger -/// debug!("New position: x: {}, y: {}", pos.x, pos.y); +/// debug!("new position: x: {}, y: {}", pos.x, pos.y); /// -/// // Or using the specified logger -/// debug!(logger: app_events, "New position: x: {}, y: {}", pos.x, pos.y); +/// // Or using the specified logger, and structured logging +/// debug!(logger: app_events, "new position", kv: { x = pos.x, y = pos.y }); /// ``` #[macro_export] macro_rules! debug { - (logger: $logger:expr, $($arg:tt)+) => ( - $crate::log!(logger: $logger, $crate::Level::Debug, $($arg)+) - ); - ($($arg:tt)+) => ( - $crate::log!($crate::Level::Debug, $($arg)+) - ) + ($($input:tt)+) => { + $crate::__normalize_forward!(__log_impl => default[logger: $crate::default_logger(), kv: {}, $crate::Level::Debug], $($input)+) + }; } /// Logs a message at the trace level. -#[doc = include_str!("./include/doc/log-macro-nameed-opt-params.md")] +#[doc = include_str!("./include/doc/log-macro-named-opt-params.md")] /// # Examples /// /// ``` @@ -176,19 +168,268 @@ macro_rules! debug { /// let pos = Position { x: 3.234, y: -1.223 }; /// /// // Using the global default logger -/// trace!("Position is: x: {}, y: {}", pos.x, pos.y); +/// trace!("position is: x: {}, y: {}", pos.x, pos.y); /// -/// // Or using the specified logger -/// trace!(logger: app_events, "x is {} and y is {}", -/// if pos.x >= 0.0 { "positive" } else { "negative" }, -/// if pos.y >= 0.0 { "positive" } else { "negative" }); +/// // Or using the specified logger, and structured logging +/// trace!(logger: app_events, "position updated", kv: { x = pos.x, y = pos.y }); /// ``` #[macro_export] macro_rules! trace { - (logger: $logger:expr, $($arg:tt)+) => ( - $crate::log!(logger: $logger, $crate::Level::Trace, $($arg)+) - ); - ($($arg:tt)+) => ( - $crate::log!($crate::Level::Trace, $($arg)+) - ) + ($($input:tt)+) => { + $crate::__normalize_forward!(__log_impl => default[logger: $crate::default_logger(), kv: {}, $crate::Level::Trace], $($input)+) + }; +} + +#[doc(hidden)] +#[macro_export] +macro_rules! __kv { + ({}) => (&[]); + ({ $($ttm:tt)+ }) => { + $crate::__kv!(@{} $($ttm)+) + }; + + (@{$($done:tt)*} $k:ident $(= $v:expr)? $(,$($rest:tt)*)?) => ($crate::__kv!(@{$($done)* $k [ ] $(= $v)?,} $($($rest)*)?)); + (@{$($done:tt)*} $k:ident : $(= $v:expr)? $(,$($rest:tt)*)?) => ($crate::__kv!(@{$($done)* $k [: ] $(= $v)?,} $($($rest)*)?)); + (@{$($done:tt)*} $k:ident :? $(= $v:expr)? $(,$($rest:tt)*)?) => ($crate::__kv!(@{$($done)* $k [:?] $(= $v)?,} $($($rest)*)?)); + (@{$($done:tt)*} $k:ident :sval $(= $v:expr)? $(,$($rest:tt)*)?) => ($crate::__kv!(@{$($done)* $k [:sval] $(= $v)?,} $($($rest)*)?)); + (@{$($done:tt)*} $k:ident :serde $(= $v:expr)? $(,$($rest:tt)*)?) => ($crate::__kv!(@{$($done)* $k [:serde] $(= $v)?,} $($($rest)*)?)); + (@{$( $k:ident [$($modifier:tt)*] $(= $v:expr)? ),+ $(,)?}) => { + &[$(($crate::kv::Key::__from_static_str(stringify!($k)), $crate::__kv_value!($k [$($modifier)*] $(= $v)?))),+] + }; +} + +#[doc(hidden)] +#[macro_export] +macro_rules! __kv_value { + ($k:ident [$($modifier:tt)*]) => { $crate::__kv_value!($k [$($modifier)*] = $k) }; + ($k:ident [ ] = $v:expr) => { $crate::kv::Value::from(&$v) }; + ($k:ident [: ] = $v:expr) => { $crate::kv::Value::capture_display(&$v) }; + ($k:ident [:?] = $v:expr) => { $crate::kv::Value::capture_debug(&$v) }; + ($k:ident [:sval] = $v:expr) => { $crate::kv::Value::capture_sval2(&$v) }; + ($k:ident [:serde] = $v:expr) => { $crate::kv::Value::capture_serde1(&$v) }; +} + +#[cfg(test)] +mod tests { + use std::{ + fmt::{self, Debug, Display}, + sync::Arc, + vec, + }; + + use crate::{ + formatter::Formatter, + kv::{Key, KeyInner}, + prelude::*, + sink::Sink, + test_utils::{self, *}, + ErrorHandler, Record, + }; + + #[test] + fn syntax_and_records() { + let test_sink = Arc::new(TestSink::new()); + let test = Arc::new(build_test_logger(|b| { + b.sink(test_sink.clone()).level_filter(LevelFilter::All) + })); + + struct Mods; + impl Debug for Mods { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "debug") + } + } + impl Display for Mods { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "display") + } + } + let (int, mod1, mod2) = (114514, Mods, Mods); + + const LEVEL_ARG: Level = Level::Info; + + let assert_records = |kv: &[(&'static str, &str)], payload| { + let records = test_sink.records(); + assert_eq!(records.len(), Level::count() + 1); + test_sink.clear(); + + records + .into_iter() + .zip([ + LEVEL_ARG, + Level::Trace, + Level::Debug, + Level::Info, + Level::Warn, + Level::Error, + Level::Critical, + ]) + .for_each(|(record, expected_level)| { + assert_eq!(record.level(), expected_level); + assert_eq!( + record + .key_values() + .into_iter() + .map(|(k, v)| (k.inner(), v.to_string())) + .collect::>(), + kv.iter() + .map(|(k, v)| (KeyInner::StaticStr(k), v.to_string())) + .collect::>() + ); + assert_eq!(record.payload(), payload); + }); + }; + + log!(logger: test, LEVEL_ARG, "logger param only"); + trace!(logger: test, "logger param only"); + debug!(logger: test, "logger param only"); + info!(logger: test, "logger param only"); + warn!(logger: test, "logger param only"); + error!(logger: test, "logger param only"); + critical!(logger: test, "logger param only"); + assert_records(&[], "logger param only"); + + log!(logger: test, kv: {}, LEVEL_ARG, "empty kv param"); + trace!(logger: test, kv: {}, "empty kv param"); + debug!(logger: test, kv: {}, "empty kv param"); + info!(logger: test, kv: {}, "empty kv param"); + warn!(logger: test, kv: {}, "empty kv param"); + error!(logger: test, kv: {}, "empty kv param"); + critical!(logger: test, kv: {}, "empty kv param"); + assert_records(&[], "empty kv param"); + + log!(logger: test, kv: { int = 114514 }, LEVEL_ARG, "kv capture value directly"); + trace!(logger: test, kv: { int = 114514 }, "kv capture value directly"); + debug!(logger: test, kv: { int = 114514 }, "kv capture value directly"); + info!(logger: test, kv: { int = 114514 }, "kv capture value directly"); + warn!(logger: test, kv: { int = 114514 }, "kv capture value directly"); + error!(logger: test, kv: { int = 114514 }, "kv capture value directly"); + critical!(logger: test, kv: { int = 114514 }, "kv capture value directly"); + assert_records(&[("int", "114514")], "kv capture value directly"); + + log!(logger: test, kv: { int = 114514, mod1: = Mods, mod2:? = Mods }, LEVEL_ARG, "kv capture value using modifiers"); + trace!(logger: test, kv: { int = 114514, mod1: = Mods, mod2:? = Mods }, "kv capture value using modifiers"); + debug!(logger: test, kv: { int = 114514, mod1: = Mods, mod2:? = Mods }, "kv capture value using modifiers"); + info!(logger: test, kv: { int = 114514, mod1: = Mods, mod2:? = Mods }, "kv capture value using modifiers"); + warn!(logger: test, kv: { int = 114514, mod1: = Mods, mod2:? = Mods }, "kv capture value using modifiers"); + error!(logger: test, kv: { int = 114514, mod1: = Mods, mod2:? = Mods }, "kv capture value using modifiers"); + critical!(logger: test, kv: { int = 114514, mod1: = Mods, mod2:? = Mods }, "kv capture value using modifiers"); + assert_records( + &[("int", "114514"), ("mod1", "display"), ("mod2", "debug")], + "kv capture value using modifiers", + ); + + log!(logger: test, kv: { int }, LEVEL_ARG, "kv shorthand"); + trace!(logger: test, kv: { int }, "kv shorthand"); + debug!(logger: test, kv: { int }, "kv shorthand"); + info!(logger: test, kv: { int }, "kv shorthand"); + warn!(logger: test, kv: { int }, "kv shorthand"); + error!(logger: test, kv: { int }, "kv shorthand"); + critical!(logger: test, kv: { int }, "kv shorthand"); + assert_records(&[("int", "114514")], "kv shorthand"); + + log!(logger: test, kv: { int, mod1:, mod2:? }, LEVEL_ARG, "kv shorthand modifiers"); + trace!(logger: test, kv: { int, mod1:, mod2:? }, "kv shorthand modifiers"); + debug!(logger: test, kv: { int, mod1:, mod2:? }, "kv shorthand modifiers"); + info!(logger: test, kv: { int, mod1:, mod2:? }, "kv shorthand modifiers"); + warn!(logger: test, kv: { int, mod1:, mod2:? }, "kv shorthand modifiers"); + error!(logger: test, kv: { int, mod1:, mod2:? }, "kv shorthand modifiers"); + critical!(logger: test, kv: { int, mod1:, mod2:? }, "kv shorthand modifiers"); + assert_records( + &[("int", "114514"), ("mod1", "display"), ("mod2", "debug")], + "kv shorthand modifiers", + ); + + log!(logger: test, LEVEL_ARG, "params arbitrary order: logger, format, kv", kv: { mod1: }); + trace!(logger: test, "params arbitrary order: logger, format, kv", kv: { mod1: }); + debug!(logger: test, "params arbitrary order: logger, format, kv", kv: { mod1: }); + info!(logger: test, "params arbitrary order: logger, format, kv", kv: { mod1: }); + warn!(logger: test, "params arbitrary order: logger, format, kv", kv: { mod1: }); + error!(logger: test, "params arbitrary order: logger, format, kv", kv: { mod1: }); + critical!(logger: test, "params arbitrary order: logger, format, kv", kv: { mod1: }); + assert_records( + &[("mod1", "display")], + "params arbitrary order: logger, format, kv", + ); + + log!(LEVEL_ARG, "params arbitrary order = format, kv, logger", kv: { mod1:? }, logger: test); + trace!("params arbitrary order = format, kv, logger", kv: { mod1:? }, logger: test); + debug!("params arbitrary order = format, kv, logger", kv: { mod1:? }, logger: test); + info!("params arbitrary order = format, kv, logger", kv: { mod1:? }, logger: test); + warn!("params arbitrary order = format, kv, logger", kv: { mod1:? }, logger: test); + error!("params arbitrary order = format, kv, logger", kv: { mod1:? }, logger: test); + critical!("params arbitrary order = format, kv, logger", kv: { mod1:? }, logger: test); + assert_records( + &[("mod1", "debug")], + "params arbitrary order = format, kv, logger", + ); + } + + #[test] + fn kv_types() { + struct Asserter; + + impl Sink for Asserter { + fn should_log(&self, _: Level) -> bool { + true + } + fn flush(&self) -> crate::Result<()> { + Ok(()) + } + fn level_filter(&self) -> LevelFilter { + LevelFilter::All + } + fn set_level_filter(&self, _: LevelFilter) { + unimplemented!() + } + fn set_formatter(&self, _: Box) { + unimplemented!() + } + fn set_error_handler(&self, _: Option) { + unimplemented!() + } + + fn log(&self, record: &Record) -> crate::Result<()> { + let kvs = record.key_values(); + let value = kvs.get(Key::from_str("v")).unwrap(); + assert_eq!(kvs.len(), 1); + + match record.payload() { + "1" => assert!(value.to_i64().is_some()), + "2" => assert!(value.to_str().is_some()), + "3" => assert!(value.to_i64().is_some()), + "4" => assert!(value.to_i64().is_some()), + "5" => assert!(value.is::>()), + "6" => assert!(value.is::()), + "7" => assert!(value.is::()), + _ => panic!(), + } + Ok(()) + } + } + + let asserter = test_utils::build_test_logger(|b| b.sink(Arc::new(Asserter))); + + #[cfg_attr(feature = "sval", derive(sval_derive::Value))] + #[cfg_attr(feature = "serde", derive(serde::Serialize))] + struct Data { + i: i32, + v: Vec, + } + let data = Data { + i: 1, + v: vec![1, 2], + }; + + info!(logger: asserter, "1", kv: { v = 1 }); + info!(logger: asserter, "2", kv: { v = "string" }); + info!(logger: asserter, "3", kv: { v: = 1 }); + info!(logger: asserter, "4", kv: { v:? = 1 }); + #[cfg(feature = "sval")] + info!(logger: asserter, "5", kv: { v:sval = vec![1, 2] }); + #[cfg(feature = "sval")] + info!(logger: asserter, "6", kv: { v:sval = data }); + #[cfg(feature = "serde")] + info!(logger: asserter, "7", kv: { v:serde = data }); + } } diff --git a/spdlog/src/record.rs b/spdlog/src/record.rs index 36e7dc9a..ac07a946 100644 --- a/spdlog/src/record.rs +++ b/spdlog/src/record.rs @@ -4,7 +4,7 @@ use std::{ time::SystemTime, }; -use crate::{Level, SourceLocation}; +use crate::{kv, Level, SourceLocation}; /// Represents a log record. /// @@ -22,8 +22,9 @@ use crate::{Level, SourceLocation}; // possible to correct. #[derive(Clone, Debug)] pub struct Record<'a> { - logger_name: Option>, + logger_name: Option<&'a str>, payload: Cow<'a, str>, + kvs: Cow<'a, [kv::Pair<'a>]>, inner: Cow<'a, RecordInner>, } @@ -42,10 +43,12 @@ impl<'a> Record<'a> { payload: impl Into>, srcloc: Option, logger_name: Option<&'a str>, + kvs: &'a [(kv::Key<'a>, kv::Value<'a>)], ) -> Record<'a> { Record { - logger_name: logger_name.map(Cow::Borrowed), + logger_name, payload: payload.into(), + kvs: Cow::Borrowed(kvs), inner: Cow::Owned(RecordInner { level, source_location: srcloc, @@ -59,8 +62,13 @@ impl<'a> Record<'a> { #[must_use] pub fn to_owned(&self) -> RecordOwned { RecordOwned { - logger_name: self.logger_name.clone().map(|n| n.into_owned()), + logger_name: self.logger_name.map(|n| n.to_owned()), payload: self.payload.to_string(), + kvs: self + .kvs + .iter() + .map(|(k, v)| (k.to_owned(), v.to_owned())) + .collect(), inner: self.inner.clone().into_owned(), } } @@ -68,7 +76,7 @@ impl<'a> Record<'a> { /// Gets the logger name. #[must_use] pub fn logger_name(&self) -> Option<&str> { - self.logger_name.as_ref().map(|n| n.as_ref()) + self.logger_name } /// Gets the level. @@ -101,52 +109,24 @@ impl<'a> Record<'a> { self.inner.tid } + /// Gets the key-values. + #[must_use] + pub fn key_values(&self) -> kv::KeyValues { + kv::KeyValues::with_borrowed(&self.kvs) + } + // When adding more getters, also add to `RecordOwned` #[must_use] pub(crate) fn replace_payload(&'a self, new: impl Into>) -> Self { Self { - logger_name: self.logger_name.clone(), + logger_name: self.logger_name, payload: new.into(), + kvs: self.kvs.clone(), inner: Cow::Borrowed(&self.inner), } } - #[cfg(feature = "log")] - #[must_use] - pub(crate) fn from_log_crate_record( - logger: &'a crate::Logger, - record: &log::Record, - time: SystemTime, - ) -> Self { - let args = record.args(); - - Self { - // If the logger has a name configured, use that name. Otherwise, the name can also be - // given by the target of the log record. - logger_name: logger.name().map(Cow::Borrowed).or_else(|| { - let log_target = record.target(); - if log_target.is_empty() { - None - } else { - Some(Cow::Owned(String::from(log_target))) - } - }), - payload: match args.as_str() { - Some(literal_str) => literal_str.into(), - None => args.to_string().into(), - }, - inner: Cow::Owned(RecordInner { - level: record.level().into(), - source_location: SourceLocation::from_log_crate_record(record), - time, - // For records from `log` crate, they never seem to come from different threads, so - // getting the current TID here should be correct - tid: get_current_tid(), - }), - } - } - #[cfg(test)] pub(crate) fn set_time(&mut self, new: SystemTime) { self.inner.to_mut().time = new; @@ -160,6 +140,7 @@ impl<'a> Record<'a> { pub struct RecordOwned { logger_name: Option, payload: String, + kvs: Vec<(kv::KeyOwned, kv::ValueOwned)>, inner: RecordInner, } @@ -168,8 +149,14 @@ impl RecordOwned { #[must_use] pub fn as_ref(&self) -> Record { Record { - logger_name: self.logger_name.as_deref().map(Cow::Borrowed), + logger_name: self.logger_name.as_deref(), payload: Cow::Borrowed(&self.payload), + kvs: Cow::Owned( + self.kvs + .iter() + .map(|(k, v)| (k.as_ref(), v.by_ref())) + .collect::>(), + ), inner: Cow::Borrowed(&self.inner), } } @@ -210,9 +197,74 @@ impl RecordOwned { self.inner.tid } + /// Gets the key-values. + #[must_use] + pub fn key_values(&self) -> kv::KeyValues { + kv::KeyValues::with_owned(&self.kvs) + } + // When adding more getters, also add to `Record` } +#[cfg(feature = "log")] +#[derive(Clone, Debug)] +pub(crate) struct LogCrateRecord<'a> { + logger_name: Option<&'a str>, + payload: Cow<'a, str>, + kvs: Vec<(log::kv::Key<'a>, kv::ValueOwned)>, + inner: Cow<'a, RecordInner>, +} + +#[cfg(feature = "log")] +impl<'a> LogCrateRecord<'a> { + #[must_use] + pub(crate) fn new( + logger: &'a crate::Logger, + record: &'a log::Record, + time: SystemTime, + ) -> Self { + let args = record.args(); + + Self { + // If the logger has a name configured, use that name. Otherwise, the name can also be + // given by the target of the log record. + logger_name: logger.name().or_else(|| Some(record.target())), + kvs: { + let kvs = record.key_values(); + let mut cvt = kv::LogCrateConverter::new(kvs.count()); + assert!(kvs.visit(&mut cvt).is_ok()); + cvt.finalize() + }, + payload: match args.as_str() { + Some(literal_str) => literal_str.into(), + None => args.to_string().into(), + }, + inner: Cow::Owned(RecordInner { + level: record.level().into(), + source_location: SourceLocation::from_log_crate_record(record), + time, + // For records from `log` crate, they never seem to come from different threads, so + // getting the current TID here should be correct + tid: get_current_tid(), + }), + } + } + + #[must_use] + pub(crate) fn as_record(&self) -> Record { + Record { + logger_name: self.logger_name, + payload: self.payload.clone(), + kvs: self + .kvs + .iter() + .map(|(k, v)| (kv::Key::from_str(k.as_str()), v.by_ref())) + .collect(), + inner: self.inner.clone(), + } + } +} + fn get_current_tid() -> u64 { #[cfg(target_os = "linux")] #[must_use] diff --git a/spdlog/src/sink/rotating_file_sink.rs b/spdlog/src/sink/rotating_file_sink.rs index ea7dc015..7a6f7d24 100644 --- a/spdlog/src/sink/rotating_file_sink.rs +++ b/spdlog/src/sink/rotating_file_sink.rs @@ -1220,7 +1220,7 @@ mod tests { { let logger = build(true); - let mut record = Record::new(Level::Info, "test log message", None, None); + let mut record = Record::new(Level::Info, "test log message", None, None, &[]); let initial_time = record.time(); assert_files_count("hourly", 1); @@ -1279,7 +1279,7 @@ mod tests { }; { - let mut record = Record::new(Level::Info, "test log message", None, None); + let mut record = Record::new(Level::Info, "test log message", None, None, &[]); assert_files_count(prefix, 1); diff --git a/spdlog/src/test_utils/common.rs b/spdlog/src/test_utils/common.rs index c0ae26d0..e9478f78 100644 --- a/spdlog/src/test_utils/common.rs +++ b/spdlog/src/test_utils/common.rs @@ -64,6 +64,10 @@ impl TestSink { self.records.lock().unwrap().clone() } + pub fn clear(&self) { + self.records.lock().unwrap().clear(); + } + #[must_use] pub fn payloads(&self) -> Vec { self.records diff --git a/spdlog/tests/compile_fail.rs b/spdlog/tests/compile_fail.rs index 17c691e4..17c5204e 100644 --- a/spdlog/tests/compile_fail.rs +++ b/spdlog/tests/compile_fail.rs @@ -2,6 +2,7 @@ fn compile_fail() { let t = trybuild::TestCases::new(); + t.compile_fail("tests/compile_fail/logging_macro_*.rs"); t.compile_fail("tests/compile_fail/pattern_macro_*.rs"); #[cfg(feature = "runtime-pattern")] t.compile_fail("tests/compile_fail/pattern_runtime_macro_*.rs"); diff --git a/spdlog/tests/compile_fail/logging_macro_syntax.rs b/spdlog/tests/compile_fail/logging_macro_syntax.rs new file mode 100644 index 00000000..81f0c0b7 --- /dev/null +++ b/spdlog/tests/compile_fail/logging_macro_syntax.rs @@ -0,0 +1,11 @@ +use spdlog::prelude::*; + +fn optional_args() { + let logger = spdlog::default_logger(); + + log!(unknown: 1, Level::Info, "unknown optional arg"); + log!(Level::Info, logger: logger, "optional arg in the middle"); + log!(logger: logger, Level::Info, "duplicate optional args", logger: logger); +} + +fn main() {} diff --git a/spdlog/tests/compile_fail/logging_macro_syntax.stderr b/spdlog/tests/compile_fail/logging_macro_syntax.stderr new file mode 100644 index 00000000..e1ddaa62 --- /dev/null +++ b/spdlog/tests/compile_fail/logging_macro_syntax.stderr @@ -0,0 +1,17 @@ +error: unknown optional parameter 'unknown' + --> tests/compile_fail/logging_macro_syntax.rs:6:10 + | +6 | log!(unknown: 1, Level::Info, "unknown optional arg"); + | ^^^^^^^ + +error: optional arguments cannot occur in the middle of regular arguments + --> tests/compile_fail/logging_macro_syntax.rs:7:23 + | +7 | log!(Level::Info, logger: logger, "optional arg in the middle"); + | ^^^^^^ + +error: found duplicate optional argument 'logger' + --> tests/compile_fail/logging_macro_syntax.rs:8:66 + | +8 | log!(logger: logger, Level::Info, "duplicate optional args", logger: logger); + | ^^^^^^ diff --git a/spdlog/tests/log_crate_proxy.rs b/spdlog/tests/log_crate_proxy.rs index a6659651..cac89f8e 100644 --- a/spdlog/tests/log_crate_proxy.rs +++ b/spdlog/tests/log_crate_proxy.rs @@ -49,3 +49,22 @@ fn test_target() { log::info!(target: "MyLogger", "body"); assert_eq!(sink.clone_string(), format!("[MyLogger] body{__EOL}")); } + +#[cfg(feature = "log")] +#[test] +fn test_kv() { + let formatter = Box::new(PatternFormatter::new(pattern!("{payload} {{ {kv} }}{eol}"))); + let sink = Arc::new(StringSink::with(|b| b.formatter(formatter))); + let logger = Arc::new(build_test_logger(|b| b.sink(sink.clone()))); + + let _guard = GLOBAL_LOG_CRATE_PROXY_MUTEX.lock().unwrap(); + spdlog::init_log_crate_proxy().ok(); + spdlog::log_crate_proxy().set_logger(Some(logger)); + log::set_max_level(log::LevelFilter::Trace); + + log::info!(key1 = 42, key2 = true; "a {} event", "log"); + assert_eq!( + sink.clone_string(), + format!("a log event {{ key1=42 key2=true }}{__EOL}") + ); +} diff --git a/spdlog/tests/pattern.rs b/spdlog/tests/pattern.rs index 301a4ad9..c4064f35 100644 --- a/spdlog/tests/pattern.rs +++ b/spdlog/tests/pattern.rs @@ -212,7 +212,7 @@ fn test_builtin_patterns() { .build() .unwrap(); - info!(logger: logger, "test payload"); + info!(logger: logger, kv: { a=true, b="text" }, "test payload"); sink.clone_string() } @@ -416,7 +416,7 @@ fn test_builtin_patterns() { if #[cfg(feature = "source-location")] { check!( "{full}", - Some([format!("[0000-00-00 00:00:00.000] [logger-name] [info] [pattern, {}:000] test payload", file!())]), + Some([format!("[0000-00-00 00:00:00.000] [logger-name] [info] [pattern, {}:000] test payload {{ a=true b=text }}", file!())]), vec![ YEAR_RANGE, MONTH_RANGE, @@ -431,7 +431,7 @@ fn test_builtin_patterns() { } else { check!( "{full}", - Some(["[0000-00-00 00:00:00.000] [logger-name] [info] test payload"]), + Some(["[0000-00-00 00:00:00.000] [logger-name] [info] test payload { a=true b=text }"]), vec![ YEAR_RANGE, MONTH_RANGE, @@ -466,6 +466,7 @@ fn test_builtin_patterns() { } check!("{logger}", Some(["logger-name"]), vec![]); check!("{payload}", Some(["test payload"]), vec![]); + check!("{kv}", Some(["a=true b=text"]), vec![]); check!("{pid}", None as Option>, vec![OS_ID_RANGE]); check!("{tid}", None as Option>, vec![OS_ID_RANGE]); check!("{eol}", Some(["{eol}"]), vec![]);