A customer called in the other day and told me that his web application took a long time to start. My initial thought was (off course) that it was a matter of the classic slow-to start web services I’ve written about earlier.

(What to do about the slow startup of web services)

As I learned more about his problem I found that this was more than just a simple matter of pre-compilation and keeping your w3wp.exe alive.

The Cause

The customer was using authenticode signed assemblies in his web application. When that application calls the assembly for the first time it will want to go on-line and check that the certificate is still valid. So, what if this is an internal server with no Internet access? Well, then we have a problem. The process will spend quite some time trying to check the certificate revocation lists. Eventually it will give up, but for my customer this meant that it hung for at least 20 seconds upon startup.

The Resolution

To resolve this I’d chose one of the following three options:

Grant Internet access to the server

This is will obviously resolve the problem, but may not always be possible.

Review the need for Authenticode signing

If you own the assemblies then you might want to consider not using Authenticode signing at all. A Strong Named Assembly might be sufficient. For more information on Strong Named Assemblies and how to create them, please see the following article on MSDN: How to: Sign an Assembly with a Strong Name

Disable Signature Verification

If all else fails you can disable Signature Verification by adding the following to your machine.config or application.exe.config:

<configuration>
     <runtime>
           <generatepublisherevidence enabled="false" />
     </runtime>
</configuration>

Identifying the problem using windbg

Okay, so if we suspect that this is the problem, how can we verify this?

I got a memory dump from my customer, so I’ll use that to demonstrate.

First of all you want to make sure the dump is taken as the application pool hangs upon the first request. Getting a dump right after the problem has occurred will usually do us no good at all. We need to get the dump as the problem is actually ocurring. Having made sure the dump is fine I open up the dump in windbg and load sos.dll. I then use the !aspxpages command to see the pending requests currently on the server. !aspxpages dumps all the HttpContexts found on the heap so we get a list of all currently executing requests, as well as recently finished ones that haven’t been garbage collected yet.

0:000> .load C:\Windows\Microsoft.NET\Framework\v2.0.50727\sos.dll
0:000> !aspxpages
Going to dump the HttpContexts found in the heap.
Loading the heap objects into our cache.
HttpContext    Timeout  Completed     Running  ThreadId ReturnCode   Verb RequestPath+QueryString
0x01b41ad4        0            no        11 Sec     XXX        200       /App/
0x01b75f48      110 Sec        no        11 Sec     XXX        401   GET /App/Default.aspx
0x01b7eb40    19200 Sec        no        11 Sec      19        200   GET /App/Default.aspx
Total 3 HttpContext objects

So, the request on thread 19 is the one we want. As we can see in the ThreadId column it is the only active request. Let’s jump to that thread and investigate what it is doing.

0:000> ~19s
eax=01510000 ebx=00000000 ecx=03e2d348 edx=776d9a94 esi=03e2d07c edi=00000000
eip=776d9a94 esp=03e2d034 ebp=03e2d0a4 iopl=0         nv up ei ng nz ac pe cy
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000297
ntdll!KiFastSystemCallRet:
776d9a94 c3              ret
0:019> !clrstack
OS Thread Id: 0x11cc (19)
ESP       EIP    
03e2eb8c 776d9a94 [PrestubMethodFrame: 03e2eb8c] App.BasePage.Page_Load(System.Object, System.EventArgs)
03e2eba0 6aada7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
03e2ebb0 6c392594 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
03e2ebc4 6c38ba84 System.Web.UI.Control.OnLoad(System.EventArgs)
03e2ebd8 6c38bac3 System.Web.UI.Control.LoadRecursive()
03e2ebf0 6c387b74 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
03e2ed48 6c3877a4 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
03e2ed80 6c3876d1 System.Web.UI.Page.ProcessRequest()
03e2edb8 6c387666 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
03e2edc4 6c387642 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
03e2edd8 012b02a6 ASP.text.ProcessRequest(System.Web.HttpContext)
03e2ede8 6c38db16 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
03e2ee1c 6c36132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
03e2ee5c 6c95531f System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
03e2ee60 6c94b704 [InlinedCallFrame: 03e2ee60]
03e2ef00 6c93613d System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
03e2ef70 6ca0a7a2 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
03e2ef74 6ca0a58f [InlinedCallFrame: 03e2ef74]
03e2f4c8 01092314 [NDirectMethodFrameStandalone: 03e2f4c8] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
03e2f4d8 6ca0a839 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
03e2f55c 6ca0a58f System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
03e2f65c 01092314 [ContextTransitionFrame: 03e2f65c]

So we’re in the Page_Load event of the page in question, but apart from that !clrstack doesn’t tell us much. Let’s take a look at the native callstack instead using the kb-command.

0:019> kb20
ChildEBP RetAddr  Args to Child             
03e2d030 776d9254 76adc244 000006d8 00000000 ntdll!KiFastSystemCallRet
03e2d034 76adc244 000006d8 00000000 03e2d07c ntdll!ZwWaitForSingleObject+0xc
03e2d0a4 74256247 000006d8 00003a98 00000000 kernel32!WaitForSingleObjectEx+0xbe
03e2d0d8 74251f7c 0141f2e4 00000002 00202005 cryptnet!CryptRetrieveObjectByUrlWithTimeout+0x1a5
03e2d1c8 742527a1 0141f2e4 00000002 00202005 cryptnet!CryptRetrieveObjectByUrlW+0xcc
03e2d268 742591be 00000000 0141f2e4 00000002 cryptnet!RetrieveObjectByUrlValidForSubject+0xa0
03e2d2c8 74252556 00000000 00000000 00000001 cryptnet!RetrieveTimeValidObjectByUrl+0x15c
03e2d374 74253fc1 00000082 0141f2d8 00000000 cryptnet!CTVOAgent::GetTimeValidObjectByUrl+0x178
03e2d45c 74253d98 00000003 018aa590 00000002 cryptnet!CTVOAgent::GetTimeValidObject+0x4a8
03e2d48c 74253428 00000003 018aa590 018c8220 cryptnet!FreshestCrlFromCrlGetTimeValidObject+0x2d
03e2d4d0 74259283 00000003 018aa590 018c8220 cryptnet!CryptGetTimeValidObject+0x58
03e2d54c 74253b1c 00000003 018aa590 018aa590 cryptnet!GetTimeValidCrl+0x2cb
03e2d590 74253992 018aa590 018c8220 03e2d5c8 cryptnet!GetBaseCrl+0x34
03e2d63c 757f77d5 00000001 00000001 00000001 cryptnet!MicrosoftCertDllVerifyRevocation+0x163
03e2d6c8 757f7641 00000001 00000001 00000001 crypt32!I_CryptRemainingMilliseconds+0x2aa
03e2d74c 757f7a26 00000001 00000001 00000001 crypt32!CertVerifyRevocation+0xd4
03e2d7f8 757f7838 01899590 00000000 00000000 crypt32!CChainPathObject::CalculateRevocationStatus+0x2d0
03e2d83c 75806c44 01899590 018c3018 01870fc0 crypt32!CChainPathObject::CalculateAdditionalStatus+0x152
03e2d904 758069a5 01899590 018aa590 01870fc0 crypt32!CCertChainEngine::CreateChainContextFromPathGraph+0x23e
03e2d93c 7580be14 018aa590 018aff94 01870fc0 crypt32!CCertChainEngine::GetChainContext+0x46
03e2d974 749172ba 01421338 018aa590 018aff94 crypt32!CertGetCertificateChain+0x72
03e2d9dc 749170fc 40000001 00000000 03e2da10 wintrust!_WalkChain+0x1ae
03e2da18 7491363b 00000000 03e2dbdc 03e2db74 wintrust!WintrustCertificateTrust+0xb9
03e2db30 7491346c 00000000 03e2dbe4 00000000 wintrust!_VerifyTrust+0x253
03e2db54 64025b1b 00000000 03e2dbe4 03e2db74 wintrust!WinVerifyTrust+0x50
03e2dbf8 716b7f4d 014443f8 00000000 00000003 mscorsec!GetPublisher+0xe4
03e2dc50 7145ed3b d60caabc 0188c4a8 00603c48 mscorwks!PEFile::CheckSecurity+0xcb
03e2dc78 7145ec84 d60caa64 00000000 0188c4a8 mscorwks!PEAssembly::DoLoadSignatureChecks+0x3a
03e2dca0 7145f0ca 01879f00 00000000 0188c4a8 mscorwks!PEAssembly::PEAssembly+0x109
03e2df3c 7145f1c5 0188c4a8 00000000 00000000 mscorwks!PEAssembly::DoOpen+0x103
03e2dfd0 71459062 0188c4a8 00000000 00000000 mscorwks!PEAssembly::Open+0x79
03e2e134 71456ace 03e2e15c 00000001 00000000 mscorwks!AppDomain::BindAssemblySpec+0x247

Here we see that we’re currently trying to check the certificate revocation list. This is done on a separate thread so this thread is currently doing nothing but waiting. Our next step would be to find this thread, but first we can find out the name of the .dll that we’re trying to verify. Look at the first argument to GetPublisher.

0:019> du 014443f8
014443f8  "C:\Windows\Microsoft.NET\Framewo"
01444438  "rk\v2.0.50727\Temporary ASP.NET "
01444478  "Files\scstt\57ae16cd\2f8637d5\as"
014444b8  "sembly\dl3\078f3d05\00fba208_c03"
014444f8  "6ca01\Microsoft.Practices.Enterp"
01444538  "riseLibrary.Logging.DLL"

So it’s a Microsoft .dll that is part of the Enterprise Library. Good to know. Now let’s find the thread that is attempting to retrieve the revocation list by running ~*kb and scanning through the threads until we find this one:

0:021> kb2000
ChildEBP RetAddr  Args to Child             
0427d7f8 776d9254 75502283 0000070c 00000001 ntdll!KiFastSystemCallRet
0427d7fc 75502283 0000070c 00000001 0427d824 ntdll!ZwWaitForSingleObject+0xc
0427d83c 75501fc8 0000070c 00000714 00000001 mswsock!SockWaitForSingleObject+0x19f
0427d928 77801693 00000001 00000000 0427d9d0 mswsock!WSPSelect+0x38c
0427d9a8 72a733e5 00000001 00000000 0427d9d0 ws2_32!select+0x494
0427e1ec 72a730fd 00000714 0427e210 72a72e88 winhttp!ICSocket::Connect_Start+0x3b0
0427e1f8 72a72e88 01828250 72a737bc 00000000 winhttp!CFsm_SocketConnect::RunSM+0x42
0427e210 72a7382b 018b0c60 00000000 00000000 winhttp!CFsm::Run+0x20
0427e234 72a7467d 01828250 018ccf30 0427e258 winhttp!DoFsm+0x2a
0427e244 72a74646 0000ea60 00000005 00000020 winhttp!ICSocket::Connect+0x32
0427e258 72a742b5 0000ea60 00000005 0000ea60 winhttp!ICSocket::Connect+0x13
0427e2a4 72a74038 01434458 0427e2c8 72a72e88 winhttp!HTTP_REQUEST_HANDLE_OBJECT::OpenConnection_Fsm+0x471
0427e2b0 72a72e88 01434458 00000000 00000000 winhttp!CFsm_OpenConnection::RunSM+0x37
0427e2c8 72a7382b 018b0c60 00000000 00000000 winhttp!CFsm::Run+0x20
0427e2ec 72a74625 01434458 018ccf30 0427e324 winhttp!DoFsm+0x2a
0427e2fc 72a745bc 00000000 00000000 018b0c60 winhttp!HTTP_REQUEST_HANDLE_OBJECT::OpenConnection+0x2f
0427e324 72a74526 0141f638 0427e348 72a72e88 winhttp!HTTP_REQUEST_HANDLE_OBJECT::MakeConnection_Fsm+0x9b
0427e330 72a72e88 0141f638 00000000 00000000 winhttp!CFsm_MakeConnection::RunSM+0x37
0427e348 72a7382b 018b0c60 00000000 00000000 winhttp!CFsm::Run+0x20
0427e36c 72a743c1 0141f638 018b0c60 014343c0 winhttp!DoFsm+0x2a
0427e3ac 72a74339 014343c0 0427e3d0 72a72e88 winhttp!HTTP_REQUEST_HANDLE_OBJECT::SendRequest_Fsm+0x93
0427e3b8 72a72e88 014343c0 018ccf30 00000000 winhttp!CFsm_SendRequest::RunSM+0x37
0427e3d0 72a7382b 018b0c60 00000000 00000000 winhttp!CFsm::Run+0x20
0427e3f4 72a73db0 014343c0 018b0c60 01888820 winhttp!DoFsm+0x2a
0427e414 72a76f71 00000000 0427e438 72a72e88 winhttp!HTTP_REQUEST_HANDLE_OBJECT::HttpSendRequest_Start+0x2af
0427e420 72a72e88 01888820 00000001 00000000 winhttp!CFsm_HttpSendRequest::RunSM+0x4c
0427e438 72a73c3e 018b0c60 00000000 00000000 winhttp!CFsm::Run+0x20
0427e480 72a73b8b 01888820 018ccf30 00000000 winhttp!StartFsmChain+0xcf
0427e4c4 72a739d8 018ccf30 00000000 00000000 winhttp!HttpWrapSendRequest+0x18c
0427e544 742599b4 018ccf30 00000000 00000000 winhttp!WinHttpSendRequest+0x19b
0427f5e4 74259741 005f7bc0 018ccf30 01898e60 cryptnet!InetSendAuthenticatedRequestAndReceiveResponse+0x56f
0427f6ec 7425921d 005f7bc0 01898e60 00202005 cryptnet!InetSendReceiveUrlRequest+0x2c8
0427f724 742523e9 01898e60 00000002 00202005 cryptnet!CInetSynchronousRetriever::RetrieveObjectByUrl+0x5f
0427f75c 742521a8 01898e60 00000002 00202005 cryptnet!InetRetrieveEncodedObject+0x64
0427f7b8 74256350 01898e60 00000002 00202005 cryptnet!CObjectRetrievalManager::RetrieveObjectByUrl+0xbb
0427f810 76ad4911 00000000 0427f85c 776be4b6 cryptnet!CryptRetrieveObjectByUrlWithTimeoutThreadProc+0x67
0427f81c 776be4b6 01898db0 4e080acf 00000000 kernel32!BaseThreadInitThunk+0xe
0427f85c 776be489 742562f7 01898db0 ffffffff ntdll!__RtlUserThreadStart+0x23
0427f874 00000000 742562f7 01898db0 00000000 ntdll!_RtlUserThreadStart+0x1b
0:021> du 01898e60
01898e60  "http://crl.microsoft.com/pki/crl"
01898ea0  "/products/CodeSignPCA2.crl"

This is the thread. To finally verify that it is in fact attempting to download the Certificate Revocation List we can check the value of the first argument to cryptnet!CInetSynchronousRetriever, InetRetrieveEncodedObject and CObjectRetrievalManager::RetrieveObjectByUrl or the second argument to cryptnet!InetSendReceiveUrlRequest as I did above.

Conclusion

In this case the customer chose to disable Signature Verification completely rather than granting Internet access to the server.

If you found the windbg-portion of this post hard to understand I can recommend a closer look at my Debugging School (In the menu to the left). Begin with Getting started with windbg - Part I and you should be set to go in no time.

/ Johan