search

aspnet / HttpSysServer

[Archived] A web server for ASP.NET Core based on the Windows Http Server API. Project moved to https://github.com/aspnet/AspNetCore
Apache License 2.0
106 stars 39 forks source link

Flaky test: RequestBody_ReadAsync_Success #457

Closed ryanbrandenburg closed 5 years ago

ryanbrandenburg commented 6 years ago

This test fails occasionally with the following error:

System.TimeoutException : AcceptAsync has timed out.
   at Microsoft.AspNetCore.Server.HttpSys.Listener.Utilities.AcceptAsync(HttpSysListener server, TimeSpan timeout) in /_/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/Utilities.cs:line 108
   at Microsoft.AspNetCore.Server.HttpSys.Listener.RequestBodyTests.RequestBody_ReadAsync_Success() in /_/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/RequestBodyTests.cs:line 73
--- End of stack trace from previous location where exception was thrown ---
Tratcher commented 6 years ago

History: http://aspnetci/project.html?projectId=XPlat&buildTypeId=&tab=testDetails&testNameId=-5284826571007502406&order=TEST_STATUS_DESC&branch_XPlat=__all_branches__&itemsCount=50

18 failures since Feb 6, all on 2008R2 - Possible agent issue?

ryanbrandenburg commented 6 years ago

What would the issue on the agent be that would cause this behavior?

Tratcher commented 6 years ago

I don't know but it's suspicious that this only fails on 2008R2 and not Win7, they're the same OS. And we only have one agent for 2008R2 so it's hard to rule out an agent issue.

ryanbrandenburg commented 6 years ago

RequestBody_ReadAsync_Success failed again.

This comment was made automatically. If there is a problem contact @ryanbrandenburg.

ryanbrandenburg commented 6 years ago

AuthTypes_AllowAnonymous_NoChallenge failed again.

This comment was made automatically. If there is a problem contact @ryanbrandenburg.

Eilon commented 6 years ago

@Tratcher - please take a look at this issue because it has been failing again.

ryanbrandenburg commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error. AuthTypes_AllowAnonymous_NoChallenge failed with about the same error. AuthTypes_AllowAnonymous_NoChallenge failed with about the same error.

This comment was made automatically. If there is a problem contact @ryanbrandenburg.

Tratcher commented 6 years ago

AppVeyor failures captured with the new tracing:

[xUnit.net 00:00:15.78]     Microsoft.AspNetCore.Server.HttpSys.Listener.ResponseCachingTests.Caching_VariousUnsupportedRequestMethods_NotCached(method: "UNKNOWN") [FAIL]
  Failed   Microsoft.AspNetCore.Server.HttpSys.Listener.ResponseCachingTests.Caching_VariousUnsupportedRequestMethods_NotCached(method: "UNKNOWN")
  Error Message:
   System.InvalidOperationException : The response completed prematurely: StatusCode: 503, ReasonPhrase: 'Service Unavailable', Version: 1.1, Content: System.Net.Http.HttpConnection+HttpConnectionResponseContent, Headers:
  {
    Server: Microsoft-HTTPAPI/2.0
    Date: Fri, 03 Aug 2018 22:50:48 GMT
    Connection: close
    Content-Type: text/html; charset=us-ascii
    Content-Length: 326
  }
  Stack Trace:
     at Microsoft.AspNetCore.Server.HttpSys.Listener.Utilities.Before[T](Task`1 acceptTask, Task`1 responseTask) in /_/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/Utilities.cs:line 123
     at Microsoft.AspNetCore.Server.HttpSys.Listener.ResponseCachingTests.Caching_VariousUnsupportedRequestMethods_NotCached(String method) in /_/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/ResponseCachingTests.cs:line 623
  --- End of stack trace from previous location where exception was thrown ---
  Results File: C:\projects\httpsysserver\artifacts\logs\UnitTests-netcoreapp2.2-t000.trx
Microsoft.AspNetCore.Server.HttpSys.Listener.ResponseHeaderTests.AddingControlCharactersToHeadersThrows(key: "\r\nServer", value: "Data") [FAIL]
  Failed   Microsoft.AspNetCore.Server.HttpSys.Listener.ResponseHeaderTests.AddingControlCharactersToHeadersThrows(key: "\r\nServer", value: "Data")
  Error Message:
   System.InvalidOperationException : The response completed prematurely: StatusCode: 503, ReasonPhrase: 'Service Unavailable', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
  {
    Connection: close
    Date: Fri, 03 Aug 2018 22:51:21 GMT
    Server: Microsoft-HTTPAPI/2.0
    Content-Length: 326
    Content-Type: text/html; charset=us-ascii
  }
  Stack Trace:
     at Microsoft.AspNetCore.Server.HttpSys.Listener.Utilities.<Before>d__15`1.MoveNext()
  --- End of stack trace from previous location where exception was thrown ---
     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
     at Microsoft.AspNetCore.Server.HttpSys.Listener.ResponseHeaderTests.<AddingControlCharactersToHeadersThrows>d__18.MoveNext()
  --- End of stack trace from previous location where exception was thrown ---
     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
  --- End of stack trace from previous location where exception was thrown ---
     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
  --- End of stack trace from previous location where exception was thrown ---
     at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
     at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

The server successfully started, there's no indication of why the client would randomly get a 503. I'll see if we get similar failures out of the main builds.

Possible mitigations:

ryanbrandenburg commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error.

This comment was made automatically. If there is a problem contact @ryanbrandenburg.

ryanbrandenburg commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error on master.

This comment was made automatically. If there is a problem contact ryanbrandenburg.

ryanbrandenburg commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error on master.

This comment was made automatically. If there is a problem contact ryanbrandenburg.

aspnet-hello commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error on master. RequestBody_ReadAsync_Success failed with about the same error on master.

This comment was made automatically. If there is a problem contact ryanbrandenburg.

aspnet-hello commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error on master.

This comment was made automatically. If there is a problem contact ryanbrandenburg.

aspnet-hello commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error on master.

This comment was made automatically. If there is a problem contact ryanbrandenburg.

Eilon commented 6 years ago

@Tratcher any update on this? What are the next steps?

Tratcher commented 6 years ago

Recent failures all have this error:

System.Threading.Tasks.TaskCanceledException : A task was canceled.
   at System.Threading.Tasks.ValueTask`1.get_Result()
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at Microsoft.AspNetCore.Server.HttpSys.Listener.RequestBodyTests.SendRequestAsync(String uri, HttpContent content) in /_/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/RequestBodyTests.cs:line 361
   at Microsoft.AspNetCore.Server.HttpSys.Listener.Utilities.Before[T](Task`1 acceptTask, Task`1 responseTask) in /_/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/Utilities.cs:line 122
   at Microsoft.AspNetCore.Server.HttpSys.Listener.RequestBodyTests.RequestBody_ReadAsync_Success() in /_/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/RequestBodyTests.cs:line 73
--- End of stack trace from previous location where exception was thrown ---

The client appears to be hitting a 10s client side timeout. @JunTaoLuo this may be related to the failure you saw in https://github.com/aspnet/HttpSysServer/issues/468, except it's a lot more frequent. There was theory this was related to a client side bug but that hasn't been tracked down.

All failures are still on Win2008R2-Universe which implies the issue is OS or agent specific. No Win7 failures which should share the same OS components.

aspnet-hello commented 6 years ago

RequestBody_ReadAsync_Success failed with about the same error on master.

This comment was made automatically. If there is a problem contact ryanbrandenburg.

aspnet-hello commented 6 years ago

There were 1 failures with about the same error on master:

This comment was made automatically. If there is a problem contact ryanbrandenburg.

aspnet-hello commented 5 years ago

This comment was made automatically. If there is a problem contact ryanbrandenburg.

There were 1 failures with about the same error on master at 5:17:26 PM:

There were 1 failures with about the same error on master at 1:26:26 PM:

aspnet-hello commented 5 years ago

This comment was made automatically. If there is a problem contact ryanbrandenburg.

There were 1 failures with about the same error on master at 11:39:41 AM:

aspnet-hello commented 5 years ago

This comment was made automatically. If there is a problem contact ryanbrandenburg.

There were 1 failures with about the same error on master at 2:21:36 PM:

aspnet-hello commented 5 years ago

This comment was made automatically. If there is a problem contact ryanbrandenburg.

There were 1 failures with about the same error on master at 9:38:58 PM:

Eilon commented 5 years ago

@Tratcher any news on this one?

aspnet-hello commented 5 years ago

This comment was made automatically. If there is a problem contact ryanbrandenburg.

There were 1 failures with about the same error on master at 2:31:34 PM:

There were 1 failures with about the same error on master at 1:27:43 PM:

aspnet-hello commented 5 years ago

This comment was made automatically. If there is a problem contact ryanbrandenburg.

There were 1 failures with about the same error on master at 12:17:56 AM:

Tratcher commented 5 years ago

Every indication here is that it's a client side SocketHttpHandler/Socket bug.

I'm working on a local repro.

Eilon commented 5 years ago

BTW if it makes sense to temporarily disable this test, please do so (per the workflow at the top of this issue).

aspnet-hello commented 5 years ago

This comment was made automatically. If there is a problem contact ryanbrandenburg.

There were 1 failures with about the same error on master at 12:01:04 PM:

Tratcher commented 5 years ago

Update. I spent a whole day trying to reproduce these and did not get a single hit. I did come up with a new theory though. For historical purposes there are two versions of most of these tests, an ASP.NET level one and a lower level Listener version. Every failure reported here is in the Listener version of these tests.

This lower level doesn't have a message pump, it has to call Accept for each expected request and then switches back and forth between client and server code on the same thread. Example: https://github.com/aspnet/HttpSysServer/blob/76cb2784b90b5549427700d4d93e44803c49101c/test/Microsoft.AspNetCore.Server.HttpSys.FunctionalTests/Listener/AuthenticationTests.cs#L29-L40

This has a few issues.

New proposal: Remove the redundant tests. They are flaky and we would not lose any coverage. I'll give more history in the PR where I can show the changes.

Eilon commented 5 years ago

@Tratcher sounds good, thanks for the investigation! If we truly believe the coverage is redundant, let's simplify.