diff --git a/Cargo.toml b/Cargo.toml index 44f9568..e6cfb85 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -27,7 +27,7 @@ edition = "2021" async-trait = "0.1.52" futures = "0.3.19" libc = "0.2.112" -log = "0.4" +log = {version = "0.4.2", features=["kv_unstable"]} nix = "0.27" oci-spec = "0.6" os_pipe = "1.1" diff --git a/crates/shim/Cargo.toml b/crates/shim/Cargo.toml index ca00dc3..e0c0ca5 100644 --- a/crates/shim/Cargo.toml +++ b/crates/shim/Cargo.toml @@ -37,7 +37,7 @@ containerd-shim-protos = { path = "../shim-protos", version = "0.5.0" } go-flag = "0.1.0" lazy_static = "1.4.0" libc.workspace = true -log = { workspace = true, features = ["std"] } +log = { workspace = true, features = ["std", "kv_unstable" ] } nix = { workspace = true, features = [ "ioctl", "fs", diff --git a/crates/shim/src/logger.rs b/crates/shim/src/logger.rs index 0d0becc..ecb757b 100644 --- a/crates/shim/src/logger.rs +++ b/crates/shim/src/logger.rs @@ -16,6 +16,7 @@ use std::{ borrow::BorrowMut, + fmt::Write as fmtwrite, fs::{File, OpenOptions}, io, io::Write, @@ -23,7 +24,10 @@ use std::{ sync::Mutex, }; -use log::{Metadata, Record}; +use log::{ + kv::{self, Visitor}, + Metadata, Record, +}; use time::{format_description::well_known::Rfc3339, OffsetDateTime}; use crate::error::Error; @@ -54,6 +58,23 @@ impl FifoLogger { } } +pub(crate) struct SimpleWriteVistor { + key_values: String, +} + +impl<'kvs> Visitor<'kvs> for SimpleWriteVistor { + fn visit_pair(&mut self, k: kv::Key<'kvs>, v: kv::Value<'kvs>) -> Result<(), kv::Error> { + write!(&mut self.key_values, " {}=\"{}\"", k, v)?; + Ok(()) + } +} + +impl SimpleWriteVistor { + fn as_str(&self) -> &str { + &self.key_values + } +} + impl log::Log for FifoLogger { fn enabled(&self, metadata: &Metadata) -> bool { metadata.level() <= log::max_level() @@ -62,6 +83,13 @@ impl log::Log for FifoLogger { fn log(&self, record: &Record) { if self.enabled(record.metadata()) { let mut guard = self.file.lock().unwrap(); + + // collect key_values but don't fail if error parsing + let mut writer = SimpleWriteVistor { + key_values: String::new(), + }; + let _ = record.key_values().visit(&mut writer); + // The logger server may have temporarily shutdown, ignore the error instead of panic. // // Manual for pipe/FIFO: https://man7.org/linux/man-pages/man7/pipe.7.html @@ -71,9 +99,10 @@ impl log::Log for FifoLogger { // EPIPE. let _ = writeln!( guard.borrow_mut(), - "time=\"{}\" level={} {}\n", + "time=\"{}\" level={}{} msg=\"{}\"\n", rfc3339_formated(), record.level().as_str().to_lowercase(), + writer.as_str(), record.args() ); } @@ -118,6 +147,8 @@ pub(crate) fn rfc3339_formated() -> String { #[cfg(test)] mod tests { + use std::fs; + use log::{Log, Record}; use super::*; @@ -151,12 +182,46 @@ mod tests { log::set_max_level(log::LevelFilter::Info); thread.join().unwrap(); + let kvs: &[(&str, i32)] = &[("a", 1), ("b", 2)]; let record = Record::builder() .level(log::Level::Error) .line(Some(1)) .file(Some("sample file")) + .key_values(&kvs) .build(); logger.log(&record); logger.flush(); } + + #[test] + fn test_supports_structured_logging() { + let tmpdir = tempfile::tempdir().unwrap(); + let path = tmpdir.path().to_str().unwrap().to_owned() + "/log"; + File::create(path.clone()).unwrap(); + + let logger = FifoLogger::with_path(&path).unwrap(); + log::set_max_level(log::LevelFilter::Info); + + let record = Record::builder() + .level(log::Level::Info) + .args(format_args!("no keys")) + .build(); + logger.log(&record); + logger.flush(); + + let contents = fs::read_to_string(path.clone()).unwrap(); + assert!(contents.contains("level=info msg=\"no keys\"")); + + let kvs: &[(&str, i32)] = &[("key", 1), ("b", 2)]; + let record = Record::builder() + .level(log::Level::Error) + .key_values(&kvs) + .args(format_args!("structured!")) + .build(); + logger.log(&record); + logger.flush(); + + let contents = fs::read_to_string(path).unwrap(); + assert!(contents.contains("level=error key=\"1\" b=\"2\" msg=\"structured!\"")); + } } diff --git a/crates/shim/src/sys/windows/named_pipe_logger.rs b/crates/shim/src/sys/windows/named_pipe_logger.rs index 64b7ea2..48f4595 100644 --- a/crates/shim/src/sys/windows/named_pipe_logger.rs +++ b/crates/shim/src/sys/windows/named_pipe_logger.rs @@ -84,10 +84,17 @@ impl log::Log for NamedPipeLogger { fn log(&self, record: &Record) { if self.enabled(record.metadata()) { + // collect key_values but don't fail if error parsing + let mut writer = logger::SimpleWriteVistor { + keyvalues: String::new(), + }; + let _ = record.key_values().visit(&mut writer); + let message = format!( - "time=\"{}\" level={} {}\n", + "time=\"{}\" level={}{} {}\n", logger::rfc3339_formated(), record.level().as_str().to_lowercase(), + writer.as_str(), record.args() ); @@ -173,10 +180,11 @@ mod tests { let mut client = create_client(pipe_name.as_str()); log::set_max_level(log::LevelFilter::Info); + let kvs: &[(&str, i32)] = &[("key", 1), ("b", 2)]; let record = Record::builder() .level(log::Level::Info) .line(Some(1)) - .file(Some("sample file")) + .key_values(&kvs) .args(format_args!("hello")) .build(); logger.log(&record); @@ -186,7 +194,7 @@ mod tests { let message = std::str::from_utf8(&buf).unwrap(); assert!(message.starts_with("time=\""), "message was: {:?}", message); assert!( - message.ends_with("level=info hello\n"), + message.ends_with("level=info key=\"1\" b=\"2\" msg=\"hello\"\n"), "message was: {:?}", message );