FatalExecutionEngineError was detected
네이티브 응용 프로그램의 일부 버그들은, windbg를 이용해도 직접적인 해결을 할 수 없는 경우가 종종 있습니다. (물론, 제 실력이 없어서인 부분도 있겠지만. ^^)
최근에 발생한 사례를 하나 소개하자면.
새로운 기능을 추가한 이후 가끔 가다가, 다음과 같은 예외가 발생하면서 닷넷 프로그램이 비정상 종료하는 경우를 접하게 되었습니다.
FatalExecutionEngineError was detected
The runtime has encountered a fatal error. The address of the error was at 0x72c6a7c6, on thread 0x28d8. The error code is 0xc0000005. This error may be a bug in the CLR or in the unsafe or non-verifiable portions of user code. Common sources of this bug include user marshaling errors for COM-interop or PInvoke, which may corrupt the stack.
다행히 Visual Studio 디버깅 중에 발생했기 때문에 스레드 창을 통해 0x28d8번 스레드를 확인할 수 있었는데요. 애석하게도 콜스택도 없고 닷넷 Managed 스레드도 아니었습니다.
테스트 환경이 복합적으로 응용 프로그램에 들어가다 보니 3rd-party 라이브러리 업체의 버그가 아닌가... 하면서 무시하고 싶었습니다. 게다가 위의 그림에도 나오지만 MDA (Managed Debugging Assistant)로 인해 발생한 것이므로 때로는 오류가 아닌 것을 의심스러워 보고하는 경우도 있으므로 더욱 무시하려고 했습니다.
하지만... 초창기 시절만 그랬을 뿐 MDA가 상당히 제대로 된 오류를 짚어냈었던 점을 경험해 보았고, 적어도 문제가 다른 모듈에 의한 것임은 확실히 알아야겠다는 생각이 들어 덤프(.dmp) 파일을 남긴 후 windbg로 열어 문제의 스레드에 해당하는 콜스택을 조사해 보았습니다.
35 Id: 23d0.28d8 Suspend: 0 Teb: 002cb000 Unfrozen
# ChildEBP RetAddr Args to Child
WARNING: Stack unwind information not available. Following frames may be wrong.
00 0a8ac01c 7299cf87 000008e4 ffffffff 00000000 ntdll!ZwWaitForSingleObject+0xc
01 0a8ac04c 7299cfce 00000000 bfaa4303 00000000 clr!CLREventBase::Reset+0x145 (FPO: [Non-Fpo])
02 0a8ac09c 7299cf51 00000000 bfaa434b 000a1228 clr!CLREventBase::Reset+0x18d (FPO: [Non-Fpo])
03 0a8ac0d4 72a6b44a ffffffff 00000000 00000000 clr!CLREventBase::WaitEx+0x152 (FPO: [Non-Fpo])
04 0a8ac0ec 72c25081 ffffffff 00000000 00000000 clr!CLREventBase::Wait+0x1a (FPO: [3,0,0])
05 0a8ac158 72c25154 0a1f94b8 0a1f94b8 0a8ac184 clr!Thread::WaitSuspendEventsHelper+0x8a (FPO: [Non-Fpo])
06 0a8ac16c 72c23498 00000000 0a1f94c0 0a1f94b8 clr!Thread::WaitSuspendEvents+0x14 (FPO: [1,0,0])
07 0a8ac184 72b2459b bfaa420f 40000000 0a8ac1f4 clr!Thread::RareEnablePreemptiveGC+0x8e (FPO: [0,1,4])
08 0a8ac1d4 72e3d125 0644f3c0 72e3b5db bfaa4277 clr!Thread::RareDisablePreemptiveGC+0x102 (FPO: [0,13,0])
09 0a8ac1dc 72e3b5db bfaa4277 0a8acde0 729b9b6c clr!GCHolderEEInterface<0,1,1>::~GCHolderEEInterface<0,1,1>+0x25 (FPO: [0,0,4])
0a 0a8ac22c 72c9c08b 0a1f94b8 0a8ac498 0a8acde8 clr!Debugger::SendMDANotification+0x1aa (FPO: [6,13,0])
0b 0a8ac6c4 72c9bd1b bfaa4573 0a8acde8 0a8acde0 clr!MdaXmlMessage::SendDebugEvent+0x17f (FPO: [Non-Fpo])
0c 0a8ac6ec 72c9c3f0 bfaa4567 0a8af080 0a8acde0 clr!MdaXmlMessage::SendEvent+0x54 (FPO: [Non-Fpo])
0d 0a8acb44 72c9c26a bfaa48cf 72fde1c0 cccccccc clr!MdaXmlMessage::SendMessage+0x14c (FPO: [0,271,0])
0e 0a8acd80 72cce947 0a8acde0 0000192f 72c6a7c6 clr!MdaXmlMessage::SendMessagef+0x8e (FPO: [2,139,0])
0f 0a8ae1e4 72c41609 72c6a7c6 c0000005 bfaa6267 clr!MdaFatalExecutionEngineError::ReportFEEE+0x94 (FPO: [Non-Fpo])
10 0a8ae23c 72c3e73a 00000002 bfaa6fc7 80131506 clr!WatsonLastChance+0x369 (FPO: [1,13,0])
11 0a8aec58 72c3eb4e 00000000 0a8af080 0a8af1b4 clr!EEPolicy::LogFatalError+0x4d6 (FPO: [Non-Fpo])
12 0a8aefa0 72c43be0 00000000 0a8af080 0a8af080 clr!EEPolicy::HandleFatalError+0xf0 (FPO: [2,203,4])
13 0a8aefc0 72b13b46 bfaa6c6f 0a8af080 0a1f94b8 clr!CLRVectoredExceptionHandlerPhase3+0xe0 (FPO: [Non-Fpo])
14 0a8aeff0 72b13c6d bfaa7387 0a8af080 00000000 clr!CLRVectoredExceptionHandlerPhase2+0x20 (FPO: [Non-Fpo])
15 0a8af018 72b13d27 bfaa73fb 075ceb50 00000000 clr!CLRVectoredExceptionHandler+0xac (FPO: [Non-Fpo])
16 0a8af064 7757fe07 0a8af080 00000017 0a8af164 clr!CLRVectoredExceptionHandlerShim+0xce (FPO: [Non-Fpo])
17 0a8af0b4 77584136 00000000 00000017 0a1f94b8 ntdll!RtlLoadString+0x217
18 0a8af14c 77598e7f 0a8af164 0a8af1b4 0a8af164 ntdll!RtlUnwind+0x1b6
19 0a8af6fc 72c88305 bfaa74b3 0a4bde28 0c5ffdd8 ntdll!KiUserExceptionDispatcher+0xf
1a 0a8af72c 72cc0c1e bfaa74a7 0a4bde28 0000009f clr!ClassLoader::~ClassLoader+0x77 (FPO: [Non-Fpo])
1b 0a8af770 72c78844 0c2de730 bfaa7453 0a4bde28 clr!Assembly::Terminate+0x91 (FPO: [1,11,0])
1c 0a8af7cc 72c7b709 bfaa7447 076960f8 08baa040 clr!AppDomain::ShutdownAssemblies+0x49 (FPO: [Non-Fpo])
1d 0a8af80c 72c7aee3 bfaa7ba3 08baa040 08baa040 clr!AppDomain::Terminate+0x1b8 (FPO: [0,9,0])
1e 0a8af83c 72c7ade6 00000000 0a8af880 72c7f38d clr!AppDomain::~AppDomain+0xaf (FPO: [Non-Fpo])
1f 0a8af848 72c7f38d 00000001 00000000 72c825ef clr!AppDomain::`vector deleting destructor'+0xb (FPO: [Non-Fpo])
20 0a8af854 72c825ef bfaa7bff 72feebc8 80000000 clr!AppDomain::Release+0x1a (FPO: [0,0,4])
21 0a8af880 72b084d7 bfaa7abb 72b081b0 0a1f94b8 clr!SystemDomain::ClearCollectedDomains+0xa0 (FPO: [0,6,4])
22 0a8af924 72b0fcc9 ffffffff 00000000 00000000 clr!AppDomain::ADUnloadThreadStart+0x463 (FPO: [Non-Fpo])
23 0a8afa48 742838f4 088f01d0 742838d0 fe927f48 clr!Thread::intermediateThreadProc+0x4d (FPO: [Non-Fpo])
24 0a8afa5c 77585de3 088f01d0 d93121d9 00000000 kernel32!BaseThreadInitThunk+0x24 (FPO: [Non-Fpo])
25 0a8afaa4 77585dae ffffffff 775ab7ee 00000000 ntdll!RtlUnicodeStringToInteger+0x253
26 0a8afab4 00000000 72b0fc80 088f01d0 00000000 ntdll!RtlUnicodeStringToInteger+0x21e
사실, 저런 콜스택을 봤다고 해서 어떻게 직접적인 문제 해결을 할 수 있겠습니까? ^^
하지만 다행인 점은, '간접적'으로나마 문제에 대한 힌트를 얻을 수는 있습니다. 일단 MDA가 저 스레드에서 발생한 것은 콜 스택에 나오므로 저 스레드가 수행한 어떤 코드가 문제였음은 어느 정도 확신할 수 있습니다. 또한 더 좋은 힌트가 있는데요, 바로 AppDomain::ShutdownAssemblies가 있다는 것입니다.
저 콜스택을 보는 순간, 해당 문제가 AppDomain이 Recycle될 때 거의 매번 발생했다는 것을 인지하게 되었습니다. 덕분에 Recycle 테스트를 수행해 높은 확률로 예외가 발생하는 것으로 실제적인 '재현'을 할 수 있게 되었습니다.
재현이 된 순간, 거의 대부분의 버그는 잡은 것이나 다름없습니다.
이처럼, windbg로 문제를 (바로) 해결하는 것은 어렵지만 심심치 않게 그 원인에 대한 실마리를 잡을 수 있는 경우가 종종 있다는!!!
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]