Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Correlation stopped working, dependency telemetry is no longer child to request (and where did Legacy Operation Id come from?) #2302

Closed
OskarKlintrot opened this issue Aug 16, 2019 · 9 comments · Fixed by #2375
Assignees

Comments

@OskarKlintrot
Copy link

OskarKlintrot commented Aug 16, 2019

I get this strange behavior where the correlation of a WebJob-execution (RequestTelemetry) do not align correctly with the DependencyTelemetry. Looking at the properties it looks like Legacy Operation Id and Legacy Id makes more sense than Operation Id and Request/Dependency Id. However nowhere the DependencyTelemetry seem to have the RequestTelemetry as parent. I log the dependency telemetry manually with TelemetryClient (to be able to log the request and response body, I use a processor to get rid of the auto-logged since I do want to log other dependencies, if there would be any). There is just one registered TelemetryClient and one registered TelemetryConfiguration so that looks all fine to me. Not sure where to even start looking to solve this, any suggestions?

image

image

image

The expected behavior is that the top most telemetry is parent to all of the telemetry below. The dependency calls are made one after the other, they are not nested as it looks in the timeline. Pay especially attention to the first dependency telemetry, in the timeline that one is actually logged as the last call but it's shown as the first anyway.

@brettsam
Copy link
Member

What version of WebJobs (and the AppInsights nuget) are you using? How are you accessing the TelemetryClient from your function?

@ghost
Copy link

ghost commented Sep 1, 2019

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.

@OskarKlintrot
Copy link
Author

I'm using Microsoft.Azure.WebJobs version 3.0.11, Microsoft.Azure.WebJobs.Logging.ApplicationInsights version 3.0.8 and Microsoft.ApplicationInsights version 2.10.0.

I'm injecting the TelemetryClient in the ctor:

public LogDependency(TelemetryClient telemetryClient, ILoggerFactory loggerFactory)

I took a sneak peak with

var telemetryClients = host.Services.GetServices<Microsoft.ApplicationInsights.TelemetryClient>();

to see if there where more than one telemetry client registered but there is only one registered.

@marnilss
Copy link

marnilss commented Sep 6, 2019

I see a variation on this, RequestTelemetry (WebJob-execution) and DependencyTelemetry and TraceTelemetry match each other, but value sent in "Request-ID" header with HttpClient to backend systems doesn't!
BUT the value in customDimensions.ai_legacyRequestId (from e.g. WebJob request) matches the "Request-ID" header, which is the same as System.Diagnostics.Activity.Current.Id.

Why don't we get same behavior as e.g. in a ASP.NET Core webapp, where they are all aligned and no use for a "ai_legacyRequestId"?
Cannot find any documentation at all on "ai_legacyRequestId"!

I'm using
Microsoft.Azure.WebJobs v3.0.12
Microsoft.Azure.WebJobs.Logging.ApplicationInsights v3.0.12

@OskarKlintrot
Copy link
Author

I just created a new webjob as a netcoreapp3.0 console app and now the http requests to other services becomes childs to the inital webjob-request but not the db-calls done in the webjob.

image

.ConfigureLogging((hostingContext, loggingBuilder) =>
{
    loggingBuilder.AddApplicationInsightsWebJobs();
})
<PackageReference Include="Microsoft.Azure.WebJobs" Version="3.0.14" />
<PackageReference Include="Microsoft.Azure.WebJobs.Logging.ApplicationInsights" Version="3.0.14" />

@OskarKlintrot
Copy link
Author

I'm not sure if it's supposed to be like this or not but the parentId on the db-calls gets prefixed by 00- and suffixed by -00.

@brettsam
Copy link
Member

@lmolkova should be able to comment on the correlation questions.

@lmolkova
Copy link
Member

Legacy request id is expected as a part of the transition to the new W3C Trace-Context standard for correlation. This is internal (and undocumented) AppInsights property that UX uses to stitch together old and new correlation-ids formats and allow backward compatibility with older applications.
Presence of legacy request id does not indicate an issue. However, if UX does not stitch operations correctly - this is certainly a bug.

@OskarKlintrot it seems you are hitting SQL correlation bug we introduced (and fixed) in AppInsights SDK microsoft/ApplicationInsights-dotnet-server#1277.

If you use pure WebJobs, you may fix it with installing the latest stable version 2.8.2 of AppInsights for ASP.NET Core

If you are using Functions, I don't think it will help. @brettsam, can you remind if Functions allow newer versions of AppInsights?

I'll send PR to pick up the latest patched AppInsights SDK from WebJobs/Functions.

@OskarKlintrot
Copy link
Author

Thanks @lmolkova, using version 2.8.2 of Microsoft.ApplicationInsights.AspNetCore fixed it!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

5 participants