diff --git a/Cargo.lock b/Cargo.lock index 02d07091c..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]] @@ -2653,15 +2654,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 +4387,6 @@ dependencies = [ "tower-layer", "tower-service", "tracing", - "tracing-subscriber", "url", "uuid", ] @@ -4516,9 +4507,12 @@ dependencies = [ "symbolicator-test", "tempfile", "thiserror", + "time", "tokio", "tokio-util", "tracing", + "tracing-serde", + "tracing-subscriber", "url", "uuid", "zip", @@ -4561,7 +4555,6 @@ dependencies = [ "symbolicator-test", "tempfile", "tokio", - "tracing-subscriber", ] [[package]] @@ -4774,9 +4767,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..898c65b9d 100644 --- a/crates/symbolicator-service/Cargo.toml +++ b/crates/symbolicator-service/Cargo.toml @@ -38,9 +38,12 @@ 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"] } 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..94a87914e --- /dev/null +++ b/crates/symbolicator-service/src/logging.rs @@ -0,0 +1,446 @@ +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, +{ + 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); + } +} 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"