scattered changes for integration in infinitepay-auth

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

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<String>,
     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::<Ident>()
-                                .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::<Literal>()
+                                .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,14 +176,27 @@ 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"]);
         assert_eq!(
             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'"#
         );
     }
 

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)]
         )
     };
 

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]

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

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<u64, Box<dyn std::error::Error>> {
@@ -22,14 +26,32 @@ fn log_error_calls_only(a: u64, b: u64) -> Result<u64, Box<dyn std::error::Error
         .ok_or_else(|| Box::from(format!("Couldn't subtract {b} from {a}")))
 }
 
+// Uncomment the following function to see a demonstration of this library's debug capabilities
+// #[instrument(err, debug)]
+// fn fail_to_compile_but_outputs_the_real_code(a: u64, b: u64) -> Result<u64, Box<dyn std::error::Error>> {
+//     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();
 }
 

infinite-tracing/src/lib.rs

@@ -117,6 +117,14 @@ fn uuid_to_u128(uuid: &str) -> Option<u128> {
     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::*;

infinite-tracing/src/minitrace_glue.rs

@@ -1,5 +1,7 @@
 use minitrace::collector::{Config, Reporter, SpanRecord};
 use serde_json::json;
+use once_cell::sync::Lazy;
+
 
 pub fn setup_minitrace(output_fn: impl std::io::Write + Send + 'static) {
     let json_reporter = JsonReporter::new(output_fn);
@@ -21,6 +23,8 @@ impl<WriteImpl: std::io::Write> JsonReporter<WriteImpl> {
 }
 
 impl<WriteImpl: std::io::Write + Send + 'static> Reporter for JsonReporter<WriteImpl> {
+
+
     fn report(&mut self, spans: &[SpanRecord]) {
         for span in spans {
             let trace_id = crate::features::convert_trace_id(span.trace_id.0);

infinite-tracing/src/structured_logger_glue.rs

@@ -1,24 +1,30 @@
 use log::kv::{Key, Value};
-use minitrace::Event;
 use std::borrow::Cow;
 use std::collections::BTreeMap;
 use std::io::{Error, Write};
+use std::iter::IntoIterator;
+use once_cell::sync::Lazy;
+
+
+static LEVEL_KEY: Lazy<Key> = Lazy::new(|| Key::from_str("level"));
+static TARGET_KEY: Lazy<Key> = Lazy::new(|| Key::from_str("target"));
+static CHRONO_FORMAT: Lazy<Vec<chrono::format::Item>> = 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<Key, Value>) -> Result<(), Error> {
             let level = entries
-                .get(&Key::from_str("level"))
+                .get(&*LEVEL_KEY)
                 .map(|value| value.to_string())
-                .unwrap_or(String::from("<MISSING LEVEL>"));
+                .unwrap_or_else(|| String::from("<MISSING LEVEL>"));
             // 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()),
                     })