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

@@ -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]

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 }

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<S, N>,
+> {
+    inner: T,
+    _marker: std::marker::PhantomData<(S, N)>,
+}
+
+impl<S, N, T> CustEventFormatter<S, N, T>
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+    T: FormatEvent<S, N>,
+{
+    pub fn new(inner: T) -> Self {
+        Self {
+            inner,
+            _marker: std::marker::PhantomData,
+        }
+    }
+}
+
+impl<S, N, T> FormatEvent<S, N> for CustEventFormatter<S, N, T>
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+    N: for<'a> FormatFields<'a> + 'static,
+    T: FormatEvent<S, N>,
+{
+    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<String>,
+    typ: Option<String>,
+    stacktrace: Option<String>,
+}
+
+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)),
+            _ => {}
+        }
+    }
+}

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<String>,
+    stacktrace: impl Into<String>,
+    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::<String>() {
+        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",
+    );
+}

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
+/// <https://opentelemetry.io/docs/specs/semconv/exceptions/exceptions-spans/>
+///
+/// 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<T>`).
+pub fn record_exception(message: impl Into<String>, stacktrace: impl Into<String>) {
+    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<Cow<'static, str>>) -> Result<opentelemetry::metrics::Meter, AnyErr> {
+pub fn meter(
+    name: impl Into<std::borrow::Cow<'static, str>>,
+) -> Result<opentelemetry::metrics::Meter, AnyErr> {
     get_global()?.meter(name)
 }
 

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;

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<Cow<'static, str>>,
+        name: impl Into<std::borrow::Cow<'static, str>>,
     ) -> Result<opentelemetry::metrics::Meter, AnyErr> {
         use opentelemetry::metrics::MeterProvider;
 

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<GlobalLog, AnyErr> {
+    // 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<S, W>(
     writer: W,
 ) -> Result<Box<dyn Layer<S> + 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)
 }