Flaky test: MaxRequestBufferSizeTests.LargeUpload

[Tratcher]

This has failed 50% of the time for me on recent local builds, always with the same actual result.

[xUnit.net 00:00:44.2552397]     LargeUpload(maxRequestBufferSize: 5242880, connectionAdapter: True, expectPause: True) [FAIL]
[xUnit.net 00:00:44.2588137]       Assert.InRange() Failure
[xUnit.net 00:00:44.2591272]       Range:  (5238785 - 20971519)
[xUnit.net 00:00:44.2592656]       Actual: 20971520
[xUnit.net 00:00:44.2619018]       Stack Trace:
[xUnit.net 00:00:44.2652259]         D:\github\AspNet\KestrelHttpServer\test\Kestrel.FunctionalTests\MaxRequestBufferSizeTests.cs(160,0): at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.<LargeUpload>d__6.MoveNext()
[xUnit.net 00:00:44.2657057]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:44.2658986]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:44.2660844]         --- End of stack trace from previous location where exception was thrown ---
[xUnit.net 00:00:44.2682372]       Output:
[xUnit.net 00:00:44.2684638]         | Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.0 POST http:///  20971520
Failed   LargeUpload(maxRequestBufferSize: 5242880, connectionAdapter: True, expectPause: True)
Error Message:
 Assert.InRange() Failure
Range:  (5238785 - 20971519)
Actual: 20971520
Stack Trace:
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.<LargeUpload>d__6.MoveNext() in D:\github\AspNet\KestrelHttpServer\test\Kestrel.FunctionalTests\MaxRequestBufferSizeTests.cs:line 160

[Tratcher]

Still failing, same error.

[muratg]

cc @halter73

[halter73]

@Tratcher What OS? Have you noticed it fail on the 2.0 or 2.1 runtime? Both?

[ryanbrandenburg]

You can see the history of this test failure here.

[ryanbrandenburg]

Another failure, but a different error this time:

System.IO.IOException : Unable to read data from the transport connection: Invalid argument.
---- System.Net.Sockets.SocketException : Invalid argument
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.<>c__DisplayClass6_2.<<LargeUpload>b__0>d.MoveNext() in /_/test/Kestrel.FunctionalTests/MaxRequestBufferSizeTests.cs:line 120
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.LargeUpload(Nullable`1 maxRequestBufferSize, Boolean connectionAdapter, Boolean expectPause) in /_/test/Kestrel.FunctionalTests/MaxRequestBufferSizeTests.cs:line 163
--- End of stack trace from previous location where exception was thrown ---
----- Inner Stack Trace -----

------- Stdout: -------
| [2018-04-10T13:17:35] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request starting HTTP/1.0 POST http:///  20971520
| [2018-04-10T13:17:39] Microsoft.AspNetCore.Server.Kestrel Error: Connection id "0HLCUSLM70C7C", Request id "0HLCUSLM70C7C:00000001": An unhandled exception was thrown by the application.
|    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ValidateState(CancellationToken cancellationToken) in /_/src/Kestrel.Core/Internal/Http/HttpRequestStream.cs:line 216
|    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpRequestStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken) in /_/src/Kestrel.Core/Internal/Http/HttpRequestStream.cs:line 110
|    at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.<>c__DisplayClass8_0.<<StartWebHost>b__3>d.MoveNext() in /_/test/Kestrel.FunctionalTests/MaxRequestBufferSizeTests.cs:line 298
| --- End of stack trace from previous location where exception was thrown ---
|    at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.ProcessRequests[TContext](IHttpApplication`1 application) in /_/src/Kestrel.Core/Internal/Http/HttpProtocol.cs:line 536
| [2018-04-10T13:17:39] Microsoft.AspNetCore.Hosting.Internal.WebHost Information: Request finished in 3976.3743ms 0

[muratg]

@Tratcher did you get a chance to look into this yet?

[Tratcher]

No, I should have some time to look at tests tomorrow.

[Tratcher]

The history for this test is pretty messy. I count 8 failures for the various overloads.
http://aspnetci/viewLog.html?buildId=446050&buildTypeId=XPlat_Windows_Win10Universe&tab=testsInfo

3 are part of mass failures and can be dismissed as agent issues
http://aspnetci/viewLog.html?buildId=424325&tab=buildResultsDiv&buildTypeId=XPlat_Mac_MacUniverseCoreCLR#testNameId6816592842570504506
http://aspnetci/viewLog.html?buildId=424325&tab=buildResultsDiv&buildTypeId=XPlat_Mac_MacUniverseCoreCLR#testNameId-9108478846534902949
http://aspnetci/viewLog.html?buildId=443056&tab=buildResultsDiv&buildTypeId=Lite_KestrelStressTest#testNameId-9108478846534902949

And 1 bind failure
http://aspnetci/viewLog.html?buildId=422166&tab=buildResultsDiv&buildTypeId=XPlat_Linux_UbuntuUniverseCoreCLR#testNameId2969803565931579806

There's 2 reports of the original issue I posted above
http://aspnetci/viewLog.html?buildId=443290&tab=buildResultsDiv&buildTypeId=XPlat_Windows_Win10Universe#testNameId6816592842570504506
http://aspnetci/viewLog.html?buildId=444798&tab=buildResultsDiv&buildTypeId=XPlat_Windows_Win10Universe#testNameId2969803565931579806

2 invalid arguments
http://aspnetci/viewLog.html?buildId=407883&tab=buildResultsDiv&buildTypeId=XPlat_Linux_UbuntuUniverseCoreCLR#testNameId2969803565931579806
http://aspnetci/viewLog.html?buildId=444611&tab=buildResultsDiv&buildTypeId=XPlat_Linux_UbuntuUniverseCoreCLR#testNameId2969803565931579806

[Tratcher]

RE the InRange failure, it does not appear to be TFM specific, and it reproduces both on Sockets and Libuv, though more readily on Sockets. Only the connectionAdapter: True variation fails with the above error.

[benaadams]

Re: System.IO.IOException : Unable to read data from the transport connection: Invalid argument.

Invalid argument is now likely to be reported as OperationAborted dotnet/corefx#29091

[Tratcher]

Mitigation for the original issue has been checked into dev for 2.2. If we see it again in 2.1 we can consider backporting it. If we see any more reports of the other errors we can open a separate issue.

[Tratcher]

Nevermind, it's still failing.

[ryanbrandenburg]

This fails most frequently on our Win10 build, on which it has failed 4 times today.

[muratg]

@Tratcher did you look into this one yet?

[Tratcher]

I wasn't able to get a consistent repro so I moved on to tests with more failures. I'll revisit it when I get that far down the list.

[mikeharder]

Just failed on my dev machine, same error as the first post in this issue:

  [xUnit.net 00:00:17.1104598]     LargeUpload(maxRequestBufferSize: 5242880, connectionAdapter: True, expectPause: True) [FAIL]
  Failed   LargeUpload(maxRequestBufferSize: 5242880, connectionAdapter: True, expectPause: True)
RUNDOTNET : error Message:  [C:\Users\mharder\.dotnet\buildtools\korebuild\2.2.0-preview1-17051\KoreBuild.proj]
   Assert.InRange() Failure
  Range:  (5238785 - 20971519)
  Actual: 20971520
  Stack Trace:
     at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.LargeUpload(Nullable`1 maxRequestBufferSize, Boolean connectionAdapter, Boolean expectPause) in D:\Git\KestrelHttpServer\test\Kestrel.FunctionalTests\MaxRequestBufferSizeTests.cs:line 149
  --- End of stack trace from previous location where exception was thrown ---

It's possible the client and/or server buffers on Win10 have been increased, so we may need to change the test parameters:

KestrelHttpServer/test/Kestrel.FunctionalTests/MaxRequestBufferSizeTests.cs

Lines 49 to 52 in de98f8c

	// Larger than default, but still significantly lower than data, so client should be paused.
	// On Windows, the client is usually paused around (MaxRequestBufferSize + 700,000).
	// On Linux, the client is usually paused around (MaxRequestBufferSize + 10,000,000).
	Tuple.Create((long?)5 * 1024 * 1024, true),

KestrelHttpServer/test/Kestrel.FunctionalTests/MaxRequestBufferSizeTests.cs

Lines 222 to 225 in de98f8c

	// The maximum is harder to determine, since there can be OS-level buffers in both the client
	// and server, which allow the client to send more than maxRequestBufferSize before getting
	// paused. We assume the combined buffers are smaller than the difference between
	// data.Length and maxRequestBufferSize.

Specifically, we may need to increase the data sent from 20MB to something larger until the test is reliable on all platforms.

[mikeharder]

I can take this issue since I wrote these tests.

[mikeharder]

On my dev machine, the failure was in Sockets.FunctionalTests (rather than Libuv.FunctionalTests). This might explain why the test was initially reliable (when Libuv was the only transport), and it only became flaky once the Sockets transport was introduced.

The next step is to determine if the flakiness is caused by test code (e.g. the 15MB difference between upload size and max request buffer is not large enough) or product code (e.g. sometimes the server fails to apply backpressure, which would be a product bug).

[mikeharder]

I've been running the LargeUpload tests in a loop on my dev machine:

for /l %n in () do dotnet test --no-build -f netcoreapp2.2 --filter "DisplayName~LargeUpload"

The following test (and only this specific test) fails about 25-30% of the time:

LargeUpload(maxRequestBufferSize: 5242880, connectionAdapter: True, expectPause: True)

It may be noteworthy that connectionAdapter: true, and the variant with connectionAdapter: false never fails.

I also tried running only the two tests with maxRequestBufferSize: 5242880 in a loop:

for /l %n in () do dotnet test --no-build -f netcoreapp2.2 --filter "DisplayName~LargeUpload & DisplayName~5242880

However, when running this subset I was unable to repro any failures.

[mikeharder]

I was also able to reproduce this in a Win10 Hyper-V VM on my dev machine. It fails significantly less often than my physical machine, but I was able to repro some failures with connectionAdapter: false:

Result	Count	Percentage
Pass	3930	95.8%
Fail (connectionAdapter: True)	167	4.0%
Fail (connectionAdapter: False)	6	0.2%

[pakrym]

New occurance: https://ci3.dot.net/job/aspnet_KestrelHttpServer/job/dev/job/linux-Configuration_Release_prtest/307/

15:41:29   [xUnit.net 00:00:14.0401462]     LargeUpload(maxRequestBufferSize: 26, connectionAdapter: False, expectPause: True) [FAIL]
15:41:29   Failed   LargeUpload(maxRequestBufferSize: 26, connectionAdapter: False, expectPause: True)
15:41:29 RUNDOTNET : error Message:  [/home/dotnet-bot/.dotnet/buildtools/korebuild/2.2.0-preview1-17060/KoreBuild.proj]
15:41:29    Assert.Contains() Failure
15:41:29   Not found: bytesRead: 41943040
15:41:29   In value:  
15:41:29   Stack Trace:
15:41:29      at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.MaxRequestBufferSizeTests.LargeUpload(Nullable`1 maxRequestBufferSize, Boolean connectionAdapter, Boolean expectPause)
15:41:29   --- End of stack trace from previous location where exception was thrown ---
15:42:50   Results File: /mnt/j/workspace/aspnet_KestrelHttpServer/dev/linux-Configuration_Release_prtest/artifacts/logs/UnitTests-netcoreapp2.2-307.trx
15:42:50