diff --git a/Cargo.lock b/Cargo.lock index e80cb52..6aa6d3c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -12,6 +12,21 @@ dependencies = [ "regex", ] +[[package]] +name = "addr2line" +version = "0.21.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8a30b2e23b9e17a9f90641c7ab1549cd9b44f296d3ccbf309d2863cfe398a0cb" +dependencies = [ + "gimli", +] + +[[package]] +name = "adler" +version = "1.0.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f26201604c87b1e01bd3d98f8d5d9a8fcbb815e8cedb41ffccbeb4bf593a35fe" + [[package]] name = "aho-corasick" version = "1.1.1" @@ -21,6 +36,30 @@ dependencies = [ "memchr", ] +[[package]] +name = "backtrace" +version = "0.3.69" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2089b7e3f35b9dd2d0ed921ead4f6d318c27680d4a5bd167b3ee120edb105837" +dependencies = [ + "addr2line", + "cc", + "cfg-if", + "libc", + "miniz_oxide", + "object", + "rustc-demangle", +] + +[[package]] +name = "cc" +version = "1.0.83" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f1174fb0b6ec23863f8b971027804a42614e347eafb0a95bf0b12cdae21fc4d0" +dependencies = [ + "libc", +] + [[package]] name = "cfg-if" version = "1.0.0" @@ -37,6 +76,29 @@ dependencies = [ "serde", ] +[[package]] +name = "getrandom" +version = "0.2.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "be4136b2a15dd319360be1c07d9933517ccf0be8f16bf62a3bee4f0d618df427" +dependencies = [ + "cfg-if", + "libc", + "wasi", +] + +[[package]] +name = "gimli" +version = "0.28.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4271d37baee1b8c7e4b708028c57d816cf9d2434acb33a549475f78c181f6253" + +[[package]] +name = "hermit-abi" +version = "0.3.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bd5256b483761cd23699d0da46cc6fd2ee3be420bbe6d020ae4a091e70b7e9fd" + [[package]] name = "itoa" version = "1.0.9" @@ -49,6 +111,12 @@ version = "1.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e2abad23fbc42b3700f2f279844dc832adb2b2eb069b2df918f455c4e18cc646" +[[package]] +name = "libc" +version = "0.2.153" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9c198f91728a82281a64e1f4f9eeb25d82cb32a5de251c6bd1b5154d63a8e7bd" + [[package]] name = "log" version = "0.4.20" @@ -61,6 +129,15 @@ version = "2.6.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8f232d6ef707e1956a43342693d2a31e72989554d58299d7a88738cc95b0d35c" +[[package]] +name = "miniz_oxide" +version = "0.7.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9d811f3e15f28568be3407c8e7fdb6514c1cda3cb30683f15b6a1a1dc4ea14a7" +dependencies = [ + "adler", +] + [[package]] name = "nu-ansi-term" version = "0.46.0" @@ -71,6 +148,25 @@ dependencies = [ "winapi", ] +[[package]] +name = "num_cpus" +version = "1.16.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4161fcb6d602d4d2081af7c3a45852d875a03dd337a6bfdd6e06407b61342a43" +dependencies = [ + "hermit-abi", + "libc", +] + +[[package]] +name = "object" +version = "0.32.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6a622008b6e321afc04970976f62ee297fdbaa6f95318ca343e3eebb9648441" +dependencies = [ + "memchr", +] + [[package]] name = "once_cell" version = "1.18.0" @@ -142,6 +238,12 @@ version = "0.7.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "dbb5fb1acd8a1a18b3dd5be62d25485eb770e05afb408a9627d14d451bae12da" +[[package]] +name = "rustc-demangle" +version = "0.1.23" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d626bb9dae77e28219937af045c257c28bfd3f69333c512553507f5f9798cb76" + [[package]] name = "ryu" version = "1.0.15" @@ -275,6 +377,29 @@ dependencies = [ "time-core", ] +[[package]] +name = "tokio" +version = "1.36.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "61285f6515fa018fb2d1e46eb21223fff441ee8db5d0f1435e8ab4f5cdb80931" +dependencies = [ + "backtrace", + "num_cpus", + "pin-project-lite", + "tokio-macros", +] + +[[package]] +name = "tokio-macros" +version = "2.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5b8a1e28f2deaa14e508979454cb3a223b10b938b45af148bc0986de36f1923b" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.37", +] + [[package]] name = "tracing" version = "0.1.37" @@ -338,9 +463,11 @@ dependencies = [ "serde_json", "thiserror", "time", + "tokio", "tracing", "tracing-core", "tracing-subscriber", + "uuid", "valuable", "valuable-serde", ] @@ -368,6 +495,15 @@ version = "1.0.12" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3354b9ac3fae1ff6755cb6db53683adb661634f67557942dea4facebec0fee4b" +[[package]] +name = "uuid" +version = "1.7.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f00cc9702ca12d3c81455259621e676d0f7251cec66a21e98fe2e9a37db93b2a" +dependencies = [ + "getrandom", +] + [[package]] name = "valuable" version = "0.1.0" @@ -398,6 +534,12 @@ dependencies = [ "valuable", ] +[[package]] +name = "wasi" +version = "0.11.0+wasi-snapshot-preview1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9c8d87e72b64a3b4db28d11ce29237c246188f4f51057d65a7eab63b7987e423" + [[package]] name = "winapi" version = "0.3.9" diff --git a/Cargo.toml b/Cargo.toml index 03e0797..175151a 100644 --- a/Cargo.toml +++ b/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"] } diff --git a/examples/demo_full_fields.rs b/examples/demo_full_fields.rs new file mode 100644 index 0000000..4e53f29 --- /dev/null +++ b/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"} +} diff --git a/src/event_formatter.rs b/src/event_formatter.rs index cd26e42..8ee8b75 100644 --- a/src/event_formatter.rs +++ b/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::>() { + 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, +} +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| "ed[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 FormatEvent for EventFormatter where S: Subscriber + for<'span> LookupSpan<'span>, diff --git a/src/serializers.rs b/src/serializers.rs index f32aa38..bebd33e 100644 --- a/src/serializers.rs +++ b/src/serializers.rs @@ -37,7 +37,8 @@ where let span_length = formatted_fields.fields.len() + 1; let mut map = serializer.serialize_map(Some(span_length))?; - match serde_json::from_str::(formatted_fields) { // TODO: this seems weird + match serde_json::from_str::(formatted_fields) { + // TODO: this seems weird // handle string escaping "properly" (this should be fixed upstream) // https://github.com/tokio-rs/tracing/issues/391 Ok(Value::Object(fields)) => {