søndag 9. november 2008

Heng i Internet Explorer.

Har vært en stund siden det har vært noe skikkelig feilsøkings stoff, men her skal jeg da Internet Explorer hengte seg fullstendig (Mao ingen vinduer ble oppdatert) bestemte jeg meg for å starte Windbg og se hva som forårsaket problemet. Her kan du se hvilken beskjed når jeg første prøvde å koble meg til prosessen med debuggeren:

Break-in sent, waiting 30 seconds...
WARNING: Break-in timed out, suspending.
This is usually caused by another thread holding the loader lock


Debuggeren har to måter å huke seg på en prosess - først prøver den å injisere en tråd som brukes til å gjøre et såkalt "break in" i prosessen - hvis denne tråden ikke har svart innen 30 sekunder vil debuggeren supsendere alle trådene og dermed stoppe prosessen på dette viset.

La oss hvilke Krtiske Seksjoner i systemet som er låst via !locks

0:004> !locks

CritSec ntdll!LdrpLoaderLock+0 at 7c97c0d8
LockCount 8
RecursionCount 1
OwningThread d98
EntryCount 74
ContentionCount 74
*** Locked

CritSec urlmon!g_mxsMedia+0 at 44604790
LockCount 0
RecursionCount 1
OwningThread d98
EntryCount 1
ContentionCount 1
*** Locked

Vi ser da et den kritiske at vi har to kritiske seksjoner hvorav den ene blir ventet på hele 8 tråder. ntdll!LdrpLoaderLock+0 er låsen til Dllmain som brukes til å installere og fjerne dll filer. Dllmain skal også informeres om eventuelle nye tråder i prosessen slik at tråder vil registere seg ved Dllmain ved DLL_THREAD_ATTACH.
La oss ta en titt på tråden som injiseres av Windbg:

22 Id: b7c.73c Suspend: 1 Teb: 7ffdc000 Unfrozen
ChildEBP RetAddr Args to Child
0124fc0c 7c90e9c0 7c91901b 00000070 00000000 ntdll!KiFastSystemCallRet
0124fc10 7c91901b 00000070 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
0124fc98 7c90104b 0197c0d8 7c927357 7c97c0d8 ntdll!RtlpWaitForCriticalSection+0x132
0124fca0 7c927357 7c97c0d8 0124fd2c 00000004 ntdll!RtlEnterCriticalSection+0x46
0124fd18 7c90eac7 0124fd2c 7c900000 00000000 ntdll!_LdrpInitialize+0xf0
00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x7


Vi kan se at tråden ikke er ferdig installert enda og venter på at den kritiske seksjonen skal frigjøres. Vi skal se på tråden som eier den krtiske seksjonen men først skal vi bruke !runaway for å se hvilke tråder som har vært mest aktive i prosessen:

0:004> !runaway
User Mode Time
Thread Time
4:d98 0 days 0:00:17.375
20:d84 0 days 0:00:02.562
15:244 0 days 0:00:00.843
0:5dc 0 days 0:00:00.765
18:170 0 days 0:00:00.171
17:e08 0 days 0:00:00.171
14:108 0 days 0:00:00.078
6:e4c 0 days 0:00:00.046
12:c4c 0 days 0:00:00.031
13:d48 0 days 0:00:00.015
22:73c 0 days 0:00:00.000
21:a5c 0 days 0:00:00.000
19:338 0 days 0:00:00.000
16:640 0 days 0:00:00.000
11:350 0 days 0:00:00.000
10:b58 0 days 0:00:00.000
9:a58 0 days 0:00:00.000
8:aec 0 days 0:00:00.000
7:c24 0 days 0:00:00.000
5:dc0 0 days 0:00:00.000
3:990 0 days 0:00:00.000
2:b8c 0 days 0:00:00.000
1:f60 0 days 0:00:00.000


Vi ser at på topp ligger tråden som eier den krtiske seksjonen men på 2, plass ligger en annen tråd som har brukt ganske mye av tiden også - vi skal se på den senere men først skal vi se på tråden som både har brukt mesteparten av tiden til scheduleren og som eier den kritiske seksjonen:

4 Id: b7c.d98 Suspend: 1 Teb: 7ffd8000 Unfrozen
ChildEBP RetAddr Args to Child
0166fe0c 7e41daf6 44577b30 00040572 001931d8 ntdll!KiFastSystemCallRet
0166fe24 44577adc 00000d98 00000000 00000000 USER32!NtUserDestroyWindow+0xc
0166fe40 44551d9f 44604820 00000000 0166fe64 urlmon!DoThreadCleanup+0x117
0166fe50 44551d86 00000001 00000001 00000000 urlmon!DoThreadCleanup+0xf
0166fe64 44551b86 44550000 00000003 00000000 urlmon!TlsDllMain+0x2a
0166fe84 44551a7f 44550000 00000003 00000000 urlmon!DllMain+0x17e
0166fee4 7c9011a7 44550000 00000003 00000000 urlmon!_initterm_e+0x12b
0166ff04 7c919213 445519f1 44550000 00000003 ntdll!LdrpCallInitRoutine+0x14
0166ff7c 7c80c096 0012e490 0012e5b8 0018ea28 ntdll!LdrShutdownThread+0xd7
0166ffb4 7c80b688 00000000 0012e490 0012e5b8 kernel32!ExitThread+0x3e
0166ffec 00000000 447ee424 0018ea28 00000000 kernel32!BaseThreadStart+0x3c

Vi ser at kernel32 har bedt om at tråden stenges og det kaller da inn i urlmon som benytter funksjonene i Dllmain for å rense opp sine objekter i tråden som skal avsluttes. urlmon brukes tilegg som benytter seg av OLE32 så kan det være noe galt med et OLE32 objekt? La oss se på den tråden som brukte nest mest av cpu-tiden i user mode:

20 Id: b7c.d84 Suspend: 1 Teb: 7ff9b000 Unfrozen
ChildEBP RetAddr Args to Child
0d2cf6e4 7c90e9ab 7c8094e2 00000002 0d2cf710 ntdll!KiFastSystemCallRet
0d2cf6e8 7c8094e2 00000002 0d2cf710 00000001 ntdll!ZwWaitForMultipleObjects+0xc
0d2cf784 7e4195f9 00000002 0d2cf7ac 00000000 kernel32!WaitForMultipleObjectsEx+0x12c
0d2cf7e0 77502235 00000001 0d2cf828 000003e8 USER32!RealMsgWaitForMultipleObjectsEx+0x13e
0d2cf808 7750235c 0d2cf828 000003e8 0d2cf838 ole32!CCliModalLoop::BlockFn+0x80
0d2cf830 77516749 ffffffff 0d2cf928 0d2cf860 ole32!ModalLoop+0x5b
0d2cf840 775f1f01 0018ee18 0d2cf928 00000000 ole32!SwitchSTA+0x21
0d2cf860 775f109a 0d2cf928 00209164 0d2cf984 ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xd1
0d2cf940 77502409 00209164 0d2cfa54 0d2cfa44 ole32!CRpcChannelBuffer::SendReceive2+0xb9
0d2cf95c 775023b2 0d2cfa54 0d2cfa44 00209164 ole32!CCliModalLoop::SendReceive+0x1e
0d2cf9c8 77500414 00209164 0d2cfa54 0d2cfa44 ole32!CAptRpcChnl::SendReceive+0x6f
0d2cfa1c 77ef3db5 00209164 0d2cfa54 0d2cfa44 ole32!CCtxComChnl::SendReceive+0x113
0d2cfa38 77ef3ead 069a696c 0d2cfa80 0600015b RPCRT4!NdrProxySendReceive+0x43
0d2cfe14 77ef3e42 774d6218 774d92ca 0d2cfe4c RPCRT4!NdrClientCall2+0x1fa
0d2cfe34 77e8a7f3 00000010 00000005 0d2cfe5c RPCRT4!ObjectStublessClient+0x8b
0d2cfe44 77501410 069a696c 00000002 0721fb50 RPCRT4!ObjectStubless+0xf
0d2cfe5c 775013b1 069a696c 0018ee18 00000002 ole32!RemoteReleaseRifRefHelper+0x84
0d2cfe84 77500052 069a696c 0018ee18 00000002 ole32!RemoteReleaseRifRef+0x74
0d2cfedc 774ffe4b 06fbce04 06fbce00 00000000 ole32!CStdMarshal::DisconnectCliIPIDs+0x200
0d2cff04 774fd878 00000002 06fbcea8 06fbce00 ole32!CStdMarshal::Disconnect+0x178

Og vi ser at denne tråden driver og rydder opp i OLE32 objekter og den står og venter på to objekter-la oss se nærmere på disse:

0:004> dd 0d2cf710
0d2cf710 0000088c 00000c40 00000001 00000000
0d2cf720 00000000 00000010 00000000 0000022d
0d2cf730 00000014 00000001 00000000 00000000
0d2cf740 00000010 ff676980 ffffffff 7ff9b000
0d2cf750 7ffde000 7ff9b000 0d2cf78c 0d2cf744
0d2cf760 0d2cf710 0d2cf984 00000002 0d2cf704
0d2cf770 06ac780c 0d2cfe04 7c839aa8 7c8095d8
0d2cf780 00000000 0d2cf7e0 7e4195f9 00000002


dd dumper da atlså arrayet med referasene til de to objektene - la oss titte nærmere på disse:

0:004> !handle 00000c40 7
Handle c40
Type Event
Attributes 0
GrantedAccess 0x1f0003:
Delete,ReadControl,WriteDac,WriteOwner,Synch
QueryState,ModifyState
HandleCount 2
PointerCount 5
Name

0:004> !handle 0000088c 7
Handle 88c
Type Event
Attributes 0
GrantedAccess 0x1f0003:
Delete,ReadControl,WriteDac,WriteOwner,Synch
QueryState,ModifyState
HandleCount 2
PointerCount 4
Name


Vi ser da at det dreier seg om to synkroniseringsobjekter-ved å bruke process explorer fant jeg ut at det ene var signaled mens det andre var såkalt non-signaled og dermed det mest interessante. Handlecount på 2 betyr at en annen struktur fremdeles referer til den la oss se om vi kan finne moduler i minnet som har en referanse til denne addressen:

07f32418 0000088c
07f3241c 0116bc21
07f32420 fffe1800
07f32424 23ffff14
07f32428 fd150003
07f3242c 04035bff SkypeIEPlugin!DllRegisterServer+0x6fef


07f910f8 633a0c16 jscript!MUTX::Enter+0x38
07f910fc 00000010
07f91100 00000000
07f91104 0000088c

SkypeIEplugin hadde også vært refert som de siste funksjonene på stakken:

0d2bdc38 04076aba SkypeIEPlugin!DllRegisterServer+0x47eaa
0d2bdc3c 04076ac2 SkypeIEPlugin!DllRegisterServer+0x47eb2
0d2bdc40 881f6a96
0d2bdc44 00000000
0d2bdc48 00000078
0d2bdc4c 040c3620 SkypeIEPlugin!DllRegisterServer+0x94a10
0d2bdc50 7c90d592 ntdll!ZwClose+0xc
0d2bdc54 00000000
0d2bdc58 00000003
0d2bdc5c 000000a8
0d2bdc60 04062ac4 SkypeIEPlugin!DllRegisterServer+0x33eb4
0d2bdc64 04076af2 SkypeIEPlugin!DllRegisterServer+0x47ee2
0d2bdc68 042627dc
0d2bdc6c 04062bbc SkypeIEPlugin!DllRegisterServer+0x33fac
0d2bdc70 00000003
0d2bdc74 04062bb3 SkypeIEPlugin!DllRegisterServer+0x33fa3
0d2bdc78 881f6a52
0d2bdc7c 00000000
0d2bdc80 040c1130 SkypeIEPlugin!DllRegisterServer+0x92520
0d2bdc84 04260000
0d2bdc88 00000000
0d2bdc8c 00000000
0d2bdc90 0d2bdc78
0d2bdc94 0d2bdcf0
0d2bdc98 0d2bdcf0
0d2bdc9c 00015be0
0d2bdca0 00000015
0d2bdca4 0d2bdc00
0d2bdca8 04062bb3 SkypeIEPlugin!DllRegisterServer+0x33fa3
0d2bdcac 0d2bdcec
0d2bdcb0 7c90ee18 ntdll!_except_handler3
0d2bdcb4 7c910570 ntdll!CheckHeapFillPattern+0x64
0d2bdcb8 ffffffff
0d2bdcbc 7c91056d ntdll!RtlFreeHeap+0x647
0d2bdcc0 04056857 SkypeIEPlugin!DllRegisterServer+0x27c47
0d2bdcc4 04260000
0d2bdcc8 00000000
0d2bdccc 04056876 SkypeIEPlugin!DllRegisterServer+0x27c66
0d2bdcd0 881f6a06
0d2bdcd4 000089be
0d2bdcd8 0d2cf12c
0d2bdcdc 000089be
0d2bdce0 000089be
0d2bdce4 0d2bdcd0
0d2bdce8 0d2bdcd4
0d2bdcec 0d2cf0d8
0d2bdcf0 04055be0 SkypeIEPlugin!DllRegisterServer+0x26fd0
0d2bdcf4 813f07aa
0d2bdcf8 fffffffe
0d2bdcfc 04056876 SkypeIEPlugin!DllRegisterServer+0x27c66
0d2bdd00 03ff2782 SkypeIEPlugin+0x2782
0d2bdd04 04268e10
0d2bdd08 04273780
0d2bdd0c 04001de6 SkypeIEPlugin+0x11de6


Det falt seg derfor naturlig å anta at det var SkypeIEplugin som var problemet og den prøvde sannsynligvis å benytte seg av Dllmain for registere dll filen mens Dllmain sin aksess var låst til en kritisk seksjon som følge av at urlmon prøvde å rydde opp OLE32 objekter brukt av SkypeIEPlugin, siden jeg ikke bruker denne Plugin'en bare fjernet jeg autolastingen av dll'en ved å bruke Autoruns.


Som sagt før, er det noe du lurer på angående dette er det bare å spørre!

Ingen kommentarer: