diff --git a/src/Microsoft.AspNetCore.Sockets.Client.Http/HttpConnection.cs b/src/Microsoft.AspNetCore.Sockets.Client.Http/HttpConnection.cs index 3c6351e9a0..80d60342d2 100644 --- a/src/Microsoft.AspNetCore.Sockets.Client.Http/HttpConnection.cs +++ b/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; diff --git a/src/Microsoft.AspNetCore.Sockets.Client.Http/Internal/LoggingHttpMessageHandler.cs b/src/Microsoft.AspNetCore.Sockets.Client.Http/Internal/LoggingHttpMessageHandler.cs new file mode 100644 index 0000000000..4528821cb4 --- /dev/null +++ b/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 _logger; + + public LoggingHttpMessageHandler(HttpMessageHandler inner, ILoggerFactory loggerFactory) : base(inner) + { + if (loggerFactory == null) + { + throw new ArgumentNullException(nameof(loggerFactory)); + } + + _logger = loggerFactory.CreateLogger(); + } + + protected override async Task 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 _sendingHttpRequest = + LoggerMessage.Define(LogLevel.Trace, new EventId(1, "SendingHttpRequest"), "Sending HTTP request to '{RequestUrl}'."); + + private static readonly Action _unsuccessfulHttpResponse = + LoggerMessage.Define(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); + } + } + } +} diff --git a/src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.Log.cs b/src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.Log.cs index 4d06ca2412..062c6c9a0f 100644 --- a/src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.Log.cs +++ b/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 _startTransport = - LoggerMessage.Define(LogLevel.Information, new EventId(1, "StartTransport"), "Starting transport. Transfer mode: {TransferFormat}."); + private static readonly Action _startTransport = + LoggerMessage.Define(LogLevel.Information, new EventId(1, "StartTransport"), "Starting transport. Transfer mode: {TransferFormat}. Url: '{WebSocketUrl}'."); private static readonly Action _transportStopped = LoggerMessage.Define(LogLevel.Debug, new EventId(2, "TransportStopped"), "Transport stopped."); @@ -43,7 +43,7 @@ namespace Microsoft.AspNetCore.Sockets.Client LoggerMessage.Define(LogLevel.Debug, new EventId(10, "MessageToApp"), "Passing message to application. Payload size: {Count}."); private static readonly Action _webSocketClosed = - LoggerMessage.Define(LogLevel.Information, new EventId(11, "WebSocketClosed"), "Websocket closed by the server. Close status {CloseStatus}."); + LoggerMessage.Define(LogLevel.Information, new EventId(11, "WebSocketClosed"), "WebSocket closed by the server. Close status {CloseStatus}."); private static readonly Action _messageReceived = LoggerMessage.Define(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 _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) diff --git a/src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.cs b/src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.cs index e54e4d99d9..8e3981be43 100644 --- a/src/Microsoft.AspNetCore.Sockets.Client.Http/WebSocketsTransport.cs +++ b/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() diff --git a/test/Microsoft.AspNetCore.SignalR.Client.Tests/HttpConnectionTests.cs b/test/Microsoft.AspNetCore.SignalR.Client.Tests/HttpConnectionTests.cs index 613b892ffb..27227c1b4a 100644 --- a/test/Microsoft.AspNetCore.SignalR.Client.Tests/HttpConnectionTests.cs +++ b/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(); + mockLoggerFactory + .Setup(m => m.CreateLogger(It.IsAny())) + .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); + } } }