GPO – How to Read a UserenvLog
Note that Userenv logging per this article does not work on any version of Windows Vista or Windows Server 2008. It will work only on Windows 2000, 2003 or XP.
Open Regedit on the problem computer and drill down to:
HKLMSoftwareMicrosoftWindows NTCurrentVersionWinlogon.
Create a REG_DWORD with the value called UserEnvDebugLevel then set the value to 0x10002 in hexadecimal. The value is not case sensitive.
Logging will start immediately to the Userenv.log file located in the %SystemRoot%DebugUserMode folder (no reboot or restart of services is required). If the Userenv.log file is larger than 300 KB, the file is renamed Userenv.bak, and a new Userenv.log file is created. This action occurs when a user logs on locally or by using Terminal Services, and the Winlogon process starts. However, because the size check only occurs when a user logs on, the Userenv.log file may grow beyond the 300 KB limit. If you need to read the log or .bak files then you can simply open them with Notepad. Since you want to see what the computer is doing when it starts, reboot the client computer.
One problem with Userenv logging, especially on a busy terminal server with lots of logon activity, is that the log is overwritten before you get a chance to find the useful information in it. While there is no way to increase the 300 KB limit on the log file, if you make Userenv.bak read-only, Winlogon can’t rename Userenv.log to Userenv.bak, so it just keeps logging to the Userenv.log indefinitely. If you decide to use this method, it is critical that you monitor the size of the Userenv.log to make sure it does not fill up the drive. Then remove the read-only attribute as soon as you are done troubleshooting.
After a reboot and once you are logged onto the client computer, open the Userenv log; you should notice information such as this:
USERENV(78c.790) 22:00:04:218 LoadUserProfile: lpProfileInfo->lpUserName = <NetworkService>
Or
USERENV(78c.790) 22:00:04:546 LoadUserProfile: lpProfileInfo->lpUserName = <LocalService>
This is normal as there are profiles for the Network Service and Local Service. These accounts have to logon just as a normal user account since they are used to start services that are running on the local computer. You may see a line in the log such as this:
USERENV(78c.790) 22:00:04:515 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.
No need to worry if it is associated with one of the services logging on. This is due to if you look at the SID (Security Identifier) for either the Network Service (S-1-5-20) or the Local Service (S-1-5-19) these are what we call Well Known Security Identifiers (SID’s). You can see a list of them in:
243330 Well-known security identifiers in Windows operating systems
http://support.microsoft.com/kb/243330
These accounts are not associated to a domain such as a user or computer account would be. So these can be ignored. Once the services have started up or still in the process of starting you will see the following:
USERENV(750.280) 22:00:43:203 ProcessGPOs: Starting computer Group Policy (Background) processing…
This signifies that the group policy for the computer is about to start processing. First we ping the server to determine if we are on a fast link or not. We do this to determine if we are on a slow link where processing group policies could be done in a different fashion. So if ICMP is not allowed through any routers and in order to ping a DC, if we go through a router, then do not expect policies to get applied.
USERENV(750.280) 22:00:43:203 PingComputer: PingBufferSize set as 2048
USERENV(750.280) 22:00:43:203 PingComputer: Adapter speed 100000000 bps
USERENV(750.280) 22:00:43:203 PingComputer: First time: 0
USERENV(750.280) 22:00:43:203 PingComputer: Fast link. Exiting.
Next we have to determine where this computer account resides in Active Directory.
USERENV(750.280) 22:00:53:953 ProcessGPOs: User name is: CN=Machine,OU=Workstations,OU=TX,OU=USA,DC=Domain,DC=com, Domain name is: Domain
USERENV(750.280) 22:00:53:953 ProcessGPOs: Domain controller is: \DC1.DOMAIN.COM Domain DN is DOMAIN.COM
Notice that we print out the LDAP path to the computer account. This is done so that we know where to check for the policies at the OU levels. It will also report which DC that the computer has contacted in order to pull the policies from.
Next the client side extensions are checked where the GUID between the {} will be different.
USERENV(750.280) 22:00:53:968 ReadExtStatus: Reading Previous Status for extension {25537BA6-77A8-11D2-9B6C-0000F8080861}
Once we have all that we start checking for policies that might be linked at an OU level, domain level or site level . We first start at the OU that the computer is located at or if the computer lies in a container the next level up that a policy can be linked at.
USERENV(750.280) 22:00:54:000 GetGPOInfo: Server connection established.
USERENV(750.280) 22:00:54:031 GetGPOInfo: Bound successfully.
USERENV(750.280) 22:00:54:046 SearchDSObject: Searching <OU=Workstations,OU=TX,OU=USA,DC=Domain,DC=com >
USERENV(750.280) 22:00:54:046 SearchDSObject: No GPO(s) for this object.
USERENV(750.280) 22:00:54:046 SearchDSObject: Searching < OU=TX,OU=USA,DC=Domain,DC=com >
USERENV(750.280) 22:00:54:046 SearchDSObject: Found GPO(s): <[LDAP://CN={Policy GUID},CN=Policies,CN=System, DC=Domain,DC=com;0]>
USERENV(750.280) 22:00:54:046 SearchDSObject: Searching < OU=USA,DC=Domain,DC=com >
USERENV(750.280) 22:00:54:046 SearchDSObject: Searching < DC=Domain,DC=com >
USERENV(750.280) 22:00:54:046 SearchDSObject: Searching <CN=MYSite,CN=Sites,CN=Configuration, DC=Domain,DC=com >
At any point in this time the log may show something like this:
USERENV(750.280) 22:00:54:046 SearchDSObject: Found GPO(s):
Then the log shows a list of GPO’s that are linked to that particular OU/Domain/Site. Note that you could run across this in the output:
USERENV(750.280) 22:00:54:046 SearchDSObject: Found GPO(s): <[LDAP://CN={Policy GUID},CN=Policies,CN=System, DC=Domain,DC=com;0]>
Note the 0 at the end, this is the default setting, 1 means the policy is set to disabled which means the policy is linked to that particular OU / domain or site level but is disabled. If the value is set to 2 this means that the policy has been set to “No Override” also known as “Enforced.” A setting of “No Override” means that if 2 separate GPOs have the same setting are defined but hold different values, the one that is set to no override wins out on what is actually applied to the client. If a policy is set to “No Override” or “Enforced” at an OU/domain level then an OU below that is set to block inheritance, the policy set for “No Override” will still apply. You cannot block a policy from applying if the “No Override” or “Enforce” has been set on a policy.
Once we have gone all the way through we start actually applying the policies:
USERENV(750.280) 22:00:54:093 ProcessGPO: Searching <CN={GPO GUID},CN=Policies,CN=System, DC=Domain,DC=com >
The path above is where in AD the particulars of the policy are stored.
USERENV(750.280) 22:00:54:093 ProcessGPO: Machine has access to this GPO.
We need to check and see if the computer has access to the policy if we do then the computer can apply the policy; if we do not have access then we cannot apply it.
USERENV(750.280) 22:00:54:109 FilterCheck: Found WMI Filter id of: <[DOMAIN.COM;{Policy GUID};0]>
If a policy has a WMI filter being applied we have to check it and see if the policy is going to apply to this computer or not. The WMI filter can be seen if you go to the properties of the policy then to the WMI tab. If you are using GPMC then this can be found in the right hand pane at the very bottom box after highlighting the policy.
USERENV(750.280) 22:00:54:093 ProcessGPO: GPO passes the filter check.
Or
USERENV(750.280) 22:00:55:250 ProcessGPO: The GPO does not pass the filter check and so will not be applied.
USERENV(750.280) 22:00:54:093 ProcessGPO: Found functionality version of: 2
Functionality version has to be a 2 for a Windows 2000 or later OS to apply the policy.
USERENV(750.280) 22:00:54:093 ProcessGPO: Found file system path of:\DOMAIN.comSysVolDOMAIN.comPolicies{GPO GUID}
This above is the path of the policy in the file system on a DC.
USERENV(750.280) 22:00:54:109 ProcessGPO: Found common name of: <{GPO GUID}>
USERENV(750.280) 22:00:54:109 ProcessGPO: Found display name of: <MY Domain Policy>
USERENV(750.280) 22:00:54:109 ProcessGPO: Found machine version of: GPC is 77, GPT is 77
Here is where we check the GPC (Group Policy Container) and the GPT (Group Policy Template) for the version numbers. We check the version numbers to determine if the policy has changed since the last time it was applied. If the version numbers are different then we either have an AD replication or File replication latency problem.
USERENV(750.280) 22:00:54:109 ProcessGPO: Found flags of: 0
USERENV(750.280) 22:00:54:109 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{53D6AB1D-2488-11D1-A28C-00C04FB94F17}][{827D319E-6EAC-11D2-A4EA-00C04F79F83A}{803E14A0-B4FB-11D0-A0D0-00A0C90F574B}][{B1BE8D72-6EAC-11D2-A4EA-00C04F79F83A}{53D6AB1D-2488-11D1-A28C-00C04FB94F17}]
The extensions above refer to the CSE (client-side extensions) and will vary from policy to policy. For a list of the CSE’s see:
216357 Identifying Group Policy Client-Side Extensions
http://support.microsoft.com/kb/216357
943729 Information about new Group Policy preferences in Windows Server 2008
http://support.microsoft.com/kb/943729
Moving right along now we come to the part where we process CSE’s for particular settings such as Folder Redirection, Disk Quota, etc. If the particular extension is not being used then you can simply ignore this section.
USERENV(750.280) 22:00:56:359 ProcessGPOs: Processing extension Folder Redirection
USERENV(750.280) 22:00:56:359 CompareGPOLists: The lists are the same.
USERENV(750.280) 22:00:56:359 CheckGPOs: No GPO changes but couldn’t read extension Folder Redirection’s status or policy time.
USERENV(750.280) 22:00:56:359 ProcessGPOs: Extension Folder Redirection skipped with flags 0x7.
Now we have pretty much come to the end of the computer processing which we know by the following:
USERENV(750.280) 22:00:56:390 SetFgRefreshInfo: Previous Machine Fg policy Synchronous, Reason: SyncPolicy.
USERENV(750.280) 22:00:56:390 SetFgRefreshInfo: Next Machine Fg policy Synchronous, Reason: SyncPolicy.
USERENV(750.280) 22:00:56:390 ProcessGPOs: No WMI logging done in this policy cycle.
USERENV(750.280) 22:00:56:390 LeaveCriticalPolicySection: Critical section 0x6d0 has been released.
USERENV(750.280) 22:00:56:390 ProcessGPOs: Computer Group Policy has been applied.
USERENV(750.280) 22:00:56:390 ProcessGPOs: Leaving with 1.
USERENV(750.280) 22:00:56:390 ApplyGroupPolicy: Leaving successfully.
USERENV(750.860) 22:00:56:640 GPOThread: Next refresh will happen in 115 minutes
This is telling us that we will be refreshing the policy in the foreground and the next one will occur the same way in 115 minutes and we are leaving successfully.
Now for a note about the next blog for the user processing, no one runs a pure Microsoft environment and almost every Userenv log I have ever seen had something in the order of this showing up:
USERENV(6e4.6d4) 22:00:56:890 GetUserNameAndDomain Failed to impersonate user
USERENV(6e4.6d4) 22:00:56:890 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.
So what is this? Note that the very first of all the sample lines that I have added so far has started with:
USERENV(750.280), the first number, 750, is the process identifier (PID) and the second number is the thread identifier (TID). You can open Calc and change the View to Scientific. Change the type to Hex then enter 750 and hit the Decimal radio button. Now you have a number of 1872, this is the PID for the process. Open Task Manager, go to View – Select Columns and put a check mark in the box for PID and hit OK. Now in the column next to the Image Name will be the PID. Sort the PID’s and look for the process associated with the number 1872 and that is the process that the Userenv logging is referring to. In this case the PID of 1872 was Winlogon.exe. If we do the same for the problem PID (6e4) we get 1764. That PID resolved to a third-party service that was causing problems.
I hope this helps in understanding how to read part of the Userenv logging that we can enable to help in determining issues when booting up, applying group policies, etc. I will complete the User processing in Part 2. Also, you can find additional information on this topic at Interpreting Userenv Log Files on TechNet.
I am going to continue using a Userenv log that I have where the customer was seeing the desktop hanging at “Applying Personal Settings.” To find the portion where the user starts his logon, search the log file for the user alias that they use to logon with:
USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpUserName = <User1>
You will also see this:
USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpDefaultPath = \DC1netlogonDefault User
By default we always look to the Netlogon share on a domain controller for the Default User profile. This goes way back to the old NT 4.0 days and it still is hanging around. Next we resolve the users name to a SID (Security Identifier) as follows:
USERENV(750.754) 22:01:02:812 LoadUserProfile: User sid: S-1-5-<domain sid-rid>
We do a check and see if the user is a local admin on the client they are logging onto:
USERENV(750.754) 22:01:02:812 RestoreUserProfile: User is a Admin
Now we actually go look and see if an existing profile exists or not to determine if we need to create a new one or whether the user has an existing profile:
USERENV(750.754) 22:01:02:812 ExtractProfileFromBackup: A profile already exists
USERENV(750.754) 22:01:02:812 PatchNewProfileIfRequred: A profile already exists with the current sid, exitting
USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Found entry in profile list for existing local profile
USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Local profile image filename = <C:Documents and Settingsuser1>
USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Expanded local profile image filename = < C:Documents and Settings user1>
USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: No local mandatory profile. Error = 2
USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Found local profile image file ok < C:Documents and Settings user1ntuser.dat>
So where do you look to find out if the user has an existing profile?
HKLMSoftwareMicrosoftWindows NTCurrentVersionProfileList
Under this key will be a list of SID’s corresponding to each user that has logged onto this client machine. If you highlight the ProfileList key you will notice some values there such as AllUsersProfile, DefaultUserProfile and the ProfilesDirectory. These values tell the system where the default directory is for the profiles then under that we know which directory the All Users and the Default Profile are. Drilling down underneath you can find the SID for the user you are looking for. Highlight it and note the ProfileImagePath value. This will point you to the directory where the system thinks your profile should be. There are other values here as well but we are not going to get into those. Note in the above output we check and see if the profile is a mandatory profile or not. How does it know whether the profile is mandatory or not? See the next line in the output at the end of the string we see Ntuser.dat in the profile path. If the Ntuser ended with a .man that would signify that the profile is mandatory. As you can see it ends with the .dat so the error = 2 means, “The system cannot find the file specified.” You can simply run “net helpmsg 2” from a command prompt to resolve some of the error messages to find out what they actually mean. In this case it did not find the Ntuser.man as the file it was looking for. So another question, what is the ntuser.dat file? This is the actual HKEY_CURRENT_USER hive you see in the registry when opening Regedit. It is simply a registry hive for the user’s profile to contain certain settings like desktop wallpaper, screen saver, application settings, etc. Once the profile is loaded we should see a line in the debug like this:
USERENV(750.754) 22:01:02:874 LoadUserProfile: Leaving with a value of 1.
The value of 1 means it was successful. This is not the time where the desktop starts showing up so don’t get confused here with that – the profile was loaded successfully. This simply means we loaded the Ntuser.dat file into the registry as the HKEY_CURRENT_USER hive. The next thing we do is start the Group Policy Processing for the user account:
USERENV(750.dec) 22:01:03:796 ProcessGPOs: Starting user Group Policy (Background) processing…
We go through the same as we did for the computer account; we need to determine the LDAP path of the user so we know where to look for any policies to apply.
USERENV(750.dec) 22:01:03:828 ProcessGPOs: User name is: CN=User1,OU=Users,OU=TX,OU=USA,DC=Domain,DC=com, Domain name is: Domain
USERENV(750.dec) 22:01:03:828 ProcessGPOs: Domain controller is: \DC1.Domain.COM Domain DN is Domain.COM
I won’t go through all the policy processing as we did in part one as it is all the same. The GPC and the GPT version numbers are checked, the display name, the common name is all the same. To know when we are done applying the user group policies look for the following in the log file:
USERENV(750.dec) 22:08:54:183 ProcessGPOs: User Group Policy has been applied.
USERENV(750.dec) 22:08:54:183 ApplyGroupPolicy: Leaving successfully.
So if you notice now between the time we logged in (22:01:02) loaded the profile and applied group policies successfully (22:08:54) took approximately 8 seconds. Also note that the desktop is still not loaded by default, we are not done yet. Now comes the time to run any logon scripts:
USERENV(46c.4c4) 22:08:54:777 LibMain: Process Name: C:WINNTSystem32WScript.exe
Now we are almost done, the GINA calls userinit.exe which in turn calls explorer.exe. Explorer is the process that brings up the shell which is the desktop with all its icons, etc. So in troubleshooting why it is taking so long for either the Userinit being called or Explorer being called you have to look to the log and see what is occurring.
USERENV(8c4.8c8) 22:08:55:808 LibMain: Process Name: C:WINNTsystem32userinit.exe
USERENV(8d8.8dc) 22:28:57:824 LibMain: Process Name: C:WINNTExplorer.EXE
Note the approximately 20 minutes difference in the time stamps of the two events above. So what is going on during this time? This is what was happening:
USERENV(6e4.6d4) 22:10:16:856 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.
USERENV(6e4.6d4) 22:10:17:090 ImpersonateUser: Failed to impersonate user with 5.
This was being logged into the Userenv log constantly. If you remember from Part 1, the 6e4 was the PID of the process that was running. In this log we could see that this PID was delaying Explorer from being called to start the shell. The PID 6e4 (hex) resolves to 1764 (decimal). If we look back in Task Manager we can see that the PID resolves to a 3rd party security service that was running. In this case we disabled that service and rebooted. We tested and no other issues came up with a delay in getting to the desktop. Here is another tidbit to help you out in case you are troubleshooting a remote machine. Let’s say someone sends you a Userenv.log file to look over, you see something similar as above but the user has either rebooted or shut down the machine so you have no way to look up that PID. Every time a service restarts or the machine restarts the process will have a new PID. Have the user generate a System Information file by going to Start – Run – Msinfo32 and hit enter. Once the System Information file comes up save the file as a System Information File with a .NFO extension. Now have the user send that file as well then in the left hand column expand Software Environment and highlight Running Tasks. There you will see all the processes running and their PID’s.
I will touch on some aspects of a roaming profile, all the information above has been for local profiles. When using a roaming profile you will see some slight differences in the Userenv log. For example if the roaming profile path is set on the user properties on the Account tab you will see the following:
USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpUserName = <User1>
USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpProfilePath = \fileserverprofilesUser1
This tells us that the roaming profile is located on the server called fileserver at the share called profiles then the user name. Once the SID has been resolved to a name we check to see if it is a cross forest logon.
USERENV(750.754) 22:01:02:796 CheckXForestLogon: checking x-forest logon, user handle = 560
USERENV(750.754) 22:01:02:796 CheckXForestLogon: not XForest logon.
There is a policy that allows cross forest roaming profiles to be loaded. By default if user account is located in one forest and they attempt to logon to a machine in another forest they will get a new default profile unless the following policy is set:
Computer Configuration Administrative Templates System Group Policy Allow Cross-Forest User Policy and Roaming User Profiles
This policy will need to be set in the domain where the machine account is located. Next we actually map a drive to the share \fileserverprofilesand most of the time it will be E drive. The drive will look like E:user1 now. Next we go through the same procedure as before, pinging the DC to determine if we are on a fast link or not. Now we check to see if the user account has ownership of the files in the profile:
USERENV(750.754) 22:01:02:796 CheckRoamingShareOwnership: checking ownership for E:User11
USERENV(750.754) 22:01:02:796 CheckRoamingShareOwnership: owner is the right user
At times the user may not be the owner of the files located in the share. Let’s say the file server was changed and now points to a new file server then the files copied over manually to the new server share. The Administrators group will most likely be the new owner of the files. So when the user logs on they will get an error attempting to load the profile unless the following policy is set:
Computer Configuration Administrative Templates System User Profiles Do not check for user ownership of Roaming Profile Folders
Next we perform the same checks to see if it is a mandatory profile or not then start reconciling the roaming profile with the locally cached profile if one exists. One thing to keep in mind is that all changes made to the profile are done locally and are not propagated to the server share until the user logs off.
I hope these two parts help you in understanding how to read a Userenv log. By no means will you be an expert in reading one the first time. It takes practice and looking at many of them to determine what is happening or not happening as the case may be. Hopefully it will give you a better understanding of how the OS is designed and what is actually occurring during the profile load.
For more information check out some of the following articles:
Interpreting Userenv Log Files
http://technet.microsoft.com/en-us/library/cc786775.aspx
Group Policy Wiki
http://grouppolicy.editme.com
250842 Troubleshooting Group Policy application problems
http://support.microsoft.com/kb/250842
221833 How to enable user environment debug logging in retail builds of Windows
http://support.microsoft.com/kb/221833