ApplicationInsights-dotnet: Dependency calls not being logged by App Insights when being performed as part of a Polly retry

Describe your environment. Describe any aspect of your environment relevant to the problem:

SDK version: 2.14.0
.NET runtime version (.NET or .NET Core, TargetFramework in the .csproj file): .netcore 3.1
Hosting Info (IIS/Azure WebApps/etc): Azure WebApp
Platform and OS version: Azure / WebApp

Since upgrading from v2.8.2, when using Polly to retry a failing Http request automatically only the first failing call to the dependency is being logged. Subsequent dependency calls are no longer appear to be logged.

Steps to reproduce. In ConfigureServices - configure app insights and setup a named http client:

  services.AddApplicationInsightsTelemetry();
  
  ...

  var httpClientBuilder = services.AddHttpClient("TestClient", (provider, client) =>
  {
     client.Timeout = TimeSpan.FromSeconds(120);
 });

  var retryPolicy = Policy.Handle<HttpRequestException>()
        .OrResult<HttpResponseMessage>(response => (int)response.StatusCode >= 500)
        .WaitAndRetryAsync(5, retryAttempt => TimeSpan.FromSeconds(1), (result, span) =>
                {
                    Console.WriteLine(result.Result.StatusCode);
                });

  httpClientBuilder.AddPolicyHandler(retryPolicy);

In Configure add a failing call to demonstrate the behaviour:


  ...
  var httpClientFactory = app.ApplicationServices.GetService<IHttpClientFactory>();
  var httpClient = httpClientFactory.CreateClient("TestClient");
  var request = new HttpRequestMessage(HttpMethod.Get, new Uri("http://httpstat.us/500"));
  var result = httpClient.SendAsync(request).Result;

What is the expected behavior? I would expect each call to the failing endpoint to be logged as a separate dependency call.

What is the actual behavior? I see only a single dependency call logged - the initial call. In the previous version of App Insights all of the calls were being logged.

Additional context. The above uses Polly 3.1.3

About this issue

Original URL
State: open
Created 4 years ago
Reactions: 9
Comments: 24 (8 by maintainers)

Most upvoted comments

Dear all,

It’s been a long time since we’ve had any update on this issue? Has any investigation been done on this? We even provided a minimal repo (as asked) for you guys to investigate.

Looking forward to hearing from you guys. Thanks.

karun-verghese on Mar 30, 2021

Is there anyone who has found a workaround on this? Wrapping retries somehow and manually generating dependency telemetry?

We do it using DelegatingHandlers (Add sorting is important):

services.AddTransient<ApplicationInsightsPayloadTracerHandler>();

services
  .AddHttpClient(..)
  .AddPolicyHandler(..)
  .AddHttpMessageHandler<ApplicationInsightsPayloadTracerHandler>();

The custom DelegatingHandler to log requests and responses.

    public class ApplicationInsightsPayloadTracerHandler : DelegatingHandler
    {
        private readonly IServiceProvider _serviceProvider;
        private readonly ILogger<ApplicationInsightsPayloadTracerHandler> _logger;

        public ApplicationInsightsPayloadTracerHandler(...) { ... }

        protected override async Task<HttpResponseMessage> SendAsync(
            HttpRequestMessage request,
            CancellationToken cancellationToken)
        {
            HttpResponseMessage response = null;
            var requestTimestamp = DateTime.UtcNow;

            try
            {
                response = await base.SendAsync(request, cancellationToken);
            }
            finally
            {
                await TraceDependencyAsync(request, response, requestTimestamp);
            }

            return response;
        }

        private async Task TraceDependencyAsync(
            HttpRequestMessage request,
            HttpResponseMessage response,
            DateTimeOffset traceTimestamp)
        {
            string traceCorrelationId = ActivityTraceHelper.BuildTraceCorrelationId();

            await TraceRequestAsync(request, traceCorrelationId, traceTimestamp);
            await TraceResponseAsync(request, response, traceCorrelationId);
        }

        private async Task TraceRequestAsync(
            HttpRequestMessage request,
            string traceCorrelationId,
            DateTimeOffset traceTimestamp)
        {
            try
            {
                using var requestScope = _serviceProvider.CreateScope();
                var telemetryClient = requestScope.ServiceProvider.GetRequiredService<TelemetryClient>();

                ...

                var requestTelemetry = new TraceTelemetry
                {
                    SeverityLevel = SeverityLevel.Verbose,
                    Timestamp = traceTimestamp,
                };

                requestTelemetry.Properties.Add("TraceCorrelationId", traceCorrelationId);
                // log headers, status code, etc.
                telemetryClient.TrackTrace(requestTelemetry);
            }
            catch (Exception ex)  {  }
        }

        private async Task TraceResponseAsync(...)
        {
           // very likely as above
        }
    }

Note: To get request headers, use request.Headers.ToString().Split(Environment.NewLine) because ToString` method is internally overridden with a special implementation.

With this setup if the first attemp fails, Polly triggers the retry that will end up in this handler again, so the request will be logged twice.

Krusty93 on Apr 25, 2023

@pzbyszynski Ok. For functions, you need to raise this issue in https://github.com/Azure/azure-webjobs-sdk repo. Functions + ApplicationInsights integration is in that repo.

(But if you see same behaviour outside of functions, let us know right here, we can help)

cijothomas on Oct 22, 2020