Cannot log application errors through tokio tracing

[Havunen]

Hi,

There is some issue where logging "exceptions" seems impossible through tokio tracing.

Steps to reproduce:

Edit the example in examples/tracing/main.rs

#[instrument(fields(test.in_attr="in attr"))]
async fn run_in_child_process() {
    tracing::info!(test.in_event="in event", "leaf fn");

    sleep(Duration::from_millis(50)).await;

    tracing::event!(
        name: "exception",
        Level::ERROR,
        ai.customEvent.name = "exception"
    );

    sleep(Duration::from_millis(50)).await;
}

When the exception event arrives to create_envelopes_for_span the name of the event is "" and then the correct application insights type is not set and the exception is not correctly shown in application insights.

[Havunen]

I tried to debug this but it seems the "name" is lost even before the code hits any sources of opentelemetry-application-insights crate

[Havunen]

link: twitchax/axum-insights#3
tokio-rs tracing discussion: tokio-rs/tracing#3189

[Havunen]

This is the bug: tokio-rs/tracing#2774

[frigus02]

Thanks for reporting and investigating. I'll try to read through all of this tomorrow and see if there is anything we can do about it here.

[Havunen]

It seems tokio macros are bugged as they dont send the event name through. Because of that opentelemetry-rust started sending "name" parameter in attributes as well: open-telemetry/opentelemetry-rust#2279

I think we should do the same here (https://github.com/frigus02/opentelemetry-application-insights/blob/main/src/trace.rs#L102-L115), read the "name" value from attributes first if its there then match by it, otherwise fallback to event name?

Then we can update those other libraries fe. twitchax/axum-insights#3 to send event name in attributes until tokio has fixed their macro

[frigus02]

Okay. If I understand correctly:

// Creates otel event with an empty name
tracing::event!(name: "exception", Level::ERROR, ai.customEvent.name = "exception");

// Creates otel event with name="exception" --> creates exception in App Insights
tracing::event!(Level::ERROR, ai.customEvent.name = "exception", "exception");

This is because the latter produces a tracing attribute called "message" with the value "exception", which tracing-opentelemetry maps to the event name.

The tracing event name (event.metadata().name()) is never recorded by tracing-opentelemetry if I see that correctly. If we want to use that, it should probably be set as the otel event name here: https://github.com/tokio-rs/tracing-opentelemetry/blob/293d206b2b02686d5b2b0166c072425feed94950/src/layer.rs#L1055

---

Interestingly tracing-opentelemetry supports more ways to record exceptions. Unfortunately they aren't super well documented. You can kinda guess them from the OpenTelemetryLayer docs. From reading the code, I think all of these work, unless you disable one of the layer options:

// Creates an otel event with name "exception" and sets `exception.message` to "error message".
// Should work with both string and debug values.
tracing::event!(Level::ERROR, error = "error message");

// This records the error message and source (backtrace) as `exception.message` and `exception.stacktrace` attribute.
// But weirdly this does not set the event name to "exception".
let error: Box<dyn std::error::Error> = "An error".into();
tracing::event!(Level::ERROR, error = error);

I wonder if it's a bug in tracing-opentelemetry that the latter doesn't set the event name to "exception".

---

Based on the above I'm hesitant to add a workaround to opentelemetry-application-insights. While we could enable something like tracing::error!(name: "exception", name = "exception");, I think using tracing::error!("exception"); or tracing::error!(error = "error message"); seems nicer.

And then we could file bugs against tracing-opentelemetry regarding:

• Using the tracing event name (event.metadata().name()) as the default otel event name.
• Setting the event name to "exception" when recording an error. At least when recording an error using the name "error", similar to how it's done for recording error = "a string".

Does that make sense? Or did I misunderstand something?

[frigus02]

Oh, also, it seems obvious that this needs better docs. I'm going to add an exception log to the tracing example in this repo. And having an example code snippet in the tracing-opentelemetry docs might also be useful, I think.

[Havunen]

Sounds good to me, I will test it tomorrow!

[Havunen]

Works great! thx!