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":
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 ...
To continue reading for free, register below or login
To read more you must become a member of SearchWindowsServer.com
describes how to enable verbose logging. Basically, you define a value at Subkey like this:
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:
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:
Using Net Helpmsg to decode the 0x2 code:
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:
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.
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.
GPO processing
Like profile processing, GPO processing is initially flagged:
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:
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.
Next, we search the Accounts OU and find
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.
This event indicates we found a GPO and will process it later.
The GPO can be read:
This is the path of the GPT.ini of the GPO -- found successfully:
Below, we can match the GUID name of the GPO with the "Display Name," or friendly name:
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):
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
[IMAGE]
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:
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.
