Test failure: ConnectionClosedTokenFiresOnClientFIN

[ajaybhargavb]

https://dev.azure.com/dnceng/internal/_build/results?buildId=572454&view=ms.vss-test-web.build-test-results-tab&runId=17951640&resultId=109104&paneView=debug

Error

System.TimeoutException : The operation at /_/src/Servers/Kestrel/shared/test/TaskTimeoutExtensions.cs:22 timed out after reaching the limit of 30000ms.

Stacktrace

at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter[T](Task`1 task, TimeSpan timeout, String filePath, Int32 lineNumber) in /_/src/Testing/src/TaskExtensions.cs:line 33
at Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.RequestTests.ConnectionClosedTokenFiresOnClientFIN(ListenOptions listenOptions) in /_/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs:line 527
--- End of stack trace from previous location ---

[halter73]

This was in the Libuv.FunctionalTests project. It appears to have timed out waiting for the app func to start. I'm not sure what we can really do other than expand the timeout or stop running libuv functional tests.

aspnetcore/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs

Lines 509 to 527 in e65408a

	using (var server = new TestServer(context =>
	{
	appStartedTcs.SetResult(null);
	var connectionLifetimeFeature = context.Features.Get<IConnectionLifetimeFeature>();
	connectionLifetimeFeature.ConnectionClosed.Register(() => connectionClosedTcs.SetResult(null));
	return Task.CompletedTask;
	}, testContext, listenOptions))
	{
	using (var connection = server.CreateConnection())
	{
	await connection.Send(
	"GET / HTTP/1.1",
	"Host:",
	"",
	"");
	await appStartedTcs.Task.DefaultTimeout();

[halter73]

Maybe we can skip on macOS. I cannot get the server side logs for this failure, but libuv has long been flaky on macOS. Timeout on connect without libuv logs ever showing a new connection arriving is how the flakiness usually exhibits itself.

[BrennanConroy]

Turns out copying test logs on mac wasn't working. Should be fixed with #20258

[BrennanConroy]

Failed recently on OSX

[0.001s] [TestLifetime] [Information] Starting test ConnectionClosedTokenFiresOnClientFIN-http_127.0.0.1_0 at 2020-06-01T22:46:27
[0.002s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Hosting starting
[0.005s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Hosting started
[0.005s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Loaded hosting startup assembly Libuv.FunctionalTests, Version=5.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60
[0.005s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] TestServer is listening on port 63015
[0.006s] [Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv] [Debug] Connection id "0HM06FMF76B3K" received FIN.
[0.006s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM06FMF76B3K" accepted.
[0.006s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM06FMF76B3K" started.
[0.007s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM06FMF76B3K" disconnecting.
[0.007s] [Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv] [Debug] Connection id "0HM06FMF76B3K" sending FIN because: "The client closed the connection."
[0.007s] [Microsoft.AspNetCore.Server.Kestrel] [Debug] Connection id "0HM06FMF76B3K" stopped.
[30.024s] [Microsoft.AspNetCore.Hosting.Diagnostics] [Debug] Hosting shutdown
[30.027s] [TestLifetime] [Information] Finished test ConnectionClosedTokenFiresOnClientFIN-http_127.0.0.1_0 in 30.0267181s

[captainsafia]

Closing this since the quarantine attribute on the test refers to #23043. We've got a reference to this in the other issue so folks can follow the trail when this gets addressed.