Crash Dump Analysis Patterns (Part 51)
Tuesday, February 19th, 2008Another suspicious threads in crash dumps are GUI threads executing message box code. Usually message boxes are displayed to show some error and we can see it by dumping the second and the third MessageBox parameters:
int MessageBox(
HWND hWnd,
LPCTSTR lpText,
LPCTSTR lpCaption,
UINT uType);
Sometimes message boxes block processes as shown in the example illustrating Coupled Process pattern. Other threads might point to possibly “hang” sessions and processes in memory dumps coming from terminal services environments. I call this pattern Message Box and it is another example of the forthcoming collective Blocked Thread pattern.
Let’s look at one example where message box pointed to the right direction of troubleshooting. Some user process was reported hanging from time to time however it was not specified which one. Searching for MessageBox in the log of all threads in the system produced by !process 0 ff WinDbg command revealed the following thread:
THREAD 88b14da8 Cid 0a04.0c14 Teb: 7ffdd000 Win32Thread: e5e50ab0 WAIT: (WrUserRequest) UserMode Non-Alertable
87b74358 SynchronizationEvent
IRP List:
87a0ba00: (0006,0244) Flags: 00000000 Mdl: 00000000
Not impersonating
DeviceMap e14bec28
Owning Process 888ffb60 Image: OUTLOOK.EXE
Wait Start TickCount 1275435 Ticks: 210 (0:00:00:03.281)
Context Switch Count 1050203 LargeStack
UserTime 00:00:16.812
KernelTime 00:00:18.000
Win32 Start Address OUTLOOK (0x30001084)
Start Address kernel32!BaseProcessStartThunk (0x7c810665)
Stack Init a0c98000 Current a0c97cb0 Base a0c98000 Limit a0c90000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 2 DecrementCount 16
ChildEBP RetAddr
a0c97cc8 804e1bd2 nt!KiSwapContext+0x2f
a0c97cd4 804e1c1e nt!KiSwapThread+0x8a
a0c97cfc bf802f70 nt!KeWaitForSingleObject+0x1c2
a0c97d38 bf803776 win32k!xxxSleepThread+0x192
a0c97d4c bf803793 win32k!xxxRealWaitMessageEx+0x12
a0c97d5c 804dd99f win32k!NtUserWaitMessage+0x14
a0c97d5c 7c90eb94 nt!KiFastCallEntry+0xfc
0013f3a8 7e419418 ntdll!KiFastSystemCallRet
0013f3e0 7e42593f USER32!NtUserWaitMessage+0xc
0013f408 7e43a91e USER32!InternalDialogBox+0xd0
0013f6c8 7e43a284 USER32!SoftModalMessageBox+0x938
0013f818 7e4661d3 USER32!MessageBoxWorker+0x2ba
0013f870 7e466278 USER32!MessageBoxTimeoutW+0x7a
0013f8a4 7e450617 USER32!MessageBoxTimeoutA+0x9c
0013f8c4 7e4505cf USER32!MessageBoxExA+0x1b
0013f8e0 088098a9 USER32!MessageBoxA+0x45
...
...
...
0: kd> .process /r /p 888ffb60
Implicit process is now 888ffb60
Loading User Symbols
0: kd> !thread 88b14da8
...
...
...
ChildEBP RetAddr Args to Child
...
...
...
0013f8e0 088098a9 00000000 0013f944 088708f0 USER32!MessageBoxA+0×45
…
…
…
0: kd> dA 0013f944
0013f944 "Cannot contact database, Retry"
This immediately raised suspicion and looking at other threads in the same application revealed that many of them were trying to open a network connection, for example:
THREAD 87a70da8 Cid 0a04.0cc0 Teb: 7ff83000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Non-Alertable
87d690b0 NotificationEvent
87a70e98 NotificationTimer
IRP List:
87af7bc8: (0006,0244) Flags: 00000000 Mdl: 00000000
Not impersonating
DeviceMap e14bec28
Owning Process 888ffb60 Image: OUTLOOK.EXE
Wait Start TickCount 1267130 Ticks: 8515 (0:00:02:13.046)
Context Switch Count 18
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address msmapi32!FOpenThreadImpersonationToken (0×35f76963)
Start Address kernel32!BaseThreadStartThunk (0×7c810659)
Stack Init 9fbc5000 Current 9fbc4ca0 Base 9fbc5000 Limit 9fbc2000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16
Kernel stack not resident.
ChildEBP RetAddr
9fbc4cb8 804e1bd2 nt!KiSwapContext+0×2f
9fbc4cc4 804e1c1e nt!KiSwapThread+0×8a
9fbc4cec 8056d2f9 nt!KeWaitForSingleObject+0×1c2
9fbc4d50 804dd99f nt!NtWaitForSingleObject+0×9a
9fbc4d50 7c90eb94 nt!KiFastCallEntry+0xfc
1bd8f52c 7c90e9c0 ntdll!KiFastSystemCallRet
1bd8f530 7c8025cb ntdll!ZwWaitForSingleObject+0xc
1bd8f594 7c802532 kernel32!WaitForSingleObjectEx+0xa8
1bd8f5a8 77eec4c6 kernel32!WaitForSingleObject+0×12
1bd8f6a4 77eec8b7 RPCRT4!WS_Open+0×31d
1bd8f7c8 77eec96d RPCRT4!TCPOrHTTP_Open+0×19e
1bd8f800 77e83e8d RPCRT4!TCP_Open+0×55
1bd8f84c 77e843f7 RPCRT4!OSF_CCONNECTION::TransOpen+0×5e
1bd8f8b4 77e84581 RPCRT4!OSF_CCONNECTION::OpenConnectionAndBind+0xbc
1bd8f8f8 77e844d0 RPCRT4!OSF_CCALL::BindToServer+0×104
1bd8f95c 77e7f99c RPCRT4!OSF_BINDING_HANDLE::AllocateCCall+0×2b0
1bd8f98c 77e791c1 RPCRT4!OSF_BINDING_HANDLE::NegotiateTransferSyntax+0×28
1bd8f9a4 77e791f8 RPCRT4!I_RpcGetBufferWithObject+0×5b
1bd8f9b4 77e79825 RPCRT4!I_RpcGetBuffer+0xf
1bd8f9c4 77ef460b RPCRT4!NdrGetBuffer+0×28
1bd8fda4 35bae645 RPCRT4!NdrClientCall2+0×195
…
…
…
Looking at IRP showed the possible problem with network at TDI level:
0: kd> !irp 87af7bc8
Irp is active with 4 stacks 2 is current (= 0x87af7c5c) No Mdl: No System Buffer: Thread 87a70da8: Irp stack trace.
cmd flg cl Device File Completion-Context
[ 0, 0] 0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
>[ f, 3] 0 e1 897b0310 87bb24c8 a1ad7080-87b6f1f0 Success Error Cancel pending
\Driver\Tcpip MYTDI!WaitForNetwork
Args: 00000000 87a33988 87a33af8 a1a57600
[ f, 3] 0 e1 88c13020 87bb24c8 a1a6bea5-87a33988 Success Error Cancel pending
\Driver\SYMTDI afd!AfdRestartSuperConnect
Args: 00000000 87a33988 87a33af8 a1a57600
[ e,31] 5 0 88bedf18 87d3af90 00000000-00000000
\Driver\AFD
Args: 00000000 00000016 000120c7 1bd8f52c
- Dmitry Vostokov @ DumpAnalysis.org -