Call stack logging: what it is and where does it go?

To understand what call stack logging is you must understand how software works internally.  Software is put together using small pieces of code.  These pieces are called functions.  Complex work is done by breaking it down into simpler tasks.  A function that performs a complex behavior gets it done by doing some of the work itself and by using functions to do simpler tasks.

 

When a function uses another function to perform a simpler task it needs to make sure that once the simpler function is done work resumes on the more complex task. To make this happen it saves off where it was.  It is saved to an area of memory called the stack.  The simpler function may very well also call on other function to perform even simpler tasks.  It also needs to save off where work was before it calls on simpler function.

 

This is why the area of memory where this information is saved is called a stack.  Just like you would pile dishes on top of each other, the saved information is piled on top of each other.  When the simpler function is done to find out where work should resume it picks off the top of the pile.  This tells it where to go back to.  This repeats when that function is done.

 

Now suppose whenever an action is taken (e.g. retrieving a handle to a registry key) this stack memory is recorded.  To do this the simpler task function looks at the stack memory find out where work would resume when it is done.  What is being recorded is the address in memory where the instruction is that resumes the more complex work.  This is literally just a number between 0 and about 4 billon.  Using the earlier example this address could in a function in a printer driver that needs the page size to print on.  This process can keep going and look at when the the page size retrieval function that is done where work would resume.  This might be function that is responsible for printing.  It can keep doing that back all the way to the function that starts the application (some function in a printer spooler).  This information (a list of memory addresses) is called a call stack log or call stack for short.

 

Now imagine you decided that retrieving a registry key handle is causing a problem you could inspect the recorded information to determine why the action was taken.  This helps in narrowing down what causes the problem.  This is especially true today because applications are put together using 100s of thousands of functions from many vendors.  Knowing the call stack tells you who initiated the action that causes a problem.

 

Collection of call stacks is an option in UPHClean v1.6d enabled via the registry setting HKEY_LOCAL_MACHINE\System\CurrentControlSet\Services\UPHClean\Parameters\CALLSTACK_LOG to 1.  The value is a DWORD but you should find it there if UPHClean has ever been run.

 

The actual call stack logging is something that is not actually done by UPHClean.  You can understand why based on the explanation I gave above: UPHClean is not being called on to perform the action of opening a registry handle.  This work is actually by functions that reside in the DLL ADVAPI32.  So when you set this option what UPHClean does is set a registry setting (HKEY_LOCAL_MACHINE\Software\Microsoft\Windows NT\CurrentVersion\Winlogon\LeakTrack).  The functions in ADVAPI32 responsible for getting a registry key handle read this value.  When the value is set appropriately they collect a call stack whenever they are asked to get a registry key under the user profile hives.  Later when the registry keys are release closed it removes the discards the collected call stack information.

 

When UPHClean is about to process a handle that is leaked by an application for remapping or closure UPHClean checks to see if call stack logging is enabled.  If call stack logging is enabled it reads the stack information recorded by ADVAPI32.  This information is recorded as a list of memory addresses tha

 

It is logged in the application event log as an addition to event 1401 or 1201.  The readme has an example:

Event Type: Information
Event Source: UPHClean
Event Category: None
Event ID: 1201
Date:  10/21/2003
Time:  5:17:38 PM
User:  RCARONDOM-DC1\u1
Computer: RCARONDOM-DC1
Description:
The following handles in user profile hive RCARONDOM-DC1\u1
(S-1-5-21-3230802392-3390281410-1560515013-1307) have been closed because they
were preventing the profile from unloading successfully:
 
profleak.exe (2604)
  HKCU (0x80)
      0x77dfc200 ADVAPI32!TrackObject+0xe
      0x00412112 profleak!<no symbol>
      0x77db571b ADVAPI32!ScSvcctrlThreadA+0xe
  HKCU\Software\Policies (0x88)
      0x77dfc200 ADVAPI32!TrackObject+0xe
      0x77da1949 ADVAPI32!RegOpenKeyExW+0x10b
      0x0041350c profleak!<no symbol>
      0x00412112 profleak!<no symbol>
      0x77db571b ADVAPI32!ScSvcctrlThreadA+0xe

 

This this call stack data indicates that the user profile hive handle leak is caused by profleak.  Profleak is an application used to causes a user profile hive handle leak.   It is not true that in all cases the listed module/DLL listed after ADVAPI32 is the culprit.  Interpreting this information requires an experienced developer or someone who can debug.

Comments

• Anonymous
  January 01, 2003
  Hi there, i got the follows event in my terminal server upclean events 1632, 1631,1651 and userenv events 1509,1515,1511 and I have checked the cached profiles on my terminal servers. I realize that uphclean is reseting the nfts permissions on profiles users folders. I would like a suggestion to troubleshoting this issues. I did a lot research on internet and I didnt find anything. Thanks in advanced, Logan