From b3d72773b113e3af158cc37fe49d565316274ed9 Mon Sep 17 00:00:00 2001 From: Stephen Halter Date: Wed, 7 Nov 2018 17:09:21 -0800 Subject: [PATCH] Fix race conditions in HTTP/2 tests (#3024) --- .../Internal/Http2/Http2MessageBody.cs | 2 +- .../Internal/Http2/Http2Stream.cs | 51 ++++++---- .../Http2/Http2ConnectionTests.cs | 98 +++++++++---------- .../Http2/Http2TestBase.cs | 7 +- .../Http2/Http2TimeoutTests.cs | 76 ++++++++------ 5 files changed, 129 insertions(+), 105 deletions(-) diff --git a/src/Kestrel.Core/Internal/Http2/Http2MessageBody.cs b/src/Kestrel.Core/Internal/Http2/Http2MessageBody.cs index c2ef70a8cc..7427e98e14 100644 --- a/src/Kestrel.Core/Internal/Http2/Http2MessageBody.cs +++ b/src/Kestrel.Core/Internal/Http2/Http2MessageBody.cs @@ -44,7 +44,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 public static MessageBody For(Http2Stream context, MinDataRate minRequestBodyDataRate) { - if (context.EndStreamReceived && !context.RequestBodyStarted) + if (context.ReceivedEmptyRequestBody) { return ZeroContentLengthClose; } diff --git a/src/Kestrel.Core/Internal/Http2/Http2Stream.cs b/src/Kestrel.Core/Internal/Http2/Http2Stream.cs index 13c23e91bc..7ba88ec746 100644 --- a/src/Kestrel.Core/Internal/Http2/Http2Stream.cs +++ b/src/Kestrel.Core/Internal/Http2/Http2Stream.cs @@ -70,6 +70,17 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 public override bool IsUpgradableRequest => false; + public bool ReceivedEmptyRequestBody + { + get + { + lock (_completionLock) + { + return EndStreamReceived && !RequestBodyStarted; + } + } + } + protected override void OnReset() { ResetHttp2Features(); @@ -326,25 +337,19 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 if (dataPayload.Length > 0) { - RequestBodyStarted = true; - - if (endStream) - { - // No need to send any more window updates for this stream now that we've received all the data. - // Call before flushing the request body pipe, because that might induce a window update. - _inputFlowControl.StopWindowUpdates(); - } - - _inputFlowControl.Advance((int)dataPayload.Length); - lock (_completionLock) { - if (IsAborted) + RequestBodyStarted = true; + + if (endStream) { - // Ignore data frames for aborted streams, but only after counting them for purposes of connection level flow control. - return Task.CompletedTask; + // No need to send any more window updates for this stream now that we've received all the data. + // Call before flushing the request body pipe, because that might induce a window update. + _inputFlowControl.StopWindowUpdates(); } + _inputFlowControl.Advance((int)dataPayload.Length); + // This check happens after flow control so that when we throw and abort, the byte count is returned to the connection // level accounting. if (InputRemaining.HasValue) @@ -358,15 +363,19 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2 InputRemaining -= dataPayload.Length; } - foreach (var segment in dataPayload) + // Ignore data frames for aborted streams, but only after counting them for purposes of connection level flow control. + if (!IsAborted) { - RequestBodyPipe.Writer.Write(segment.Span); - } - var flushTask = RequestBodyPipe.Writer.FlushAsync(); + foreach (var segment in dataPayload) + { + RequestBodyPipe.Writer.Write(segment.Span); + } + var flushTask = RequestBodyPipe.Writer.FlushAsync(); - // It shouldn't be possible for the RequestBodyPipe to fill up an return an incomplete task if - // _inputFlowControl.Advance() didn't throw. - Debug.Assert(flushTask.IsCompleted); + // It shouldn't be possible for the RequestBodyPipe to fill up an return an incomplete task if + // _inputFlowControl.Advance() didn't throw. + Debug.Assert(flushTask.IsCompleted); + } } } diff --git a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs index 28e4fb3a56..c845a11a08 100644 --- a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs +++ b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2ConnectionTests.cs @@ -816,19 +816,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await SendDataAsync(1, _helloWorldBytes, endStream: false); + // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. await WaitForConnectionErrorAsync( ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, expectedErrorCode: Http2ErrorCode.STREAM_CLOSED, - expectedErrorMessage: null); - - // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. - var closedMessage = CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.DATA, streamId: 1); - var halfClosedMessage = CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(Http2FrameType.DATA, streamId: 1); - - var message = Assert.Single(TestApplicationErrorLogger.Messages, m => m.Exception is Http2ConnectionErrorException); - Assert.True(message.Exception.Message.IndexOf(closedMessage) >= 0 - || message.Exception.Message.IndexOf(halfClosedMessage) >= 0); + expectedErrorMessage: new[] { + CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.DATA, streamId: 1), + CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(Http2FrameType.DATA, streamId: 1) + }); } [Fact] @@ -1329,19 +1325,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests // Try to re-use the stream ID (http://httpwg.org/specs/rfc7540.html#rfc.section.5.1.1) await StartStreamAsync(1, _browserRequestHeaders, endStream: true); + // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. await WaitForConnectionErrorAsync( ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, expectedErrorCode: Http2ErrorCode.STREAM_CLOSED, - expectedErrorMessage: null); - - // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. - var closedMessage = CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.HEADERS, streamId: 1); - var halfClosedMessage = CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(Http2FrameType.HEADERS, streamId: 1); - - var message = Assert.Single(TestApplicationErrorLogger.Messages, m => m.Exception is Http2ConnectionErrorException); - Assert.True(message.Exception.Message.IndexOf(closedMessage) >= 0 - || message.Exception.Message.IndexOf(halfClosedMessage) >= 0); + expectedErrorMessage: new[] { + CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.HEADERS, streamId: 1), + CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(Http2FrameType.HEADERS, streamId: 1) + }); } [Fact] @@ -3782,12 +3774,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests // Logged without an exception. Assert.Contains(TestApplicationErrorLogger.Messages, m => m.Message.Contains("the application completed without reading the entire request body.")); - // There's a race when the appfunc is exiting about how soon it unregisters the stream. - for (var i = 0; i < 10; i++) - { - await SendDataAsync(1, new byte[100], endStream: false); - } - // These would be refused if the cool-down period had expired switch (finalFrameType) { @@ -3830,12 +3816,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await WaitForStreamErrorAsync(1, Http2ErrorCode.INTERNAL_ERROR, "The connection was aborted by the application."); - // There's a race when the appfunc is exiting about how soon it unregisters the stream. - for (var i = 0; i < 10; i++) - { - await SendDataAsync(1, new byte[100], endStream: false); - } - // These would be refused if the cool-down period had expired switch (finalFrameType) { @@ -3877,21 +3857,22 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await WaitForStreamErrorAsync(1, Http2ErrorCode.INTERNAL_ERROR, "The connection was aborted by the application."); - // There's a race when the appfunc is exiting about how soon it unregisters the stream. - for (var i = 0; i < 10; i++) - { - await SendDataAsync(1, new byte[100], endStream: false); - } - switch (finalFrameType) { case Http2FrameType.DATA: await SendDataAsync(1, new byte[100], endStream: true); // An extra one to break it await SendDataAsync(1, new byte[100], endStream: true); - - await WaitForConnectionErrorAsync(ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, Http2ErrorCode.STREAM_CLOSED, - CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.DATA, 1)); + + // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. + await WaitForConnectionErrorAsync( + ignoreNonGoAwayFrames: false, + expectedLastStreamId: 1, + expectedErrorCode: Http2ErrorCode.STREAM_CLOSED, + expectedErrorMessage: new[] { + CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.DATA, streamId: 1), + CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(Http2FrameType.DATA, streamId: 1) + }); break; case Http2FrameType.HEADERS: @@ -3899,8 +3880,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests // An extra one to break it await SendHeadersAsync(1, Http2HeadersFrameFlags.END_STREAM | Http2HeadersFrameFlags.END_HEADERS, _requestTrailers); - await WaitForConnectionErrorAsync(ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, Http2ErrorCode.STREAM_CLOSED, - CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.HEADERS, 1)); + // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. + await WaitForConnectionErrorAsync( + ignoreNonGoAwayFrames: false, + expectedLastStreamId: 1, + expectedErrorCode: Http2ErrorCode.STREAM_CLOSED, + expectedErrorMessage: new[] { + CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.HEADERS, streamId: 1), + CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(Http2FrameType.HEADERS, streamId: 1) + }); break; case Http2FrameType.CONTINUATION: @@ -3908,8 +3896,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await SendContinuationAsync(1, Http2ContinuationFrameFlags.END_HEADERS, _requestTrailers); // An extra one to break it. It's not a Continuation because that would fail with an error that no headers were in progress. await SendHeadersAsync(1, Http2HeadersFrameFlags.END_STREAM, _requestTrailers); - await WaitForConnectionErrorAsync(ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, Http2ErrorCode.STREAM_CLOSED, - CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.HEADERS, 1)); + + // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. + await WaitForConnectionErrorAsync( + ignoreNonGoAwayFrames: false, + expectedLastStreamId: 1, + expectedErrorCode: Http2ErrorCode.STREAM_CLOSED, + expectedErrorMessage: new[] { + CoreStrings.FormatHttp2ErrorStreamClosed(Http2FrameType.HEADERS, streamId: 1), + CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(Http2FrameType.HEADERS, streamId: 1) + }); break; default: throw new NotImplementedException(finalFrameType.ToString()); @@ -3933,11 +3929,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await WaitForStreamErrorAsync(1, Http2ErrorCode.INTERNAL_ERROR, "The connection was aborted by the application."); - // There's a race when the appfunc is exiting about how soon it unregisters the stream. - for (var i = 0; i < 10; i++) - { - await SendDataAsync(1, new byte[100], endStream: false); - } await SendRstStreamAsync(1); // Send an extra frame to make it fail @@ -3955,8 +3946,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests throw new NotImplementedException(finalFrameType.ToString()); } - await WaitForConnectionErrorAsync(ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, Http2ErrorCode.STREAM_CLOSED, - CoreStrings.FormatHttp2ErrorStreamClosed(finalFrameType, 1)); + // There's a race where either of these messages could be logged, depending on if the stream cleanup has finished yet. + await WaitForConnectionErrorAsync( + ignoreNonGoAwayFrames: false, + expectedLastStreamId: 1, + expectedErrorCode: Http2ErrorCode.STREAM_CLOSED, + expectedErrorMessage: new[] { + CoreStrings.FormatHttp2ErrorStreamClosed(finalFrameType, streamId: 1), + CoreStrings.FormatHttp2ErrorStreamHalfClosedRemote(finalFrameType, streamId: 1) + }); } public static TheoryData UpperCaseHeaderNameData diff --git a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs index a160f70436..300eece503 100644 --- a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs +++ b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TestBase.cs @@ -1110,7 +1110,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests Assert.Equal(expectedErrorCode, frame.GoAwayErrorCode); } - protected async Task WaitForConnectionErrorAsync(bool ignoreNonGoAwayFrames, int expectedLastStreamId, Http2ErrorCode expectedErrorCode, string expectedErrorMessage) + protected async Task WaitForConnectionErrorAsync(bool ignoreNonGoAwayFrames, int expectedLastStreamId, Http2ErrorCode expectedErrorCode, params string[] expectedErrorMessage) where TException : Exception { var frame = await ReceiveFrameAsync(); @@ -1125,10 +1125,11 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests VerifyGoAway(frame, expectedLastStreamId, expectedErrorCode); - if (expectedErrorMessage != null) + if (expectedErrorMessage?.Length > 0) { var message = Assert.Single(TestApplicationErrorLogger.Messages, m => m.Exception is TException); - Assert.Contains(expectedErrorMessage, message.Exception.Message); + + Assert.Contains(expectedErrorMessage, expected => message.Exception.Message.Contains(expected)); } await _connectionTask; diff --git a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs index 2ded1c404a..42e232cbbd 100644 --- a/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs +++ b/test/Kestrel.InMemory.FunctionalTests/Http2/Http2TimeoutTests.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Threading; using System.Threading.Tasks; using Microsoft.AspNetCore.Connections; using Microsoft.AspNetCore.Server.Kestrel.Core.Features; @@ -191,7 +192,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests [Theory] [InlineData(Http2FrameType.DATA)] - [InlineData(Http2FrameType.HEADERS)] + [InlineData(Http2FrameType.CONTINUATION, Skip = "https://github.com/aspnet/KestrelHttpServer/issues/3077")] public async Task AbortedStream_ResetsAndDrainsRequest_RefusesFramesAfterCooldownExpires(Http2FrameType finalFrameType) { var mockSystemClock = _serviceContext.MockSystemClock; @@ -208,40 +209,55 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests await WaitForStreamErrorAsync(1, Http2ErrorCode.INTERNAL_ERROR, "The connection was aborted by the application."); - // There's a race when the appfunc is exiting about how soon it unregisters the stream. - for (var i = 0; i < 10; i++) + var cts = new CancellationTokenSource(); + + async Task AdvanceClockAndSendFrames() { - await SendDataAsync(1, new byte[100], endStream: false); + if (finalFrameType == Http2FrameType.CONTINUATION) + { + await SendHeadersAsync(1, Http2HeadersFrameFlags.END_STREAM, new byte[0]); + } + + // There's a race when the appfunc is exiting about how soon it unregisters the stream, so retry until success. + while (!cts.Token.IsCancellationRequested) + { + // Just past the timeout + mockSystemClock.UtcNow += Constants.RequestBodyDrainTimeout + TimeSpan.FromTicks(1); + (_connection as IRequestProcessor).Tick(mockSystemClock.UtcNow); + + // Send an extra frame to make it fail + switch (finalFrameType) + { + case Http2FrameType.DATA: + await SendDataAsync(1, new byte[100], endStream: false); + break; + + case Http2FrameType.CONTINUATION: + await SendContinuationAsync(1, Http2ContinuationFrameFlags.NONE, new byte[0]); + break; + + default: + throw new NotImplementedException(finalFrameType.ToString()); + } + + if (!cts.Token.IsCancellationRequested) + { + await Task.Delay(10); + } + } } - // Just short of the timeout - mockSystemClock.UtcNow += Constants.RequestBodyDrainTimeout; - (_connection as IRequestProcessor).Tick(mockSystemClock.UtcNow); + var sendTask = AdvanceClockAndSendFrames(); - // Still fine - await SendDataAsync(1, new byte[100], endStream: false); - - // Just past the timeout - mockSystemClock.UtcNow += TimeSpan.FromTicks(1); - (_connection as IRequestProcessor).Tick(mockSystemClock.UtcNow); - - // Send an extra frame to make it fail - switch (finalFrameType) - { - case Http2FrameType.DATA: - await SendDataAsync(1, new byte[100], endStream: true); - break; - - case Http2FrameType.HEADERS: - await SendHeadersAsync(1, Http2HeadersFrameFlags.END_STREAM | Http2HeadersFrameFlags.END_HEADERS, _requestTrailers); - break; - - default: - throw new NotImplementedException(finalFrameType.ToString()); - } - - await WaitForConnectionErrorAsync(ignoreNonGoAwayFrames: false, expectedLastStreamId: 1, Http2ErrorCode.STREAM_CLOSED, + await WaitForConnectionErrorAsync( + ignoreNonGoAwayFrames: false, + expectedLastStreamId: 1, + Http2ErrorCode.STREAM_CLOSED, CoreStrings.FormatHttp2ErrorStreamClosed(finalFrameType, 1)); + + cts.Cancel(); + + await sendTask.DefaultTimeout(); } [Fact]