인증서로 서명된 닷넷 어셈블리의 실행 지연 현상
인증 기관으로부터 받은 인증서로 signtool을 이용하여 서명한 닷넷 어셈블리를 실행하는 경우, 초기 실행 시간이 hang 현상에 가까운 이상 증상이 나타나는 컴퓨터가 있었습니다. 지금 와서야 '서명'되었다는 것을 인식할 수 있었을 뿐, 이 사실을 몰랐을 당시에는 특정 컴퓨터에서 닷넷 어셈블리의 실행이 무척 느리다는 것만 알 수 있었습니다.
뭐랄까... ^^; 그야말로 황당했지요.
최근에 그와 같은 '희귀 증상'을 나타내는 서버를 다시 발견할 수 있었고, 다행히 문제를 발견할 수 있도록 몇 가지 시도를 할 수 있어서 원인을 파악할 수 있었습니다. 처음엔 해당 컴퓨터의 환경을 살펴보았는데, 안티 바이러스 제품이 설치된 것만이 특이해서 '과거의 안 좋은 기억' 탓에 그 제품과의 간섭이 아닌가 의심을 했었습니다. 일단, 그 곳에서 당장 결론은 못 내고, 그 증상을 나타내는 서버로부터 닷넷 EXE 파일이 실행되어 '정지'되는 그 순간에 프로세스에 대한 Full Dump를 얻을 수 있었고 회사에 돌아와서 천천히 살펴보기 시작했습니다. (왜냐하면, 저는 windbg를 현란하게 다루는 수준...이 아닌 완전 초보자이기 때문입니다. ^^)
Windbg.exe를 실행하고, "File" / "Open Crash Dump..." 메뉴를 이용하여 덤프를 열고 심벌 파일을 로드합니다.
.reload -f
아직, 인증서 문제였는지 몰랐으므로 sos.dll을 로드했는데요. clrstack 명령어로는 아무것도 알아낼 수 없는 수준이었습니다.
.load C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\sos.dll
0:000> !clrstack
OS Thread Id: 0x27b0 (0)
ESP EIP
0012fa98 7c96860c [DebuggerClassInitMarkFrame: 0012fa98]
위의 결과가 무척 당황스러운데요. 덤프 파일을 가져와서 혼자서 보길 잘했다는 생각이 확 듭니다. ^^; sos.dll마저 도움이 안되는 환경이라늬!!! 절망스럽기까지 합니다.
혹시나 하는 마음에,,, 일단 스레드들의 상태를 확인해봐야 했습니다.
0:000> ~*k
. 0 Id: 980.27b0 Suspend: 0 Teb: 7ffdf000 Unfrozen
ChildEBP RetAddr
0012f000 7c967d29 ntdll!KiFastSystemCallRet
0012f004 7c821d1e ntdll!ZwWaitForSingleObject+0xc
0012f074 73b7790b kernel32!WaitForSingleObjectEx+0xac
0012f0a0 73b7485a cryptnet!CryptRetrieveObjectByUrlWithTimeout+0x12f
0012f0cc 73b737ce cryptnet!CryptRetrieveObjectByUrlW+0x9b
0012f144 73b74a60 cryptnet!RetrieveObjectByUrlValidForSubject+0x5b
0012f194 73b73525 cryptnet!RetrieveTimeValidObjectByUrl+0xbc
0012f1fc 73b73473 cryptnet!CTVOAgent::GetTimeValidObjectByUrl+0xc2
0012f2ac 73b73314 cryptnet!CTVOAgent::GetTimeValidObject+0x2f1
0012f2dc 73b72c00 cryptnet!FreshestCrlFromCrlGetTimeValidObject+0x2d
0012f320 73b743a4 cryptnet!CryptGetTimeValidObject+0x58
0012f37c 73b73122 cryptnet!GetTimeValidCrl+0x1e0
0012f3c0 73b73080 cryptnet!GetBaseCrl+0x34
0012f460 76069033 cryptnet!MicrosoftCertDllVerifyRevocation+0x128
0012f4f0 76068eef crypt32!I_CryptRemainingMilliseconds+0x21b
0012f560 7605f39f crypt32!CertVerifyRevocation+0xb7
0012f5e0 76056966 crypt32!CChainPathObject::CalculateRevocationStatus+0x1f2
0012f628 76056771 crypt32!CChainPathObject::CalculateAdditionalStatus+0x147
0012f6e4 760578bc crypt32!CCertChainEngine::CreateChainContextFromPathGraph+0x227
0012f714 7605783f crypt32!CCertChainEngine::GetChainContext+0x44
0012f73c 76ac6e1a crypt32!CertGetCertificateChain+0x60
0012f7a0 76ac6c47 wintrust!_WalkChain+0x1a8
0012f7dc 76ac3a6f wintrust!WintrustCertificateTrust+0xb7
0012f8d0 76ac3202 wintrust!_VerifyTrust+0x144
0012f8f4 64025c32 wintrust!WinVerifyTrust+0x4e
0012f998 7a0f0955 mscorsec!GetPublisher+0xe4
0012f9f0 79ea5249 mscorwks!PEFile::CheckSecurity+0x9a
0012fa18 79f06ed4 mscorwks!PEFile::PEFile+0x9b
0012fa48 79f07ec9 mscorwks!PEFile::Open+0x3f
0012ff18 79f07dc7 mscorwks!SystemDomain::ExecuteMainMethod+0xa9
0012ff68 79f05f61 mscorwks!ExecuteEXE+0x59
0012ffb0 79011b5f mscorwks!_CorExeMain+0x11b
0012ffc0 7c82f23b mscoree!_CorExeMain+0x2c
0012fff0 00000000 kernel32!BaseProcessStart+0x23
1 Id: 980.14d8 Suspend: 0 Teb: 7ffde000 Unfrozen
ChildEBP RetAddr
00abfe30 7c967d19 ntdll!KiFastSystemCallRet
00abfe34 7c82202c ntdll!NtWaitForMultipleObjects+0xc
00abfedc 7c822fbe kernel32!WaitForMultipleObjectsEx+0x11a
00abfef8 79ed4b06 kernel32!WaitForMultipleObjects+0x18
00abff58 79ed4a63 mscorwks!DebuggerRCThread::MainLoop+0xcf
00abff88 79ed49a6 mscorwks!DebuggerRCThread::ThreadProc+0xca
00abffb8 7c82482f mscorwks!DebuggerRCThread::ThreadProcStatic+0x82
00abffec 00000000 kernel32!BaseThreadStart+0x34
2 Id: 980.724 Suspend: 0 Teb: 7ffdd000 Unfrozen
ChildEBP RetAddr
00c7fc80 7c967d29 ntdll!KiFastSystemCallRet
00c7fc84 7c821d1e ntdll!ZwWaitForSingleObject+0xc
00c7fcf4 79e77fd1 kernel32!WaitForSingleObjectEx+0xac
00c7fd38 79e77f9a mscorwks!PEImage::LoadImage+0x199
00c7fd88 79e77f50 mscorwks!CLREvent::WaitEx+0x117
00c7fd98 79eb9a2d mscorwks!CLREvent::Wait+0x17
00c7fdb4 79ea2e68 mscorwks!WKS::WaitForFinalizerEvent+0x12d
00c7fdc8 79ecb4a4 mscorwks!WKS::GCHeap::FinalizerThreadWorker+0x75
00c7fdd8 79ecb442 mscorwks!Thread::UserResumeThread+0xfb
00c7fe6c 79ecb364 mscorwks!Thread::DoADCallBack+0x355
00c7fea8 79ed5e8b mscorwks!Thread::DoADCallBack+0x541
00c7fed0 79ed5e56 mscorwks!ManagedThreadBase_NoADTransition+0x32
00c7fedc 79ed6c0b mscorwks!ManagedThreadBase::FinalizerBase+0xb
00c7ff14 79ecb00b mscorwks!WKS::GCHeap::FinalizerThreadStart+0xbb
00c7ffb8 7c82482f mscorwks!Thread::intermediateThreadProc+0x49
00c7ffec 00000000 kernel32!BaseThreadStart+0x34
3 Id: 980.2a30 Suspend: 0 Teb: 7ffdc000 Unfrozen
ChildEBP RetAddr
00eafee4 7c967d19 ntdll!KiFastSystemCallRet
00eafee8 7c82202c ntdll!NtWaitForMultipleObjects+0xc
00eaff90 760443f9 kernel32!WaitForMultipleObjectsEx+0x11a
00eaffb8 7c82482f crypt32!ILS_WaitForThreadProc+0x2b
00eaffec 00000000 kernel32!BaseThreadStart+0x34
4 Id: 980.1954 Suspend: 0 Teb: 7ffdb000 Unfrozen
ChildEBP RetAddr
00fafcec 7c967d19 ntdll!KiFastSystemCallRet
00fafcf0 7c97c7be ntdll!NtWaitForMultipleObjects+0xc
00faffb8 7c82482f ntdll!RtlpWaitThread+0x161
00faffec 00000000 kernel32!BaseThreadStart+0x34
5 Id: 980.20e8 Suspend: 0 Teb: 7ffda000 Unfrozen
ChildEBP RetAddr
010afec0 7c967d19 ntdll!KiFastSystemCallRet
010afec4 7c82202c ntdll!NtWaitForMultipleObjects+0xc
010aff6c 7c822fbe kernel32!WaitForMultipleObjectsEx+0x11a
010aff88 75819e35 kernel32!WaitForMultipleObjects+0x18
010affb8 7c82482f userenv!NotificationThread+0x5f
010affec 00000000 kernel32!BaseThreadStart+0x34
6 Id: 980.2798 Suspend: 0 Teb: 7ffd9000 Unfrozen
ChildEBP RetAddr
011ce084 7c967d29 ntdll!KiFastSystemCallRet
011ce088 719d1af5 ntdll!ZwWaitForSingleObject+0xc
011ce0c4 719d1a03 mswsock!SockWaitForSingleObject+0x19d
011ce1b4 71ab283c mswsock!WSPSelect+0x380
011ce204 4ce1ed6b ws2_32!select+0xb9
011cea44 4ce1eeca winhttp!ICSocket::Connect_Start+0x3a8
011cea50 4ce19d7c winhttp!CFsm_SocketConnect::RunSM+0x42
011cea68 4ce19e16 winhttp!CFsm::Run+0x20
011cea8c 4ce1efc0 winhttp!DoFsm+0x2a
011cea9c 4ce1efdd winhttp!ICSocket::Connect+0x32
011ceab0 4ce2c264 winhttp!ICSocket::Connect+0x13
011ceaf8 4ce2c3ce winhttp!HTTP_REQUEST_HANDLE_OBJECT::OpenConnection_Fsm+0x43f
011ceb04 4ce19d7c winhttp!CFsm_OpenConnection::RunSM+0x37
011ceb1c 4ce19e16 winhttp!CFsm::Run+0x20
011ceb40 4ce2c44c winhttp!DoFsm+0x2a
011ceb50 4ce2e158 winhttp!HTTP_REQUEST_HANDLE_OBJECT::OpenConnection+0x2f
011ceb78 4ce2e451 winhttp!HTTP_REQUEST_HANDLE_OBJECT::MakeConnection_Fsm+0x9b
011ceb84 4ce19d7c winhttp!CFsm_MakeConnection::RunSM+0x37
011ceb9c 4ce19e16 winhttp!CFsm::Run+0x20
011cebc0 4ce2cc76 winhttp!DoFsm+0x2a
011cebf8 4ce2cea0 winhttp!HTTP_REQUEST_HANDLE_OBJECT::SendRequest_Fsm+0x8e
011cec04 4ce19d7c winhttp!CFsm_SendRequest::RunSM+0x37
011cec1c 4ce19e16 winhttp!CFsm::Run+0x20
011cec40 4ce27daa winhttp!DoFsm+0x2a
011cec60 4ce2831f winhttp!HTTP_REQUEST_HANDLE_OBJECT::HttpSendRequest_Start+0x2a4
011cec6c 4ce19d7c winhttp!CFsm_HttpSendRequest::RunSM+0x4c
011cec84 4ce19f13 winhttp!CFsm::Run+0x20
011ceccc 4ce10942 winhttp!StartFsmChain+0xd9
011ced10 4ce10c98 winhttp!HttpWrapSendRequest+0x199
011ced94 73b7c57a winhttp!WinHttpSendRequest+0x1ee
011cfe10 73b7c9f5 cryptnet!InetSendAuthenticatedRequestAndReceiveResponse+0x108
011cfeb4 73b75607 cryptnet!InetSendReceiveUrlRequest+0x1b0
011cfee4 73b72505 cryptnet!CInetSynchronousRetriever::RetrieveObjectByUrl+0x59
011cff20 73b721a8 cryptnet!InetRetrieveEncodedObject+0x66
011cff74 73b7768d cryptnet!CObjectRetrievalManager::RetrieveObjectByUrl+0xb1
011cffb8 7c82482f cryptnet!CryptRetrieveObjectByUrlWithTimeoutThreadProc+0x56
011cffec 00000000 kernel32!BaseThreadStart+0x34
7 Id: 980.2338 Suspend: 0 Teb: 7ffd8000 Unfrozen
ChildEBP RetAddr
0360ff7c 7c9677f9 ntdll!KiFastSystemCallRet
0360ff80 719d5914 ntdll!NtRemoveIoCompletion+0xc
0360ffb8 7c82482f mswsock!SockAsyncThread+0x69
0360ffec 00000000 kernel32!BaseThreadStart+0x34
8 Id: 980.f40 Suspend: 0 Teb: 7ffd7000 Unfrozen
ChildEBP RetAddr
0370e084 7c967d29 ntdll!KiFastSystemCallRet
0370e088 719d1af5 ntdll!ZwWaitForSingleObject+0xc
0370e0c4 719d1a03 mswsock!SockWaitForSingleObject+0x19d
0370e1b4 71ab283c mswsock!WSPSelect+0x380
0370e204 4ce1ed6b ws2_32!select+0xb9
0370ea44 4ce1eeca winhttp!ICSocket::Connect_Start+0x3a8
0370ea50 4ce19d7c winhttp!CFsm_SocketConnect::RunSM+0x42
0370ea68 4ce19e16 winhttp!CFsm::Run+0x20
0370ea8c 4ce1efc0 winhttp!DoFsm+0x2a
0370ea9c 4ce1efdd winhttp!ICSocket::Connect+0x32
0370eab0 4ce2c264 winhttp!ICSocket::Connect+0x13
0370eaf8 4ce2c3ce winhttp!HTTP_REQUEST_HANDLE_OBJECT::OpenConnection_Fsm+0x43f
0370eb04 4ce19d7c winhttp!CFsm_OpenConnection::RunSM+0x37
0370eb1c 4ce19e16 winhttp!CFsm::Run+0x20
0370eb40 4ce2c44c winhttp!DoFsm+0x2a
0370eb50 4ce2e158 winhttp!HTTP_REQUEST_HANDLE_OBJECT::OpenConnection+0x2f
0370eb78 4ce2e451 winhttp!HTTP_REQUEST_HANDLE_OBJECT::MakeConnection_Fsm+0x9b
0370eb84 4ce19d7c winhttp!CFsm_MakeConnection::RunSM+0x37
0370eb9c 4ce19e16 winhttp!CFsm::Run+0x20
0370ebc0 4ce2cc76 winhttp!DoFsm+0x2a
0370ebf8 4ce2cea0 winhttp!HTTP_REQUEST_HANDLE_OBJECT::SendRequest_Fsm+0x8e
0370ec04 4ce19d7c winhttp!CFsm_SendRequest::RunSM+0x37
0370ec1c 4ce19e16 winhttp!CFsm::Run+0x20
0370ec40 4ce27daa winhttp!DoFsm+0x2a
0370ec60 4ce2831f winhttp!HTTP_REQUEST_HANDLE_OBJECT::HttpSendRequest_Start+0x2a4
0370ec6c 4ce19d7c winhttp!CFsm_HttpSendRequest::RunSM+0x4c
0370ec84 4ce19f13 winhttp!CFsm::Run+0x20
0370eccc 4ce10942 winhttp!StartFsmChain+0xd9
0370ed10 4ce10c98 winhttp!HttpWrapSendRequest+0x199
0370ed94 73b7c57a winhttp!WinHttpSendRequest+0x1ee
0370fe10 73b7c9f5 cryptnet!InetSendAuthenticatedRequestAndReceiveResponse+0x108
0370feb4 73b75607 cryptnet!InetSendReceiveUrlRequest+0x1b0
0370fee4 73b72505 cryptnet!CInetSynchronousRetriever::RetrieveObjectByUrl+0x59
0370ff20 73b721a8 cryptnet!InetRetrieveEncodedObject+0x66
0370ff74 73b7768d cryptnet!CObjectRetrievalManager::RetrieveObjectByUrl+0xb1
0370ffb8 7c82482f cryptnet!CryptRetrieveObjectByUrlWithTimeoutThreadProc+0x56
0370ffec 00000000 kernel32!BaseThreadStart+0x34
오~~~ 그런데, 이게 웬일입니까! 소가 뒷걸음질치다 쥐(이 단어에서 오해 없으시기 바랍니다!)를 잡은 심정입니다.
대충 호출 스택을 보니, 윈도우가 닷넷 어셈블리의 서명을 확인하는 과정에서 hang이 발생했음을 짐작할 수 있게 합니다. 그러고 보니... 위의 현상이 나타났던 그 서버는 외부 접속이 안되는 환경이었습니다. (이 시점에서, 다시 생각이 바뀝니다. 현장에서 덤프 분석했어도 괜찮았을 텐데!)
그럼, 이 문제를 어떻게 해결해야 할까요? 원인 분석이 제대로 되었으니 나머지는 구글링을 통해서 쉽게 찾아볼 수 있었습니다.
Delay when starting up a web service
; http://consultingblogs.emc.com/anthonysteele/archive/2007/02/07/Delay-when-starting-up-a-web-service.aspx
Measurement Studio .NET Assemblies Take More Than 10 Seconds to Load at Run Time
; http://digital.ni.com/public.nsf/allkb/18e25101f0839c6286256f960061b282
어차피 외부 접속이 안되는 서버이니, 아예 CRL 체크를 해제해버리는 것도 방법일 수 있습니다.
아니면, 다음과 같이 app.config 파일의 내용을 변경해 주면 됩니다.
<configuration>
<runtime>
<generatePublisherEvidence enabled="false"/>
</runtime>
</configuration>
마지막으로,,, 흥미로운 점이 있다면 위의 환경에 대한 재현을 하는데 실패했다는 것입니다. 새로 윈도우 서버 2003 운영체제를 설치하고 인터넷 연결이 안된 상태에서 테스트를 해보았으나, hang 현상이 없었습니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]