From 2bc0c4faf34d82eb00ac82120b84afe5f82ca238 Mon Sep 17 00:00:00 2001 From: Arpad Borsos Date: Tue, 20 Feb 2024 14:44:22 +0100 Subject: [PATCH] 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); + } +}