UPHClean and other profile ramblings

New UPHClean beta build

Hi there!

Good news -- I'm releasing an updated beta build today.  It fixes machine hangs and crashes that could occur with build 2.0.48.0. 

The 32 bit plaform bits are here and for 64 bit platforms here.

If you find any problem with this build please email the details to uphclean@microsoft.com or post them here.

Thank you all for your patience in waiting for updated beta bits.

Robin

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.

When will UPHClean v2.0 be done?

UPHClean v2.0 has been in beta for an extended period.  Over 3,000 people have received the beta bits.  There have been enough reports of computers hanging and crashing to prevent release.  Further beta builds are needed to insure that those remaining problems are resolved.  Once ship quality is achieved a release date will be selected.  Based on my current work load and experience with past projects I expect that will at least 6 more months before final release.

Group Policy Administrative Template To Manage 2.0 Beta Settings

Here is an administrative template to make it easier to manage the file remapping settings available with UPHClean v2.0.

Thank you Kevin Henriksen for this contribution.

About UPHClean v2.0 events 1630, 1631 and 1632

UPHClean v2.0 tries to assist when the security descriptor prevents access to a file or directory.  This often prevents the system from completing the profile reconciliation process.  This can happen because the inherited permissions are set incorrectly or possibly because the user sets to prevent administrative and/or system access.

UPHClean attempts to deal with that by changing the security descriptor.  This is done for access to file or directory access that result in access denied.  In the case where the file or directory is local it is likely that UPHClean will be able to change the security descriptor since it can use the take ownership right to do so.  In the remote case it is possible that UPHClean will fail to change the permissions.  So this correction UPHClean may not always succeed.

Here are relevant events that can occur:

• Event 1630: Access to %1 was granted after updating the security descriptor of the file.
  • This event indicates that UPHClean changed the security descriptor for the file/directory named %1 and was successful.  Access permissions necessary to proceed with profile work were granted.  Access to the file or directory was successful.
• Event  1631: Access to %1 failed after updating the security descriptor of the file.
  • This event indicates that UPHClean changed the security descriptor and was successful.  Even though UPHClean granted the access permissions necessary to perform the profile work the requested access was denied.  This can happen if the source of the access denied is not security descriptor permission related.  The interference could be coming from a background process (i.e. a virus scanner) or other unknown source.
• Event 1632: Security descriptor for file %1 could not be updated.  Error %2 %3.
  • This event indicates that UPHClean failed in its attempt to change the security descriptor.  %2 is replaced with the text of the error and %3 is the error number.  Access to the file or directory failed.

Note that the name logged with the event may contain an unfamiliar drive letter.  This drive letter represents the roaming profile location.  It exists only during the profile reconciliation process.

These events are logged so that you can know that UPHClean took these actions.  This is critical if auditing. 

If the user profile is reconciling properly you can ignore these.  If the profile is not reconciling properly and you are logging events 1631 or 1632 you should review the security descriptor hierarchy to insure that the permissions are as intended and allow system/administrative access.

UPHClean v2.0 beta

UPHClean v2.0

UPHClean v2.0 is a new version that tries to help with the following scenarios:

Timing fix

In v1.6 there is a timing issue with where the profile unload process stopped trying to unload the user profile hive before UPHClean finished its work. UPHClean finished its release of user profile hive handles but Winlogon had already proceeded without unloading the profile causing it to report a profile hive unload failure.  This is now addressed by having Winlogon waiting until UPHClean has finished all of its work before proceeding.

Open file handles

Apart open registry handles that UPHClean v1.6 deals with open file handles to the user profile can have a bad influence on the profile load and unload process. Open references to profile files prevent the profile load and unload process from reconciling (copying files) from and to the roaming profile location.  This prevents the deletion of the locally cached profile.  Other symptoms of this is if the same user logs in again he or she gets a new profile with a name like username.000, username.001 etc.

UPHClean v2.0 takes care of these by releasing the handle to user profile files when the profile is unloaded.  This is not without risk.  Since UPHClean removes access to files or directories data that was cached by the application for the file is lost.  This could cause the process to fail because it cannot read from the file. During testing this has not been found to be true but there is still a chance that it could happen. This is the reason why the file handle remap feature is disabled by default.

To enable the feature you have to set the following registry key:

HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\UPHClean\Parameters
SHARING_VIOLATION_REMAP REG_DWORD 0X00000001

Without enabling the remapping feature UPHClean automatically detects sharing violation during the user logoff and retries the failed operation for a small amount of time. You can control the amount of time using the SHARING_VIOLATION_DELAY value. This value is specified in millisecond and has a default value of 1000 millisecond. 

File permissions

In some cases a program might change file permissions or creates a new file/folder within the profile but incorrect permissions.  This may leave the profile load/unload process unable to copy it or delete it. To resolve the issue you have to take ownership first before you can delete the file or folder. UPHClean takes care of those situations.

Real world problems

Here are actual scenarios that UPHClean v2.0 resolves:

• VMware hgfs.dat
  VMware creates the hgfs.dat file in profile folder for the first user that logs in and keeps it open. When using roaming profiles you get a problem with that. (read VMware FAQ1317 for a solution)
• SUN Java (JRE)
  In some cases SUN Java creates a folder called hsperfdata<username> with file permissions only set to the user and can not be removed by the system without taking ownership. SUN say’s this is by design (bug id 5042659)
• Microsoft Internet explorer cookies and favorites
  Favorites and cookie files sometimes excide more than 255 chars and can only be deleted through the command line
• Also suspects for open file handles causing sharing violation
  SAP SapGui (SapWorkDir), Imprivata SSO, Indexing Software, Virus scanner etc.

It will be supported on Windows 2000 (all versions), Windows XP, Windows Server 2003, Windows Vista, Windows Server 2008.  It will be available for 32 bit and 64 bit platforms.  There are beta bit available for 32 and 64 bit platforms for all Windows 2000, Windows XP, and Windows Server 2003.

Windows Vista, Windows Server 2008 and UPHClean

UPHClean fails to install on Windows Vista and Windows Server 2008.  This happens because the User Profile service included with those operating system includes the functionality of UPHClean v1.6 built in.  There is no point in having UPHClean perform its monitoring work when the profile service does all necessary work to prevent user hive fails from occuring.

Whereas UPHClean logs event 1401 to indicate that it took action to resolve a problem that would have prevent a user profile hive from unloading, the User Profile service logs event 1530.  It looks like this:

Log Name: Application
Source: Microsoft-Windows-User Profiles Service
Date: 2/28/2008 2:56:52 PM
Event ID: 1530
Task Category: None
Level: Warning
Keywords: Classic
User: SYSTEM
Computer: RCARON-PC
Description:
Windows detected your registry file is still in use by other applications or
services. The file will be unloaded now. The applications or services that
hold your registry file may not function properly afterwards.

DETAIL -
1 user registry handles leaked from
\Registry\User\S-1-5-21-2641105361-2081720548-7543625-1000:
Process 896 (\Device\HarddiskVolume1\Windows\System32\svchost. exe) has
opened key \REGISTRY\USER\S-1-5-21-2641105361-2081720548-7543625-1000

This event is letting you know that when the profile was being unloaded svchost.exe with process id (PID) 896 had a registry key handle to the profile hive for the user with SID S-1-5-21-2641105361-2081720548-7543625-1000.

The event is there so you know that the system took action.  That way you could know that if the application fails in some way you can investigate whether this action might be involved in the failure.  Generally my advice for this (as for UPHClean event 1401) is to ignore it.

I am working on UPHClean v2.0.  This version will address many more user profile problem scenarios.  This version will likely install on Windows Vista and Windows Server 2008.  It is in beta but currently the beta bits do not yet install on those operating systems.

Robin.

Hi

I am Robin Caron.  I have worked for 8 years as an escalation engineer for Microsoft supporting directory services technologies for the Windows platform.

I am starting this blog as a way to distribute information about UPHClean and to offer some ramblings about Windows user profiles. 

UPHClean is a tool that I wrote about 5 years ago to help resolve the problem of user profile hive not unloading.  When user profile hives do not unload you get a variety of problems including slow logoff (on Windows 2000), no reconciliation of roaming profiles, possible kernel memory exhaustion and a variety of error events logged in the application log.  UPHClean helps this scenario.  You can get UPHClean from here.

UPHClean was successful beyond my wildest dream (over 3 million downloads in less than 3 years).  I worked with the profile team to get its functionality integrated into the operating system.  This is now available in Windows Vista and Windows Server 2008 in the User Profile service.

I plan on telling you more about how profiles work and how UPHClean attempts to help with problems that occur with them. I'll also discuss problem scenarios future versions of UPHClean will attempt to help with.

Do not hesitate to give your feedback about what types of information about profiles/UPHClean you would like to see.  You can either leave a comment here or send email to uphclean@microsoft.com.

Robin.