ApplicationInsights-Java icon indicating copy to clipboard operation
ApplicationInsights-Java copied to clipboard

Not all exceptions are populated with exception type and message

Open ivan-zaitsev opened this issue 1 year ago • 10 comments

Expected behavior

Span should contain exception type and message. More details: https://github.com/microsoft/ApplicationInsights-Java/pull/3148

Actual behavior

Exception type and message is not added in case exception is not propagated to main thread. Span will contain only exception field.

In other cases span contains exception.type and excpetion.message, without exception field.

Looks like inconsistent behavior which produces completely different fields.

To Reproduce

Code:

BlobServiceClient blobServiceClient = ...
BlobContainerClient blobContainerClient = blobServiceClient.getBlobContainerClient("blob-name");
blobContainerClient.exists();

Exception is not thrown to main thread, but rather caught inside blobContainerClient.exists().

Produced span:

2024-06-11 12:18:58.916+03:00 DEBUG c.m.a.a.i.exporter.AgentSpanExporter - exporting span: SpanData{
    spanContext=ImmutableSpanContext{traceId=REDACTED, spanId=REDACTED, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=true}, 
    parentSpanContext=ImmutableSpanContext{traceId=REDACTED, spanId=REDACTED, traceFlags=01, traceState=ArrayBasedTraceState{entries=[]}, 
    remote=false, valid=true}, resource=Resource{schemaUrl=null, attributes={service.name="unknown_service:java", telemetry.sdk.language="java", telemetry.sdk.name="opentelemetry", telemetry.sdk.version="1.35.0"}}, 
    instrumentationScopeInfo=InstrumentationScopeInfo{name=azure-storage-blob, version=12.25.3, schemaUrl=https://opentelemetry.io/schemas/1.17.0, attributes={}}, 
    name=AzureBlobStorageCont.getProperties, kind=INTERNAL, startEpochNanos=1718097538120247437, endEpochNanos=1718097538844404395, 
    attributes=AttributesMap{data={az.namespace=Microsoft.Storage, thread.id=70, applicationinsights.internal.operation_name=REDACTED, thread.name=http-nio-8080-exec-1}, capacity=128, totalAddedValues=4}, 
    totalAttributeCount=4, events=[ImmutableExceptionEventData{epochNanos=1718097538844385117, exception=com.azure.storage.blob.models.BlobStorageException: Status code 404, "<?xml version="1.0" encoding="utf-8"?><Error><Code>ContainerNotFound</Code><Message>The specified container does not exist.

RequestId:REDACTED
Time:2024-06-11T09:18:58.7592080Z</Message></Error>", additionalAttributes={}, spanLimits=SpanLimitsValue{maxNumberOfAttributes=128, maxNumberOfEvents=128, maxNumberOfLinks=128, maxNumberOfAttributesPerEvent=128, maxNumberOfAttributesPerLink=128, maxAttributeValueLength=2147483647}}], totalRecordedEvents=1, links=[], totalRecordedLinks=0, status=ImmutableStatusData{statusCode=ERROR, description=}, hasEnded=true}

ivan-zaitsev avatar Jun 11 '24 09:06 ivan-zaitsev

@ivan-zaitsev did you see exception.type and exception.message in the Application Insights logs blade remoteDependencies table? We've checked the code, this log didn't represent the actual custom dimensions to application insights. exception.type and exception.message should be parsed automatically by opentelemetry trace sdk. Please let me know.

heyams avatar Jul 09 '24 17:07 heyams

Hello @heyams Correct it doesn't represent the actual custom dimensions to application insights and I didn't see fields exception.type and exception.message in Azure Insights dependencies table.

I have custom extension which processes span events and it relies on exception.type and exception.message. Seems that the telemetry exporter behaves differently when exception is propagated to main thread it adds exception.type and exception.message, but when it is not propagated it adds different field - exception.

Currently because of this inconsistent behavior I need to cover two cases because Azure Blob Storage client library sometimes throws exactly identical exception to main thread for example for find operations and sometimes it catches exception for example for exist operations.

ivan-zaitsev avatar Jul 09 '24 17:07 ivan-zaitsev

@ivan-zaitsev exception.type and exception.message are added to custom dimensions by getAttributes() https://github.com/open-telemetry/opentelemetry-java/blob/main/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/internal/data/ImmutableExceptionEventData.java.

I will use your code to reproduce it or if you can push a repro app to https://github.com/microsoft/ApplicationInsights-Java-Repros will help too.

heyams avatar Jul 09 '24 17:07 heyams

@heyams In case of code above To Reproduce when exception is not propagated to main thread exception.type and exception.message will not be added.

ivan-zaitsev avatar Jul 09 '24 18:07 ivan-zaitsev

I have custom extension which processes span events and it relies on exception.type and exception.message. Seems that the telemetry exporter behaves differently when exception is propagated to main thread it adds exception.type and exception.message, but when it is not propagated it adds different field - exception.

hi @ivan-zaitsev, from your log we can see

events=[ImmutableExceptionEventData{epochNanos=1718097538844385117, exception=com.azure.storage.blob.models.BlobStorageException: ...

If you look at ImmutableExceptionEventData.java, you'll see that what you are seeing is just the toString() representation, and not reflective of the attributes on that event.

check out https://github.com/open-telemetry/opentelemetry-java/blob/6fc1d216ca0f199670a1cc5b081ad764d4a043fb/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/internal/data/ImmutableExceptionEventData.java#L62-L85 and you'll see that the exception.type and exception.message really are present and available on that ImmutableExceptionEventData.

trask avatar Aug 01 '24 17:08 trask

@ivan-zaitsev we found a difference in our exporter code paths for log-based exceptions and span event-based exceptions, we're exploring the impact of fixing that, we're not sure but it may be related to the issue you're seeing

trask avatar Aug 01 '24 19:08 trask

Hello @trask I have added repro code to this repo. You can try. https://github.com/microsoft/ApplicationInsights-Java-Repros/pull/12/files

ivan-zaitsev avatar Aug 01 '24 19:08 ivan-zaitsev

@trask More likely this issue is connected to that difference. Because SdkLogRecordData contains exception.type, exception.message, and SpanData contains only exception.

ivan-zaitsev avatar Aug 01 '24 20:08 ivan-zaitsev

thanks for the repro!

we are intentionally not exporting the "internal" exception that is happening under the hood when calling exists()

this serves two purposes:

  • it doesn't clutter the exception table in Application Insights, as we try to only populate the exception table with things that correlate to request failure
  • saves cost ($) because capturing all of those internal (often "expected") exception stack traces adds up

In particular, if you are interested, this is where it's being suppressed during export: https://github.com/Azure/azure-sdk-for-java/blob/599ec92aa4a207929fd3ca4b4289cec5577915d0/sdk/monitor/azure-monitor-opentelemetry-exporter/src/main/java/com/azure/monitor/opentelemetry/exporter/implementation/SpanDataMapper.java#L786-L788

if you can describe what you are trying to accomplish a bit more, maybe we can help with a workaround or config option, thanks

trask avatar Aug 02 '24 21:08 trask

@trask I just wanted to filter out the traces produced by exists() or delete() caused by same exception and message internally in Azure Blob SDK, but one of methods catches exception, other throws. In any case it will be exported to Azure Insights as success = false.

I have custom extension which allows to processes span events, because this agent by default doesn't do that. Because of this inconsistent behavior I need to cover two cases with exception attribute produced by SpanData and exception.type, exception.measage attributtes produced by SdkLogRecordData.

ivan-zaitsev avatar Aug 03 '24 05:08 ivan-zaitsev