Alos lookat:
https://technet.microsoft.com/en-us/library/cc786775(v=ws.10).aspx
As promised here is the second part of Understanding How to Read a Userenv Log (see Part 1 if you missed it). Most of the time when we need to enable Userenv logging is due to a delay of getting to the desktop after entering our credentials. Normally the user will be stuck at “Applying Personal Settings” is most often the scenario we see. The problem can stem from several different problems. One can be that another process, usually the anti-virus, has a lock on a file within the profile and cannot open the file. When this happens the user will get a new default profile. A reboot of the client will temporarily resolve this forcing all handles to be released. This does not always work but at times it will allow the user to logon and receive his old profile. Eventually the problem will come back. There also could be permissions issue or network issues when attempting to load a roaming profile. There are many different scenarios that plague users and loading their profiles.
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 = \\DC1\netlogon\Default 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 Settings\user1>
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 \user1\ntuser.dat>
So where do you look to find out if the user has an existing profile?
HKLM\Software\Microsoft\Windows NT\CurrentVersion\ProfileList
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:\WINNT\System32\WScript.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:\WINNT\system32\userinit.exe
USERENV(8d8.8dc) 22:28:57:824 LibMain: Process Name: C:\WINNT\Explorer.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.
In order to analyze this issue, i record the information, please see the attachement
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 = \\fileserver\profiles\User1
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 \\fileserver\profiles and 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
