OTEP: Recording exceptions as log records

[lmolkova]

trafficstars

Related to https://github.com/open-telemetry/semantic-conventions/issues/1536

Changes

Recording exceptions as span events is problematic since it

• ties recording exceptions to tracing/sampling
• duplicates exceptions recorded by instrumented libraries on logs
• does not leverage log features such as typical log filtering based on severity

This OTEP provides guidance on how to record exceptions using OpenTelemetry logs focusing on minimizing duplication and providing context to reduce the noise.

If accepted, the follow-up spec changes are expected to replace existing (stable) documents:

• https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/trace/exceptions.md
• https://github.com/open-telemetry/semantic-conventions/blob/main/docs/exceptions/exceptions-spans.md

---

• [x] Related issues https://github.com/open-telemetry/semantic-conventions/issues/1536
• [x] ~~Related OTEP(s) #~~
• [ ] Links to the prototypes (when adding or changing features)
• [x] CHANGELOG.md file updated for non-trivial changes
• [x] ~~spec-compliance-matrix.md updated if necessary~~

[pellared]

I think this is a related issue:

• https://github.com/open-telemetry/opentelemetry-specification/issues/4234

[carlosalberto]

A small doubt:

If this instrumentation supports tracing, it should capture the error in the scope of the processing span.

Although (I think) it's not called out, I'm understanding exceptions should now be explicitly reported as both 1) Span.Event and 2) Log/Event? i.e. coding wise you should do this:

currentSpan.recordException(e);
logger.logRecordBuilder
    .addException(e);

Is this the case?

[lmolkova]

Although (I think) it's not called out, I'm understanding exceptions should now be explicitly reported as both 1) Span.Event and 2) Log/Event? i.e. coding wise you should do this:

@carlosalberto thanks for the clarification! The intent here is to eventually replace span events with logs in the instrumentations (in non-breaking manner for existing ones).

I clarified it in the text, PTAL.

[trask]

github u/x is showing a weird diff, have seen this before, may be worth trying to rebase and force push

[adriangb]

Doesn't this potentially make data much harder to query? I can't possibly be familiar with all of the ways backends store and make data queryable so I will take our backend as an example. We essentially store the data in a relational table and make it queryable via SQL.

If the exception is on the span itself I can do something like:

select *
from records
where span_name = 'db query' and has_exceptions(events)

Whereas if it's emitted as a (non span) event (aka a log?) we would have to either re-assemble during ingest (very difficult) or it ends up as it's own row, which means the query would have to be something like:

select *
from records r1
where span_name = 'db query' and exists (
  select
  from records r2
  where r1.trace_id = r2.trace_id and r2.parent_span_id = r1.span_id and has_exceptions(r2.events)
)

[pellared]

Doesn't this potentially make data much harder to query? I can't possibly be familiar with all of the ways backends store and make data queryable so I will take our backend as an example. We essentially store the data in a relational table and make it queryable via SQL.

If the exception is on the span itself I can do something like:

select *
from records
where span_name = 'db query' and has_exceptions(events)

Whereas if it's emitted as a (non span) event (aka a log?) we would have to either re-assemble during ingest (very difficult) or it ends up as it's own row, which means the query would have to be something like:

select *
from records r1
where span_name = 'db query' and exists (
  select
  from records r2
  where r1.trace_id = r2.trace_id and r2.parent_span_id = r1.span_id and has_exceptions(r2.events)
)

How is this related to the OTEP? Many backends already show log records related to the given trace. It looks like a complain to the trace-log correlation. Or even https://github.com/open-telemetry/opentelemetry-specification/blob/main/oteps/0265-event-vision.md#relationship-to-span-events (different OTEP).

re-assemble during ingest (very difficult)

I guess the difficulty depends on the given backend design.

[adriangb]

How is this related to the OTEP? Many backends already show log records related to the given trace. It looks like a complain to the trace-log correlation. Or even https://github.com/open-telemetry/opentelemetry-specification/blob/main/oteps/0265-event-vision.md#relationship-to-span-events (different OTEP).

The OTEP is proposing to move data from the span to related logs, so understanding the impact of this on user experience is important. I guess you could say my question is more in general about https://github.com/open-telemetry/opentelemetry-specification/blob/main/oteps/0265-event-vision.md#relationship-to-span-events but I think exceptions are a particularly important tipping point.

Many backends already show log records related to the given trace. It looks like a complain to the trace-log correlation

We do as well. But do any of them support doing this programmatically? It's one thing to have the backend know how to retrieve that data, it's another thing to do it programatically e.g. to build a dashboard of error rate by endpoint. If they do I'd like to see what that query looks like before and after this proposal from a general user's perspective.

[adriangb]

I also want to confirm what the proposed behavior is based on this scenario. It was not clear to me from reading the OTEP.

from opentelemetry.sdk.resources import SERVICE_NAME, Resource

from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor, ConsoleSpanExporter
from opentelemetry.sdk.trace import ReadableSpan

resource = Resource(attributes={SERVICE_NAME:"test"})

def formatter(span: ReadableSpan) -> str:
    out: list[str] = []
    out.append(f"{span.name}")
    for event in span.events:
        if event.name == "exception":
            attributes = event.attributes or {}
            stacktrace = attributes.get("exception.stacktrace") or ""
            out.append(f"  {event.name}: {stacktrace}")
    out.append("")
    return "\n".join(out)

trace_provider = TracerProvider(resource=resource)
processor = BatchSpanProcessor(ConsoleSpanExporter(formatter=formatter))
trace_provider.add_span_processor(processor)
trace.set_tracer_provider(trace_provider)

tracer = trace.get_tracer("test")



def inner() -> None:
    with tracer.start_as_current_span("inner"):
        raise ValueError('the message')

def outer() -> None:
    with tracer.start_as_current_span("outer"):
        inner()


try:
    with tracer.start_as_current_span("root"):
        outer()
except Exception as e:
    pass  # keep the output clean

Currently this gives (cleanup up a bit):

inner
  File "/Users/adriangb/GitHub/platform/test.py", line 32, in inner
    raise ValueError('the message')
ValueError: the message

outer
  File "/Users/adriangb/GitHub/platform/test.py", line 36, in outer
    inner()
  File "/Users/adriangb/GitHub/platform/test.py", line 32, in inner
    raise ValueError('the message')
ValueError: the message

root
  File "/Users/adriangb/GitHub/platform/test.py", line 41, in <module>
    outer()
  File "/Users/adriangb/GitHub/platform/test.py", line 36, in outer
    inner()
  File "/Users/adriangb/GitHub/platform/test.py", line 32, in inner
    raise ValueError('the message')
ValueError: the message

The point is that each span has the exception recorded on it, and they each have a different stack trace.

Under this new paradigm, would a log/event be emitted for each span the exception bubbles up through? Or would only a single log/event be emitted for the first span it bubbles though? The current version of this PR states:

It's NOT RECOMMENDED to record the same error as it propagates through the call stack, or to attach the same instance of an exception to multiple log records.

If this means that only a single log would be emitted we'd loose information on the fact that this exception bubbled up through the other spans. Even if the span's status code and message get set, I still don't have the stack trace that bubbled up through the event, meaning information is lost relative to the current system.

[lmolkova]

Doesn't this potentially make data much harder to query?

@adriangb

I don't agree with "much", but yes, it makes data harder to query if backend previously stored span events next to spans (which is not always the case).

Arguably, if you want to get all information about some operation today, you would end up querying across multiple tables in your backend. Only if we record all logs as span events we would solve this problem.

E.g. in Azure Monitor, querying all spans by trace-id would look like requests | union dependencies | where operation_Id == "your-trace-id". Querying across all tables would be union * | where operation_Id == "your-trace-id"

So it really depends on how backend stores data and query language.

In any case, it's a trade-off. Not everything is instrumented with tracing (or should be instrumented with tracing), traces are sampled - these drawbacks are outlined in motivation section.

So the switch to logs is made out of necessity. If you have any alternative solutions for this, please share.

[alexmojaki]

I don't agree with "much", but yes, it makes data harder to query if backend previously stored span events next to spans (which is not always the case).

Arguably, if you want to get all information about some operation today, you would end up querying across multiple tables in your backend. Only if we record all logs as span events we would solve this problem.

E.g. in Azure Monitor, querying all spans by trace-id would look like requests | union dependencies | where operation_Id == "your-trace-id". Querying across all tables would be union * | where operation_Id == "your-trace-id"

So it really depends on how backend stores data and query language.

With span events, it's easy for the backend to store the span and the exception together because OTLP keeps them together. If recording an exception on a span generates a separate log event then those are guaranteed to be in separate exports. For our backend at least it's very hard to then bring them together in storage. It would have been easier with the relational database we were using before but we moved away from that because it's impractically slow for most queries.

traces are sampled

If a span is excluded by sampling, what happens to its child log events by default? Even if it's included, it will be missing the parent span describing the context of the exception. It's better than nothing, but this doesn't seem like a real solution to exceptions being lost by sampling. Tail sampling seems like the way to deal with that.

So the switch to logs is made out of necessity. If you have any alternative solutions for this, please share.

I understand that it's useful to be able to log exceptions without the need to create a span, but that's different from saying that spans should no longer contain exceptions, which is where this OTEP seems headed even if it's not requiring it yet. Why remove span events?

[alexmojaki]

I don't agree with "much", but yes, it makes data harder to query if backend previously stored span events next to spans (which is not always the case).

We extract special columns like is_exception and exception_type from events which make it trivial for users to query exceptions, they don't have to know about events at all.

[alexmojaki]

I will say that span events are a bit odd and I've never seen them used for anything other than exceptions. Span events themselves are not special, but storing exception data directly inside relevant spans is important to us. So if all this goes forward and span events disappear, then we will probably find ways to workaround it in our SDK. For example I'm hoping Span.record_exception will still exist and will switch from adding a span event to logging a child event, in which case we'll override it to also add special attributes to the span containing the exception data. We might also then allow users to disable emitting the redundant log events to reduce their costs.

[cijothomas]

I will say that span events are a bit odd and I've never seen them used for anything other than exceptions. Span events themselves are not special, but storing exception data directly inside relevant spans is important to us. So if all this goes forward and span events disappear, then we will probably find ways to workaround it in our SDK. For example I'm hoping Span.record_exception will still exist and will switch from adding a span event to logging a child event, in which case we'll override it to also add special attributes to the span containing the exception data. We might also then allow users to disable emitting the redundant log events to reduce their costs.

I've never seen them used for anything other than exceptions

Sharing one example from RedisInstrumentation which leveraged SpanEvents (named ActivityEvents in .NET world): https://github.com/open-telemetry/opentelemetry-dotnet-contrib/blob/main/src/OpenTelemetry.Instrumentation.StackExchangeRedis/StackExchangeRedisInstrumentationOptions.cs#L34-L37 (TBH, I haven't seen other cases outside of Exceptions)

but storing exception data directly inside relevant spans is important to us.

Even if Exceptions are reported via Logs, it is possible to write a LogRecordProcessor that can attach the Exception to the current Span. (I have seen people doing it in .NET)

[adriangb]

Arguably, if you want to get all information about some operation today, you would end up querying across multiple tables in your backend. Only if we record all logs as span events we would solve this problem.

Currently a backend can store the information for exceptions alongside spans (same table, same row) because it receives them together. With this change backends can not (easily, without buffering, etc.) store exceptions alongside the spans they bubbled through, even if they wanted to. So on a matrix of options you currently can choose to store them on the same row but in the future you will not be able to store them on the same row.

I don't think examples of some backends currently choosing to store this information on different rows justifies breaking backends that currently choose to store them on the same row.

[cijothomas]

Arguably, if you want to get all information about some operation today, you would end up querying across multiple tables in your backend. Only if we record all logs as span events we would solve this problem.

Currently a backend can store the information for exceptions alongside spans (same table, same row) because it receives them together. With this change backends can not (easily, without buffering, etc.) store exceptions alongside the spans they bubbled through, even if they wanted to. So on a matrix of options you currently can choose to store them on the same row but in the future you will not be able to store them on the same row.

I don't think examples of some backends currently choosing to store this information on different rows justifies breaking backends that currently choose to store them on the same row.

https://github.com/open-telemetry/opentelemetry-specification/pull/4333#issuecomment-2640226319 Even with the proposal, it is still possible to send exceptions reported via Logging API to be added to Span by writing LogRecordProcessor.

[adriangb]

it is still possible to send exceptions reported via Logging API to be added to Span by writing LogRecordProcessor.

Yes that's what I meant by:

can not (easily, without buffering, etc.)

Just because it's possible doesn't mean it's easy. At the SDK level it's doable, you can assume there are no network failures, etc. Even then it's not simple because you're still buffering stuff in memory you didn't have to previously which can result in increased memory usage, having to sequence flushing correctly to avoid flushing the logs before you process the spans that they relate to, etc. Let's say you do write something that works pretty well: now you have to convince all of your users to install it and configure it correctly. That's not an easy thing to do.

Once you realize it's hard to get all users on board with your custom LogRecordProcessor you decide to do it at your infrastructure level, during ingestion. This is now a much harder problem. There's no guarantee that a log will arrive at the same time as it's span. So you end up having to buffer indefinitely or implement some sort of watermark system. And what if there's a failure? Now you need to persist data. It's not a simple problem to solve.

[samuelcolvin]

We discussed this at length on the OT Python SOG call - I think it's pretty clear that in python at least, this change represents a profound regression in functionality vs. the status quo.

[cijothomas]

it is still possible to send exceptions reported via Logging API to be added to Span by writing LogRecordProcessor.

Yes that's what I meant by:

can not (easily, without buffering, etc.)

Just because it's possible doesn't mean it's easy. At the SDK level it's doable, you can assume there are no network failures, etc. Even then it's not simple because you're still buffering stuff in memory you didn't have to previously which can result in increased memory usage, having to sequence flushing correctly to avoid flushing the logs before you process the spans that they relate to, etc. Let's say you do write something that works pretty well: now you have to convince all of your users to install it and configure it correctly. That's not an easy thing to do.

Not sure I follow this.. If exceptions are being sent via spans today, then you are already buffering and dealing with all these today already. Using LogRecordProcessor to attach Exception to SpanEvent won't change that - exceptions continue to work the same way as before.

[adriangb]

it is still possible to send exceptions reported via Logging API to be added to Span by writing LogRecordProcessor.

Yes that's what I meant by:

can not (easily, without buffering, etc.)

Just because it's possible doesn't mean it's easy. At the SDK level it's doable, you can assume there are no network failures, etc. Even then it's not simple because you're still buffering stuff in memory you didn't have to previously which can result in increased memory usage, having to sequence flushing correctly to avoid flushing the logs before you process the spans that they relate to, etc. Let's say you do write something that works pretty well: now you have to convince all of your users to install it and configure it correctly. That's not an easy thing to do.

Not sure I follow this.. If exceptions are being sent via spans today, then you are already buffering and dealing with all these today already. Using LogRecordProcessor to attach Exception to SpanEvent won't change that - exceptions continue to work the same way as before.

When I receive a span today I know that I've also received all of the exceptions associated with that span: they come in the same payload, at the same time. If the exceptions are sent as logs (or child spans, anything except the same span) they may arrive at any time, e.g. an hour before or after the span was received in the case of a networking issue. Or they may never arrive at all.

[cijothomas]

it is still possible to send exceptions reported via Logging API to be added to Span by writing LogRecordProcessor.

Yes that's what I meant by:

can not (easily, without buffering, etc.)

Just because it's possible doesn't mean it's easy. At the SDK level it's doable, you can assume there are no network failures, etc. Even then it's not simple because you're still buffering stuff in memory you didn't have to previously which can result in increased memory usage, having to sequence flushing correctly to avoid flushing the logs before you process the spans that they relate to, etc. Let's say you do write something that works pretty well: now you have to convince all of your users to install it and configure it correctly. That's not an easy thing to do.

Not sure I follow this.. If exceptions are being sent via spans today, then you are already buffering and dealing with all these today already. Using LogRecordProcessor to attach Exception to SpanEvent won't change that - exceptions continue to work the same way as before.

When I receive a span today I know that I've also received all of the exceptions associated with that span: they come in the same payload, at the same time. If the exceptions are sent as logs (or child spans, anything except the same span) they may arrive at any time, e.g. an hour before or after the span was received in the case of a networking issue. Or they may never arrive at all.

Sorry, I don't follow...Here's an example showing my thinking:

my_method()
{
let span = tracer.startActiveSpan("my span");
try 
{
 doSomething()
}
catch(ex)
{
   log(ex);
   //  span.recordException(ex); this is commented out. i.e exception is *not* reported as SpanEvent by instrumentation.
}

span.end()
}

LogRecordProcessor
{
 OnEmit(LogRecord)
 {
    ex = logRecord.ex
    span = GetActiveSpan();
    span.recordException(ex);  // this will add exception to span itself. achieving same effect as instrumentation natively doing this.
 } 
}

^ This will have the same effect as doing the commented out part (span.recordException). Span payload will have the exception information, just like before. (when instrumentation was doing span.RecordException)

[adriangb]

Sorry, I don't follow...Here's an example showing my thinking:

Now convince all of your users to put that into their code. Configuring OTEL correctly is already ~50 LOC, now it's 100 LOC. Users won't do it. And as explained above it's not really possible to do this reliably in a collector / backend.

[cijothomas]

Sorry, I don't follow...Here's an example showing my thinking:

Now convince all of your users to put that into their code. Configuring OTEL correctly is already ~50 LOC, now it's 100 LOC. Users won't do it. And as explained above it's not really possible to do this reliably in a collector / backend.

If a user wants to do it (see exception inside Span), they can. I just showed it is possible. Whether users do it or not - I can't comment.

if # of lines is a concern, Otel SDKs can provide an option to do it automatically. https://github.com/open-telemetry/opentelemetry-specification/pull/4333#discussion_r1945153176 has a link to a (Log->SpanEvent) option in one of the languages.

[adriangb]

In my opinion what matters is not what's possible, what matters is what the real world experience is going to be for users and backend implementers. And the reality is that this change may have a serious negative impact on both.

[cijothomas]

In my opinion what matters is not what's possible, what matters is what the real world experience is going to be for users and backend implementers. And the reality is that this change may have a serious negative impact on both.

I don't think Otel ever recommended Exceptions MUST/SHOULD be reported via SpanEvents. It had conventions for reporting exception via SpanEvent and Logs. (logs convention came later than Span), but never recommended one over other. This was also my first comment on this OTEP.

This OTEP would be the first time Otel officially makes a recommendation on the preferred way of reporting exception.

(That is my read. Happy to be corrected!)

[adriangb]

I agree with your interpretation. My point is that recording events via logs does have downsides. Right now you have to opt into it so it's okay to have to do something like the LogRecordProcessor you proposed to get that to work correctly (essentially duplicating the info). But if it becomes the recommendation and presumably eventually the default, as this OTEP is proposing, that results in a a worse user experience for both users and OTEL backend engineers.

[cijothomas]

I agree with your interpretation. My point is that recording events via logs does have downsides. Right now you have to opt into it so it's okay to have to do something like the LogRecordProcessor you proposed to get that to work correctly (essentially duplicating the info). But if it becomes the recommendation and presumably eventually the default, as this OTEP is proposing, that results in a a worse user experience for both users and OTEL backend engineers.

that results in a a worse user experience for both users and OTEL backend engineers.

I think this depends on the backend/vendor.

Recording exceptions via logs has downsides. Recording exceptions via SpanEvents also has downsides too. Having no recommendation from Otel is also not good. It is definitely possible to have something in the Otel Spec for SDKs, to have a feature flag to control this based on user preference. (The feature flag, can do the conversion of exceptions from LogRecord to SpanEvents OR vice-versa, with or without duplicating.). It is also possible to have feature-flag for instrumentations, but it may be easier to have an SDK level thing that'll ensure consistent behavior, irrespective of the instrumentation used.

[lmolkova]

to @alexmojaki

With span events, it's easy for the backend to store the span and the exception together because OTLP keeps them together. If recording an exception on a span generates a separate log event then those are guaranteed to be in separate exports. For our backend at least it's very hard to then bring them together in storage.

You could bring them on the SDK level with a events-to-span-events processor. It's a great question how the span-events -> logs migration would look like and whether such processor should be provided by contrib component, individual distros or by default.

If a span is excluded by sampling, what happens to its child log events by default? Even if it's included, it will be missing the parent span describing the context of the exception. It's better than nothing, but this doesn't seem like a real solution to exceptions being lost by sampling. Tail sampling seems like the way to deal with that.

Correlated logs with errors and other details without parent span are pretty valuable regardless of tracing or sampling.

I understand that it's useful to be able to log exceptions without the need to create a span, but that's different from saying that spans should no longer contain exceptions, which is where this OTEP seems headed even if it's not requiring it yet. Why remove span events?

this is part of the previous OTEP on Events - https://github.com/open-telemetry/opentelemetry-specification/blob/main/oteps/0265-event-vision.md#relationship-to-span-events. In the long term, we hope to replace span events with log-based events with migration story for consumers.

We extract special columns like is_exception and exception_type from events which make it trivial for users to query exceptions, they don't have to know about events at all.

We report error.type on spans and it contains exception type if exception was the reason. PTAL at the https://github.com/open-telemetry/semantic-conventions/blob/main/docs/general/recording-errors.md. If you have some scenarios in mind where it's necessary to capture that the error manifested as exception (vs some status code) is useful, please bring them up in semantic conventions.

Span events themselves are not special, but storing exception data directly inside relevant spans is important to us.

Does it include the stack trace? The rest is (or can be) stored for a single 'terminal' exception that the span ends with. Or is your goal to store exception chain and/or handled exceptions that happened during span lifetime?

The counter-argument I have is that there are a lot of exceptions that happen during span execution and most of them are already recorded as logs by runtimes, client libs, frameworks, etc. I.e. you're already in the world where exceptions are not exported along with spans.

It's a fair ask though that user app may want to associate arbitrary exceptions with a span today and we're taking it away when moving to logs.

[trask]

@adriangb @alexmojaki @samuelcolvin would you mind summarizing where we are with each of your concerns above as separate review comments (on the Files changed tab at the top, pick a relevant-ish line and add the summary of where we're at there) so we can have "threaded" discussions on each one of them? I really want to follow along and see what needs to be addressed, but am having trouble following with everything as mainline comments 😅 thank you ❤️

[ChristopherKlinge]

Hi,

I have a question regarding the proposed error.type attribute. As far as I can tell from the current spec and this proposal, this is the "technical" type of the exception (e.g. java.lang.NullPointerException). How is this supposed to translate to error codes for business errors?

In a more traditional logging based stack, when logging an exception, the developer should add a human readable error message explaining the underlying exception's effect on the current process. Without these messages, an observer has a very hard time figuring out what broke from a business perspective.

{
  "level": "ERROR",
  "message": "Could not generate invoice for order XYZ.",
  "exception": "java.lang.NullPointerException",
  "stack_trace": "..."
}

If I understand this OTEP correctly, this log message would not change much and the corresponding trace would look like this:

{
  "status": {
    "status_code": "ERROR",
    "description": "Could not generate invoice for order XYZ."
  },
  "attributes": {
    "error.type": "java.lang.NullPointerException"
  }
}

Is this correct?

[lmolkova]

@ChristopherKlinge please check out https://github.com/open-telemetry/semantic-conventions/blob/main/docs/general/recording-errors.md which covers existing error.type attribute.

This OTEP is about exception and errors on logs and encourages to add additional information to logs.