Save Our Souls – Troubleshooting Handle Leak with Application Verifier and WinDBG !htrace facilities

Handles are data structures that represent open instances of basic operating system objects applications interact with, such as files, registry keys, synchronization primitives, and shared memory. There are two limits related to the number of handles a process can create: the maximum number of handles the system sets for a process and the amount of memory available to store the handles and the objects the application is referencing with its handles.  Usually, your application process should never reach these fairly high limits, however there are times where application’s misuse of handles or failure to release resources (handle leak) may cause issues, sometimes as bad as pool errors 2019 or 2020 in OS that are profiled in this post in NTDebugging blog here – http://blogs.msdn.com/b/ntdebugging/archive/2006/12/18/understanding-pool-consumption-and-event-id_3a00_–2020-or-2019.aspx

handles

So, as we will need to leak handles before we can troubleshoot I will; create a C++ console application named LeakHandles to do so.  There isn’t anything complex I need to do here is create a handle that we don’t close

:

// LeakHandles.cpp : Defines the entry point for the console application.
//

#include "stdafx.h"
#include 


void Leak1(void);
void Leak2(void);
void Leak3(void);
void Leak4(void);
int _tmain(int argc, _TCHAR* argv[])
{
	while (1)
	{
		Leak1();
		Leak2();
		Sleep(100);
	}
	return 0;
}

void Leak1(void)

{

	Leak3();

}



void Leak2(void)

{

	Leak4();



}
void Leak3(void)

{

	HANDLE hEvent;



	hEvent = CreateEvent(NULL, TRUE, TRUE, NULL);

	CloseHandle(hEvent);

}
//here we will leak handle
void Leak4(void)

{

	HANDLE hEvent2;



	hEvent2 = CreateEvent(NULL, TRUE, TRUE, NULL);

}

Now I will build my LeakHandles little application and lets run resulting LeakHandles.exe. Easy way to see that above leak is working is simply open Task Manager and watch handles in CPU area of Performance tab – with only LeakHandles active my handles are increasing really quick.

handles2

Next step that we do have an issue lets troubleshoot it. As I introduced you to AppVerifier in my previous post, I will not go deep on what is that tool and where you get it. Just to summarize – Application Verifier is a runtime verification tool for native code that assists in finding subtle programming errors that can be difficult to identify with normal application testing. Its now bundled as part of Windows SDK , so you can install it from – https://msdn.microsoft.com/en-us/windows/desktop/hh852363.aspx. Choose appropriate processor architecture for your system (x86 or x64).

After you download tools and install these on affected machine running culprit application we will need to setup Verifier rules. By activating Application Verifier, stack trace information is saved each time the process opens a handle, closes a handle, or references an invalid handle.

Open Verifier , then use File –>Add Application and pick culprit application from the browse dialog. In the right pane (Tests) pick Basics and make sure Handles are checked.  You should have something like below:

appverifier_handles

Click save and you will see this message:

message

That’s ok as I am planning to attach debugger to my process a bit later. Lets reopen Verifier again, just to make sure that our settings were properly saved into registry and we are still doing the right thing.  If we look good after extra check, lets close it again.

If your process is currently running, stop and restart the process.   If for example you are using IIS, you want to run iisreset at this point to restart IIS.  This step is required as the process reads the Application Verifier flags ONLY during startup.

In our case we are still working with my sample LeakHandles executable, so I will launch that now.

leakhandles

Now open WinDBG.exe (from Debugging Tools For Windows install).  Select File |-> Attach To Process. I will attach to my culprit exe non invasively:

handles_attach

Next after you successfully attached, run following:

0:000> !htrace -enable
Handle tracing enabled.
Handle tracing information snapshot successfully taken.

This extension,  !htrace extension displays stack trace information for one or more handles. When you provide –enable parameter for user mode process it enables handle tracing and takes the first snapshot of the handle information to use as the initial state by the -diff option.

Once I enabled I can exit debugger by using q – quit command.

Now we want to see what handle tracking can do for us.  Start WinDBG and attach to culprit process again same as above. Observe that since we attached previously in non-invasive mode, process didn’t exit as we detached, so we have same PID as before.  Next after we attached we will generate a nice memory dump like below:

0:000> .dump /ma f:\leakdump.dmp
Creating f:\leakdump.dmp - mini user dump
Dump successfully written

I ill quit again to exit debugger. Now I will open my dump in the debugger. Remember to make sure your symbol path is setup correctly – https://msdn.microsoft.com/en-us/library/windows/hardware/ff558829(v=vs.85).aspx. If your symbols are set correctly as you open dump there will be a bit of a pause as symbols are downloaded to your local downstream symbol store.  Next in my case as LeakHandles.exe is 32 bit process running in 64 bit Windows under WoW (Windows on Windows) and I am in 64 bit WinDBG I will need to use wow64exts  extension to switch to 32 bit stacks. If you are debugging 32 bit on 32 bit or 64 bit native you don’t need this step at all.

0:000> !wow64exts.sw
Switched to 32bit mode

Now we want to see a trace of our handle activity, run the !htrace command with no arguments:

!htrace

Next you will see tons of debugger spew like below:

--------------------------------------
Handle = 0x0000000000002b9c - OPEN
Thread ID = 0x000000000000700c, Process ID = 0x0000000000008b28

0x00007fff5959125a: ntdll!ZwCreateEvent+0x000000000000000a
0x0000000000f06750: verifier!AVrfpNtCreateEvent+0x0000000000000080
0x000000007777a032: wow64!whNtCreateEvent+0x0000000000000062
0x000000007777a44b: wow64!Wow64SystemServiceEx+0x00000000000000fb
0x00000000777c1dc5: wow64cpu!TurboDispatchJumpAddressEnd+0x000000000000000b
0x000000007778219a: wow64!RunCpuSimulation+0x000000000000000a
0x00000000777820d2: wow64!Wow64LdrpInitialize+0x0000000000000172
0x00007fff595c3d39: ntdll!LdrpInitializeProcess+0x0000000000001591
0x00007fff595a379e: ntdll!_LdrpInitialize+0x0000000000087d2e
0x00007fff5951ba1e: ntdll!LdrInitializeThunk+0x000000000000000e
0x000000007780cafc: ntdll_777d0000!ZwCreateEvent+0x000000000000000c
0x000000000ffd510c: vfbasics+0x000000000001510c
0x00000000753b221a: KERNELBASE!CreateEventExW+0x000000000000006a
0x00000000753b2288: KERNELBASE!CreateEventW+0x0000000000000028

This shows you all the handle activity in the process.

You can locate a double close by searching for the CLOSE lines:

Handle = 0x000000000000033c – CLOSE

This will also have the stack trace of the code that closed the handle.

In our case LeakHandles had one function Leak3 that properly close handle and that can be confirmed from !htrace output:

--------------------------------------
Handle = 0x0000000000002b9c - CLOSE
Thread ID = 0x000000000000700c, Process ID = 0x0000000000008b28

0x00000000777c2352: wow64cpu!TurboDispatchJumpAddressEnd+0x0000000000000598
0x00000000777c2318: wow64cpu!TurboDispatchJumpAddressEnd+0x000000000000055e
0x000000007778219a: wow64!RunCpuSimulation+0x000000000000000a
0x00000000777820d2: wow64!Wow64LdrpInitialize+0x0000000000000172
0x00007fff595c3d39: ntdll!LdrpInitializeProcess+0x0000000000001591
0x00007fff595a379e: ntdll!_LdrpInitialize+0x0000000000087d2e
0x00007fff5951ba1e: ntdll!LdrInitializeThunk+0x000000000000000e
0x000000007780c76c: ntdll_777d0000!NtClose+0x000000000000000c
0x000000000ffd52e6: vfbasics+0x00000000000152e6
0x00000000753aef8a: KERNELBASE!CloseHandle+0x000000000000001a
0x000000000ffd6327: vfbasics+0x0000000000016327
0x000000000ffd63ae: vfbasics+0x00000000000163ae
0x000000000ffd6327: vfbasics+0x0000000000016327
0x000000000ffd638d: vfbasics+0x000000000001638d
0x00000000001914d4: LeakHandles!Leak3+0x0000000000000044

But I also see lots of open handles like

Handle = 0x000000000000361c - OPEN
Thread ID = 0x000000000000700c, Process ID = 0x0000000000008b28

0x00000000777c2352: wow64cpu!TurboDispatchJumpAddressEnd+0x0000000000000598
0x00000000777c2318: wow64cpu!TurboDispatchJumpAddressEnd+0x000000000000055e
0x000000007778219a: wow64!RunCpuSimulation+0x000000000000000a
0x00000000777820d2: wow64!Wow64LdrpInitialize+0x0000000000000172
0x00007fff595c3d39: ntdll!LdrpInitializeProcess+0x0000000000001591
0x00007fff595a379e: ntdll!_LdrpInitialize+0x0000000000087d2e
0x00007fff5951ba1e: ntdll!LdrInitializeThunk+0x000000000000000e
0x000000007780c76c: ntdll_777d0000!NtClose+0x000000000000000c
0x000000000ffd52e6: vfbasics+0x00000000000152e6
0x00000000753aef8a: KERNELBASE!CloseHandle+0x000000000000001a
0x000000000ffd6327: vfbasics+0x0000000000016327
0x000000000ffd63ae: vfbasics+0x00000000000163ae
0x000000000ffd6327: vfbasics+0x0000000000016327
0x000000000ffd638d: vfbasics+0x000000000001638d
0x00000000001914d4: LeakHandles!Leak4+0x0000000000000044
--------------------------------------

Well, I suppose we got what we were looking for here. Next, be absolutely sure to start App Verifier again and delete the process entry for your process!  You want to always do this since the App Verifier settings are persisted in the registry, they will survive even a server reboot.  Right click on the Image Name and select “Delete Application”.  Then click Save and close and re-open App Verifier to ensure that the entry is gone. As well if you are debugging some service you want to restart the service to stop the tracking, run iisreset for example again to reset IIS to normal state if you are debugging IIS. I will open Application Verifier , Delete Application and Save. At the end you should have clean Application Verifier window like:

cleanappverifier

Happy handle hunting!.

For more see –http://blogs.technet.com/b/markrussinovich/archive/2009/09/29/3283844.aspx, https://msdn.microsoft.com/en-us/library/ms220948(v=vs.90).aspx, http://blogs.technet.com/b/yongrhee/archive/2011/12/19/how-to-troubleshoot-a-handle-leak.aspx, http://blogs.msdn.com/b/junfeng/archive/2008/04/21/use-htrace-to-debug-handle-leak.aspx, http://blogs.technet.com/b/brad_rutkowski/archive/2007/11/13/got-a-handle-leak-use-htrace-to-help-find-the-leaking-stacks-non-invasively.aspx, http://stackoverflow.com/questions/7617256/how-do-i-diagnose-a-handle-leak, http://www.asprangers.com/post/2012/01/23/How-to-Debug-Handle-leak-(using-!htrace)-in-w3wpexe.aspx, http://blogs.msdn.com/b/ntdebugging/archive/2006/12/18/understanding-pool-consumption-and-event-id_3a00_–2020-or-2019.aspx.

Hope this helps.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s