search

arcus-azure / arcus.observability

Observability with Microsoft Azure in a breeze.
https://observability.arcus-azure.net/
MIT License
23 stars 15 forks source link

Correlation in Azure Application Insights is not working #69

Closed gverstraete closed 4 years ago

gverstraete commented 4 years ago

Describe the bug in my code I added the new packages for correlation and the ones for logging. But when combining the two i see all the requests seperately from each other and not nested.

image

To Reproduce So this is my Program:

public class Program
    {
        public static void Main(string[] args)
        {
            CreateHostBuilder(args).Build().Run();
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseSerilog().UseStartup<Startup>();
                });
    }

And the startup:

    public class Startup
    {
        public void ConfigureServices(IServiceCollection services)
        {
            IServiceCollectionExtensions.AddCorrelation(services);

            services.AddMvc(options => options.EnableEndpointRouting = false).SetCompatibilityVersion(CompatibilityVersion.Version_3_0); ;

            services.AddSingleton<ITestRepo, TestRepo>();

            services.AddHttpCorrelation();

            services.AddSwaggerGen(c =>
            {
                c.SwaggerDoc("Api", new Microsoft.OpenApi.Models.OpenApiInfo { Title = "API", Version = "#{VERSION}#" });
            });
        }

        // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
        public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
        {
            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }

            app.UseSwagger();
            app.UseSwaggerUI(c => { c.SwaggerEndpoint("/swagger/Api/swagger.json", "BMID.Fraud.Onboarding.Api"); });

            app.UseMiddleware<RequestLoggingMiddleware>();

            app.UseHttpsRedirection();
            app.UseMvc();

            app.UseHttpCorrelation();

            Log.Logger = new LoggerConfiguration()
                .MinimumLevel.Verbose()
                .Enrich.WithCorrelationInfo()
                .WriteTo.AzureApplicationInsights("xxxxx")
                .WriteTo.Console(outputTemplate:"{Message}")
                .CreateLogger();

        }

Expected behavior I would expect to see the correlation in action :)

Additional context

  <ItemGroup>
    <PackageReference Include="Arcus.Observability.Correlation" Version="0.1.0-preview-5" />
    <PackageReference Include="Arcus.Observability.Telemetry.Core" Version="0.1.0-preview-5" />
    <PackageReference Include="Arcus.Observability.Telemetry.Serilog.Sinks.ApplicationInsights" Version="0.1.0-preview-5" />
    <PackageReference Include="Arcus.WebApi.Correlation" Version="1.0.0-preview-1" />
    <PackageReference Include="Arcus.WebApi.Logging" Version="1.0.0-preview-1" />
    <PackageReference Include="Dapper" Version="2.0.30" />
    <PackageReference Include="Dapper.Contrib" Version="2.0.30" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.SqlServer" Version="3.0.0" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.Tools" Version="3.0.0">
      <PrivateAssets>all</PrivateAssets>
      <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
    </PackageReference>
    <PackageReference Include="Microsoft.Extensions.Logging.Debug" Version="3.0.0" />
    <PackageReference Include="Microsoft.VisualStudio.Web.CodeGeneration.Design" Version="3.0.0" />
    <PackageReference Include="Serilog.AspNetCore" Version="3.2.0" />
    <PackageReference Include="Swashbuckle.AspNetCore.Swagger" Version="5.2.1" />
    <PackageReference Include="Swashbuckle.AspNetCore.SwaggerGen" Version="5.2.1" />
    <PackageReference Include="Swashbuckle.AspNetCore.SwaggerUI" Version="5.2.1" />
  </ItemGroup>
tomkerkhove commented 4 years ago

PTAL @stijnmoreels, would be good to investigate asap as this is an essential feature. Not sure if it's due to WebAPI (enricher) or Observability (sink) though.

gverstraete commented 4 years ago

As requested, some more information:

[09:18:41 DBG] Wildcard detected, all requests with hosts will be allowed.
[09:18:41 VRB] All hosts are allowed.
[09:18:41 VRB] All hosts are allowed.
[09:19:04 VRB] All hosts are allowed.
[09:19:04 DBG] The request path  does not match the path filter
[09:19:06 DBG] Request successfully matched the route with name 'TestApi' and template 'api/Tests/api/test'
[09:19:06 VRB] mymessage
[09:19:08 INF] SQL Dependency {DependencyTargetName} for {DependencyName} for operation {DependencyData} in {DependencyDuration} at {DependencyStartTime} (Successful: {DependencyIsSuccessful} - Context: {})
[09:19:08 INF] Executing HttpStatusCodeResult, setting HTTP status code 200
[09:19:10 INF] HTTP Request {RequestMethod} {RequestHost}/{RequestUri} completed with {ResponseStatusCode} in {RequestDuration} at {RequestTime} - (Context: {})

As you see context is still empty

tomkerkhove commented 4 years ago

Something else which I don't get is why the actual values are not filled in, we either have a misconfiguration (doc bug) or bug 🤔

stijnmoreels commented 4 years ago

This line: IServiceCollectionExtensions.AddCorrelation(services); is wrong.

stijnmoreels commented 4 years ago

This line: app.UseHttpCorrelation(); should be above the app.UseMvc() like specified in the docs. It's registering middleware so as high as possible even.

tomkerkhove commented 4 years ago

This line: IServiceCollectionExtensions.AddCorrelation(services); is wrong.

This is ok, it's same as services.AddCorrelation();

This line: app.UseHttpCorrelation(); should be above the app.UseMvc() like specified in the docs. It's registering middleware so as high as possible even.

Can you try moving these @gverstraete?

stijnmoreels commented 4 years ago

This line: IServiceCollectionExtensions.AddCorrelation(services); is wrong.

This is ok, it's same as services.AddCorrelation();

No, I mean it is not necessary to call this entirely; bc the services.AddHttpCorrelation(); does the work.

tomkerkhove commented 4 years ago

Ah like that!

gverstraete commented 4 years ago

I changed the order so it looks like this:

            if (env.IsDevelopment())
            {
                app.UseDeveloperExceptionPage();
            }

            app.UseHttpCorrelation();

            app.UseSwagger();
            app.UseSwaggerUI(c => { c.SwaggerEndpoint("/swagger/BMID.Fraud.Onboarding.Api/swagger.json", "BMID.Fraud.Onboarding.Api"); });

            app.UseMiddleware<RequestLoggingMiddleware>();

            app.UseHttpsRedirection();
            app.UseMvc();

I do see now this in my logs & response: image

but no correlation in AI; same result there

tomkerkhove commented 4 years ago

You should also update ConfigureServices:

public void ConfigureServices(IServiceCollection services)
        {
            services.AddHttpCorrelation();

            services.AddMvc(options => options.EnableEndpointRouting = false).SetCompatibilityVersion(CompatibilityVersion.Version_3_0); ;

            services.AddSingleton<ITestRepo, TestRepo>();
            services.AddSwaggerGen(c =>
            {
                c.SwaggerDoc("Api", new Microsoft.OpenApi.Models.OpenApiInfo { Title = "API", Version = "#{VERSION}#" });
            });
        }

Can you paste the raw messages as well please?

gverstraete commented 4 years ago

Oh sorry!

Changed that. Same result.

[10:14:46 DBG] Wildcard detected, all requests with hosts will be allowed.
[10:14:46 VRB] All hosts are allowed.
[10:14:46 VRB] Setting correlation response header 'X-Transaction-ID' to '985f79aa-de70-439d-90f3-3acf85840b9a'
[10:14:46 VRB] Setting correlation response header 'RequestId' to '0HLUM2IUK3F5M:00000001'
[10:14:46 VRB] All hosts are allowed.
[10:14:46 VRB] Setting correlation response header 'X-Transaction-ID' to '648bb21b-2ad0-436e-a5fe-f7242c7ad80b'
[10:14:46 VRB] Setting correlation response header 'RequestId' to '0HLUM2IUK3F5M:00000003'
[10:14:53 VRB] All hosts are allowed.
[10:14:53 DBG] The request path  does not match the path filter
[10:14:56 DBG] Request successfully matched the route with name 'TestApi' and template 'api/Tests/api/test'
[10:14:56 VRB] mymessage
[10:14:59 INF] SQL Dependency {DependencyTargetName} for {DependencyName} for operation {DependencyData} in {DependencyDuration} at {DependencyStartTime} (Successful: {DependencyIsSuccessful} - Context: {})
[10:14:59 INF] Executing HttpStatusCodeResult, setting HTTP status code 200
[10:15:01 INF] HTTP Request {RequestMethod} {RequestHost}/{RequestUri} completed with {ResponseStatusCode} in {RequestDuration} at {RequestTime} - (Context: {})
[10:15:01 VRB] Setting correlation response header 'X-Transaction-ID' to 'fbabed3b-a996-4a9e-a64c-c56c8a91c9c4'
[10:15:01 VRB] Setting correlation response header 'RequestId' to '0HLUM2IUK3F5M:00000005'
[10:15:29 VRB] All hosts are allowed.
[10:15:29 DBG] The request path  does not match the path filter
[10:15:31 DBG] Request successfully matched the route with name 'TestApi' and template 'api/Tests/api/test'
[10:15:31 VRB] mymessage
[10:15:31 INF] SQL Dependency {DependencyTargetName} for {DependencyName} for operation {DependencyData} in {DependencyDuration} at {DependencyStartTime} (Successful: {DependencyIsSuccessful} - Context: {})
[10:15:31 INF] Executing HttpStatusCodeResult, setting HTTP status code 200
[10:15:32 INF] HTTP Request {RequestMethod} {RequestHost}/{RequestUri} completed with {ResponseStatusCode} in {RequestDuration} at {RequestTime} - (Context: {})
[10:15:32 VRB] Setting correlation response header 'X-Transaction-ID' to '757c89a0-acb4-493e-8f7e-3c02cd53a9e2'
[10:15:32 VRB] Setting correlation response header 'RequestId' to '0HLUM2IUK3F5M:00000007'
tomkerkhove commented 4 years ago

@stijnmoreels Think we'll need to repro this locally based on the code above and check why: 1) Text is not replaced with values 2) Context is not provided by using correlation

Optionally even use our code directly instead of via NuGet package.

gverstraete commented 4 years ago

Willing to share my dummy project as well if this would help

stijnmoreels commented 4 years ago

But the outputtemplate on the Console is set to {Message} so that wouldn't work either way. We should only look at how the Application Insights problem is.

tomkerkhove commented 4 years ago

We need to pinpoint where the issue lies. You can go straight to Application Insights, but maybe the real issue is how the messages are written and provided of context (which is clearly empty here)

tomkerkhove commented 4 years ago

So that's why console messages would help so I suggest to use the repro, fix the output template and see what that gives and start from there.

stijnmoreels commented 4 years ago

I removed the console output message, coppied the code pasted here, and ran the application: image

tomkerkhove commented 4 years ago

That's good, now time to dig in the correlation!

For example: Does the telemetry contain context (both AI/console) and does it include correlation info?

stijnmoreels commented 4 years ago

The sample code here also uses the wrong ICorrelationInfoAccessor. It's using the DefaultCorrelationInfoAccessor explained in the docs using the .WithCorrelationInfo() method, while in fact it would use the HttpCorrelationInfoAccessor. Something like this: .Enrich.WithCorrelationInfo(new HttpCorrelationInfoAccessor(app.ApplicationServices.GetService<IHttpContextAccessor>()))

stijnmoreels commented 4 years ago

Then the correlation info is present in Application Insights

tomkerkhove commented 4 years ago

Can you post a screenshot of that please?

Actually it's not wrong in the code then in the sense that we should handle this transparently imo :)

We should add a .Enricht.WithHttpCorrelationInfo() that take away this pain imo.

tomkerkhove commented 4 years ago

But nice fine 👍

stijnmoreels commented 4 years ago

image

stijnmoreels commented 4 years ago

But the console still doesn't show the correct rendered message. Even without using our extensions, placing the string directly...

tomkerkhove commented 4 years ago

I don't think we are there yet since the tree view is just the event.

The information is there but most probably we need to fix telemetry that we are sending. We should ensure that this property is set as well in our converters with the correlation id: https://github.com/serilog/serilog-sinks-applicationinsights/blob/master/src/Serilog.Sinks.ApplicationInsights/Sinks/ApplicationInsights/TelemetryConverters/TelemetryConverterBase.cs#L123

They rely on operationId which is case sensitive, so we won't use that but define it ourselves.

I'll send a PR in a jiffy.

gverstraete commented 4 years ago

Yes, just tested that as well with this change and I do see extra logs but not a correlation in AI:

[13:05:24 DBG] Wildcard detected, all requests with hosts will be allowed.
[13:05:24 VRB] All hosts are allowed.
[13:05:24 VRB] Setting correlation response header 'X-Transaction-ID' to 'ef443753-a230-48db-9aa2-4dece6d0b9f9'
[13:05:24 VRB] Setting correlation response header 'RequestId' to '0HLUM5I9L951E:00000001'
[13:05:24 VRB] All hosts are allowed.
[13:05:24 VRB] Setting correlation response header 'X-Transaction-ID' to 'df189355-8254-4418-b1f7-de0a6e940df5'
[13:05:24 VRB] Setting correlation response header 'RequestId' to '0HLUM5I9L951E:00000003'
[13:05:46 VRB] All hosts are allowed.
[13:05:46 DBG] The request path  does not match the path filter
[13:05:48 DBG] Request successfully matched the route with name 'TestApi' and template 'api/Tests/api/test'
[13:05:48 INF] Route matched with {action = "Get", controller = "Tests"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] GetAsync() on controller TestCorrelationWebApp.Controllers.TestsController (TestCorrelationWebApp).
[13:05:48 DBG] Execution plan of authorization filters (in the following order): ["None"]
[13:05:48 DBG] Execution plan of resource filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"]
[13:05:48 DBG] Execution plan of action filters (in the following order): ["Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)", "Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter (Order: -2000)"]
[13:05:48 DBG] Execution plan of exception filters (in the following order): ["None"]
[13:05:48 DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter", "Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter (Order: -2000)"]
[13:05:48 VRB] Resource Filter: Before executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:48 VRB] Resource Filter: After executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:48 DBG] Executing controller factory for controller TestCorrelationWebApp.Controllers.TestsController (TestCorrelationWebApp)
[13:05:48 DBG] Executed controller factory for controller TestCorrelationWebApp.Controllers.TestsController (TestCorrelationWebApp)
[13:05:48 VRB] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[13:05:48 VRB] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[13:05:48 VRB] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[13:05:48 VRB] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[13:05:48 INF] Executing action method TestCorrelationWebApp.Controllers.TestsController.GetAsync (TestCorrelationWebApp) - Validation state: Valid
[13:05:48 VRB] mymessage
[13:05:51 INF] SQL Dependency {DependencyTargetName} for {DependencyName} for operation {DependencyData} in {DependencyDuration} at {DependencyStartTime} (Successful: {DependencyIsSuccessful} - Context: {})
[13:05:51 INF] Executed action method TestCorrelationWebApp.Controllers.TestsController.GetAsync (TestCorrelationWebApp), returned result Microsoft.AspNetCore.Mvc.OkResult in 3079.1691ms.
[13:05:51 VRB] Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[13:05:51 VRB] Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ModelStateInvalidFilter.
[13:05:51 VRB] Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[13:05:51 VRB] Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
[13:05:51 VRB] Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:51 VRB] Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:51 VRB] Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[13:05:51 VRB] Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[13:05:51 VRB] Before executing action result Microsoft.AspNetCore.Mvc.OkResult.
[13:05:51 INF] Executing HttpStatusCodeResult, setting HTTP status code 200
[13:05:51 VRB] After executing action result Microsoft.AspNetCore.Mvc.OkResult.
[13:05:51 VRB] Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[13:05:51 VRB] Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter.
[13:05:51 VRB] Result Filter: Before executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:52 VRB] Result Filter: After executing OnResultExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:52 VRB] Resource Filter: Before executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:52 VRB] Resource Filter: After executing OnResourceExecuted on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
[13:05:52 INF] Executed action TestCorrelationWebApp.Controllers.TestsController.GetAsync (TestCorrelationWebApp) in 3336.4133ms
[13:10:11 INF] HTTP Request {RequestMethod} {RequestHost}/{RequestUri} completed with {ResponseStatusCode} in {RequestDuration} at {RequestTime} - (Context: {})
[13:10:11 VRB] Setting correlation response header 'X-Transaction-ID' to 'bbc5aa48-5bbd-47df-9e63-5d97c9b22b4e'
[13:10:11 VRB] Setting correlation response header 'RequestId' to '0HLUM5I9L951E:00000005'
tomkerkhove commented 4 years ago

Working on it here: https://github.com/arcus-azure/arcus.observability/pull/68

Moving to Observability as the issue lies there.

stijnmoreels commented 4 years ago

But the console still doesn't show the correct rendered message. Even without using our extensions, placing the string directly...

The console couldn't render the context correctly, had to add this one: .Destructure.ByTransforming<Dictionary<string, object>>(dic => String.Join(", ", dic.Select(kv => $"[{kv.Key}, {kv.Value}]")))

tomkerkhove commented 4 years ago

What does it look like then?

This might be something we have to fix as well, would you mind opening a dedicated issue please?

stijnmoreels commented 4 years ago

It doesn't look like anything. The message is not rendered bc of this.

tomkerkhove commented 4 years ago

It should just work out of the box with our extensions, so if you have to add .Destructure.ByTransforming<Dictionary<string, object>>(dic => String.Join(", ", dic.Select(kv => $"[{kv.Key}, {kv.Value}]"))) to make it usable I'd argue we have to make it even simpler.

What was the configuration you had to use in the end?

stijnmoreels commented 4 years ago

It should just work out of the box with our extensions, so if you have to add .Destructure.ByTransforming<Dictionary<string, object>>(dic => String.Join(", ", dic.Select(kv => $"[{kv.Key}, {kv.Value}]"))) to make it usable I'd argue we have to make it even simpler.

What was the configuration you had to use in the end?

new LoggerConfiguration()
  .Destructure.ByTransforming<Dictionary<string, object>>(dic => String.Join(", ", dic.Select(kv => $"[{kv.Key}, {kv.Value}]")))
  .Enrich.WithCorrelationInfo(new HttpCorrelationInfoAccessor(app.ApplicationServices.GetService<IHttpContextAccessor>()))
  .WriteTo.Console()
  .WriteTo.AzureApplicationInsights()
tomkerkhove commented 4 years ago

If that line is a must then we have to help as Arcus :) We cause the issue, so have to fix the issue.

tomkerkhove commented 4 years ago

Did we have an open action for Observability here or only for Web API?

tomkerkhove commented 4 years ago

We checked and everything should be tackled. Are you missing something as part of this @gverstraete?

tomkerkhove commented 4 years ago

Correlation will be available in v0.1.0 which we're shipping now.

gverstraete commented 4 years ago

Thanks! Just checked and it worked; sorry for the late reply!