From 5c633aa1834071ecd99ae29b9b88eee0b9262948 Mon Sep 17 00:00:00 2001 From: James Newton-King Date: Thu, 24 May 2018 14:21:48 +1200 Subject: [PATCH] Log 404 responses from long polling transport DELETE as Debug instead of Error (#2366) --- .../Internal/LongPollingTransport.Log.cs | 8 +++ .../Internal/LongPollingTransport.cs | 13 ++++- .../LongPollingTransportTests.cs | 55 ++++++++++++++++++- 3 files changed, 73 insertions(+), 3 deletions(-) diff --git a/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.Log.cs b/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.Log.cs index ec407297e5..2329c49f41 100644 --- a/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.Log.cs +++ b/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.Log.cs @@ -53,6 +53,9 @@ namespace Microsoft.AspNetCore.Http.Connections.Client.Internal private static readonly Action _errorSendingDeleteRequest = LoggerMessage.Define(LogLevel.Error, new EventId(13, "ErrorSendingDeleteRequest"), "Error sending DELETE request to '{PollUrl}'."); + private static readonly Action _connectionAlreadyClosedSendingDeleteRequest = + LoggerMessage.Define(LogLevel.Debug, new EventId(14, "ConnectionAlreadyClosedSendingDeleteRequest"), "A 404 response was returned from sending DELETE request to '{PollUrl}', likely because the transport was already closed on the server."); + // EventIds 100 - 106 used in SendUtils public static void StartTransport(ILogger logger, TransferFormat transferFormat) @@ -123,6 +126,11 @@ namespace Microsoft.AspNetCore.Http.Connections.Client.Internal { _errorSendingDeleteRequest(logger, pollUrl, ex); } + + public static void ConnectionAlreadyClosedSendingDeleteRequest(ILogger logger, Uri pollUrl) + { + _connectionAlreadyClosedSendingDeleteRequest(logger, pollUrl, null); + } } } } diff --git a/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.cs b/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.cs index 860f54b3ee..f2a92e71d3 100644 --- a/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.cs +++ b/src/Microsoft.AspNetCore.Http.Connections.Client/Internal/LongPollingTransport.cs @@ -221,8 +221,17 @@ namespace Microsoft.AspNetCore.Http.Connections.Client.Internal { Log.SendingDeleteRequest(_logger, url); var response = await _httpClient.DeleteAsync(url); - response.EnsureSuccessStatusCode(); - Log.DeleteRequestAccepted(_logger, url); + + if (response.StatusCode == HttpStatusCode.NotFound) + { + Log.ConnectionAlreadyClosedSendingDeleteRequest(_logger, url); + } + else + { + // Check for non-404 errors + response.EnsureSuccessStatusCode(); + Log.DeleteRequestAccepted(_logger, url); + } } catch (Exception ex) { diff --git a/test/Microsoft.AspNetCore.SignalR.Client.Tests/LongPollingTransportTests.cs b/test/Microsoft.AspNetCore.SignalR.Client.Tests/LongPollingTransportTests.cs index ee4c60daac..9dfbb30b56 100644 --- a/test/Microsoft.AspNetCore.SignalR.Client.Tests/LongPollingTransportTests.cs +++ b/test/Microsoft.AspNetCore.SignalR.Client.Tests/LongPollingTransportTests.cs @@ -17,16 +17,22 @@ using System.Threading.Tasks; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Http.Connections.Client; using Microsoft.AspNetCore.Http.Connections.Client.Internal; +using Microsoft.AspNetCore.SignalR.Tests; using Moq; using Moq.Protected; using Xunit; +using Xunit.Abstractions; namespace Microsoft.AspNetCore.SignalR.Client.Tests { - public class LongPollingTransportTests + public class LongPollingTransportTests : VerifiableLoggedTest { private static readonly Uri TestUri = new Uri("http://example.com/?id=1234"); + public LongPollingTransportTests(ITestOutputHelper output) : base(output) + { + } + [Fact] public async Task LongPollingTransportStopsPollAndSendLoopsWhenTransportStopped() { @@ -222,6 +228,53 @@ namespace Microsoft.AspNetCore.SignalR.Client.Tests } } + [Fact] + public async Task StopTransportWhenConnectionAlreadyStoppedOnServer() + { + var pollRequestTcs = new TaskCompletionSource(); + + var mockHttpHandler = new Mock(); + var firstPoll = true; + mockHttpHandler.Protected() + .Setup>("SendAsync", ItExpr.IsAny(), ItExpr.IsAny()) + .Returns(async (request, cancellationToken) => + { + await Task.Yield(); + if (request.Method == HttpMethod.Delete) + { + // Simulate the server having already cleaned up the connection on the server + return ResponseUtils.CreateResponse(HttpStatusCode.NotFound); + } + else + { + if (firstPoll) + { + firstPoll = false; + return ResponseUtils.CreateResponse(HttpStatusCode.OK); + } + + await pollRequestTcs.Task; + return ResponseUtils.CreateResponse(HttpStatusCode.OK); + } + }); + + using (StartVerifiableLog(out var loggerFactory)) + { + using (var httpClient = new HttpClient(mockHttpHandler.Object)) + { + var longPollingTransport = new LongPollingTransport(httpClient, loggerFactory); + + await longPollingTransport.StartAsync(TestUri, TransferFormat.Binary).OrTimeout(); + + var stopTask = longPollingTransport.StopAsync(); + + pollRequestTcs.SetResult(null); + + await stopTask.OrTimeout(); + } + } + } + [Fact] public async Task LongPollingTransportStopsWhenSendRequestFails() {