From b8dc102c7f4234baffd7dfc7e0e6430a1f2ae104 Mon Sep 17 00:00:00 2001 From: Yoshua Wuyts Date: Sat, 10 Aug 2019 03:17:54 +0200 Subject: [PATCH] add kv-logging to async-log Signed-off-by: Yoshua Wuyts --- Cargo.toml | 6 +++--- README.md | 5 +---- examples/trace.rs | 13 +++++------- src/lib.rs | 53 +++++++++++++++++++++++++++++++++++++++++------ src/logger.rs | 34 +++++++++++++++++++++++------- 5 files changed, 82 insertions(+), 29 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index c7e018d..9f5eae8 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -12,12 +12,12 @@ readme = "README.md" edition = "2018" [dependencies] -log = { version = "0.4.6", features = ["std"] } -backtrace = "0.3.32" +log = { version = "0.4.8", features = ["std", "kv_unstable"] } +backtrace = "0.3.34" async-log-attributes = { path = "async-log-attributes", version = "1.0.1" } [dev-dependencies] -env_logger = "0.6.1" +femme = "1.2.0" [workspace] members = [ diff --git a/README.md b/README.md index 630d4e0..3615091 100644 --- a/README.md +++ b/README.md @@ -89,10 +89,7 @@ use async_log::span; use log::info; fn setup_logger() { - let logger = env_logger::Builder::new() - .filter(None, log::LevelFilter::Trace) - .build(); - + let logger = femme::pretty::Logger::new(); async_log::Logger::wrap(logger, || 12) .start(log::LevelFilter::Trace) .unwrap(); diff --git a/examples/trace.rs b/examples/trace.rs index f952519..e829ba3 100644 --- a/examples/trace.rs +++ b/examples/trace.rs @@ -2,10 +2,7 @@ use async_log::{instrument, span}; use log::info; fn setup_logger() { - let logger = env_logger::Builder::new() - .filter(None, log::LevelFilter::Trace) - .build(); - + let logger = femme::pretty::Logger::new(); async_log::Logger::wrap(logger, || /* get the task id here */ 0) .start(log::LevelFilter::Trace) .unwrap(); @@ -14,11 +11,11 @@ fn setup_logger() { fn main() { setup_logger(); - span!("new level, depth={}", 1, { + span!("level {}", 1, { let x = "beep"; - info!("look at this value, x={}", x); + info!("look at this value: {}", x); - span!("new level, depth={}", 2, { + span!("level {}", 2, { inner("boop"); }) }) @@ -26,5 +23,5 @@ fn main() { #[instrument] fn inner(y: &str) { - info!("another nice value, y={}", y); + info!("another nice value: {}", y); } diff --git a/src/lib.rs b/src/lib.rs index afdd469..4c473ba 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -82,10 +82,7 @@ //! use log::info; //! //! fn setup_logger() { -//! let logger = env_logger::Builder::new() -//! .filter(None, log::LevelFilter::Trace) -//! .build(); -//! +//! let logger = femme::pretty::Logger::new(); //! async_log::Logger::wrap(logger, || 12) //! .start(log::LevelFilter::Trace) //! .unwrap(); @@ -113,6 +110,8 @@ pub use async_log_attributes::instrument; +use std::fmt::Arguments; + mod backtrace; mod logger; mod macros; @@ -137,7 +136,18 @@ impl Span { /// You should generally prefer to call `span!` instead of constructing this manually. pub fn new(args: impl AsRef) -> Self { let args = args.as_ref(); - log::trace!("{}, span_mark=start", args); + struct KeyValues; + impl log::kv::Source for KeyValues { + fn visit<'kvs>( + &'kvs self, + visitor: &mut dyn log::kv::Visitor<'kvs>, + ) -> Result<(), log::kv::Error> { + visitor.visit_pair("span_mark".into(), "start".into())?; + Ok(()) + } + } + + print(log::Level::Trace, format_args!("{}", args), KeyValues {}); Self { args: args.to_owned(), } @@ -146,6 +156,37 @@ impl Span { impl Drop for Span { fn drop(&mut self) { - log::trace!("{}, span_mark=end", self.args); + struct KeyValues; + impl log::kv::Source for KeyValues { + fn visit<'kvs>( + &'kvs self, + visitor: &mut dyn log::kv::Visitor<'kvs>, + ) -> Result<(), log::kv::Error> { + visitor.visit_pair("span_mark".into(), "end".into())?; + Ok(()) + } + } + + print( + log::Level::Trace, + format_args!("{}", self.args), + KeyValues {}, + ); + } +} + +fn print(level: log::Level, msg: Arguments<'_>, key_values: impl log::kv::Source) { + if level <= log::STATIC_MAX_LEVEL && level <= log::max_level() { + log::logger().log( + &log::Record::builder() + .args(msg) + .key_values(&key_values) + .level(level) + .target(module_path!()) + .module_path(Some(module_path!())) + .file(Some(file!())) + .line(Some(line!())) + .build(), + ); } } diff --git a/src/logger.rs b/src/logger.rs index 5d155d2..66962b9 100644 --- a/src/logger.rs +++ b/src/logger.rs @@ -52,11 +52,11 @@ where } /// Get the thread id. Useful because ThreadId doesn't implement Display. -fn thread_id() -> String { +fn thread_id() -> u64 { let mut string = format!("{:?}", thread::current().id()); string.replace_range(0..9, ""); string.pop(); - string + string.parse().unwrap() } impl log::Log for Logger @@ -69,12 +69,14 @@ where fn log(&self, record: &Record<'_>) { if self.enabled(record.metadata()) { - let curr_id = self.with(); let depth = self.compute_stack_depth(&record); let symbol = async_log_capture_caller(depth); - let thread_id = format!(", thread_id={}", thread_id()); - let task_id = format!(", task_id={}", curr_id); + let key_values = KeyValues { + thread_id: thread_id(), + task_id: self.with(), + kvs: record.key_values(), + }; let (line, filename, fn_name) = if self.backtrace { match symbol { @@ -107,15 +109,14 @@ where self.logger.log( &log::Record::builder() .args(format_args!( - "{}{}{}{}{}{}", + "{}{}{}{}", record.args(), filename, line, fn_name, - task_id, - thread_id )) .metadata(record.metadata().clone()) + .key_values(&key_values) .level(record.level()) .target(record.target()) .module_path(record.module_path()) @@ -127,3 +128,20 @@ where } fn flush(&self) {} } + +struct KeyValues<'a> { + thread_id: u64, + task_id: u64, + kvs: &'a dyn log::kv::Source, +} +impl<'a> log::kv::Source for KeyValues<'a> { + fn visit<'kvs>( + &'kvs self, + visitor: &mut dyn log::kv::Visitor<'kvs>, + ) -> Result<(), log::kv::Error> { + self.kvs.visit(visitor)?; + visitor.visit_pair("thread_id".into(), self.thread_id.into())?; + visitor.visit_pair("task_id".into(), self.task_id.into())?; + Ok(()) + } +}