add kv-logging to async-log (#5)

Signed-off-by: Yoshua Wuyts <[email protected]>

Author: yoshuawuyts

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 = [

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();

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,17 +11,17 @@ 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");
         })
     })
 }
 
 #[instrument]
 fn inner(y: &str) {
-    info!("another nice value, y={}", y);
+    info!("another nice value: {}", y);
 }

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<str>) -> 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(),
+        );
     }
 }

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<L: Log, F> log::Log for Logger<L, F>
@@ -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(())
+    }
+}