-
Notifications
You must be signed in to change notification settings - Fork 86
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Add support for instrumented functions which return Result (#28)
## Motivation Currently, the tracing instrumentation macro emits a single event after the function call, but in the current span, with just a field named error set. For example: ```rust #[instrument(err)] fn test() -> Result<(), ()> { ...body } ``` gets roughly expanded to ```rust fn test() -> Result<(), ()> { let span = span!("test") fn inner() -> Result<(), ()> { ...body } match inner() { Ok(x) => Ok(x), Err(err) => { error!(error=%err) Err(err) } } ``` In the error case of the result, the macro will emit an error level event with just an `error` field set to the display (or debug) value of the returned error. While there exists support for the Error primitive in tracing, the primitive only supports 'static Errors. See tokio-rs/tracing#1308 ## Solution This PR adds support to use this event to fill the span status error description with the content of the error field of this event. Additionally, this ass support to emit these events (or manually created ones that follow the same format) as OTel events following the exception convention. The operation is optional and can be configured using the `ErrorFieldConfig`. This seems like another hack similar to `otel.*` fields, but should reduce some boilerplate in existing codebases. I propose to keep this until `tracing` improves support for Error fields.
- Loading branch information
Showing
3 changed files
with
611 additions
and
29 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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(()) | ||
} | ||
} |
Oops, something went wrong.