Understanding How to Read a Userenv Log – Part 1

[clandis]

First published on TechNet on Nov 11, 2008
Hey everyone, this is Mark from the Directory Services team. We get calls all the time where enabling Userenv logging is necessary to see exactly what is happening with group policy and profile loading. If you have ever looked at one it can be confusing to say the least. One thing to remember is that if the logging is not enabled then do not try and interpret the log since very minimal logging is enabled by default! I am going to break this down into 2 parts with one being the Computer side and its processing then the second part of the User side and its processing. So let’s jump in and get our feet wet with some of the basics.

First, what is Userenv logging? This is short for “User Environment.” How do I enable the logging? You can reference the following KB article:

221833 How to enable user environment debug logging in retail builds of Windows
http://support.microsoft.com/kb/221833

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.

- Mark Ramey