AuthProxy__ValidCreds_ProxySendsRequestToServer failing a lot in CI

[stephentoub]

This test is failing a lot in outerloop runs, e.g.
https://mc.dot.net/#/user/stephentoub/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/23bace4614f4705c1b92f1cc2e2e78a1ed65f0ea

2018-10-13 03:15:04,595: INFO: proc(55): run_and_log_output: Output: Assertion Failed
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output: 
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.HttpConnectionPool.InvalidateHttp2Connection(Http2Connection connection) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs:line 822
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.Http2Connection.AbortStreams(Int32 lastValidStream) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 496
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.Http2Connection.ProcessIncomingFrames() in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 139
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 934
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.Http2Connection.ProcessIncomingFrames()
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.Http2Connection.SetupAsync() in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 91
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.<>c.<.cctor>b__11_0(Object s) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 525
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\ExecutionContext.cs:line 166
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 563
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\TaskContinuation.cs:line 814
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\Task.cs:line 3272
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\future.cs:line 421
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 646
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 633
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.Http2Connection.ReadFrameAsync() in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 131
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.<>c.<.cctor>b__11_0(Object s) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 525
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\ExecutionContext.cs:line 166
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 563
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\TaskContinuation.cs:line 814
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\Task.cs:line 3272
2018-10-13 03:15:04,651: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\future.cs:line 421
2018-10-13 03:15:04,653: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 641
2018-10-13 03:15:04,653: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult() in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 254
2018-10-13 03:15:04,653: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.Http2Connection.EnsureIncomingBytesAsync(Int32 minReadBytes) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 105
2018-10-13 03:15:04,653: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.<>c.<.cctor>b__11_0(Object s) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 525
2018-10-13 03:15:04,653: INFO: proc(55): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\ExecutionContext.cs:line 166
2018-10-13 03:15:04,653: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 563
2018-10-13 03:15:04,653: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\TaskContinuation.cs:line 814
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\Task.cs:line 3272
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\future.cs:line 421
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 641
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder`1.SetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Runtime\CompilerServices\AsyncValueTaskMethodBuilder.cs:line 169
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Net.Http.Http2Connection.ReadAtLeastAsync(Stream stream, Memory`1 buffer, Int32 minReadBytes) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 767
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.<>c.<.cctor>b__11_0(Object s) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 525
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\ExecutionContext.cs:line 166
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 563
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\TaskContinuation.cs:line 814
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\Task.cs:line 3272
2018-10-13 03:15:04,654: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\future.cs:line 421
2018-10-13 03:15:04,655: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 641
2018-10-13 03:15:04,655: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder`1.SetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Runtime\CompilerServices\AsyncValueTaskMethodBuilder.cs:line 169
2018-10-13 03:15:04,655: INFO: proc(55): run_and_log_output: Output:    at System.Net.Security.SslStreamInternal.ReadAsyncInternal[TReadAdapter](TReadAdapter adapter, Memory`1 buffer) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Security\src\System\Net\Security\SslStreamInternal.cs:line 338
2018-10-13 03:15:04,655: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.<>c.<.cctor>b__11_0(Object s) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 525
2018-10-13 03:15:04,655: INFO: proc(55): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\ExecutionContext.cs:line 166
2018-10-13 03:15:04,655: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 563
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\TaskContinuation.cs:line 814
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\Task.cs:line 3272
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\future.cs:line 421
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 641
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetResult(TResult result) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 633
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Net.Security.SslStreamInternal.<FillBufferAsync>g__InternalFillBufferAsync|38_0[TReadAdapter](TReadAdapter adap, ValueTask`1 task, Int32 min, Int32 initial) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Security\src\System\Net\Security\SslStreamInternal.cs:line 515
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.<>c.<.cctor>b__11_0(Object s) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 525
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\ExecutionContext.cs:line 166
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 563
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.InvokeContinuation(Action`1 continuation, Object state, Boolean forceAsync) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Sockets\src\System\Net\Sockets\Socket.Tasks.cs:line 1038
2018-10-13 03:15:04,657: INFO: proc(55): run_and_log_output: Output:    at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.OnCompleted(SocketAsyncEventArgs _) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Sockets\src\System\Net\Sockets\Socket.Tasks.cs:line 869
2018-10-13 03:15:04,658: INFO: proc(55): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncEventArgs.FinishOperationAsyncSuccess(Int32 bytesTransferred, SocketFlags flags) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Sockets\src\System\Net\Sockets\SocketAsyncEventArgs.cs:line 770
2018-10-13 03:15:04,658: INFO: proc(55): run_and_log_output: Output:    at System.Net.Sockets.SocketAsyncEventArgs.<>c.<.cctor>b__174_0(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Sockets\src\System\Net\Sockets\SocketAsyncEventArgs.Windows.cs:line 1195
2018-10-13 03:15:04,658: INFO: proc(55): run_and_log_output: Output:    at System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pNativeOverlapped) in E:\A\_work\164\s\src\System.Private.CoreLib\src\System\Threading\Overlapped.cs:line 78

and

2018-10-13 03:07:40,539: INFO: proc(55): run_and_log_output: Output:     System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Proxy_Test.AuthProxy__ValidCreds_ProxySendsRequestToServer(proxyAuthScheme: Basic, secureServer: True, proxyClosesConnectionAfterFirst407Response: True) [FAIL]
2018-10-13 03:07:40,539: INFO: proc(55): run_and_log_output: Output:       System.Net.Http.HttpRequestException : An error occurred while sending the request.
2018-10-13 03:07:40,539: INFO: proc(55): run_and_log_output: Output:       ---- System.IO.IOException : Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host..
2018-10-13 03:07:40,539: INFO: proc(55): run_and_log_output: Output:       -------- System.Net.Sockets.SocketException : An existing connection was forcibly closed by the remote host.
2018-10-13 03:07:40,540: INFO: proc(55): run_and_log_output: Output:       Stack Trace:
2018-10-13 03:07:40,540: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnection.cs(683,0): at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
2018-10-13 03:07:40,540: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\AuthenticationHelper.NtAuth.cs(43,0): at System.Net.Http.AuthenticationHelper.SendWithNtAuthAsync(HttpRequestMessage request, Uri authUri, ICredentials credentials, Boolean isProxyAuth, HttpConnection connection, HttpConnectionPool connectionPool, CancellationToken cancellationToken)
2018-10-13 03:07:40,540: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(496,0): at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(467,0): at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\AuthenticationHelper.cs(220,0): at System.Net.Http.AuthenticationHelper.SendWithAuthAsync(HttpRequestMessage request, Uri authUri, ICredentials credentials, Boolean preAuthenticate, Boolean isProxyAuth, Boolean doRequestAuth, HttpConnectionPool pool, CancellationToken cancellationToken)
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(620,0): at System.Net.Http.HttpConnectionPool.EstablishProxyTunnel(CancellationToken cancellationToken)
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\Tasks\ValueTask.cs(849,0): at System.Threading.Tasks.ValueTask`1.get_Result()
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(567,0): at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\Tasks\ValueTask.cs(849,0): at System.Threading.Tasks.ValueTask`1.get_Result()
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(595,0): at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
2018-10-13 03:07:40,542: INFO: proc(55): run_and_log_output: Output:         E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\Tasks\ValueTask.cs(849,0): at System.Threading.Tasks.ValueTask`1.get_Result()
2018-10-13 03:07:40,543: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(671,0): at System.Net.Http.HttpConnectionPool.WaitForCreatedConnectionAsync(ValueTask`1 creationTask)
2018-10-13 03:07:40,543: INFO: proc(55): run_and_log_output: Output:         E:\A\_work\164\s\src\System.Private.CoreLib\shared\System\Threading\Tasks\ValueTask.cs(849,0): at System.Threading.Tasks.ValueTask`1.get_Result()
2018-10-13 03:07:40,543: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(454,0): at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
2018-10-13 03:07:40,543: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\RedirectHandler.cs(33,0): at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
2018-10-13 03:07:40,545: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\HttpClient.cs(475,0): at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
2018-10-13 03:07:40,545: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.Proxy.cs(95,0): at System.Net.Http.Functional.Tests.HttpClientHandler_Proxy_Test.AuthProxy__ValidCreds_ProxySendsRequestToServer(AuthenticationSchemes proxyAuthScheme, Boolean secureServer, Boolean proxyClosesConnectionAfterFirst407Response)
2018-10-13 03:07:40,545: INFO: proc(55): run_and_log_output: Output:         --- End of stack trace from previous location where exception was thrown ---
2018-10-13 03:07:40,545: INFO: proc(55): run_and_log_output: Output:         ----- Inner Stack Trace -----
2018-10-13 03:07:40,545: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnection.cs(1293,0): at System.Net.Http.HttpConnection.FillAsync()
2018-10-13 03:07:40,546: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnection.cs(1245,0): at System.Net.Http.HttpConnection.ReadNextResponseHeaderLineAsync(Boolean foldedHeadersAllowed)
2018-10-13 03:07:40,546: INFO: proc(55): run_and_log_output: Output:         D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnection.cs(512,0): at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
2018-10-13 03:07:40,546: INFO: proc(55): run_and_log_output: Output:         ----- Inner Stack Trace -----

[davidsh]

@geoffkizer

2018-10-13 03:15:04,595: INFO: proc(55): run_and_log_output: Output: Assertion Failed
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output:
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output: at System.Net.Http.HttpConnectionPool.InvalidateHttp2Connection(Http2Connection connection) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs:line 822
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output: at System.Net.Http.Http2Connection.AbortStreams(Int32 lastValidStream) in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 496
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output: at System.Net.Http.Http2Connection.ProcessIncomingFrames() in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 139
2018-10-13 03:15:04,648: INFO: proc(55): run_and_log_output: Output: at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in E:\A_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 934
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output: at System.Net.Http.Http2Connection.ProcessIncomingFrames()
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output: at System.Net.Http.Http2Connection.SetupAsync() in D:\j\workspace\windows-TGrou---db113413\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\Http2Connection.cs:line 91
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output: at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.<>c.<.cctor>b__11_0(Object s) in E:\A_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 525
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output: at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in E:\A_work\164\s\src\System.Private.CoreLib\shared\System\Threading\ExecutionContext.cs:line 166
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output: at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.MoveNext() in E:\A_work\164\s\src\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilder.cs:line 563
2018-10-13 03:15:04,650: INFO: proc(55): run_and_log_output: Output: at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in E:\A_work\164\s\src\System.Private.CoreLib\src\System\Threading\Tasks\TaskContinuation.cs:line 814

[geoffkizer]

There's a timing issue in the current logic. We need to add some coordination here.

That said, it seems really strange that we are trying to use HTTP2 here. For one, the test is not enabling HTTP2. For another, the specified host (SecureRemoteEchoServer) should not support HTTP2, so even if we try to negotiate HTTP2 it should downgrade to HTTP/1.1. Yet per the stack above, it looks like we are negotiating HTTP2 and then trying to read from the HTTP2 connection, which fails (presumably it's not actually HTTP2) and leads to the assert eventually.

@wfurt I think you wrote this test, any thoughts here?

[geoffkizer]

I see this failure locally fairly regularly, but I don't see the stack posted above. What I see is:

  System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpClientHandler_Proxy_Test.AuthProxy__ValidCreds_ProxySendsRequestToServer(proxyAuthScheme: Digest, secureServer: False, proxyClosesConnectionAfterFirst407Response: True) [FAIL]
    System.Net.Http.HttpRequestException : An error occurred while sending the request.
    ---- System.IO.IOException : Unable to read data from 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.
    Stack Trace:
      C:\github\geoffkizer\corefx\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnection.cs(684,0): at System.Net.Http.HttpConnection.SendAsyncCore(HttpRequestMessage request, CancellationToken cancellationToken)
      C:\github\geoffkizer\corefx\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\AuthenticationHelper.NtAuth.cs(44,0): at System.Net.Http.AuthenticationHelper.SendWithNtAuthAsync(HttpRequestMessage request, Uri authUri, ICredentials credentials, Boolean isProxyAuth, HttpConnection connection, HttpConnectionPool connectionPool, CancellationToken cancellationToken)
      C:\github\geoffkizer\corefx\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(512,0): at System.Net.Http.HttpConnectionPool.SendWithNtConnectionAuthAsync(HttpConnection connection, HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
      C:\github\geoffkizer\corefx\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\HttpConnectionPool.cs(483,0): at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
      C:\github\geoffkizer\corefx\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\AuthenticationHelper.cs(220,0): at System.Net.Http.AuthenticationHelper.SendWithAuthAsync(HttpRequestMessage request, Uri authUri, ICredentials credentials, Boolean preAuthenticate, Boolean isProxyAuth, Boolean doRequestAuth, HttpConnectionPool pool, CancellationToken cancellationToken)
      C:\github\geoffkizer\corefx\src\System.Net.Http\src\System\Net\Http\SocketsHttpHandler\RedirectHandler.cs(33,0): at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
      C:\github\geoffkizer\corefx\src\System.Net.Http\src\System\Net\Http\HttpClient.cs(475,0): at System.Net.Http.HttpClient.FinishSendAsyncBuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
      C:\github\geoffkizer\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.Proxy.cs(95,0): at System.Net.Http.Functional.Tests.HttpClientHandler_Proxy_Test.AuthProxy__ValidCreds_ProxySendsRequestToServer(AuthenticationSchemes proxyAuthScheme, Boolean secureServer, Boolean proxyClosesConnectionAfterFirst407Response)

[wfurt]

I'l try to reproduce on Windiows @geoffkizer . Can you make it fail just running that single test in loop?

[geoffkizer]

Can you make it fail just running that single test in loop?

Haven't tried.

[wfurt]

I look at the official test runs and there are only 4 failures in last 180 days. However there were 436 PR failures. All on Windows.

[davidsh]

This test is failing all the time on Nano even with the latest PRs.
https://mc.dot.net/#/user/davidsh/pr~2Fjenkins~2Fdotnet~2Fcorefx~2Fmaster~2F/test~2Ffunctional~2Fcli~2F/5875f79897e6412f633a9fc359da8315f8b7294e/workItem/System.Net.Http.Functional.Tests

I plan to submit a PR to disable this test on Nano and reference this issue.

[karelz]

@davidsh are you still working on this one? What is left here?

[davidsh]

@davidsh are you still working on this one? What is left here?

I originally wrote this test. I'm disappointed that it is still unstable. We've disabled it on most platforms except it still runs on Windows 8.1 CI and fails still at times.

I don't think it is required to fix for 3.0 so I will move the issue to Future.