UserEnvLogging
There are many issues that can be resolved or clarified by reading a Userenv log:- Group Policies not processed or not applied as Expected
- Folder Redirection Does Not Occur
- Profile or Registry Hive Load, Unload, or Deletion, Failures
- Not getting logon script or Script not applied as expected
- Default Behaviors are Occurring Because a Slow Link Was Detected
- Roaming Profile Issues- Slow Logon Issues
How to Read a Userenv log
Below we have an example Userenv log, We will walk the log and determine normal behaviors and touch on some known, common, issues. Some sections of this log have been parsed for readability.
USERENV(b8.a0) 13:49:53:519 MyGetUserName: GetUserNameEx failed with 1722.
USERENV(b8.a0) 13:49:54:140 MyGetUserName: GetUserNameEx failed with 1722.
USERENV(b8.a0) 13:49:54:760 MyGetUserName: GetUserNameEx failed with 1722.
USERENV(b8.a0) 13:49:54:760 GetUserGuid: Failed to get user guid with 1722.
USERENV(b8.a0) 13:49:54:891 MyGetUserName: GetUserNameEx failed with 1722.
USERENV(b8.a0) 13:49:55:512 MyGetUserName: GetUserNameEx failed with 1722.
USERENV(b8.70) 12:16:33:102
\\ The above errors are normal in this log and they reflect the time that logging was enabled before the client logged off and logged on. It is important to get the account name of the user you are testing with. Search the log for the account name and delete everything above the line break.
=========================================================
USERENV(b8.70) 12:16:33:102 LoadUserProfile: Entering, hToken = <0x528>, lpProfileInfo = 0x6f64c
USERENV(b8.70) 12:16:33:102 LoadUserProfile: Entering, hToken = <0x528>, lpProfileInfo = 0x6f64c
\\ New to SP4 and 2003 is CheckXForestLogon. If User profile is stored on a machine that is a member of a different domain then the one we are logging into we will not load the roaming profile by default. Reg key can change this behavior.
Example:
USERENV(31c.7f4) 21:34:15:265 CheckXForestLogon: checking x-forest logon, user handle = 452
USERENV(31c.7f4) 21:34:15:328 CheckXForestLogon CheckUserInMachineForest failed
-----------------------------------------------------------------------------------------------------------
USERENV(b8.70) 12:16:33:102 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>
USERENV(b8.70) 12:16:33:102 LoadUserProfile: lpProfileInfo->lpUserName =
\\ User who is logging in
USERENV(b8.70) 12:16:33:102 LoadUserProfile: NULL central profile path
USERENV(b8.70) 12:16:33:102 LoadUserProfile: lpProfileInfo->lpDefaultPath =
<\\ USSJDC1\netlogon\Default User>
\\ Shows logon server and Netlogon share we will use
USERENV(b8.70) 12:16:33:102 LoadUserProfile: NULL server name
\\ If the profile is Roaming we will see an entry here with the path to the roaming profile. *New to SP4 and 2003 Server we will CheckRoamingShareOwnership, if we are not the owner of the profile the profile will fail to load. Example:
USERENV(31c.7f4) 21:34:15:562 CheckRoamingShareOwnership: checking ownership for \\wyf1\profiles\test1
USERENV(31c.7f4) 21:34:15:593 CheckRoamingShareOwnership: owner is
S-1-5-21-1120813546-1682452264-1544898942-500!
USERENV(31c.7f4) 21:34:15:609 IsCentralProfileReachable: Ownership check failed with 8007051B
\\Check the Ownership NTFS setting to see who owns the profile directory for the
affected user(s) to resolve this issue.
USERENV(b8.70) 12:16:33:102 LoadUserProfile: Created mutex. Waiting...
USERENV(b8.70) 12:16:33:102 LoadUserProfile: Wait succeeded. Mutex currently held.
USERENV(b8.70) 12:16:33:102 RestoreUserProfile: Entering
USERENV(b8.70) 12:16:33:102 IsCentralProfileReachable: Entering
USERENV(b8.70) 12:16:33:102 IsCentralProfileReachable: Null path. Leaving
USERENV(b8.70) 12:16:33:102 RestoreUserProfile: Profile path = <>
USERENV(b8.70) 12:16:33:102 ExtractProfileFromBackup: A profile already exists
USERENV(b8.70) 12:16:33:102 PatchNewProfileIfRequred: A profile already exists with the current sid, exitting
USERENV(b8.70) 12:16:33:102 CreateLocalProfileKey: Not setting additional Security
USERENV(b8.70) 12:16:33:102 GetExistingLocalProfileImage: Found entry in profile list for existing local profile
USERENV(b8.70) 12:16:33:102 GetExistingLocalProfileImage: Local profile image filename = <%SystemDrive%\Documents and Settings\rtest>
\\ Client has logged on to this box before and a local profile exists. We do not need to create a new one. For a new user or for a user with a roaming profile and the “delete local profile at logoff” policy is enabled we will see this message:
One way or another, we do not have a local profile. Creating Local profile at
USERENV(b8.70) 12:16:33:112 GetExistingLocalProfileImage: Expanded local profile image filename =
USERENV(b8.70) 12:16:33:122 GetExistingLocalProfileImage: No local mandatory profile. Error = 2
\\ Normal message, local profile does not have the .man extension
USERENV(b8.70) 12:16:33:152 GetExistingLocalProfileImage: Found local profile image file ok
USERENV(b8.70) 12:16:33:152 GetExistingLocalProfileImage: Failed to query low profile unload time with error 2
USERENV(b8.70) 12:16:33:152 Local Existing Profile Image is reachable
USERENV(b8.70) 12:16:33:152 Local profile name is
USERENV(b8.70) 12:16:33:152 RestoreUserProfile: No central profile. Attempting to load local profile.
USERENV(b8.70) 12:16:33:232 MyRegLoadKey: Mutex released. Returning 0.
USERENV(b8.70) 12:16:33:302 MyRegLoadKey: Mutex released. Returning 0.
USERENV(b8.70) 12:16:33:302 CreateClassHive: existing user classes hive found
USERENV(b8.70) 12:16:33:302 RestoreUserProfile: About to Leave. Final Information follows:
USERENV(b8.70) 12:16:33:302 Profile was successfully loaded.
USERENV(b8.70) 12:16:33:302 lpProfile->lpRoamingProfile = <>
USERENV(b8.70) 12:16:33:302 lpProfile->lpLocalProfile =
USERENV(b8.70) 12:16:33:302 lpProfile->dwInternalFlags = 0x0
USERENV(b8.70) 12:16:33:302 RestoreUserProfile: Leaving.
USERENV(b8.70) 12:16:33:432 UpgradeProfile: Entering
USERENV(b8.70) 12:16:33:432 UpgradeProfile: Build numbers match
USERENV(b8.70) 12:16:33:432 UpgradeProfile: Leaving Successfully
USERENV(b8.70) 12:16:33:442 LoadUserProfile: Releasing mutex.
USERENV(b8.70) 12:16:33:442 LoadUserProfile: Leaving with a value of 1.
USERENV(b8.70) 12:16:33:442 LoadUserProfile: hProfile = <0x69c>
USERENV(b8.70) 12:16:33:442 =========================================================
USERENV(b8.c4) 12:16:34:113 ApplyGroupPolicy: Entering. Flags = 6
USERENV(b8.c4) 12:16:34:113 ProcessGPOs:
USERENV(b8.c4) 12:16:34:123 ProcessGPOs:
USERENV(b8.c4) 12:16:34:123 ProcessGPOs: Starting user Group Policy processing...
USERENV(b8.c4) 12:16:34:123 ProcessGPOs:
USERENV(b8.c4) 12:16:34:123 ProcessGPOs:
USERENV(b8.c4) 12:16:34:123 EnterCriticalPolicySection: User critical section has been claimed. Handle = 0x6c4
USERENV(b8.c4) 12:16:34:123 ProcessGPOs: Machine role is 2.
USERENV(b8.c4) 12:16:34:123 PingComputer: First time: 0
USERENV(b8.c4) 12:16:34:123 PingComputer: Fast link. Exiting.
\\ Here is where we determine Slow Link. We do this by Ping if ICMP is disabled we will assume Slow Link. By Default the following policies will not apply over Slow Link:
Login Scripts, Folder Redirection, Application Deployment, Disk Quotas
Slow Link detection can be disabled in local registry or via group policy
227369 Default Behavior for Group Policy Extensions with Slow Link
http://kb/article.asp?id=Q227369
USERENV(b8.c4) 12:16:34:123 ProcessGPOs: User name is: CN=regulatory,OU=Regulatory,OU=Operations,OU=SouthJordan,DC=merit,DC=com, Domain name is: MMNT
USERENV(b8.c4) 12:16:34:133 ProcessGPOs: Domain controller is: \\ussjdc1.merit.com Domain DN is merit.com
USERENV(b8.c4) 12:16:34:133 ProcessGPOs: Calling GetGPOInfo for normal policy mode
\\ First we find out what GPOs apply to our user then to our computer account but we do not process the GPOS yet
USERENV(b8.c4) 12:16:34:133 GetGPOInfo: ********************************
USERENV(b8.c4) 12:16:34:133 GetGPOInfo: Entering...
USERENV(b8.c4) 12:16:34:143 GetGPOInfo: Server connection established.
USERENV(b8.c4) 12:16:34:153 GetGPOInfo: Bound successfully.
USERENV(b8.c4) 12:16:34:153 SearchDSObject: Searching
USERENV(b8.c4) 12:16:34:153 SearchDSObject: Found GPO(s): <[LDAP://CN={4DD0AD5A-DEB6-474A-9D69-71B52C445B5A},CN=Policies,CN=System,DC=merit,DC=com;0][LDAP://CN={C2699861-836E-48B8-8194-405FA8F70329},CN=Policies,CN=System,DC=merit,DC=com;0]>
USERENV(b8.c4) 12:16:34:153 ProcessGPO: ==============================
USERENV(b8.c4) 12:16:34:153 ProcessGPO: Deferring search for
USERENV(b8.c4) 12:16:34:153 ProcessGPO: ==============================
USERENV(b8.c4) 12:16:34:153 ProcessGPO: Deferring search for
USERENV(b8.c4) 12:16:34:163 SearchDSObject:
USERENV(b8.c4) 12:16:34:163 SearchDSObject: Searching
USERENV(b8.c4) 12:16:34:163 SearchDSObject: Found GPO(s): <[LDAP://CN={C2699861-836E-48B8-8194-405FA8F70329},CN=Policies,CN=System,DC=merit,DC=com;0]>
USERENV(b8.c4) 12:16:34:203 ProcessGPO: Found file system path of: <\\merit.com\SysVol\merit.com\Policies\{3F810FD9-EA1E-4EDB-9359-36C1DA17E00C}>
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Found common name of: <{3F810FD9-EA1E-4EDB-9359-36C1DA17E00C}>
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Found display name of:
\\ After we have determined the GPOs applied to us, we process them in order. Above we see the GUID and the Display name of the GPO that applies to us
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Found user version of: GPC is 23, GPT is 23
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Found flags of: 0
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{0F6B957E-509E-11D1-A7CC-0000F87571E3}][{A2E30F80-D7DE-11D2-BBDE-00C04F86AE3B}{FC715823-C5FB-11D1-9EEF-00A0C90347FF}]
USERENV(b8.c4) 12:16:34:244 ProcessGPO: ==============================
USERENV(b8.c4) 12:16:34:244 ProcessGPO: ==============================
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Searching
USERENV(b8.c4) 12:16:34:244 ProcessGPO: User has access to this GPO.
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Found functionality version of: 2
USERENV(b8.c4) 12:16:34:244 ProcessGPO: Found file system path of: <\\merit.com\SysVol\merit.com\Policies\{4DD0AD5A-DEB6-474A-9D69-71B52C445B5A}>
USERENV(b8.c4) 12:16:34:324 ProcessGPO: Found common name of: <{4DD0AD5A-DEB6-474A-9D69-71B52C445B5A}>
USERENV(b8.c4) 12:16:34:324 ProcessGPO: Found display name of:
USERENV(b8.c4) 12:16:34:324 ProcessGPO: Found user version of: GPC is 5, GPT is 5
\\ By default registry keys applied via GPO ARE NOT processed at every logon. We compare user version with gpt version and if the policy has not changed we will not reapply.
USERENV(b8.c4) 12:16:34:324 ProcessGPO: Found flags of: 0
USERENV(b8.c4) 12:16:34:324 ProcessGPO: Found extensions: [{42B5FAAE-6536-11D2-AE5A-0000F87571E3}{40B66650-4972-11D1-A7CA-0000F87571E3}]
USERENV(b8.c4) 12:16:34:324 ProcessGPO: ==============================
USERENV(b8.c4) 12:16:34:324 ProcessGPO: ==============================
USERENV(b8.c4) 12:16:34:354 GetGPOInfo: GPO Local Group Policy doesn't contain any data since the version number is 0. It will be skipped.
USERENV(b8.c4) 12:16:34:354 GetGPOInfo: Leaving with 1
USERENV(b8.c4) 12:16:34:354 GetGPOInfo: ********************************
USERENV(b8.c4) 12:16:34:354 ProcessGPOs: OpenThreadToken failed with error 1008, assuming thread is not impersonating
USERENV(b8.c4) 12:16:34:354 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:354 ProcessGPOs: Processing extension Registry
USERENV(b8.c4) 12:16:34:354 CompareGPOLists: The lists are the same.
USERENV(b8.c4) 12:16:34:354 CheckGPOs: No GPO changes and no security group membership change and extension Registry has NoGPOChanges set.
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: Processing extension Security
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: Extension Security skipped with flags 0x6.
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: Processing extension Internet Explorer Branding
\\ IE Polices are applied differently than other policies.
USERENV(b8.c4) 12:16:34:364 CompareGPOLists: The lists are the same.
USERENV(b8.c4) 12:16:34:364 CheckGPOs: No GPO changes and no security group membership change and extension Internet Explorer Branding has NoGPOChanges set.
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: Processing extension EFS recovery
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: Extension EFS recovery skipped with flags 0x6.
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:364 ProcessGPOs: Processing extension Application Management
USERENV(b8.c4) 12:16:34:364 CompareGPOLists: The lists are the same.
USERENV(b8.c4) 12:16:34:374 CheckGPOs: No GPO changes but couldn't read extension Application Management's status or policy time.
USERENV(b8.c4) 12:16:34:374 ProcessGPOs: Extension Application Management skipped because both deleted and changed GPO lists are empty.
USERENV(b8.c4) 12:16:34:374 ProcessGPOs: -----------------------
USERENV(b8.c4) 12:16:34:374 ProcessGPOs: Processing extension IP Security
USERENV(b8.c4) 12:16:34:374 ProcessGPOs: Extension IP Security skipped with flags 0x6.
USERENV(b8.c4) 12:16:34:374 LeaveCriticalPolicySection: Critical section 0x6c4 has been released.
USERENV(b8.c4) 12:16:34:374 ProcessGPOs: User Group Policy has been applied.
USERENV(b8.c4) 12:16:34:374 ProcessGPOs: Leaving with 1.
USERENV(b8.c4) 12:16:34:374 ApplyGroupPolicy: Leaving successfully.
USERENV(b8.408) 12:16:35:255 GPOThread: Next refresh will happen in 105 minutes
USERENV(144.3d8) 12:16:38:760 LibMain: Process Name: C:\WINNT\system32\userinit.exe
USERENV(40c.3dc) 12:16:41:624 LibMain: Process Name: C:\WINNT\Explorer.EXE
USERENV(404.3fc) 12:16:53:020 LibMain: Process Name: C:\WINNT\System32\mobsync.exe
USERENV(294.3ec) 12:17:12:097 LibMain: Process Name: C:\WINNT\system32\mobsync.exe
\\ End of Profile Load shows some process configured to start at login time.
USERENV(b8.70) 12:17:13:168 UnloadUserProfile: Entering, hProfile = <0x69c>
USERENV(b8.70) 12:17:13:168 UnloadUserProfile: Created mutex. Waiting...
USERENV(b8.70) 12:17:13:168 UnloadUserProfile: Wait succeeded. Mutex currently held.
USERENV(b8.70) 12:17:13:188 MyRegUnloadKey: Mutex released. Returning 1.
USERENV(b8.70) 12:17:13:188 UnloadUserProfile: Succesfully unloaded profile
\\ ProfileUnload Success
USERENV(b8.70) 12:17:13:188 MyRegUnloadKey: Mutex released. Returning 1.
USERENV(b8.70) 12:17:13:198 UnLoadClassHive: Successfully unmounted S-1-5-21-62665781-543716556-941767090-6690_Classes
\\ Users Registry Hive Successfully Unloaded from HKey_Users
USERENV(b8.70) 12:17:13:198 UnloadUserProfile: Successfully unloaded user classes
USERENV(b8.70) 12:17:13:198 UnloadUserProfile: Impersonated user
USERENV(b8.70) 12:17:13:198 UnloadUserProfile: Writing local ini file
USERENV(b8.70) 12:17:13:208 UnloadUserProfile: Reverting to Self
USERENV(b8.70) 12:17:13:208 UnloadUserProfile: exitting and cleaning up
USERENV(b8.70) 12:17:13:208 LoadUserProfile: Releasing mutex.
USERENV(b8.70) 12:17:13:208 UnloadUserProfile: Leaving with a return value of 1
USERENV(1ac.4d8) 12:17:23:303 LibMain: Process Name: C:\WINNT\system32\spoolsv.exe
