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 Sep 29, 2023
1 parent 5adedb0 commit d5bc52c
Show file tree
Hide file tree
Showing 3 changed files with 409 additions and 0 deletions.
186 changes: 186 additions & 0 deletions examples/opentelemetry-error.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,186 @@
use std::{
borrow::Cow,
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>> {
let builder = sdk::trace::TracerProvider::builder().with_simple_exporter(WriterExporter);
let provider = builder.build();
let tracer = provider.versioned_tracer(
"opentelemetry-write-exporter",
None::<Cow<'static, str>>,
None::<Cow<'static, str>>,
None,
);
global::set_tracer_provider(provider);

let opentelemetry = tracing_opentelemetry::layer().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();
}
writeln!(writer).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(())
}
}
101 changes: 101 additions & 0 deletions src/layer.rs
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,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 Down Expand Up @@ -180,6 +181,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.sem_conv_config.error_events_to_status {
if let Some(span) = &mut self.span_builder {
span.status = otel::Status::error(format!("{:?}", value));
}
}
if self.sem_conv_config.error_events_to_exceptions {
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 @@ -198,6 +220,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.sem_conv_config.error_events_to_status {
if let Some(span) = &mut self.span_builder {
span.status = otel::Status::error(format!("{:?}", value));
}
}
if self.sem_conv_config.error_events_to_exceptions {
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 @@ -289,6 +332,25 @@ struct SemConvConfig {
///
/// Note that this uses tracings `record_error` which is only implemented for `(dyn Error + 'static)`.
error_records_to_exceptions: bool,

/// 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.
///
/// Note: the instrument macro will emit an error event if the function returns the `Err` variant.
/// This is not affected by this setting. Disabling this will only affect the span status.
error_events_to_status: 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.
///
/// Note: the instrument macro will emit an error event if the function returns the `Err` variant.
/// This is not affected by this setting. Disabling this will only affect the created fields on the OTel span.
error_events_to_exceptions: bool,
}

struct SpanAttributeVisitor<'a> {
Expand Down Expand Up @@ -439,7 +501,10 @@ where
sem_conv_config: SemConvConfig {
error_fields_to_exceptions: true,
error_records_to_exceptions: true,
error_events_to_exceptions: true,
error_events_to_status: true,
},

get_context: WithContext(Self::get_context),
_registry: marker::PhantomData,
}
Expand Down Expand Up @@ -540,6 +605,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 set the span status error description.
pub fn with_error_events_to_status(self, error_events_to_status: bool) -> Self {
Self {
sem_conv_config: SemConvConfig {
error_events_to_status,
..self.sem_conv_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 mapped.
///
/// [conv]: https://github.com/open-telemetry/semantic-conventions/tree/main/docs/exceptions/
pub fn with_error_events_to_exceptions(self, error_events_to_exceptions: bool) -> Self {
Self {
sem_conv_config: SemConvConfig {
error_events_to_exceptions,
..self.sem_conv_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 @@ -912,6 +1012,7 @@ where
vec![Key::new("level").string(meta.level().as_str()), target],
0,
);

event.record(&mut SpanEventVisitor {
event_builder: &mut otel_event,
span_builder,
Expand Down
Loading

0 comments on commit d5bc52c

Please sign in to comment.