Debugging user profile and GPO problems with Userenv logs

Expert Gary Olsen walks through the basics of the Userenv.log file and shares some useful case studies that illustrate how to use Userenv to debug problems involving the user environment.

Gary Olsen

Some of the most difficult problems to debug involving the user environment center around either the user profile or the Group Policy Object (GPO) application.

Most Windows administrators are familiar with tools like Microsoft's GPResult, which reports the Group Policy and Group Policy extension settings that are applied to the client and user. Of course, the Group Policy Management Console (GPMC) is also well known as a powerful tool for management and troubleshooting GPO issues. However, very few administrators, at least that I have talked to, know much about the Userenv.log.

Userenv basics

The Userenv.log contains verbose information about policy and profile processing, as well as additional logs such as gptext.txt, that log events for Group Policy extensions such as security scripts and folder redirection.

The file is found in %systemroot%\debug\user mode\ and contains entries associated with the Userenv process. It is usually a fairly small text file since verbose logging is not enabled by default. Without logging enabled, a typical Userenv.log file would contain data like this:

USERENV(dc.274) 12:54:57:446 ProcessGPOs: Extension Security
ProcessGroupPolicy failed, status 0x3.
USERENV(dc.274) 12:59:57:713 ProcessGPOs: Extension Security
ProcessGroupPolicy failed, status 0x3.
USERENV(dc.274) 13:04:58:043 ProcessGPOs: Extension Security
ProcessGroupPolicy failed, status 0x3.
USERENV(dc.274) 13:09:58:389 ProcessGPOs: Extension Security
ProcessGroupPolicy failed, status 0x3.
USERENV(dc.274) 13:14:58:703 ProcessGPOs: Extension Security
ProcessGroupPolicy failed, status 0x3.

By doing a Net Helpmsg from the command prompt, we see the error description for "status 0x3":

C:\>net helpmsg 3

The system cannot find the path specified.

While this helps, it is insufficient for us to narrow the problem. To get more data, we need to enable verbose logging for Userenv. KB 221833: How to enable user environment debug logging in retail builds of Windows describes how to enable verbose logging. Basically, you define a value at Subkey like this:

HKEY_LOCAL_MACHINE\Software\Microsoft\Windows
NT\CurrentVersion\Winlogon
Entry: UserEnvDebugLevel
Type: REG_DWORD
Value data: 30002 (Hexadecimal)

Note that you can use several values for various levels of logging for different functions. However, I always use 0x00030002, as this value produces the most verbose output. Notice the difference in the Userenv.log with the following value set, compared to the previous example using the default setting:

USERENV(a8.23c) 17:55:25:071 ProcessGPOs: Starting computer Group
Policy processing...
USERENV(a8.23c) 17:55:25:071 EnterCriticalPolicySection: Machine critical
section has been claimed. Handle = 0x41c
USERENV(a8.23c) 17:55:25:071 ProcessGPOs: Machine role is 2.
USERENV(a8.23c) 17:55:25:081 PingComputer: First time: 0
USERENV(a8.23c) 17:55:25:081 PingComputer: Fast link. Exiting.
USERENV(a8.23c) 17:55:25:151 ProcessGPOs: User name is:
CN=PC123,OU=Computers,OU=Atlanta,DC=Corp,DC=Net
Domain name is: Corp

Each entry has a time stamp, but, unfortunately, there is no date stamp. Userenv.log has had this problem since the Windows 2000 Server beta, but it has never been changed. I suppose that administrators became so conditioned to working around it that they stopped complaining, so Microsoft never fixed it.

Because there is no date stamp, we don't know if these entries were made today or last year. To make sure you have current log data, do the following:

  1. Go to %systemRoot%\Debug\UserMode and delete or rename the current Userenv.log.
  2. Log off and log back on.
  3. Reproduce the problem (if it requires more than just logging off and on).
  4. A new Userenv.log will be produced. Save this so you'll know when it was taken.

Interpreting Userenv entries

Much like DCpromo.log, the Userenv.log isn't especially difficult to interpret. Microsoft really hasn't offered a good guide on reading a Userenv.log, but there are several articles that reference its use. Conducting a search of Userenv.log at Microsoft's Web site will provide a long list of issues that use entries in the Userenv.log to resolve.

Here are a few basic rules that will help when reading the log.

Error codes
Failure codes recorded are standard NT errors. They can be interpreted with the Net Helpmsg command. For example:

USERENV(a8.23c) 17:55:25:772 ProcessGPOs: Extension
Scripts ProcessGroupPolicy failed, status 0x2.

Using Net Helpmsg to decode the 0x2 code:

C:\>net helpmsg 2

The system cannot find the file specified.

In this case, during the processing of a Group Policy extension (scripts), it was unable to find the file. This would most likely be caused by the script not being in the path it was expected to be in, or a pointer (scripts.ini) was incorrect.

Profiles
The User Profile is loaded in the "LoadUserProfile" entry:

USERENV(d8.d4) 17:55:21:926 LoadUserProfile:
lpProfileInfo->lpUserName = <SMSCliSvcAcct&>
USERENV(d8.d4) 17:55:21:926 LoadUserProfile:
lpProfileInfo->lpProfilePath = <>
USERENV(d8.d4) 17:55:21:936 LoadUserProfile: NULL
default profile path

Here the User Name is exposed in the first line. In determining the Profile Path, a NULL is returned. NULL is returned when Winlogon's GetUserInfo call fails -- or, rather, has no data. Note that if it references the "Central Profile Path," it is loading a roaming profile. Thus, if it returns a NULL, a roaming profile would not be used.

The following entries are pretty straightforward. We see there is no local mandatory profile and there is an Error code of 2, which means the file can't be found. In this case, it is only a problem if there is a mandatory profile to read.

USERENV(d8.d4) 17:55:21:946 GetExistingLocalProfileImage:
Expanded local profile image filename = <C:\Documents and
Settings\SMSCliSvcAcct&>
USERENV(d8.d4) 17:55:22:057 GetExistingLocalProfileImage: No local
mandatory profile. Error = 2

In these two lines, we see that the local profile was found (including the path to the ntuser.dat). Also, there is "No Central Profile," which means there is no roaming profile.

USERENV(d8.d4) 17:55:22:077 GetExistingLocalProfileImage: Found
local profile image file ok <C:\Documents and
Settings\SMSCliSvcAcct&\ntuser.dat>
USERENV(d8.d4) 17:55:22:077 RestoreUserProfile: No central profile.
Attempting to load local profile.

GPO processing
Like profile processing, GPO processing is initially flagged:

USERENV(a8.23c) 17:55:25:071 ProcessGPOs: Starting computer
Group Policy processing...

The next lines show the user for which the policy is being processed, followed by the DC that the policy is being obtained from. Note that the user is in a nested OU called Power Users:

USERENV(a8.23c) 17:55:25:151 ProcessGPOs: User name is:
CN=Olseng,OU=Power
Users,OU=Accounts,OU=Atlanta,Dc=Corp,DC=net, Domain name is:
Corp
USERENV(a8.23c) 17:55:25:151 ProcessGPOs: Domain controller is:
\\ATL-DC01.corp.net Domain DN is Corp.net
USERENV(a8.23c) 17:55:25:161 ProcessGPOs: Calling GetGPOInfo
for normal policy mode
USERENV(a8.23c) 17:55:25:161 GetGPOInfo:
********************************
USERENV(a8.23c) 17:55:25:161 GetGPOInfo: Entering...
USERENV(a8.23c) 17:55:25:191 GetGPOInfo: Server connection
established.
USERENV(a8.23c) 17:55:25:211 GetGPOInfo: Bound successfully.

The above process searched for GPOs in the Power Users OU; now, we search the Accounts OU for GPOs. Note that there are no GPOs to process.

USERENV(a8.23c) 17:55:25:261 SearchDSObject: Searching <
OU=Power Users,OU=Accounts,OU=Atlanta,Dc=Corp,DC=net,
Domain name is: Corp >
USERENV(a8.23c) 17:55:25:261 SearchDSObject: No GPO(s) for
this object.

Next, we search the Accounts OU and find

USERENV(a8.23c) 17:55:25:221 SearchDSObject: Searching
<OU=Accounts,OU=Atlanta,Dc=Corp,DC=net>
USERENV(a8.23c) 17:55:25:221 SearchDSObject: Found GPO(s):
<[LDAP://CN={A11C7DF4-CF73-4535-9C91-
F8098CB9D163},CN=Policies,CN=System,Dc=Corp,DC=net;0][LDA
P://CN={EE62499D-80A2-4527-A2A6-
F9859F064565},CN=Policies,CN=System,Dc=Corp,DC=net;0][LDAP
://CN={44C1CAC3-B685-4A68-8771-
6D465A765A4C},CN=Policies,CN=System,Dc=Corp,DC=net;0]>

This would continue and look for GPOs in the Atlanta OU and in the Corp.net domain.

The next group of events tells us a lot about the success of the GPO. First, we find the GPO by the global unique identifier (GUID) and begin processing.

USERENV(a8.23c) 17:55:25:331 ProcessGPO: Searching
<CN={CC0AB454-824D-4EB7-B80B-
03B06A0B195F},CN=Policies,CN=System,Dc=corp,dc=net>

This event indicates we found a GPO and will process it later.

USERENV(a8.23c) 17:55:25:231 ProcessGPO: Deferring search for
<LDAP://CN={31B2F340-016D-11D2-945F-
00C04FB984F9},CN=Policies,CN=System,DC=Corp,DC=net>

The GPO can be read:

USERENV(a8.23c) 17:55:25:331 ProcessGPO: Machine
has access to this GPO.
USERENV(a8.23c) 17:55:25:331 ProcessGPO: Found
functionality version of: 2

This is the path of the GPT.ini of the GPO -- found successfully:

USERENV(a8.23c) 17:55:25:331 ProcessGPO: Found file
system path of:
\\Corp.net\SysVol\Corp.net\Policies\{CC0AB454-824D-
4EB7-B80B-03B06A0B195F}

Below, we can match the GUID name of the GPO with the "Display Name," or friendly name:

USERENV(a8.23c) 17:55:25:341 ProcessGPO: Found common name of: <{CC0AB454-824D-4EB7-B80B-03B06A0B195F}>
USERENV(a8.23c) 17:55:25:341 ProcessGPO: Found display name of: <Atlanta Policy>

The next entry tells us that the Active Directory Object of the GPO (GPC) and the SYSVOL template of the GPO (GPT) match (version 35 for each):

USERENV(a8.23c) 17:55:25:341 ProcessGPO: Found
machine version of: GPC is 35, GPT is 35
USERENV(a8.23c) 17:55:25:341 ProcessGPO: Found flags
of: 0

Now we get a list of all extensions applied to the GPO. The extensions are shown by their GUID. We can convert them to a friendly name by drilling in the registry to HKLM\Software\Microsoft\WindowsNT\Winlogon\GPExtensions as shown in Figure 1.

Figure 1

Note that in this figure, I clicked on the {42B5FAAE…} entry. In the right pane I can see that the description (top line) is Scripts. Therefore, this policy has a script defined in it because in the list below, I see the GUID for the scripts extension, along with two others:

USERENV(a8.23c) 17:55:25:341 ProcessGPO: Found extensions: [{42B5FAAE-6536-11D2-AE5A-0000F87571E3}{40B6664F-4972-11D1-A7CA-0000F87571E3}][{827D319E-6EAC-11D2-A4EA-00C04F79F83A}

Finding errors
As you look through the Userenv.log, you will find errors, warnings and failures. You can search on those words to make a faster determination of the problem, but you have to read above and below the actual error line to determine what was going on. Obviously, there isn't space here to go into a complete analysis of how to debug a problem, but you have the basics. Again, just reading the logs and having a few guidelines will help you extract some useful debugging information.

Stay tuned for the next article. I will show how we can get additional logging for GPO extensions, such as scripts and folder redirection, and I'll present a case study that shows where we used Userenv.log and the extension log to debug a policy problem.

Gary Olsen is a systems software engineer for Hewlett-Packard in Global Solutions Engineering. He authored Windows 2000: Active Directory Design and Deployment and co-authored Windows Server 2003 on HP ProLiant Servers. Gary is a Microsoft MVP for Windows Server-File Systems. 

 


 

This was first published in March 2007

Dig deeper on Microsoft Group Policy Management

Pro+

Features

Enjoy the benefits of Pro+ membership, learn more and join.

0 comments

Oldest 

Forgot Password?

No problem! Submit your e-mail address below. We'll send you an email containing your password.

Your password has been sent to:

-ADS BY GOOGLE

SearchServerVirtualization

SearchCloudComputing

SearchExchange

SearchSQLServer

SearchWinIT

SearchEnterpriseDesktop

SearchVirtualDesktop

Close