From 22434c2ca283e81c0af1b307517cfc44264c7ad6 Mon Sep 17 00:00:00 2001 From: Zak Stucke Date: Sun, 18 Feb 2024 16:05:55 +0200 Subject: [PATCH 1/2] Auto tracing panics, easy recording interface when wanting to add exceptions, special formatting of exceptions for stdout and file to make them look more like stacktraces --- py/pyproject.toml | 8 +- rust/Cargo.toml | 3 +- .../log/global_log/event_formatter.rs | 102 ++++++++++++++++++ rust/bitbazaar/log/global_log/exceptions.rs | 43 ++++++++ rust/bitbazaar/log/global_log/global_fns.rs | 17 ++- rust/bitbazaar/log/global_log/mod.rs | 2 + rust/bitbazaar/log/global_log/out.rs | 4 +- rust/bitbazaar/log/global_log/setup.rs | 90 ++++++++++++---- rust/bitbazaar/log/mod.rs | 51 ++++++++- 9 files changed, 288 insertions(+), 32 deletions(-) create mode 100644 rust/bitbazaar/log/global_log/event_formatter.rs create mode 100644 rust/bitbazaar/log/global_log/exceptions.rs diff --git a/py/pyproject.toml b/py/pyproject.toml index 8b464a51..00f3f9d0 100644 --- a/py/pyproject.toml +++ b/py/pyproject.toml @@ -40,11 +40,11 @@ classifiers = [ ] dependencies = [ - "lazy-object-proxy>=1.8.0,<2.0.0", + "lazy-object-proxy>=1.8.0", "rich>=13.6.0", - "opentelemetry-api>=1.20.0,<2.0.0", - "opentelemetry-sdk>=1.20.0,<2.0.0", - "opentelemetry-exporter-otlp>=1.20.0,<2.0.0", + "opentelemetry-api>=1.20.0", + "opentelemetry-sdk>=1.20.0", + "opentelemetry-exporter-otlp>=1.20.0", ] [project.urls] diff --git a/rust/Cargo.toml b/rust/Cargo.toml index a7d2ec7d..cbdd02e0 100644 --- a/rust/Cargo.toml +++ b/rust/Cargo.toml @@ -23,7 +23,6 @@ all-features = true cli = ['dep:normpath', 'dep:conch-parser', 'dep:homedir'] redis = ['dep:deadpool-redis', 'dep:redis', 'dep:sha1_smol'] opentelemetry = [ - 'dep:tracing-core', 'dep:tracing-log', 'dep:opentelemetry-appender-tracing', 'dep:opentelemetry_sdk', @@ -38,6 +37,7 @@ opentelemetry = [ [dependencies] parking_lot = { version = "0.12", features = ["deadlock_detection", "serde"] } tracing = "0.1" +tracing-core = "0.1" error-stack = "0.4" chrono = '0.4' colored = '2.0' @@ -64,7 +64,6 @@ redis = { version = "0.24", default-features = false, features = ["aio", "json"] sha1_smol = { version = "1.0", optional = true } # FEAT: opentelemetry: -tracing-core = { version = "0.1", optional = true } # Only needed whilst we're using ot_tracing_bridge.rs tracing-log = { version = "0.2", optional = true } # Only needed whilst we're using ot_tracing_bridge.rs opentelemetry-appender-tracing = { version = "0.2.0", optional = true } opentelemetry_sdk = { version = "0.21", features = ["rt-tokio"], optional = true } diff --git a/rust/bitbazaar/log/global_log/event_formatter.rs b/rust/bitbazaar/log/global_log/event_formatter.rs new file mode 100644 index 00000000..f4ca56dd --- /dev/null +++ b/rust/bitbazaar/log/global_log/event_formatter.rs @@ -0,0 +1,102 @@ +use tracing_core::Subscriber; +use tracing_subscriber::{ + fmt::{format::Writer, FmtContext, FormatEvent, FormatFields}, + registry::LookupSpan, +}; + +pub struct CustEventFormatter< + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + T: FormatEvent, +> { + inner: T, + _marker: std::marker::PhantomData<(S, N)>, +} + +impl CustEventFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + T: FormatEvent, +{ + pub fn new(inner: T) -> Self { + Self { + inner, + _marker: std::marker::PhantomData, + } + } +} + +impl FormatEvent for CustEventFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + T: FormatEvent, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &tracing::Event<'_>, + ) -> std::fmt::Result { + let exception_fields = [ + "exception.message", + "exception.type", + "exception.stacktrace", + ]; + let meta = event.metadata(); + + let mut is_exception = false; + for field in meta.fields() { + if exception_fields.contains(&field.name()) { + is_exception = true; + break; + } + } + + if is_exception { + let mut visitor = ExceptionEventVisitor::default(); + event.record(&mut visitor); + if let Some(stacktrace) = visitor.stacktrace.as_ref() { + writeln!(writer, "{}", clean_string(stacktrace))?; + } + if let Some(typ) = visitor.typ.as_ref() { + if let Some(message) = visitor.message.as_ref() { + writeln!(writer, "{}: {}", clean_string(typ), clean_string(message))?; + } else { + writeln!(writer, "{}", clean_string(typ))?; + } + } else if let Some(message) = visitor.message.as_ref() { + writeln!(writer, "{}", clean_string(message))?; + } + Ok(()) + } else { + self.inner.format_event(ctx, writer, event) + } + } +} + +#[inline] +/// Weirdly they seem to come in with quotes around them, this simple removes them. +/// In a sep func to allow extending if needed. +fn clean_string(s: &str) -> &str { + s.trim_matches('"') +} + +#[derive(Default)] +struct ExceptionEventVisitor { + message: Option, + typ: Option, + stacktrace: Option, +} + +impl tracing::field::Visit for ExceptionEventVisitor { + fn record_debug(&mut self, field: &tracing_core::Field, value: &dyn std::fmt::Debug) { + match field.name() { + "exception.message" => self.message = Some(format!("{:?}", value)), + "exception.type" => self.typ = Some(format!("{:?}", value)), + "exception.stacktrace" => self.stacktrace = Some(format!("{:?}", value)), + _ => {} + } + } +} diff --git a/rust/bitbazaar/log/global_log/exceptions.rs b/rust/bitbazaar/log/global_log/exceptions.rs new file mode 100644 index 00000000..968097d0 --- /dev/null +++ b/rust/bitbazaar/log/global_log/exceptions.rs @@ -0,0 +1,43 @@ +// Inner for record_exception to allow specifying type internally. +pub fn record_exception_inner( + message: impl Into, + stacktrace: impl Into, + typ: &str, +) { + tracing::event!( + tracing::Level::ERROR, + name = "exception", // Must be named this for observers to recognise it as an exception + exception.message = message.into(), + exception.stacktrace = stacktrace.into(), + "exception.type" = typ + ); +} + +/// Setup the program to automatically log panics as an error event on the current span. +pub fn auto_trace_panics() { + let prev_hook = std::panic::take_hook(); + std::panic::set_hook(Box::new(move |panic_info| { + panic_hook(panic_info); + prev_hook(panic_info); + })); +} + +fn panic_hook(panic_info: &std::panic::PanicInfo) { + let payload = panic_info.payload(); + + #[allow(clippy::manual_map)] + let payload = if let Some(s) = payload.downcast_ref::<&str>() { + Some(&**s) + } else if let Some(s) = payload.downcast_ref::() { + Some(s.as_str()) + } else { + None + }; + + let location = panic_info.location().map(|l| l.to_string()); + super::exceptions::record_exception_inner( + payload.unwrap_or("Panic missing message."), + location.unwrap_or_else(|| "Panic missing location.".to_string()), + "Panic", + ); +} diff --git a/rust/bitbazaar/log/global_log/global_fns.rs b/rust/bitbazaar/log/global_log/global_fns.rs index 5881f089..70aa4997 100644 --- a/rust/bitbazaar/log/global_log/global_fns.rs +++ b/rust/bitbazaar/log/global_log/global_fns.rs @@ -1,10 +1,19 @@ -use std::borrow::Cow; - use parking_lot::{MappedMutexGuard, MutexGuard}; use super::{out::GLOBAL_LOG, GlobalLog}; use crate::prelude::*; +/// Record an exception to the currently active span. +/// Matches oltp spec so it shows up correctly as an exception in observers +/// +/// +/// Arguments: +/// - `message`: Information about the exception e.g. `Internal Error leading to 500 http response`. +/// - `stacktrace`: All of the location information for the exception, (maybe also the exception itself if e.g. from `Report`). +pub fn record_exception(message: impl Into, stacktrace: impl Into) { + super::exceptions::record_exception_inner(message, stacktrace, "Err"); +} + #[cfg(feature = "opentelemetry")] /// Returns a new [`opentelemetry::metrics::Meter`] with the provided name and default configuration. /// @@ -14,7 +23,9 @@ use crate::prelude::*; /// /// If the name is empty, then an implementation defined default name will /// be used instead. -pub fn meter(name: impl Into>) -> Result { +pub fn meter( + name: impl Into>, +) -> Result { get_global()?.meter(name) } diff --git a/rust/bitbazaar/log/global_log/mod.rs b/rust/bitbazaar/log/global_log/mod.rs index 3181450f..bb6ded6f 100644 --- a/rust/bitbazaar/log/global_log/mod.rs +++ b/rust/bitbazaar/log/global_log/mod.rs @@ -1,4 +1,6 @@ mod builder; +mod event_formatter; +mod exceptions; pub mod global_fns; #[cfg(feature = "opentelemetry")] mod http_headers; diff --git a/rust/bitbazaar/log/global_log/out.rs b/rust/bitbazaar/log/global_log/out.rs index 884c6241..b5a65b3a 100644 --- a/rust/bitbazaar/log/global_log/out.rs +++ b/rust/bitbazaar/log/global_log/out.rs @@ -1,5 +1,3 @@ -use std::borrow::Cow; - use once_cell::sync::Lazy; use parking_lot::Mutex; use tracing::{Dispatch, Level}; @@ -94,7 +92,7 @@ impl GlobalLog { /// See [`super::global_fns::meter`]` pub fn meter( &self, - name: impl Into>, + name: impl Into>, ) -> Result { use opentelemetry::metrics::MeterProvider; diff --git a/rust/bitbazaar/log/global_log/setup.rs b/rust/bitbazaar/log/global_log/setup.rs index 2096a72c..9ce8f3ba 100644 --- a/rust/bitbazaar/log/global_log/setup.rs +++ b/rust/bitbazaar/log/global_log/setup.rs @@ -1,10 +1,8 @@ use tracing::{Dispatch, Level, Metadata, Subscriber}; -use tracing_subscriber::{ - filter::FilterFn, fmt::MakeWriter, prelude::*, registry::LookupSpan, Layer, -}; +use tracing_subscriber::{filter::FilterFn, layer::SubscriberExt, registry::LookupSpan, Layer}; use super::{builder::GlobalLogBuilder, GlobalLog}; -use crate::prelude::*; +use crate::{log::global_log::event_formatter::CustEventFormatter, prelude::*}; /// Need the write trait for our write function. impl std::io::Write for super::builder::CustomConf { @@ -29,6 +27,13 @@ impl<'writer> tracing_subscriber::fmt::MakeWriter<'writer> for super::builder::C } pub fn builder_into_global_log(builder: GlobalLogBuilder) -> Result { + // Configure the program to automatically log panics as an error event on the current span: + super::exceptions::auto_trace_panics(); + + #[cfg(feature = "opentelemetry")] + // If opentelemetry being used, error_stacks should have color turned off, this would break text in external viewers outside terminals: + error_stack::Report::set_color_mode(error_stack::fmt::ColorMode::None); + let all_loc_matchers = builder .outputs .iter() @@ -253,20 +258,41 @@ fn create_fmt_layer( writer: W, ) -> Result + Send + Sync + 'static>, AnyErr> where - S: Subscriber, + S: Subscriber + Send + Sync + 'static, for<'a> S: LookupSpan<'a>, // Each layer has a different type, so have to box for return - W: for<'writer> MakeWriter<'writer> + Send + Sync + 'static, // Allows all writers to be passed in before boxing + W: for<'writer> tracing_subscriber::fmt::MakeWriter<'writer> + Send + Sync + 'static, // Allows all writers to be passed in before boxing { - let base_layer = tracing_subscriber::fmt::layer() - .with_level(true) - .with_target(false) - .with_file(include_loc) - .with_line_number(include_loc) - .with_ansi(include_color) - .with_writer(writer); + /// README: This is all so complicated because tracing_subscriber layers all have distinct types depending on the args. + /// We also override the event formatter with our own that defers to the original for everything except exception events, + /// for exception events we try and keep like a usual stacktrace. + /// + /// The macros are all about keeping the code concise, despite the different types and repeated usage (due to lack of clone) + + macro_rules! base { + ($layer_or_fmt:expr) => { + $layer_or_fmt + .with_level(true) + .with_target(false) + .with_file(include_loc) + .with_line_number(include_loc) + .with_ansi(include_color) + }; + } + + macro_rules! base_layer { + () => { + base!(tracing_subscriber::fmt::layer()).with_writer(writer) + }; + } + + macro_rules! base_format { + () => { + base!(tracing_subscriber::fmt::format()) + }; + } // Annoying have to duplicate, but pretty/compact & time both change the type and prevents adding the filter at the end before boxing: - if include_timestamp { + let layer = if include_timestamp { // Create the custom timer, given either stdout or a file rotated daily, no need for date in the log, // also no need for any more than ms precision, // also make it a UTC time: @@ -277,13 +303,39 @@ where let timer = tracing_subscriber::fmt::time::OffsetTime::new(time_offset, timer); if pretty { - Ok(base_layer.pretty().with_timer(timer).boxed()) + base_layer!() + .pretty() + .with_timer(timer.clone()) + .event_format(CustEventFormatter::new( + base_format!().pretty().with_timer(timer), + )) + .boxed() } else { - Ok(base_layer.compact().with_timer(timer).boxed()) + base_layer!() + .compact() + .with_timer(timer.clone()) + .event_format(CustEventFormatter::new( + base_format!().compact().with_timer(timer), + )) + .boxed() } } else if pretty { - Ok(base_layer.pretty().without_time().boxed()) + base_layer!() + .pretty() + .without_time() + .event_format(CustEventFormatter::new( + base_format!().pretty().without_time(), + )) + .boxed() } else { - Ok(base_layer.compact().without_time().boxed()) - } + base_layer!() + .compact() + .without_time() + .event_format(CustEventFormatter::new( + base_format!().compact().without_time(), + )) + .boxed() + }; + + Ok(layer) } diff --git a/rust/bitbazaar/log/mod.rs b/rust/bitbazaar/log/mod.rs index 1a41bf83..96e05de1 100644 --- a/rust/bitbazaar/log/mod.rs +++ b/rust/bitbazaar/log/mod.rs @@ -11,7 +11,10 @@ pub use global_log::{global_fns::*, GlobalLog}; #[cfg(test)] mod tests { - use std::collections::{HashMap, HashSet}; + use std::{ + collections::{HashMap, HashSet}, + sync::atomic::AtomicU32, + }; use once_cell::sync::Lazy; use parking_lot::Mutex; @@ -196,6 +199,52 @@ mod tests { Ok(()) } + /// - Confirm record_exception() and is recorded as an exception event on active span. + /// - Confirm panic() is auto recorded as an exception event on active span. + /// - Confirm both are recognised internally as exception events and use a custom formatter to give nice error messages. + #[rstest] + fn test_exception_recording() -> Result<(), AnyErr> { + static LOGS: Lazy>> = Lazy::new(Mutex::default); + { + // Fn repeat usage so static needs clearing each time: + LOGS.lock().clear(); + } + + let log = GlobalLog::builder() + .custom(false, false, false, false, |log| { + LOGS.lock() + .push(String::from_utf8_lossy(log).trim().to_string()); + }) + .build()?; + + // Programmatically keeping line in check, atomic needed due to catch_unwind: + let line_preceding_panic = AtomicU32::new(0); + log.with_tmp_global(|| { + // Manual record: + record_exception("test_exc", "test_stack"); + + // Panics should be auto recorded: + let _ = std::panic::catch_unwind(|| { + line_preceding_panic.store(line!(), std::sync::atomic::Ordering::Relaxed); + panic!("test_panic"); + }); + })?; + + let out = into_vec(&LOGS); + assert_eq!( + out, + vec![ + "test_stack\nErr: test_exc".to_string(), + format!( + "bitbazaar/log/mod.rs:{}:17\nPanic: test_panic", + line_preceding_panic.load(std::sync::atomic::Ordering::Relaxed) + 1 + ) + ] + ); + + Ok(()) + } + #[rstest] fn test_log_to_file() -> Result<(), AnyErr> { let temp_dir = tempdir().change_context(AnyErr)?; From c66403ca5f51ed0da9e6135916dc301943633179 Mon Sep 17 00:00:00 2001 From: Zak Stucke Date: Sun, 18 Feb 2024 16:17:11 +0200 Subject: [PATCH 2/2] Fix windows --- rust/bitbazaar/log/mod.rs | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/rust/bitbazaar/log/mod.rs b/rust/bitbazaar/log/mod.rs index 96e05de1..7ec4f490 100644 --- a/rust/bitbazaar/log/mod.rs +++ b/rust/bitbazaar/log/mod.rs @@ -231,14 +231,20 @@ mod tests { })?; let out = into_vec(&LOGS); + let exp_panic_loc = [ + "bitbazaar".to_string(), + "log".to_string(), + format!( + "mod.rs:{}:17", + line_preceding_panic.load(std::sync::atomic::Ordering::Relaxed) + 1 + ), + ] + .join(if cfg!(windows) { "\\\\" } else { "/" }); assert_eq!( out, vec![ "test_stack\nErr: test_exc".to_string(), - format!( - "bitbazaar/log/mod.rs:{}:17\nPanic: test_panic", - line_preceding_panic.load(std::sync::atomic::Ordering::Relaxed) + 1 - ) + format!("{}\nPanic: test_panic", exp_panic_loc) ] );