Tunning the log outputs

Cargo.toml

@@ -33,3 +33,5 @@ valuable-serde = { version = "0.1.0", optional = true }
 [dev-dependencies]
 tracing = "0.1.34"
 time = { version = "0.3.30", features = ["serde", "serde-well-known", "formatting"] }
+uuid = { version = "1.7.0", features = ["v4"] }
+tokio = { version = "1", features = ["rt", "rt-multi-thread", "macros"] }

examples/demo_full_fields.rs

@@ -0,0 +1,81 @@
+use tracing::{info, instrument, trace_span};
+use tracing_stackdriver_cw::layer;
+use tracing_subscriber::prelude::*;
+use tracing_subscriber::Registry;
+use uuid::Uuid;
+
+#[instrument]
+fn sync_database_function() {
+    info!("This is the SYNC database function");
+}
+
+#[instrument]
+fn sync_business_logic_function() {
+    info!("This is the SYNC business logic function");
+    sync_database_function();
+}
+
+#[instrument]
+fn sync_endpoint_function() {
+    // `trace_id` can come from Google App Engine, via headers.
+    // Here, we generate it manually
+    let trace_id = Uuid::new_v4().to_string();
+    // the following 2 variables must only be dropped at the end of the function,
+    // or else `traceId` won't be tracked correctly, as it is controlled by the
+    // opened "spans" on each thread.
+    let span = trace_span!("sync_endpoint_function", trace_id = %trace_id, test="\"trace_id\":\"yeah, yeah\"");
+    let _enter = span.enter();
+
+    info!(trace_id = %trace_id, "This is the SYNC endpoint function");
+    sync_business_logic_function();
+}
+
+#[instrument]
+async fn async_database_function() {
+    info!("This is the ASYNC database function");
+}
+
+#[instrument]
+async fn async_business_logic_function() {
+    info!("This is the ASYNC business logic function");
+    async_database_function().await;
+}
+
+#[instrument]
+async fn async_endpoint_function() {
+    // `trace_id` can come from Google App Engine, via headers.
+    // Here, we generate it manually
+    let trace_id = Uuid::new_v4().to_string();
+    // the following 2 variables must only be dropped at the end of the function,
+    // or else `traceId` won't be tracked correctly, as it is controlled by the
+    // opened "spans" on each thread.
+    let span = trace_span!("async_endpoint_function", trace_id = %trace_id, test=1);
+    let _enter = span.enter();
+
+    info!(trace_id = %trace_id, "This is the SYNC endpoint function");
+    async_business_logic_function().await;
+}
+
+#[tokio::main]
+async fn main() {
+    // Set up the subscriber.
+    let stackdriver = layer(); // writes to std::io::Stdout
+    let subscriber = Registry::default().with(stackdriver);
+
+    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");
+
+    // For traditional sync functions, tracing-stackdriver will link spans to threads.
+    sync_endpoint_function();
+
+    // You can safely assume that tracing-stackdriver will work as expected in async scenarios when using Tokio,
+    // as it will link spans to execution contexts for the async mode.
+    // Ensure that all your asynchronous tasks (futures) are spawned within the Tokio runtime.
+    // Avoid mixing threads and tasks directly; let Tokio manage the execution flow.
+    async_endpoint_function().await;
+
+    // observe that each log entry contains the same 'traceId' field at the root of each json,
+    // like the following excerpt:
+    // {"time":"2024-02-15T14:38:07.97665775Z","target":"demo_full_fields","logging.googleapis.com/sourceLocation":{"file":"examples/demo_full_fields.rs","line":"29"},"span":{"trace_id":"25075b50-d745-4d6b-9040-015be8482ad7","name":"endpoint_function"},"traceId":"25075b50-d745-4d6b-9040-015be8482ad7","severity":"INFO","message":"This is the endpoint function","traceId":"25075b50-d745-4d6b-9040-015be8482ad7"}
+    // {"time":"2024-02-15T14:38:07.976721894Z","target":"demo_full_fields","logging.googleapis.com/sourceLocation":{"file":"examples/demo_full_fields.rs","line":"14"},"span":{"name":"business_logic_function"},"traceId":"25075b50-d745-4d6b-9040-015be8482ad7","severity":"INFO","message":"This is the business logic function"}
+    // {"time":"2024-02-15T14:38:07.976742013Z","target":"demo_full_fields","logging.googleapis.com/sourceLocation":{"file":"examples/demo_full_fields.rs","line":"9"},"span":{"name":"database_function"},"traceId":"25075b50-d745-4d6b-9040-015be8482ad7","severity":"INFO","message":"This is the database function"}
+}

src/event_formatter.rs

@@ -6,8 +6,11 @@ use crate::{
 };
 use serde::ser::{SerializeMap, Serializer as _};
 use std::fmt;
+use std::fmt::Debug;
 use time::{format_description::well_known::Rfc3339, OffsetDateTime};
-use tracing_core::{Event, Subscriber};
+use tracing_core::field::Value;
+use tracing_core::field::Visit;
+use tracing_core::{Event, Field, Subscriber};
 use tracing_subscriber::{
     field::VisitOutput,
     fmt::{
@@ -79,19 +82,31 @@ impl EventFormatter {
             }
         }
 
-        // serialize the current span and its leaves
+        // serialize the current span // and its leaves
         if let Some(span) = span {
             map.serialize_entry("span", &SerializableSpan::new(&span))?;
             // map.serialize_entry("spans", &SerializableContext::new(context))?; TODO: remove
         }
+        let mut trace_id = TraceIdVisitor::new();
+        context
+            .visit_spans(|span| {
+                for field in span.fields() {
+                    if field.name() == "trace_id" {
+                        let extensions = span.extensions();
+                        if let Some(json_fields) = extensions
+                            .get::<tracing_subscriber::fmt::FormattedFields<
+                            tracing_subscriber::fmt::format::JsonFields,
+                        >>() {
+                            json_fields.record(&field, &mut trace_id);
+                        }
+                    }
+                }
+                Ok::<(), Error>(())
+            })?;
 
-        // TODO: obtain and serialize trace_id here.
-        // if let Some(trace_id) = trace_id {
-        //     map.serialize_entry(
-        //         "logging.googleapis.com/trace",
-        //         &format!("projects/{project_id}/traces/{trace_id}",),
-        //     )?;
-        // }
+        if let Some(trace_id) = trace_id.trace_id {
+            map.serialize_entry("traceId", &trace_id)?;
+        }
 
         // serialize the stackdriver-specific fields with a visitor
         let mut visitor = Visitor::new(severity, map);
@@ -101,6 +116,35 @@ impl EventFormatter {
     }
 }
 
+/// A custom visitor that looks for the `trace_id` field and store its value.
+struct TraceIdVisitor {
+    trace_id: Option<String>,
+}
+impl TraceIdVisitor {
+    fn new() -> Self {
+        TraceIdVisitor { trace_id: None }
+    }
+}
+
+impl Visit for TraceIdVisitor {
+    fn record_str(&mut self, field: &Field, value: &str) {
+        if field.name() == "trace_id" {
+            // `trace_id` can be a json serialized string
+            // -- if so, we unpack it
+            let value = value
+                .split("\"trace_id\":")
+                .skip(1)
+                .filter(|quoted| quoted.len() >= 2)
+                .map(|quoted| &quoted[1..quoted.len() - 2])
+                .find(|_| true)
+                .unwrap_or(value);
+
+            self.trace_id = Some(value.to_string());
+        }
+    }
+    fn record_debug(&mut self, _field: &Field, _value: &dyn Debug) {}
+}
+
 impl<S> FormatEvent<S, JsonFields> for EventFormatter
 where
     S: Subscriber + for<'span> LookupSpan<'span>,