Test failure: System.Net.Http.Functional.Tests.HttpProtocolTests / GetAsync_ExpectedStatusCodeAndReason_Success

[karelz]

Type of failures

The operation has been canceled

Failure: 20171208.04

System.Net.Http.HttpRequestException : An error occurred while sending the request.
---- System.Net.Http.WinHttpException : The operation has been canceled
   at System.Net.Http.HttpClient.<FinishSendAsyncBuffered>d__58.MoveNext() in E:\A\_work\1355\s\corefx\src\System.Net.Http\src\System\Net\Http\HttpClient.cs:line 464
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.HttpProtocolTests.<>c__DisplayClass1_0.<<GetAsync_ExpectedStatusCodeAndReason_Success>b__0>d.MoveNext() in E:\A\_work\1355\s\corefx\src\System.Net.Http\tests\FunctionalTests\HttpProtocolTests.cs:line 47
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t) in E:\A\_work\1355\s\corefx\src\Common\tests\System\Net\Http\LoopbackServer.cs:line 67
   at System.Threading.Tasks.ContinuationTaskFromTask.InnerInvoke() in E:\A\_work\1993\s\src\mscorlib\src\System\Threading\Tasks\TaskContinuation.cs:line 59
   at System.Threading.Tasks.Task.<>c.<.cctor>b__278_1(Object obj) in E:\A\_work\1993\s\src\mscorlib\src\System\Threading\Tasks\Task.cs:line 2480
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\1993\s\src\mscorlib\shared\System\Threading\ExecutionContext.cs:line 151
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot) in E:\A\_work\1993\s\src\mscorlib\src\System\Threading\Tasks\Task.cs:line 2440
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.HttpProtocolTests.<GetAsync_ExpectedStatusCodeAndReason_Success>d__1.MoveNext() in E:\A\_work\1355\s\corefx\src\System.Net.Http\tests\FunctionalTests\HttpProtocolTests.cs:line 42
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
----- Inner Stack Trace -----
   at System.Threading.Tasks.RendezvousAwaitable`1.GetResult() in E:\A\_work\1355\s\corefx\src\Common\src\System\Threading\Tasks\RendezvousAwaitable.cs:line 62
   at System.Net.Http.WinHttpHandler.<StartRequest>d__105.MoveNext() in E:\A\_work\1355\s\corefx\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs:line 856

The handle is invalid

Failure: 20171205.06

System.Net.Http.HttpRequestException : An error occurred while sending the request.
---- System.Net.Http.WinHttpException : The handle is invalid
   at System.Net.Http.HttpClient.<FinishSendAsyncBuffered>d__58.MoveNext() in E:\A\_work\2046\s\corefx\src\System.Net.Http\src\System\Net\Http\HttpClient.cs:line 464
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.HttpProtocolTests.<>c__DisplayClass1_0.<<GetAsync_ExpectedStatusCodeAndReason_Success>b__0>d.MoveNext() in E:\A\_work\2046\s\corefx\src\System.Net.Http\tests\FunctionalTests\HttpProtocolTests.cs:line 54
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t) in E:\A\_work\2046\s\corefx\src\Common\tests\System\Net\Http\LoopbackServer.cs:line 68
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\1613\s\src\mscorlib\shared\System\Threading\ExecutionContext.cs:line 151
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot) in E:\A\_work\1613\s\src\mscorlib\src\System\Threading\Tasks\Task.cs:line 2440
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.HttpProtocolTests.<GetAsync_ExpectedStatusCodeAndReason_Success>d__1.MoveNext() in E:\A\_work\2046\s\corefx\src\System.Net.Http\tests\FunctionalTests\HttpProtocolTests.cs:line 42
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
----- Inner Stack Trace -----
   at System.Net.Http.WinHttpException.ThrowExceptionUsingLastError() in E:\A\_work\2046\s\corefx\src\Common\src\System\Net\Http\WinHttpException.cs:line 44
   at System.Net.Http.WinHttpHandler.SetRequestHandleRedirectionOptions(SafeWinHttpHandle requestHandle) in E:\A\_work\2046\s\corefx\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs:line 1082
   at System.Net.Http.WinHttpHandler.SetRequestHandleOptions(WinHttpRequestState state) in E:\A\_work\2046\s\corefx\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs:line 956
   at System.Net.Http.WinHttpHandler.<StartRequest>d__105.MoveNext() in E:\A\_work\2046\s\corefx\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs:line 833

An existing connection was forcibly closed by the remote host

Failure: 20171205.02

System.IO.IOException : Unable to transfer data on the transport connection: An existing connection was forcibly closed by the remote host.
---- System.Net.Sockets.SocketException : An existing connection was forcibly closed by the remote host
   at System.Net.Http.Functional.Tests.HttpProtocolTests_Dribble.DribbleStream.<WriteAsync>d__2.MoveNext() in E:\A\_work\436\s\corefx\src\System.Net.Http\tests\FunctionalTests\HttpProtocolTests.cs:line 126
--- End of stack trace from previous location where exception was thrown ---
   at System.IO.StreamWriter.<FlushAsyncInternal>d__70.MoveNext() in E:\A\_work\436\s\corefx\src\System.Runtime.Extensions\src\System\IO\StreamWriter.cs:line 982
--- End of stack trace from previous location where exception was thrown ---
   at System.IO.StreamWriter.<WriteAsyncInternal>d__55.MoveNext() in E:\A\_work\436\s\corefx\src\System.Runtime.Extensions\src\System\IO\StreamWriter.cs:line 627
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Test.Common.LoopbackServer.<ReadWriteAcceptedAsync>d__8.MoveNext() in E:\A\_work\436\s\corefx\src\Common\tests\System\Net\Http\LoopbackServer.cs:line 104
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Test.Common.LoopbackServer.<AcceptSocketAsync>d__11.MoveNext() in E:\A\_work\436\s\corefx\src\Common\tests\System\Net\Http\LoopbackServer.cs:line 180
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.HttpProtocolTests.<>c__DisplayClass1_0.<<GetAsync_ExpectedStatusCodeAndReason_Success>b__0>d.MoveNext() in E:\A\_work\436\s\corefx\src\System.Net.Http\tests\FunctionalTests\HttpProtocolTests.cs:line 54
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t) in E:\A\_work\436\s\corefx\src\Common\tests\System\Net\Http\LoopbackServer.cs:line 68
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\1762\s\src\mscorlib\shared\System\Threading\ExecutionContext.cs:line 151
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot) in E:\A\_work\1762\s\src\mscorlib\src\System\Threading\Tasks\Task.cs:line 2440
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.HttpProtocolTests.<GetAsync_ExpectedStatusCodeAndReason_Success>d__1.MoveNext() in E:\A\_work\436\s\corefx\src\System.Net.Http\tests\FunctionalTests\HttpProtocolTests.cs:line 42
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
----- Inner Stack Trace -----

History of failures

Day	Build	Queue	FailureMessage
10/25	20171025.04	Win7	The handle is invalid
11/3	20171103.07	Win7	The handle is invalid
11/3	20171103.11	Win7	The operation has been canceled
11/4	20171104.03	Win7	The operation has been canceled
11/6	20171106.03	Win7	The handle is invalid
11/7	20171107.02	Win8.1	The operation has been canceled
11/7	20171107.02	Win7	The handle is invalid
11/7	20171107.04	Win8.1	The operation has been canceled
11/15	20171115.01	Win7	An existing connection was forcibly closed by the remote host
11/19	20171119.02	Win8.1	The operation has been canceled
11/22	20171122.02	Win7	The handle is invalid
11/24	20171124.01	Win7	The handle is invalid
11/27	20171127.06	Win7	The handle is invalid
12/5	20171205.02	Win7	An existing connection was forcibly closed by the remote host
12/5	20171205.05	Win7	The handle is invalid
12/5	20171205.06	Win7	The handle is invalid
12/8	20171208.04	Win8.1	The operation has been canceled
12/13	20171213.01	Win7	The handle is invalid - link
12/13	20171213.06	Win8.1	The operation has been canceled - link
12/13	20171213.06	Win7	An existing connection was forcibly closed by the remote host - link
12/17	20171217.02	Win7	The operation has been canceled - link
12/29	20171229.01	Win8.1	The operation has been canceled - link
12/31	20171231.02	Win8.1	The handle is invalid - link
1/10	20180110.03	Win7	The handle is invalid - link
1/11	20180111.02	Win7	The handle is invalid - link
1/13	20180113.03	Win8.1	The operation has been canceled - link
1/15	20180115.01	Win8.1	The operation has been canceled - link
1/16	20180116.01	Win7	The operation has been canceled - only in catastrophic failure logs
1/20	20180120.01	Win7	An existing connection was forcibly closed by the remote host - link
1/23	20180123.01	Win7	The handle is invalid - link
1/23	20180123.01	Win8.1	The operation has been canceled - link
1/23	20180123.04	Win8.1	The operation has been canceled - link
1/25	20180125.01	Win7	An existing connection was forcibly closed by the remote host - link
2/1	20180201.05	Win7	The handle is invalid - link
2/1	20180201.05	Win8.1	The operation has been canceled - link
2/6	20180206.05	Win7	An existing connection was forcibly closed by the remote host - link
2/8	20180208.01	Win7	2x The handle is invalid - link and link
2/10	20180210.01	Win7	An existing connection was forcibly closed by the remote host - link
2/10	20180210.01	Win7	The handle is invalid - only in catastrophic failure logs
2/20	20180220.08	Win7	The handle is invalid
2/21	20180221.01	Win7	The handle is invalid
2/25	20180225.01	Win7	The handle is invalid - link
2/28	20180228.03	Win10	The operation has been canceled
3/1	20180301.01	Win7	The handle is invalid
3/3	20180303.01	Win10	2x The operation has been canceled
3/4	20180304.03	Win10	The operation has been canceled
3/6	20180306.02	Win10	The operation has been canceled
3/7	20180307.03	Win7	The handle is invalid
3/8	20180308.01	Win7	The handle is invalid
3/10	20180310.01	Win10	The operation has been canceled
3/10	20180310.02	Win7	The handle is invalid
3/14	20180314.01	Win7	The handle is invalid

Similar exceptions / errors as in dotnet/corefx#25896 and dotnet/corefx#25902 and dotnet/corefx#25912

[rmkerr]

It looks like the "handle is invalid" error occurs only on windows 7. That particular issue also appears to be occurring in #21838, failing on win7 with the same error here. Since the error occurs so frequently I'll take a look at it first.

[karelz]

BTW: If you think there are multiple issues, feel free to split them off (and edit top post to contain just relevant parts)

[rmkerr]

After looking through the existing issues I think that those "handle is invalid" failures might be caused by #17542. The last stack trace posted in that thread is very similar to the one you posted, though for a different test:

Message :
System.Net.Http.HttpRequestException : An error occurred while sending the request.
---- System.Net.Http.WinHttpException : The handle is invalid
Stack Trace :
   at System.Net.Http.HttpClient.<FinishSendAsyncBuffered>d__58.MoveNext() in D:\j\workspace\windows-TGrou---6368dffa\src\System.Net.Http\src\System\Net\Http\HttpClient.cs:line 464
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.PostScenarioTest.<PostUsingAuthHelper>d__25.MoveNext() in D:\j\workspace\windows-TGrou---6368dffa\src\System.Net.Http\tests\FunctionalTests\PostScenarioTest.cs:line 239
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.PostScenarioTest.<PostRewindableContentUsingAuth_NoPreAuthenticate_Success>d__20.MoveNext() in D:\j\workspace\windows-TGrou---6368dffa\src\System.Net.Http\tests\FunctionalTests\PostScenarioTest.cs:line 148
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
--- End of stack trace from previous location where exception was thrown ---
----- Inner Stack Trace -----
   at System.Net.Http.WinHttpException.ThrowExceptionUsingLastError() in D:\j\workspace\windows-TGrou---6368dffa\src\Common\src\System\Net\Http\WinHttpException.cs:line 44
   at System.Net.Http.WinHttpHandler.SetRequestHandleRedirectionOptions(SafeWinHttpHandle requestHandle) in D:\j\workspace\windows-TGrou---6368dffa\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs:line 1082
   at System.Net.Http.WinHttpHandler.SetRequestHandleOptions(WinHttpRequestState state) in D:\j\workspace\windows-TGrou---6368dffa\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs:line 956
   at System.Net.Http.WinHttpHandler.<StartRequest>d__105.MoveNext() in D:\j\workspace\windows-TGrou---6368dffa\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs:line 833

They also are not failing with the same data -- 20171205.06 fails with the arguments
statusLine: \"HTTP/1.1 201 Created\", expectedStatusCode: 201, expectedReason: \"Created\"

but 20171205.05 fails with
statusLine: \"HTTP/1.1 202 Accepted\", expectedStatusCode: 202, expectedReason: \"Accepted\"

[karelz]

Note that "The handle is invalid" failures would be just transformed into another exception (e.g. "The operation has been canceled") if #17542 was fixed, the test would still fail - see https://github.com/dotnet/corefx/issues/25912#issuecomment-351808254

[rmkerr]

Thanks for letting me know -- I was definitely getting sidetracked by that issue. I'll try to see if I can root cause the problem in the test then instead of looking into #17542.

[karelz]

BTW: Both issues are important to get to clean test runs, so feel free to focus on the one you think is easier / more tractable ;)

[rmkerr]

I spent quite a while looking into this issue, but since I haven't tracked down the solution I'll be setting it aside to get on to other work for now. Here are the basics of what I've discovered:

• The failures are all the result of a request being cancelled. I do not know whether this cancellation comes from a timeout or from some other source.
• The failures all occur when using WinHttpHandler. Though sometimes there are failures in ManagedHandler tests, those tests all use the test proxy server. The test proxy server uses WinHttpHandler and is actually what fails in those cases.
• The cancellation happens before the request is sent.
• The failures is caught in WinHttpHandler after the native call to WinHttpSendRequest returns an error indicating that the handle has been closed.

I can consistently reproduce the issue and can collect logs if anyone would like more information. For now though, I'll be focusing on other issues.

[karelz]

It would be great to see a PerfView trace of the failure. If it's low-overhead for you to collect one, please send it to me.
Moving to Future as we don't have time to track it down for 2.1.

[rmkerr]

Closing as this issue has not occurred since March 21st.