Introducing new event for failed http requests #106284 (#106964)

* Introduce new event for failed http requests

* remove response code, because it is not applicable

* fix log level from error to information and message

* fix formating

* fix message template and add tests

* minor fixes

Author: OlzhabaevSh

src/libraries/Microsoft.Extensions.Http/src/Logging/LogHelper.cs

@@ -25,11 +25,15 @@ private static class EventIds
             public static readonly EventId RequestHeader = new EventId(102, "RequestHeader");
             public static readonly EventId ResponseHeader = new EventId(103, "ResponseHeader");
 
+            public static readonly EventId RequestFailed = new EventId(104, "RequestFailed");
+
             public static readonly EventId PipelineStart = new EventId(100, "RequestPipelineStart");
             public static readonly EventId PipelineEnd = new EventId(101, "RequestPipelineEnd");
 
             public static readonly EventId RequestPipelineRequestHeader = new EventId(102, "RequestPipelineRequestHeader");
             public static readonly EventId RequestPipelineResponseHeader = new EventId(103, "RequestPipelineResponseHeader");
+
+            public static readonly EventId PipelineFailed = new EventId(104, "RequestPipelineFailed");
         }
 
         public static readonly Func<string, bool> ShouldRedactHeaderValue = (header) => true;
@@ -45,6 +49,11 @@ private static class EventIds
             EventIds.RequestEnd,
             "Received HTTP response headers after {ElapsedMilliseconds}ms - {StatusCode}");
 
+        private static readonly Action<ILogger, double, Exception?> _requestFailed = LoggerMessage.Define<double>(
+            LogLevel.Information,
+            EventIds.RequestFailed,
+            "HTTP request failed after {ElapsedMilliseconds}ms");
+
         private static readonly Func<ILogger, HttpMethod, string?, IDisposable?> _beginRequestPipelineScope = LoggerMessage.DefineScope<HttpMethod, string?>("HTTP {HttpMethod} {Uri}");
 
         private static readonly Action<ILogger, HttpMethod, string?, Exception?> _requestPipelineStart = LoggerMessage.Define<HttpMethod, string?>(
@@ -57,6 +66,11 @@ private static class EventIds
             EventIds.PipelineEnd,
             "End processing HTTP request after {ElapsedMilliseconds}ms - {StatusCode}");
 
+        private static readonly Action<ILogger, double, Exception?> _requestPipelineFailed = LoggerMessage.Define<double>(
+            LogLevel.Information,
+            EventIds.PipelineFailed,
+            "HTTP request failed after {ElapsedMilliseconds}ms");
+
         private static bool GetDisableUriRedactionSettingValue()
         {
             if (AppContext.TryGetSwitch("System.Net.Http.DisableUriRedaction", out bool value))
@@ -112,6 +126,9 @@ public static void LogRequestEnd(this ILogger logger, HttpResponseMessage respon
             }
         }
 
+        public static void LogRequestFailed(this ILogger logger, TimeSpan duration, HttpRequestException exception) =>
+            _requestFailed(logger, duration.TotalMilliseconds, exception);
+
         public static IDisposable? BeginRequestPipelineScope(this ILogger logger, HttpRequestMessage request, out string? formattedUri)
         {
             formattedUri = GetRedactedUriString(request.RequestUri);
@@ -148,6 +165,9 @@ public static void LogRequestPipelineEnd(this ILogger logger, HttpResponseMessag
             }
         }
 
+        public static void LogRequestPipelineFailed(this ILogger logger, TimeSpan duration, HttpRequestException exception) =>
+            _requestPipelineFailed(logger, duration.TotalMilliseconds, exception);
+
         internal static string? GetRedactedUriString(Uri? uri)
         {
             if (uri is null)

src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingHttpMessageHandler.cs

@@ -59,16 +59,25 @@ async Task<HttpResponseMessage> Core(HttpRequestMessage request, bool useAsync,
                 // not really anything to surround.
                 _logger.LogRequestStart(request, shouldRedactHeaderValue);
                 var stopwatch = ValueStopwatch.StartNew();
-                HttpResponseMessage response = useAsync
-                    ? await base.SendAsync(request, cancellationToken).ConfigureAwait(false)
+
+                try
+                {
+                    HttpResponseMessage response = useAsync
+                        ? await base.SendAsync(request, cancellationToken).ConfigureAwait(false)
 #if NET
-                    : base.Send(request, cancellationToken);
+                        : base.Send(request, cancellationToken);
 #else
-                    : throw new NotImplementedException("Unreachable code");
+                        : throw new NotImplementedException("Unreachable code");
 #endif
-                _logger.LogRequestEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);
+                    _logger.LogRequestEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);
 
-                return response;
+                    return response;
+                }
+                catch (HttpRequestException ex)
+                {
+                    _logger.LogRequestFailed(stopwatch.GetElapsedTime(), ex);
+                    throw;
+                }
             }
         }
 

src/libraries/Microsoft.Extensions.Http/src/Logging/LoggingScopeHttpMessageHandler.cs

@@ -59,16 +59,25 @@ async Task<HttpResponseMessage> Core(HttpRequestMessage request, bool useAsync,
                 using (_logger.BeginRequestPipelineScope(request, out string? formattedUri))
                 {
                     _logger.LogRequestPipelineStart(request, formattedUri, shouldRedactHeaderValue);
-                    HttpResponseMessage response = useAsync
-                        ? await base.SendAsync(request, cancellationToken).ConfigureAwait(false)
+
+                    try
+                    {
+                        HttpResponseMessage response = useAsync
+                            ? await base.SendAsync(request, cancellationToken).ConfigureAwait(false)
 #if NET
-                        : base.Send(request, cancellationToken);
+                            : base.Send(request, cancellationToken);
 #else
-                        : throw new NotImplementedException("Unreachable code");
+                            : throw new NotImplementedException("Unreachable code");
 #endif
-                    _logger.LogRequestPipelineEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);
+                        _logger.LogRequestPipelineEnd(response, stopwatch.GetElapsedTime(), shouldRedactHeaderValue);
 
-                    return response;
+                        return response;
+                    }
+                    catch (HttpRequestException ex)
+                    {
+                        _logger.LogRequestPipelineFailed(stopwatch.GetElapsedTime(), ex);
+                        throw;
+                    }
                 }
             }
         }

src/libraries/Microsoft.Extensions.Http/tests/Microsoft.Extensions.Http.Tests/Logging/FailedHttpRequestLoggingTests.cs

@@ -0,0 +1,77 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System.Linq;
+using System.Net.Http;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.Extensions.DependencyInjection;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Testing;
+using Xunit;
+
+namespace Microsoft.Extensions.Http.Tests.Logging
+{
+    public class FailedHttpRequestLoggingTests
+    {
+        private const string OuterLoggerName = "System.Net.Http.HttpClient.test.LogicalHandler";
+        private const string InnerLoggerName = "System.Net.Http.HttpClient.test.ClientHandler";
+
+        private static class EventIds
+        {
+            public static readonly EventId RequestFailed = new EventId(104, "RequestFailed");
+            public static readonly EventId PipelineFailed = new EventId(104, "RequestPipelineFailed");
+        }
+
+        [Fact]
+        public async Task FailedHttpRequestLogged()
+        {
+            // Arrange
+            var sink = new TestSink();
+
+            var serviceCollection = new ServiceCollection();
+            serviceCollection.AddLogging();
+            serviceCollection.AddSingleton<ILoggerFactory>(new TestLoggerFactory(sink, enabled: true));
+
+            // Act
+            serviceCollection
+                .AddHttpClient("test")
+                .ConfigurePrimaryHttpMessageHandler(() => new FailMessageHandler());
+
+            // Assert
+            var services = serviceCollection.BuildServiceProvider();
+
+            var client = services.GetRequiredService<IHttpClientFactory>().CreateClient("test");
+
+            var request = new HttpRequestMessage(HttpMethod.Get, "http://example.com");
+
+            await Assert.ThrowsAsync<HttpRequestException>(async () =>
+                await client.SendAsync(request));
+
+            var messages = sink.Writes.ToArray();
+
+            var requestFailedMessage = Assert.Single(messages.Where(m =>
+            {
+                return
+                    m.EventId == EventIds.RequestFailed &&
+                    m.LoggerName == InnerLoggerName;
+            }));
+            var pipelineFailedMessage = Assert.Single(messages.Where(m =>
+            {
+                return
+                    m.EventId == EventIds.PipelineFailed &&
+                    m.LoggerName == OuterLoggerName;
+            }));
+        }
+
+        private const string ExceptionMessage = "Dummy error message";
+
+        private class FailMessageHandler : HttpClientHandler
+        {
+            protected override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
+            {
+                throw new HttpRequestException(ExceptionMessage);
+            }
+        }
+    }
+}