From a37323851c3f09a116430a0a37000d41842d578f Mon Sep 17 00:00:00 2001 From: Arpad Borsos Date: Tue, 20 Feb 2024 10:03:59 +0100 Subject: [PATCH 1/2] Move `tracing` init into its own file Also consolidates all the usage sites and removes unused feature flags --- Cargo.lock | 14 +------ Cargo.toml | 1 - crates/symbolicator-service/Cargo.toml | 1 + crates/symbolicator-service/src/lib.rs | 1 + crates/symbolicator-service/src/logging.rs | 24 +++++++++++ crates/symbolicator-stress/Cargo.toml | 1 - crates/symbolicator-stress/src/logging.rs | 47 ++++------------------ crates/symbolicator-test/Cargo.toml | 2 +- crates/symbolicator/Cargo.toml | 1 - crates/symbolicator/src/logging.rs | 14 ++----- crates/symbolicli/Cargo.toml | 2 +- 11 files changed, 39 insertions(+), 69 deletions(-) create mode 100644 crates/symbolicator-service/src/logging.rs diff --git a/Cargo.lock b/Cargo.lock index 02d07091c..942606744 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2653,15 +2653,6 @@ dependencies = [ "libc", ] -[[package]] -name = "num_threads" -version = "0.1.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5c7398b9c8b70908f6371f47ed36737907c87c52af34c268fed0bf0ceb92ead9" -dependencies = [ - "libc", -] - [[package]] name = "object" version = "0.32.2" @@ -4395,7 +4386,6 @@ dependencies = [ "tower-layer", "tower-service", "tracing", - "tracing-subscriber", "url", "uuid", ] @@ -4519,6 +4509,7 @@ dependencies = [ "tokio", "tokio-util", "tracing", + "tracing-subscriber", "url", "uuid", "zip", @@ -4561,7 +4552,6 @@ dependencies = [ "symbolicator-test", "tempfile", "tokio", - "tracing-subscriber", ] [[package]] @@ -4774,9 +4764,7 @@ checksum = "c8248b6521bb14bc45b4067159b9b6ad792e2d6d754d6c41fb50e29fefe38749" dependencies = [ "deranged", "itoa", - "libc", "num-conv", - "num_threads", "powerfmt", "serde", "time-core", diff --git a/Cargo.toml b/Cargo.toml index 9ef520ac6..35c36bfea 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -43,7 +43,6 @@ reqwest = { git = "https://github.com/getsentry/reqwest", branch = "restricted-c # This patch adds limited "templated lambdas" demangling support cpp_demangle = { git = "https://github.com/getsentry/cpp_demangle", branch = "sentry-patches" } - # For local development: uncomment the following three lines (and adjust the path if necessary) # to use a local symbolic checkout everywhere. # This only works for the very specific crate listed here, and not for its dependency tree. diff --git a/crates/symbolicator-service/Cargo.toml b/crates/symbolicator-service/Cargo.toml index d2b24c759..a0de76119 100644 --- a/crates/symbolicator-service/Cargo.toml +++ b/crates/symbolicator-service/Cargo.toml @@ -41,6 +41,7 @@ thiserror = "1.0.31" tokio = { version = "1.24.2", features = ["rt", "macros", "fs"] } tokio-util = { version = "0.7.1", features = ["io"] } tracing = "0.1.34" +tracing-subscriber = { version = "0.3.17", features = ["env-filter", "time", "json"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "1.0.0", features = ["v4", "serde"] } zip = { version = "0.6.4", default-features = false, features = ["deflate"] } diff --git a/crates/symbolicator-service/src/lib.rs b/crates/symbolicator-service/src/lib.rs index 0b58d4666..98d4f0ab3 100644 --- a/crates/symbolicator-service/src/lib.rs +++ b/crates/symbolicator-service/src/lib.rs @@ -8,6 +8,7 @@ pub mod caches; pub mod caching; pub mod config; pub mod download; +pub mod logging; pub mod objects; pub mod services; pub mod source_context; diff --git a/crates/symbolicator-service/src/logging.rs b/crates/symbolicator-service/src/logging.rs new file mode 100644 index 000000000..4a551e6f2 --- /dev/null +++ b/crates/symbolicator-service/src/logging.rs @@ -0,0 +1,24 @@ +use tracing_subscriber::fmt::time::UtcTime; +use tracing_subscriber::fmt::{fmt, MakeWriter}; +use tracing_subscriber::prelude::*; +use tracing_subscriber::util::SubscriberInitExt; + +pub fn init_json_logging(env_filter: &str, make_writer: W) +where + W: for<'writer> MakeWriter<'writer> + Send + Sync + 'static, +{ + fmt() + .with_timer(UtcTime::rfc_3339()) + .with_target(true) + .with_env_filter(env_filter) + .json() + .flatten_event(true) + .with_current_span(true) + .with_span_list(true) + .with_file(true) + .with_line_number(true) + .with_writer(make_writer) + .finish() + .with(sentry::integrations::tracing::layer()) + .init(); +} diff --git a/crates/symbolicator-stress/Cargo.toml b/crates/symbolicator-stress/Cargo.toml index 23c1c4e0b..90d12ee12 100644 --- a/crates/symbolicator-stress/Cargo.toml +++ b/crates/symbolicator-stress/Cargo.toml @@ -21,7 +21,6 @@ symbolicator-service = { path = "../symbolicator-service" } symbolicator-test = { path = "../symbolicator-test" } tempfile = "3.2.0" tokio = { version = "1.24.2", features = ["rt-multi-thread", "macros", "time", "sync"] } -tracing-subscriber = "0.3.17" [target.'cfg(not(target_env = "msvc"))'.dependencies] jemallocator = { version = "0.5", features = ["unprefixed_malloc_on_supported_platforms"] } diff --git a/crates/symbolicator-stress/src/logging.rs b/crates/symbolicator-stress/src/logging.rs index c5479b5c1..3c40807cd 100644 --- a/crates/symbolicator-stress/src/logging.rs +++ b/crates/symbolicator-stress/src/logging.rs @@ -1,14 +1,10 @@ use std::collections::BTreeMap; use std::env; use std::future::Future; -use std::io::Write; use std::net::{SocketAddr, TcpListener, UdpSocket}; use std::pin::Pin; -use symbolicator_service::metrics; -use tracing_subscriber::fmt::fmt; -use tracing_subscriber::fmt::time::UtcTime; -use tracing_subscriber::prelude::*; +use symbolicator_service::{logging, metrics}; #[derive(Debug, Default)] pub struct Config { @@ -61,27 +57,12 @@ pub fn init(config: Config) -> Guard { } if config.tracing { - let rust_log = "INFO"; - let subscriber = fmt() - .with_timer(UtcTime::rfc_3339()) - .with_target(true) - .with_env_filter(rust_log); - - // we want all the tracing machinery to be active, but not spam the console, - // so redirect everything into the void: - let subscriber = subscriber.with_writer(|| NoopWriter); - - // this should mimic the settings used in production: - subscriber - .json() - .flatten_event(true) - .with_current_span(true) - .with_span_list(true) - .with_file(true) - .with_line_number(true) - .finish() - .with(sentry::integrations::tracing::layer()) - .init(); + let env_filter = "INFO,\ + minidump=ERROR,\ + trust_dns_proto=WARN"; + // we want all the tracing machinery to be active and use the production JSON output, + // but not spam the console, so redirect everything into the void (`std::io::sink`): + logging::init_json_logging(env_filter, std::io::sink); } if config.metrics { @@ -111,17 +92,3 @@ pub fn init(config: Config) -> Guard { guard } - -struct NoopWriter; -impl Write for NoopWriter { - fn write(&mut self, buf: &[u8]) -> std::io::Result { - // try to prevent the compiler from optimizing away all the formatting code: - let buf = std::hint::black_box(buf); - - Ok(buf.len()) - } - - fn flush(&mut self) -> std::io::Result<()> { - Ok(()) - } -} diff --git a/crates/symbolicator-test/Cargo.toml b/crates/symbolicator-test/Cargo.toml index 4e757c092..691eea090 100644 --- a/crates/symbolicator-test/Cargo.toml +++ b/crates/symbolicator-test/Cargo.toml @@ -17,4 +17,4 @@ symbolicator-sources = { path = "../symbolicator-sources" } tempfile = "3.2.0" tokio = { version = "1.26.0", features = ["rt", "macros", "fs"] } tower-http = { version = "0.5.0", features = ["fs", "trace"] } -tracing-subscriber = { version = "0.3.17", features = ["tracing-log", "local-time", "env-filter", "json"] } +tracing-subscriber = { version = "0.3.17", features = ["env-filter"] } diff --git a/crates/symbolicator/Cargo.toml b/crates/symbolicator/Cargo.toml index 57f4dd247..f39e94cf8 100644 --- a/crates/symbolicator/Cargo.toml +++ b/crates/symbolicator/Cargo.toml @@ -36,7 +36,6 @@ tower = "0.4" tower-layer = "0.3" tower-service = "0.3" tracing = "0.1.34" -tracing-subscriber = { version = "0.3.17", features = ["tracing-log", "local-time", "env-filter", "json"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "1.0.0", features = ["v4", "serde"] } diff --git a/crates/symbolicator/src/logging.rs b/crates/symbolicator/src/logging.rs index 85aa1f9e3..721d8294a 100644 --- a/crates/symbolicator/src/logging.rs +++ b/crates/symbolicator/src/logging.rs @@ -1,5 +1,6 @@ use std::env; +use symbolicator_service::logging::init_json_logging; use tracing::level_filters::LevelFilter; use tracing_subscriber::fmt::fmt; use tracing_subscriber::fmt::time::UtcTime; @@ -52,7 +53,7 @@ pub fn init_logging(config: &Config) { let subscriber = fmt() .with_timer(UtcTime::rfc_3339()) .with_target(true) - .with_env_filter(rust_log); + .with_env_filter(&rust_log); match (config.logging.format, console::user_attended()) { (LogFormat::Auto, true) | (LogFormat::Pretty, _) => subscriber @@ -66,16 +67,7 @@ pub fn init_logging(config: &Config) { .finish() .with(sentry::integrations::tracing::layer()) .init(), - (LogFormat::Json, _) => subscriber - .json() - .flatten_event(true) - .with_current_span(true) - .with_span_list(true) - .with_file(true) - .with_line_number(true) - .finish() - .with(sentry::integrations::tracing::layer()) - .init(), + (LogFormat::Json, _) => init_json_logging(&rust_log, std::io::stdout), } } diff --git a/crates/symbolicli/Cargo.toml b/crates/symbolicli/Cargo.toml index f7a2eb150..7072a2723 100644 --- a/crates/symbolicli/Cargo.toml +++ b/crates/symbolicli/Cargo.toml @@ -23,5 +23,5 @@ tempfile = "3.3.0" tokio = { version = "1.24.2", features = ["rt-multi-thread", "macros", "time", "sync"] } toml = "0.8.0" tracing = "0.1.37" -tracing-subscriber = { version = "0.3.17", features = ["tracing-log", "local-time", "env-filter", "json"] } +tracing-subscriber = { version = "0.3.17", features = ["env-filter"] } url = "2.3.1" From 2bc0c4faf34d82eb00ac82120b84afe5f82ca238 Mon Sep 17 00:00:00 2001 From: Arpad Borsos Date: Tue, 20 Feb 2024 14:44:22 +0100 Subject: [PATCH 2/2] Create a `tracing` layer doing JSON output and Sentry at once Using composition to chain the JSON output and the Sentry layer means that both layers are capturing span attributes, duplicating that work. This pretty much copy-pasted the code of both these layers and combines them, thus avoiding doing all the `SpanAttribute` capturing twice. --- Cargo.lock | 3 + crates/symbolicator-service/Cargo.toml | 2 + crates/symbolicator-service/src/logging.rs | 454 ++++++++++++++++++++- 3 files changed, 443 insertions(+), 16 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 942606744..dc54770a4 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1245,6 +1245,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b42b6fa04a440b495c8b04d0e71b707c585f83cb9cb28cf8cd0d976c315e31b4" dependencies = [ "powerfmt", + "serde", ] [[package]] @@ -4506,9 +4507,11 @@ dependencies = [ "symbolicator-test", "tempfile", "thiserror", + "time", "tokio", "tokio-util", "tracing", + "tracing-serde", "tracing-subscriber", "url", "uuid", diff --git a/crates/symbolicator-service/Cargo.toml b/crates/symbolicator-service/Cargo.toml index a0de76119..898c65b9d 100644 --- a/crates/symbolicator-service/Cargo.toml +++ b/crates/symbolicator-service/Cargo.toml @@ -38,9 +38,11 @@ symbolic = { version = "12.7.1", features = ["cfi", "common-serde", "debuginfo", symbolicator-sources = { path = "../symbolicator-sources" } tempfile = "3.2.0" thiserror = "1.0.31" +time = { version = "0.3.34", features = ["serde", "formatting"] } tokio = { version = "1.24.2", features = ["rt", "macros", "fs"] } tokio-util = { version = "0.7.1", features = ["io"] } tracing = "0.1.34" +tracing-serde = "0.1.3" tracing-subscriber = { version = "0.3.17", features = ["env-filter", "time", "json"] } url = { version = "2.2.0", features = ["serde"] } uuid = { version = "1.0.0", features = ["v4", "serde"] } diff --git a/crates/symbolicator-service/src/logging.rs b/crates/symbolicator-service/src/logging.rs index 4a551e6f2..94a87914e 100644 --- a/crates/symbolicator-service/src/logging.rs +++ b/crates/symbolicator-service/src/logging.rs @@ -1,24 +1,446 @@ -use tracing_subscriber::fmt::time::UtcTime; -use tracing_subscriber::fmt::{fmt, MakeWriter}; -use tracing_subscriber::prelude::*; +use std::cell::RefCell; +use std::collections::BTreeMap; +use std::error::Error; + +use sentry::integrations::tracing::{breadcrumb_from_event, event_from_event}; +use sentry::protocol::Exception; +use sentry::{event_from_error, TransactionOrSpan}; +use serde::ser::SerializeMap as _; +use serde::{Serialize, Serializer}; +use serde_json::Value; +use time::OffsetDateTime; +use tracing::field::{Field, Visit}; +use tracing::{span, Event, Level, Subscriber}; +use tracing_serde::AsSerde; +use tracing_subscriber::fmt::MakeWriter; +use tracing_subscriber::layer::{Context, Layer}; +use tracing_subscriber::registry::{LookupSpan, SpanRef}; use tracing_subscriber::util::SubscriberInitExt; +use tracing_subscriber::{prelude::*, registry, EnvFilter, Registry}; pub fn init_json_logging(env_filter: &str, make_writer: W) where W: for<'writer> MakeWriter<'writer> + Send + Sync + 'static, { - fmt() - .with_timer(UtcTime::rfc_3339()) - .with_target(true) - .with_env_filter(env_filter) - .json() - .flatten_event(true) - .with_current_span(true) - .with_span_list(true) - .with_file(true) - .with_line_number(true) - .with_writer(make_writer) - .finish() - .with(sentry::integrations::tracing::layer()) + Registry::default() + .with(SymbolicatorLayer(make_writer).with_filter(EnvFilter::new(env_filter))) .init(); } + +struct SymbolicatorLayer(W); + +/// Data that is attached to the tracing Spans `extensions`, in order to +/// `finish` the corresponding sentry span `on_close`, and re-set its parent as +/// the *current* span. +struct SymbolicatorSpanData { + span_attrs: BTreeMap<&'static str, Value>, + sentry_span: TransactionOrSpan, + parent_sentry_span: Option, +} + +#[derive(Serialize)] +struct JsonFormattedLog<'s, 'c, Span> +where + Span: Subscriber + for<'lookup> registry::LookupSpan<'lookup>, +{ + level: tracing_serde::SerializeLevel<'s>, + target: &'s str, + #[serde(skip_serializing_if = "Option::is_none")] + filename: Option<&'s str>, + #[serde(skip_serializing_if = "Option::is_none")] + line_number: Option, + + #[serde(with = "time::serde::rfc3339")] + timestamp: OffsetDateTime, + + #[serde(flatten)] + event: EventFieldsAdapter<'s>, + #[serde(skip_serializing_if = "Option::is_none")] + #[serde(bound(serialize = ""))] + span: Option>, + #[serde(skip_serializing_if = "Option::is_none")] + #[serde(bound(serialize = ""))] + spans: Option>, +} + +struct SerializableContext<'a, 'b, Span>(&'b Context<'a, Span>) +where + Span: Subscriber + for<'lookup> LookupSpan<'lookup>; + +impl<'a, 'b, Span> serde::ser::Serialize for SerializableContext<'a, 'b, Span> +where + Span: Subscriber + for<'lookup> LookupSpan<'lookup>, +{ + fn serialize(&self, serializer_o: Ser) -> Result + where + Ser: serde::ser::Serializer, + { + use serde::ser::SerializeSeq; + let mut serializer = serializer_o.serialize_seq(None)?; + + if let Some(leaf_span) = self.0.lookup_current() { + for span in leaf_span.scope().from_root() { + serializer.serialize_element(&SerializableSpan(&span))?; + } + } + + serializer.end() + } +} + +struct SerializableSpan<'a, 'b, Span>(&'b SpanRef<'a, Span>) +where + Span: for<'lookup> LookupSpan<'lookup>; + +impl<'a, 'b, Span> serde::ser::Serialize for SerializableSpan<'a, 'b, Span> +where + Span: for<'lookup> LookupSpan<'lookup>, +{ + fn serialize(&self, serializer: Ser) -> Result + where + Ser: serde::ser::Serializer, + { + let mut serializer = serializer.serialize_map(None)?; + + let ext = self.0.extensions(); + let data = ext + .get::() + .expect("Unable to find `SymbolicatorSpanData` in extensions; this is a bug"); + + for (key, value) in &data.span_attrs { + serializer.serialize_entry(*key, value)?; + } + serializer.serialize_entry("name", self.0.metadata().name())?; + serializer.end() + } +} + +struct EventFieldsAdapter<'s>(&'s Event<'s>); + +impl Serialize for EventFieldsAdapter<'_> { + fn serialize(&self, serializer: S) -> Result + where + S: Serializer, + { + let serializer = serializer.serialize_map(None)?; + let mut visitor = tracing_serde::SerdeMapVisitor::new(serializer); + self.0.record(&mut visitor); + let serializer = visitor.take_serializer()?; + serializer.end() + } +} + +impl Layer for SymbolicatorLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, + W: for<'writer> MakeWriter<'writer> + 'static, +{ + fn on_event(&self, event: &Event, ctx: Context<'_, S>) { + match *event.metadata().level() { + Level::ERROR => { + sentry::capture_event(event_from_event(event, None::>)); + } + Level::WARN | Level::INFO => { + sentry::add_breadcrumb(breadcrumb_from_event(event)); + } + _ => {} + } + + let meta = event.metadata(); + let current_span = event + .parent() + .and_then(|id| ctx.span(id)) + .or_else(|| ctx.lookup_current()); + + let json = JsonFormattedLog { + level: meta.level().as_serde(), + target: meta.target(), + filename: meta.file(), + line_number: meta.line(), + timestamp: OffsetDateTime::now_utc(), + event: EventFieldsAdapter(event), + + span: current_span.as_ref().map(SerializableSpan), + spans: current_span.as_ref().map(|_| SerializableContext(&ctx)), + }; + + let writer = self.0.make_writer(); + let _ = serde_json::to_writer(writer, &json); + } + + /// When a new Span gets created, run the filter and start a new sentry span + /// if it passes, setting it as the *current* sentry span. + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + let span = match ctx.span(id) { + Some(span) => span, + None => return, + }; + + if *span.metadata().level() > Level::INFO { + return; + } + + let (description, span_attrs) = extract_span_data(attrs); + let op = span.name(); + + // Spans don't always have a description, this ensures our data is not empty, + // therefore the Sentry UI will be a lot more valuable for navigating spans. + let description = description.unwrap_or_else(|| { + let target = span.metadata().target(); + if target.is_empty() { + op.to_string() + } else { + format!("{target}::{op}") + } + }); + + let parent_sentry_span = sentry::configure_scope(|s| s.get_span()); + let sentry_span: sentry::TransactionOrSpan = match &parent_sentry_span { + Some(parent) => parent.start_child(op, &description).into(), + None => { + let ctx = sentry::TransactionContext::new(&description, op); + sentry::start_transaction(ctx).into() + } + }; + // Add the data from the original span to the sentry span. + // This comes from typically the `fields` in `tracing::instrument`. + for (key, value) in &span_attrs { + if *key != "message" { + sentry_span.set_data(key, value.clone()); + } + } + + sentry::configure_scope(|scope| scope.set_span(Some(sentry_span.clone()))); + + let mut extensions = span.extensions_mut(); + extensions.insert(SymbolicatorSpanData { + span_attrs, + sentry_span, + parent_sentry_span, + }); + } + + /// When a span gets closed, finish the underlying sentry span, and set back + /// its parent as the *current* sentry span. + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + let span = match ctx.span(&id) { + Some(span) => span, + None => return, + }; + + let mut extensions = span.extensions_mut(); + let SymbolicatorSpanData { + sentry_span, + parent_sentry_span, + .. + } = match extensions.remove::() { + Some(data) => data, + None => return, + }; + + sentry_span.finish(); + sentry::configure_scope(|scope| scope.set_span(parent_sentry_span)); + } + + /// Implement the writing of extra data to span + fn on_record(&self, span: &span::Id, attrs: &span::Record<'_>, ctx: Context<'_, S>) { + let span = match ctx.span(span) { + Some(s) => s, + _ => return, + }; + + let mut extensions = span.extensions_mut(); + let Some(data) = extensions.get_mut::() else { + return; + }; + + let json_values = VISITOR_BUFFER.with_borrow_mut(|buf| { + let mut visitor = FieldVisitor::with_buf(buf); + attrs.record(&mut visitor); + visitor.json_values + }); + + for (key, value) in &json_values { + data.sentry_span.set_data(key, value.clone()); + } + data.span_attrs.extend(json_values); + } +} + +/// Extracts the message and metadata from a span +fn extract_span_data(attrs: &span::Attributes) -> (Option, BTreeMap<&'static str, Value>) { + let json_values = VISITOR_BUFFER.with_borrow_mut(|buf| { + let mut visitor = FieldVisitor::with_buf(buf); + attrs.record(&mut visitor); + visitor.json_values + }); + + // Find message of the span, if any + let message = json_values + .get("message") + .and_then(|v| v.as_str().map(|s| s.to_owned())); + + (message, json_values) +} + +thread_local! { + static VISITOR_BUFFER: RefCell = const { RefCell::new(String::new()) }; +} + +/// Records all fields of [`tracing_core::Event`] for easy access +struct FieldVisitor<'s> { + buf: &'s mut String, + json_values: BTreeMap<&'static str, Value>, + exceptions: Vec, +} + +impl<'s> FieldVisitor<'s> { + fn with_buf(buf: &'s mut String) -> Self { + Self { + buf, + json_values: BTreeMap::new(), + exceptions: vec![], + } + } + fn record>(&mut self, field: &Field, value: T) { + self.json_values.insert(field.name(), value.into()); + } +} + +impl Visit for FieldVisitor<'_> { + fn record_i64(&mut self, field: &Field, value: i64) { + self.record(field, value); + } + + fn record_u64(&mut self, field: &Field, value: u64) { + self.record(field, value); + } + + fn record_bool(&mut self, field: &Field, value: bool) { + self.record(field, value); + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.record(field, value); + } + + fn record_error(&mut self, _field: &Field, value: &(dyn Error + 'static)) { + let event = event_from_error(value); + for exception in event.exception { + self.exceptions.push(exception); + } + } + + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + use std::fmt::Write; + write!(self.buf, "{value:?}").unwrap(); + self.json_values + .insert(field.name(), self.buf.as_str().into()); + self.buf.clear(); + } +} + +#[cfg(test)] +mod tests { + use std::io; + use std::sync::{Arc, Mutex, MutexGuard}; + + use tracing_subscriber::fmt::time::UtcTime; + use tracing_subscriber::Registry; + + use super::*; + + pub(crate) struct MockWriter { + buf: Arc>>, + } + + impl MockWriter { + pub(crate) fn new(buf: Arc>>) -> Self { + Self { buf } + } + + pub(crate) fn buf(&self) -> MutexGuard<'_, Vec> { + self.buf.lock().unwrap() + } + } + + impl io::Write for MockWriter { + fn write(&mut self, buf: &[u8]) -> io::Result { + self.buf().write(buf) + } + + fn flush(&mut self) -> io::Result<()> { + self.buf().flush() + } + } + + #[derive(Clone, Default)] + pub(crate) struct MockMakeWriter { + buf: Arc>>, + } + + impl MockMakeWriter { + pub(crate) fn new(buf: Arc>>) -> Self { + Self { buf } + } + + pub(crate) fn get_string(&self) -> String { + let mut buf = self.buf.lock().expect("lock shouldn't be poisoned"); + let string = std::str::from_utf8(&buf[..]) + .expect("formatter should not have produced invalid utf-8") + .to_owned(); + buf.clear(); + string + } + } + + impl<'a> MakeWriter<'a> for MockMakeWriter { + type Writer = MockWriter; + + fn make_writer(&'a self) -> Self::Writer { + MockWriter::new(self.buf.clone()) + } + } + + fn event_without_timestamp(writer: &MockMakeWriter) -> Value { + let mut value: Value = serde_json::from_str(&writer.get_string()).unwrap(); + if let Some(obj) = value.as_object_mut() { + obj.remove("timestamp"); + } + value + } + + #[test] + fn custom_layer_is_same_as_fmt() { + let fmt_writer = MockMakeWriter::new(Default::default()); + let sym_writer = MockMakeWriter::new(Default::default()); + + let fmt = tracing_subscriber::fmt::layer() + .with_timer(UtcTime::rfc_3339()) + .with_target(true) + .json() + .flatten_event(true) + .with_current_span(true) + .with_span_list(true) + .with_file(true) + .with_line_number(true) + .with_writer(fmt_writer.clone()); + + let subscriber = Registry::default() + .with(fmt) + .with(SymbolicatorLayer(sym_writer.clone())); + + { + let _guard = subscriber.set_default(); + let _span = tracing::info_span!("some span").entered(); + let _child_span = tracing::info_span!("another span", with = ?"data").entered(); + tracing::error!("lets log some shit!"); + } + + let fmt = event_without_timestamp(&fmt_writer); + let sym = event_without_timestamp(&sym_writer); + + dbg!(&fmt, &sym); + assert_eq!(fmt, sym); + } +}