Crash Dump Analysis Patterns (Part 9c)

Article
09/18/2008

번역: 김희준 (Heejune Kim, drost@naver.com, https://insidekernel.net)

작성일자: 2007-10-17

이번에는 이벤트와 크리티컬 섹션과 같은 동기화 객체들이 함께 섞여서 사용된 데드락 패턴의 다른 변형된 버전입니다. 이벤트는 큐에 데이터가 있어서 work item을 처리 가능하다는 상황을 알릴 때 사용할 수 있고, 크리티컬 섹션은 공유 데이터를 보호하기 위해서 사용할 수 있습니다.

전형적인 데드락 시나리오는 다음과 같습니다. 하나의 스레드가 WaitForSingleObject를 호출해서 이벤트를 reset 하고, 크리티컬 섹션을 얻으려고 시도합니다. 그와 동시에 그 크리티컬 섹션을 이미 소유하고 있는 두번째 스레드가 그 이벤트가 set 되어지기를 기다립니다:

Thread A     | Thread B
      ..           | ..
reset Event | ..
      ..           | acquire CS
wait for CS | ..
                   | wait for Event

이 버그를 수정하려면 두 스레드에서 크리티컬 섹션을 얻고 이벤트를 기다리는 것을 동일한 순서로 해야 합니다.

우리의 크래쉬 덤프 예제에서는 크리티컬 섹션을 얻었고 이벤트 0x480을 기다리고 있는 두번째 스레드를 손쉽게 찾아낼 수 있습니다:

0:000> !locks

CritSec ntdll!LdrpLoaderLock+0 at 7c889d94
WaiterWoken        No
LockCount          9
RecursionCount     1
OwningThread       2038
EntryCount         0
ContentionCount    164
*** Locked

13 Id: 590.2038 Suspend: 1 Teb: 7ffaa000 Unfrozen
ChildEBP RetAddr Args to Child
0483fd5c 7c822124 77e6bad8 00000480 00000000 ntdll!KiFastSystemCallRet
0483fd60 77e6bad8 00000480 00000000 00000000 ntdll!NtWaitForSingleObject+0xc
0483fdd0 77e6ba42 00000480 ffffffff 00000000 kernel32!WaitForSingleObjectEx+0xac
0483fde4 776cfb30 00000480 ffffffff 777904f8 kernel32!WaitForSingleObject+0×12
0483fe00 776adfaa 00000480 00000000 00000080 ole32!CDllHost::ClientCleanupFinish+0×2a
0483fe2c 776adf1a 00000000 0483fe7c 77790828 ole32!DllHostProcessUninitialize+0×80
0483fe4c 776b063f 00000000 00000000 0c9ecee0 ole32!ApartmentUninitialize+0xf8
0483fe64 776b06e3 0483fe7c 00000000 00000001 ole32!wCoUninitialize+0×48
0483fe80 776e43f5 00000001 77670000 776afef0 ole32!CoUninitialize+0×65
0483fe8c 776afef0 0483feb4 776b5cb8 77670000 ole32!DoThreadSpecificCleanup+0×63
0483fe94 776b5cb8 77670000 00000003 00000000 ole32!ThreadNotification+0×37
0483feb4 776b5c1b 77670000 00000003 00000000 ole32!DllMain+0×176
0483fed4 7c82257a 77670000 00000003 00000000 ole32!_DllMainCRTStartup+0×52
0483fef4 7c83c195 776b5bd3 77670000 00000003 ntdll!LdrpCallInitRoutine+0×14
0483ffa8 77e661d6 00000000 00000000 0483ffec ntdll!LdrShutdownThread+0xd2
0483ffb8 77e66090 00000000 00000000 00000000 kernel32!ExitThread+0×2f
0483ffec 00000000 77c5de6d 0ab24f68 00000000 kernel32!BaseThreadStart+0×39

0:000> !handle 480 ff
Handle 00000480
Type          Event
Attributes    0
GrantedAccess 0×1f0003:
         Delete,ReadControl,WriteDac,WriteOwner,Synch
         QueryState,ModifyState
HandleCount   2
PointerCount 4
Name          <none>
No object specific information available

그러나 이벤트를 reset하였고 크리티컬 섹션을 기다리고 있는 첫번째 스레드를 찾아내는 것은 어렵습니다. 우리의 덤프 예제에서는 !locks 명령어를 쳤을 때 9개의 스레드가 나왔습니다:

LockCount 9

동기화 객체(primitive)인 이벤트는 owner(소유자)를 갖지 않습니다. 그럼에도 불구하고 만약 데이터가 덮어 쓰여지지 않았다면 다른 스레드 raw 스택에서 0x480과 WaitForSingleObject 주소 근처를 찾아볼 수 있습니다. 메모리 검색을 한번 해봅시다:

0:000> s -d 0 L4000000 00000480
000726ec 00000480 00000022 000004a4 00000056
008512a0 00000480 00000480 00000000 00000000
008512a4 00000480 00000000 00000000 01014220
0085ab68 00000480 00000480 00000092 00000000
0085ab6c 00000480 00000092 00000000 01014234
00eb12a0 00000480 00000480 00000000 00000000
00eb12a4 00000480 00000000 00000000 0101e614
00ebeb68 00000480 00000480 00000323 00000000
00ebeb6c 00000480 00000323 00000000 0101e644
03ffb4fc 00000480 d772c13b ce753966 00fa840f
040212a0 00000480 00000480 00000000 00000000
040212a4 00000480 00000000 00000000 01063afc
0402ab68 00000480 00000480 00000fb6 00000000
0402ab6c 00000480 00000fb6 00000000 01063b5c
041312a0 00000480 00000480 00000000 00000000
041312a4 00000480 00000000 00000000 01065b28
0413eb68 00000480 00000480 00001007 00000000
0413eb6c 00000480 00001007 00000000 01065b7c
043412a0 00000480 00000480 00000000 00000000
043412a4 00000480 00000000 00000000 01066b44
0434ab68 00000480 00000480 00001033 00000000
0434ab6c 00000480 00001033 00000000 01066b9c
0483fd68 00000480 00000000 00000000 00000000
0483fdd8 00000480 ffffffff 00000000 0483fe00
0483fdec 00000480 ffffffff 777904f8 77790738
0483fe08 00000480 00000000 00000080 776b0070
0483fe20 00000480 00000000 00000000 0483fe4c
05296f58 00000480 ffffffff ffffffff ffffffff
05297eb0 00000480 00000494 000004a4 000004c0
0557cf9c 00000480 00000000 00000000 00000000
05580adc 00000480 00000000 00000000 00000000
0558715c 00000480 00000000 00000000 00000000
0558d3cc 00000480 00000000 00000000 00000000
0559363c 00000480 00000000 00000000 00000000
0559ee0c 00000480 00000000 00000000 00000000
055a507c 00000480 00000000 00000000 00000000
056768ec 00000480 00000000 00000000 00000000
0568ef14 00000480 00000000 00000000 00000000
0581ff88 00000480 07ca7ee0 0581ff98 776cf2a3
05ed1260 00000480 00000480 00000000 00000000
05ed1264 00000480 00000000 00000000 01276efc
05ed8b68 00000480 00000480 00005c18 00000000
05ed8b6c 00000480 00005c18 00000000 01276f74
08f112a0 00000480 00000480 00000000 00000000
08f112a4 00000480 00000000 00000000 00000000
08f1ab68 00000480 00000480 00007732 00000000
08f1ab6c 00000480 00007732 00000000 01352db0

파란색으로 강조한 부분이 스레드 #13의 raw 스택이고, 붉은색으로 강조한 부분이 다른 스레드 raw 스택에 속한 메모리 영역들입니다. 사실 이 부분들이 검색결과에서 코드와 연관되어 있다고 볼 수 있는 유일한 메모리 영역입니다. 의미 있는 스택 trace는 위에서 파란색과 붉은색으로 강조한 메모리 영역 뿐입니다.

WinDbg의 dds 명령을 실행한 결과에서도 이 내용을 찾아 볼 수 있습니다(간결을 위해서 부분 생략):

0:000> .foreach (place { s-[1]d 0 L4000000 00000480 }) { dds place -30; .printf "\n" }
000726bc 00000390
000726c0 00000022
000726c4 000003b4
000726c8 00000056
000726cc 00000004
000726d0 6dc3f6fd
000726d4 0000040c
000726d8 0000001e
000726dc 0000042c
000726e0 00000052
000726e4 00000004
000726e8 eacb0f6d
000726ec 00000480
000726f0 00000022
000726f4 000004a4
000726f8 00000056
000726fc 00000004
00072700 62b796d2
00072704 000004fc
00072708 0000001e
0007270c 0000051c
00072710 00000052
00072714 00000004
00072718 2a615cff
0007271c 00000570
00072720 00000024
00072724 00000598
00072728 00000058
0007272c 00000004
00072730 51913e59
00072734 000005f0
00072738 00000016
...
...
...
0568eee4 05680008 xpsp2res+0x1b0008
0568eee8 01200000
0568eeec 00001010
0568eef0 00200001
0568eef4 00000468
0568eef8 00000121
0568eefc 00000000
0568ef00 00000028
0568ef04 00000030
0568ef08 00000060
0568ef0c 00040001
0568ef10 00000000
0568ef14 00000480
0568ef18 00000000
0568ef1c 00000000
0568ef20 00000000
0568ef24 00000000
0568ef28 00000000
0568ef2c 00800000
0568ef30 00008000
0568ef34 00808000
0568ef38 00000080
0568ef3c 00800080
0568ef40 00008080
0568ef44 00808080
0568ef48 00c0c0c0
0568ef4c 00ff0000
0568ef50 0000ff00
0568ef54 00ffff00
0568ef58 000000ff
0568ef5c 00ff00ff
0568ef60 0000ffff

0581ff58 0581ff70
0581ff5c 776b063f ole32!wCoUninitialize+0x48
0581ff60 00000001
0581ff64 00007530
0581ff68 77790438 ole32!gATHost
0581ff6c 00000000
0581ff70 0581ff90
0581ff74 776cf370 ole32!CDllHost::WorkerThread+0xdd
0581ff78 0581ff8c
0581ff7c 00000001
0581ff80 77e6ba50 kernel32!WaitForSingleObjectEx
0581ff84 0657cfe8
0581ff88 00000480
0581ff8c 07ca7ee0
0581ff90 0581ff98
0581ff94 776cf2a3 ole32!DLLHostThreadEntry+0xd
0581ff98 0581ffb8
0581ff9c 776b2307 ole32!CRpcThread::WorkerLoop+0×1e
0581ffa0 77790438 ole32!gATHost
0581ffa4 00000000
0581ffa8 0657cfe8
0581ffac 77670000 ole32!_imp__InstallApplication <PERF> (ole32+0×0)
0581ffb0 776b2374 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0×20
0581ffb4 00000000
0581ffb8 0581ffec
0581ffbc 77e6608b kernel32!BaseThreadStart+0×34
0581ffc0 0657cfe8
0581ffc4 00000000
0581ffc8 00000000
0581ffcc 0657cfe8
0581ffd0 3cfb5963
0581ffd4 0581ffc4

05ed1230 0101f070
05ed1234 05ed1274
05ed1238 05ed1174
05ed123c 05ed0000
05ed1240 05ed1280
05ed1244 00000000
05ed1248 00000000
05ed124c 00000000
05ed1250 05ed8b80
05ed1254 05ed8000
05ed1258 00002000
05ed125c 00001000
05ed1260 00000480
05ed1264 00000480
05ed1268 00000000
05ed126c 00000000
05ed1270 01276efc
05ed1274 05ed12b4
05ed1278 05ed1234
05ed127c 05ed0000
05ed1280 05ed2d00
05ed1284 05ed1240
05ed1288 05ed1400
05ed128c 00000000
05ed1290 05edade0
05ed1294 05eda000
05ed1298 00002000
05ed129c 00001000
05ed12a0 00000220
05ed12a4 00000220
05ed12a8 00000000
05ed12ac 00000000
...
...
...
08f1ab3c 00000000
08f1ab40 00000000
08f1ab44 00000000
08f1ab48 00000000
08f1ab4c 00000000
08f1ab50 00000000
08f1ab54 00000000
08f1ab58 00000000
08f1ab5c 00000000
08f1ab60 abcdbbbb
08f1ab64 08f11000
08f1ab68 00000480
08f1ab6c 00000480
08f1ab70 00007732
08f1ab74 00000000
08f1ab78 01352db0
08f1ab7c dcbabbbb
08f1ab80 ffffffff
08f1ab84 c0c00ac1
08f1ab88 00000000
08f1ab8c c0c0c0c0
08f1ab90 c0c0c0c0
08f1ab94 c0c0c0c0
08f1ab98 c0c0c0c0
08f1ab9c c0c0c0c0
08f1aba0 c0c0c0c0
08f1aba4 ffffffff
08f1aba8 c0c00ac1
08f1abac 00000000
08f1abb0 c0c0c0c0
08f1abb4 c0c0c0c0
08f1abb8 c0c0c0c0

주소 0581ff88이 가장 의미 있는 주소이고 또한 근처에 WaitForSingleObjectEx를 가지고 있음을 볼 수 있습니다. 이 주소는 아래 스레드 #16의 raw stack에 속합니다:

16 Id: 590.1a00 Suspend: 1 Teb: 7ffa9000 Unfrozen
ChildEBP RetAddr
0581fc98 7c822124 ntdll!KiFastSystemCallRet
0581fc9c 7c83970f ntdll!NtWaitForSingleObject+0xc
0581fcd8 7c839620 ntdll!RtlpWaitOnCriticalSection+0x19c
0581fcf8 7c83a023 ntdll!RtlEnterCriticalSection+0xa8
0581fe00 77e67bcd ntdll!LdrUnloadDll+0x35
0581fe14 776b46fb kernel32!FreeLibrary+0x41
0581fe20 776b470f ole32!CClassCache::CDllPathEntry::CFinishObject::Finish+0x2f
0581fe34 776b44a0 ole32!CClassCache::CFinishComposite::Finish+0x1d
0581ff0c 776b0bfd ole32!CClassCache::CleanUpDllsForApartment+0x1d0
0581ff38 776b0b1f ole32!FinishShutdown+0xd7
0581ff58 776b063f ole32!ApartmentUninitialize+0x94
0581ff70 776cf370 ole32!wCoUninitialize+0x48
0581ff90 776cf2a3 ole32!CDllHost::WorkerThread+0xdd
0581ff98 776b2307 ole32!DLLHostThreadEntry+0xd
0581ffac 776b2374 ole32!CRpcThread::WorkerLoop+0×1e
0581ffb8 77e6608b ole32!CRpcThreadCache::RpcWorkerThreadEntry+0×20
0581ffec 00000000 kernel32!BaseThreadStart+0×34

그리고 검색 결과의 스택 Trace와 raw 스택 데이터 양쪽의 WaitForSingleObjectEx 아래에서 찾을 수 있는 ole32!CRpcThread::WorkerLoop 함수를 디어셈블하면 실제로 함수를 호출한 이전의 함수를 볼 수 있다.

0:000> uf ole32!CRpcThread::WorkerLoop
ole32!CRpcThread::WorkerLoop:
776b22e9 mov     edi,edi
776b22eb push    esi
776b22ec mov     esi,ecx
776b22ee cmp     dword ptr [esi+4],0
776b22f2 jne     ole32!CRpcThread::WorkerLoop+0x67 (776b234d)

ole32!CRpcThread::WorkerLoop+0xb:
776b22f4 push    ebx
776b22f5 push    edi
776b22f6 mov edi,dword ptr [ole32!_imp__WaitForSingleObjectEx (77671304)]
776b22fc mov     ebx,7530h

ole32!CRpcThread::WorkerLoop+0x18:
776b2301 push    dword ptr [esi+0Ch]
776b2304 call    dword ptr [esi+8]
776b2307 call    dword ptr [ole32!_imp__GetCurrentThread (7767130c)]
776b230d push    eax
776b230e call    dword ptr [ole32!_imp__RtlCheckForOrphanedCriticalSections (77671564)]
776b2314 xor     eax,eax
776b2316 cmp     dword ptr [esi],eax
776b2318 mov     dword ptr [esi+8],eax
776b231b mov     dword ptr [esi+0Ch],eax
776b231e je      ole32!CRpcThread::WorkerLoop+0x65 (776b234b)

ole32!CRpcThread::WorkerLoop+0x37:
776b2320 push    esi
776b2321 mov     ecx,offset ole32!gRpcThreadCache (7778fc28)
776b2326 call    ole32!CRpcThreadCache::AddToFreeList (776de78d)

ole32!CRpcThread::WorkerLoop+0x55:
776b232b push 0
776b232d push ebx
776b232e push dword ptr [esi]
776b2330 call edi
776b2332 test eax,eax
776b2334 je ole32!CRpcThread::WorkerLoop+0×60 (776cf3be)

ole32!CRpcThread::WorkerLoop+0x44:
776b233a push    esi
776b233b mov     ecx,offset ole32!gRpcThreadCache (7778fc28)
776b2340 call    ole32!CRpcThreadCache::RemoveFromFreeList (776e42de)
776b2345 cmp     dword ptr [esi+4],0
776b2349 je      ole32!CRpcThread::WorkerLoop+0x55 (776b232b)

ole32!CRpcThread::WorkerLoop+0x65:
776b234b pop edi
776b234c pop ebx

ole32!CRpcThread::WorkerLoop+0x67:
776b234d pop esi
776b234e ret

ole32!CRpcThread::WorkerLoop+0x60:
776cf3be cmp dword ptr [esi+4],eax
776cf3c1 je ole32!CRpcThread::WorkerLoop+0x18 (776b2301)

ole32!CRpcThread::WorkerLoop+0x69:
776cf3c7 jmp ole32!CRpcThread::WorkerLoop+0x65 (776b234b)

따라서 우리는 스레드#16이 WaitForSingleObjectEx를 호출함으로써 이벤트를 reset했고 크리티컬 섹션을 얻으려 했다는 것을 확인할 수 있다. 또한 두번째 스레드 #13이 크리티컬 섹션을 이미 소유하고 있고 이벤트가 시그널 되기를 기다리고 있다고 밝혀낼 수도 있다.

- Dmitry Vostokov @ DumpAnalysis.org -

Crash Dump Analysis Patterns (Part 9c)

Additional resources