Runtime: Test failure: Manual_CertificateSentMatchesCertificateReceived_Success

Created on 20 Jun 2016  路  43Comments  路  Source: dotnet/runtime

The test as currently written fails sporadically on Windows. If, however, GC.Collect(); GC.WaitForPendingFinalizers(); is added inside the loop here: https://github.com/dotnet/corefx/blob/483aa5a3012fe78ea001ece1b0404b18c0b90a29/src/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTest.ClientCertificates.cs#L117
the reuseClient==false test fails deterministically for me with the error "The client certificate credentials were not recognized". It appears something is getting finalized and preventing the same certificate instance from being used with subsequent HttpClientHandler instances.

area-System.Net.Http bug disabled-test os-windows test-run-core
Source
picture stephentoub

Most helpful comment

Currently running the tests with the fix for dotnet/corefx#16516 to see if the test results change. Will report back when I have the information.

picture steveharter on 5 May 2017
👍2

All 43 comments

Failed on Ubuntu here: http://dotnet-ci.cloudapp.net/job/dotnet_corefx/job/master/job/ubuntu14.04_debug_prtest/2303/testReport/junit/System.Net.Http.Functional.Tests/HttpClientHandler_ClientCertificates_Test/Manual_CertificateSentMatchesCertificateReceived_Success_numberOfRequests__3__reuseClient__True_/

Stacktrace

MESSAGE:
System.Threading.Tasks.TaskCanceledException : A task was canceled.
+++++++++++++++++++
STACK TRACE:
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at System.Runtime.CompilerServices.TaskAwaiter.GetResult() at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass5_0.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.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 System.Runtime.CompilerServices.TaskAwaiter.GetResult() at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass5_2.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.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 System.Runtime.CompilerServices.TaskAwaiter.GetResult() at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t) at System.Threading.Tasks.Task.Execute() --- 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 System.Runtime.CompilerServices.TaskAwaiter.GetResult() at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__5.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)
mellinoe picture mellinoe on 24 Jun 2016

Failed on Ubuntu again:

http://dotnet-ci.cloudapp.net/job/dotnet_corefx/job/master/job/ubuntu14.04_debug_prtest/2465/testReport/junit/System.Net.Http.Functional.Tests/HttpClientHandler_ClientCertificates_Test/Manual_CertificateSentMatchesCertificateReceived_Success_numberOfRequests__3__reuseClient__True_/

mellinoe picture mellinoe on 1 Jul 2016

Failed on Ubuntu again

Thanks, but this is a different failure than the one highlighted. This is a timeout, whereas the other is some kind of data corruption due to finalization.

stephentoub picture stephentoub on 1 Jul 2016

Sorry about that, you're right. Looks like both of my links are for a different root cause (and different OS).

I filed dotnet/corefx#9785 for the Ubuntu issue.

mellinoe picture mellinoe on 1 Jul 2016

@stephentoub I have a theory about why this test is failing.

the reuseClient==false test fails deterministicly for me with the error "The client certificate credentials were not recognized". It appears something is getting finalized and preventing the same certificate instance from being used with subsequent HttpClientHandler instances.

The client certificate used in this test is a STATIC thing coming from here:
https://github.com/dotnet/corefx/blob/master/src/Common/tests/System/Net/Configuration.Certificates.cs#L24

This client certificate is added to an instance of an X509Certificate2Collection object within a HttpClientHandler object. What are the dispose/finalization rules for X509Certificate2Collection? Does it dispose of things in the collection? If it does, this is why this is failing. The fix for this is to create instance copies of the client certificate instead of re-using a static object.

@bartonjs Can you comment on this?

cc: @CIPop

davidsh picture davidsh on 27 Aug 2016

I think the best solution is probably to change Configuration.Certificate.cs so that it returns a new instance of the certificates.

It's ok for the DATA to create a certificate (server or client) to be a static thing. But the X509Certificate2 object itself that is returned should be a new instance copy.

davidsh picture davidsh on 27 Aug 2016

@davidsh X509Certificate2Collection isn't inherently IDisposable; nothing would Dispose a cert unless you did it manually. That said, the X509Certificate tests do hold static data, and each test that wants the data clones it anew.

bartonjs picture bartonjs on 27 Aug 2016

Fails on build 20161204.02. So adding "test-run-core"
https://mc.dot.net/#/product/netcore/master/source/official~2Fcorefx~2Fmaster~2F/type/test~2Ffunctional~2Fcli~2F/build/20161204.02/workItem/System.Net.Http.Functional.Tests/analysis/xunit/System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test~2FManual_CertificateSentMatchesCertificateReceived_Success(numberOfRequests:%203,%20reuseClient:%20True)

Unhandled Exception of Type System.Threading.Tasks.TaskCanceledException
Message :
System.Threading.Tasks.TaskCanceledException : A task was canceled.

Stack Trace :
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass5_0.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass5_2.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t)
   at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__5.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   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.ExceptionServices.ExceptionDispatchInfo.Throw()
   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.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
jiangzeng picture jiangzeng on 5 Dec 2016

Fails on build 20161227.01, please check: https://mc.dot.net/#/product/netcore/master/source/official~2Fcorefx~2Fmaster~2F/type/test~2Ffunctional~2Fcli~2F/build/20161227.01/workItem/System.Net.Http.Functional.Tests/analysis/xunit/System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test~2FManual_CertificateSentMatchesCertificateReceived_Success(numberOfRequests:%203,%20reuseClient:%20True)

Message:
~
System.Threading.Tasks.TaskCanceledException : A task was canceled.
~

Stack Trace:
~
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass5_0.<b__2>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass5_2.<b__4>d.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.b__0(Task t)
at System.Threading.Tasks.Task.Execute()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.d__5.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
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.ExceptionServices.ExceptionDispatchInfo.Throw()
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.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
~

KristinXie1 picture KristinXie1 on 28 Dec 2016

Tracking all System.Net intermittently failing bugs with dotnet/corefx#14519.

CIPop picture CIPop on 28 Dec 2016

Reopening since it's being referenced by dotnet/corefx#16167

stephentoub picture stephentoub on 15 Feb 2017

I believe there are two issues with this test:
1) A cert was reused after it was gc'd and caused errors like "The client certificate credentials were not recognized". This was fixed with the creation of the cert every time through the loop https://github.com/dotnet/corefx/issues/15777
2) The test fails with "a task has been canceled" or "The server returned an invalid or unrecognized response". This has not been fixed yet.

steveharter picture steveharter on 17 Feb 2017

This is still active; may or may not be a test bug as the last attempt to fix resulted in occasional test hangs

steveharter picture steveharter on 2 Mar 2017

Flagging this as product bug, not test bug. Adding a Task.Delay(1) at the end of makeAndValidateRequest() appears to mask the issue and avoid the occasional exception. Perhaps there is a timing or race condition stemming from calling LoopbackServer.AcceptSocketAsync for each run (with the same server).

This can be repro'd on Windows by changing the

        [InlineData(6, false)]
        [InlineData(3, true)]

to

        [InlineData(600, false)]
        [InlineData(300, true)]

or similar large value. I've found that locally only a single run is should raise an exception, although two may be needed.

steveharter picture steveharter on 20 Mar 2017

@steveharter Do you still have a repro? (I couldn't repro with the above values - looks like this one is very tightly related to timings.)

CIPop picture CIPop on 26 Apr 2017

I no longer have a local repro. I enabled the test, change the InlineData values and ran the suite 5 times without error (normally once was enough).

steveharter picture steveharter on 26 Apr 2017

@steveharter can you please check if you hit it on the CI machine in a loop?
If not, I guess we should close it as no repro, at least until next failure in CI. Thoughts?

karelz picture karelz on 2 May 2017

I originally thought this might be dotnet/corefx#16516 which we currently believe it's caused by a Windows bug.
This is happening on both Linux and Windows.

CIPop picture CIPop on 4 May 2017

I can repro after running the HttpFunctional tests in a loop. Out of 32 runs, it repro'd twice.

What I did to repro:
1) Comment out the [ActiveIssue(9543)]
2) Change [InlineData] values from 6,3 to 666,333
3) Run all of the HttpFunctional tests in a loop on my local Windows 10 machine

steveharter picture steveharter on 4 May 2017

@CIPop needs some more traces - @steveharter can you please help? (@CIPop will try to repro locally first)

karelz picture karelz on 4 May 2017

Sure. Currently running just the single test to see if it repros alone.

steveharter picture steveharter on 4 May 2017

In a limited run of 70, this did not repro running the test individually, so assuming likely interference from other tests however the data is not conclusive.

@CIPop I can apply your proposed fix for dotnet/corefx#16516 and see if it repros when running the whole suite if you are unable to repro locally yourself.

steveharter picture steveharter on 4 May 2017

Currently running the tests with the fix for dotnet/corefx#16516 to see if the test results change. Will report back when I have the information.

steveharter picture steveharter on 5 May 2017
👍2

The test is still failing with the recent changes to dotnet/corefx#16516.

The first failure occurred on run # 46:

System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfRequests: 666, reuseClient: False) [FAIL]
      System.Net.Http.HttpRequestException : An error occurred while sending the request.
      ---- System.Net.Http.WinHttpException : The client certificate credentials were not recognized
      Stack Trace:
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
            at System.Net.Http.HttpClient.<FinishSendAsyncUnbuffered>d__59.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
            at System.Net.Http.HttpClient.<GetStringAsyncCore>d__27.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t)
            at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__6.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         ----- Inner Stack Trace -----
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Threading.Tasks.RendezvousAwaitable`1.GetResult()
            at System.Net.Http.WinHttpHandler.<StartRequest>d__105.MoveNext()
steveharter picture steveharter on 6 May 2017

@steveharter I'm trying to fix my parallel execution script but I'm hitting a problem when trying to determine the runtime path:
I see that during msbuild build+test this is part of the output:

```GenerateTestExecutionScripts:
Generating S:\corefx\bin//TestDependencies/System.Net.Ping.Functional.Tests-.dependencylist.txt
Test Command lines = set XUNIT_PERFORMANCE_MIN_ITERATION=1
set XUNIT_PERFORMANCE_MAX_ITERATION=1
call %RUNTIME_PATH%\dotnet.exe xunit.console.netcore.exe System.Net.Ping.Functional.Tests.dll -showprogress -notrait category=failing -notrait category=nonwindowstests
Wrote Windows-compatible test execution script to S:\corefx\bin/Windows_NT.AnyCPU.Debug/System.Net.Ping.Functional.Tests/netstandard//RunTests.cmd


The RUNTIME_PATH variable is not set in my environment: I presume it's something calculated during MSBuild. Even more, the test execution script won't run:

Using /=\ as the test runtime folder.
Executing in S:\corefx\bin\Windows_NT.AnyCPU.Debug\System.Net.Ping.Functional.Tests\netstandard\
Running tests... Start time: 17:49:08.88

set XUNIT_PERFORMANCE_MIN_ITERATION=1

set XUNIT_PERFORMANCE_MAX_ITERATION=1

call /=\dotnet.exe xunit.console.netcore.exe System.Net.Ping.Functional.Tests.dll -showprogress -notrait category=failing -notrait category=nonwindowstests
'/' is not recognized as an internal or external command,
operable program or batch file.
Finished running tests. End time=17:49:08.88, Exit code = 1
```

Any ideas on how to automate running the test in a tight loop without recompiling every time?

CIPop picture CIPop on 6 May 2017

I figured it out: it was a few lines below: Using S:\corefx\bin\testhost\netcoreapp-Windows_NT-Debug-x64\ as the test runtime folder.

CIPop picture CIPop on 6 May 2017

@steveharter Looks like we're seeing multiple issues here. I can repro two failures if I replace the fors with Parallel.For:

 WIP: Starting - Manual_CertificateSentMatchesCertificateReceived_Success

 Unhandled Exception: System.ObjectDisposedException: Cannot access a disposed object.
  Object name: 'System.Net.Sockets.Socket'.
     at System.Net.Sockets.Socket.EndAccept(Byte[]& buffer, Int32& bytesTransferred, IAsyncResult asyncResult) in S:\corefx\src\S
  ystem.Net.Sockets\src\System\Net\Sockets\Socket.cs:line 3760
     at System.Net.Sockets.Socket.EndAccept(IAsyncResult asyncResult) in S:\corefx\src\System.Net.Sockets\src\System\Net\Sockets\
  Socket.cs:line 3737
     at System.Net.Test.Common.LoopbackServer.<>c.<AcceptAsyncApm>b__13_0(IAsyncResult iar) in S:\corefx\src\Common\tests\System\
  Net\Http\LoopbackServer.cs:line 206
  --- End of stack trace from previous location where exception was thrown ---

  ...

  ystem.Net.Sockets\src\System\Net\Sockets\Socket.cs:line 3760
     at System.Net.Sockets.Socket.EndAccept(IAsyncResult asyncResult) in S:\corefx\src\System.Net.Sockets\src\System\Net\Sockets\
  Socket.cs:line 3737
     at System.Net.Test.Common.LoopbackServer.<>c.<AcceptAsyncApm>b__13_0(IAsyncResult iar) in S:\corefx\src\Common\tests\System\
  Net\Http\LoopbackServer.cs:line 206

And something very similar to the one above:

      Condition(s) not met: \"BackendDoesNotSupportCustomCertificateHandling\"
WIP: Starting - Manual_CertificateSentMatchesCertificateReceived_Success (666, False)
WIP: Finished - Manual_CertificateSentMatchesCertificateReceived_Success
WIP: Starting - Manual_CertificateSentMatchesCertificateReceived_Success (333, True)

Unhandled Exception: System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext() in S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs:line 106
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_2.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__5>d.MoveNext() in 
...
S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs:line 130
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
CIPop picture CIPop on 9 May 2017

The Parallel.For changes I'm making here and here are breaking the async/await pattern. For some reason the compiler isn't smart enough to detect that if only one of the above places is replaced by a Parallel.For.
If I replace both for statements with Parallel.For the compiler shows that the top-level async lambda doesn't contain the await keyword anymore.

@steveharter The issue you reproed and the one in this bug do not match:

Your issue (_B_) is:

  System.Net.Http.HttpRequestException : An error occurred while sending the request.
 ---- System.Net.Http.WinHttpException : The client certificate credentials were not recognized

While the original one from CI is (_A_):

 Unhandled Exception of Type System.Threading.Tasks.TaskCanceledException
 Message :
 System.Threading.Tasks.TaskCanceledException : A task was canceled.

I'm currently trying to understand the cryptic stack from _A_ by looking at the decompiled test code.

@stephentoub - is there a better way to read stacks involving lambda and autogenerated classes such as private sealed class <<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d : IAsyncStateMachine?

@steveharter - can you still repro _B_? Were you able to repro _A_ at any point?

CIPop picture CIPop on 9 May 2017

The Parallel.For changes I'm making here and here are breaking the async/await pattern

What change are you trying to make? The delegate Parallel.For takes is void-returning: as far as the Parallel.For is concerned, for each iteration it'll invoke the delegate and that iteration is done when the delegate returns, but in the case of a void async, it'll return at the first await that yields. That's definitely not going to do what you want. See https://blogs.msdn.microsoft.com/pfxteam/2012/03/05/implementing-a-simple-foreachasync-part-2/ for some example implementations that will work.

stephentoub picture stephentoub on 9 May 2017

What change are you trying to make?

The way I've obtained the TaskCanceled failure above was to replace this "for" loop with a Parallel.For. (The new code is incorrect as we've both pointed out but it may still be interesting since the same error is thrown.)

it'll return at the first await that yields

I'm now thinking that something very similar is happening in the original code: one of the tasks in the task chain is not properly awaited. I don't know where yet.

Any pointers on how to interpret the stack trace w/o decompiling the test binary and looking at the generated classes for each lambda?

CIPop picture CIPop on 9 May 2017

Any pointers on how to interpret the stack trace

The stack is:

System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext() in S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs:line 106
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_2.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__5>d.MoveNext() in S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs:line 130
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

Mentally delete these three lines from each section:

   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

Those are infrastructure involved in propagating the exception stored in the task, and unfortunately don't have a good way to hide it from stack traces.

That leaves you with:

System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext() in S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs:line 106
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_2.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__5>d.MoveNext() in S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs:line 130
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

The async part of this should be pretty easy to understand: those two lines 106 and 130 are in the async method Manual_CertificateSentMatchesCertificateReceived_Success. The b__2 and b__5 actually have little to do with async/await: those are the names of the methods generated for the lambdas in the code (you would see similar names in regular synchronous code using lambdas).

stephentoub picture stephentoub on 9 May 2017
👍1

Regarding the original failure described by (_A_):

at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>__c__DisplayClass5_0__.<b__2>d.MoveNext() doesn't exist anymore. This has been replaced by private sealed class <>__c__DisplayClass6_0__ .

If I make this conversion, the stack tells us that the exception was thrown by the taskAwaiter in private sealed class <<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d : IAsyncStateMachine which is:

taskAwaiter = TestHelper.WhenAllCompletedOrAnyFailed(new Task[]
                {
                    this.client.GetStringAsync(this.url),
                    LoopbackServer.AcceptSocketAsync(this.server, new Func<Socket, Stream, StreamReader, StreamWriter, Task<List<string>>>(this.<>8__1.<Manual_CertificateSentMatchesCertificateReceived_Success>b__3), this.<>4__this.options)
                }).GetAwaiter();

Unless that code changed as well, the exception is probably caused by this line.

At this point we don't know exactly what happened: there is a race condition in the continuations and the original exception is now gone.
In the current LoopbackServer or test code I don't see anything cancelling a task and so I think the best bet is that HttpClient canceled something internally.

This leaves us with a single option: the HttpClient Timeout expired.

Setting HttpClient.Timeout to 100ms I can a very similar stack:

     System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfReque
  sts: 666, reuseClient: False) [STARTING]
     System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfReque
  sts: 666, reuseClient: False) [FAIL]
        System.Threading.Tasks.TaskCanceledException : A task was canceled.
        Stack Trace:
              at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
              at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
           S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs(105,0): at System.Net.Http.Functional.Tests
  .HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext()
           --- End of stack trace from previous location where exception was thrown ---
              at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
              at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
              at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
           S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs(142,0): at System.Net.Http.Functional.Tests
  .HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.MoveNext()
           --- End of stack trace from previous location where exception was thrown ---
              at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
              at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
              at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
     System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfReque
  sts: 666, reuseClient: False) [FINISHED] Time: 0.1556715s
     System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfReque
  sts: 333, reuseClient: True) [STARTING]
           S:\corefx\src\Common\tests\System\Net\Http\LoopbackServer.cs(57,0): at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateSe
  rverAsync>b__0(Task t)
              at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
              at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
           --- End of stack trace from previous location where exception was thrown ---
              at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
              at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
           S:\corefx\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs(116,0): at System.Net.Http.Functional.Tests
  .HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__6.MoveNext()
           --- End of stack trace from previous location where exception was thrown ---
              at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
              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.ExceptionServices.ExceptionDispatchInfo.Throw()
              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.ExceptionServices.ExceptionDispatchInfo.Throw()
              at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
              at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
     System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfReque
  sts: 333, reuseClient: True) [FAIL]

The default HttpClient timeout is 100s. We don't have enough information to debug the conditions that lead for this request and the test to hang for more than a minute.

I'll add instrumentation that will crash the process after less than the HttpClient timeout default (somewhere around 10-20s) and hopefully the full-memory dump can show us the state of both the HttpClientHandler and the LoopbackServer. I'll also see if I can safely add some fail-fast checks within LoopbackServer itself for Debug builds.

@steveharter I think (_B_), the issue you've reported is different from this one and deserves a separate bug. Please open one together with all the information you can gather. A full-memory dump would be ideal.

CIPop picture CIPop on 10 May 2017

Looking at _B_ the error was ERROR_WINHTTP_CLIENT_CERT_NO_ACCESS_PRIVATE_KEY which seems closely related to dotnet/corefx#16516.

CIPop picture CIPop on 10 May 2017

@steveharter - can you still repro B? Were you able to repro A at any point?

Yes _B_ repros the most. I am no longer able to repro _A_ (A task was cancelled).

Here's what I got after 1,600 runs runs on Win10:

  • 52 instances of "System.Net.Http.WinHttpException : The client certificate credentials were not recognized" (numberOfRequests: 666, reuseClient: False)
    -- Note: this is error _B_ per above
    -- Note: these all had test args of 666, False (no instances of 333, True)
  • 2 instances of "System.Net.Http.WinHttpException : The handle is invalid" (numberOfRequests: 666, reuseClient: False)
  • 4 instances of "System.IO.IOException : Authentication failed because the remote party has closed the transport stream." (numberOfRequests: 666, reuseClient: False)
  • 1 instance of "System.Net.Http.WinHttpException : The server returned an invalid or unrecognized response" (numberOfRequests: 333, reuseClient: True)
    -- Note: Same exception also occurred 5 times on test .ReadAsStreamAsync_ValidServerResponse_Success(transferType: ContentLength, transferError: None)

Here's the full stacks for each:

System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfRequests: 666, reuseClient: False) [FAIL]
      System.Net.Http.HttpRequestException : An error occurred while sending the request.
      ---- System.Net.Http.WinHttpException : The client certificate credentials were not recognized
      Stack Trace:
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
         c:\git\api53\src\System.Net.Http\src\System\Net\Http\HttpClient.cs(487,0): at System.Net.Http.HttpClient.<FinishSendAsyncUnbuffered>d__59.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
         c:\git\api53\src\System.Net.Http\src\System\Net\Http\HttpClient.cs(139,0): at System.Net.Http.HttpClient.<GetStringAsyncCore>d__27.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         C:\git\api53\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs(103,0): at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         C:\git\api53\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs(140,0): at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         C:\git\api53\src\Common\tests\System\Net\Http\LoopbackServer.cs(57,0): at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t)
            at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         C:\git\api53\src\System.Net.Http\tests\FunctionalTests\HttpClientHandlerTest.ClientCertificates.cs(114,0): at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__6.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         ----- Inner Stack Trace -----
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
         c:\git\api53\src\Common\src\System\Threading\Tasks\RendezvousAwaitable.cs(62,0): at System.Threading.Tasks.RendezvousAwaitable`1.GetResult()
         c:\git\api53\src\System.Net.Http.WinHttpHandler\src\System\Net\Http\WinHttpHandler.cs(856,0): at System.Net.Http.WinHttpHandler.<StartRequest>d__105.MoveNext()

System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfRequests: 666, reuseClient: False) [FAIL]
      System.IO.IOException : Authentication failed because the remote party has closed the transport stream.
      Stack Trace:
            at System.Net.Security.SslState.StartReadFrame(Byte[] buffer, Int32 readBytes, AsyncProtocolRequest asyncRequest)
            at System.Net.Security.SslState.PartialFrameCallback(AsyncProtocolRequest asyncRequest)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Net.Security.SslState.InternalEndProcessAuthentication(LazyAsyncResult lazyResult)
            at System.Net.Security.SslState.EndProcessAuthentication(IAsyncResult result)
            at System.Net.Security.SslStream.EndAuthenticateAsServer(IAsyncResult asyncResult)
            at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Test.Common.LoopbackServer.<AcceptSocketAsync>d__9.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t)
            at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__6.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)

System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfRequests: 666, reuseClient: False) [FAIL]
      System.Net.Http.HttpRequestException : An error occurred while sending the request.
      ---- System.Net.Http.WinHttpException : The handle is invalid
      Stack Trace:
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
            at System.Net.Http.HttpClient.<FinishSendAsyncUnbuffered>d__59.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
            at System.Net.Http.HttpClient.<GetStringAsyncCore>d__27.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t)
            at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__6.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         ----- Inner Stack Trace -----
            at System.Net.Http.WinHttpException.ThrowExceptionUsingLastError()
            at System.Net.Http.WinHttpHandler.SetWinHttpOption(SafeWinHttpHandle handle, UInt32 option, IntPtr optionData, UInt32 optionSize)
            at System.Net.Http.WinHttpHandler.SetRequestHandleClientCertificateOptions(SafeWinHttpHandle requestHandle, Uri requestUri)
            at System.Net.Http.WinHttpHandler.SetRequestHandleOptions(WinHttpRequestState state)
            at System.Net.Http.WinHttpHandler.<StartRequest>d__105.MoveNext()

System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.Manual_CertificateSentMatchesCertificateReceived_Success(numberOfRequests: 333, reuseClient: True) [FAIL]
      System.Net.Http.HttpRequestException : An error occurred while sending the request.
      ---- System.Net.Http.WinHttpException : The server returned an invalid or unrecognized response
      Stack Trace:
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
            at System.Net.Http.HttpClient.<FinishSendAsyncUnbuffered>d__59.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
            at System.Net.Http.HttpClient.<GetStringAsyncCore>d__27.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__2>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<>c__DisplayClass6_1.<<Manual_CertificateSentMatchesCertificateReceived_Success>b__4>d.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Test.Common.LoopbackServer.<>c__DisplayClass3_0.<CreateServerAsync>b__0(Task t)
            at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
            at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
            at System.Net.Http.Functional.Tests.HttpClientHandler_ClientCertificates_Test.<Manual_CertificateSentMatchesCertificateReceived_Success>d__6.MoveNext()
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         --- End of stack trace from previous location where exception was thrown ---
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
         ----- Inner Stack Trace -----
            at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
            at System.Threading.Tasks.RendezvousAwaitable`1.GetResult()
            at System.Net.Http.WinHttpHandler.<StartRequest>d__105.MoveNext()
steveharter picture steveharter on 10 May 2017

Thanks @steveharter ! These are all different issues from the original (which was a server-side crash or other kind of timeout).
Do you think we should track using separate issues or keep the same since they all happen within this particular test?

The stacks are almost impossible to decipher - they require disassembly to understand what __DisplayClass3_0. ... b__0() and similar actually mean. On top of that, if the code changes with as much as adding another await all of the IDs change to mean something different... Even after doing so I found out that the actual error/exception was long gone and what we're seeing is just the error state being marshaled to the test thread.

@karelz @davidsh @DavidGoll Based on the triage decision of time-boxing this investigation, I'm moving this to "Future".

@steveharter proved that under stress, the HttpClient/WinHttpHandler has at least 3 failure modes. To continue the investigation my ideas would be to:

  1. Use sufficient VMs that continuously run the tests in a tight loop. This increases the likelihood of repro-ing the problems as well as providing an A/B testing environment.
  2. Instrument the code to Debug.Fail and dump memory on unknown errors such as ERROR_WINHTTP_CLIENT_CERT_NO_ACCESS_PRIVATE_KEY, ERROR_WINHTTP_INVALID_SERVER_RESPONSE, ERROR_WINHTTP_INCORRECT_HANDLE_TYPE, ERROR_WINHTTP_INCORRECT_HANDLE_STATE.
  3. For errors such as Authentication failed because the remote party has closed the transport stream. we would also need to capture a full-memory dump and understand the state for the LoopbackServer/SslStream/NetworkStream to understand where they crash.
  4. Fix the TestHelper.WhenAllCompletedOrAnyFailed pattern to ensure we somehow get sufficient state information from all other tasks when a test failure is logged.
  5. Instrument LoopbackServer to fail fast (with a memory dump in order to see the client task state) and otherwise log each operation.
  6. As a last resort, separate the test into two processes : client and server. Running on 2 separate machines this method will also allow capturing network traffic.
CIPop picture CIPop on 11 May 2017
👍1

In the case of Authentication failed because the remote party has closed the transport stream. the remote party is HttpClient.

It's expected to see either this or one of the other 3 failures: WinHttp initiates the connection then enters a faulted state (e.g. ERROR_WINHTTP_CLIENT_CERT_NO_ACCESS_PRIVATE_KEY) during negotiation which most likely triggers our code to force-close all WinHTTP handles. Since that translates in the TCP connection being RST-ed, the server-side SslStream will throw the IOException.

Because of the race condition in TestHelper.WhenAllCompletedOrAnyFailed we will only see one error: either the client (one of the three above) or the server IOException.

CIPop picture CIPop on 11 May 2017

if the code changes with as much as adding another await all of the IDs change to mean something different

Can you clarify this part? That should not be the case. Those IDs have nothing to do with individual awaits or even async: they're the names of the lambdas in the code. Can you share an example where adding an await to an existing async method changes those names?

stephentoub picture stephentoub on 11 May 2017

@karelz, if someone on your team has time, it'd be very helpful to investigate this one. This doesn't appear to be doing anything particular special with client certificates, but after the changes in https://github.com/dotnet/corefx/pull/29238, this now repros for me 100% of the time with WinHttpHandler, and sporadically with SocketsHttpHandler. I worry there's some issue with how we're interacting with Windows in both that's causing an issue for client certs. Hopefully it's somehow just a test bug or a configuration issue or something.

stephentoub picture stephentoub on 20 Apr 2018

@caesar1995 can you please help us and take a look?

karelz picture karelz on 20 Apr 2018

The test is marked as disabled. How did you see the failures @stephentoub? (just curious)

karelz picture karelz on 20 Apr 2018

How did you see the failures

I removed the ActiveIssue.

stephentoub picture stephentoub on 20 Apr 2018

Here is my current summary:

Without any modification to current code base, there are three faliures for Manual_CertificateSentMatchesCertificateReceived_Success:

  1. SocketsHttpHandler: args(numberOfRequests: 6, reuseClient: False)
  2. SocketsHttpHandler: args(numberOfRequests: 3, reuseClient: True)
  3. WinHttpHandler: args(numberOfRequests: 6, reuseClient: False)

_1 & 2 are intermittent failure, 3 is 100% repro._

1 & 2 (SocketsHttpHandler failures) are in the same category, below is their exception stack. I think the root cause for them is here: dotnet/corefx#23341, and the summary is that:

  1. _Parallel tests using client certificates are problematic on Windows._
  2. There are two potential workaround https://github.com/dotnet/corefx/issues/23341#issuecomment-328693624. (Import the PFX with EphemeralKeySet, or use a private PFX editor)
System.AggregateException : One or more errors occurred. (One or more errors occurred. (The SSL connection could not be established, see inner exception.)) (One or
  more errors occurred. (Authentication failed because the remote party has closed the transport stream.))
        ---- System.AggregateException : One or more errors occurred. (The SSL connection could not be established, see inner exception.)
        -------- System.Net.Http.HttpRequestException : The SSL connection could not be established, see inner exception.
->        ------------ _**System.ComponentModel.Win32Exception : The credentials supplied to the package were not recognized**_ <-
        ---- System.AggregateException : One or more errors occurred. (Authentication failed because the remote party has closed the transport stream.)
        -------- System.IO.IOException : Authentication failed because the remote party has closed the transport stream.

The failure 3 has similar exception stack as 1 & 2. My current finding/experiment points to this potential cause: the certificate gets finalized/disposed too early during execution (need more investigation and verification).

System.AggregateException : One or more errors occurred. (One or more errors occurred. (An error occurred while sending the request.)) (One or more errors occurred.
   (Authentication failed because the remote party has closed the transport stream.))
        ---- System.AggregateException : One or more errors occurred. (An error occurred while sending the request.)
        -------- System.Net.Http.HttpRequestException : An error occurred while sending the request.
->        ------------ _**System.Net.Http.WinHttpException : Error 12186 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The client certificate credentials were not recognized'.**_ <-
        ---- System.AggregateException : One or more errors occurred. (Authentication failed because the remote party has closed the transport stream.)
        -------- System.IO.IOException : Authentication failed because the remote party has closed the transport stream.

I tried to add XUnitAssemblyAttributes.cs, which set DisableTestParallelization to true (just for testing purpose, this cannot be a solution). 1 & 2 seems goes away (no repro for several runs), while case 3 is still 100% repro.

We can discuss the potential workarounds for 1&2. Hopefully after implementing it, case 3 will be resolved. Meanwhile, I will continue look into case 3.

/cc: @karelz

caesar-chen picture caesar-chen on 24 Apr 2018

dotnet/corefx#9543 is related to this issue.

The best way to fix this is to do the same thing as @bartonjs did for the X509 tests by using the PFXEdit tool to strip out the key friendly name from the PFX file. This was done for the X509 tests here:
https://github.com/dotnet/corefx-testdata/commit/7d0aeccf493f2f2a8e5d8a3bf0d238f9881cff0a

I am now able to build that tool using docker and Ubuntu 14.04 (plus a few packages) and am planning to update the System.Net.Security related PFX files checked into the corefx-testdata repo: https://github.com/dotnet/corefx-testdata/tree/master/System.Net.TestData.

Doing so will fix these strange SCHANNEL related errors we get when these tests runs in parallel:

The client certificate credentials were not recognized

The credentials supplied to the package were not recognized

davidsh picture davidsh on 14 May 2018
Was this page helpful?
0 / 5 - 0 ratings

Related issues

sahithreddyk picture sahithreddyk  路  3Comments
yahorsi picture yahorsi  路  3Comments
omariom picture omariom  路  3Comments
bencz picture bencz  路  3Comments
noahfalk picture noahfalk  路  3Comments