How to troubleshoot SSL\TSL or x509 Certificate Validation in .NET

Hello,

if your SSL\TLS connection does not work, or establishing is very slow and you don't know what to do, this post is for you. There is a lot of text and links, and no images. So, be strong.

In my case there was method that takes 15-30s to establish connection:

HttpWebRequest.GetRequestStream()

To troubleshoot this, or other SSL\TLS issue start with enabling network tracing in configuration file. You can do this just add next several lines to <configuration> section of your config file (How to: Configure Network Tracing):

<configuration>
  <system.diagnostics>
    <sources>
      <source name="System.Net" tracemode="includehex" maxdatasize="1024">
        <listeners>
          <add name="System.Net"/>
        </listeners>
      </source>
      <source name="System.Net.Sockets">
        <listeners>
          <add name="System.Net"/>
        </listeners>
      </source>
      <source name="System.Net.Cache">
        <listeners>
          <add name="System.Net"/>
        </listeners>
      </source>
    </sources>
    <switches>
      <add name="System.Net" value="Verbose"/>
      <add name="System.Net.Sockets" value="Verbose"/>
      <add name="System.Net.Cache" value="Verbose"/>
    </switches>
    <sharedListeners>
      <add name="System.Net"
        type="System.Diagnostics.TextWriterTraceListener"
        traceOutputOptions="DateTime, ProcessId, ThreadId, Callstack"
        initializeData="d:\temp\network.log"
      />
    </sharedListeners>
    <trace autoflush="true"/>
  </system.diagnostics>
</configuration>

Please note traceOutputOptions attribute, it is very useful. Full list of options available on MSDN.
If you troubleshoot on production environment, do not forget to turn off logging after you reproduce the error. Now analyse your log file. For example I found next few lines:

System.Net Verbose: 0 : [28516] HttpWebRequest#21454193::GetRequestStream()
    DateTime=2012-05-23T15:10:23.9141803Z
    Timestamp=289843104974
System.Net Error: 0 : [28516] Can't retrieve proxy settings for  Uri 'https://www.example.com/tempuri/default.asx?a=1'. Error code: 12180.
    DateTime=2012-05-23T15:10:26.5350475Z
    Timestamp=289849567756

It takes 2sec to find proxy. But since I have no proxy, I disabled it for application. Just add to the <configuration> section next few lines:

<system.net> 
 <defaultProxy enabled="false" useDefaultCredentials="false"> 
  <proxy/> 
  <bypasslist/> 
  <module/> 
 </defaultProxy> 
</system.net> 

Next interesting thing (warning: a lot of chars, stacktrace included):

System.Net Information: 0 : [16392] SecureChannel#28372289 - We have user-provided certificates. The server has specified 4 issuer(s). Looking for certificates that match any of the issuers.
    DateTime=2012-05-23T15:33:20.3010355Z
    Callstack=   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at System.Diagnostics.TraceEventCache.get_Callstack()
   at System.Diagnostics.TraceListener.WriteFooter(TraceEventCache eventCache)
   at System.Diagnostics.TraceSource.TraceEvent(TraceEventType eventType, Int32 id, String message)
   at System.Net.Logging.PrintLine(TraceSource traceSource, TraceEventType eventType, Int32 id, String msg)
   at System.Net.Logging.PrintInfo(TraceSource traceSource, Object obj, String msg)
   at System.Net.Security.SecureChannel.AcquireClientCredentials(Byte[]& thumbPrint)
   at System.Net.Security.SecureChannel.GenerateToken(Byte[] input, Int32 offset, Int32 count, Byte[]& output)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ForceAuthentication(Boolean receiveFirst, Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessAuthentication(LazyAsyncResult lazyResult)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean ignoreSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Net.TlsStream.ProcessAuthentication(LazyAsyncResult result)
   at System.Net.TlsStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.PooledStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.ConnectStream.WriteHeaders(Boolean async)
   at System.Net.HttpWebRequest.EndSubmitRequest()
   at System.Net.Connection.CompleteConnection(Boolean async, HttpWebRequest request)
   at System.Net.Connection.CompleteStartConnection(Boolean async, HttpWebRequest httpWebRequest)
   at System.Net.Connection.CompleteStartRequest(Boolean onSubmitThread, HttpWebRequest request, TriState needReConnect)
   at System.Net.Connection.SubmitRequest(HttpWebRequest request, Boolean forcedsubmit)
   at System.Net.ServicePoint.SubmitRequest(HttpWebRequest request, String connName)
   at System.Net.HttpWebRequest.SubmitRequest(ServicePoint servicePoint)
   at System.Net.HttpWebRequest.GetRequestStream(TransportContext& context)
   at System.Net.HttpWebRequest.GetRequestStream()
   at TestConnection.Program.Main(String[] args)
System.Net Information: 0 : [16392] SecureChannel#28372289 - Selected certificate: [Version]
  V3
[Subject]
-------------------------------- CERTIFICATE DETAILS ------------------------------------
    DateTime=2012-05-23T15:33:35.3242207Z
    Callstack=   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at System.Diagnostics.TraceEventCache.get_Callstack()
   at System.Diagnostics.TraceListener.WriteFooter(TraceEventCache eventCache)
   at System.Diagnostics.TraceSource.TraceEvent(TraceEventType eventType, Int32 id, String message)
   at System.Net.Logging.PrintLine(TraceSource traceSource, TraceEventType eventType, Int32 id, String msg)
   at System.Net.Logging.PrintInfo(TraceSource traceSource, Object obj, String msg)
   at System.Net.Security.SecureChannel.AcquireClientCredentials(Byte[]& thumbPrint)
   at System.Net.Security.SecureChannel.GenerateToken(Byte[] input, Int32 offset, Int32 count, Byte[]& output)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessReceivedBlob(Byte[] buffer, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartReceiveBlob(Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.StartSendBlob(Byte[] incoming, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ForceAuthentication(Boolean receiveFirst, Byte[] buffer, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.ProcessAuthentication(LazyAsyncResult lazyResult)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean ignoreSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Net.TlsStream.ProcessAuthentication(LazyAsyncResult result)
   at System.Net.TlsStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.PooledStream.Write(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.ConnectStream.WriteHeaders(Boolean async)
   at System.Net.HttpWebRequest.EndSubmitRequest()
   at System.Net.Connection.CompleteConnection(Boolean async, HttpWebRequest request)
   at System.Net.Connection.CompleteStartConnection(Boolean async, HttpWebRequest httpWebRequest)
   at System.Net.Connection.CompleteStartRequest(Boolean onSubmitThread, HttpWebRequest request, TriState needReConnect)
   at System.Net.Connection.SubmitRequest(HttpWebRequest request, Boolean forcedsubmit)
   at System.Net.ServicePoint.SubmitRequest(HttpWebRequest request, String connName)
   at System.Net.HttpWebRequest.SubmitRequest(ServicePoint servicePoint)
   at System.Net.HttpWebRequest.GetRequestStream(TransportContext& context)
   at System.Net.HttpWebRequest.GetRequestStream()
   at TestConnection.Program.Main(String[] args)

You can see 15sec gap here. Now I suggest you to enable .NET source debugging. Also there is a big chanses that PDBs on MS Source Server are of different version of .NET, so you can use Reflector with VS Addin, to generate PDBs of neccessary DLLs. After that done, you can start debugging and dig into depth of .NET. You should be interested in (see line 70 on log dump above):

SecureChannel.AcquireClientCredentials()

After analysing that method you can find call to:

X509Chain.Build()

This method internally calls Windows Crypto API, function CertGetCertificateChain:

if (!CAPISafe.CertGetCertificateChain(hChainEngine, pCertContext, ref pTime, invalidHandle, ref cert_chain_para, dwFlags, IntPtr.Zero, ref ppChainContext))

That is defined as:

[DllImport("crypt32.dll", CharSet = CharSet.Auto, SetLastError = true)] 
internal static extern bool CertGetCertificateChain([In] IntPtr hChainEngine, [In] SafeCertContextHandle pCertContext, [In] ref System.Runtime.InteropServices.ComTypes.FILETIME pTime, [In] SafeCertStoreHandle hAdditionalStore, [In] ref CAPIBase.CERT_CHAIN_PARA pChainPara, [In] uint dwFlags, [In] IntPtr pvReserved, [In, Out] ref SafeCertChainHandle ppChainContext);

This function, among other certificate checks, performs check of every certificate in the chain to see if it was revoked. In order to check the current revocation status, it needs up-to-date information from a CRL or an OCSP responder. If the correct CRL isn't provided explicitly during the setup of the path validation request, it can try to fetch it (usually over the Internet) if a URL for the CRL is listed in the "CRL Distribution Points" extension.
This can take some time if network connection is slow, the path is long, or the CRLs are large.
Alternatively, it might automatically contact an OCSP responder if it is advertised in the "Authority Information Access" extension.

* Description above, about CRL and OCSP was taken from answer to my question on stackoverflow. Answer was written by Erikson. Thank you very much!

You can try to disable CRL and OCSP checks in several ways (but it is not recommended):

1. In configuration file, <configuration> section add (KB936707):
   

   <runtime> 
     <generatePublisherEvidence enabled="false"/> 
   </runtime>
   

2. Machine-wide: Control Panel -> Internet Options -> Advanced -> under Security tab, uncheck the "Check for publisher's certificate revocation option" (EricLaw's IEInternals)
3. In registry (there is Windows API function for that WintrustSetRegPolicyFlags):
   

   [HKEY_USERS\S-1-5-20\Software\Microsoft\Windows\CurrentVersion\WinTrust\Trust Providers\Software Publishing] "State"=dword:00023e00
   

I tried all mentioned variants, but still had delays. So I go to Event log and enabled CAPI2 logging. You can read how to do it on the Windows PKI blog. And after all the investigations I found several Error entries with message:

<CryptRetrieveObjectByUrlWire>
  <URL scheme="http">http://www.download.windowsupdate.com/msdownload/update/v3/static/trustedr/en/authrootstl.cab</URL> 
  <Object type="Blob" constant="0" /> 
  <Timeout>PT15S</Timeout> 
  <Flags value="205004" CRYPT_WIRE_ONLY_RETRIEVAL="true" CRYPT_STICKY_CACHE_RETRIEVAL="true" CRYPT_OFFLINE_CHECK_RETRIEVAL="true" CRYPT_PROXY_CACHE_RETRIEVAL="true" /> 
  <AdditionalInfo>
    <Action name="NetworkRetrievalTimeout">
      <Error value="5B4">This operation returned because the timeout period expired.</Error> 
    </Action>
  </AdditionalInfo>
  <EventAuxInfo ProcessName="TestConnection.exe" /> 
  <CorrelationAuxInfo TaskId="{D8E01E93-CCAB-41C8-B227-08F5A838B72D}" SeqNumber="8" /> 
  <Result value="5B4">This operation returned because the timeout period expired.</Result> 
</CryptRetrieveObjectByUrlWire>

Wow! Application tries to download Certificate Trust List and seems like it is strict FW rules that denies access to Windows Update site. So I enabled access to all URLs that I found in CAPI2 event logs. To recheck and find list of possible IPs, you can use Process Explorer from Mark Russinovich, Sysinternals. Just open properties of your process, go to TCP\IP tab, and initiate certificate check.

That's it, it was a long jorney.. BTW, depending on your certificates and FW rules, you can check next URLs:

• http://crl.verisign.com
• http://crl.microsoft.com
• http://www.microsoft.com
• http://www.download.windowsupdate.com

Hope this blog post saves your time and money :)