Skip to content

Commit

Permalink
add support for instrumented functions which return Result
Browse files Browse the repository at this point in the history
Currently, the instrumentation macro emits a single event after the
function call, but in the current span, with just a field named error
set.
This commit adds support to use this event to fill the span status error
description with the content of the error field of this event.
The mapping is optional and can be configured using the
ErrorFieldConfig.
  • Loading branch information
valkum committed Jun 22, 2023
1 parent 040c57a commit 37ec0bc
Show file tree
Hide file tree
Showing 3 changed files with 428 additions and 0 deletions.
187 changes: 187 additions & 0 deletions examples/opentelemetry-error.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,187 @@
use std::{
error::Error as StdError,
fmt::{Debug, Display},
io::Write,
thread,
time::{Duration, SystemTime},
};

use opentelemetry::{
global,
sdk::{
self,
export::trace::{ExportResult, SpanExporter},
},
trace::TracerProvider,
};
use tracing::{error, instrument, span, trace, warn};
use tracing_subscriber::prelude::*;

#[derive(Debug)]
enum Error {
ErrorQueryPassed,
}

impl StdError for Error {}

impl Display for Error {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
match self {
Error::ErrorQueryPassed => write!(f, "Encountered the error flag in the query"),
}
}
}

#[instrument(err)]
fn failable_work(fail: bool) -> Result<&'static str, Error> {
span!(tracing::Level::INFO, "expensive_step_1")
.in_scope(|| thread::sleep(Duration::from_millis(25)));
span!(tracing::Level::INFO, "expensive_step_2")
.in_scope(|| thread::sleep(Duration::from_millis(25)));

if fail {
return Err(Error::ErrorQueryPassed);
}
Ok("success")
}

#[instrument(err)]
fn double_failable_work(fail: bool) -> Result<&'static str, Error> {
span!(tracing::Level::INFO, "expensive_step_1")
.in_scope(|| thread::sleep(Duration::from_millis(25)));
span!(tracing::Level::INFO, "expensive_step_2")
.in_scope(|| thread::sleep(Duration::from_millis(25)));
error!(error = "test", "hello");
if fail {
return Err(Error::ErrorQueryPassed);
}
Ok("success")
}

fn main() -> Result<(), Box<dyn StdError + Send + Sync + 'static>> {
// Install an otel pipeline with a simple span processor that exports data one at a time when
// spans end. See the `install_batch` option on each exporter's pipeline builder to see how to
// export in batches.

let builder = sdk::trace::TracerProvider::builder().with_simple_exporter(WriterExporter);
let provider = builder.build();
let tracer = provider.versioned_tracer("opentelemetry-write-exporter", None, None);
global::set_tracer_provider(provider);

let opentelemetry = tracing_opentelemetry::layer()
.with_error_recording(true)
.with_error_propagation(true)
.with_tracer(tracer);
tracing_subscriber::registry()
.with(opentelemetry)
.try_init()?;

{
let root = span!(tracing::Level::INFO, "app_start", work_units = 2);
let _enter = root.enter();

let work_result = failable_work(false);

trace!("status: {}", work_result.unwrap());
let work_result = failable_work(true);

trace!("status: {}", work_result.err().unwrap());
warn!("About to exit!");

let _ = double_failable_work(true);
} // Once this scope is closed, all spans inside are closed as well

// Shut down the current tracer provider. This will invoke the shutdown
// method on all span processors. span processors should export remaining
// spans before return.
global::shutdown_tracer_provider();

Ok(())
}

#[derive(Debug)]
struct WriterExporter;

impl SpanExporter for WriterExporter {
fn export(
&mut self,
batch: Vec<opentelemetry::sdk::export::trace::SpanData>,
) -> futures_util::future::BoxFuture<'static, opentelemetry::sdk::export::trace::ExportResult>
{
let mut writer = std::io::stdout();
for span in batch {
writeln!(writer, "{}", SpanData(span)).unwrap();
}
write!(writer, "\n").unwrap();

Box::pin(async move { ExportResult::Ok(()) })
}
}

struct SpanData(opentelemetry::sdk::export::trace::SpanData);
impl Display for SpanData {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
writeln!(f, "Span: \"{}\"", self.0.name)?;
match &self.0.status {
opentelemetry::trace::Status::Unset => {}
opentelemetry::trace::Status::Error { description } => {
writeln!(f, "- Status: Error")?;
writeln!(f, "- Error: {description}")?
}
opentelemetry::trace::Status::Ok => writeln!(f, "- Status: Ok")?,
}
writeln!(
f,
"- Start: {}",
self.0
.start_time
.duration_since(SystemTime::UNIX_EPOCH)
.expect("start time is before the unix epoch")
.as_secs()
)?;
writeln!(
f,
"- End: {}",
self.0
.end_time
.duration_since(SystemTime::UNIX_EPOCH)
.expect("end time is before the unix epoch")
.as_secs()
)?;
writeln!(f, "- Resource:")?;
for (k, v) in self.0.resource.iter() {
writeln!(f, " - {}: {}", k, v)?;
}
writeln!(f, "- Attributes:")?;
for (k, v) in self.0.attributes.iter() {
writeln!(f, " - {}: {}", k, v)?;
}

writeln!(f, "- Events:")?;
for event in self.0.events.iter() {
if let Some(error) =
event
.attributes
.iter()
.fold(Option::<String>::None, |mut acc, d| {
if let Some(mut acc) = acc.take() {
use std::fmt::Write;
let _ = write!(acc, ", {}={}", d.key, d.value);
Some(acc)
} else {
Some(format!("{} = {}", d.key, d.value))
}
})
{
writeln!(f, " - \"{}\" {{{error}}}", event.name)?;
} else {
writeln!(f, " - \"{}\"", event.name)?;
}
}
writeln!(f, "- Links:")?;
for link in self.0.links.iter() {
writeln!(f, " - {:?}", link)?;
}
Ok(())
}
}
112 changes: 112 additions & 0 deletions src/layer.rs
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ const SPAN_KIND_FIELD: &str = "otel.kind";
const SPAN_STATUS_CODE_FIELD: &str = "otel.status_code";
const SPAN_STATUS_MESSAGE_FIELD: &str = "otel.status_message";

const EVENT_EXCEPTION_NAME: &str = "exception";
const FIELD_EXCEPTION_MESSAGE: &str = "exception.message";
const FIELD_EXCEPTION_STACKTRACE: &str = "exception.stacktrace";

Expand All @@ -36,6 +37,7 @@ pub struct OpenTelemetryLayer<S, T> {
tracked_inactivity: bool,
with_threads: bool,
exception_config: ExceptionFieldConfig,
error_config: ErrorFieldConfig,
get_context: WithContext,
_registry: marker::PhantomData<S>,
}
Expand Down Expand Up @@ -117,6 +119,7 @@ struct SpanEventVisitor<'a, 'b> {
event_builder: &'a mut otel::Event,
span_builder: Option<&'b mut otel::SpanBuilder>,
exception_config: ExceptionFieldConfig,
error_config: ErrorFieldConfig,
}

impl<'a, 'b> field::Visit for SpanEventVisitor<'a, 'b> {
Expand Down Expand Up @@ -177,6 +180,27 @@ impl<'a, 'b> field::Visit for SpanEventVisitor<'a, 'b> {
fn record_str(&mut self, field: &field::Field, value: &str) {
match field.name() {
"message" => self.event_builder.name = value.to_string().into(),
// While tracing supports the error primitive, the instrumentation macro does not
// use the primitive and instead uses the debug or display primitive.
// In both cases, an event with an empty name and with an error attribute is created.
"error" if self.event_builder.name.is_empty() => {
if self.error_config.propagate_events {
if let Some(span) = &mut self.span_builder {
span.status = otel::Status::error(format!("{:?}", value));
}
}
if self.error_config.record {
self.event_builder.name = EVENT_EXCEPTION_NAME.into();
self.event_builder.attributes.push(KeyValue::new(
FIELD_EXCEPTION_MESSAGE,
format!("{:?}", value),
));
} else {
self.event_builder
.attributes
.push(KeyValue::new("error", format!("{:?}", value)));
}
}
// Skip fields that are actually log metadata that have already been handled
#[cfg(feature = "tracing-log")]
name if name.starts_with("log.") => (),
Expand All @@ -195,6 +219,27 @@ impl<'a, 'b> field::Visit for SpanEventVisitor<'a, 'b> {
fn record_debug(&mut self, field: &field::Field, value: &dyn fmt::Debug) {
match field.name() {
"message" => self.event_builder.name = format!("{:?}", value).into(),
// While tracing supports the error primitive, the instrumentation macro does not
// use the primitive and instead uses the debug or display primitive.
// In both cases, an event with an empty name and with an error attribute is created.
"error" if self.event_builder.name.is_empty() => {
if self.error_config.propagate_events {
if let Some(span) = &mut self.span_builder {
span.status = otel::Status::error(format!("{:?}", value));
}
}
if self.error_config.record {
self.event_builder.name = EVENT_EXCEPTION_NAME.into();
self.event_builder.attributes.push(KeyValue::new(
FIELD_EXCEPTION_MESSAGE,
format!("{:?}", value),
));
} else {
self.event_builder
.attributes
.push(KeyValue::new("error", format!("{:?}", value)));
}
}
// Skip fields that are actually log metadata that have already been handled
#[cfg(feature = "tracing-log")]
name if name.starts_with("log.") => (),
Expand Down Expand Up @@ -284,6 +329,31 @@ struct ExceptionFieldConfig {
propagate: bool,
}

// TODO(valkum): Reconsider this once the error primitive has improved support, e.g.
// `record_error` is called for all types implementing `Error`, or to be precise,
// `tracing::event!` allows all types which implement `Error` and the instrument macro
// makes use of this.
//
/// Controls over OpenTelemetry conventional error/exception fields in relation to non-error field types
///
/// Currently, the error primitive is not used by the instrumentation macro.
/// Instead, the debug or display primitives are used.
/// This controls how to map this behavior into OpenTelemetry.
#[derive(Clone, Copy)]
struct ErrorFieldConfig {
/// If a function is instrumented and returns a `Result`, should the error
/// value be propagated to the span status.
///
/// Without this enabled, the span status will be "Error" with an empty description
/// when at least one error event is recorded in the span.
propagate_events: bool,
/// If an event with an empty name and a field named `error` is recorded,
/// should the event be rewritten to have the name `exception` and the field `exception.message`
///
/// Follows the semantic conventions for exceptions.
record: bool,
}

struct SpanAttributeVisitor<'a> {
span_builder: &'a mut otel::SpanBuilder,
exception_config: ExceptionFieldConfig,
Expand Down Expand Up @@ -433,6 +503,10 @@ where
record: false,
propagate: false,
},
error_config: ErrorFieldConfig {
record: false,
propagate_events: false,
},
get_context: WithContext(Self::get_context),
_registry: marker::PhantomData,
}
Expand Down Expand Up @@ -474,6 +548,7 @@ where
tracked_inactivity: self.tracked_inactivity,
with_threads: self.with_threads,
exception_config: self.exception_config,
error_config: self.error_config,
get_context: WithContext(OpenTelemetryLayer::<S, Tracer>::get_context),
_registry: self._registry,
}
Expand Down Expand Up @@ -501,6 +576,41 @@ where
}
}

/// Sets whether or not an event considered for exception mapping (see [`OpenTelemetryLayer::with_error_recording`])
/// should be propagated to the span status error description.
///
///
/// By default, these events do not set the span status error description.
pub fn with_error_propagation(self, error_propagation: bool) -> Self {
Self {
error_config: ErrorFieldConfig {
propagate_events: error_propagation,
..self.error_config
},
..self
}
}

/// Sets whether or not a subset of events following the described schema are mapped to
/// events following the [OpenTelemetry semantic conventions for
/// exceptions][conv].
///
/// * Only events without a message field (unnamed events) and at least one field with the name error
/// are considered for mapping.
///
/// By default, these events are not mapped.
///
/// [conv]: https://opentelemetry.io/docs/reference/specification/trace/semantic_conventions/exceptions/
pub fn with_error_recording(self, error_recording: bool) -> Self {
Self {
error_config: ErrorFieldConfig {
record: error_recording,
..self.error_config
},
..self
}
}

/// Sets whether or not reporting an `Error` value on an event will
/// propagate the OpenTelemetry exception fields such as `exception.message`
/// and `exception.backtrace` to the corresponding span. You do not need to
Expand Down Expand Up @@ -843,10 +953,12 @@ where
vec![Key::new("level").string(meta.level().as_str()), target],
0,
);

event.record(&mut SpanEventVisitor {
event_builder: &mut otel_event,
span_builder,
exception_config: self.exception_config,
error_config: self.error_config,
});

if let Some(OtelData { builder, .. }) = extensions.get_mut::<OtelData>() {
Expand Down
Loading

0 comments on commit 37ec0bc

Please sign in to comment.