Application Insights Dependency Logging setting incorrect parentId for Blob storage calls from Storage SDK

[jegour]

Describe your environment. Describe any aspect of your environment relevant to the problem:
Azure Service Fabric application in ASP.NET Core 3.1 running the Application Insights C# telemetry collection SDK.

• SDK version: Microsoft.ApplicationInsights.AspNetCore 2.14.0
• .NET runtime version (.NET or .NET Core, TargetFramework in the .csproj file): .NET Core 3.1
• Hosting Info (IIS/Azure WebApps/etc): Azure Service Fabric
• Platform and OS version: Windows 10

If you're reporting a problem with a specific version of a library in this repo, please check whether the problem has been fixed on master.

Steps to reproduce.
Use the the newest 12.4 version of Azure.Storage.Blob client SDK to interact with Azure Blob.

What is the expected behavior?
The operation_parentId value generated for each dependency log statement corresponding to each blob client call should match the id value of the requests log statement corresponding to the request from which the Blob calls were made.

What is the actual behavior?
The operation_parentId value does not correspond to any value present in the requests logs. Not only that but sequential blob client calls do not even have the same operation_parentId value. This results in the blob calls not being put in the appropriate place in the distributed trace view.

Additional context.
This works as expected with version 11 of the storage library. We saw this issue occur once we updated to version 12. I have already filed an issue with the Storage SDK, and they pointed me to the Application Insights as where the issue must originate (see Azure/azure-sdk-for-net#12511).

[cijothomas]

@rajkumar-rangaraj would you time to try this out? We should have func tests which can be upgraded to newest version of this blob nuget and see if it fails.
If its really application insights, then we need to schedule a fix soon. If its an issue with blob sdk itself, we need to let them know.

cc : @TimothyMothra as well as Mothra is going to implement an integration test pipeline to catch these issues very early.

[rajkumar-rangaraj]

I could recreate an issue. Dependencies telemetries generated for Azure.Storage.Blobs has different ai.operation.parentId for it. In case of Microsoft.Azure.Storage, ai.operation.parentId has correct value and it is the id of Request telemetry.

Azure.Storage.Blobs 12.4.4

Application Insights Telemetry: {"name":"AppDependencies","time":"2020-06-20T02:40:00.3136303Z","iKey":"IKEY","tags":{"ai.cloud.roleInstance":"MachineName","ai.operation.id":"7892c75e1d221841890ddea1de150016","ai.operation.parentId":"7bc51d1b98664043","ai.internal.sdkVersion":"dotnet:2.15.0-19521"},"data":{"baseType":"RemoteDependencyData","baseData":{"ver":2,"name":"PUT storage","id":"e3ea2db0ce5bc149","data":"https://storage.blob.core.windows.net/testcontainer1?restype=container","duration":"00:00:00.4470577","resultCode":"201","success":true,"type":"Azure blob","target":"storage.blob.core.windows.net","properties":{"_MS.ProcessedByMetricExtractors":"(Name:'Dependencies', Ver:'1.1')","ServerRequestId":"303bcedb-201e-0121-11ac-46aadb000000","ClientRequestId":"a57c1b43-9895-4ab0-ab27-1d815c845b26","Container":"testcontainer1"}}}}
Application Insights Telemetry: {"name":"AppDependencies","time":"2020-06-20T02:40:01.2641503Z","iKey":"IKEY","tags":{"ai.cloud.roleInstance":"MachineName","ai.operation.id":"7892c75e1d221841890ddea1de150016","ai.operation.parentId":"a3a20c3cc492404c","ai.internal.sdkVersion":"dotnet:2.15.0-19521"},"data":{"baseType":"RemoteDependencyData","baseData":{"ver":2,"name":"PUT storage","id":"00bdf2d312326942","data":"https://storage.blob.core.windows.net/testcontainer1/testName","duration":"00:00:00.1695202","resultCode":"201","success":true,"type":"Azure blob","target":"storage.blob.core.windows.net","properties":{"_MS.ProcessedByMetricExtractors":"(Name:'Dependencies', Ver:'1.1')","ServerRequestId":"303bd064-201e-0121-6eac-46aadb000000","ClientRequestId":"1cd6d14b-0061-4b4f-8f8e-be9d046f6932","Container":"testcontainer1","Blob":"testName"}}}}
Application Insights Telemetry: {"name":"AppDependencies","time":"2020-06-20T02:40:01.4690757Z","iKey":"IKEY","tags":{"ai.cloud.roleInstance":"MachineName","ai.operation.id":"7892c75e1d221841890ddea1de150016","ai.operation.parentId":"ac4aa87d9f020b4d","ai.internal.sdkVersion":"dotnet:2.15.0-19521"},"data":{"baseType":"RemoteDependencyData","baseData":{"ver":2,"name":"DELETE storage","id":"a9076242a54b0543","data":"https://storage.blob.core.windows.net/testcontainer1?restype=container","duration":"00:00:00.0692091","resultCode":"202","success":true,"type":"Azure blob","target":"storage.blob.core.windows.net","properties":{"_MS.ProcessedByMetricExtractors":"(Name:'Dependencies', Ver:'1.1')","ServerRequestId":"303bd0f8-201e-0121-77ac-46aadb000000","ClientRequestId":"e3a46ea3-b58c-422e-8ba4-13cdf8cdcb7d","Container":"testcontainer1"}}}}
Application Insights Telemetry: {"name":"AppRequests","time":"2020-06-20T02:39:59.6705277Z","iKey":"IKEY","tags":{"ai.cloud.roleInstance":"MachineName","ai.user.id":"p33je","ai.operation.id":"7892c75e1d221841890ddea1de150016","ai.operation.parentId":"05e6fa5f46ee3c40","ai.operation.name":"POST /default.aspx","ai.location.ip":"::1","ai.internal.sdkVersion":"web:2.15.0-19521"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"7922a7d268f00b43","name":"POST /default.aspx","duration":"00:00:01.9591400","success":true,"responseCode":"200","url":"https://localhost:44309/default.aspx","properties":{"_MS.ProcessedByMetricExtractors":"(Name:'Requests', Ver:'1.1')"}}}}

Microsoft.Azure.Storage 11.1.7

Application Insights Telemetry: {"name":"AppDependencies","time":"2020-06-20T02:42:01.9803092Z","iKey":"IKEY","tags":{"ai.cloud.roleInstance":"MachineName","ai.operation.id":"97f3d20f7ac8224bade84c5d28cbd70e","ai.operation.parentId":"9fcc177d657d074a","ai.internal.sdkVersion":"rdddsd:2.15.0-19521","ai.internal.nodeName":"MachineName"},"data":{"baseType":"RemoteDependencyData","baseData":{"ver":2,"name":"PUT storage","id":"37c566a7a9b3ff47","data":"https://storage.blob.core.windows.net:443/testcontainer?restype=container","duration":"00:00:00.4912904","resultCode":"409","success":false,"type":"Azure blob","target":"storage.blob.core.windows.net","properties":{"_MS.ProcessedByMetricExtractors":"(Name:'Dependencies', Ver:'1.1')","Container":"testcontainer"}}}}
Application Insights Telemetry: {"name":"AppDependencies","time":"2020-06-20T02:42:02.9523109Z","iKey":"IKEY","tags":{"ai.cloud.roleInstance":"MachineName","ai.operation.id":"97f3d20f7ac8224bade84c5d28cbd70e","ai.operation.parentId":"9fcc177d657d074a","ai.internal.sdkVersion":"rdddsd:2.15.0-19521","ai.internal.nodeName":"MachineName"},"data":{"baseType":"RemoteDependencyData","baseData":{"ver":2,"name":"HEAD storage","id":"4a7db0502637dc48","data":"https://storage.blob.core.windows.net:443/testcontainer/testName","duration":"00:00:00.2283462","resultCode":"200","success":true,"type":"Azure blob","target":"storage.blob.core.windows.net","properties":{"_MS.ProcessedByMetricExtractors":"(Name:'Dependencies', Ver:'1.1')","Container":"testcontainer","Blob":"testName"}}}}
Application Insights Telemetry: {"name":"AppRequests","time":"2020-06-20T02:42:01.3113211Z","iKey":"IKEY","tags":{"ai.cloud.roleInstance":"MachineName","ai.user.id":"p33je","ai.operation.id":"97f3d20f7ac8224bade84c5d28cbd70e","ai.operation.parentId":"3ce0dd0b28e39a4f","ai.operation.name":"POST /default.aspx","ai.location.ip":"::1","ai.internal.sdkVersion":"web:2.15.0-19521"},"data":{"baseType":"RequestData","baseData":{"ver":2,"id":"9fcc177d657d074a","name":"POST /default.aspx","duration":"00:00:01.9598348","success":true,"responseCode":"200","url":"https://localhost:44363/default.aspx","properties":{"_MS.ProcessedByMetricExtractors":"(Name:'Requests', Ver:'1.1')"}}}}

Storage REST API calls from Azure.Storage.Blobs adds traceparent header to the System.Net calls.

Headers: {x-ms-version: 2019-07-07
x-ms-client-request-id: 00e2e6b1-1337-45c9-83f5-b4c752eaf326
x-ms-return-client-request-id: true
User-Agent: azsdk-net-Storage.Blobs/12.4.4 (.NET Framework 4.8.4180.0; Microsoft Windows 10.0.18363 )
x-ms-date: Sun, 21 Jun 2020 21:39:39 GMT
traceparent: 00-6c9631f3914894419581c3652d541747-967745235941314f-00
Host: storage.blob.core.windows.net

If a traceparent is present in request header, application insights SDK will not set parent id for it, hence parent-child correlation is broken.

Following is the code for Azure.Core module which creates new Activity for storage calls and sets traceparent to it.

https://github.com/Azure/azure-sdk-for-net/blob/d63cf3c691d88efaae7f8167b25561530f255222/sdk/core/Azure.Core/src/Pipeline/Internal/RequestActivityPolicy.cs#L61

Microsoft.Azure.Storage does not create Activity or set traceparent, so everything is working as expected here.

Further investigation needed to check why Azure Core creates a new activity.

[cijothomas]

@pakrym Something you can help?

[pakrym]

Further investigation needed to check why Azure Core creates a new activity.

We create the activity to enable Azure SDK HTTP request tracking functionality independently of the framework version being used.

This is something we collaborated with @lmolkova on.

[TimothyMothra]

@lmolkova can you please take a look at this?

[lmolkova]

I was able to find the root cause:
Azure SDK tracks additional 'logical' operations (e.g. BlobContainerClient.CreateIfNotExists), but it's not reported by ApplicationInsights, therefore parentId don't match.

What happens is:

• Azure SDK creates Azure.Client.Blobs source here https://github.com/Azure/azure-sdk-for-net/blob/0eb893cfda1a9b39801d414ec77ce753eec43868/sdk/core/Azure.Core/src/Shared/DiagnosticScopeFactory.cs#L17

• And then creates another instance of the listener again. And it uses this second listener to write events to.

• Application Insights ends up having 2 subscriptions for the same source.

• Unfortunately AppInsights has a protection mechanism that allows only one source to send events (this is done for the case when multiple apps are hosted in the same process, see more Fix duplicated request telemetry when multiple hosts run in the same process ApplicationInsights-aspnetcore#787) which basically means that whichever source was registered first is active one and the rest are ignored.
  This is done with assumption that all diagnostic sources are static and there is only one source with given name in the process.

I suggest fixing it in a following way:
We should allow multiple DiagnosticSources with the same name as long as they are different instances:

• it will still protect from multiple apps hosted in the same process (the problem there is 1 source instance with multiple subscriptions from multiple AppInsights)
• it will also remove requirement to have static sources only.

I'll send a PR with the fix in the next few days.

[DJ4ddi]

@TimothyMothra This issue is still reproducable with ApplicationInsights 2.22.0 and Azure.Storage.Blobs 12.19.1 - shouldn't this be fixed by now?

The current behavior is correct for the dependencies with type InProc | Microsoft.Storage, but still wrong for dependencies with type Azure blob.