Tracking User Environment Creation

[Alex Simons (AZURE)]

First published on CloudBlogs on Aug, 20 2007

In my soliloquy of AD logon you heard some broad generalities intended to give a general understanding of the intended design and how it all fits together.  In this post I hope to give you a more detailed idea of how it works.

How to enable user environment debug logging in retail builds of Windows

http://support.microsoft.com/kb/221833

For years we at Microsoft have told people how to enable USERENV logging and information, sometimes detailed information, on what you’ll see.  I’m going to give you my highlights on what I do when I review a USERENV debug log, and some of the more frequently relevant things to look at.

First of all, USERENV is a contraction of “user environment”, the creation of which is what this logging monitors.  This does not mean that there is a service or process on your computer as you logon named “userenv” however.    USERENV debug entries originate in the Winlogon.exe process instance that is instantiated when a user logs onto the computer.    This may raise a question in your mind of “what if more than one user is logged onto the computer, like on a terminal server?”  The answer is that each user will have their own instance of Winlogon.exe.  All instances of Winlogon.exe, however, will spew their debug logging to one "universal" USERENV log on that computer.

So, all of the various users logon details in the above terminal server scenario will dump to the same USERENV debug log file (as described in the KB article on how to enable the logging, link above).

Let's assume you’ve enabled the debug logging on a supported system and you want to review your log to see what it says about you.    Don’t get ahead of yourselves folks, it won’t tell your horoscope, just what happened during the user logon.

When I open the log I usually have the intention of looking for what happened to a specific user.  It helps as a starting point to open the file in Notepad and choose EditàFind then search for that username.  This should take you to a section that looks like below, essentially.    Note that you could just as easily search for LoadUserProfile and to find your starting point, but you could end up looking at the wrong user’s logon section if you do that.

=========================================================

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: Entering, hToken = <0x73c>, lpProfileInfo = 0x6e3e0

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: lpProfileInfo->lpUserName = <sombrerobob>

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: NULL central profile path

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: lpProfileInfo->lpDefaultPath = <\hatsrusnetlogonDefault User>

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: NULL server name

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: In console winlogon process

USERENV(1f4.1f8) 15:19:56:468 In LoadUserProfileP

USERENV(1f4.1f8) 15:19:56:468 =========================================================

So now we have a time reference for when the user logon began ( 15:19:56:468) for user SombreroBob (the man who makes his own shade).  This is good for the reason of having a starting point in reviewing the log, but it’s also useful for tracking slow user logon issues that take place after your user provides their credentials and presses enter, in addition to answering questions like “what policy processing is taking place?” in detail.

The next entries give us excellent information regarding locating a user profile for the user to logon with.  Keep in mind that whether a user has a roaming user profile or not, and where it is located, is mandated by the user account properties in AD.  Nice little tie-in from the Soliloquy, right?

The entries a few paragraphs above show SombreroBob logging on where he does not have a roaming profile specified so the logon will look for a prior local one or create a new profile for this iser from defaults located either in the netlogon share of the domain or on the computer being logged into.  I’ve made the difference boldface text below.

USERENV(1f4.1f8) 15:19:56:468 =========================================================

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: Entering, hToken = <0x73c>, lpProfileInfo = 0x6e3e0

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: lpProfileInfo->dwFlags = <0x0>

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: lpProfileInfo->lpUserName = <sombrerobob>

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: lpProfileInfo->lpProfilePath = <\ha trackprofilessombrerobob>

USERENV(1f4.1f8) 15:19:56:468 LoadUserProfile: lpProfileInfo->lpDefaultPath = <\hatsrus-dc1netlogonDefault User>

For instances of a user logon where a profile is already existing locally on the computer then the remote copy and the must be compared for the latest versions of the users profile files.  For the remote profile case this will incur a good amount of SMB traffic on the wire as files are compared.  The reason for this is quite good: consider that you have a terminal server farm and the user may never (or at least infrequently) logon to the same terminal server twice.  Since by default there will be a local copy of that profile we can save some time, local computer resources and network usage by comparing that up-to-date roaming profile with the files that were left behind when the user logged off that terminal server last and then only copying over those files which need to be copied.  In other words, the deltas or changes between what the user had at last logoff from that server and what has since changed.

The USERENV log gives a lot of entries from these comparison routines and you can quickly move to the appropriate section of the log if your needs mandate that by searching for ReconcileFile.

Another interesting technique that people use at times is to compare the directory path of the profile being loaded with the SID (security identifier) of the user.  This can be interesting if you need to look in detail at what profile is being loaded versus what you have in the local computers registry regarding profile paths at HKLMSoftwareMicrosoftWindows NTCurrentVersionProfileListSID.

Group policy processing at user logon (as well as at computer startup and GPO refresh intervals-unless you have Vista or 2008 which have an event log for that) will appear in this log as well.  The basic rundown is that the list of the GPOs which are linked to the OU where the user’s object resides in AD is examined and assessed to see if the user has permissions to them.  This will appear in the USERENV log similar to below and generates LDAP traffic on the wire from client computer the user is logging onto to the domain controller.

USERENV(1f4.1f8) 15:20:11:234  ProcessGPOs: Calling GetGPOInfo for normal policy mode

USERENV(1f4.1f8) 15:20:11:234  GetGPOInfo:  ********************************

USERENV(1f4.1f8) 15:20:11:234  GetGPOInfo:  Entering...

USERENV(1f4.1f8) 15:20:11:234   GetGPOInfo:  Server connection established.

USERENV(1f4.1f8) 15:20:11:234   GetGPOInfo:  Bound successfully.

USERENV(1f4.1f8) 15:20:11:234  SearchDSObject:  Searching <OU=PremiumHatWearers,OU=Sales,OU=Users,DC=hatsrus,DC=com>

USERENV(1f4.1f8) 15:20:12:010  SearchDSObject:  Found GPO(s):  <[LDAP://cn={23F09E20-DFAB-441C-B656-6CB543A029CF},cn=policies,cn=system,DC=hatsrus,DC=com;0][LDAP://cn={2CBDE770-B492-424A-8AB0-60DF2CF25B7B},cn=policies,cn=system, DC=hatsrus,DC=com;0][LDAP://cn={E6A34850-7F6E-445G-97E2-95D0A44B86F9},cn=policies,cn=system,DC=hatsrus,DC=com;0][LDAP://cn={978EBEEF-EADE-4AF0-953D-CAFEC4B72B3B},cn=policies,cn=system,DC=hatsrus,DC=com;0][LDAP://CN={F0DF6A59-2D70-76YF-BDF9-F34D766FFA27},CN=Policies,CN=System,DC=hatsrus,DC=com;0][LDAP://cn={E6D33304-X49H-4285-B6F0-AAA7434D461E},cn=policies,cn=system,DC=hatsrus,DC=com;0][LDAP://cn={C109DD8D-8F46-4647-E335-935FB6A534E1},cn=policies,cn=system,DC=hatsrus,DC=com;0]>

USERENV(1f4.1f8) 15:20:12:010  ProcessGPO:  ==============================

So now we have a list of GPOs which are linked to the OU where the user account resides in AD.   Next we should see some entries which determine whether user has access to the GPO enough that he or she should be able to process and apply it, indicated by the “GPO passes the filter check” entry.

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  ==============================

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Searching <CN ={23F09E20-DFAB-441C-B656-6CB543A029CF},cn=policies,cn=system,DC=hatsrus,DC=com >

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  User has access to this GPO.

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  GPO passes the filter check.

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Found functionality version of:  2

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Found file system path of:  <\hatsrus.comSysVolhatsrus.comPolicies {23F09E20-DFAB-441C-B656-6CB543A029CF} >

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Found common name of:  < {23F09E20-DFAB-441C-B656-6CB543A029CF} >

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Found display name of:  <Non-Propeller Hat Wearers Folder Redirection Policy>

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Found user version of:  GPC is 80, GPT is 80

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Found flags of:  0

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  Found extensions:  [{25537BA6-77A8-11D2-9B6C-0000F8080861}]

USERENV(1f4.1f8) 15:20:12:010 ProcessGPO:  ==============================

So now we have the GPOs which will be processed for this user at logon and queued up (so to speak), ready to process.

From here it’s crucial to understand that GPO processing “where the rubber meets the road” is really all about client side extensions (CSEs).  A CSE is the portion of our code that gets the setting to where it needs to be, and there are CSEs for different types of settings.  For example, registry settings are applied by the Registry CSE.  Scripts are processed by the Scripts CSE.  I think you can all see where this type of thing is going.

In the USERENV there is a list of extensions which represents the types of settings the GPO specifies, listed in the Found Extensions portion above.  Each of these GUIDs represents a CSE.  In the above example, the CSE which this GPO has settings from is Folder Redirection.  You can view a list of the CSEs and the GUIDs which relate to them (usable as a reference when seeing them in a USERENV log) by opening Regedit.exe and viewing the properties of the keys located here, listed by GUID: HKEY_LOCAL_MACHINESOFTWAREMicrosoftWindows NTCurrentVersionWinlogonGPExtensions.

At a certain point in the USERENV log there’s a check done to see if these settings have been applied previously and how the CSE should behave if so.  The general idea is that, for performance reasons, you may not want to apply policy settings at every policy processing if these settings have already been applied successfully.   Don’t expect great detail here in the log, but do expect that the settings are things governed by looking to the registry on the client computer and deciding what to do based on what is there:

USERENV(1f4.1f8) 15:20:13:544 ReadExtStatus: Reading Previous Status for extension {25537BA6-77A8-11D2-9B6C-0000F8080861}

USERENV(1f4.1f8) 15:21:01:028 ReadStatus: Read Extension's Previous status successfully.

<snip>

USERENV(1f4.1f8) 15:21:01:028 ProcessGPOs: -----------------------

USERENV(1f4.1f8) ) 15:21:01:028 ProcessGPOs: Processing extension Folder Redirection

USERENV(1f4.1f8) 15:21:01:143 CompareGPOLists: The lists are the same.

USERENV(1f4.1f8) 15:21:01:143 ProcessGPOList: Entering for extension Folder Redirection

USERENV(1f4.1f8) 15:21:01:143 UserPolicyCallback: Setting status UI to Applying Folder Redirection policy...

USERENV(1f4.1f8) 15:21:01:143 UserPolicyCallback: Setting status UI to Applying your personal settings...

USERENV(1f4.1f8) 15:21:01:143 ProcessGPOList: Extension Folder Redirection returned 0x0

A similar story can be told for each CSE as it processes.  Is the USERENV the best place to look for details on how the CSEs do their job?  Well, no, not really.  Each CSE may have its own debug logging detailing how that CSE works and giving good info on problems if any are found.  But we’re not going there in this post.

In this post we’ve gone over user logon and the user environment creation process, the intention being to provide an understanding of how user logon works.  For Windows 2000, XP and 2003 clients this post can be used as a walkthrough for reviewing a USERENV log you create.  For Vista and Server 2008, since USERENV logging is now a tracing format in those operating systems, you can use this post a reference point.    In either event I hope you’ve gleaned some value in this post.

Finally, here’s a good Technet article we have that has more information:

How Core Group Policy Works

http://technet2.microsoft.com/windowsserver/en/library/eb0042e3-699b-4c49-abcc-e3526dbecc0e1033...