search

dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.34k stars 9.98k forks source link

Quarantine Http1Connection_RequestEndsWithIncompleteReadAsync #57944

Open halter73 opened 3 weeks ago

halter73 commented 3 weeks ago

Failing Test(s)

Error Message

Assert.Equal() Failure: Strings differ
↓ (pos 76)
Expected: ···" 01 Jan 2000 00:00:00 GMT

Hello World?"
Actual:   ···"
Date: Sat, 01 Jan 2000 00:00:00 GMT

H"

Stacktrace

```text at Microsoft.AspNetCore.InternalTesting.StreamBackedTestConnection.Receive(String[] lines) in /_/src/Servers/Kestrel/shared/test/StreamBackedTestConnection.cs:line 126 at Microsoft.AspNetCore.InternalTesting.StreamBackedTestConnection.ReceiveEnd(String[] lines) in /_/src/Servers/Kestrel/shared/test/StreamBackedTestConnection.cs:line 131 at Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.KestrelMetricsTests.Http1Connection_RequestEndsWithIncompleteReadAsync() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/KestrelMetricsTests.cs:line 182 at Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.KestrelMetricsTests.Http1Connection_RequestEndsWithIncompleteReadAsync() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/KestrelMetricsTests.cs:line 195 --- End of stack trace from previous location --- ```

Logs

```text | [0.001s] TestLifetime Information: Starting test Http1Connection_RequestEndsWithIncompleteReadAsync at 2024-09-18T08:43:57 | [0.007s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting starting | [0.036s] Microsoft.Hosting.Lifetime Information: Now listening on: http://127.0.0.1:0 | [0.036s] Microsoft.AspNetCore.Hosting.Diagnostics Debug: Loaded hosting startup assembly InMemory.FunctionalTests | [0.036s] Microsoft.Hosting.Lifetime Information: Application started. Press Ctrl+C to shut down. | [0.036s] Microsoft.Hosting.Lifetime Information: Hosting environment: Production | [0.036s] Microsoft.Hosting.Lifetime Information: Content root path: /datadisks/disk1/work/BB780A13/w/BDFA0A36/e/ | [0.036s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting started | [0.038s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6NNNTMKOJT" accepted. | [0.038s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6NNNTMKOJT" started. | [0.066s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request starting HTTP/1.0 POST http:/// - - 12 | [0.070s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HN6NNNTMKOJT", Request id "0HN6NNNTMKOJT:00000001": started reading request body. | [0.071s] Microsoft.AspNetCore.Hosting.Diagnostics Information: Request finished HTTP/1.0 POST http:/// - 200 - - 5.0670ms | [0.072s] Microsoft.AspNetCore.Server.Kestrel Error: Connection id "0HN6NNNTMKOJT", Request id "0HN6NNNTMKOJT:00000001": automatic draining of the request body failed because the body reader is in an invalid state. | System.InvalidOperationException: Reading is already in progress. | at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1ContentLengthMessageBody.TryReadInternal(ReadResult& readResult) in /_/src/Servers/Kestrel/Core/src/Internal/Http/Http1ContentLengthMessageBody.cs:line 121 | at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.OnConsumeAsync() in /_/src/Servers/Kestrel/Core/src/Internal/Http/Http1MessageBody.cs:line 53 | [0.072s] Microsoft.AspNetCore.Server.Kestrel Debug: Connection id "0HN6NNNTMKOJT", Request id "0HN6NNNTMKOJT:00000001": done reading request body. | [0.072s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6NNNTMKOJT" disconnecting. | [0.072s] Microsoft.AspNetCore.Server.Kestrel.Connections Debug: Connection id "0HN6NNNTMKOJT" stopped. | [0.074s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting stopping | [0.074s] Microsoft.Hosting.Lifetime Information: Application is shutting down... | [0.509s] Microsoft.Extensions.Hosting.Internal.Host Debug: Hosting stopped | [1.515s] Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.KestrelMetricsTests Error: Test threw an exception. | Xunit.Sdk.EqualException: Assert.Equal() Failure: Strings differ | ↓ (pos 76) | Expected: ···" 01 Jan 2000 00:00:00 GMT\r\n\r\nHello World?" | Actual: ···"\nDate: Sat, 01 Jan 2000 00:00:00 GMT\r\n\r\nH" | at Xunit.Assert.Equal(ReadOnlySpan`1 expected, ReadOnlySpan`1 actual, Boolean ignoreCase, Boolean ignoreLineEndingDifferences, Boolean ignoreWhiteSpaceDifferences, Boolean ignoreAllWhiteSpace) in /_/src/xunit.assert/Asserts/StringAsserts.cs:line 957 | at Xunit.Assert.Equal(String expected, String actual, Boolean ignoreCase, Boolean ignoreLineEndingDifferences, Boolean ignoreWhiteSpaceDifferences, Boolean ignoreAllWhiteSpace) in /_/src/xunit.assert/Asserts/StringAsserts.cs:line 1334 | at Xunit.Assert.Equal(String expected, String actual) in /_/src/xunit.assert/Asserts/StringAsserts.cs:line 841 | at Microsoft.AspNetCore.InternalTesting.StreamBackedTestConnection.Receive(String[] lines) in /_/src/Servers/Kestrel/shared/test/StreamBackedTestConnection.cs:line 126 | at Microsoft.AspNetCore.InternalTesting.StreamBackedTestConnection.ReceiveEnd(String[] lines) in /_/src/Servers/Kestrel/shared/test/StreamBackedTestConnection.cs:line 131 | at Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.KestrelMetricsTests.Http1Connection_RequestEndsWithIncompleteReadAsync() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/KestrelMetricsTests.cs:line 182 | at Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.KestrelMetricsTests.Http1Connection_RequestEndsWithIncompleteReadAsync() in /_/src/Servers/Kestrel/test/InMemory.FunctionalTests/KestrelMetricsTests.cs:line 195 | at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass46_0.<b__1>d.MoveNext() in /_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs:line 253 | --- End of stack trace from previous location --- | at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48 | at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90 | [1.569s] TestLifetime Information: Finished test Http1Connection_RequestEndsWithIncompleteReadAsync in 1.5686297s ```

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=811708&view=ms.vss-test-web.build-test-results-tab&runId=21019092&resultId=122858&paneView=attachments

amcasey commented 5 days ago

If I'm reading the assert message correctly, the problem is that we were expecting "Hello World?" and only got the initial "H".

~However, looking more carefully, it looks like Expected and Actual are reversed at this call site so we're expecting "H" and getting "Hello World?". I wonder if Buffer.ToSpan() can return more than Buffer.Length says it will.~

Edit: I was looking at the wrong assert.

amcasey commented 5 days ago

Receive can stop reading without seeing the expected length if any given ReadAsync call returns 0.

https://github.com/dotnet/aspnetcore/blob/44a9f8a83a1d20a3e367d5ec0d82111e84c7e5ec/src/Servers/Kestrel/shared/test/StreamBackedTestConnection.cs#L110

StreamReader.ReadAsync is documented as returning 0 for end-of-stream, so that seems right. Presumably, that means the missing text never made it across the wire, which seems plausible if there's an intentional failure.

amcasey commented 5 days ago

I believe @JamesNK added this test fairly recently, so he might be interested in taking a look.