Quarantine Http1Connection_RequestEndsWithIncompleteReadAsync

[halter73]

Failing Test(s)

• Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.KestrelMetricsTests.Http1Connection_RequestEndsWithIncompleteReadAsync

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

   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

| [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.<<InvokeTestMethodAsync>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]

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]

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

aspnetcore/src/Servers/Kestrel/shared/test/StreamBackedTestConnection.cs

Line 110 in 44a9f8a

if (count == 0)

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]

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

[JamesNK]

Fixed in #57946