SslStream test failing to access Mutex

[stephentoub]

@CIPop, this looks like fall out from your recent change:
https://ci.dot.net/job/dotnet_corefx/job/master/job/osx10.12_release_prtest/3093/consoleText

System.Net.Security.Tests.SslStreamStreamToStreamTest_Async.SslStream_StreamToStream_Successive_ClientWrite_Sync_Success [FAIL]
        Cannot acquire the global certificate mutex.
        Expected: True
        Actual:   False
        Stack Trace:
           /Users/dotnet-bot/j/workspace/dotnet_corefx/master/osx10.12_release_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(38,0): at System.Net.Test.Common.Configuration.Certificates.GetCertificateCollection(String certificateFileName)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/master/osx10.12_release_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs(391,0): at System.Net.Security.Tests.SslStreamStreamToStreamTest_Async.DoHandshake(SslStream clientSslStream, SslStream serverSslStream)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/master/osx10.12_release_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs(78,0): at System.Net.Security.Tests.SslStreamStreamToStreamTest.SslStream_StreamToStream_Successive_ClientWrite_Sync_Success()
     System.Net.Security.Tests.SslStreamStreamToStreamTest_BeginEnd.SslStream_StreamToStream_Authentication_Success [FAIL]
        Cannot acquire the global certificate mutex.
        Expected: True
        Actual:   False
        Stack Trace:
           /Users/dotnet-bot/j/workspace/dotnet_corefx/master/osx10.12_release_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(38,0): at System.Net.Test.Common.Configuration.Certificates.GetCertificateCollection(String certificateFileName)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/master/osx10.12_release_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs(404,0): at System.Net.Security.Tests.SslStreamStreamToStreamTest_BeginEnd.DoHandshake(SslStream clientSslStream, SslStream serverSslStream)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/master/osx10.12_release_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs(36,0): at System.Net.Security.Tests.SslStreamStreamToStreamTest.SslStream_StreamToStream_Authentication_Success()

[CIPop]

Thanks @stephentoub. You were right: it's probably the small timer. I'll increase to 30s.

[stephentoub]

Failed again here:
https://ci.dot.net/job/dotnet_corefx/job/release_2.0.0/job/osx10.12_debug_prtest/84/consoleText

        Cannot acquire the global certificate mutex.
        Expected: True
        Actual:   False
        Stack Trace:
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(48,0): at System.Net.Test.Common.Configuration.Certificates.GetCertificateCollection(String certificateFileName)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(34,0): at System.Net.Test.Common.Configuration.Certificates.GetServerCertificateCollection()
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(24,0): at System.Net.Test.Common.Configuration.Certificates.GetServerCertificate()
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamAlertsTest.cs(68,0): at System.Net.Security.Tests.SslStreamAlertsTest.<SslStream_StreamToStream_ServerInitiatedCloseNotify_Ok>d__3.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.Security.Tests.SslStreamNetworkStreamTest.SslStream_SendReceiveOverNetworkStream_Ok [FAIL]
        Cannot acquire the global certificate mutex.
        Expected: True
        Actual:   False
        Stack Trace:
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(48,0): at System.Net.Test.Common.Configuration.Certificates.GetCertificateCollection(String certificateFileName)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(34,0): at System.Net.Test.Common.Configuration.Certificates.GetServerCertificateCollection()
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(24,0): at System.Net.Test.Common.Configuration.Certificates.GetServerCertificate()
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamNetworkStreamTest.cs(24,0): at System.Net.Security.Tests.SslStreamNetworkStreamTest.<SslStream_SendReceiveOverNetworkStream_Ok>d__0.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.Security.Tests.CertificateValidationClientServer.CertificateValidationClientServer_EndToEnd_Ok(useClientSelectionCallback: False) [FAIL]
        Cannot acquire the global certificate mutex.
        Expected: True
        Actual:   False
        Stack Trace:
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(48,0): at System.Net.Test.Common.Configuration.Certificates.GetCertificateCollection(String certificateFileName)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs(34,0): at System.Net.Test.Common.Configuration.Certificates.GetServerCertificateCollection()
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/CertificateValidationClientServer.cs(26,0): at System.Net.Security.Tests.CertificateValidationClientServer..ctor()
  Exception from RemoteExecutorConsoleApp(System.Net.Security.Tests, Version=4.1.0.0, Culture=neutral, PublicKeyToken=9d77cc7ad39b68eb, System.Net.Security.Tests.LoggingTest+<>c, <EventSource_EventsRaisedAsExpected>b__1_0):
  Assembly: System.Net.Security.Tests, Version=4.1.0.0, Culture=neutral, PublicKeyToken=9d77cc7ad39b68eb
  Type: System.Net.Security.Tests.LoggingTest+<>c
  Method: Int32 <EventSource_EventsRaisedAsExpected>b__1_0()
  Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> Xunit.Sdk.TrueException: Cannot acquire the global certificate mutex.
  Expected: True
  Actual:   False
     at Xunit.Assert.True(Nullable`1 condition, String userMessage)
     at System.Net.Test.Common.Configuration.Certificates.GetCertificateCollection(String certificateFileName) in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs:line 48
     at System.Net.Test.Common.Configuration.Certificates.GetServerCertificateCollection() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs:line 34
     at System.Net.Test.Common.Configuration.Certificates.GetServerCertificate() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs:line 24
     at System.Net.Security.Tests.SslStreamStreamToStreamTest.SslStream_StreamToStream_Authentication_Success() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs:line 34
     at System.Net.Security.Tests.LoggingTest.<>c.<EventSource_EventsRaisedAsExpected>b__1_1() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/LoggingTest.cs:line 40
     at System.Diagnostics.Tracing.TestEventListener.RunWithCallback(Action`1 handler, Action body) in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs:line 91
     at System.Net.Security.Tests.LoggingTest.<>c.<EventSource_EventsRaisedAsExpected>b__1_0() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/LoggingTest.cs:line 36
     --- End of inner exception stack trace ---
     at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
     at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)
     at RemoteExecutorConsoleApp.Program.Main(String[] args) in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Diagnostics/RemoteExecutorConsoleApp/RemoteExecutorConsoleApp.cs:line 55
  
  Unhandled Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> Xunit.Sdk.TrueException: Cannot acquire the global certificate mutex.
  Expected: True
  Actual:   False
     at Xunit.Assert.True(Nullable`1 condition, String userMessage)
     at System.Net.Test.Common.Configuration.Certificates.GetCertificateCollection(String certificateFileName) in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs:line 48
     at System.Net.Test.Common.Configuration.Certificates.GetServerCertificateCollection() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs:line 34
     at System.Net.Test.Common.Configuration.Certificates.GetServerCertificate() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Net/Configuration.Certificates.cs:line 24
     at System.Net.Security.Tests.SslStreamStreamToStreamTest.SslStream_StreamToStream_Authentication_Success() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/SslStreamStreamToStreamTest.cs:line 34
     at System.Net.Security.Tests.LoggingTest.<>c.<EventSource_EventsRaisedAsExpected>b__1_1() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/LoggingTest.cs:line 40
     at System.Diagnostics.Tracing.TestEventListener.RunWithCallback(Action`1 handler, Action body) in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs:line 91
     at System.Net.Security.Tests.LoggingTest.<>c.<EventSource_EventsRaisedAsExpected>b__1_0() in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Security/tests/FunctionalTests/LoggingTest.cs:line 36
     --- End of inner exception stack trace ---
     at RemoteExecutorConsoleApp.Program.Main(String[] args) in /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/Common/tests/System/Diagnostics/RemoteExecutorConsoleApp/RemoteExecutorConsoleApp.cs:line 67
     System.Net.Http.Functional.Tests.HttpClientHandler_DangerousAcceptAllCertificatesValidator_Test.SetDelegate_ConnectionSucceeds(acceptedProtocol: Tls, requestOnlyThisProtocol: False) [FAIL]
        System.Net.Http.HttpRequestException : An error occurred while sending the request.
        ---- System.Net.Http.CurlException : SSL connect error
        Stack Trace:
              at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
              at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
              at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Http/src/System/Net/Http/HttpClient.cs(462,0): at System.Net.Http.HttpClient.<FinishSendAsyncBuffered>d__58.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)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTest.AcceptAllCerts.cs(46,0): at System.Net.Http.Functional.Tests.HttpClientHandler_DangerousAcceptAllCertificatesValidator_Test.<>c__DisplayClass1_0.<<SetDelegate_ConnectionSucceeds>b__0>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)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/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)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Http/tests/FunctionalTests/HttpClientHandlerTest.AcceptAllCerts.cs(44,0): at System.Net.Http.Functional.Tests.HttpClientHandler_DangerousAcceptAllCertificatesValidator_Test.<SetDelegate_ConnectionSucceeds>d__1.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 -----
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.cs(644,0): at System.Net.Http.CurlHandler.ThrowIfCURLEError(CURLcode error)
           /Users/dotnet-bot/j/workspace/dotnet_corefx/release_2.0.0/osx10.12_debug_prtest/src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.MultiAgent.cs(863,0): at System.Net.Http.CurlHandler.MultiAgent.FinishRequest(StrongToWeakReference`1 easyWrapper, CURLcode messageResult)

[CIPop]

@mmitche what are the specs of the machines OSX running on? (CPU/RAM) How many parallel instances of the tests are we running on them? What is the average CPU utilization when CI runs?

@stephentoub @karelz @steveharter Do we notice a lot of issues with other tests on the OSX machines caused by slowness?

@bartonjs - one of the threads failed to acquire the cert loading mutex in more than 30 seconds. Are there any known issues with the X509 components that could cause these kinds of delays?

The possible fixes would be to increase the timeout or exclude all other OSs from this workaround for Windows. I don't like either options as they just cover this real issue with either:

• My design of the cert loader code / mutex
• Infrastructure being very slow / machine running out of resources
• X509 having a problem
• Mutex / Threading having a problem

[mmitche]

@CIPop:

• IIRC, 16GB 4 core.
• Generally one, but a few nodes run 2.
• We probably run as many tests in parallel as there are CPUs, but that is controlled by the repo, not CI.
• I don't know average CPU utilization during the run.

[CIPop]

Thanks @mmitche: this doesn't sound like a resource issue.
I doubt this is my code since it runs fine on Windows and Linux.

@kouvel, @alexperovich, PTAL regarding a potential Mutex problem
@bartonjs, @steveharter PTAL regarding a potential X509 problem

[kouvel]

If the code in-between m.WaitOne() and m.ReleaseMutex() throws for some reason (in this run or a parallel one), then the mutex may remain locked until the process terminates. I don't see other failures in this run, but a thing to try could be to ignore AbandonedMutexException from the WaitOne() call, and use try/finally for the code in-between with ReleaseMutex() in the finally block. At least it may weed out side-effects of the actual failure, or it may indicate an actual problem in the mutex.

[CIPop]

Thanks @kouvel : I'll make a change to remove that possibility and crash the process immediately if any exception is thrown from the inner code or if we get an AbandonedMutexException.

[kouvel]

In the event of AbandonedMutexException being thrown, the lock is taken so it would still have to call ReleaseMutex before crashing, otherwise the "abandoned" state will be reinstated by this process since it will end up abandoning it upon termination. I think it's ok to ignore the exception, it's only an indication that someone else abandoned it, but is not relevant to this test run - the error should have already been reported on the other side.

[kouvel]

Also if the process is crashed without releasing the mutex and another process from a parallel test run has it open, the other process will get the abandoned mutex exception. Since this is a global mutex, crashing after release would be good I think.

[bartonjs]

Are there any known issues with the X509 components that could cause these kinds of delays?

Nope. We do quite a lot of wacky things in the X509 tests, and the whole library finishes in well less than 30 seconds. But 60 things running into a 0.5 second IO + cryptography operation means 30 seconds of wait.

[CIPop]

500ms seems a lot for disk I/O (the lock shouldn't be held by network I/O) but since we don't have more info I'll also increase the time to 1 minute.

[bartonjs]

@CIPop I don't actually have a 500ms data number, I was just pointing out that it could be that things are "just slow enough" that with enough queueing that things are going out of timing bounds.