The search for exceptions

Sometimes knowing where to look for exceptions could be crucial to understand and debug the issue. There are many approaches mentioned in different articles. Hereby, I try to consolidate them into one.

The following approaches are mainly focused on the user-mode exception. For the kernel-mode exception, the article by Jamie E. Hanrahan -- Using the Windows Debugger: Exceptions, Bugchecks, and Register Context provides pretty useful information.

1. Look for an EXCEPTION_POINTERS from the first parameter of PeekMessageExceptionFilter

030c21d0 76df3448 00000000 030c6138 76db6b0d ntdll!DbgBreakPoint
030c21dc 76db6b0d 030c2204 77b8d585 030c220c ole32!PeekMessageExceptionFilter+0x42
030c21e4 77b8d585 030c220c 00000000 030c220c ole32!CCliModalLoop::MyPeekMessage+0x41

(Excerpted from http://blogs.msdn.com/oldnewthing/archive/2006/08/21/710754.aspx)

2. Look for an exception context from the second parameter of KiUserExceptionDispatcher

0096c7f0 0096caf0
0096c7f4 7c82ecc6 ntdll!KiUserExceptionDispatcher+0xe
0096c7f8 0096c000
0096c7fc 0096c824 ; a pointer to an exception context

(Excerpted from http://www.dumpanalysis.org/blog/index.php/2007/02/02/crash-dump-analysis-patterns-part-8)

3. Look for an EXCEPTION_POINTERS from the only parameter of UnhandledExceptionFilter

09a8f334 77eb9b46 0000244c 00000001 00000000 ntdll!ZwWaitForSingleObject+0xb
09a8f644 77ea7e7a 09a8f66c 77e861ae 09a8f674 KERNEL32!UnhandledExceptionFilter+0x2b5
09a8ffec 00000000 787bf0b8 0216fe94 00000000 KERNEL32!BaseThreadStart+0x65

(Excerpted from http://support.microsoft.com/kb/313109)

4. Look for an exception code from the first parameter of Kernel32!RaiseException

5. Look for the context flags (1003f or 1001f on x86) on the stack

Use “s -d esp L1000 1003f" to search for addresses on the stack containing 0x1003f or 0x1001f.

0535ef48 0001003f 00000000 00000000 00000000 ?...............

The first column would be the address containing 0x1003f or 0x1001f, which would be the address of the context on the stack as well. The rest of the columns would be the corresponding fields in the context. If multiple entries are found, use the first one, since it would be the most recent exception.

Use “.cxr 0535ef48” to set the current context.

The approach takes advantage of the fact that the exception context is pushed onto the stack. Its first field -- context flags always has the value of 0x1003f (CONTEXT_ALL) or 0x1001f (CONTEXT_ALL & ~CONTEXT_EXTENDED_REGISTERS) on x86.

(Excerpted from http://blogs.msdn.com/jmstall/archive/2005/01/18/355697.aspx)

6. Look for exception contexts with valid addresses

An exception context is pushed onto the stack after an exception is thrown. The .cxr command is used to restore registers to their pre-exception context. Therefore, an exception context address should be less than ESP, ESP should be less than or equal to EBP, when ESP and EBP have been restored to their pre-exception context.

7. Look for a managed exception from the first parameter of mscorwks!RaiseTheExceptionInternalOnly

ChildEBP RetAddr Args to Child
0012f2d8 79eda99c e0434f4d 00000001 00000001 KERNEL32!RaiseException+0x53
0012f338 79fb48f8 012c9a78 00000000 00000000 mscorwks!RaiseTheExceptionInternalOnly+0x2a8
0012f3fc 00cd067c 012c9a78 00000000 00000000 mscorwks!JIT_Throw+0xfc

0:000> !pe 012c9a78
Exception object: 012c9a78
Exception type: System.ArgumentException
Message: Obj cannot be null
InnerException:
StackTrace (generated):
[...]
StackTraceString:
HResult: 80070057

Notes on LPC

I ran into a series of articles on LPC by Roy from GES site recently.

• http://blogs.msdn.com/ntdebugging/archive/2007/07/26/lpc-local-procedure-calls-part-1-architecture.aspx

• http://blogs.msdn.com/ntdebugging/archive/2007/09/05/lpc-part-2-kernel-debugger-extensions.aspx

• http://blogs.msdn.com/ntdebugging/archive/2007/09/10/lpc-part-3-debugging-a-real-world-lpc-scenario.aspx

• http://blogs.msdn.com/ntdebugging/archive/2007/09/14/lpc-case2-when-things-are-not-rosy.aspx

Those articles provide a pretty decent treatment to the internals of LPC and troubleshooting LPC related issues.

Why did DllRegisterServer return 80070006?

I tried to register an in-proc COM server using regsvr32. However, regsvr32 kept returning the error code 80070006.


Driven by the curiosity, I decided to figure out the reason. At the DOS command prompt, I typed "windbg -o cmd.exe /c regsvr32 08comps.dll" to attach WinDBG to the child process (regsvr32.exe).

Before going forward, I checked the error message for 80070006.

1:001> !error 80070006
Error code: (HRESULT) 0x80070006 (2147942406) - The handle is invalid.

Below the display of registers for each step is yanked out for clarity.

1:001> sxe ld:08comps* ; break when 08comps.dll is loaded
1:001> x 08comps!*DllRegisterServer*
009723f0 08comps!DllRegisterServer (void)
1:001> bp 08comps!DllRegisterServer ; break at DllRegisterServer

08comps!DllRegisterServer:
009723f0 mov edi,edi
009723f2 push ebp
009723f3 mov ebp,esp
009723f5 push ecx
009723f6 mov eax,dword ptr [08comps!aProxyFileList (00973040)] ds:0023:00973040={08comps!srv_ProxyFileInfo (009721d8)}
009723fb mov ecx,dword ptr [eax+4] ds:0023:009721dc={08comps!_srv_StubVtblList (00973038)}
009723fe cmp dword ptr [ecx],0 ds:0023:00973038={08comps!_ICalculatorStubVtbl (00972198)}
00972401 je 08comps!DllRegisterServer+0x25 (00972415) [br=0]
00972403 mov edx,dword ptr [08comps!aProxyFileList (00973040)] ds:0023:00973040={08comps!srv_ProxyFileInfo (009721d8)}
00972409 mov eax,dword ptr [edx+4] ds:0023:009721dc={08comps!_srv_StubVtblList (00973038)}
0097240c mov ecx,dword ptr [eax] ds:0023:00973038={08comps!_ICalculatorStubVtbl (00972198)}
0097240e mov edx,dword ptr [ecx] ds:0023:00972198={08comps!IID_ICalculator (00972200)}
00972410 mov dword ptr [ebp-4],edx ss:0023:0007e86c=7c917de9
00972413 jmp 08comps!DllRegisterServer+0x2c (0097241c)
0097241c mov eax,dword ptr [ebp-4] ss:0023:0007e86c={08comps!IID_ICalculator (00972200)}
0097241f push eax
00972420 push offset 08comps!aProxyFileList (00973040)
00972425 mov ecx,dword ptr [08comps!hProxyDll (00973360)] ds:0023:00973360=00000000 ; hProxyDll is NULL. It seems suspicious.
0097242b push ecx ; hProxyDll is the first parameter
0097242c call dword ptr [08comps!_imp__NdrDllRegisterProxy (00972058)] ds:0023:00972058={RPCRT4!NdrDllRegisterProxy (77ed3211)}

RPCRT4!NdrDllRegisterProxy:
77ed3211 mov edi,edi
77ed3213 push ebp
77ed3214 mov ebp,esp
77ed3216 sub esp,140h
77ed321c mov eax,dword ptr [RPCRT4!__security_cookie (77efb2ac)] ds:0023:77efb2ac=0000cf46
77ed3221 mov ecx,dword ptr [ebp+10h] ss:0023:0007e868={08comps!IID_ICalculator (00972200)}
77ed3224 push ebx
77ed3225 push esi
77ed3226 mov dword ptr [ebp-4],eax ss:0023:0007e854=00000000
77ed3229 mov eax,dword ptr [ebp+8] ss:0023:0007e860=00000000 ; store hProxyDLL in EAX
77ed322c xor esi,esi ; esi = 0
77ed322e cmp eax,esi ; check if hProxyDll is NULL
77ed3230 push edi
77ed3231 mov edi,dword ptr [ebp+0Ch] ss:0023:0007e864={08comps!aProxyFileList (00973040)}
77ed3234 mov dword ptr [ebp-13Ch],ecx ss:0023:0007e71c=00972f58
77ed323a mov ebx,80070000h
77ed323f je RPCRT4!NdrDllRegisterProxy+0x68 (77ed3279) [br=1] ; jump since hProxyDLL is NULL
77ed3279 mov dword ptr [ebp-134h],80070006h ss:0023:0007e724=00000000 ; store error code 80070006 in a local variable
77ed3283 xor esi,esi ; esi = 0
77ed3285 cmp dword ptr [ebp-134h],esi ss:0023:0007e724=80070006 ; check if error code is less than 0
77ed328b jl RPCRT4!NdrDllRegisterProxy+0x254 (77ed3464) [br=1] ; jump since error code is less than 0
77ed3464 mov ecx,dword ptr [ebp-4] ss:0023:0007e854=0000cf46
77ed3467 mov eax,dword ptr [ebp-134h] ss:0023:0007e724=80070006 ; store error code in EAX
77ed346d pop edi
77ed346e pop esi
77ed346f pop ebx
77ed3470 call RPCRT4!__security_check_cookie (77e7602d)
77ed3475 leave
77ed3476 ret 0Ch

From the above code tracing, it seemed that the error code 80070006 returned from DllRegisterServer was because 08comps!hProxyDll was NULL. The next question was why hProxyDll was NULL. I restarted the debugging session and set break on access to hProxyDll -- ba w4 08comps!hProxyDll. However, the code did not break. It indicated that no code ever tried to set a value to hProxyDll. Then I found out from rpcproxy.h that hProxyDll is set to the module handle in DllMain. So I tried "x 08comps!*dllmain*" and "x 08comps!*" and searched for "DllMain". However, there was no matches. It seemed 08comps.dll used DllMain provided by the runtime instead of its own. Then I checked the source code. It turned out that DLLDATA_ROUTINES macro was used. The macro does not provide the code for DllMain. To fix the issue, REGISTER_PROXY_DLL_ROUTINES macro should be used. Since it provides its own DllMain, where hProxyDll is set to the module handle.

Annotated 0x86 Assembly -- VC++ Exception

Armed with the knowledge learned from the article by Matt Pietrek -- A Crash Course on the Depths of Win32™ Structured Exception Handling, and the article by Vishal Kochhar -- How a C++ compiler implements exception handling, below I list the annotated 0x86 assembly for a C++ program containing the nested exception handling and built on VS2008.

Recall the standard exception frame generated by VC++ is as following,

EBP-18 Standard ESP in frame
EBP-14 GetExceptionPointers
EBP-10 previous EXCEPTION_REGISTRATION
EBP-0C handler function address
EBP-08 scopetable pointer
EBP-04 trylevel
EBP-00 _ebp

The annotated assembly is as following,

52 00401000 push ebp ; _ebp
52 00401001 mov ebp,esp
52 00401003 push 0FFFFFFFEh ; initial value for trylevel
52 00401005 push offset ExceptionSample!_TI1H+0x10 (004027c8) ; scopetable pointer
52 0040100a push offset ExceptionSample!_except_handler4 (00401b75) ; handler address
52 0040100f mov eax,dword ptr fs:[00000000h]
52 00401015 push eax ; previous EXCEPTION_REGISTRATION
52 00401016 sub esp,8 ; reserve space for ExceptionPointer and ESP
52 00401019 push ebx
52 0040101a push esi
52 0040101b push edi
52 0040101c mov eax,dword ptr [ExceptionSample!__security_cookie (00403018)]
52 00401021 xor dword ptr [ebp-8],eax
52 00401024 xor eax,ebp
52 00401026 push eax
52 00401027 lea eax,[ebp-10h] ; eax = ebp-10h
52 0040102a mov dword ptr fs:[00000000h],eax ; point fs:[0] to the beginning of EXCEPTION_REGISTRATION on the stack
52 00401030 mov dword ptr [ebp-18h],esp
53 00401033 mov dword ptr [ebp-4],0 ; first try block
55 0040103a mov eax,1
55 0040103f mov dword ptr [ebp-4],eax ; second try block
57 00401042 mov dword ptr [ebp-4],2 ; third try block
59 00401049 mov dword ptr ds:[0],0
64 00401053 mov dword ptr [ebp-4],eax ; back to second try block
66 00401056 mov dword ptr [ebp-4],0 ; back to first try block
66 0040105d call ExceptionSample!try_except_finally+0x88 (00401088)
66 00401062 jmp ExceptionSample!try_except_finally+0xa8 (004010a8)
74 004010a8 mov eax,0FFFFFFFEh
74 004010ad mov dword ptr [ebp-4],eax ; out of try block
75 004010b0 mov dword ptr [ebp-4],3 ; fourth try block
77 004010b7 mov dword ptr ds:[0],0
78 004010c1 mov dword ptr [ebp-4],eax ; out of try block
84 004010c4 mov ecx,dword ptr [ebp-10h]
84 004010c7 mov dword ptr fs:[0],ecx ; point fs:[0] to previous EXCEPTION_REGISTRATION
84 004010ce pop ecx
84 004010cf pop edi
84 004010d0 pop esi
84 004010d1 pop ebx
84 004010d2 mov esp,ebp
84 004010d4 pop ebp
84 004010d5 ret

The following is the source code,

void try_except_finally()
{
__try
{
__try
{
__try
{
*((int *) 0) = 0;
}
__except(EXCEPTION_EXECUTE_HANDLER) { global = 1; }
}
__finally { global = 2; }
}
__except(EXCEPTION_EXECUTE_HANDLER) { global = 3; }

__try
{
*((int *) 0) = 0;
}
__except(EXCEPTION_EXECUTE_HANDLER) { global = 4; }
}

Notes on investigating security failures

In nowadays, every application running on Windows interacts with some type of security object. One of the often seen scenarios is an IIS-hosting web service tries to access local file system.

When it comes to investigating security failures, three questions have to be answered:

1. What privileges have been granted to the thread or process?
2. What privileges are required to access the security object?
3. What security objects are involved in the interaction?

The !token extension command can be used to answer the first question in both user and kernel modes.

lkd> !token -n
Thread is not impersonating. Using process token...
_EPROCESS 81c32020, _ETHREAD 81f6cda8, _TOKEN e7856380
TS Session ID: 0
User: S-1-5-21-527237240-926492609-839522115-1006 (User: BXIA\bing)
Groups:
00 S-1-5-21-527237240-926492609-839522115-513 (Group: BXIA\None)
Attributes - Mandatory Default Enabled
01 S-1-1-0 (Well Known Group: localhost\Everyone)
Attributes - Mandatory Default Enabled
02 S-1-5-21-527237240-926492609-839522115-1004 (Alias: BXIA\Debugger Users)
Attributes - Mandatory Default Enabled
03 S-1-5-32-544 (Alias: BUILTIN\Administrators)
Attributes - Mandatory Default Enabled Owner
04 S-1-5-32-545 (Alias: BUILTIN\Users)
Attributes - Mandatory Default Enabled
05 S-1-5-4 (Well Known Group: NT AUTHORITY\INTERACTIVE)
Attributes - Mandatory Default Enabled
06 S-1-5-11 (Well Known Group: NT AUTHORITY\Authenticated Users)
Attributes - Mandatory Default Enabled
07 S-1-5-5-0-1588032 (no name mapped)
Attributes - Mandatory Default Enabled LogonId
08 S-1-2-0 (Well Known Group: localhost\LOCAL)
Attributes - Mandatory Default Enabled
Primary Group: S-1-5-21-527237240-926492609-839522115-513 (Group: BXIA\None)
Privs:
00 0x000000017 SeChangeNotifyPrivilege Attributes - Enabled Default
01 0x000000008 SeSecurityPrivilege Attributes -
02 0x000000011 SeBackupPrivilege Attributes -
03 0x000000012 SeRestorePrivilege Attributes -
04 0x00000000c SeSystemtimePrivilege Attributes -
05 0x000000013 SeShutdownPrivilege Attributes -
06 0x000000018 SeRemoteShutdownPrivilege Attributes -
07 0x000000009 SeTakeOwnershipPrivilege Attributes -
08 0x000000014 SeDebugPrivilege Attributes - Enabled
09 0x000000016 SeSystemEnvironmentPrivilege Attributes -
10 0x00000000b SeSystemProfilePrivilege Attributes -
11 0x00000000d SeProfileSingleProcessPrivilege Attributes -
12 0x00000000e SeIncreaseBasePriorityPrivilege Attributes -
13 0x00000000a SeLoadDriverPrivilege Attributes - Enabled
14 0x00000000f SeCreatePagefilePrivilege Attributes -
15 0x000000005 SeIncreaseQuotaPrivilege Attributes -
16 0x000000019 SeUndockPrivilege Attributes - Enabled
17 0x00000001c SeManageVolumePrivilege Attributes -
18 0x00000001d SeImpersonatePrivilege Attributes - Enabled Default
19 0x00000001e SeCreateGlobalPrivilege Attributes - Enabled Default
Authentication ID: (0,185ddb)
Impersonation Level: Anonymous
TokenType: Primary
Source: User32 TokenFlags: 0x89 ( Token in use )
Token ID: 12a3e141 ParentToken ID: 0
Modified ID: (0, 12a45412)
RestrictedSidCount: 0 RestrictedSids: 00000000

The !sd extension command can be used to answer the second question. Since the security descriptor is protected by the kernel mode, !sd can only be run in the kernel mode. Thanks to local kernel debugging supported on XP and later versions of Windows, it becomes easier to check the security descriptor of a security object.

lkd> !object 81c32020
Object: 81c32020 Type: (833c8ca0) Process
ObjectHeader: 81c32008 (old version)
HandleCount: 5 PointerCount: 157

lkd> dt _OBJECT_HEADER 81c32008
nt!_OBJECT_HEADER
+0x000 PointerCount : 157
+0x004 HandleCount : 5
+0x004 NextToFree : 0x00000005
+0x008 Type : 0x833c8ca0 _OBJECT_TYPE
+0x00c NameInfoOffset : 0 ''
+0x00d HandleInfoOffset : 0 ''
+0x00e QuotaInfoOffset : 0 ''
+0x00f Flags : 0x20 ' '
+0x010 ObjectCreateInfo : 0x81f12da8 _OBJECT_CREATE_INFORMATION
+0x010 QuotaBlockCharged : 0x81f12da8
+0x014 SecurityDescriptor : 0xe6d77c33
+0x018 Body : _QUAD

lkd> !sd 0xe6d77c33 & FFFFFFF8
->Revision: 0x1
->Sbz1 : 0x0
->Control : 0x8004
SE_DACL_PRESENT
SE_SELF_RELATIVE
->Owner : S-1-5-21-527237240-926492609-839522115-1006
->Group : S-1-5-21-527237240-926492609-839522115-513
->Dacl :
->Dacl : ->AclRevision: 0x2
->Dacl : ->Sbz1 : 0x0
->Dacl : ->AclSize : 0x40
->Dacl : ->AceCount : 0x2
->Dacl : ->Sbz2 : 0x0
->Dacl : ->Ace[0]: ->AceType: ACCESS_ALLOWED_ACE_TYPE
->Dacl : ->Ace[0]: ->AceFlags: 0x0
->Dacl : ->Ace[0]: ->AceSize: 0x24
->Dacl : ->Ace[0]: ->Mask : 0x001f0fff
->Dacl : ->Ace[0]: ->SID: S-1-5-21-527237240-926492609-839522115-1006

->Dacl : ->Ace[1]: ->AceType: ACCESS_ALLOWED_ACE_TYPE
->Dacl : ->Ace[1]: ->AceFlags: 0x0
->Dacl : ->Ace[1]: ->AceSize: 0x14
->Dacl : ->Ace[1]: ->Mask : 0x001f0fff
->Dacl : ->Ace[1]: ->SID: S-1-5-18

->Sacl : is NULL

The corresponding shortcut for the above steps is as following:

lkd> !sd poi(81c32020-4) & FFFFFFF8
->Revision: 0x1
->Sbz1 : 0x0
->Control : 0x8004
SE_DACL_PRESENT
SE_SELF_RELATIVE
->Owner : S-1-5-21-527237240-926492609-839522115-1006
->Group : S-1-5-21-527237240-926492609-839522115-513
->Dacl :
->Dacl : ->AclRevision: 0x2
->Dacl : ->Sbz1 : 0x0
->Dacl : ->AclSize : 0x40
->Dacl : ->AceCount : 0x2
->Dacl : ->Sbz2 : 0x0
->Dacl : ->Ace[0]: ->AceType: ACCESS_ALLOWED_ACE_TYPE
->Dacl : ->Ace[0]: ->AceFlags: 0x0
->Dacl : ->Ace[0]: ->AceSize: 0x24
->Dacl : ->Ace[0]: ->Mask : 0x001f0fff
->Dacl : ->Ace[0]: ->SID: S-1-5-21-527237240-926492609-839522115-1006

->Dacl : ->Ace[1]: ->AceType: ACCESS_ALLOWED_ACE_TYPE
->Dacl : ->Ace[1]: ->AceFlags: 0x0
->Dacl : ->Ace[1]: ->AceSize: 0x14
->Dacl : ->Ace[1]: ->Mask : 0x001f0fff
->Dacl : ->Ace[1]: ->SID: S-1-5-18

->Sacl : is NULL

With first two questions answered, it is straightforward to check whether the principal identified by the token has enough privileges to access the object protected by the security descriptor.

What makes the investigation of a security issue challenging is the third question. For instance, in an invocation to ImpersonateSelf, more than one security objects are involved.

0:001> uf ADVAPI32!ImpersonateSelf
ADVAPI32!ImpersonateSelf:
77dfd203 8bff mov edi,edi
77dfd205 55 push ebp
77dfd206 8bec mov ebp,esp
77dfd208 ff7508 push dword ptr [ebp+8]
77dfd20b ff153012dd77 call dword ptr [ADVAPI32!_imp__RtlImpersonateSelf (77dd1230)]
77dfd211 85c0 test eax,eax
77dfd213 0f8c31210000 jl ADVAPI32!ImpersonateSelf+0x12 (77dff34a)

ADVAPI32!ImpersonateSelf+0x1c:
77dfd219 33c0 xor eax,eax
77dfd21b 40 inc eax

ADVAPI32!ImpersonateSelf+0x1f:
77dfd21c 5d pop ebp
77dfd21d c20400 ret 4

ADVAPI32!ImpersonateSelf+0x12:
77dff34a 50 push eax
77dff34b e8d479fdff call ADVAPI32!BaseSetLastNTError (77dd6d24)
77dff350 33c0 xor eax,eax
77dff352 e9c5deffff jmp ADVAPI32!ImpersonateSelf+0x1f (77dfd21c)

0:001> uf ntdll!RtlImpersonateSelf
ntdll!RtlImpersonateSelf:
7c92aa7d 8bff mov edi,edi
7c92aa7f 55 push ebp
7c92aa80 8bec mov ebp,esp
7c92aa82 83ec28 sub esp,28h
7c92aa85 8b4508 mov eax,dword ptr [ebp+8]
7c92aa88 53 push ebx
7c92aa89 8945f4 mov dword ptr [ebp-0Ch],eax
7c92aa8c 8d45f0 lea eax,[ebp-10h]
7c92aa8f 56 push esi
7c92aa90 8945ec mov dword ptr [ebp-14h],eax
7c92aa93 8d45fc lea eax,[ebp-4]
7c92aa96 50 push eax
7c92aa97 33db xor ebx,ebx
7c92aa99 6a02 push 2
7c92aa9b 6aff push 0FFFFFFFFh ; indicate current process handle
7c92aa9d c745d818000000 mov dword ptr [ebp-28h],18h
7c92aaa4 895ddc mov dword ptr [ebp-24h],ebx
7c92aaa7 895de4 mov dword ptr [ebp-1Ch],ebx
7c92aaaa 895de0 mov dword ptr [ebp-20h],ebx
7c92aaad 895de8 mov dword ptr [ebp-18h],ebx
7c92aab0 c745f00c000000 mov dword ptr [ebp-10h],0Ch
7c92aab7 c645f801 mov byte ptr [ebp-8],1
7c92aabb 885df9 mov byte ptr [ebp-7],bl
7c92aabe e8cd32feff call ntdll!ZwOpenProcessToken (7c90dd90) ; security descriptor of current process might be checked
7c92aac3 8bf0 mov esi,eax
7c92aac5 3bf3 cmp esi,ebx
7c92aac7 7c3c jl ntdll!RtlImpersonateSelf+0x88 (7c92ab05)

ntdll!RtlImpersonateSelf+0x4c:
7c92aac9 8d4508 lea eax,[ebp+8]
7c92aacc 50 push eax
7c92aacd 6a02 push 2
7c92aacf 53 push ebx
7c92aad0 8d45d8 lea eax,[ebp-28h]
7c92aad3 50 push eax
7c92aad4 6a04 push 4
7c92aad6 ff75fc push dword ptr [ebp-4]
7c92aad9 e8442efeff call ntdll!ZwDuplicateToken (7c90d922) ; security descriptor of primary token might be checked
7c92aade 8bf0 mov esi,eax
7c92aae0 3bf3 cmp esi,ebx
7c92aae2 7c19 jl ntdll!RtlImpersonateSelf+0x80 (7c92aafd)

ntdll!RtlImpersonateSelf+0x67:
7c92aae4 6a04 push 4
7c92aae6 8d4508 lea eax,[ebp+8]
7c92aae9 50 push eax
7c92aaea 6a05 push 5
7c92aaec 6afe push 0FFFFFFFEh ; indicate current thread handle
7c92aaee e84f3bfeff call ntdll!ZwSetInformationThread (7c90e642) ; security descriptor of current thread might be checked
7c92aaf3 ff7508 push dword ptr [ebp+8]
7c92aaf6 8bf0 mov esi,eax
7c92aaf8 e8892afeff call ntdll!NtClose (7c90d586) ; superseded by CloseHandle

ntdll!RtlImpersonateSelf+0x80:
7c92aafd ff75fc push dword ptr [ebp-4]
7c92ab00 e8812afeff call ntdll!NtClose (7c90d586) ; superseded by CloseHandle

ntdll!RtlImpersonateSelf+0x88:
7c92ab05 8bc6 mov eax,esi
7c92ab07 5e pop esi
7c92ab08 5b pop ebx
7c92ab09 c9 leave
7c92ab0a c20400 ret 4

From the above unassembled code, it is clear that there are three security objects involved in the invocation to ImpersonateSelf -- the current process, the primary token of current process, and the current thread. Their security descriptors will be checked and inadequate privileges on any of them will cause the error. Therefore, to answer the third question, we might have to dig deeper to see what happens behind the scene.

Tidbits of WinDBG tips

Q: How to know a thread's start address and its optional parameter?
A: On WinXP
001bff00 7732e489 ntdll!_RtlUserThreadStart+0x1b
001bff04 00ac1576 dbgex4!mainCRTStartup
001bff08 7ffd4000
001bff0c 00000000
001bff10 00000000
001bff14 00000000
001bff18 00000000
001bff1c 00ac1576 dbgex4!mainCRTStartup ; start address
001bff20 7ffd4000 ; optional parameter

On Vista
0088fb20 7782e489 ntdll!_RtlUserThreadStart+0x1b
0088fb24 7713361f kernel32!LoadLibraryW
0088fb28 00080000
0088fb2c 00000000
0088fb30 00000000
0088fb34 00000000
0088fb38 00000000
0088fb3c 7713361f kernel32!LoadLibraryW ; start address
0088fb40 00080000 ; optional parameter

They are 7th and 8th parameters.

(Excerpted from http://blogs.msdn.com/ntdebugging/archive/2009/03/06/it-s-not-my-fault-a-case-of-remote-code-injection-gone-bad.aspx)

Q: How to convert the time (System.DateTime, a value type) to an actual timestamp?
A: dq {address of the time} (dump the content of the time as a quad word to get the number of ticks)
.formats {quad word} & 0x3FFFFFFFFFFFFFFF (run .formats on the number of ticks with the 2 highest bits filtered out)

Q: How to find out the corresponding kernel object using the handle from the user mode?
A: The process id, thread id, and handle in the user mode are recognizable in kernel mode. They can be used to look for the corresponding kernel object in the kernel debugger.

For instance, the following is the output from the user mode debugger.
0:000> !handle 7b0 ff
Handle 7b0
Type Event
...
0:000> |
. 0 id: b24 create name: 07sample.exe

The following is the output from the local kernel debugger. The handle and process id from the user mode debugger are used directly in the kernel debugger.

lkd> !handle 7b0 7 0b24
processor number 0, process 00000b24
Searching for Process with Cid == b24
PROCESS 89490760 SessionId: 0 Cid: 0b24 Peb: 7ffda000 ParentCid: 0670
DirBase: 51c9e000 ObjectTable: e82902c8 HandleCount: 22.
Image: 07sample.exe

Handle table at e1839000 with 22 Entries in use
07b0: Object: 887a08e8 GrantedAccess: 001f0003 Entry: e1839f60
Object: 887a08e8 Type: (89befbf8) Event
ObjectHeader: 887a08d0 (old version)
HandleCount: 1 PointerCount: 2
Directory Object: e16a1368 Name: 07sample

Q: How to track down an invalid handle error?
A: Before we get into troubleshooting let’s look at a couple of scenarios for bad handles.
In the first bad handle scenario, let’s say your application closes handle 2 using CloseHandle(), however your application keeps the value 2 in a variable somewhere. In this scenario we will assume no other code has come along and opened a new object that is occupying element 2 of the handle table. If you go to make a file I/O call using handle 2 the object manager will catch this and your app will get an invalid handle exception. This is somewhat harmless but your app may crash if you don’t catch the exception and your I/O will obviously not complete.

In the second scenario we’ll say that your file I/O code closes the handle, and holds on to that handle value. Meanwhile another part of your application opens a registry key or some other object that is not a file object. Now your file I/O code goes to use handle 2 again. The problem is it’s not a handle to a file now. When the registry code opened the registry key element 2 was available so we now have a registry object in that location. If you go to do a file I/O on handle 2 you will get an invalid handle message.

Now in our final scenario, we close a file handle in our file I/O code and keep the handle around. In this case though we have different code that is also doing file I/O, It opens a file and gets handle value 2. Now you have big trouble because if the first file I/O code now writes to handle 2, and it should not be because it closed it! This handle now belongs to a different file. This means you have code basically doing a write into an unknown region for that code’s context and file format. This will result in file corruption and no invalid handle error.

So this really comes down to best practice. If you’re writing code and close a handle NULL IT OUT! That way you guarantee it will not be reused accidently at some other point.

CloseHandle(MyHandle);
MyHandle = NULL;

The following action plan can be used to track down the invalid handle.
1.Start gflags and under the image file tab, enter your application name in the image edit control.
2.Check Create User mode stack trace database.
3.Start the process under windbg. “WinDBG processname.exe”
4.In windbg Run !htrace -enable
5.Do a sxe ch. This will cause windbg to break on an invalid handle exception.
6.Run sx to confirm “ch - Invalid handle – break” should be set.
7.Enter g for go.
8.Let the process run until you get an invalid handle message. The debugger should break in.
9.Now all you have to do is run !htrace

Htrace will dump out all the call stacks for each handle that was opened or closed.

You need to take the invalid handle value and search backward to see where it was last opened, and where it was closed before that. It’s likely that the close before the last open is your culprit code path. Make sure that suspect close nulls that handle value out so it does not reuse it.

(Excerpted from http://blogs.msdn.com/ntdebugging/archive/2008/05/19/ntdebugging-puzzler-0x00000006-invalid-handle-can-you-handle-it.aspx)

Q: How to find out what service is hosted in svchost.exe?
A: 0:006> x /v svchost!*service*name*
pub global 010040b4 0 svchost!ServiceNames =
0:006> du poi(010040b4)
0009add0 "DnsCache"

Q: How to find out what type a kernel dispatcher object is when the !object extension command fails?
A: From the !thread command, we have the following display,
0: kd> !thread 89238998
THREAD 89238998 Cid 0a90.05fc Teb: 7ffad000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Non-Alertable
89238a88 NotificationTimer
[...]

0: kd> !object 89238a88
89238a88: Not a valid object (ObjectType.Name at 0x2710 invalid)

0: kd> dt _DISPATCHER_HEADER 89238a88
nt!_DISPATCHER_HEADER
+0x000 Type : 0x8 '' ; NOTIFICATION_TIMER (see the list below)
+0x001 Absolute : 0 ''
+0x002 Size : 0xa ''
+0x003 Inserted : 0x1 ''
+0x004 SignalState : 0
+0x008 WaitListHead : _LIST_ENTRY [ 0x89238a50 - 0x89238a50 ]

Type codes of kernel dispatcher objects:

Type Object
0 NOTIFICATION_EVENT
1 SYNCHRONIZATION_EVENT
2 MUTANT
3 PROCESS
4 QUEUE
5 SEMAPHORE
6 THREAD
7 (not assigned?)
8 NOTIFICATION_TIMER
9 SYNCHRONIZATION_TIMER

(Excerpted from http://computer.forensikblog.de/en/2006/02/dispatcher_header.html)

The approach could also be used to find out the type of the object, which is passed as the first parameter into nt!KeWaitForSingleObject.

Q: How to check stack overflow?
A: 0:000> dt _TEB 7ffde000
ntdll!_TEB
+0x000 NtTib : _NT_TIB
[...]
+0xe0c DeallocationStack : 0x00040000
[...]

0:000> dt _NT_TIB 7ffde000
MSVCR71!_NT_TIB
+0x000 ExceptionList : 0x0007ffb0 _EXCEPTION_REGISTRATION_RECORD
+0x004 StackBase : 0x00080000
+0x008 StackLimit : 0x0006f000
+0x00c SubSystemTib : (null)
+0x010 FiberData : 0x00001e00
+0x010 Version : 0x1e00
+0x014 ArbitraryUserPointer : (null)
+0x018 Self : 0x7ffde000 _NT_TIB

0:000> ? 0x00080000 - 0x0006f000 ; Current stack size = StackBase - StackLimit
Evaluate expression: 69632 = 00011000
0:000> ? 0x00080000 - 0x00040000
Evaluate expression: 262144 = 00040000 ; Max stack size = StackBase - DeallocationStack

There is more than adequate stack space left.

(Excerpted from http://msdn.microsoft.com/en-us/library/cc267849.aspx)

Q: How to dump memory addresses that have the "nt" string?
A: .foreach(obj {s -[1]a 0 0FFFFFFF "nt"}) {da /c 0n100 ${obj}}

Q: How to count a specified string in a file or output of commands?
A: .shell -i c:\handle.txt FIND /C "licensestatus"
.shell -i - -ci "dps 00226000 00230000" FIND /C "ntdll!"
.shell -i - -ci "~* kb" FIND /C "RaiseException"

Q: How to track the reference count of an object?
A: Assume ESI refers to the object itself and ESI+0x8 refers to its reference count.
ba w4 @esi+0x8 "[WinDBG script] @esi poi(@esi+8);k;g"

The WinDBG script takes the object and its reference count and prints them out.
.printf "this=%p",${$arg1}
.printf "\t"
.printf "refcount=%d",${$arg2}
.printf "\r\n"

Q: How to dump all the .NET exceptions on the heap?
A: .foreach (ex {!dumpheap -type Exception -short}){.echo "********************************";!pe –nested ${ex} }

Q: How to set a breakpoint on dynamically generated code?
A: Set a native breakpoint on mscorjit!CILJit::compileMethod

ChildEBP RetAddr Args to Child
001de8d0 7028722c 70bc7268 001dea90 001dea08 mscorjit!CILJit::compileMethod

Dump the third parameter to the function, where the first DWORD contains the method descriptor.

0:000> dd 001dea08 L1
001dea08 002b2ff8

0:000> !bpmd -md 002b2ff8
MethodDesc = 002b2ff8
Adding pending breakpoints...

0:000> !dumpmd 002b2ff8
Method Name: Advanced.NET.Debugging.Chapter4.TypeCast.Main(System.String[])
Class: 002b12f8
MethodTable: 002b300c
mdToken: 06000004
Module: 002b2c5c
IsJitted: no
CodeAddr: ffffffff

Q: How to determine the range of user space and system space?
A: lkd> x nt!mmhighestuseraddress
80567edc nt!MmHighestUserAddress
lkd> dp nt!mmhighestuseraddress l1
80567edc 7ffeffff

This indicates that user space ranges from the address 0x00000000 to 0x7FFEFFFF, and system space therefore ranges from 0x80000000 up to the highest possible address (which is 0xFFFFFFFF on a standard 32-bit Windows installation).

The same method can be used on 64-bit Windows as well.

lkd> dp nt!mmhighestuseraddress l1
fffff800`011b2748 000007ff`fffeffff

Q: How to find out which function returns a specific value?
A: wt -oR or tct; z(eax!=0xc000000d)

Q: How to set a breakpoint at Main for a .NET application?
A: The following command combination does not work for me although some blogs claim it works for them.
sxe ld:mscorwks.dll
!mx 03ObjTypes!*Main*  // retrieve fully-qualified method name
!bpmd 03ObjTypes Advanced.NET.Debugging.Chapter3.ObjTypes.Main

However, the following command combination does work for me.
sxe ld:mscorjit.dll
!mx 03ObjTypes!*Main*  // retrieve fully-qualified method name
!bpmd 03ObjTypes Advanced.NET.Debugging.Chapter3.ObjTypes.Main 

Q: How to identify a module header from the raw memory?
A: 0:000> dc 00400000
00400000  00905a4d 00000003 00000004 0000ffff  MZ..............
00400010  000000b8 00000000 00000040 00000000  ........@.......
00400020  00000000 00000000 00000000 00000000  ................
00400030  00000000 00000000 00000000 00000080  ................
00400040  0eba1f0e cd09b400 4c01b821 685421cd  ........!..L.!Th
00400050  70207369 72676f72 63206d61 6f6e6e61  is program canno
00400060  65622074 6e757220 206e6920 20534f44  t be run in DOS
00400070  65646f6d 0a0d0d2e 00000024 00000000  mode....$.......

Identify the header by the “MZ” string at the beginning of the header. Then use !dh to display the headers

Q:
A:

Annotated 0x86 Assembly -- Fundamentals Exercise

I tried out Debug Fundamentals Exercise 4: The GAMEOVER exercise on GES Blog. I did not make all right, especially the reverse engineering part. After spending some time on the assembly code of functions in the exercise, I list below their annotated assembly. It contains some interesting instructions for string manipulation.

0:000> uf dbgex4!main
dbgex4!main [c:\tmp\dbgex4.cpp @ 119]:
119 00ac12c1 mov edi,edi
119 00ac12c3 push ebp
119 00ac12c4 mov ebp,esp
119 00ac12c6 sub esp,4Ch ; allocate buffer[4C] on the stack
121 00ac12c9 lea eax,[ebp-4Ch] ; store it in EAX
121 00ac12cc push eax ; pass the buffer in callee
121 00ac12cd call dbgex4!snap (00ac1292)
122 00ac12d2 leave
122 00ac12d3 ret

0:000> uf dbgex4!snap
dbgex4!crack [c:\tmp\dbgex4.cpp @ 67]:
67 00ac1245 mov edi,edi
67 00ac1247 push ebp
67 00ac1248 mov ebp,esp
68 00ac124a mov ecx,dword ptr [ebp+8] ; store passed in buffer in ECX
71 00ac124d cmp byte ptr [ecx],0 ; check if it is empty
71 00ac1250 push esi
71 00ac1251 mov esi,ecx
71 00ac1253 mov eax,ecx
71 00ac1255 je dbgex4!crack+0x18 (00ac125d)

dbgex4!crack+0x12 [c:\tmp\dbgex4.cpp @ 71]:
71 00ac1257 inc eax
71 00ac1258 cmp byte ptr [eax],0
71 00ac125b jne dbgex4!crack+0x12 (00ac1257) ; the above three instructions move EAX to the NULL char

dbgex4!crack+0x18 [c:\tmp\dbgex4.cpp @ 72]:
72 00ac125d dec eax
74 00ac125e cmp eax,ecx
74 00ac1260 jbe dbgex4!crack+0x2d (00ac1272) ; the above three instructions move EAX one step back to the last non-NULL char

dbgex4!crack+0x1d [c:\tmp\dbgex4.cpp @ 74]:
74 00ac1262 push ebx

dbgex4!crack+0x1e [c:\tmp\dbgex4.cpp @ 77]:
77 00ac1263 mov bl,byte ptr [eax]
77 00ac1265 mov dl,byte ptr [esi]
77 00ac1267 mov byte ptr [esi],bl
77 00ac1269 inc esi
78 00ac126a mov byte ptr [eax],dl
78 00ac126c dec eax
78 00ac126d cmp eax,esi
78 00ac126f ja dbgex4!crack+0x1e (00ac1263) ; reverse the content of string

dbgex4!crack+0x2c [c:\tmp\dbgex4.cpp @ 78]:
78 00ac1271 pop ebx

dbgex4!crack+0x2d [c:\tmp\dbgex4.cpp @ 83]:
83 00ac1272 xor eax,eax ; zero out EAX
85 00ac1274 cmp byte ptr [ecx],0C3h ; check if the first char is 0C3
85 00ac1277 pop esi
85 00ac1278 je dbgex4!crack+0x3c (00ac1281)

dbgex4!crack+0x35 [c:\tmp\dbgex4.cpp @ 88]:
88 00ac127a inc eax
88 00ac127b cmp byte ptr [eax+ecx],0C3h
88 00ac127f jne dbgex4!crack+0x35 (00ac127a) ; the above three instructions search for 0C3 in the string. EXA stores the index of char -- 0C3. If there is no 0C3 in the string, the code is in trouble.

dbgex4!crack+0x3c [c:\tmp\dbgex4.cpp @ 91]:
91 00ac1281 inc eax ; turn the index into length
93 00ac1282 push eax
93 00ac1283 push ecx
93 00ac1284 call dbgex4!pop (00ac1216)
94 00ac1289 pop ebp
94 00ac128a ret 4

dbgex4!snap [c:\tmp\dbgex4.cpp @ 103]:
103 00ac1292 mov edi,edi
103 00ac1294 push ebp
103 00ac1295 mov ebp,esp
104 00ac1297 mov al,byte ptr [dbgex4!string (00ac3000)] ; al stores first char
104 00ac129c test al,al ; check if the string @ 00ac3000 is empty
104 00ac129e je dbgex4!snap+0x24 (00ac12b6)

dbgex4!snap+0xe [c:\tmp\dbgex4.cpp @ 104]:
104 00ac12a0 mov edx,dword ptr [ebp+8] ; edx stores destination buffer
104 00ac12a3 mov cl,al ; cl stores the first char
104 00ac12a5 mov eax,offset dbgex4!string (00ac3000) ; eax stores source buffer
104 00ac12aa sub edx,eax

dbgex4!snap+0x1a [c:\tmp\dbgex4.cpp @ 106]:
106 00ac12ac mov byte ptr [edx+eax],cl
106 00ac12af inc eax
106 00ac12b0 mov cl,byte ptr [eax]
106 00ac12b2 test cl,cl ; if cl = 0
106 00ac12b4 jne dbgex4!snap+0x1a (00ac12ac) ; the above six instructions copy data from source to desintation. The destination may not be NULL-terminated!

dbgex4!snap+0x24 [c:\tmp\dbgex4.cpp @ 110]:
110 00ac12b6 pop ebp
109 00ac12b7 jmp dbgex4!crack (00ac1245)

0:000> uf dbgex4!pop
dbgex4!pop [c:\tmp\dbgex4.cpp @ 49]:
49 00ac1216 mov edi,edi
49 00ac1218 push ebp
49 00ac1219 mov ebp,esp
51 00ac121b mov edx,dword ptr [ebp+0Ch] ; store the length
51 00ac121e push esi
51 00ac121f mov esi,dword ptr [ebp+8] ; store the buffer
53 00ac1222 mov al,byte ptr [esi+edx] ; store buffer[length]
53 00ac1225 mov ecx,esi
53 00ac1227 jmp dbgex4!pop+0x19 (00ac122f)

dbgex4!pop+0x13 [c:\tmp\dbgex4.cpp @ 54]:
54 00ac1229 mov byte ptr [ecx],al
54 00ac122b inc ecx
54 00ac122c mov al,byte ptr [ecx+edx]

dbgex4!pop+0x19 [c:\tmp\dbgex4.cpp @ 53]:
53 00ac122f test al,al
53 00ac1231 jne dbgex4!pop+0x13 (00ac1229) ; the above instructions move the content starting from length to the beginning of the string

dbgex4!pop+0x1d [c:\tmp\dbgex4.cpp @ 58]:
58 00ac1233 push esi
58 00ac1234 mov byte ptr [ecx],al ; set NULL-terminated
58 00ac1236 call dbgex4!boom (00ac11c5)
58 00ac123b pop esi
59 00ac123c pop ebp
59 00ac123d ret 8

0:000> uf dbgex4!boom
dbgex4!boom [c:\tmp\dbgex4.cpp @ 29]:
29 00ac11c5 mov edi,edi
29 00ac11c7 push ebp
29 00ac11c8 mov ebp,esp
33 00ac11ca mov eax,dword ptr [ebp+8]
33 00ac11cd mov cl,byte ptr [eax]
33 00ac11cf sub esp,2Ch ; reserve 2C on the stack
33 00ac11d2 test cl,cl
33 00ac11d4 je dbgex4!boom+0x20 (00ac11e5)

dbgex4!boom+0x11 [c:\tmp\dbgex4.cpp @ 33]:
33 00ac11d6 lea edx,[ebp-2Bh] ; set destination buffer with size of 2Bh
33 00ac11d9 sub edx,eax

dbgex4!boom+0x16 [c:\tmp\dbgex4.cpp @ 35]:
35 00ac11db mov byte ptr [edx+eax],cl
35 00ac11de inc eax
35 00ac11df mov cl,byte ptr [eax]
35 00ac11e1 test cl,cl ; if cl = 0
35 00ac11e3 jne dbgex4!boom+0x16 (00ac11db) ; the above instructions copy data from source (EAX) to desintation (EDX). If the source is larger than 2Bh, we have buffer overflow.

dbgex4!boom+0x20 [c:\tmp\dbgex4.cpp @ 38]:
38 00ac11e5 mov cl,byte ptr [ebp-2Ch]
38 00ac11e8 lea eax,[ebp-2Ch] ; set buffer with size of 2Ch
38 00ac11eb jmp dbgex4!boom+0x3f (00ac1204)

dbgex4!boom+0x28 [c:\tmp\dbgex4.cpp @ 38]:
38 00ac11ed mov cl,byte ptr [eax]
38 00ac11ef mov dl,byte ptr [eax]
38 00ac11f1 movzx ecx,cl ; convert to unsigned
38 00ac11f4 movzx edx,dl ; convert to unsigned
38 00ac11f7 shr ecx,4 ; ecx >>= 4
38 00ac11fa shl edx,4 ; edx <<= 4
38 00ac11fd or ecx,edx ; ecx |= edx
38 00ac11ff mov byte ptr [eax],cl ; store low 8 bits of ecx
38 00ac1201 inc eax
38 00ac1202 mov cl,byte ptr [eax]

dbgex4!boom+0x3f [c:\tmp\dbgex4.cpp @ 38]:
38 00ac1204 test cl,cl
38 00ac1206 jne dbgex4!boom+0x28 (00ac11ed) ; the above instructions switch the first four bits and the last four bits for each char in the string.

dbgex4!boom+0x43 [c:\tmp\dbgex4.cpp @ 40]:
40 00ac1208 mov eax,53454750h
41 00ac120d leave
41 00ac120e ret 4

Use .foreach to display objects

Thanks to Roberto Farah's blog on .foreach command usage, I try the command on a dump file and am impressed by its power.

0:002> !finalizequeue
SyncBlocks to be cleaned up: 0
MTA Interfaces to be released: 0
STA Interfaces to be released: 0
----------------------------------
generation 0 has 88 finalizable objects (001efc68->001efdc8)
generation 1 has 19 finalizable objects (001efc1c->001efc68)
generation 2 has 77 finalizable objects (001efae8->001efc1c)
Ready for finalization 0 objects (001efdc8->001efdc8)
Statistics:
MT Count TotalSize Class Name
...
00f99444 89 4984 UtilAPI.ServerProtectionItem
Total 184 objects

0:002> !dumpheap -mt 00f99444
Address MT Size
00ffb74c 00f99444 56
01004088 00f99444 56
010044e4 00f99444 56
...
010567cc 00f99444 56
01056904 00f99444 56
total 1683 objects
Statistics:
MT Count TotalSize Class Name
00f99444 1683 94248 UtilAPI.ServerProtectionItem
Total 1683 objects

There are total 1683 ServerProtectionItem instances, and I would like to know what IP address is in each instance.

0:002> !do 00ffb74c
Name: UtilAPI.ServerProtectionItem
MethodTable: 00f99444
EEClass: 02ff7d68
Size: 56(0x38) bytes
(C:\Program Files\Ipswitch\WS_FTP Server\WrapperUtilAPI.dll)
Fields:
MT Field Offset Type VT Attr Value Name
7911d5e4 4000298 4 PTR 0 instance 00000000 m_pObj
7910bff0 40003c2 10 System.UInt32 0 instance 486 m_dwID
7910bff0 40003c3 14 System.UInt32 0 instance 1 m_dwListenerID
7910bff0 40003c4 18 System.UInt32 0 instance 68 m_dwAccessDenyFlag
7910bff0 40003c5 1c System.UInt32 0 instance 65 m_dwEntryTypeFlag
7910bff0 40003c6 20 System.UInt32 0 instance 2147483647 m_dwCountTimespanSeconds
7910c878 40003c7 24 System.DateTime 1 instance 00ffb770 m_dEntryExpires
7910c878 40003c8 2c System.DateTime 1 instance 00ffb778 m_dEntryCreated
790fd8c4 40003c9 8 System.String 0 instance 00ffb784 m_pszIPAddress
790fd8c4 40003ca c System.String 0 instance 00ffb7b4 m_pszIPMask

0:002> !do 00ffb784
Name: System.String
MethodTable: 790fd8c4
EEClass: 790fd824
Size: 46(0x2e) bytes
(C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: 89.162.184.244
Fields:
MT Field Offset Type VT Attr Value Name
79102290 4000096 4 System.Int32 0 instance 15 m_arrayLength
79102290 4000097 8 System.Int32 0 instance 14 m_stringLength
790ff328 4000098 c System.Char 0 instance 38 m_firstChar
790fd8c4 4000099 10 System.String 0 shared static Empty

To manually display the IP address in a ServerProtectionItem instance, I have to !do twice. Since there are 1683 instances, the manual approach would be time-consuming and error-prone. In this case, .foreach command comes into the rescue. Since the output of !do does not serve the purpose well, I have to figure out how to display the managed object without it.

0:002>du poi(00ffb74c+0x8)+0xc
00ffb790 "89.162.184.244"

00ffb74c is the address of a ServerProtectionItem instance, 0x8 is the offset of m_pszIPAddress in ServerProtectionItem, and 0xc is the offset of m_firstChar in System.String.

0:002> .foreach /pS 3 /ps 2 (obj {!dumpheap -mt 00f99444}) {du poi(${obj}+0x8)+0xc}
00ffb790 "89.162.184.244"
010040cc "67.214.140.63"
01004528 "216.124.168.7"
...
010566dc "166.70.91.103"
01056810 "220.130.152.65"
01056948 "218.25.86.166"
Couldn't resolve error at 'total+0x8)+0xc'

Since the output from "!dumpheap -mt 00f99444" has the following format,

Address MT Size
00ffb74c 00f99444 56
01004088 00f99444 56
010044e4 00f99444 56
...
010567cc 00f99444 56
01056904 00f99444 56
total 1683 objects

/pS 3 is used to skip the initial three tokens in red, and /ps 2 is used to skip two tokens in blue repeatedly. The error message at the end is because of the line "total 1683 objects". It seems that .foreach does not provide a way to skip the last three tokens.

Memory leak, service hang, and more

The FTP server hanged in the load test and used about 2 GB memory. In my previous investigation, the FTP server hang was due to the deadlock triggered by the hang in PostgreSQL worker processes. As to high memory usage, it probably was because the deadlock blocked the finalizer thread. However, when I dig into the dump, I did not find any deadlock this time. Then I noticed that even there was not any connection to the server, it still used about 50% CPU.

0:013> !runaway 7
User Mode Time
Thread Time
13:834 0 days 12:35:08.281
14:f34 0 days 0:00:06.328
10:8b0 0 days 0:00:01.718
0:9f8 0 days 0:00:01.687
9:ed0 0 days 0:00:01.562
7:478 0 days 0:00:00.296
6:878 0 days 0:00:00.203
8:ebc 0 days 0:00:00.140
4:7ec 0 days 0:00:00.078
5:994 0 days 0:00:00.031
12:804 0 days 0:00:00.000
11:8a8 0 days 0:00:00.000
3:858 0 days 0:00:00.000
2:9d8 0 days 0:00:00.000
1:670 0 days 0:00:00.000
Kernel Mode Time
Thread Time
13:834 8 days 16:27:26.875
10:8b0 0 days 0:00:49.500
14:f34 0 days 0:00:20.546
9:ed0 0 days 0:00:14.187
0:9f8 0 days 0:00:01.328
7:478 0 days 0:00:00.437
6:878 0 days 0:00:00.265
8:ebc 0 days 0:00:00.156
4:7ec 0 days 0:00:00.125
2:9d8 0 days 0:00:00.093
5:994 0 days 0:00:00.046
3:858 0 days 0:00:00.046
12:804 0 days 0:00:00.015
11:8a8 0 days 0:00:00.000
1:670 0 days 0:00:00.000
Elapsed Time
Thread Time
0:9f8 10 days 2:46:48.317
2:9d8 10 days 2:46:48.270
1:670 10 days 2:46:48.270
3:858 10 days 2:46:47.708
4:7ec 10 days 2:46:47.692
5:994 10 days 2:46:46.833
6:878 10 days 2:46:46.817
7:478 10 days 2:46:44.301
8:ebc 10 days 2:46:44.161
9:ed0 10 days 2:46:44.098
10:8b0 10 days 2:46:43.958
11:8a8 10 days 2:46:43.911
12:804 10 days 2:36:43.301
13:834 10 days 0:20:23.708
14:f34 10 days 0:11:55.114

Thread 13 used most of the kernel and user mode time. It caused the starvation of the other threads. Then I displayed the unmanaged and managed stack traces of this thread along with its registers.

0:013> r
eax=00000002 ebx=00002000 ecx=00041000 edx=775f9a94 esi=00260000 edi=00040000
eip=77610191 esp=77588ee8 ebp=77588f00 iopl=0 nv up ei pl nz na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000206
ntdll!RtlpExtendHeap+0x10d:
77610191 23c7 and eax,edi

0:013> kb 100
ChildEBP RetAddr Args to Child
77588f00 775df8c1 001fa000 00040000 00277602 ntdll!RtlpExtendHeap+0x10d
77588fe8 77608752 0003fff8 00040000 00000000 ntdll!RtlpAllocateHeap+0x7db
77589060 775df258 00260000 00800000 0003fff8 ntdll!RtlAllocateHeap+0x1e3
775890a8 77607cd1 002768ca 00260000 00000000 ntdll!RtlpAllocateUserBlock+0xa2
77589120 77605955 776058a6 00000000 77094de9 ntdll!RtlpLowFragHeapAllocFromContext+0x785
7758918c 75e21859 00260000 00000000 00000f30 ntdll!RtlAllocateHeap+0x17c
775891c8 7568ccec 00000001 7568334c 00000000 nsi!NsiAllocateAndGetTable+0xb8
7758922c 7568d07c 049107c8 77589264 00000001 IPHLPAPI!GetIfTable+0x5a
7758924c 7568d0f3 70a0c704 00000001 04910000 IPHLPAPI!InternalGetTable+0x33
7758926c 70a0235b 70a0c704 04910000 00000000 IPHLPAPI!InternalGetIfTable+0x1f
77589280 70a016d6 d6f74c01 775893b0 00000001 inetmib1!LoadIfTable+0x70
775892b4 70a048f7 00000001 775893b4 77589308 inetmib1!UpdateCache+0x51
775892c4 72a8380d 000000a1 06ad9c68 775893b4 inetmib1!MibGetIfEntry+0xd
77589308 72a8415a 06ac18d0 775893b0 775893b4 snmpapi!ProcessQuery+0x26
77589330 72a842e7 0560cf58 00000000 775893a8 snmpapi!ProcessQueryList+0x48
77589358 70a02072 0560cf58 000000a1 775893a8 snmpapi!SnmpTfxQuery+0x41
77589374 00b11431 000000a1 775893a8 775893b0 inetmib1!SnmpExtensionQuery+0x1c
775894fc 00b136e2 072101f0 03202ed0 77589668 ftpaccess!getmacs+0x381 [d:\fts\licensing\client\sdks\client sdk\ipsa13\source\hardware.c @ 108]
77589634 00b14413 072101f0 03202ed0 77589704 ftpaccess!license_checkhw+0x202 [d:\fts\licensing\client\sdks\client sdk\ipsa13\source\license.c @ 184]
77589648 00b1506b 77589668 9c569d50 03202ed0 ftpaccess!license_initA+0x23 [d:\fts\licensing\client\sdks\client sdk\ipsa13\source\license.c @ 747]
77589704 00b14fd4 072101f0 00000001 032c0cb0 ftpaccess!CIpswitchLicense::Validate+0x6b [d:\fts\licensing\client\sdks\client sdk\ipsa86\ipswitchlicense.cpp @ 708]
77589728 00b19e29 77589954 7758974c 9c569c34 ftpaccess!CIpswitchLicense::Validate+0xc4 [d:\fts\licensing\client\sdks\client sdk\ipsa86\ipswitchlicense.cpp @ 689]
77589b68 00b1a4f5 77589ce0 77589ccc 06abe000 ftpaccess!IFTPLicense_Impl::Validate+0xc9 [d:\fts\ftpaccess\src\ftplicense_impl.cpp @ 183]
77589c84 00b1a6a0 77589d14 00000104 77589ccc ftpaccess!InitializeLicensing+0x95 [d:\fts\ftpaccess\src\ftplicense_impl.cpp @ 1077]
77589d38 717d609d 77589d54 717d6041 011d2548 ftpaccess!IFTPCreateLicense+0x40 [d:\fts\ftpaccess\src\ftplicense_impl.cpp @ 1168]

0:013> !clrstack
OS Thread Id: 0x834 (13)
ESP EIP
77589ccc 77610191 [NDirectMethodFrameStandalone: 77589ccc] .IFTPCreateLicense(Char*, UInt32)
77589cdc 035865a2 UtilAPI.Core.IsOKToRun()
77589ce0 0358625f [InlinedCallFrame: 77589ce0]
77589f58 03585cdc SSHServerAPI.Transport.FTPTransport.ProcessCommand()
77589fa4 03585499 SSHServerAPI.Transport.FTPTransport.ProcessCommand(Byte[], Int32)
77589fc0 03588b74 SSHServerAPI.Transport.FTPTransport.OnPlainData(Byte[], SSLApi.SSLClient)
77589fd4 03588a9c SSLApi.SSLServer.DecryptDataHelper(SSLApi.SSLClient)
7758e7fc 03587a47 SSLApi.SSLServer.DecryptData(Byte[], Int32, SSLApi.SSLClient)
7758e820 035878bc SSHServerAPI.Transport.FTPTransport.ReadCallback(System.IAsyncResult)
7758e858 70f5ee09 System.Net.LazyAsyncResult.Complete(IntPtr)
7758e890 70f61eba System.Net.ContextAwareResult.CompleteCallback(System.Object)
7758e898 717d01ef System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
7758e8b0 70f625b1 System.Net.ContextAwareResult.Complete(IntPtr)
7758e8c8 70f5ed70 System.Net.LazyAsyncResult.ProtectedInvokeCallback(System.Object, IntPtr)
7758e8f8 70f624b4 System.Net.Sockets.BaseOverlappedAsyncResult.CompletionPortCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
7758e930 7177cdc4 System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32, UInt32, System.Threading.NativeOverlapped*)
7758ead0 72bb1b4c [GCFrame: 7758ead0]

From the stack trace, it seemed that thread 13 was blocked in the heap manager.

0:013> uf ntdll!RtlpExtendHeap
...
ntdll!RtlpExtendHeap+0xf1:
77610175 8b4d0c mov ecx,dword ptr [ebp+0Ch]
77610178 81c100100000 add ecx,1000h
7761017e 394d08 cmp dword ptr [ebp+8],ecx
77610181 7431 je ntdll!RtlpExtendHeap+0x130 (776101b4)

ntdll!RtlpExtendHeap+0xff:
77610183 d16d08 shr dword ptr [ebp+8],1
77610186 394d08 cmp dword ptr [ebp+8],ecx
77610189 7303 jae ntdll!RtlpExtendHeap+0x10a (7761018e)

ntdll!RtlpExtendHeap+0x107:
7761018b 894d08 mov dword ptr [ebp+8],ecx

ntdll!RtlpExtendHeap+0x10a:
7761018e 8b4640 mov eax,dword ptr [esi+40h]
77610191 23c7 and eax,edi ; current IP
77610193 f7d8 neg eax
77610195 1bc0 sbb eax,eax
77610197 83e03c and eax,3Ch
7761019a 83c004 add eax,4
7761019d 50 push eax
7761019e 53 push ebx
7761019f 8d4508 lea eax,[ebp+8]
776101a2 50 push eax
776101a3 6a00 push 0
776101a5 8d45fc lea eax,[ebp-4]
776101a8 50 push eax
776101a9 6aff push 0FFFFFFFFh
776101ab e8b87bfeff call ntdll!ZwAllocateVirtualMemory (775f7d68)
776101b0 85c0 test eax,eax
776101b2 7cc1 jl ntdll!RtlpExtendHeap+0xf1 (77610175)
...

I unassembled RtlpExtendHeap function. There is indeed a loop. So thread 13 has been spinning in a loop most of the time. Then the question is why this thread has been spinning in an infinite loop.

0:013> !gle
LastErrorValue: (Win32) 0x8 (8) - Not enough storage is available to process this command.
LastStatusValue: (NTSTATUS) 0xc0000017 - {Not Enough Quota} Not enough virtual memory or paging file quota is available to complete the specified operation.

So it seemed that due to the high memory usage, the heap manager failed to allocate memory and somehow ran into an infinite loop. It caused the starvation of the other threads and thereby the service hang. Then the next question is what caused the high memory usage. The usual answer is memory leak. Then which code caused the memory leak -- unmanged code, managed code, or both?

0:013> !eeheap -gc
Number of GC Heaps: 1
generation 0 starts at 0x01343340
generation 1 starts at 0x01343334
generation 2 starts at 0x011d1000
ephemeral segment allocation context: none
segment begin allocated size
011d0000 011d1000 0134334c 0x0017234c(1516364)
Large object heap starts at 0x021d1000
segment begin allocated size
021d0000 021d1000 021d68d0 0x000058d0(22736)
Total Size 0x177c1c(1539100)
------------------------------
GC Heap Size 0x177c1c(1539100)

Since the managed heap only used about 1.5 MB memory, the memory leak did not come from the managed code.

0:013> !heap -s
LFH Key : 0x1ed5084c
Termination on corruption : DISABLED
Heap Flags Reserv Commit Virt Free List UCR Virt Lock Fast
(k) (k) (k) (k) length blocks cont. heap
-----------------------------------------------------------------------------
00260000 00000002 1921552 1921552 1921552 43 177 262 0 ec LFH
00010000 00008000 64 4 64 2 1 1 0 0
000c0000 00001002 1088 136 1088 23 7 2 0 0 LFH
00790000 00041002 256 28 256 2 5 1 0 0
00050000 00001002 1088 968 1088 3 9 2 0 0 LFH
00b40000 00001002 64 32 64 30 1 1 0 0
011c0000 00001002 7232 5504 7232 1385 130 4 0 1c LFH
External fragmentation 25 % (130 free blocks)
032e0000 00001002 256 128 256 2 10 1 0 5 LFH
00c40000 00001002 64 12 64 4 2 1 0 0
035a0000 00001002 256 92 256 2 2 1 0 0 LFH
04d70000 00001002 1280 628 1280 224 44 2 0 2 LFH
04f90000 00001002 1088 628 1088 112 25 2 0 6 LFH
04de0000 00011002 256 4 256 1 2 1 0 0
052d0000 00001002 64 4 64 2 1 1 0 0
054d0000 00001002 64 4 64 2 1 1 0 0
05200000 00001002 64 16 64 13 1 1 0 0
053f0000 00001002 256 116 256 5 5 1 0 3 LFH
05f00000 00001003 256 4 256 2 1 1 0 bad
060c0000 00001003 256 4 256 2 1 1 0 bad
04910000 00001002 64 4 64 1 1 1 0 0
-----------------------------------------------------------------------------

One heap used about 1.9 GB memory. So it seemed that the memory leak was from the unmanaged code.

0:013> !handle 0 f
...
245442 Handles
Type Count
Event 63093
Section 16
File 125795
Directory 2
Mutant 4
Semaphore 36
Key 56460
Token 1
Thread 27
IoCompletion 7
Timer 1

There were a lot of event, file and key handles open. It seemed that the memory leak was caused by the handle leak.

The event was named.

Handle 000f0188
Type Event
Attributes 0
GrantedAccess 0x1f0003:
Delete,ReadControl,WriteDac,WriteOwner,Synch
QueryState,ModifyState
HandleCount 64096
PointerCount 64098
Name \BaseNamedObjects\licensestatus
No object specific information available

It was pretty straighfoward to find out which code left the handle open. It was the license code.

There was no name associated with the file handle. They might be sockets.

Handle 000f0190
Type File
Attributes 0
GrantedAccess 0x100080:
Synch
ReadAttr
HandleCount 2
PointerCount 3
No object specific information available

The registry key handle had a name associcated to it as well,

Handle 000f01b4
Type Key
Attributes 0
GrantedAccess 0x3:
None
QueryValue,SetValue
HandleCount 2
PointerCount 3
Name \REGISTRY\MACHINE\SOFTWARE\Microsoft\RFC1156Agent\CurrentVersion\Parameters
No object specific information available

The name had something to do with SNMP. The license code used SNMP to communicate with the license server.

Since these three types of handles had been leaking at the same time, it indicated that they might be related and probably all came from the license code.

After the code review, the event handle leak was because of the early return from a license activation function without closing it. The license activation function is called when the server creates a license object or refreshes an existing license object. What is interesting was why the server needed to create so many license objects or keep refreshing the license object. From the following stack trace of the managed code,

77589ccc 77610191 [NDirectMethodFrameStandalone: 77589ccc] .IFTPCreateLicense(Char*, UInt32)
77589cdc 035865a2 UtilAPI.Core.IsOKToRun()
77589ce0 0358625f [InlinedCallFrame: 77589ce0]
77589f58 03585cdc SSHServerAPI.Transport.FTPTransport.ProcessCommand()

It indicated that the server tried to create the license object when the client connected to it . However, the license object should be created during the server startup and would not be set to NULL in the lifetime of the server. Therefore, it seemed that the license object had never been successfully created and in the load test, each connection from the client triggered the server to create the license object and thereby invoked the license activation function. Then I checked the per-process global license object. It was indeed NULL. When I checked the server log, I found tons of the error message -- "License file is for wrong hardware". It seemed that the culprit was the license file.

Invalid instruction pointer

The web server has encountered several random crashes recently. Two crash dumps have been saved. Both dump files display the similar top stack trace.

I use [] instead of angle brackets to enclose templates below.

The stack trace comes from one dump:

0:007> kb 100
ChildEBP RetAddr Args to Child
WARNING: Frame IP not in any known module. Following frames may be wrong.
0181f9c8 02a5952c 0745e6d8 02a59568 00000000 0x1f
0181f9d0 02a59568 00000000 02a5949b 00000001 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x2c [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2574]
0181f9d8 02a5949b 00000001 022a16b8 77d04239 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`scalar deleting destructor'+0x8
0181f9e4 77d04239 0745e6d8 022a16b8 022a16b8 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::Release+0x1b [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2588]
0181f9f8 76f9f619 022a16b8 030f96d0 76f9b7e6 oleaut32!VariantClear+0xb1
0181fa04 76f9b7e6 030f96d0 0229c880 022a41e0 jscript!VAR::Clear+0x5d
0181fa1c 76f94058 00000000 022a41e0 02291eb0 jscript!GcAlloc::ReclaimAll+0x40
0181fa38 76f9b74b 00000001 02291d1c 02291cb0 jscript!GcContext::Reclaim+0x89
0181fa50 76f98753 0181fa80 76f9b0d3 00000000 jscript!IScavengerBase::UnlinkFromGc+0x5b
0181fa58 76f9b0d3 00000000 00000000 00000010 jscript!ScavVarList::Init+0x2d
0181fa80 76f9b57d 0181fadc 0181fb08 008ca390 jscript!CSession::Close+0xb5
0181faa0 6400189b 022c3d18 f7bb5dd5 0181fadc jscript!COleScript::Close+0x7c
0181fac8 003635c5 0181fae0 0181fb08 0181fbb4 Core!CActiveScriptEngine::~CActiveScriptEngine+0x5b [d:\fts\ws_ftp web server\core\activescriptengine.cpp @ 41]
0181fad8 0036fd70 f7b10f15 0181fc40 0181fbcc WSFTPWebServer!CWebActiveScriptEngine::~CWebActiveScriptEngine+0x85 [d:\fts\ws_ftp web server\nmwebserver\webactivescriptengine.cpp @ 29]
0181fbb4 003713d7 0181fc88 0732e910 06d2b390 WSFTPWebServer!CWebTcp::_ProcessScript+0x270 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1752]
0181fc4c 003710b4 0181fc88 0732e910 06d2b390 WSFTPWebServer!CWebTcp::_ProcessFile+0x1e7 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1932]
0181fca8 0036f94a 0181fd6c 0732e910 06d2b390 WSFTPWebServer!CWebTcp::ProcessFile+0x64 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1888]
0181fd08 003696b5 0181fd6c 0732e910 0204f1c8 WSFTPWebServer!CWebTcp::_ProcessRequest+0x30a [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1696]
0181ff10 6404cd10 f7bb5829 00000000 008ca368 WSFTPWebServer!CWebTcp::DoTask+0x6e5 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 220]
0181ff4c 6405b17e f7bb581d 00000000 00000000 Core!CThreadPoolThread::_Run+0x80 [d:\fts\ws_ftp web server\core\threadpool.cpp @ 404]
0181ff78 781329bb 008ca368 f7d07408 00000000 Core!CWorkerThread::_ThreadProc+0x3e [d:\fts\ws_ftp web server\core\workerthread.cpp @ 100]
0181ffb0 78132a47 00000000 77e64829 008ca390 msvcr80!_endthreadex+0x3b
0181ffb8 77e64829 008ca390 00000000 00000000 msvcr80!_endthreadex+0xc7
0181ffec 00000000 781329e1 008ca390 00000000 kernel32!BaseThreadStart+0x34

The stack trace comes from the other dump:

0:007> kb 100
ChildEBP RetAddr Args to Child
WARNING: Frame IP not in any known module. Following frames may be wrong.
0171d7e4 02a5952c 03035ab8 02a59568 00000000 0x46005f
0171d7ec 02a59568 00000000 02a5949b 00000001 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x2c [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2574]
0171d7f4 02a5949b 00000001 02285000 77d04239 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`scalar deleting destructor'+0x8
0171d800 77d04239 03035ab8 003fd950 02285000 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::Release+0x1b [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2588]
0171d814 76f9f619 02285000 02285000 76f9f361 oleaut32!VariantClear+0xb1
0171d820 76f9f361 003fd950 02229c50 003fc658 jscript!VAR::Clear+0x5d
0171d84c 76fc633a 02229c70 00000000 02229c50 jscript!GcAlloc::ReclaimGarbage+0x74
0171d868 76f9f4f6 00000002 0171de04 0171da68 jscript!GcContext::Reclaim+0x82
0171d87c 76f9f6bb 0171de04 02266988 02266988 jscript!GcContext::Collect+0xa5
0171da54 76fa5996 0171de04 00000000 0171db70 jscript!CScriptRuntime::Run+0xfd
0171db18 76fa6e7e 0171de04 00000001 030f9960 jscript!ScrFncObj::Call+0x69
0171dbac 76fa5f15 003f8178 00000000 00000003 jscript!NameTbl::InvokeInternal+0x218
0171dbd8 76fa7bb8 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xfb
0171dc1c 76fa64ea 003f8178 0171dc3c 00000003 jscript!VAR::InvokeByName+0x164
0171dc5c 76fa6aa3 003f8178 00000003 0171de04 jscript!VAR::InvokeDispName+0x43
0171dc80 76fa7abe 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xb9
0171de74 76fa5996 0171e224 00000000 0171df90 jscript!CScriptRuntime::Run+0x18fb
0171df38 76fa6e7e 0171e224 00000003 030f99d0 jscript!ScrFncObj::Call+0x69
0171dfcc 76fa5f15 003f8178 00000000 00000003 jscript!NameTbl::InvokeInternal+0x218
0171dff8 76fa7bb8 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xfb
0171e03c 76fa64ea 003f8178 0171e05c 00000003 jscript!VAR::InvokeByName+0x164
0171e07c 76fa6aa3 003f8178 00000003 0171e224 jscript!VAR::InvokeDispName+0x43
0171e0a0 76fa7abe 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xb9
0171e294 76fa5996 0171e644 00000000 0171e3b0 jscript!CScriptRuntime::Run+0x18fb
0171e358 76fa6e7e 0171e644 00000001 030f9ae0 jscript!ScrFncObj::Call+0x69
0171e3ec 76fa5f15 003f8178 00000000 00000003 jscript!NameTbl::InvokeInternal+0x218
0171e418 76fa7bb8 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xfb
0171e45c 76fa64ea 003f8178 0171e47c 00000003 jscript!VAR::InvokeByName+0x164
0171e49c 76fa6aa3 003f8178 00000003 0171e644 jscript!VAR::InvokeDispName+0x43
0171e4c0 76fa7abe 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xb9
0171e6b4 76fa5996 0171ea64 00000000 0171e7d0 jscript!CScriptRuntime::Run+0x18fb
0171e778 76fa6e7e 0171ea64 00000000 022228d8 jscript!ScrFncObj::Call+0x69
0171e80c 76fa5f15 003f8178 00000000 00000001 jscript!NameTbl::InvokeInternal+0x218
0171e838 76fa7bb8 003f8178 00000000 00000001 jscript!VAR::InvokeByDispID+0xfb
0171e87c 76fa64ea 003f8178 0171e89c 00000001 jscript!VAR::InvokeByName+0x164
0171e8bc 76fa6aa3 003f8178 00000001 0171ea64 jscript!VAR::InvokeDispName+0x43
0171e8e0 76fa7abe 003f8178 00000000 00000001 jscript!VAR::InvokeByDispID+0xb9
0171ead4 76fa5996 0171ee90 0171ebec 00000000 jscript!CScriptRuntime::Run+0x18fb
0171eb98 76fbb951 0171ee90 00000000 00000000 jscript!ScrFncObj::Call+0x69
0171ec14 76fa7b7e 003f8178 0171eca4 0171ee90 jscript!JsEval+0x10b
0171ec4c 76fa7316 0171ee90 00000001 02222908 jscript!NatFncObj::Call+0x41
0171ece0 76fa5f15 003f8178 0227be50 00000003 jscript!NameTbl::InvokeInternal+0xd5
0171ed0c 76fa7abe 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xfb
0171ef00 76fa5996 0171f2b0 00000000 0171f01c jscript!CScriptRuntime::Run+0x18fb
0171efc4 76fa6e7e 0171f2b0 00000000 022229f8 jscript!ScrFncObj::Call+0x69
0171f058 76fa5f15 003f8178 00000000 00000001 jscript!NameTbl::InvokeInternal+0x218
0171f084 76fa7bb8 003f8178 00000000 00000001 jscript!VAR::InvokeByDispID+0xfb
0171f0c8 76fa64ea 003f8178 0171f0e8 00000001 jscript!VAR::InvokeByName+0x164
0171f108 76fa6aa3 003f8178 00000001 0171f2b0 jscript!VAR::InvokeDispName+0x43
0171f12c 76fa7abe 003f8178 00000000 00000001 jscript!VAR::InvokeByDispID+0xb9
0171f320 76fa5996 0171f6d0 00000000 0171f43c jscript!CScriptRuntime::Run+0x18fb
0171f3e4 76fa6e7e 0171f6d0 00000001 02222b58 jscript!ScrFncObj::Call+0x69
0171f478 76fa5f15 003f8178 00000000 00000003 jscript!NameTbl::InvokeInternal+0x218
0171f4a4 76fa7bb8 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xfb
0171f4e8 76fa64ea 003f8178 0171f508 00000003 jscript!VAR::InvokeByName+0x164
0171f528 76fa6aa3 003f8178 00000003 0171f6d0 jscript!VAR::InvokeDispName+0x43
0171f54c 76fa7abe 003f8178 00000000 00000003 jscript!VAR::InvokeByDispID+0xb9
0171f740 76fa5996 00000000 76f9ff88 00000000 jscript!CScriptRuntime::Run+0x18fb
0171f804 76fa57e5 00000000 00000000 00000000 jscript!ScrFncObj::Call+0x69
0171f87c 76f9bd59 02295eb8 00000000 00000000 jscript!CSession::Execute+0xb8
0171f8cc 76f9bf89 00000000 0171f998 0171f9cc jscript!COleScript::ExecutePendingScripts+0x141
0171f92c 76f9bdec 05700030 00000000 00000000 jscript!COleScript::ParseScriptTextCore+0x221
0171f958 640017f7 003f7e7c 05700030 00000000 jscript!COleScript::ParseScriptText+0x2b
0171f9cc 0036e56b 05c1a018 00000001 73052595 Core!CActiveScriptEngine::ParseScript+0xf7 [d:\fts\ws_ftp web server\core\activescriptengine.cpp @ 273]
0171fac8 0036fc76 0171faf8 01f2ada0 05c1a018 WSFTPWebServer!CWebTcp::_ProcessScriptEx+0x61b [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1430]
0171fbb4 003713d7 0171fc88 01f2ada0 03034ed8 WSFTPWebServer!CWebTcp::_ProcessScript+0x176 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1746]
0171fc4c 003710b4 0171fc88 01f2ada0 03034ed8 WSFTPWebServer!CWebTcp::_ProcessFile+0x1e7 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1932]
0171fca8 0036f94a 0171fd6c 01f2ada0 03034ed8 WSFTPWebServer!CWebTcp::ProcessFile+0x64 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1888]
0171fd08 003696b5 0171fd6c 01f2ada0 0216d620 WSFTPWebServer!CWebTcp::_ProcessRequest+0x30a [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1696]
0171ff10 6404cd10 73053b25 00000000 008ca120 WSFTPWebServer!CWebTcp::DoTask+0x6e5 [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 220]
0171ff4c 6405b17e 73053b11 00000000 00000000 Core!CThreadPoolThread::_Run+0x80 [d:\fts\ws_ftp web server\core\threadpool.cpp @ 404]
0171ff78 781329bb 008ca120 73102f5d 00000000 Core!CWorkerThread::_ThreadProc+0x3e [d:\fts\ws_ftp web server\core\workerthread.cpp @ 100]
0171ffb0 78132a47 00000000 77e64829 008ca148 msvcr80!_endthreadex+0x3b
0171ffb8 77e64829 008ca148 00000000 00000000 msvcr80!_endthreadex+0xc7
0171ffec 00000000 781329e1 008ca148 00000000 kernel32!BaseThreadStart+0x34

The top instruction pointers from both dump files are obviously invalid. And WinDBG displays the warning: Frame IP not in any known module. Following frames may be wrong.

Due to the warning from WinDBG, I made a quick check to ensure the stack traces are indeed correct.

0:007> ub 02a5952c
IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x8 [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2574]:
02a59508 c7069c71a902 mov dword ptr [esi],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a9719c)
02a5950e c746088871a902 mov dword ptr [esi+8],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a97188)
02a59515 c7460c7071a902 mov dword ptr [esi+0Ch],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a97170)
02a5951c c74614010000c0 mov dword ptr [esi+14h],0C0000001h
02a59523 7407 je IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x2c (02a5952c)
02a59525 8b01 mov eax,dword ptr [ecx]
02a59527 8b5004 mov edx,dword ptr [eax+4]
02a5952a ffd2 call edx

0:007> ub 02a59568
IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x5b:
02a5955b cc int 3
02a5955c cc int 3
02a5955d cc int 3
02a5955e cc int 3
02a5955f cc int 3
IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`scalar deleting destructor':
02a59560 56 push esi
02a59561 8bf1 mov esi,ecx
02a59563 e898ffffff call IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense] (02a59500)
...

Since each unassembled code from ub command ends up with call instruction, it seems that the stack trace is correct and the warning is due to the invalid instruction pointer. Next, I tried to figure out where the correct instruction pointer should be.

I displayed the stack trace again with the calling convention.

0:007> kv
ChildEBP RetAddr Args to Child
WARNING: Frame IP not in any known module. Following frames may be wrong.
0181f9c8 02a5952c 0745e6d8 02a59568 00000000 0x1f
0181f9d0 02a59568 00000000 02a5949b 00000001 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x2c (FPO: [0,0,4]) (CONV: thiscall) [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2574]
0181f9d8 02a5949b 00000001 022a16b8 77d04239 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`scalar deleting destructor'+0x8 (FPO: [1,0,4]) (CONV: thiscall)
0181f9e4 77d04239 0745e6d8 022a16b8 022a16b8 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::Release+0x1b (FPO: [1,0,4]) (CONV: stdcall) [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2588]
0181f9f8 76f9f619 022a16b8 030f96d0 76f9b7e6 oleaut32!VariantClear+0xb1 (FPO: [1,0,0])
0181fa04 76f9b7e6 030f96d0 0229c880 022a41e0 jscript!VAR::Clear+0x5d (FPO: [0,0,0])
0181fa1c 76f94058 00000000 022a41e0 02291eb0 jscript!GcAlloc::ReclaimAll+0x40 (FPO: [0,1,0])
0181fa38 76f9b74b 00000001 02291d1c 02291cb0 jscript!GcContext::Reclaim+0x89 (FPO: [1,2,0])
0181fa50 76f98753 0181fa80 76f9b0d3 00000000 jscript!IScavengerBase::UnlinkFromGc+0x5b (FPO: [0,1,0])
0181fa58 76f9b0d3 00000000 00000000 00000010 jscript!ScavVarList::Init+0x2d (FPO: [4,0,0])
0181fa80 76f9b57d 0181fadc 0181fb08 008ca390 jscript!CSession::Close+0xb5 (FPO: [0,1,4])
0181faa0 6400189b 022c3d18 f7bb5dd5 0181fadc jscript!COleScript::Close+0x7c (FPO: [1,3,4])
0181fac8 003635c5 0181fae0 0181fb08 0181fbb4 Core!CActiveScriptEngine::~CActiveScriptEngine+0x5b (FPO: [0,4,0]) (CONV: thiscall) [d:\fts\ws_ftp web server\core\activescriptengine.cpp @ 41]
0181fad8 0036fd70 f7b10f15 0181fc40 0181fbcc WSFTPWebServer!CWebActiveScriptEngine::~CWebActiveScriptEngine+0x85 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\fts\ws_ftp web server\nmwebserver\webactivescriptengine.cpp @ 29]
0181fbb4 003713d7 0181fc88 0732e910 06d2b390 WSFTPWebServer!CWebTcp::_ProcessScript+0x270 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1752]
0181fc4c 003710b4 0181fc88 0732e910 06d2b390 WSFTPWebServer!CWebTcp::_ProcessFile+0x1e7 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1932]
0181fca8 0036f94a 0181fd6c 0732e910 06d2b390 WSFTPWebServer!CWebTcp::ProcessFile+0x64 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1888]
0181fd08 003696b5 0181fd6c 0732e910 0204f1c8 WSFTPWebServer!CWebTcp::_ProcessRequest+0x30a (FPO: [Non-Fpo]) (CONV: thiscall) [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 1696]
0181ff10 6404cd10 f7bb5829 00000000 008ca368 WSFTPWebServer!CWebTcp::DoTask+0x6e5 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\fts\ws_ftp web server\nmwebserver\webserver.cpp @ 220]
0181ff4c 6405b17e f7bb581d 00000000 00000000 Core!CThreadPoolThread::_Run+0x80 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\fts\ws_ftp web server\core\threadpool.cpp @ 404]

Since I had the return address, I unassembled it backward.

0:007> ub 02a5952c L10
IFtpSrvAPI![thunk]:ATL::CComObject[CFTPLicense]::QueryInterface`adjustor{8}'+0xc:
02a594fc cc int 3
02a594fd cc int 3
02a594fe cc int 3
02a594ff cc int 3
IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense] [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2572]:
02a59500 56 push esi
02a59501 8bf1 mov esi,ecx ; move this from ecx to esi
02a59503 8b4e18 mov ecx,dword ptr [esi+18h] ; move object at offset 18h
02a59506 85c9 test ecx,ecx
02a59508 c7069c71a902 mov dword ptr [esi],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a9719c)
02a5950e c746088871a902 mov dword ptr [esi+8],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a97188)
02a59515 c7460c7071a902 mov dword ptr [esi+0Ch],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a97170)
02a5951c c74614010000c0 mov dword ptr [esi+14h],0C0000001h
02a59523 7407 je IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x2c (02a5952c)
02a59525 8b01 mov eax,dword ptr [ecx] ; move vtable to eax
02a59527 8b5004 mov edx,dword ptr [eax+4] ; move function at offset 4
02a5952a ffd2 call edx ; call function

Since the calling convention for the destructor of ATL::CComObject[CFTPLicense] is thiscall, this pointer would be passed through ecx register. Then the object at offset 0x18 is stored in ecx register. If the object has vtable, its vtable is stored in eax register, and the function at offset 0x04 of the vtable is invoked.

From the above code, at the very beginning of the function, esi register is used to store this pointer from ecx register. Even though esi register has not been modified before the call instruction, it is possible that it would be modified inside the invoked virtual function. To check whether esi register indeed stores this pointer, I check the frame 3 with the following line of stack trace,

0181f9e4 77d04239 0745e6d8 022a16b8 022a16b8 IFtpSrvAPI!ATL::CComObject[CFTPLicense]::Release+0x1b (FPO: [1,0,4]) (CONV: stdcall) [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2588]

Since the calling convention is stdcall, the first parameter would be the implicit this pointer. Since it matches to the value in esi register (see below). esi register has not been modified.

0:007> r
eax=04362bd8 ebx=022a1928 ecx=0633a580 edx=0000001f esi=0745e6d8 edi=00000009
eip=0000001f esp=0181f9cc ebp=0181f9f8 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00010202
0000001f ?? ???

Then I display the information for this object.

0:007> dt -n ATL::CComObject[CFTPLicense] 0745e6d8
IFtpSrvAPI!ATL::CComObject[CFTPLicense]
+0x014 m_dwRef : -1073741823
+0x014 m_pOuterUnknown : 0xc0000001 IUnknown
+0x000 __VFN_table : 0x02a9719c
+0x004 m_pSD : ATL::CComPtr { 00000000 }
=02ab94c0 ATL::IDispatchImpl,&_GUID_0b6d7133_466e_4bd5_b0bf_47617be2dd3d,&ATL::CAtlModule::m_libid,1,0,ATL::CComTypeInfoHolder>::_tih : ATL::CComTypeInfoHolder
+0x008 __VFN_table : 0x02a97188
+0x00c __VFN_table : 0x02a97170
+0x010 m_dwCurrentSafety : 0
+0x018 m_pLicense : 0x0633a580 FTP::IFTPLicense

However, when I deferenced ecx register to retrieve the vtable and then retrieved the virtual function, I had the following result,

0:007> dd 0633a580 l1
0633a580 073c6bb0

The value does not match to that in eax register.

0:007> dps 073c6bb0+0x4 l1
073c6bb4 00000020

The value does not match to the instruction pointer at the top.

Then I used u command to unassemble the code forward. Combining the output from both ub and u commands, I had the following code,

IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense] [c:\program files\microsoft visual studio 8\vc\atlmfc\include\atlcom.h @ 2572]:
02a59500 56 push esi
02a59501 8bf1 mov esi,ecx
02a59503 8b4e18 mov ecx,dword ptr [esi+18h]
02a59506 85c9 test ecx,ecx ; if (m_pLicense)
02a59508 c7069c71a902 mov dword ptr [esi],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a9719c)
02a5950e c746088871a902 mov dword ptr [esi+8],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a97188)
02a59515 c7460c7071a902 mov dword ptr [esi+0Ch],offset IFtpSrvAPI!ATL::CComObject[CFTPLicense]::`vftable' (02a97170)
02a5951c c74614010000c0 mov dword ptr [esi+14h],0C0000001h ; m_dwRef = -(LONG_MAX/2)
02a59523 7407 je IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x2c (02a5952c)
02a59525 8b01 mov eax,dword ptr [ecx]
02a59527 8b5004 mov edx,dword ptr [eax+4]
02a5952a ffd2 call edx ; m_pLicense->RELEASE()
02a5952c c7461800000000 mov dword ptr [esi+18h],0 ; m_pLicense = NULL
02a59533 8b0d5cfcab02 mov ecx,dword ptr [IFtpSrvAPI!ATL::_pAtlModule (02abfc5c)]
02a59539 8b01 mov eax,dword ptr [ecx]
02a5953b 8b5008 mov edx,dword ptr [eax+8]
02a5953e ffd2 call edx ; _pAtlModule->Unlock()
02a59540 8b7604 mov esi,dword ptr [esi+4]
02a59543 85f6 test esi,esi
02a59545 7408 je IFtpSrvAPI!ATL::CComObject[CFTPLicense]::~CComObject[CFTPLicense]+0x4f (02a5954f)

From ATL source code, we have

virtual ~CComObject() throw()
{
m_dwRef = -(LONG_MAX/2);
FinalRelease();
#ifdef _ATL_DEBUG_INTERFACES
_AtlDebugInterfacesModule.DeleteNonAddRefThunk(_GetRawUnknown());
#endif
_pAtlModule->Unlock();
}

From CFTPLicense sourc code, we have

void CFTPLicense::FinalRelease()
{
if (m_pLicense) m_pLicense->RELEASE();
m_pLicense = NULL;
}

It seems that the function FinalRelease has been inlined due to optimization. From this point, it seem that the last function invoked is m_pLicense->RELEASE().

Then I attached a debugger to the web server and found out IFTPLicense_Impl::Release was indeed at offset 4 of the vtable.

Then I unassembled the Release function as following,

0:007> u ftpaccess!IFTPLicense_Impl::Release
ftpaccess!IFTPLicense_Impl::Release [d:\fts\ftpaccess\src\ftplicense_impl.cpp @ 139]:
02b2a360 56 push esi
02b2a361 8bf1 mov esi,ecx
02b2a363 8d4604 lea eax,[esi+4]
02b2a366 50 push eax
02b2a367 ff158c00b302 call dword ptr [ftpaccess!_imp__InterlockedDecrement (02b3008c)]
02b2a36d 85c0 test eax,eax
02b2a36f 7f34 jg ftpaccess!IFTPLicense_Impl::Release+0x45 (02b2a3a5)
02b2a371 683c6bb302 push offset ftpaccess!g_sLicenseCS (02b36b3c)

From the unassembled code, esi register is used to store the value of ecx register at the very beginning of the function, so I concluded the last function call was IFTPLicense_Impl::Release and the instruction pointer could be right at the call instruction.

There is a per-process global license object, which is also stored at offset 0x18 of ATL::CComObject[CFTPLicense] object. However, in both dump files, the global instance is different from those stored at offset 0x18. In one case, the global instance is NULL. So to figure out the crash, I think we have to figure out why those pointers are out of sync. One possible reason could be that we have over-released IFTPLicense_Impl object.