Added logging of .NET client HTTP requests (#1723)

src/Microsoft.AspNetCore.Sockets.Client.Http/HttpConnection.cs

@@ -14,6 +14,7 @@ using System.Threading.Tasks;
 using Microsoft.AspNetCore.Http.Features;
 using Microsoft.AspNetCore.Connections;
 using Microsoft.AspNetCore.Sockets.Client.Http;
+using Microsoft.AspNetCore.Sockets.Client.Http.Internal;
 using Microsoft.AspNetCore.Sockets.Client.Internal;
 using Microsoft.AspNetCore.Sockets.Http.Internal;
 using Microsoft.AspNetCore.Sockets.Internal;
@@ -26,7 +27,9 @@ namespace Microsoft.AspNetCore.Sockets.Client
     public partial class HttpConnection : IConnection
     {
         private static readonly TimeSpan HttpClientTimeout = TimeSpan.FromSeconds(120);
+#if !NETCOREAPP2_1
         private static readonly Version Windows8Version = new Version(6, 2);
+#endif
 
         private readonly ILoggerFactory _loggerFactory;
         private readonly ILogger _logger;
@@ -99,10 +102,11 @@ namespace Microsoft.AspNetCore.Sockets.Client
 
         private HttpClient CreateHttpClient()
         {
-            HttpMessageHandler httpMessageHandler = null;
+            var httpClientHandler = new HttpClientHandler();
+            HttpMessageHandler httpMessageHandler = httpClientHandler;
+
             if (_httpOptions != null)
             {
-                var httpClientHandler = new HttpClientHandler();
                 if (_httpOptions.Proxy != null)
                 {
                     httpClientHandler.Proxy = _httpOptions.Proxy;
@@ -135,7 +139,10 @@ namespace Microsoft.AspNetCore.Sockets.Client
                 }
             }
 
-            var httpClient = httpMessageHandler == null ? new HttpClient() : new HttpClient(httpMessageHandler);
+            // Wrap message handler in a logging handler last to ensure it is always present
+            httpMessageHandler = new LoggingHttpMessageHandler(httpMessageHandler, _loggerFactory);
+
+            var httpClient = new HttpClient(httpMessageHandler);
             httpClient.Timeout = HttpClientTimeout;
 
             return httpClient;

src/Microsoft.AspNetCore.Sockets.Client.Http/Internal/LoggingHttpMessageHandler.cs

@@ -0,0 +1,62 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using System.Collections.Generic;
+using System.Net;
+using System.Net.Http;
+using System.Text;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
+
+namespace Microsoft.AspNetCore.Sockets.Client.Http.Internal
+{
+    public class LoggingHttpMessageHandler : DelegatingHandler
+    {
+        private readonly ILogger<LoggingHttpMessageHandler> _logger;
+
+        public LoggingHttpMessageHandler(HttpMessageHandler inner, ILoggerFactory loggerFactory) : base(inner)
+        {
+            if (loggerFactory == null)
+            {
+                throw new ArgumentNullException(nameof(loggerFactory));
+            }
+
+            _logger = loggerFactory.CreateLogger<LoggingHttpMessageHandler>();
+        }
+
+        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
+        {
+            Log.SendingHttpRequest(_logger, request.RequestUri);
+
+            var response = await base.SendAsync(request, cancellationToken);
+
+            if (!response.IsSuccessStatusCode)
+            {
+                Log.UnsuccessfulHttpResponse(_logger, request.RequestUri, response.StatusCode);
+            }
+
+            return response;
+        }
+
+        private static class Log
+        {
+            private static readonly Action<ILogger, Uri, Exception> _sendingHttpRequest =
+                LoggerMessage.Define<Uri>(LogLevel.Trace, new EventId(1, "SendingHttpRequest"), "Sending HTTP request to '{RequestUrl}'.");
+
+            private static readonly Action<ILogger, Uri, HttpStatusCode, Exception> _unsuccessfulHttpResponse =
+                LoggerMessage.Define<Uri, HttpStatusCode>(LogLevel.Warning, new EventId(2, "UnsuccessfulHttpResponse"), "Unsuccessful HTTP response status code of {StatusCode} return from '{RequestUrl}'.");
+
+            public static void SendingHttpRequest(ILogger logger, Uri requestUrl)
+            {
+                _sendingHttpRequest(logger, requestUrl, null);
+            }
+            public static void UnsuccessfulHttpResponse(ILogger logger, Uri requestUrl, HttpStatusCode statusCode)
+            {
+                _unsuccessfulHttpResponse(logger, requestUrl, statusCode, null);
+            }
+        }
+    }
+}

src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.Log.cs

@@ -12,8 +12,8 @@ namespace Microsoft.AspNetCore.Sockets.Client
     {
         private static class Log
         {
-            private static readonly Action<ILogger, TransferFormat, Exception> _startTransport =
+            private static readonly Action<ILogger, TransferFormat, Uri, Exception> _startTransport =
-                LoggerMessage.Define<TransferFormat>(LogLevel.Information, new EventId(1, "StartTransport"), "Starting transport. Transfer mode: {TransferFormat}.");
+                LoggerMessage.Define<TransferFormat, Uri>(LogLevel.Information, new EventId(1, "StartTransport"), "Starting transport. Transfer mode: {TransferFormat}. Url: '{WebSocketUrl}'.");
 
             private static readonly Action<ILogger, Exception> _transportStopped =
                 LoggerMessage.Define(LogLevel.Debug, new EventId(2, "TransportStopped"), "Transport stopped.");
@@ -43,7 +43,7 @@ namespace Microsoft.AspNetCore.Sockets.Client
                 LoggerMessage.Define<int>(LogLevel.Debug, new EventId(10, "MessageToApp"), "Passing message to application. Payload size: {Count}.");
 
             private static readonly Action<ILogger, WebSocketCloseStatus?, Exception> _webSocketClosed =
-                LoggerMessage.Define<WebSocketCloseStatus?>(LogLevel.Information, new EventId(11, "WebSocketClosed"), "Websocket closed by the server. Close status {CloseStatus}.");
+                LoggerMessage.Define<WebSocketCloseStatus?>(LogLevel.Information, new EventId(11, "WebSocketClosed"), "WebSocket closed by the server. Close status {CloseStatus}.");
 
             private static readonly Action<ILogger, WebSocketMessageType, int, bool, Exception> _messageReceived =
                 LoggerMessage.Define<WebSocketMessageType, int, bool>(LogLevel.Debug, new EventId(12, "MessageReceived"), "Message received. Type: {MessageType}, size: {Count}, EndOfMessage: {EndOfMessage}.");
@@ -66,9 +66,9 @@ namespace Microsoft.AspNetCore.Sockets.Client
             private static readonly Action<ILogger, Exception> _cancelMessage =
                 LoggerMessage.Define(LogLevel.Debug, new EventId(18, "CancelMessage"), "Canceled passing message to application.");
 
-            public static void StartTransport(ILogger logger, TransferFormat transferFormat)
+            public static void StartTransport(ILogger logger, TransferFormat transferFormat, Uri webSocketUrl)
             {
-                _startTransport(logger, transferFormat, null);
+                _startTransport(logger, transferFormat, webSocketUrl, null);
             }
 
             public static void TransportStopped(ILogger logger, Exception exception)

src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.cs

@@ -109,10 +109,11 @@ namespace Microsoft.AspNetCore.Sockets.Client
                 ? WebSocketMessageType.Binary
                 : WebSocketMessageType.Text;
 
+            var resolvedUrl = ResolveWebSocketsUrl(url);
 
-            Log.StartTransport(_logger, transferFormat);
+            Log.StartTransport(_logger, transferFormat, resolvedUrl);
 
-            await Connect(url);
+            await _webSocket.ConnectAsync(resolvedUrl, CancellationToken.None);
 
             // TODO: Handle TCP connection errors
             // https://github.com/SignalR/SignalR/blob/1fba14fa3437e24c204dfaf8a18db3fce8acad3c/src/Microsoft.AspNet.SignalR.Core/Owin/WebSockets/WebSocketHandler.cs#L248-L251
@@ -324,7 +325,7 @@ namespace Microsoft.AspNetCore.Sockets.Client
                    ws.State == WebSocketState.CloseSent);
         }
 
-        private async Task Connect(Uri url)
+        private static Uri ResolveWebSocketsUrl(Uri url)
         {
             var uriBuilder = new UriBuilder(url);
             if (url.Scheme == "http")
@@ -336,7 +337,7 @@ namespace Microsoft.AspNetCore.Sockets.Client
                 uriBuilder.Scheme = "wss";
             }
 
-            await _webSocket.ConnectAsync(uriBuilder.Uri, CancellationToken.None);
+            return uriBuilder.Uri;
         }
 
         public async Task StopAsync()

test/Microsoft.AspNetCore.SignalR.Client.Tests/HttpConnectionTests.cs

@@ -12,7 +12,9 @@ using Microsoft.AspNetCore.Client.Tests;
 using Microsoft.AspNetCore.Connections;
 using Microsoft.AspNetCore.Sockets.Client;
 using Microsoft.AspNetCore.Sockets.Client.Http;
+using Microsoft.AspNetCore.Sockets.Client.Http.Internal;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
 using Microsoft.Extensions.Logging.Testing;
 using Moq;
 using Xunit;
@@ -172,5 +174,43 @@ namespace Microsoft.AspNetCore.SignalR.Client.Tests
             Assert.Same(httpOptions.Proxy, httpClientHandler.Proxy);
             Assert.Same(httpOptions.Credentials, httpClientHandler.Credentials);
         }
+
+        [Fact]
+        public async Task HttpRequestAndErrorResponseLogged()
+        {
+            var testHttpHandler = new TestHttpMessageHandler(false);
+
+            testHttpHandler.OnNegotiate((request, cancellationToken) => ResponseUtils.CreateResponse(HttpStatusCode.BadGateway));
+
+            var httpOptions = new HttpOptions();
+            httpOptions.HttpMessageHandler = inner => testHttpHandler;
+
+            const string loggerName = "Microsoft.AspNetCore.Sockets.Client.Http.Internal.LoggingHttpMessageHandler";
+            var testSink = new TestSink();
+            var logger = new TestLogger(loggerName, testSink, true);
+
+            var mockLoggerFactory = new Mock<ILoggerFactory>();
+            mockLoggerFactory
+                .Setup(m => m.CreateLogger(It.IsAny<string>()))
+                .Returns((string categoryName) => (categoryName == loggerName) ? (ILogger)logger : NullLogger.Instance);
+
+            try
+            {
+                await WithConnectionAsync(
+                    CreateConnection(httpOptions, loggerFactory: mockLoggerFactory.Object, url: "http://fakeuri.org/"),
+                    async (connection, closed) =>
+                    {
+                        await connection.StartAsync(TransferFormat.Text).OrTimeout();
+                    });
+            }
+            catch
+            {
+                // ignore connection error
+            }
+
+            Assert.Equal(2, testSink.Writes.Count);
+            Assert.Equal("SendingHttpRequest", testSink.Writes[0].EventId.Name);
+            Assert.Equal("UnsuccessfulHttpResponse", testSink.Writes[1].EventId.Name);
+        }
     }
 }