Add support for kv feature (#69)

- Write structured data in `extra` argument
- Set new minimal version for log crate

Author: benruijl

Cargo.toml

@@ -14,14 +14,20 @@ rust-version = "1.74"
 
 # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
 
+[features]
+kv = ["log/kv"]
+
 [dependencies]
 arc-swap = "~1"
 # It's OK to ask for std on log, because pyo3 needs it too.
-log = { version = "~0.4.4", default-features = false, features = ["std"] }
+log = { version = "~0.4.21", default-features = false, features = ["std"] }
 pyo3 = { version = "0.26", default-features = false }
 
 [dev-dependencies]
-pyo3 = { version = "0.26", default-features = false, features = ["auto-initialize", "macros"] }
+pyo3 = { version = "0.26", default-features = false, features = [
+    "auto-initialize",
+    "macros",
+] }
 
 # `pyo3-macros` is lying about the minimal version for its `syn` dependency.
 # Because we're testing with `-Zminimal-versions`, we need to explicitly set it here.

examples/hello_world/Cargo.lock

@@ -11,6 +11,6 @@ name = "hello_world"
 crate-type = ["cdylib"]
 
 [dependencies]
-log = "~0.4"
+log = { version = "~0.4", features = ["kv"] }
 pyo3 = { version = "~0.26", features = ["extension-module"] }
-pyo3-log = { path = "../.." }
+pyo3-log = { path = "../..", features = ["kv"] }

examples/hello_world/Cargo.toml

@@ -3,8 +3,24 @@
 import logging
 import hello_world
 
-FORMAT = '%(levelname)s %(name)s %(asctime)-15s %(filename)s:%(lineno)d %(message)s'
-logging.basicConfig(format=FORMAT)
-logging.getLogger().setLevel(logging.INFO)
-logging.info("Test 1")
+
+class ExtraInfoFormatter(logging.Formatter):
+    def format(self, record):
+        record_dict = record.__dict__.copy()
+        standard_keys = logging.makeLogRecord({}).__dict__.keys()
+        extras = {k: v for k, v in record_dict.items()
+                  if k not in standard_keys}
+        extras_string = f" {extras}" if extras else ""
+        formatted_message = super().format(record)
+        return f"{formatted_message}{extras_string}"
+
+
+logger = logging.getLogger('hello_world')
+handler = logging.StreamHandler()
+handler.setFormatter(ExtraInfoFormatter("%(levelname)s:%(message)s"))
+logger.addHandler(handler)
+logger.setLevel(logging.INFO)
+
+logger.info("Hello, world!", extra={"foo": 42, "bar": "baz"})
+
 hello_world.log_hello()

examples/hello_world/hw.py

@@ -1,4 +1,4 @@
-use log::{debug, trace, info};
+use log::{debug, info, trace};
 use pyo3::prelude::*;
 use pyo3::wrap_pyfunction;
 use pyo3_log::{Caching, Logger};
@@ -10,12 +10,12 @@ fn log_hello() {
     debug!("Stuff");
     info!("Hello {}", "world");
     info!("Hello 2{}", "world");
+    info!(test = 5; "Hello world with KV");
 }
 
 #[pymodule]
 fn hello_world(py: Python<'_>, m: &Bound<'_, PyModule>) -> PyResult<()> {
-    let _ = Logger::new(py, Caching::LoggersAndLevels)?
-        .install();
+    let _ = Logger::new(py, Caching::LoggersAndLevels)?.install();
 
     m.add_wrapped(wrap_pyfunction!(log_hello))?;
 

examples/hello_world/src/lib.rs

@@ -452,7 +452,42 @@ impl Logger {
         // it. And besides, we can save ourselves few python calls if it's turned off.
         if is_enabled_for(&logger, record.level())? {
             let none = py.None();
-            // TODO: kv pairs, if enabled as a feature?
+
+            #[allow(unused_mut)]
+            let mut extra = py.None().into_bound(py);
+
+            #[cfg(feature = "kv")]
+            if record.key_values().count() > 0 {
+                // write structured data to 'extra', serializing the values
+                use log::kv::{Key, Value, VisitSource};
+                use pyo3::types::{PyDict, PyString};
+
+                struct PyDictVisitor<'p> {
+                    dict: Bound<'p, PyDict>,
+                }
+
+                impl<'kvs, 'p> VisitSource<'kvs> for PyDictVisitor<'p> {
+                    fn visit_pair(
+                        &mut self,
+                        key: Key<'kvs>,
+                        value: Value<'kvs>,
+                    ) -> Result<(), log::kv::Error> {
+                        let py_key = PyString::new(self.dict.py(), key.as_str());
+                        let py_value = PyString::new(self.dict.py(), &value.to_string());
+
+                        let _ = self.dict.set_item(py_key, py_value);
+                        Ok(())
+                    }
+                }
+
+                let mut visitor = PyDictVisitor {
+                    dict: PyDict::new(py),
+                };
+                let _ = record.key_values().visit(&mut visitor);
+
+                extra = visitor.dict.into_any();
+            }
+
             let record = logger.call_method1(
                 "makeRecord",
                 (
@@ -463,8 +498,11 @@ impl Logger {
                     msg,
                     PyTuple::empty(py), // args
                     &none,              // exc_info
+                    &none,              // func
+                    extra,              // extra
                 ),
             )?;
+
             logger.call_method1("handle", (record,))?;
         }