diff --git a/Cargo.lock b/Cargo.lock index 996c782..f40b62e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4,9 +4,9 @@ version = 3 [[package]] name = "aho-corasick" -version = "1.0.4" +version = "1.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6748e8def348ed4d14996fa801f4122cd763fff530258cdc03f64b25f89d3a5a" +checksum = "b2969dcb958b36655471fc61f7e416fa76033bdd4bfed0678d8fee1e2d07a1f0" dependencies = [ "memchr", ] @@ -17,15 +17,6 @@ version = "2.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b4682ae6287fcf752ecaabbfcc7b6f9b72aa33933dc23a554d853aea8eea8635" -[[package]] -name = "cc" -version = "1.0.83" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f1174fb0b6ec23863f8b971027804a42614e347eafb0a95bf0b12cdae21fc4d0" -dependencies = [ - "libc", -] - [[package]] name = "env_logger" version = "0.10.0" @@ -41,30 +32,19 @@ dependencies = [ [[package]] name = "errno" -version = "0.3.2" +version = "0.3.5" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "6b30f669a7961ef1631673d2766cc92f52d64f7ef354d4fe0ddfd30ed52f0f4f" +checksum = "ac3e13f66a2f95e32a39eaa81f6b95d42878ca0e1db0c7543723dfe12557e860" dependencies = [ - "errno-dragonfly", "libc", "windows-sys", ] -[[package]] -name = "errno-dragonfly" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "aa68f1b12764fab894d2755d2518754e71b4fd80ecfb822714a1206c2aab39bf" -dependencies = [ - "cc", - "libc", -] - [[package]] name = "hermit-abi" -version = "0.3.2" +version = "0.3.3" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "443144c8cdadd93ebf52ddb4056d257f5b52c04d3c804e657d19eb73fc33668b" +checksum = "d77f7ec81a6d05a3abb01ab6eb7590f6083d08449fe5a1c8b1e620283546ccb7" [[package]] name = "humantime" @@ -85,15 +65,15 @@ dependencies = [ [[package]] name = "libc" -version = "0.2.147" +version = "0.2.149" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b4668fb0ea861c1df094127ac5f1da3409a82116a4ba74fca2e58ef927159bb3" +checksum = "a08173bc88b7955d1b3145aa561539096c421ac8debde8cbc3612ec635fee29b" [[package]] name = "linux-raw-sys" -version = "0.4.5" +version = "0.4.10" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "57bcfdad1b858c2db7c38303a6d2ad4dfaf5eb53dfeb0910128b2c26d6158503" +checksum = "da2479e8c062e40bf0066ffa0bc823de0a9368974af99c9f6df941d2c231e03f" [[package]] name = "log" @@ -103,7 +83,7 @@ checksum = "b5e6163cb8c49088c2c36f57875e58ccd8c87c7427f7fbd50ea6710b2f3f2e8f" [[package]] name = "log-instrument" -version = "0.1.4" +version = "0.2.0" dependencies = [ "env_logger", "log", @@ -121,15 +101,15 @@ dependencies = [ [[package]] name = "memchr" -version = "2.5.0" +version = "2.6.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "2dffe52ecf27772e601905b7522cb4ef790d2cc203488bbd0e2fe85fcb74566d" +checksum = "f665ee40bc4a3c5590afb1e9677db74a508659dfd71e126420da8274909a0167" [[package]] name = "proc-macro2" -version = "1.0.66" +version = "1.0.69" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "18fb31db3f9bddb2ea821cde30a9f70117e3f119938b5ee630b7403aa6e2ead9" +checksum = "134c189feb4956b20f6f547d2cf727d4c0fe06722b20a0eec87ed445a97f92da" dependencies = [ "unicode-ident", ] @@ -145,9 +125,9 @@ dependencies = [ [[package]] name = "regex" -version = "1.9.3" +version = "1.10.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "81bc1d4caf89fac26a70747fe603c130093b53c773888797a6329091246d651a" +checksum = "d119d7c7ca818f8a53c300863d4f87566aac09943aef5b355bb83969dae75d87" dependencies = [ "aho-corasick", "memchr", @@ -157,9 +137,9 @@ dependencies = [ [[package]] name = "regex-automata" -version = "0.3.6" +version = "0.4.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "fed1ceff11a1dddaee50c9dc8e4938bd106e9d89ae372f192311e7da498e3b69" +checksum = "465c6fc0621e4abc4187a2bda0937bfd4f722c2730b29562e19689ea796c9a4b" dependencies = [ "aho-corasick", "memchr", @@ -168,15 +148,15 @@ dependencies = [ [[package]] name = "regex-syntax" -version = "0.7.4" +version = "0.8.1" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e5ea92a5b6195c6ef2a0295ea818b312502c6fc94dde986c5553242e18fd4ce2" +checksum = "56d84fdd47036b038fc80dd333d10b6aab10d5d31f4a366e20014def75328d33" [[package]] name = "rustix" -version = "0.38.8" +version = "0.38.18" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "19ed4fa021d81c8392ce04db050a3da9a60299050b7ae1cf482d862b54a7218f" +checksum = "5a74ee2d7c2581cd139b42447d7d9389b889bdaad3a73f1ebb16f2a3237bb19c" dependencies = [ "bitflags", "errno", @@ -187,9 +167,9 @@ dependencies = [ [[package]] name = "syn" -version = "2.0.29" +version = "2.0.38" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c324c494eba9d92503e6f1ef2e6df781e78f6a7705a0202d9801b198807d518a" +checksum = "e96b79aaa137db8f61e26363a0c9b47d8b4ec75da28b7d1d614c2303e232408b" dependencies = [ "proc-macro2", "quote", @@ -198,18 +178,18 @@ dependencies = [ [[package]] name = "termcolor" -version = "1.2.0" +version = "1.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "be55cf8942feac5c765c2c993422806843c9a9a45d4d5c407ad6dd2ea95eb9b6" +checksum = "6093bad37da69aab9d123a8091e4be0aa4a03e4d601ec641c327398315f62b64" dependencies = [ "winapi-util", ] [[package]] name = "unicode-ident" -version = "1.0.11" +version = "1.0.12" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "301abaae475aa91687eb82514b328ab47a211a533026cb25fc3e519b86adfc3c" +checksum = "3354b9ac3fae1ff6755cb6db53683adb661634f67557942dea4facebec0fee4b" [[package]] name = "winapi" @@ -229,9 +209,9 @@ checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" [[package]] name = "winapi-util" -version = "0.1.5" +version = "0.1.6" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178" +checksum = "f29e6f9198ba0d26b4c9f07dbe6f9ed633e1f3d5b8b414090084349e46a52596" dependencies = [ "winapi", ] diff --git a/README.md b/README.md index 3a871d0..6d1037a 100644 --- a/README.md +++ b/README.md @@ -9,6 +9,8 @@ Offers an attribute procedural macro that adds [`log::trace!`](https://docs.rs/l ### Example ```rust +use log::*; + fn main() { env_logger::builder() .filter_level(LevelFilter::Trace) @@ -24,23 +26,35 @@ fn one(x: u32) -> u32 { if cmp { return 4; } - x + 3 + two(x + 3) +} +#[log_instrument::instrument] +fn two(x: u32) -> u32 { + let res = x % 2; + debug!("res: {res}"); + res } ``` Outputs: ``` -[2023-08-30T13:58:20Z TRACE log_instrument] one enter -[2023-08-30T13:58:20Z DEBUG one] cmp: true -[2023-08-30T13:58:20Z TRACE log_instrument] one exit -[2023-08-30T13:58:20Z INFO one] 4 -[2023-08-30T13:58:20Z TRACE log_instrument] one enter -[2023-08-30T13:58:20Z DEBUG one] cmp: false -[2023-08-30T13:58:20Z TRACE log_instrument] one exit -[2023-08-30T13:58:20Z INFO one] 6 -[2023-08-30T13:58:20Z TRACE log_instrument] one enter -[2023-08-30T13:58:20Z DEBUG one] cmp: false -[2023-08-30T13:58:20Z TRACE log_instrument] one exit -[2023-08-30T13:58:20Z INFO one] 7 +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)>>one +[2023-10-12T16:38:00Z DEBUG six] cmp: true +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)<>one +[2023-10-12T16:38:00Z DEBUG six] cmp: false +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one>>two +[2023-10-12T16:38:00Z DEBUG six] res: 0 +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one<>one +[2023-10-12T16:38:00Z DEBUG six] cmp: false +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one>>two +[2023-10-12T16:38:00Z DEBUG six] res: 1 +[2023-10-12T16:38:00Z TRACE log_instrument] ThreadId(1)::one< u32 { + let cmp = x == 2; + debug!("cmp: {cmp}"); + if cmp { + return 4; + } + two(x + 3) +} +#[log_instrument::instrument] +fn two(x: u32) -> u32 { + let res = x % 2; + debug!("res: {res}"); + res +} diff --git a/log-instrument/examples/three.rs b/log-instrument/examples/three.rs index b2bb330..48e0fdd 100644 --- a/log-instrument/examples/three.rs +++ b/log-instrument/examples/three.rs @@ -1,15 +1,5 @@ use log::*; -/// Outputs: -/// ```text -/// [2023-08-20T22:22:25Z TRACE log_instrument] one enter -/// [2023-08-20T22:22:25Z TRACE log_instrument] one exit -/// [2023-08-20T22:22:25Z INFO three] None -/// [2023-08-20T22:22:25Z TRACE log_instrument] one enter -/// [2023-08-20T22:22:25Z DEBUG three] ["a", "b"] -/// [2023-08-20T22:22:25Z TRACE log_instrument] one exit -/// [2023-08-20T22:22:25Z INFO three] Some(["a", "b"]) -/// ``` fn main() { env_logger::builder() .filter_level(LevelFilter::Trace) diff --git a/log-instrument/examples/two.rs b/log-instrument/examples/two.rs index 3e42c81..c6bfa88 100644 --- a/log-instrument/examples/two.rs +++ b/log-instrument/examples/two.rs @@ -1,15 +1,5 @@ use log::*; -/// Outputs: -/// ```text -/// [2023-08-20T22:21:51Z TRACE log_instrument] one enter -/// [2023-08-20T22:21:51Z TRACE log_instrument] one exit -/// [2023-08-20T22:21:51Z INFO two] None -/// [2023-08-20T22:21:51Z TRACE log_instrument] one enter -/// [2023-08-20T22:21:51Z DEBUG two] ["a", "b"] -/// [2023-08-20T22:21:51Z TRACE log_instrument] one exit -/// [2023-08-20T22:21:51Z INFO two] Some(["a", "b"] -/// ``` fn main() { env_logger::builder() .filter_level(LevelFilter::Trace) diff --git a/log-instrument/src/lib.rs b/log-instrument/src/lib.rs index 0765ab4..5c3f32d 100644 --- a/log-instrument/src/lib.rs +++ b/log-instrument/src/lib.rs @@ -1,14 +1,52 @@ pub use log_instrument_macros::*; +use std::collections::HashMap; +use std::fmt::Write; +use std::sync::Mutex; +use std::sync::OnceLock; -pub struct __Instrument<'a>(&'a str); -impl<'a> __Instrument<'a> { - pub fn new(s: &'a str) -> __Instrument<'a> { - log::trace!("{s} enter"); - __Instrument(s) +type InnerPath = Mutex>>; +static PATH: OnceLock = OnceLock::new(); +fn init_path() -> InnerPath { + Mutex::new(HashMap::new()) +} + +pub struct __Instrument; + +impl __Instrument { + pub fn new(s: &'static str) -> __Instrument { + // Get log + let mut guard = PATH.get_or_init(init_path).lock().unwrap(); + let id = std::thread::current().id(); + let prefix = if let Some(spans) = guard.get_mut(&id) { + let out = spans.iter().fold(String::new(), |mut s, x| { + let _ = write!(s, "::{x}"); + s + }); + spans.push(s); + out + } else { + guard.insert(id, vec![s]); + String::new() + }; + + // Write log + log::trace!("{id:?}{prefix}>>{s}"); + + // Return exit struct + __Instrument } } -impl<'a> std::ops::Drop for __Instrument<'a> { +impl std::ops::Drop for __Instrument { fn drop(&mut self) { - log::trace!("{} exit", self.0); + // Get log + let mut guard = PATH.get_or_init(init_path).lock().unwrap(); + let id = std::thread::current().id(); + let spans = guard.get_mut(&id).unwrap(); + let s = spans.pop().unwrap(); + let out = spans.iter().fold(String::new(), |mut s, x| { + let _ = write!(s, "::{x}"); + s + }); + log::trace!("{id:?}{out}<<{s}"); } } diff --git a/log-instrument/tests/integration_tests.rs b/log-instrument/tests/integration_tests.rs index 575fcc6..67c04f2 100644 --- a/log-instrument/tests/integration_tests.rs +++ b/log-instrument/tests/integration_tests.rs @@ -3,6 +3,7 @@ const TWO: &str = "../target/debug/examples/two"; const THREE: &str = "../target/debug/examples/three"; const FOUR: &str = "../target/debug/examples/four"; const FIVE: &str = "../target/debug/examples/five"; +const SIX: &str = "../target/debug/examples/six"; const TIMESTAMP_RANGE: std::ops::Range = 1..20; @@ -28,18 +29,18 @@ fn one() { assert!(output.status.success()); assert_eq!(output.stdout, b""); let expected_stderr = b"\ - [2023-08-30T13:58:20Z TRACE log_instrument] one enter\n\ - [2023-08-30T13:58:20Z DEBUG one] cmp: true\n\ - [2023-08-30T13:58:20Z TRACE log_instrument] one exit\n\ - [2023-08-30T13:58:20Z INFO one] 4\n\ - [2023-08-30T13:58:20Z TRACE log_instrument] one enter\n\ - [2023-08-30T13:58:20Z DEBUG one] cmp: false\n\ - [2023-08-30T13:58:20Z TRACE log_instrument] one exit\n\ - [2023-08-30T13:58:20Z INFO one] 6\n\ - [2023-08-30T13:58:20Z TRACE log_instrument] one enter\n\ - [2023-08-30T13:58:20Z DEBUG one] cmp: false\n\ - [2023-08-30T13:58:20Z TRACE log_instrument] one exit\n\ - [2023-08-30T13:58:20Z INFO one] 7\n\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)>>one\n\ + [2023-10-12T16:29:00Z DEBUG one] cmp: true\n\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:00Z DEBUG one] cmp: false\n\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:00Z DEBUG one] cmp: false\n\ + [2023-10-12T16:29:00Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:29:30Z DEBUG two] [\"a\", \"b\"]\n\ + [2023-10-12T16:29:30Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:04Z DEBUG three] [\"a\", \"b\"]\n\ + [2023-10-12T16:30:04Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:30:37Z DEBUG four] [\"a\", \"b\"]\n\ + [2023-10-12T16:30:37Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:12Z DEBUG five] [\"a\", \"b\"]\n\ + [2023-10-12T16:31:12Z DEBUG five] 23\n\ + [2023-10-12T16:31:12Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:54Z DEBUG six] cmp: true\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)<>one\n\ + [2023-10-12T16:31:54Z DEBUG six] cmp: false\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one>>two\n\ + [2023-10-12T16:31:54Z DEBUG six] res: 0\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one<>one\n\ + [2023-10-12T16:31:54Z DEBUG six] cmp: false\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one>>two\n\ + [2023-10-12T16:31:54Z DEBUG six] res: 1\n\ + [2023-10-12T16:31:54Z TRACE log_instrument] ThreadId(1)::one<