From 3f3a8e6fa34f8e7ecf55f54722fdbfd940a3eb6c Mon Sep 17 00:00:00 2001 From: Luiz Silveira Date: Wed, 17 Apr 2024 10:27:20 -0300 Subject: [PATCH 1/2] scattered changes for integration in auth --- infinite-tracing-macro/src/lib.rs | 3 +- infinite-tracing-macro/src/parameters.rs | 38 +++++++++++++++---- infinite-tracing-macro/src/tracing_impl.rs | 7 +++- infinite-tracing/Cargo.toml | 3 +- infinite-tracing/benches/tracers.rs | 14 +++---- .../examples/infinite-tracing-demo.rs | 24 +++++++++++- infinite-tracing/src/lib.rs | 8 ++++ infinite-tracing/src/minitrace_glue.rs | 12 +++++- .../src/structured_logger_glue.rs | 22 +++++++---- 9 files changed, 102 insertions(+), 29 deletions(-) diff --git a/infinite-tracing-macro/src/lib.rs b/infinite-tracing-macro/src/lib.rs index ad2a781..2e3c880 100644 --- a/infinite-tracing-macro/src/lib.rs +++ b/infinite-tracing-macro/src/lib.rs @@ -20,6 +20,7 @@ pub fn instrument( let parameters = syn::parse_macro_input!(macro_args_tokens as MacroArgs); let function_definition_tokens = tracing_impl::instrument(parameters, fn_item); - //panic!("FN is defined AS:\n{}", function_definition_tokens.to_string()); + // uncomment to debug: + //panic!("`infinite-tracing` DEBUG param is enabled: FUNCTION is defined as:\n{}", function_definition_tokens.to_string()); function_definition_tokens.into() } diff --git a/infinite-tracing-macro/src/parameters.rs b/infinite-tracing-macro/src/parameters.rs index 47f7f1e..13442f1 100644 --- a/infinite-tracing-macro/src/parameters.rs +++ b/infinite-tracing-macro/src/parameters.rs @@ -1,4 +1,4 @@ -use proc_macro2::Span; +use proc_macro2::{Literal, Span}; use quote::ToTokens; use syn::parse::{Parse, ParseStream}; use syn::punctuated::Punctuated; @@ -10,6 +10,8 @@ pub struct MacroArgs { pub log_parameters: bool, pub parameters_to_skip: Vec, pub custom_params: Vec<(String, String)>, + /// if set, passes the `debug` param to the `logcall` crate -- for inspection of the generated function results + pub logcall_debug: bool, } impl Default for MacroArgs { fn default() -> Self { @@ -18,6 +20,7 @@ impl Default for MacroArgs { log_parameters: true, parameters_to_skip: vec![], custom_params: vec![], + logcall_debug: false, } } } @@ -79,8 +82,11 @@ impl Parse for MacroArgs { .map(|_| Err(syn::Error::new(Span::call_site(), String::from(INVALID_SKIP_COMBINATION) ))) .unwrap_or(Ok(false))?; - } - _ => return Err(syn::Error::new(Span::call_site(), format!("Unknown identifier parameter '{}' -- known ones are: 'err', 'ok', 'ret', 'skip_all'", ident))), + }, + "logcall_debug" => { + macro_args.logcall_debug = true; + }, + _ => return Err(syn::Error::new(Span::call_site(), format!("Unknown identifier parameter '{}' -- known ones are: 'err', 'ok', 'ret', 'skip_all', 'logcall_debug'", ident))), } } else if input.lookahead1().peek(token::Paren) { // name(identifier list) parsing -- "func" @@ -128,10 +134,13 @@ impl Parse for MacroArgs { _ => { // custom name=val parameters let name = ident.to_string(); - let val = input.parse::() - .map_err(|err| syn::Error::new(Span::call_site(), format!("Can't parse `val` for custom `name`=`val` parameter for name '{}': {:?}", name, err)))? + let lit_val = input.parse::() + .map_err(|err| syn::Error::new(Span::call_site(), format!("Can't parse `val` as literal for custom `name`=`val` parameter for name '{}': {:?}", name, err)))? .to_string(); - macro_args.custom_params.push((name, val)); + let val = lit_val + .trim_matches('\'') + .trim_matches('"'); + macro_args.custom_params.push((name, val.to_string())); } } } else { @@ -167,7 +176,19 @@ mod tests { #[test] fn typical_usage() { - let parsed_args: MacroArgs = parse_str(r#"err, skip(hello, world), a=b"#).unwrap(); + let parsed_args: MacroArgs = parse_str(r#"err, skip(hello, world), a='b'"#).unwrap(); + assert_eq!(parsed_args.log_return, ReturnLogOptions::LogErrOnly); + assert!(parsed_args.log_parameters); + assert_eq!(parsed_args.parameters_to_skip, vec!["hello", "world"]); + assert_eq!( + parsed_args.custom_params, + vec![("a".to_string(), "b".to_string())] + ); + } + + #[test] + fn debug() { + let parsed_args: MacroArgs = parse_str(r#"err, skip(hello, world), a='b', logcall_debug"#).unwrap(); assert_eq!(parsed_args.log_return, ReturnLogOptions::LogErrOnly); assert!(parsed_args.log_parameters); assert_eq!(parsed_args.parameters_to_skip, vec!["hello", "world"]); @@ -175,6 +196,7 @@ mod tests { parsed_args.custom_params, vec![("a".to_string(), "b".to_string())] ); + assert!(parsed_args.logcall_debug, "`logcall_debug` arg was specified but not taken into account"); } #[test] @@ -282,7 +304,7 @@ mod tests { assert!(parsed_args.is_err()); assert_eq!( parsed_args.unwrap_err().to_string(), - r#"Unknown identifier parameter 'nonexistingparam' -- known ones are: 'err', 'ok', 'ret', 'skip_all'"# + r#"Unknown identifier parameter 'nonexistingparam' -- known ones are: 'err', 'ok', 'ret', 'skip_all', 'logcall_debug'"# ); } diff --git a/infinite-tracing-macro/src/tracing_impl.rs b/infinite-tracing-macro/src/tracing_impl.rs index 4a564a6..15396e2 100644 --- a/infinite-tracing-macro/src/tracing_impl.rs +++ b/infinite-tracing-macro/src/tracing_impl.rs @@ -48,12 +48,17 @@ pub fn instrument(parameters: MacroArgs, fn_item: ItemFn) -> proc_macro2::TokenS // no `skip_options` list present means that no input params will be logged for the function call quote!() }; + let debug = if parameters.logcall_debug { + quote!(debug=true, ) + } else { + quote!() + }; let logcall_annotation_tokens = if degress_params.is_empty() && ingress_params.is_empty() { quote!() } else { quote!( - #[::logcall::logcall(#degress_params #ingress_params #skip_params)] + #[::logcall::logcall(#degress_params #ingress_params #skip_params #debug)] ) }; diff --git a/infinite-tracing/Cargo.toml b/infinite-tracing/Cargo.toml index 4a27888..3fb42a0 100644 --- a/infinite-tracing/Cargo.toml +++ b/infinite-tracing/Cargo.toml @@ -16,13 +16,14 @@ default = [] [dependencies] log = "0.4" infinite-tracing-macro = { path = "../infinite-tracing-macro" } -logcall = { git = "https://github.com/cloudwalk/logcall", branch = "main" } +logcall = { git = "https://github.com/cloudwalk/logcall", branch = "log_kv_fix" } minitrace = { version = "0.6", features = ["enable"] } structured-logger = "1" chrono = "0.4" serde = { version = "1.0.197", features = ["derive"] } serde_json = "1.0.114" uuid = { version = "1.7", features = ["v4"], optional = true } +once_cell = "1.19.0" [dev-dependencies] diff --git a/infinite-tracing/benches/tracers.rs b/infinite-tracing/benches/tracers.rs index 875d1db..b5341ed 100644 --- a/infinite-tracing/benches/tracers.rs +++ b/infinite-tracing/benches/tracers.rs @@ -40,7 +40,7 @@ fn bench_tracers(criterion: &mut Criterion) { let bench_id = "baseline method call"; group.bench_function(bench_id, |bencher| { - bencher.iter(|| black_box({ baseline_method(bench_id.as_ptr() as u32) })) + bencher.iter(|| black_box(baseline_method(bench_id.as_ptr() as u32))) }); // infinite_tracing @@ -62,13 +62,13 @@ fn bench_tracers(criterion: &mut Criterion) { // scenario: no tracing nor logging is done -- the method doesn't end in `Err` let bench_id = "`infinite-tracing` OVERHEAD"; group.bench_function(bench_id, |bencher| { - bencher.iter(|| black_box({ infinite_tracing_overhead_method(bench_id.as_ptr() as u32) })) + bencher.iter(|| black_box(infinite_tracing_overhead_method(bench_id.as_ptr() as u32))) }); - // scenario: tracing & loggig is done -- the method ends in `Err` + // scenario: tracing & logging is done -- the method ends in `Err` let bench_id = "`infinite-tracing` THROUGHPUT"; group.bench_function(bench_id, |bencher| { - bencher.iter(|| black_box({ infinite_tracing_throughput_method(bench_id.as_ptr() as u32) })) + bencher.iter(|| black_box(infinite_tracing_throughput_method(bench_id.as_ptr() as u32))) }); // Cloudwalk's tracing-stackdriver @@ -94,14 +94,14 @@ fn bench_tracers(criterion: &mut Criterion) { let bench_id = "Cloudwalk's `tracing-stackdriver` OVERHEAD"; group.bench_function(bench_id, |bencher| { bencher - .iter(|| black_box({ tracing_stackdriver_overhead_method(bench_id.as_ptr() as u32) })) + .iter(|| black_box(tracing_stackdriver_overhead_method(bench_id.as_ptr() as u32))) }); - // scenario: tracing & loggig is done -- the method ends in `Err` + // scenario: tracing & logging is done -- the method ends in `Err` let bench_id = "Cloudwalk's `tracing-stackdriver` THROUGHPUT"; group.bench_function(bench_id, |bencher| { bencher - .iter(|| black_box({ tracing_stackdriver_throughput_method(bench_id.as_ptr() as u32) })) + .iter(|| black_box(tracing_stackdriver_throughput_method(bench_id.as_ptr() as u32))) }); group.finish(); diff --git a/infinite-tracing/examples/infinite-tracing-demo.rs b/infinite-tracing/examples/infinite-tracing-demo.rs index 72e7ce7..4cd87af 100644 --- a/infinite-tracing/examples/infinite-tracing-demo.rs +++ b/infinite-tracing/examples/infinite-tracing-demo.rs @@ -1,5 +1,9 @@ +use std::fmt::{Display, Formatter}; +use std::task::Context; use infinite_tracing::*; use log::info; +use minitrace::collector::{SpanContext, SpanId, TraceId}; +use tracing::instrument::WithSubscriber; #[instrument(ret)] fn log_all_calls_and_returns(a: u64, b: u64) -> Result> { @@ -22,14 +26,32 @@ fn log_error_calls_only(a: u64, b: u64) -> Result Result> { +// a.checked_sub(b) +// .ok_or_else(|| Box::from(format!("Couldn't subtract {b} from {a}"))) +// } + #[instrument] fn sync_database_function() { - info!("This is the SYNC database function: `log_error_calls()` will be called, but it will produce an Ok Result -- so no logs should follow"); + info!("This is the SYNC database function: `log_error_calls()` will be called, but it will produce an Ok Result -- so no logs should follow. Nonetheless, this log should include the `ctx` variable set on the upstream function"); _ = log_error_calls_only(10, 3); } #[instrument] fn sync_business_logic_function() { + // add something to the span -- to be included in the logs made downstream: + #[derive(Debug)] + struct Context { + state: String, + metrics: u32, + } + let ctx = Context { + state: "My Context has a State".to_string(), + metrics: 42, + }; + info!(ctx:?; "Context is shared here. See 'span'"); sync_database_function(); } diff --git a/infinite-tracing/src/lib.rs b/infinite-tracing/src/lib.rs index c7cd0af..dd7b9ce 100644 --- a/infinite-tracing/src/lib.rs +++ b/infinite-tracing/src/lib.rs @@ -117,6 +117,14 @@ fn uuid_to_u128(uuid: &str) -> Option { Some(parsed_value) } +// experimental +macro_rules! span { + ($key:expr, $value:expr) => { + let _minitrace_guard = ::minitrace::Span::new().enter(); + let _minitrace_event_guard = ::minitrace::LocalEventGuard::new($key, $value); + } +} + #[cfg(test)] mod tests { use super::*; diff --git a/infinite-tracing/src/minitrace_glue.rs b/infinite-tracing/src/minitrace_glue.rs index e662359..17d60b4 100644 --- a/infinite-tracing/src/minitrace_glue.rs +++ b/infinite-tracing/src/minitrace_glue.rs @@ -1,5 +1,10 @@ use minitrace::collector::{Config, Reporter, SpanRecord}; use serde_json::json; +use once_cell::sync::Lazy; + + +static EMPTY_MAP: Lazy> = Lazy::new(|| serde_json::Map::with_capacity(0)); + pub fn setup_minitrace(output_fn: impl std::io::Write + Send + 'static) { let json_reporter = JsonReporter::new(output_fn); @@ -21,6 +26,8 @@ impl JsonReporter { } impl Reporter for JsonReporter { + + fn report(&mut self, spans: &[SpanRecord]) { for span in spans { let trace_id = crate::features::convert_trace_id(span.trace_id.0); @@ -31,7 +38,7 @@ impl Reporter for JsonReporter timestamp = property_value, @@ -40,6 +47,7 @@ impl Reporter for JsonReporter line = property_value, _ => { structured_fields + .get_or_insert_with(|| serde_json::Map::new()) .insert(property_key.to_string(), json!(property_value)); } } @@ -48,7 +56,7 @@ impl Reporter for JsonReporter = Lazy::new(|| Key::from_str("level")); +static TARGET_KEY: Lazy = Lazy::new(|| Key::from_str("target")); +static CHRONO_FORMAT: Lazy> = Lazy::new(|| chrono::format::StrftimeItems::new("%Y-%m-%dT%H:%M:%S%.3fZ").into_iter().collect()); pub fn setup_structured_logger() { struct MyWriter; impl structured_logger::Writer for MyWriter { fn write_log(&self, entries: &BTreeMap) -> Result<(), Error> { let level = entries - .get(&Key::from_str("level")) + .get(&*LEVEL_KEY) .map(|value| value.to_string()) - .unwrap_or(String::from("")); + .unwrap_or_else(|| String::from("")); // Add the log record as an event in the current local span - Event::add_to_local_parent(level, || { + minitrace::Event::add_to_local_parent(level, || { #[allow(clippy::needless_borrowed_reference)] entries .iter() .filter(|(&ref k, _v)| { - k != &Key::from_str("level") && k != &Key::from_str("target") + k != &*LEVEL_KEY && k != &*TARGET_KEY }) .map(|(k, v)| match k.as_str() { "message" => (Cow::Borrowed("message"), v.to_string()), @@ -30,9 +36,9 @@ pub fn setup_structured_logger() { 1_000_000 * (timestamp_ms % 1_000) as u32, ) .unwrap_or(chrono::NaiveDateTime::MIN); - let timestamp_str = - chrono_time.format("%Y-%m-%dT%H:%M:%S%.3fZ").to_string(); - (Cow::Borrowed("timestamp"), timestamp_str) + let timestamp = + chrono_time.format_with_items(CHRONO_FORMAT.iter()).to_string(); + (Cow::Borrowed("timestamp"), timestamp) } _ => (Cow::Owned(k.to_string()), v.to_string()), }) From d571f7499ef3ac8934ab13b4cf7878c4ec2efa37 Mon Sep 17 00:00:00 2001 From: Luiz Silveira Date: Wed, 17 Apr 2024 17:14:05 -0300 Subject: [PATCH 2/2] addressed review topics --- infinite-tracing/src/minitrace_glue.rs | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/infinite-tracing/src/minitrace_glue.rs b/infinite-tracing/src/minitrace_glue.rs index 17d60b4..5a04433 100644 --- a/infinite-tracing/src/minitrace_glue.rs +++ b/infinite-tracing/src/minitrace_glue.rs @@ -3,9 +3,6 @@ use serde_json::json; use once_cell::sync::Lazy; -static EMPTY_MAP: Lazy> = Lazy::new(|| serde_json::Map::with_capacity(0)); - - pub fn setup_minitrace(output_fn: impl std::io::Write + Send + 'static) { let json_reporter = JsonReporter::new(output_fn); minitrace::set_reporter(json_reporter, Config::default()); @@ -38,7 +35,7 @@ impl Reporter for JsonReporter timestamp = property_value, @@ -47,7 +44,6 @@ impl Reporter for JsonReporter line = property_value, _ => { structured_fields - .get_or_insert_with(|| serde_json::Map::new()) .insert(property_key.to_string(), json!(property_value)); } } @@ -56,7 +52,7 @@ impl Reporter for JsonReporter