Freigeben über

UserEnv Debugging Line by Line

  • Artikel

There aren’t a lot of documents on the Internet about how to interpret UserEnv debugging logs. I’ll admit that I do not have a dictionary for every single line that anyone could possibly see in a UserEnv log. This blog is an attempt to decipher the UserEnv log line by line. There are some lines that have been removed because of redundancy.

 

The Environment:

 

Windows Server 2003 Domain Controller for contoso.com (RootDC)

Two client machines that are both Windows XP (XPClient1 and XPClient2)

Two user accounts during the lab reproduction (HQUser and RemoteUser)

 

Let’s take a look at the boot process of a Windows XP machine before we start breaking things. This UserEnv log is taken from a client machine located in the OU named Laptops. The full distinguished name of this computer is CN=XPCLIENT2,OU=Laptops,OU=Company Computers,DC=contoso,DC=com. At first, during the boot up process, the client machine begins by starting winlogon service.

USERENV(16c.170) 12:03:10:268 LibMain: Process Name: \??\C:\WINDOWS\system32\winlogon.exe

USERENV(16c.170) 12:03:10:498 Entering CUserProfile::Initialize ...

USERENV(16c.170) 12:03:10:498 CUserProfile::Initialize called by winlogon

USERENV(16c.170) 12:03:10:498 CUserProfile::Initialize: critical section initialized

USERENV(16c.170) 12:03:10:498 CSyncManager::Initialize: critical section initialized

USERENV(16c.170) 12:03:10:498 CUserProfile::Initialize: registry key Software\Microsoft\Windows NT\CurrentVersion\ProfileList opened

As we can see, this log contains the time of each event but does not contain the date. Because of this, a good troubleshooting step would be to remotely delete the userenv.log file prior to performing whatever action you want to troubleshoot such as GPO processing during boot or GPO processing during logon.

Another point to note is the process itself. In the above snippet, we see the process 16c.170. This information is in HEX and the first part of this HEX value is the process itself and the second part corresponds to the thread. Using a converter, 16c translates to 364. If you then run either task manager or task list and view the Process ID (PID) of the Winlogon process it will be process ID 364. This is the PID of my Winlogon process and would change on each client.

So now the Winlogon process has initialized and the computer then starts a cleanup process of profiles that exist on the machine. This section is rather long and has been truncated so that it doesn’t include each and every SID/Profile cleanup process.

USERENV(16c.170) 12:03:10:508 CUserProfile::Initialize: Proccessing S-1-5-21-3817846394-4251116553-2531831203-1106

USERENV(16c.170) 12:03:10:508 CSyncManager::EnterLock <S-1-5-21-3817846394-4251116553-2531831203-1106>

USERENV(16c.170) 12:03:10:508 CSyncManager::EnterLock: No existing entry found

USERENV(16c.170) 12:03:10:508 CSyncManager::EnterLock: New entry created

USERENV(16c.170) 12:03:10:508 CHashTable::HashAdd: S-1-5-21-3817846394-4251116553-2531831203-1106 added in bucket 7

USERENV(16c.170) 12:03:10:508 CUserProfile::CleanupUserProfile: Enter critical section.

USERENV(16c.170) 12:03:10:508 CUserProfile::GetRefCountAndFlags: Ref count is 0, state is 00000000

USERENV(16c.170) 12:03:10:508 CSyncManager::LeaveLock <S-1-5-21-3817846394-4251116553-2531831203-1106>

USERENV(16c.170) 12:03:10:508 CSyncManager::LeaveLock: Lock released

USERENV(16c.170) 12:03:10:508 CHashTable::HashDelete: S-1-5-21-3817846394-4251116553-2531831203-1106 deleted

USERENV(16c.170) 12:03:10:508 CSyncManager::LeaveLock: Lock deleted

USERENV(16c.170) 12:03:10:508 CUserProfile::CleanupUserProfile: Leave critical section

USERENV(16c.170) 12:03:10:508 CUserProfile::Initialize: Proccessing S-1-5-21-3817846394-4251116553-2531831203-1105

USERENV(16c.170) 12:03:10:508 CSyncManager::EnterLock <S-1-5-21-3817846394-4251116553-2531831203-1105>

USERENV(16c.170) 12:03:10:508 CSyncManager::EnterLock: No existing entry found

USERENV(16c.170) 12:03:10:508 CSyncManager::EnterLock: New entry created

USERENV(16c.170) 12:03:10:508 CHashTable::HashAdd: S-1-5-21-3817846394-4251116553-2531831203-1105 added in bucket 6

USERENV(16c.170) 12:03:10:508 CUserProfile::CleanupUserProfile: Enter critical section.

USERENV(16c.170) 12:03:10:508 CUserProfile::GetRefCountAndFlags: Ref coulnt is 0, state is 00000000

USERENV(16c.170) 12:03:10:508 CSyncManager::LeaveLock <S-1-5-21-3817846394-4251116553-2531831203-1105>

USERENV(16c.170) 12:03:10:508 CSyncManager::LeaveLock: Lock released

USERENV(16c.170) 12:03:10:508 CHashTable::HashDelete: S-1-5-21-3817846394-4251116553-2531831203-1105 deleted

USERENV(16c.170) 12:03:10:508 CSyncManager::LeaveLock: Lock deleted

USERENV(16c.170) 12:03:10:508 CUserProfile::CleanupUserProfile: Leave critical section

USERENV(16c.170) 12:03:10:518 CUserProfile::Initialize: RpcServerRegisterIfEx successful

USERENV(16c.170) 12:03:10:528 Exiting CUserProfile::Initialize, successful

We then start services.exe and lsass.exe:

USERENV(198.19c) 12:03:10:588 LibMain: Process Name: C:\WINDOWS\system32\services.exe

USERENV(1a4.1a8) 12:03:10:628 LibMain: Process Name: C:\WINDOWS\system32\lsass.exe

Now we check to see whether the computer is flagged with the need to do a Synchronous Foreground refresh of Group Policy.

USERENV(16c.170) 12:03:10:669 IsSyncForegroundPolicyRefresh: Asynchronous, Reason: NoNeedForSync

An example of a scenario when this line would read differently is in a situation where we created a Group Policy that assigned software to the computer. In that case, because of the way Windows XP works with Asynchronous processing of Group Policy, the original pass-through of the Group Policy processing would recognize that it needed to install software, flag the system for a Synchronous processing of Group Policy at next boot, and would install the software synchronously at next Foreground Group Policy processing (i.e. at next boot).

Now we start the Network Service.

USERENV(248.24c) 12:03:10:999 LibMain: Process Name: C:\WINDOWS\system32\svchost.exe

Group Policy runs under the System context. The Network Service also has a profile. This can be seen by configuring explorer to display hidden files and browsing to C:\Documents and Settings\. Inside there is a NetworkService profile. In order for Group Policy to open the profile and perform tasks as a user (in this case a service), it must impersonate the user. In the next line, the system checks to see if it can impersonate the NetworkService user account yet we have not begun to impersonate the user and are still running as the System context.

USERENV(198.19c) 12:03:11:139 LoadUserProfile: Yes, we can impersonate the user. Running as self

USERENV(198.19c) 12:03:11:139 =========================================================

Computer starts loading the NetworkService profile. You’ll see that it switches from self to client and back numerous times:

USERENV(198.19c) 12:03:11:139 LoadUserProfile: Entering, hToken = <0x29c>, lpProfileInfo = 0x7fcf8

USERENV(198.19c) 12:03:11:139 LoadUserProfile: lpProfileInfo->dwFlags = <0x9>

USERENV(198.19c) 12:03:11:139 LoadUserProfile: lpProfileInfo->lpUserName = <NetworkService>

USERENV(198.19c) 12:03:11:139 LoadUserProfile: NULL central profile path

USERENV(198.19c) 12:03:11:139 LoadUserProfile: NULL default profile path

USERENV(198.19c) 12:03:11:139 LoadUserProfile: NULL server name

USERENV(198.19c) 12:03:11:139 GetInterface: Returning rpc binding handle

USERENV(16c.270) 12:03:11:139 IProfileSecurityCallBack: client authenticated.

USERENV(16c.270) 12:03:11:139 DropClientContext: Got client token 00000348, sid = S-1-5-18

USERENV(16c.270) 12:03:11:139 MIDL_user_allocate enter

USERENV(16c.270) 12:03:11:139 DropClientContext: load profile object successfully made

USERENV(16c.270) 12:03:11:139 DropClientContext: Returning 0

USERENV(198.19c) 12:03:11:139 LoadUserProfile: Calling DropClientToken (as self) succeeded

USERENV(16c.184) 12:03:11:139 IProfileSecurityCallBack: client authenticated.

USERENV(16c.184) 12:03:11:139 In LoadUserProfileP

USERENV(16c.184) 12:03:11:139 LoadUserProfile: Running as client

USERENV(16c.184) 12:03:11:139 =========================================================

-----SNIP------

USERENV(16c.184) 12:03:11:139 GetExistingLocalProfileImage: Local profile image filename = <%SystemDrive%\Documents and Settings\NetworkService>

USERENV(16c.184) 12:03:11:139 GetExistingLocalProfileImage: Expanded local profile image filename = <C:\Documents and Settings\NetworkService>

Here we’re checking for a Mandatory profile. There isn’t one so we get an error of 2.

USERENV(16c.184) 12:03:11:139 GetExistingLocalProfileImage: No local mandatory profile. Error = 2

Continuing:

USERENV(16c.184) 12:03:11:139 GetExistingLocalProfileImage: Found local profile image file ok <C:\Documents and Settings\NetworkService\ntuser.dat>

USERENV(16c.184) 12:03:11:139 Local Existing Profile Image is reachable

USERENV(16c.184) 12:03:11:139 Local profile name is <C:\Documents and Settings\NetworkService>

Now the computer looks for a Roaming Profile. There isn’t one so it loads the local profile:

USERENV(16c.184) 12:03:11:139 RestoreUserProfile: No central profile. Attempting to load local profile.

USERENV(16c.184) 12:03:11:139 MyRegLoadKey: Returning 00000000

USERENV(16c.184) 12:03:11:139 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.

USERENV(16c.184) 12:03:11:139 MyRegLoadKey: Returning 00000000

USERENV(16c.184) 12:03:11:139 CreateClassHive: existing user classes hive found

USERENV(16c.184) 12:03:11:139 RestoreUserProfile: About to Leave. Final Information follows:

USERENV(16c.184) 12:03:11:139 Profile was successfully loaded.

----- More profile loading SNIP -----

More impersonating user and back:

USERENV(16c.184) 12:03:11:179 LoadUserProfile: Impersonated user: 0000034c, 00000358

USERENV(1a4.1e4) 12:03:11:179 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.

USERENV(1a4.1e4) 12:03:11:179 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.

USERENV(16c.184) 12:03:11:209 LoadUserProfile: Reverted to user: 00000000

USERENV(16c.184) 12:03:11:209 LoadUserProfile: Reverted back to user <00000000>

USERENV(16c.184) 12:03:11:209 LoadUserProfile: Leaving with a value of 1.

USERENV(16c.184) 12:03:11:209 =========================================================

USERENV(16c.184) 12:03:11:209 LoadUserProfileI: returning 0

USERENV(198.19c) 12:03:11:209 LoadUserProfile: Running as self

USERENV(198.19c) 12:03:11:209 LoadUserProfile: Calling LoadUserProfileI (as user) succeeded

----- Snipping the rest of the NetworkService profile loading -----

Starting other processes (note the different HEX for the process ID):

USERENV(328.32c) 12:03:13:372 LibMain: Process Name: C:\WINDOWS\system32\svchost.exe

USERENV(380.384) 12:03:13:623 LibMain: Process Name: C:\WINDOWS\system32\spoolsv.exe

Now let’s process some Group Policy:

USERENV(16c.300) 12:03:23:076 ApplyGroupPolicy: Entering. Flags = f

USERENV(16c.300) 12:03:23:076 ProcessGPOs:

USERENV(16c.300) 12:03:23:076 ProcessGPOs:

Informing that we’ll be applying Group Policy asynchronously:

USERENV(16c.300) 12:03:23:076 ProcessGPOs: Starting computer Group Policy (Async forground) processing...

USERENV(16c.300) 12:03:23:076 ProcessGPOs:

USERENV(16c.300) 12:03:23:076 ProcessGPOs:

USERENV(16c.300) 12:03:23:076 EnterCriticalPolicySectionEx: Entering with timeout 600000 and flags 0x0

USERENV(16c.300) 12:03:23:076 EnterCriticalPolicySectionEx: Machine critical section has been claimed. Handle = 0x728

USERENV(16c.300) 12:03:23:076 EnterCriticalPolicySectionEx: Leaving successfully.

USERENV(16c.300) 12:03:23:076 ProcessGPOs: Machine role is 2.

Next is where the computer pings the domain controller during slow link detection. By default, a slow link is defined as 500 kb per second or slower. That number can be configured for the user, computer, or both.

USERENV(16c.300) 12:03:23:076 PingComputer: PingBufferSize set as 2048

USERENV(16c.300) 12:03:23:086 PingComputer: Adapter speed 100000000 bps

USERENV(16c.300) 12:03:23:086 PingComputer: First time: 3

USERENV(16c.300) 12:03:23:086 PingComputer: Fast link. Exiting.

The query proved to be a fast link and, therefore, exited the slow link detection. If the ping would have resulted in a slow link, by default, certain policy settings would not be applied. These are settings such as Folder Redirection and Software Installation. These are settings that we wouldn’t want to configure across a slow link. That would not be optimal.

Again we check to see if we can impersonate the user, which we can. The computer reports that it’s able to impersonate the user and that it’s currently running as the system and not the user.

USERENV(198.430) 12:03:23:297 LoadUserProfile: Yes, we can impersonate the user. Running as self

USERENV(198.430) 12:03:23:297 =========================================================

USERENV(198.430) 12:03:23:297 LoadUserProfile: Entering, hToken = <0x1b8>, lpProfileInfo = 0x9bf6e8

USERENV(198.430) 12:03:23:297 LoadUserProfile: lpProfileInfo->dwFlags = <0x9>

USERENV(198.430) 12:03:23:297 LoadUserProfile: lpProfileInfo->lpUserName = <LocalService>

USERENV(198.430) 12:03:23:297 LoadUserProfile: NULL central profile path

USERENV(198.430) 12:03:23:297 LoadUserProfile: NULL default profile path

USERENV(198.430) 12:03:23:297 LoadUserProfile: NULL server name

----- Snip (Some other processes start up but I’ve removed them) -----

Back to the GPO Processing. We provide the client network address as well as the user name (in this case the computer name):

USERENV(16c.300) 12:03:23:737 ProcessGPOs: network name is 10.0.0.0

USERENV(16c.300) 12:03:23:747 ProcessGPOs: User name is: CN=XPCLIENT2,OU=Laptops,OU=Company Computers,DC=contoso,DC=com, Domain name is: CONTOSO

USERENV(16c.300) 12:03:23:747 ProcessGPOs: Domain controller is: \\ROOTDC.contoso.com Domain DN is contoso.com

The client then queries for a RSOP entry point for the client side extensions. This occurs every time GPO is processed.

USERENV(16c.300) 12:03:23:747 ReadGPExtensions: Rsop entry point not found for gptext.dll.

USERENV(16c.300) 12:03:23:747 ReadGPExtensions: Rsop entry point not found for dskquota.dll.

USERENV(16c.300) 12:03:23:747 ReadGPExtensions: Rsop entry point not found for gptext.dll.

USERENV(16c.300) 12:03:23:747 ReadGPExtensions: Rsop entry point not found for iedkcs32.dll.

USERENV(16c.300) 12:03:23:747 ReadGPExtensions: Rsop entry point not found for scecli.dll.

USERENV(16c.300) 12:03:23:747 ReadGPExtensions: Rsop entry point not found for C:\WINDOWS\System32\cscui.dll.

USERENV(16c.300) 12:03:23:747 ReadGPExtensions: Rsop entry point not found for gptext.dll.

The Winlogon GPO process then looks for the previous status of each client side extension. The purpose of this query is to determine whether or not any settings have changed for the client side extension. The previous status for each client side extension is read and then the Winlogon process determines whether or not a client side extension setting has changed and if so, determines the settings that need to change based on that.

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {35378EAC-683F-11D2-A89A-00C04FBBCFA2}

USERENV(16c.300) 12:03:23:747 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {0ACDD40C-75AC-47ab-BAA0-BF6DE7E7FE63}

USERENV(16c.300) 12:03:23:747 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {25537BA6-77A8-11D2-9B6C-0000F8080861}

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {3610eda5-77ef-11d2-8dc5-00c04fa31a66}

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {426031c0-0b47-4852-b0ca-ac3d37bfcb39}

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {42B5FAAE-6536-11d2-AE5A-0000F87571E3}

USERENV(16c.300) 12:03:23:747 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {4CFB60C1-FAA6-47f1-89AA-0B18730C9FD3}

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {827D319E-6EAC-11D2-A4EA-00C04F79F83A}

USERENV(16c.300) 12:03:23:747 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {A2E30F80-D7DE-11d2-BBDE-00C04F86AE3B}

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {B1BE8D72-6EAC-11D2-A4EA-00C04F79F83A}

USERENV(16c.300) 12:03:23:747 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {B587E2B1-4D59-4e7e-AED9-22B9DF11D053}

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {C631DF4C-088F-4156-B058-4375F0853CD8}

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {c6dc5466-785a-11d2-84d0-00c04fb169f7}

USERENV(16c.300) 12:03:23:747 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:23:747 ReadExtStatus: Reading Previous Status for extension {e437bc1c-aa7d-11d2-a382-00c04f991e27}

USERENV(16c.300) 12:03:23:747 ReadStatus: Read Extension's Previous status successfully.

After the Winlogon process reads the previous status of each CSE, it’s time to start evaluating what GPOs exist:

USERENV(16c.300) 12:03:23:747 ProcessGPOs: Calling GetGPOInfo for normal policy mode

USERENV(16c.300) 12:03:23:747 GetGPOInfo: ********************************

USERENV(16c.300) 12:03:23:747 GetGPOInfo: Entering...

USERENV(16c.300) 12:03:23:757 GetGPOInfo: Server connection established.

USERENV(16c.300) 12:03:23:787 GetGPOInfo: Bound successfully.

We search the entire hierarchy to look to see if any Group Policies are linked to any OU in the tree, the domain, or the Active Directory site:

USERENV(16c.300) 12:03:23:787 SearchDSObject: Searching <OU=Laptops,OU=Company Computers,DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:787 SearchDSObject: No GPO(s) for this object.

USERENV(16c.300) 12:03:23:787 SearchDSObject: Searching <OU=Company Computers,DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:787 SearchDSObject: No GPO(s) for this object.

USERENV(16c.300) 12:03:23:787 SearchDSObject: Searching <DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:787 SearchDSObject: Found GPO(s): <[LDAP://cn={AF5C4ACE-C8FD-4574-A9E4-07B77EED376E},cn=policies,cn=system,DC=contoso,DC=com;0][LDAP://CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=contoso,DC=com;0]>

USERENV(16c.300) 12:03:23:787 ProcessGPO: ==============================

USERENV(16c.300) 12:03:23:787 ProcessGPO: Deferring search for <LDAP://cn={AF5C4ACE-C8FD-4574-A9E4-07B77EED376E},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:797 ProcessGPO: ==============================

USERENV(16c.300) 12:03:23:797 ProcessGPO: Deferring search for <LDAP://CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:797 SearchDSObject: Searching <CN=Default-First-Site-Name,CN=Sites,CN=Configuration,DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:797 SearchDSObject: No GPO(s) for this object.

USERENV(16c.300) 12:03:23:797 EvaluateDeferredGPOs: Searching for GPOs in cn=policies,cn=system,DC=contoso,DC=com

After each GPO is located, the a check is performed to determine whether or not the user account (in this case the client) has access to the Group Policy and then performs a WMI filter check against any WMI filters applied to each Group Policy.

USERENV(16c.300) 12:03:23:797 ProcessGPO: ==============================

USERENV(16c.300) 12:03:23:797 ProcessGPO: Searching <cn={AF5C4ACE-C8FD-4574-A9E4-07B77EED376E},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:797 ProcessGPO: Machine has access to this GPO.

USERENV(16c.300) 12:03:23:797 ProcessGPO: GPO passes the filter check.

The next line is where the client looks for the functionality version of the Group Policy. This version will always be 2 because of the version of the GPEdit tool that was used to create the Group Policy.

USERENV(16c.300) 12:03:23:797 ProcessGPO: Found functionality version of: 2

Now it’s time to locate the Group Policy within SYSVOL to determine what settings are configured within registry.pol:

USERENV(16c.300) 12:03:23:797 ProcessGPO: Found file system path of: <\\contoso.com\SysVol\contoso.com\Policies\{AF5C4ACE-C8FD-4574-A9E4-07B77EED376E}>

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found common name of: <{AF5C4ACE-C8FD-4574-A9E4-07B77EED376E}>

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found display name of: <All Domain Systems>

This next line, below, is a check that’s performed to determine what version number exists for the Group Policy Template (GPT) within SYSVOL. The check against the version number inside of GPT.ini within SYSVOL is then compared to the Group Policy Container (GPC) within Active Directory. These should match but there are certain situations in which they wouldn’t match. The GPT is replicated through FRS Replication whereas the GPC is replicated through Active Directory Replication. If one of the two replication mechanisms is behind in replication, this check will not be in sync.

Under this circumstance, in Windows 2000, an error message would be generated that there was a version mismatch and Group Policy processing for that GPO would cease at that point. This was not efficient for a number of reasons. Take, for instance, an environment where Change Notification is enabled on the site link between two Active Directory sites. In this scenario, Active Directory replication between the two sites would act as though they were in the same site and would use Intra-site Replication standards. Change notification across site links only works for AD Replication and not FRS. In this scenario, if a change is made to a Group Policy, Active Directory would replicate the change to another site almost instantaneously whereas FRS would have to wait the normal Site Link Replication schedule before the change was replicated resulting in a version mismatch between GPC and GPT and Group Policy processing of that one GPO would fail. This was changed in Windows XP and Windows Server 2003.

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found machine version of: GPC is 1, GPT is 1

Then a check is performed on the Group Policy to look for any specific flags such as Enforcement (No Override):

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found flags of: 0

The next line in the log is where the Winlogon process determines what Client Side Extensions need to be pulled in order to process the Group Policy.

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{0F6B957D-509E-11D1-A7CC-0000F87571E3}]

USERENV(16c.300) 12:03:23:807 ProcessGPO: ==============================

USERENV(16c.300) 12:03:23:807 ProcessGPO: ==============================

Same thing happens for the other Group Policies:

USERENV(16c.300) 12:03:23:807 ProcessGPO: Searching <CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=contoso,DC=com>

USERENV(16c.300) 12:03:23:807 ProcessGPO: Machine has access to this GPO.

USERENV(16c.300) 12:03:23:807 ProcessGPO: GPO passes the filter check.

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found functionality version of: 2

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found file system path of: <\\contoso.com\sysvol\contoso.com\Policies\{31B2F340-016D-11D2-945F-00C04FB984F9}>

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found common name of: <{31B2F340-016D-11D2-945F-00C04FB984F9}>

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found display name of: <Default Domain Policy>

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found machine version of: GPC is 3, GPT is 3

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found flags of: 0

USERENV(16c.300) 12:03:23:807 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{53D6AB1B-2488-11D1-A28C-00C04FB94F17}][{827D319E-6EAC-11D2-A4EA-00C04F79F83A}{803E14A0-B4FB-11D0-A0D0-00A0C90F574B}][{B1BE8D72-6EAC-11D2-A4EA-00C04F79F83A}{53D6AB1B-2488-11D1-A28C-00C04FB94F17}]

USERENV(16c.300) 12:03:23:807 ProcessGPO: ==============================

After all Group Policies are identified and all checks are complete, the client then looks for any local GPO defined within a local gpt.ini. Generally this is not defined and, therefore, the following message is displayed:

USERENV(16c.300) 12:03:23:807 GetGPOInfo: Local GPO's gpt.ini is not accessible, assuming default state.

USERENV(16c.300) 12:03:23:807 GetGPOInfo: Leaving with 1

USERENV(16c.300) 12:03:23:807 GetGPOInfo: ********************************

USERENV(16c.300) 12:03:23:817 ProcessGPOs: Logging Data for Target <XPCLIENT2>.

USERENV(16c.300) 12:03:23:817 GetWbemServices: CoCreateInstance succeeded

USERENV(16c.300) 12:03:23:867 ConnectToNameSpace: ConnectServer returned 0x0

USERENV(16c.300) 12:03:23:867 CSessionLogger::Log: logging new security grps

USERENV(16c.300) 12:03:23:877 ProcessGPOs: Logged Rsop Session successfully.

USERENV(16c.300) 12:03:23:877 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:23:877 ProcessGPOs: Processing extension Registry

USERENV(16c.300) 12:03:23:877 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:23:877 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:23:877 ProcessGPOList: Entering for extension Registry

USERENV(16c.300) 12:03:23:877 MachinePolicyCallback: Setting status UI to Applying Registry policy...

USERENV(16c.300) 12:03:23:877 MachinePolicyCallback: Extension requested status UI when status UI is not available.

USERENV(16c.300) 12:03:23:908 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(16c.300) 12:03:23:908 EnterCriticalPolicySectionEx: Entering with timeout 60000 and flags 0x2

USERENV(16c.300) 12:03:23:908 EnterCriticalPolicySectionEx: Machine critical section has been claimed. Handle = 0x824

USERENV(16c.300) 12:03:23:908 EnterCriticalPolicySectionEx: Leaving successfully.

USERENV(16c.300) 12:03:23:908 ResetPolicies: Entering.

One of the settings configured in my “All Computers” GPO was disabling the Windows Firewall. The next couple of lines who where this settings was configured:

USERENV(16c.300) 12:03:23:908 ParseRegistryFile: Entering with <C:\Documents and Settings\All Users\ntuser.pol>.

USERENV(16c.300) 12:03:23:918 DeleteRegistryValue: Deleted SOFTWARE\Policies\Microsoft\WindowsFirewall\DomainProfile\EnableFirewall

USERENV(16c.300) 12:03:23:938 ParseRegistryFile: Entering with <\\contoso.com\SysVol\contoso.com\Policies\{AF5C4ACE-C8FD-4574-A9E4-07B77EED376E}\Machine\registry.pol>.

USERENV(16c.300) 12:03:23:938 SetRegistryValue: EnableFirewall => 0 [OK]

USERENV(16c.300) 12:03:23:938 ParseRegistryFile: Leaving.

USERENV(16c.300) 12:03:23:948 ParseRegistryFile: Entering with <\\contoso.com\sysvol\contoso.com\Policies\{31B2F340-016D-11D2-945F-00C04FB984F9}\Machine\registry.pol>.

USERENV(16c.300) 12:03:24:008 LogRegistry RsopData: Successfully logged registry Rsop data

USERENV(16c.300) 12:03:24:028 LeaveCriticalPolicySection: Critical section 0x824 has been released.

USERENV(16c.300) 12:03:24:028 ProcessGPOList: Extension Registry was able to log data. RsopStatus = 0x0, dwRet = 0, Clearing the dirty bit

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

When Group Policy processing occurs, it occurs at the Client Side Extension. If one setting changes for, say, Folder Redirection, any Group Policy that leverages the Client Side Extension fdeploy.dll would have to process regardless of whether or not the actual Group Policy changed.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Processing extension Wireless

USERENV(16c.300) 12:03:24:038 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:24:038 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Extension Wireless skipped because both deleted and changed GPO lists are empty.

The above section shows that no changes were made to any Group Policy that leverages the Client Side extension for Wireless and, therefore, there was nothing for it to do.

More CSE processing:

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Processing extension Folder Redirection

USERENV(16c.300) 12:03:24:038 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Extension Folder Redirection skipped with flags 0x1000f.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Processing extension Microsoft Disk Quota

USERENV(16c.300) 12:03:24:038 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Extension Microsoft Disk Quota skipped with flags 0x1000f.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Processing extension QoS Packet Scheduler

USERENV(16c.300) 12:03:24:038 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Extension QoS Packet Scheduler skipped because both deleted and changed GPO lists are empty.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Processing extension Scripts

USERENV(16c.300) 12:03:24:038 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:24:038 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Extension Scripts skipped because both deleted and changed GPO lists are empty.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Processing extension Internet Explorer Zonemapping

USERENV(16c.300) 12:03:24:038 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Extension Internet Explorer Zonemapping skipped because both deleted and changed GPO lists are empty.

USERENV(16c.300) 12:03:24:038 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:24:038 ProcessGPOs: Processing extension Security

USERENV(16c.300) 12:03:24:038 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:24:038 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:24:038 ProcessGPOList: Entering for extension Security

USERENV(16c.300) 12:03:24:038 MachinePolicyCallback: Setting status UI to Applying Security policy...

USERENV(16c.300) 12:03:24:038 MachinePolicyCallback: Extension requested status UI when status UI is not available.

USERENV(16c.300) 12:03:24:038 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(16c.300) 12:03:24:058 MachinePolicyCallback: Setting status UI to Applying security policy...

USERENV(16c.300) 12:03:24:058 MachinePolicyCallback: Extension requested status UI when status UI is not available.

USERENV(16c.300) 12:03:24:058 MachinePolicyCallback: Setting status UI to Default Domain Policy

USERENV(16c.300) 12:03:24:058 MachinePolicyCallback: Extension requested status UI when status UI is not available.

USERENV(16c.300) 12:03:24:158 MachinePolicyCallback: Setting status UI to Configuring security policy to the system.

USERENV(16c.300) 12:03:24:158 MachinePolicyCallback: Extension requested status UI when status UI is not available.

USERENV(16c.300) 12:03:26:712 MachinePolicyCallback: Setting status UI to Applying computer settings...

USERENV(16c.300) 12:03:26:712 MachinePolicyCallback: Extension requested status UI when status UI is not available.

USERENV(16c.300) 12:03:26:712 ProcessGPOList: Extension Security returned 0x0.

USERENV(16c.300) 12:03:26:712 ProcessGPOList: Extension Security was able to log data. RsopStatus = 0x0, dwRet = 0, Clearing the dirty bit

USERENV(16c.300) 12:03:26:722 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:722 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:722 ProcessGPOs: Processing extension Internet Explorer Branding

USERENV(16c.300) 12:03:26:722 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:26:722 ProcessGPOs: Extension Internet Explorer Branding skipped with flags 0x1000f.

USERENV(16c.300) 12:03:26:722 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:722 ProcessGPOs: Processing extension EFS recovery

USERENV(16c.300) 12:03:26:722 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:26:722 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:26:722 ProcessGPOList: Entering for extension EFS recovery

USERENV(16c.300) 12:03:26:722 MachinePolicyCallback: Setting status UI to Applying EFS recovery policy...

USERENV(16c.300) 12:03:26:722 MachinePolicyCallback: Extension requested status UI when status UI is not available.

USERENV(16c.300) 12:03:26:722 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:26:732 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(16c.300) 12:03:26:732 ProcessGPOList: Extension EFS recovery returned 0x0.

USERENV(16c.300) 12:03:26:732 ProcessGPOList: Extension EFS recovery doesn't support rsop logging

USERENV(16c.300) 12:03:26:742 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:742 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Processing extension 802.3 Group Policy

USERENV(16c.300) 12:03:26:742 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Extension 802.3 Group Policy skipped because both deleted and changed GPO lists are empty.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Processing extension Microsoft Offline Files

USERENV(16c.300) 12:03:26:742 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Extension Microsoft Offline Files skipped because both deleted and changed GPO lists are empty.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Processing extension Software Installation

USERENV(16c.300) 12:03:26:742 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:26:742 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Extension Software Installation skipped because both deleted and changed GPO lists are empty.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: -----------------------

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Processing extension IP Security

USERENV(16c.300) 12:03:26:742 ReadStatus: Read Extension's Previous status successfully.

USERENV(16c.300) 12:03:26:742 CompareGPOLists: The lists are the same.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Extension IP Security skipped because both deleted and changed GPO lists are empty.

After all CSEs have processed, and all GPOs have successfully processed, the client then determines whether or not any settings missed due to Asynchronous policy processing versus Synchronous processing. If any policies failed to process because the computer required a Synchronous foreground policy processing a message would display in the next line stating that the next policy processing would be a Synchronous policy process.

USERENV(16c.300) 12:03:26:742 SetFgRefreshInfo: Previous Machine Fg policy Asynchronous, Reason: NoNeedForSync.

USERENV(16c.300) 12:03:26:742 LeaveCriticalPolicySection: Critical section 0x728 has been released.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Computer Group Policy has been applied.

USERENV(16c.300) 12:03:26:742 ProcessGPOs: Leaving with 1.

USERENV(16c.300) 12:03:26:742 ApplyGroupPolicy: Leaving successfully.

USERENV(16c.57c) 12:03:26:752 PolicyChangedThread: Calling UpdateUser with 1.

USERENV(16c.57c) 12:03:26:752 PolicyChangedThread: Broadcast message for 1.

USERENV(16c.57c) 12:03:26:752 PolicyChangedThread: Leaving

Group Policy processing (in this case for the computer account) occurs at system boot and during the background policy refresh which occurs anywhere from 90 - 120 minutes after the last policy processing. This next line shows when the next policy refresh will occur:

USERENV(16c.580) 12:03:26:752 GPOThread: Next refresh will happen in 102 minutes

At this point, the client processing of Group Policy is complete.

Now that we’ve seen a successful boot sequence of a Windows XP, let’s look at a user logon process. There are a lot of similarities between a boot sequence and a user logon process. First thing we see is a check to determine if the system context can impersonate the user account (in this case the user HQUser):

USERENV(160.164) 14:15:18:845 LoadUserProfile: Yes, we can impersonate the user. Running as self

USERENV(160.164) 14:15:18:845 =========================================================

USERENV(160.164) 14:15:18:845 LoadUserProfile: Entering, hToken = <0x844>, lpProfileInfo = 0x6e3e0

USERENV(160.164) 14:15:18:845 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>

USERENV(160.164) 14:15:18:845 LoadUserProfile: lpProfileInfo->lpUserName = <HQUser>

USERENV(160.164) 14:15:18:845 LoadUserProfile: NULL central profile path

USERENV(160.164) 14:15:18:845 LoadUserProfile: lpProfileInfo->lpDefaultPath = <\\ROOTDC\netlogon\Default User>

USERENV(160.164) 14:15:18:845 LoadUserProfile: NULL server name

USERENV(160.164) 14:15:18:845 LoadUserProfile: In console winlogon process

USERENV(160.164) 14:15:18:845 In LoadUserProfileP

USERENV(160.164) 14:15:18:845 =========================================================

----- Snip (A lot of profile loading and expanding of the profile path) -----

Now we start processing Group Policy. The initial check it to determine if we need a Synchronous or Asynchronous processing of Group Policy. This was the first time I logged in as this user and, therefore, Fast Logon Optimization was turned on and a Synchronous refresh of Group Policy was required:

USERENV(160.164) 14:15:21:689 IsSyncForegroundPolicyRefresh: Synchronous, Reason: FirstPolicyRefresh

USERENV(160.7b0) 14:15:21:689 IsSyncForegroundPolicyRefresh: Synchronous, Reason: FirstPolicyRefresh

USERENV(160.7b0) 14:15:21:910 ApplyGroupPolicy: Entering. Flags = 6

USERENV(160.7b0) 14:15:21:910 ProcessGPOs:

USERENV(160.7b0) 14:15:21:910 ProcessGPOs:

USERENV(160.7b0) 14:15:21:910 ProcessGPOs: Starting user Group Policy (Background) processing...

USERENV(160.7b0) 14:15:21:910 ProcessGPOs:

USERENV(160.7b0) 14:15:21:910 ProcessGPOs:

USERENV(160.7b0) 14:15:21:910 EnterCriticalPolicySectionEx: Entering with timeout 600000 and flags 0x0

USERENV(160.7b0) 14:15:21:910 EnterCriticalPolicySectionEx: User critical section has been claimed. Handle = 0x774

USERENV(160.7b0) 14:15:21:910 EnterCriticalPolicySectionEx: Leaving successfully.

Slow Link Detection again and again we determined the connection to be a fast link:

USERENV(160.7b0) 14:15:21:910 PingComputer: PingBufferSize set as 2048

USERENV(160.7b0) 14:15:21:910 PingComputer: Adapter speed 100000000 bps

USERENV(160.7b0) 14:15:21:910 PingComputer: First time: 0

USERENV(160.7b0) 14:15:21:910 PingComputer: Fast link. Exiting.

Enumerating the user account:

USERENV(160.7b0) 14:15:21:910 ProcessGPOs: User name is: CN=HQ User,OU=HQ Users,OU=Company Users,DC=contoso,DC=com, Domain name is: CONTOSO

USERENV(160.7b0) 14:15:21:910 ProcessGPOs: Domain controller is: \\ROOTDC.contoso.com Domain DN is contoso.com

RSOP entry point for client side extensions and reading the previous state of each CSE again:

USERENV(160.7b0) 14:15:21:910 ReadGPExtensions: Rsop entry point not found for gptext.dll.

USERENV(160.7b0) 14:15:21:910 ReadGPExtensions: Rsop entry point not found for dskquota.dll.

USERENV(160.7b0) 14:15:21:910 ReadGPExtensions: Rsop entry point not found for gptext.dll.

USERENV(160.7b0) 14:15:21:910 ReadGPExtensions: Rsop entry point not found for iedkcs32.dll.

USERENV(160.7b0) 14:15:21:910 ReadGPExtensions: Rsop entry point not found for scecli.dll.

USERENV(160.7b0) 14:15:21:910 ReadGPExtensions: Rsop entry point not found for C:\WINDOWS\System32\cscui.dll.

USERENV(160.7b0) 14:15:21:910 ReadGPExtensions: Rsop entry point not found for gptext.dll.

USERENV(160.7b0) 14:15:21:910 ReadExtStatus: Reading Previous Status for extension {35378EAC-683F-11D2-A89A-00C04FBBCFA2}

USERENV(160.7b0) 14:15:21:910 ReadExtStatus: Reading Previous Status for extension {0ACDD40C-75AC-47ab-BAA0-BF6DE7E7FE63}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {25537BA6-77A8-11D2-9B6C-0000F8080861}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {3610eda5-77ef-11d2-8dc5-00c04fa31a66}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {426031c0-0b47-4852-b0ca-ac3d37bfcb39}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {42B5FAAE-6536-11d2-AE5A-0000F87571E3}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {4CFB60C1-FAA6-47f1-89AA-0B18730C9FD3}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {827D319E-6EAC-11D2-A4EA-00C04F79F83A}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {A2E30F80-D7DE-11d2-BBDE-00C04F86AE3B}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {B1BE8D72-6EAC-11D2-A4EA-00C04F79F83A}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {B587E2B1-4D59-4e7e-AED9-22B9DF11D053}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {C631DF4C-088F-4156-B058-4375F0853CD8}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {c6dc5466-785a-11d2-84d0-00c04fb169f7}

USERENV(160.7b0) 14:15:21:920 ReadExtStatus: Reading Previous Status for extension {e437bc1c-aa7d-11d2-a382-00c04f991e27}

Gathering GPOs for processing:

USERENV(160.7b0) 14:15:21:920 ProcessGPOs: Calling GetGPOInfo for normal policy mode

USERENV(160.7b0) 14:15:21:920 GetGPOInfo: ********************************

USERENV(160.7b0) 14:15:21:920 GetGPOInfo: Entering...

USERENV(160.7b0) 14:15:21:920 GetGPOInfo: Server connection established.

USERENV(160.7b0) 14:15:21:920 GetGPOInfo: Bound successfully.

USERENV(160.7b0) 14:15:21:930 SearchDSObject: Searching <OU=HQ Users,OU=Company Users,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 SearchDSObject: No GPO(s) for this object.

USERENV(160.7b0) 14:15:21:930 SearchDSObject: Searching <OU=Company Users,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 SearchDSObject: Found GPO(s): <[LDAP://cn={2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155},cn=policies,cn=system,DC=contoso,DC=com;0]>

USERENV(160.7b0) 14:15:21:930 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:930 ProcessGPO: Deferring search for <LDAP://cn={2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 SearchDSObject: Searching <DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 SearchDSObject: Found GPO(s): <[LDAP://cn={AF5C4ACE-C8FD-4574-A9E4-07B77EED376E},cn=policies,cn=system,DC=contoso,DC=com;0][LDAP://CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=contoso,DC=com;0]>

USERENV(160.7b0) 14:15:21:930 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:930 ProcessGPO: Deferring search for <LDAP://cn={AF5C4ACE-C8FD-4574-A9E4-07B77EED376E},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:930 ProcessGPO: Deferring search for <LDAP://CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 SearchDSObject: Searching <CN=Default-First-Site-Name,CN=Sites,CN=Configuration,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 SearchDSObject: No GPO(s) for this object.

USERENV(160.7b0) 14:15:21:930 EvaluateDeferredGPOs: Searching for GPOs in cn=policies,cn=system,DC=contoso,DC=com

Checking to make sure the user account has access to the GPO and that it passes WMI filtering checks:

USERENV(160.7b0) 14:15:21:930 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:930 ProcessGPO: Searching <cn={AF5C4ACE-C8FD-4574-A9E4-07B77EED376E},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:930 ProcessGPO: User has access to this GPO.

USERENV(160.7b0) 14:15:21:930 ProcessGPO: GPO passes the filter check.

USERENV(160.7b0) 14:15:21:930 ProcessGPO: Found functionality version of: 2

USERENV(160.7b0) 14:15:21:930 ProcessGPO: Found file system path of: <\\contoso.com\SysVol\contoso.com\Policies\{AF5C4ACE-C8FD-4574-A9E4-07B77EED376E}>

USERENV(160.7b0) 14:15:21:970 ProcessGPO: Found common name of: <{AF5C4ACE-C8FD-4574-A9E4-07B77EED376E}>

USERENV(160.7b0) 14:15:21:970 ProcessGPO: Found display name of: <All Domain Systems>

USERENV(160.7b0) 14:15:21:970 ProcessGPO: Found user version of: GPC is 0, GPT is 0

USERENV(160.7b0) 14:15:21:970 ProcessGPO: Found flags of: 0

USERENV(160.7b0) 14:15:21:970 ProcessGPO: No client-side extensions for this object.

USERENV(160.7b0) 14:15:21:970 ProcessGPO: GPO All Domain Systems doesn't contain any data since the version number is 0. It will be skipped.

USERENV(160.7b0) 14:15:21:970 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:970 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:970 ProcessGPO: Searching <CN={31B2F340-016D-11D2-945F-00C04FB984F9},CN=Policies,CN=System,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:970 ProcessGPO: User has access to this GPO.

USERENV(160.7b0) 14:15:21:980 ProcessGPO: GPO passes the filter check.

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found functionality version of: 2

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found file system path of: <\\contoso.com\sysvol\contoso.com\Policies\{31B2F340-016D-11D2-945F-00C04FB984F9}>

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found common name of: <{31B2F340-016D-11D2-945F-00C04FB984F9}>

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found display name of: <Default Domain Policy>

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found user version of: GPC is 1, GPT is 1

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found flags of: 0

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found extensions: [{3060E8D0-7020-11D2-842D-00C04FA372D4}{3060E8CE-7020-11D2-842D-00C04FA372D4}]

USERENV(160.7b0) 14:15:21:980 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:980 ProcessGPO: ==============================

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Searching <cn={2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.7b0) 14:15:21:980 ProcessGPO: User has access to this GPO.

USERENV(160.7b0) 14:15:21:980 ProcessGPO: GPO passes the filter check.

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found functionality version of: 2

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found file system path of: <\\contoso.com\SysVol\contoso.com\Policies\{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found common name of: <{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found display name of: <All Company Users>

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found user version of: GPC is 3, GPT is 3

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found flags of: 0

USERENV(160.7b0) 14:15:21:980 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{0F6B957E-509E-11D1-A7CC-0000F87571E3}]

USERENV(160.7b0) 14:15:21:980 ProcessGPO: ==============================

Checking for any local GPOs at this point:

USERENV(160.7b0) 14:15:21:980 GetGPOInfo: Local GPO's gpt.ini is not accessible, assuming default state.

USERENV(160.7b0) 14:15:21:980 GetGPOInfo: Leaving with 1

USERENV(160.7b0) 14:15:21:980 GetGPOInfo: ********************************

USERENV(160.7b0) 14:15:21:990 ProcessGPOs: Logging Data for Target <HQUser>.

USERENV(160.7b0) 14:15:21:990 GetWbemServices: CoCreateInstance succeeded

USERENV(160.7b0) 14:15:22:020 ConnectToNameSpace: ConnectServer returned 0x8004100e

USERENV(160.7b0) 14:15:22:350 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(160.7b0) 14:15:22:350 CSessionLogger::Log: logging new security grps

USERENV(160.7b0) 14:15:22:370 LogRsopData: Successfully logged Rsop data

USERENV(160.7b0) 14:15:22:370 ProcessGPOs: Logged Rsop Data successfully.

Processing GPO:

USERENV(160.7b0) 14:15:22:390 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:390 ProcessGPOs: Processing extension Registry

USERENV(160.7b0) 14:15:22:390 CompareGPOLists: One list is empty

USERENV(160.7b0) 14:15:22:390 ProcessGPOList: Entering for extension Registry

USERENV(160.7b0) 14:15:22:390 UserPolicyCallback: Setting status UI to Applying Registry policy...

USERENV(160.7b0) 14:15:22:390 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(160.7b0) 14:15:22:390 EnterCriticalPolicySectionEx: Entering with timeout 60000 and flags 0x2

USERENV(160.7b0) 14:15:22:390 EnterCriticalPolicySectionEx: User critical section has been claimed. Handle = 0x894

USERENV(160.7b0) 14:15:22:390 EnterCriticalPolicySectionEx: Leaving successfully.

USERENV(160.7b0) 14:15:22:390 ResetPolicies: Entering.

USERENV(160.7b0) 14:15:22:390 ParseRegistryFile: Entering with <C:\Documents and Settings\HQUser\ntuser.pol>.

USERENV(160.7b0) 14:15:22:390 ParseRegistryFile: Leaving.

USERENV(160.7b0) 14:15:22:390 ResetPolicies: Leaving.

Getting registry.pol for the GPOs:

USERENV(160.7b0) 14:15:22:400 ParseRegistryFile: Entering with <\\contoso.com\SysVol\contoso.com\Policies\{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}\User\registry.pol>.

The settings I configured for this particular GPO was to remove the Welcome Screen, add Logoff to the Start Menu and to disable the automatic update of ADM files during GPO editing. These settings are seen here:

USERENV(160.7b0) 14:15:22:400 SetRegistryValue: NoWelcomeScreen => 1 [OK]

USERENV(160.7b0) 14:15:22:400 SetRegistryValue: ForceStartMenuLogOff => 1 [OK]

USERENV(160.7b0) 14:15:22:400 SetRegistryValue: DisableAutoADMUpdate => 1 [OK]

USERENV(160.7b0) 14:15:22:400 ParseRegistryFile: Leaving.

USERENV(160.7b0) 14:15:22:430 LeaveCriticalPolicySection: Critical section 0x894 has been released.

USERENV(160.7b0) 14:15:22:430 ProcessGPOList: Extension Registry was able to log data. RsopStatus = 0x0, dwRet = 0, Clearing the dirty bit

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

Processing Client Side Extensions:

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension Wireless

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Extension Wireless skipped with flags 0x6.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension Folder Redirection

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Extension Folder Redirection skipped because both deleted and changed GPO lists are empty.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension Microsoft Disk Quota

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Extension Microsoft Disk Quota skipped with flags 0x6.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension QoS Packet Scheduler

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Extension QoS Packet Scheduler skipped with flags 0x6.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension Scripts

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Extension Scripts skipped because both deleted and changed GPO lists are empty.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension Internet Explorer Zonemapping

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Extension Internet Explorer Zonemapping skipped because both deleted and changed GPO lists are empty.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension Security

USERENV(160.7b0) 14:15:22:430 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Extension Security skipped with flags 0x6.

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:430 ProcessGPOs: Processing extension Internet Explorer Branding

USERENV(160.7b0) 14:15:22:440 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Extension Internet Explorer Branding skipped because both deleted and changed GPO lists are empty.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Processing extension EFS recovery

USERENV(160.7b0) 14:15:22:440 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Extension EFS recovery skipped with flags 0x6.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Processing extension 802.3 Group Policy

USERENV(160.7b0) 14:15:22:440 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Extension 802.3 Group Policy skipped with flags 0x6.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Processing extension Microsoft Offline Files

USERENV(160.7b0) 14:15:22:440 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Extension Microsoft Offline Files skipped with flags 0x6.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Processing extension Software Installation

USERENV(160.7b0) 14:15:22:440 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:440 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Extension Software Installation skipped because both deleted and changed GPO lists are empty.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: -----------------------

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Processing extension IP Security

USERENV(160.7b0) 14:15:22:440 CompareGPOLists: The lists are the same.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Extension IP Security skipped with flags 0x6.

Determining if any settings were not able to be applied due to an asynchronous refresh of Group Policy. This was the first login so it was a Synchronous process of Group Policy:

USERENV(160.7b0) 14:15:22:440 SetFgRefreshInfo: Previous User Fg policy Synchronous, Reason: FirstPolicyRefresh.

USERENV(160.7b0) 14:15:22:440 SetFgRefreshInfo: Next User Fg policy Asynchronous, Reason: NoNeedForSync.

USERENV(160.7b0) 14:15:22:440 LeaveCriticalPolicySection: Critical section 0x774 has been released.

Group Policy is reporting as being applied:

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: User Group Policy has been applied.

USERENV(160.7b0) 14:15:22:440 ProcessGPOs: Leaving with 1.

USERENV(160.7b0) 14:15:22:440 ApplyGroupPolicy: Leaving successfully.

USERENV(160.164) 14:15:22:731 IsSyncForegroundPolicyRefresh: Asynchronous, Reason: NoNeedForSync

USERENV(70.bc) 14:15:22:801 LibMain: Process Name: C:\WINDOWS\system32\userinit.exe

USERENV(8c.94) 14:15:22:861 LibMain: Process Name: C:\WINDOWS\system32\userinit.exe

The next couple of lines are common in UserEnv logs. The “Failed to impersonate user with 5” error is common and does not necessarily represent an error with Group Policy processing. Remember that the process being logged is reported in HEX. If you look at the next couple of lines, you’ll see that the process changes from HEX 160 to HEX 198. Another process attempted to impersonate the user and failed. In this case, it had nothing to do with Group Policy processing:

USERENV(198.1b0) 14:15:22:961 ImpersonateUser: Failed to impersonate user with 5.

USERENV(198.1b0) 14:15:22:961 GetUserNameAndDomain Failed to impersonate user

USERENV(198.1b0) 14:15:22:961 ImpersonateUser: Failed to impersonate user with 5.

USERENV(198.1b0) 14:15:22:961 GetUserDNSDomainName: Failed to impersonate user

Group Policy processing is complete at this point and the random background refresh is displayed here:

USERENV(160.7cc) 14:15:22:971 GPOThread: Next refresh will happen in 90 minutes

So now we’ve covered both the client boot process and the user logon process. Now let’s look at our first error. This first snippet is a time synchronization error which resulted in an initial pass of Group Policy processing failing during a client boot process:

USERENV(160.2c8) 14:02:42:867 ProcessGPOs: Calling GetGPOInfo for normal policy mode

USERENV(160.2c8) 14:02:42:867 GetGPOInfo: ********************************

USERENV(160.2c8) 14:02:42:867 GetGPOInfo: Entering...

USERENV(160.2c8) 14:02:42:877 GetMachineToken: AcceptSecurityContext failed with 0x80090324

USERENV(160.2c8) 14:02:42:877 GetGPOInfo: Failed to get the machine token with -2146893020

USERENV(160.2c8) 14:02:42:877 GetGPOInfo: Leaving with 0

USERENV(160.2c8) 14:02:42:877 GetGPOInfo: ********************************

USERENV(160.2c8) 14:02:42:877 ProcessGPOs: GetGPOInfo failed.

USERENV(160.2c8) 14:02:42:877 ProcessGPOs: No WMI logging done in this policy cycle.

USERENV(160.2c8) 14:02:42:877 ProcessGPOs: Processing failed with error -2146893020.

USERENV(160.2c8) 14:02:42:877 LeaveCriticalPolicySection: Critical section 0x738 has been released.

After I reconfigured the time Group Policy successfully applied.

Let’s look at a Folder Redirection problem now. I logged in as RemoteUser who has Folder Redirection configured for the desktop and My Documents folders. Folder Redirection failed though:

USERENV(16c.744) 13:36:42:388 ProcessGPOs: -----------------------

USERENV(16c.744) 13:36:42:388 ProcessGPOs: -----------------------

USERENV(16c.744) 13:36:42:388 ProcessGPOs: Processing extension Wireless

USERENV(16c.744) 13:36:42:388 CompareGPOLists: The lists are the same.

USERENV(16c.744) 13:36:42:388 ProcessGPOs: Extension Wireless skipped with flags 0x6.

USERENV(16c.744) 13:36:42:388 ProcessGPOs: -----------------------

USERENV(16c.744) 13:36:42:388 ProcessGPOs: Processing extension Folder Redirection

USERENV(16c.744) 13:36:42:388 CompareGPOLists: One list is empty

USERENV(16c.744) 13:36:42:388 CompareGPOLists: One list is empty

USERENV(16c.744) 13:36:42:388 ProcessGPOList: Entering for extension Folder Redirection

USERENV(16c.744) 13:36:42:388 UserPolicyCallback: Setting status UI to Applying Folder Redirection policy...

USERENV(16c.744) 13:36:42:388 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(16c.744) 13:36:42:528 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(16c.744) 13:36:42:588 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(16c.744) 13:36:42:628 UserPolicyCallback: Setting status UI to Applying your personal settings...

USERENV(16c.744) 13:36:42:628 ProcessGPOList: Extension Folder Redirection returned 0x5.

USERENV(16c.744) 13:36:42:628 ProcessGPOList: Extension Folder Redirection was able to log data. RsopStatus = 0x0, dwRet = 5, Clearing the dirty bit

USERENV(16c.744) 13:36:42:628 ProcessGPOs: Extension Folder Redirection ProcessGroupPolicy failed, status 0x5.

USERENV(16c.744) 13:36:42:628 ProcessGPOs: -----------------------

USERENV(16c.744) 13:36:42:628 ProcessGPOs: -----------------------

I then enabled FDeploy Client Side Extension logging https://technet.microsoft.com/en-us/library/cc727967(WS.10).aspx

The fdeploy.log file displayed the following information:

13:47:17:356 Entering folder redirection extension

13:47:17:356 Flags = 0x0

13:47:17:396 Group Policy Object name = {FCFEAACD-739E-4516-BE4D-520417A159BE}

13:47:17:396 File system path = \\contoso.com\SysVol\contoso.com\Policies\{FCFEAACD-739E-4516-BE4D-520417A159BE}\User

13:47:17:396 Directory path = LDAP://CN=User,cn={FCFEAACD-739E-4516-BE4D-520417A159BE},cn=policies,cn=system,DC=contoso,DC=com

13:47:17:396 Display name = Remote Users

13:47:17:396 Found folder redirection settings for policy Remote Users.

13:47:17:416 The user was found to be a member of the group s-1-1-0. The corresponding path was \\RootDC\Share\%USERNAME%\Desktop.

13:47:17:416 Successfully obtained redirection data for Desktop, (Flags: 0x31).

13:47:17:416 The user was found to be a member of the group s-1-1-0. The corresponding path was \\RootDC\Share\%USERNAME%\My Documents.

13:47:17:416 Successfully obtained redirection data for My Documents, (Flags: 0x31).

13:47:17:416 Successfully obtained redirection data for My Pictures, (Flags: 0x2).

13:47:17:416 Successfully gathered folder redirection settings for policy Remote Users.

13:47:17:416 Redirecting folder Desktop to \\RootDC\Share\%USERNAME%\Desktop.

13:47:17:456 Previous folder path C:\Documents and Settings\remoteuser\Desktop expanded to C:\Documents and Settings\remoteuser\Desktop.

13:47:17:456 New folder path \\RootDC\Share\%USERNAME%\Desktop expanded to \\RootDC\Share\remoteuser\Desktop.

13:47:17:456 Failed to perform redirection of folder Desktop.

The new directories for the redirected folder could not be created.

The folder is configured to be redirected to <\\RootDC\Share\%USERNAME%\Desktop>, the final expanded path was <\\RootDC\Share\remoteuser\Desktop>.

The following error occurred:

%%5

 

13:47:17:456 Redirecting folder My Documents to \\RootDC\Share\%USERNAME%\My Documents.

13:47:17:476 Previous folder path C:\Documents and Settings\remoteuser\My Documents expanded to C:\Documents and Settings\remoteuser\My Documents.

13:47:17:476 New folder path \\RootDC\Share\%USERNAME%\My Documents expanded to \\RootDC\Share\remoteuser\My Documents.

13:47:17:476 Failed to perform redirection of folder My Documents.

The new directories for the redirected folder could not be created.

The folder is configured to be redirected to <\\RootDC\Share\%USERNAME%\My Documents>, the final expanded path was <\\RootDC\Share\remoteuser\My Documents>.

The following error occurred:

%%5

This issue was related to an Access Denied error in which the system (and user) didn’t have access to create the redirected folder in the shared space. I corrected that and we then saw the following UserEnv.log and Fdeploy.log:

USERENV(168.4f0) 15:16:30:041 ProcessGPOs: -----------------------

USERENV(168.4f0) 15:16:30:041 ProcessGPOs: Processing extension Folder Redirection

USERENV(168.4f0) 15:16:30:041 ReadStatus: Read Extension's Previous status successfully.

USERENV(168.4f0) 15:16:30:041 CompareGPOLists: One list is empty

USERENV(168.4f0) 15:16:30:041 CompareGPOLists: The lists are the same.

USERENV(168.4f0) 15:16:30:041 ProcessGPOList: Entering for extension Folder Redirection

USERENV(168.4f0) 15:16:30:041 UserPolicyCallback: Setting status UI to Applying Folder Redirection policy...

USERENV(168.4f0) 15:16:30:041 GetWbemServices: CoCreateInstance succeeded

USERENV(168.4f0) 15:16:30:061 ConnectToNameSpace: ConnectServer returned 0x0

USERENV(168.4f0) 15:16:30:071 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(168.4f0) 15:16:30:121 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(168.4f0) 15:16:30:221 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(168.4f0) 15:16:30:471 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(168.4f0) 15:16:30:632 UserPolicyCallback: Setting status UI to Applying your personal settings...

USERENV(168.4f0) 15:16:30:632 ProcessGPOList: Extension Folder Redirection returned 0x0.

USERENV(168.4f0) 15:16:30:632 ProcessGPOList: Extension Folder Redirection was able to log data. RsopStatus = 0x0, dwRet = 0, Clearing the dirty bit

USERENV(168.4f0) 15:16:30:642 ProcessGPOs: -----------------------

USERENV(168.4f0) 15:16:30:642 ProcessGPOs: -----------------------

Fdeploy.log:

15:08:22:617 Entering folder redirection extension

15:08:22:617 Flags = 0x0

15:08:22:657 Group Policy Object name = {FCFEAACD-739E-4516-BE4D-520417A159BE}

15:08:22:657 File system path = \\contoso.com\SysVol\contoso.com\Policies\{FCFEAACD-739E-4516-BE4D-520417A159BE}\User

15:08:22:657 Directory path = LDAP://CN=User,cn={FCFEAACD-739E-4516-BE4D-520417A159BE},cn=policies,cn=system,DC=contoso,DC=com

15:08:22:657 Display name = Remote Users

15:08:22:657 Found folder redirection settings for policy Remote Users.

15:08:22:667 The user was found to be a member of the group s-1-1-0. The corresponding path was \\RootDC\Share\%USERNAME%\Desktop.

15:08:22:667 Successfully obtained redirection data for Desktop, (Flags: 0x31).

15:08:22:667 The user was found to be a member of the group s-1-1-0. The corresponding path was \\RootDC\Share\%USERNAME%\My Documents.

15:08:22:667 Successfully obtained redirection data for My Documents, (Flags: 0x31).

15:08:22:667 Successfully obtained redirection data for My Pictures, (Flags: 0x2).

15:08:22:667 Successfully gathered folder redirection settings for policy Remote Users.

15:08:22:667 Redirecting folder Desktop to \\RootDC\Share\%USERNAME%\Desktop.

15:08:22:667 Folder Desktop already redirected to \\RootDC\Share\remoteuser\Desktop.

15:08:22:687 Redirecting folder My Documents to \\RootDC\Share\%USERNAME%\My Documents.

15:08:22:697 Previous folder path C:\Documents and Settings\remoteuser\My Documents expanded to C:\Documents and Settings\remoteuser\My Documents.

15:08:22:697 New folder path \\RootDC\Share\%USERNAME%\My Documents expanded to \\RootDC\Share\remoteuser\My Documents.

15:08:22:757 Contents of redirected folder My Documents will be copied to the new location.

15:08:22:947 Redirecting folder My Pictures to \\RootDC\Share\%USERNAME%\My Documents\My Pictures.

15:08:22:967 Previous folder path C:\Documents and Settings\remoteuser\My Documents\My Pictures expanded to C:\Documents and Settings\remoteuser\My Documents\My Pictures.

15:08:22:967 New folder path \\RootDC\Share\%USERNAME%\My Documents\My Pictures expanded to \\RootDC\Share\remoteuser\My Documents\My Pictures.

15:08:22:977 Contents of redirected folder My Pictures will be copied to the new location.

15:08:23:047 Previous contents of folder My Pictures at C:\Documents and Settings\remoteuser\My Documents\My Pictures will be deleted.

15:08:23:057 Querying the DS for user remoteuser's home directory.

15:08:23:077 Obtained home directory : .

15:08:23:087 Successfully redirected folder My Pictures.

The folder was redirected from <C:\Documents and Settings\remoteuser\My Documents\My Pictures> to <\\RootDC\Share\remoteuser\My Documents\My Pictures>.

15:08:23:087 Previous contents of folder My Documents at C:\Documents and Settings\remoteuser\My Documents will be deleted.

15:08:23:137 Successfully redirected folder My Documents.

The folder was redirected from <C:\Documents and Settings\remoteuser\My Documents> to <\\RootDC\Share\remoteuser\My Documents>.

15:08:23:137 Disabling permission for user redirection of My Documents.

15:08:23:167 Successfully updated the shortcut to My Pictures in <\\RootDC\Share\remoteuser\My Documents>.

This next snippet is an issue with locating gpt.ini which could be a result of gpt.ini simply not existing or an issue with ACLs set on the policy within SYSVOL:

USERENV(160.c0) 14:26:31:248 ProcessGPO: ==============================

USERENV(160.c0) 14:26:31:248 ProcessGPO: ==============================

USERENV(160.c0) 14:26:31:248 ProcessGPO: Searching <cn={2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.c0) 14:26:31:248 ProcessGPO: User has access to this GPO.

USERENV(160.c0) 14:26:31:248 ProcessGPO: GPO passes the filter check.

USERENV(160.c0) 14:26:31:248 ProcessGPO: Found functionality version of: 2

USERENV(160.c0) 14:26:31:248 ProcessGPO: Found file system path of: <\\contoso.com\SysVol\contoso.com\Policies\{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.c0) 14:26:31:248 ProcessGPO: Couldn't find the group policy template file <\\contoso.com\SysVol\contoso.com\Policies\{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}\gpt.ini>, error = 0x2.

USERENV(160.c0) 14:26:31:248 ProcessGPO: ==============================

USERENV(160.c0) 14:26:31:248 EvalList: ProcessGPO failed

USERENV(160.c0) 14:26:31:248 GetGPOInfo: EvaluateDeferredGPOs failed. Exiting

USERENV(160.c0) 14:26:31:258 GetGPOInfo: Leaving with 0

USERENV(160.c0) 14:26:31:258 GetGPOInfo: ********************************

The issue in this case was because I specifically denied access to my user account and they were not able to read the file gpt.ini for the {2C1B…} GPO. Granting access to that GPT resulted in correcting the issue.

The next error was a result of a version number missing from GPT.ini. Remember that the Winlogon process compares the version of GPT with the version of GPC. It does this by checking the version number in the file GPT.ini and comparing with the version of the same GPO within Active Directory. Here is the snippet:

USERENV(160.254) 14:19:35:340 ProcessGPO: Searching <cn={2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.254) 14:19:35:340 ProcessGPO: User has access to this GPO.

USERENV(160.254) 14:19:35:340 ProcessGPO: GPO passes the filter check.

USERENV(160.254) 14:19:35:340 ProcessGPO: Found functionality version of: 2

USERENV(160.254) 14:19:35:340 ProcessGPO: Found file system path of: <\\contoso.com\SysVol\contoso.com\Policies\{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(1cc.3fc) 14:19:35:350 GetProfileType: Profile already loaded.

USERENV(1cc.3fc) 14:19:35:350 GetProfileType: ProfileFlags is 0

USERENV(160.254) 14:19:35:360 ProcessGPO: Found common name of: <{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.254) 14:19:35:360 ProcessGPO: Found display name of: <All Company Users>

USERENV(160.254) 14:19:35:360 ProcessGPO: Found user version of: GPC is 3, GPT is 0

USERENV(160.254) 14:19:35:360 ProcessGPO: Found flags of: 0

USERENV(160.254) 14:19:35:360 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{0F6B957E-509E-11D1-A7CC-0000F87571E3}]

USERENV(160.254) 14:19:35:360 ProcessGPO: ==============================

Here is a version mismatch:

USERENV(160.48c) 14:18:04:189 ProcessGPO: Searching <cn={2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.48c) 14:18:04:189 ProcessGPO: User has access to this GPO.

USERENV(160.48c) 14:18:04:189 ProcessGPO: GPO passes the filter check.

USERENV(160.48c) 14:18:04:189 ProcessGPO: Found functionality version of: 2

USERENV(160.48c) 14:18:04:189 ProcessGPO: Found file system path of: <\\contoso.com\SysVol\contoso.com\Policies\{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.48c) 14:18:04:209 ProcessGPO: Found common name of: <{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.48c) 14:18:04:209 ProcessGPO: Found display name of: <All Company Users>

USERENV(160.48c) 14:18:04:209 ProcessGPO: Found user version of: GPC is 3, GPT is 3000

USERENV(160.48c) 14:18:04:209 ProcessGPO: Found flags of: 0

USERENV(160.48c) 14:18:04:209 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{0F6B957E-509E-11D1-A7CC-0000F87571E3}]

USERENV(160.48c) 14:18:04:209 ProcessGPO: ==============================

Here is an issue in which the user does not have the ability to apply Group Policy:

USERENV(160.d8) 14:24:06:200 ProcessGPO: ==============================

USERENV(160.d8) 14:24:06:200 ProcessGPO: ==============================

USERENV(160.d8) 14:24:06:200 ProcessGPO: Searching <cn={2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155},cn=policies,cn=system,DC=contoso,DC=com>

USERENV(160.d8) 14:24:06:200 ProcessGPO: User does not have access to the GPO and so will not be applied.

USERENV(160.d8) 14:24:06:200 ProcessGPO: Found functionality version of: 2

USERENV(160.d8) 14:24:06:200 ProcessGPO: Found file system path of: <\\contoso.com\SysVol\contoso.com\Policies\{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.d8) 14:24:06:200 ProcessGPO: Sysvol access skipped because GPO is not getting applied.

USERENV(160.d8) 14:24:06:200 ProcessGPO: Found common name of: <{2C1B39B1-02EC-41B9-B6BA-BD0E7FCC7155}>

USERENV(160.d8) 14:24:06:200 ProcessGPO: Found display name of: <All Company Users>

USERENV(160.d8) 14:24:06:200 ProcessGPO: Found user version of: GPC is 3, GPT is 65535

USERENV(160.d8) 14:24:06:200 ProcessGPO: Found flags of: 0

USERENV(160.d8) 14:24:06:200 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{0F6B957E-509E-11D1-A7CC-0000F87571E3}]

USERENV(160.d8) 14:24:06:200 ProcessGPO: ==============================

So now that we’ve discussed how GPO processing is supposed to occur and some of the issue that we see in UserEnv, let’s look at how a UserEnv log looks when a user falls out of scope of applying the GPO:

First pass of GPO:

USERENV(168.9c) 15:19:36:783 ProcessGPOs: Processing extension Folder Redirection

USERENV(168.9c) 15:19:36:783 ReadStatus: Read Extension's Previous status successfully.

USERENV(168.9c) 15:19:36:783 CheckForGPOsToRemove: GPO <Remote Users> needs to be removed

USERENV(168.9c) 15:19:36:783 CheckForGPOsToRemove: GPO <Remote Users> needs to be removed

We know we need to remove the Folder Redirection at this point……

USERENV(168.9c) 15:19:36:783 GetDeletedGPOList: Finished.

USERENV(168.9c) 15:19:36:783 GetDeletedGPOList: Finished.

USERENV(168.9c) 15:19:36:783 ProcessGPOList: Entering for extension Folder Redirection

USERENV(168.9c) 15:19:36:783 UserPolicyCallback: Setting status UI to Applying Folder Redirection policy...

USERENV(168.9c) 15:19:36:783 UserPolicyCallback: Extension requested status UI when status UI is not available.

USERENV(168.9c) 15:19:36:793 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(168.9c) 15:19:36:843 UserPolicyCallback: Setting status UI to Applying your personal settings...

USERENV(168.9c) 15:19:36:843 UserPolicyCallback: Extension requested status UI when status UI is not available.

USERENV(168.9c) 15:19:36:843 ProcessGPOList: Extension Folder Redirection returned 0x4fa.

USERENV(168.9c) 15:19:36:843 ProcessGPOList: Extension Folder Redirection was able to log data. RsopStatus = 0x0, dwRet = 1274, Clearing the dirty bit

Can’t redirect the Folder Redirection back to the original location when we’re already logged in and, therefore, we see this:

USERENV(168.9c) 15:19:36:843 ProcessGPOs: Extension Folder Redirection ProcessGroupPolicy returned sync_foreground.

USERENV(168.9c) 15:19:36:843 ProcessGPOs: -----------------------

USERENV(168.9c) 15:19:36:843 ProcessGPOs: -----------------------

Second Pass of GPO run in Synchronous mode:

USERENV(168.3a4) 15:21:59:772 ProcessGPOs: Processing extension Folder Redirection

USERENV(168.3a4) 15:21:59:772 ReadStatus: Read Extension's Previous status successfully.

USERENV(168.3a4) 15:21:59:772 CheckForGPOsToRemove: GPO <Remote Users> needs to be removed

USERENV(168.3a4) 15:21:59:772 CheckForGPOsToRemove: GPO <Remote Users> needs to be removed

USERENV(168.3a4) 15:21:59:772 GetDeletedGPOList: Finished.

USERENV(168.3a4) 15:21:59:772 GetDeletedGPOList: Finished.

USERENV(168.3a4) 15:21:59:772 ProcessGPOList: Entering for extension Folder Redirection

USERENV(168.3a4) 15:21:59:772 UserPolicyCallback: Setting status UI to Applying Folder Redirection policy...

USERENV(168.3a4) 15:21:59:782 LogExtSessionStatus: Successfully logged Extension Session data

USERENV(168.3a4) 15:21:59:852 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(168.3a4) 15:22:10:907 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(168.3a4) 15:22:11:017 UserPolicyCallback: Setting status UI to Applying personal document settings...

USERENV(168.3a4) 15:22:22:161 UserPolicyCallback: Setting status UI to Applying your personal settings...

USERENV(168.3a4) 15:22:22:161 ProcessGPOList: Extension Folder Redirection returned 0x0.

USERENV(168.3a4) 15:22:22:161 ProcessGPOList: Extension Folder Redirection was able to log data. RsopStatus = 0x0, dwRet = 0, Clearing the dirty bit

USERENV(168.3a4) 15:22:22:171 ProcessGPOs: -----------------------

Hoping this helps with interpreting UserEnv debug logs and with GPO troubleshooting! Here is a support article that also discusses how to interpret UserEnv logs:

Interpreting Userenv log files
https://technet.microsoft.com/en-us/library/cc786775(WS.10).aspx

 

Updated: After posting this blog and then looking for the support article from Technet about how to interpret UserEnv log files, I found two other Blogs about interpreting UserEnv. These are very good blogs.

Understanding How to Read a Userenv Log – Part 1
https://blogs.technet.com/askds/archive/2008/11/11/understanding-how-to-read-a-userenv-log-part-1.aspx

Understanding How to Read a Userenv Log – Part 2
https://blogs.technet.com/askds/archive/2008/11/11/understanding-how-to-read-a-userenv-log-part-2.aspx