AI (Internal): Operation to stop does not match the current operation

[brobichaud]

I've got a simple DotNet Core 2.0 app using AppInsights. I've started using the AppInsights SDK as well and the TrackTrace() method in particular. It's working fine, but queries on the traces table in Analyitics are showing a number of traces with a message of "AI (Internal): Operation to stop does not match the current operation". I'm not generating these and they are polluting my data. Any idea why they are generated and how I can make them stop? I'm using SDK v2.4.0-32153

Here are the trace details (with some values obscured):
timestamp [UTC]: 2018-01-10T19:39:20.651Z
message: AI (Internal): Operation to stop does not match the current operation.
operation_SyntheticSource: SDKTelemetry
client_Type: PC
client_IP: my-ip-address
client_CountryOrRegion: United States
appId: 43dda5df-4e1c-46a9-82ee-977811e262b5
appName: debug-fossil
iKey: my-ikey-value
sdkVersion: dotnet:2.4.0-32153
itemId: f754898b-f63d-11e7-8081-3b3156d2a6a2
itemType: trace
itemCount: 1

[Ruud-cb]

Same problem!

[lmolkova]

@brobichaud @Ruud-cb

Could you please help us find the root cause of the issue

1. Do you notice any discrepancy in telemetry correlation in particular between request and dependency telemetry? (it could be really hard to notice)

2. Do you call TelemteryClient extension methods StartOperation and StopOperation? If you do, please review this article and make sure you start/stop operations in the isolated async flows.

3. Do you have any outgoing HTTP calls from your app? Are they tracked as http dependency calls (SDK does it automatically)?

4. If your service is under low load, could you please try to find all requests and dependencies reported by the same service/instance within one second after this error (in analytics)? I can help you with the query if needed.

@Ruud-cb
do you run .NET Core app as well?

Thanks a lot for the info!

[brobichaud]

@lmolkova Here are my responses:

1. Hmm, this one I don't know how to answer, likely based on my newbie status with App Insights. I'm not sure how to correlate the two.
2. No, I'm not calling either of those methods.
3. Yes most definitely. I do see lots of calls to Azure Storage and some to Azure CosmosDB as expected. But then I also DO NOT see calls to other endpoints that I know we are calling (loggly is a big one).
4. Yes it is definitely low load currently. I am unable to send this data because it seems the behavior has changed since I reported this. I am now seeing events like the one below instead.

timestamp [UTC]: 2018-02-27T19:02:08.058Z
message: AI (Internal): Current Activity is null
operation_SyntheticSource: SDKTelemetry
client_Type: PC
client_IP: 0.0.0.0
client_City: Boydton
client_StateOrProvince: Virginia
client_CountryOrRegion: United States
appId: 0ceb6f84-2c81-45a5-961c-455e880ae3f0
appName: dev-fossil
iKey: my-ikey-value
sdkVersion: dotnet:2.4.0-32153
itemId: c7889c58-1bf0-11e8-9f2d-49ace55083f7
itemType: trace
itemCount: 1

Please let me know if there is any info I can gather. I will admit my mind is not fresh on this as I've not revisited it until today.

[lmolkova]

@brobichaud

Thanks for the info. Now we can narrow down the problem to the HTTP dependency collection.

3. Yes most definitely. I do see lots of calls to Azure Storage and some to Azure CosmosDB as expected. But then I also DO NOT see calls to other endpoints that I know we are calling (loggly is a big one).

Make sure these are HTTP dependencies. We can dig more into this issue as well, but please open another issue for this.

4. Yes it is definitely low load currently. I am unable to send this data because it seems the behavior has changed since I reported this.

In analytics, you may specify any timestamp in the past. Are you able to find any AI (Internal): Operation to stop does not match the current operation. now or all of them are lost because of data retention policy? Let me know if you need any help with finding them.

Regarding the new trace you observe AI (Internal): Current Activity is null -
we hope we have it fixed in ApplicationInsights Web SDK 2.6: microsoft/ApplicationInsights-dotnet-server#799. For now, it does not indicate an issue. Just out of curiosity, how many of them you observe comparing to the number of depednencies?

[brobichaud]

@lmolkova

I am no longer able to see any taces with "AI (Internal): Operation to stop does not match the current operation.". I queried a subset of that string and find nothing, which likely is a result of data retention policies of AppInsights as you suggest. So I'm not sure where to go with that. Seems kindof odd since I'm using the same version of the appinsights sdk.

I'm glad to hear the "Current Activity is null" issue will be fixed. I'm not sure why they suddenly started showing up. It feels like something changed out from under me. Any ideas why the change in behavior?

[lmolkova]

@brobichaud

I am no longer able to see any taces with "AI (Internal): Operation to stop does not match the current operation.". I queried a subset of that string and find nothing, which likely is a result of data retention policies of AppInsights as you suggest. So I'm not sure where to go with that. Seems kindof odd since I'm using the same version of the appinsights sdk.

This error does not happen frequently. It could be some very specific case in the HttpClient diagnostics that causes it. E.g. some network issue that is not handled in diagnostics pipeline. So you may start observing it again at some point. If you do, please come back :)

Let's hope that @Ruud-cb or someone else experiencing this issue would be able to find telemetry following this event.

I'm glad to hear the "Current Activity is null" issue will be fixed. I'm not sure why they suddenly started showing up. It feels like something changed out from under me. Any ideas why the change in behavior?

For this issue, we know just one reason to cause it so far: some temp network issues transmitting telemetry to AppInsights endpoint. Unfortunately, this event does not give us enough info (until 2.6), so we cannot tell if it happens in any other cases. I do not think it could be caused by your code. If your service and the rest of Azure services you use are in different data centers, network glitches would be expected at a reasonable rate.

If you see a huge spike in these events and/or unexpected decrease in number of http dependency telemetry items tracked - this would indicate an issue.

[Ruud-cb]

Hi,

Just for the record, it seems to occur on local computers only, not when the app is in production.

1 It seems to happen before some front-end requests. NPM related files that get loaded.
This is shown when I click on "All available telemetry for this root operation":

Another example:

Not sure if it helps but there is only 1 I noticed in production that occured before a http timeout. Another error though:

2. No

3. Yes I have outgoing calls, Azure Storage is shown, SQL db is shown. Wierd thing is, is that it shows my own requests as dependency because Insights is loaded in the front-end and the back-end so actually all my requests are also dependency calls :(. I am missing web service calls to wsdl/xml API's, maybe because the code is not within the web app.

4. See 1 for screenshots, After those requests it is just normal API calls from front-end to back-end and retrieving from database.
   Here is the AppInsights export: https://www.dropbox.com/s/n49r0smfxt1vcog/query_data.csv?dl=0 I will delete this shortly after.

Also running NET Core.

[lmolkova]

@Ruud-cb

Thanks for the info, it really helps. It's interesting that localhost requests have this problem. I also see that your dependencies are reported twice. I'm pretty sure you are hitting microsoft/ApplicationInsights-dotnet-server#723. It was fixed in ApplicationInsight AspNetCore SDK 2.2-beta2.
Could you please try to update to the latest 2.2.1?
This could also be a reason for other discrepancies I see in the logs such as dependency being a grandchild of the requests.

could you please confirm that you are indeed, have Microsoft.ApplicationInsights.AspNetCore 2.2.0-beta1 and Microsoft.ApplicationInsights.DependencyCollector 2.5.0-beta1?
Otherwise, it seems we did not fix the issue.

Regarding production issue you observe, it's microsoft/ApplicationInsights-dotnet-server#780. We target to fix it in the upcoming stable release.

Yes I have outgoing calls, Azure Storage is shown, SQL db is shown. Wierd thing is, is that it shows my own requests as dependency because Insights is loaded in the front-end and the back-end so actually all my requests are also dependency calls :(.

you should have both: request and dependency telemetry when you call your backed instrumentation with AI. This is expected behavior. More on this

I am missing web service calls to wsdl/xml API's, maybe because the code is not within the web app.

can you elaborate? where you are making these requests from? Are these Http apis?

[lmolkova]

Should be fixed with microsoft/ApplicationInsights-dotnet-server#848 in 2.6.0-beta3 Microsoft.ApplicationInsights (base SDK) and 2.3.0-beta1 Microsoft.ApplicationInsights.AspNetCore.

Please reopen if reproduces

[raphac]

I have the same problem. I use Microsoft.ApplicationInsights.AspNetCore Version="2.5.1" and have two TelemetryProcessor and one TelemetryInitializer. Could the TelemetryProcessor or the TelemetryInitializer be a problem? We don't use a TelemteryClient.