Microsoft's official enterprise support blog for AD DS and more
Hey everyone, this is Mark from the Directory Services team. We get calls all the time where enabling Userenv logging is necessary to see exactly what is happening with group policy and profile loading. If you have ever looked at one it can be confusing to say the least. One thing to remember is that if the logging is not enabled then do not try and interpret the log since very minimal logging is enabled by default! I am going to break this down into 2 parts with one being the Computer side and its processing then the second part of the User side and its processing. So let’s jump in and get our feet wet with some of the basics.
First, what is Userenv logging? This is short for “User Environment.” How do I enable the logging? You can reference the following KB article:
221833 How to enable user environment debug logging in retail builds of Windows http://support.microsoft.com/kb/221833
Note that Userenv logging per this article does not work on any version of Windows Vista or Windows Server 2008. It will work only on Windows 2000, 2003 or XP.
Open Regedit on the problem computer and drill down to:
HKLM\Software\Microsoft\Windows NT\CurrentVersion\Winlogon.
Create a REG_DWORD with the value called UserEnvDebugLevel then set the value to 0x10002 in hexadecimal. The value is not case sensitive.
Logging will start immediately to the Userenv.log file located in the %SystemRoot%\Debug\UserMode folder (no reboot or restart of services is required). If the Userenv.log file is larger than 300 KB, the file is renamed Userenv.bak, and a new Userenv.log file is created. This action occurs when a user logs on locally or by using Terminal Services, and the Winlogon process starts. However, because the size check only occurs when a user logs on, the Userenv.log file may grow beyond the 300 KB limit. If you need to read the log or .bak files then you can simply open them with Notepad. Since you want to see what the computer is doing when it starts, reboot the client computer.
One problem with Userenv logging, especially on a busy terminal server with lots of logon activity, is that the log is overwritten before you get a chance to find the useful information in it. While there is no way to increase the 300 KB limit on the log file, if you make Userenv.bak read-only, Winlogon can’t rename Userenv.log to Userenv.bak, so it just keeps logging to the Userenv.log indefinitely. If you decide to use this method, it is critical that you monitor the size of the Userenv.log to make sure it does not fill up the drive. Then remove the read-only attribute as soon as you are done troubleshooting.
After a reboot and once you are logged onto the client computer, open the Userenv log; you should notice information such as this:
USERENV(78c.790) 22:00:04:218 LoadUserProfile: lpProfileInfo->lpUserName = <NetworkService>
Or
USERENV(78c.790) 22:00:04:546 LoadUserProfile: lpProfileInfo->lpUserName = <LocalService>
This is normal as there are profiles for the Network Service and Local Service. These accounts have to logon just as a normal user account since they are used to start services that are running on the local computer. You may see a line in the log such as this:
USERENV(78c.790) 22:00:04:515 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.
No need to worry if it is associated with one of the services logging on. This is due to if you look at the SID (Security Identifier) for either the Network Service (S-1-5-20) or the Local Service (S-1-5-19) these are what we call Well Known Security Identifiers (SID’s). You can see a list of them in:
243330 Well-known security identifiers in Windows operating systems http://support.microsoft.com/kb/243330
These accounts are not associated to a domain such as a user or computer account would be. So these can be ignored. Once the services have started up or still in the process of starting you will see the following:
USERENV(750.280) 22:00:43:203 ProcessGPOs: Starting computer Group Policy (Background) processing...
This signifies that the group policy for the computer is about to start processing. First we ping the server to determine if we are on a fast link or not. We do this to determine if we are on a slow link where processing group policies could be done in a different fashion. So if ICMP is not allowed through any routers and in order to ping a DC, if we go through a router, then do not expect policies to get applied.
USERENV(750.280) 22:00:43:203 PingComputer: PingBufferSize set as 2048 USERENV(750.280) 22:00:43:203 PingComputer: Adapter speed 100000000 bps USERENV(750.280) 22:00:43:203 PingComputer: First time: 0 USERENV(750.280) 22:00:43:203 PingComputer: Fast link. Exiting.
Next we have to determine where this computer account resides in Active Directory.
USERENV(750.280) 22:00:53:953 ProcessGPOs: User name is: CN=Machine,OU=Workstations,OU=TX,OU=USA,DC=Domain,DC=com, Domain name is: Domain USERENV(750.280) 22:00:53:953 ProcessGPOs: Domain controller is: \\DC1.DOMAIN.COM Domain DN is DOMAIN.COM
Notice that we print out the LDAP path to the computer account. This is done so that we know where to check for the policies at the OU levels. It will also report which DC that the computer has contacted in order to pull the policies from.
Next the client side extensions are checked where the GUID between the {} will be different.
USERENV(750.280) 22:00:53:968 ReadExtStatus: Reading Previous Status for extension {25537BA6-77A8-11D2-9B6C-0000F8080861}
Once we have all that we start checking for policies that might be linked at an OU level, domain level or site level . We first start at the OU that the computer is located at or if the computer lies in a container the next level up that a policy can be linked at.
USERENV(750.280) 22:00:54:000 GetGPOInfo: Server connection established. USERENV(750.280) 22:00:54:031 GetGPOInfo: Bound successfully. USERENV(750.280) 22:00:54:046 SearchDSObject: Searching <OU=Workstations,OU=TX,OU=USA,DC=Domain,DC=com > USERENV(750.280) 22:00:54:046 SearchDSObject: No GPO(s) for this object. USERENV(750.280) 22:00:54:046 SearchDSObject: Searching < OU=TX,OU=USA,DC=Domain,DC=com > USERENV(750.280) 22:00:54:046 SearchDSObject: Found GPO(s): <[LDAP://CN={Policy GUID},CN=Policies,CN=System, DC=Domain,DC=com;0]> USERENV(750.280) 22:00:54:046 SearchDSObject: Searching < OU=USA,DC=Domain,DC=com > USERENV(750.280) 22:00:54:046 SearchDSObject: Searching < DC=Domain,DC=com > USERENV(750.280) 22:00:54:046 SearchDSObject: Searching <CN=MYSite,CN=Sites,CN=Configuration, DC=Domain,DC=com >
At any point in this time the log may show something like this:
USERENV(750.280) 22:00:54:046 SearchDSObject: Found GPO(s):
Then the log shows a list of GPO’s that are linked to that particular OU/Domain/Site. Note that you could run across this in the output:
USERENV(750.280) 22:00:54:046 SearchDSObject: Found GPO(s): <[LDAP://CN={Policy GUID},CN=Policies,CN=System, DC=Domain,DC=com;0]>
Note the 0 at the end, this is the default setting, 1 means the policy is set to disabled which means the policy is linked to that particular OU / domain or site level but is disabled. If the value is set to 2 this means that the policy has been set to “No Override” also known as “Enforced.” A setting of “No Override” means that if 2 separate GPOs have the same setting are defined but hold different values, the one that is set to no override wins out on what is actually applied to the client. If a policy is set to “No Override” or “Enforced” at an OU/domain level then an OU below that is set to block inheritance, the policy set for “No Override” will still apply. You cannot block a policy from applying if the “No Override” or “Enforce” has been set on a policy.
Once we have gone all the way through we start actually applying the policies:
USERENV(750.280) 22:00:54:093 ProcessGPO: Searching <CN={GPO GUID},CN=Policies,CN=System, DC=Domain,DC=com >
The path above is where in AD the particulars of the policy are stored.
USERENV(750.280) 22:00:54:093 ProcessGPO: Machine has access to this GPO.
We need to check and see if the computer has access to the policy if we do then the computer can apply the policy; if we do not have access then we cannot apply it.
USERENV(750.280) 22:00:54:109 FilterCheck: Found WMI Filter id of: <[DOMAIN.COM;{Policy GUID};0]>
If a policy has a WMI filter being applied we have to check it and see if the policy is going to apply to this computer or not. The WMI filter can be seen if you go to the properties of the policy then to the WMI tab. If you are using GPMC then this can be found in the right hand pane at the very bottom box after highlighting the policy.
USERENV(750.280) 22:00:54:093 ProcessGPO: GPO passes the filter check.
USERENV(750.280) 22:00:55:250 ProcessGPO: The GPO does not pass the filter check and so will not be applied. USERENV(750.280) 22:00:54:093 ProcessGPO: Found functionality version of: 2
Functionality version has to be a 2 for a Windows 2000 or later OS to apply the policy.
USERENV(750.280) 22:00:54:093 ProcessGPO: Found file system path of: \\DOMAIN.com\SysVol\DOMAIN.com\Policies\{GPO GUID}
This above is the path of the policy in the file system on a DC.
USERENV(750.280) 22:00:54:109 ProcessGPO: Found common name of: <{GPO GUID}> USERENV(750.280) 22:00:54:109 ProcessGPO: Found display name of: <MY Domain Policy> USERENV(750.280) 22:00:54:109 ProcessGPO: Found machine version of: GPC is 77, GPT is 77
Here is where we check the GPC (Group Policy Container) and the GPT (Group Policy Template) for the version numbers. We check the version numbers to determine if the policy has changed since the last time it was applied. If the version numbers are different then we either have an AD replication or File replication latency problem.
USERENV(750.280) 22:00:54:109 ProcessGPO: Found flags of: 0 USERENV(750.280) 22:00:54:109 ProcessGPO: Found extensions: [{35378EAC-683F-11D2-A89A-00C04FBBCFA2}{53D6AB1D-2488-11D1-A28C-00C04FB94F17}][{827D319E-6EAC-11D2-A4EA-00C04F79F83A}{803E14A0-B4FB-11D0-A0D0-00A0C90F574B}][{B1BE8D72-6EAC-11D2-A4EA-00C04F79F83A}{53D6AB1D-2488-11D1-A28C-00C04FB94F17}]
The extensions above refer to the CSE (client-side extensions) and will vary from policy to policy. For a list of the CSE’s see:
216357 Identifying Group Policy Client-Side Extensions http://support.microsoft.com/kb/216357
943729 Information about new Group Policy preferences in Windows Server 2008 http://support.microsoft.com/kb/943729
Moving right along now we come to the part where we process CSE’s for particular settings such as Folder Redirection, Disk Quota, etc. If the particular extension is not being used then you can simply ignore this section.
USERENV(750.280) 22:00:56:359 ProcessGPOs: Processing extension Folder Redirection USERENV(750.280) 22:00:56:359 CompareGPOLists: The lists are the same. USERENV(750.280) 22:00:56:359 CheckGPOs: No GPO changes but couldn't read extension Folder Redirection's status or policy time. USERENV(750.280) 22:00:56:359 ProcessGPOs: Extension Folder Redirection skipped with flags 0x7.
Now we have pretty much come to the end of the computer processing which we know by the following:
USERENV(750.280) 22:00:56:390 SetFgRefreshInfo: Previous Machine Fg policy Synchronous, Reason: SyncPolicy. USERENV(750.280) 22:00:56:390 SetFgRefreshInfo: Next Machine Fg policy Synchronous, Reason: SyncPolicy. USERENV(750.280) 22:00:56:390 ProcessGPOs: No WMI logging done in this policy cycle. USERENV(750.280) 22:00:56:390 LeaveCriticalPolicySection: Critical section 0x6d0 has been released. USERENV(750.280) 22:00:56:390 ProcessGPOs: Computer Group Policy has been applied. USERENV(750.280) 22:00:56:390 ProcessGPOs: Leaving with 1. USERENV(750.280) 22:00:56:390 ApplyGroupPolicy: Leaving successfully. USERENV(750.860) 22:00:56:640 GPOThread: Next refresh will happen in 115 minutes
This is telling us that we will be refreshing the policy in the foreground and the next one will occur the same way in 115 minutes and we are leaving successfully.
Now for a note about the next blog for the user processing, no one runs a pure Microsoft environment and almost every Userenv log I have ever seen had something in the order of this showing up:
USERENV(6e4.6d4) 22:00:56:890 GetUserNameAndDomain Failed to impersonate user USERENV(6e4.6d4) 22:00:56:890 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available.
So what is this? Note that the very first of all the sample lines that I have added so far has started with:
USERENV(750.280), the first number, 750, is the process identifier (PID) and the second number is the thread identifier (TID). You can open Calc and change the View to Scientific. Change the type to Hex then enter 750 and hit the Decimal radio button. Now you have a number of 1872, this is the PID for the process. Open Task Manager, go to View – Select Columns and put a check mark in the box for PID and hit OK. Now in the column next to the Image Name will be the PID. Sort the PID’s and look for the process associated with the number 1872 and that is the process that the Userenv logging is referring to. In this case the PID of 1872 was Winlogon.exe. If we do the same for the problem PID (6e4) we get 1764. That PID resolved to a third-party service that was causing problems.
I hope this helps in understanding how to read part of the Userenv logging that we can enable to help in determining issues when booting up, applying group policies, etc. I will complete the User processing in Part 2. Also, you can find additional information on this topic at Interpreting Userenv Log Files on TechNet.
- Mark Ramey
Hi all, Rob Newhouse here and today I am talking about upgrading your domain to Windows Server 2008 and what you may see in the process, plus a couple of tips to make your transition a smooth one.
This post will show the proper use of ADPREP and what to expect when you are running it.
ADPREP is broken down into four stages with Windows Server 2008, instead of the two that most of you may be familiar with when you upgraded to Windows Server 2003. The four steps include Forest Preparation, Domain Preparation, Group Policy Preparation and Read-Only Domain Controller (RODC) Preparation (which you have to run if you want to add a RODC to your environment). You will use ADPREP.exe to perform all of these steps.
Preparing to Run ADPREP /forestprep
ADPREP /forestprep makes modifications to the schema. In order to successfully run it you should:
So let’s go through all these preparatory steps in detail
Running ADPREP /forestprep
Preparing to Run ADPREP /domainprep
After a successful completion of ADPREP /forestprep, you will be ready to run ADPREP /domainprep. ADPREP /domainprep must be run against each domain that you wish to upgrade.
Prerequisites
In order to run ADPREP /domainprep you should:
Note: Upgrading from Windows 2000 is not supported. For more information see Guide for Upgrading to Windows 2008.
Running ADPREP /Domainprep
For a better understanding of what will occur running the ADPREP /Domainprep command, I have referenced the KB article Enhancements to ADPREP.exe in Windows Server 2003 Service Pack 1(Q324392). The More Information section describes the functionality post-Windows 2003 SP1, including the Windows 2008 ADPREP.
Preparing to Run ADPREP /domainprep /gpprep
ADPREP /domainPrep /gpprep only adds the inheritable access control entries on Group Policy objects in the Sysvol share. If you run it prior to running adprep /domainprep it will run both functions, first the domain prep and then the GP prep.
In order to run ADPREP /domainprep /gpprep you should:
Note Upgrading from Windows 2000 is not supported. For more information see Guide for Upgrading to Windows 2008.
Running ADPREP /domainprep /gpprep
ADPREP /domainprep /gpprep without running adprep /domainprep first.
ADPREP /domainprep /gpprep after running adprep /domainprep
Preparing to Run ADPREP /rodcprep
RODC’s (Read-Only Domain Controllers) are a cool new feature added in Windows Server 2008. The benefits of a RODC in certain domain configurations are well worth the effort of learning and implementing them. For more information on the benefits, see RODC Features on TechNet. If you intend to introduce them into your environment you will have to run ADPREP /rodcprep. This command prepares partitions in Active Directory so RODC’s can be used by adding security to the ForestDNS, DomainDNS, and Domain partitions.
In order to run ADPREP /domainprep /rodcprep you should:
Note ADPREP /rodcprep will let you run without first running ADPREP /forestprep and ADPREP /domainprep, however it is not recommended.
Running ADPREP /rodcprep
That concludes this post on running ADPREP. Running through the steps in order should eliminate many of the problems you might otherwise encounter.
- Rob Newhouse
Hello everyone, Brian Singleton here. Here’s a question I often get from customer regarding Windows Time:
“Is there a way I can configure the Windows Time settings via Group Policy and have it only apply to the domain controller that holds the PDC FSMO role?”
This is a wonderful question to pose and there are very good reasons why this should be done:
We have a feature in Group Policy to help us that you may have read about on this blog, and that is WMI filtering.
Windows Management Instrumentation (WMI) is a powerful feature in Windows that we can leverage to provide us very detailed information about computers in our environment. We can use WMI via a script to remotely manage machines, as well as gather information about machines in our domain for inventory purposes.
The main reason why I have brought this feature up is that we can provide an additional layer of filtering for Group Policy application using WMI.
We can configure a GPO on the domain controller OU for our W32Time settings to configure the authoritative time server, but instead of using security filtering and explicitly securing it for the domain controller that has the PDC emulator role; WMI filtering can be used instead. It is important to state here before continuing is that WMI filtering will only work with computers running Windows XP/Windows Server 2003 and later. That means that you cannot use WMI filtering with Windows 2000.
Below is an example:
The domain I configure this policy on is Windows Server 2003, but the same applies to Windows Server 2008 as well. I am also using Group Policy Management Console (GPMC) which can be downloaded from here. For those of you who are using Windows Vista you can get GPMC by downloading the Microsoft Remote Server Administration Tools (RSAT).
First I will create my WMI filter:
The next part is me adding my query:
In the above image I added the following query:
Select * from Win32_ComputerSystem where DomainRole = 5
You can use WMIC to verify the current value of the DomainRole property. This can be a helpful way to get a sanity check on the value to make sure the filtering will achieve the desired result.
To view the DomainRole value locally:
wmic computersystem get domainrole
To view the DomainRole value remotely (where M1 is the remote computer):
wmic /node:”M1” computersystem get domainrole
In WMI we break up the various components of the OS and actual machine into classes. The Win32_ComputerSystem class is for computers running a Windows OS. Have a look at the following MSDN link for this class as well as other WMI classes:
WMI Classes http://msdn.microsoft.com/en-us/library/aa394554(VS.85).aspx
The Win32_ComputerSystem class has a lot of methods that can used in scripting as well as filtering for Group Policy but for the purposes of this post we will focus on the DomainRole:
From the MSDN website:
DomainRole
Role of a computer in an assigned domain workgroup. A domain workgroup is a collection of computers on the same network. For example, a DomainRole property may show that a computer is a member workstation. This property is inherited from CIM_ManagedSystemElement.
Value
Meaning
0
Standalone Workstation
1
Member Workstation
2
Standalone Server
3
Member Server
4
Backup Domain Controller
5
Primary Domain Controller
As you can see from the above chart 5 means Primary Domain Controller. So the query, Select * from Win32_ComputerSystem where DomainRole = 5, means select a machine whose DomainRole is 5, Primary Domain Controller. For those of you who would like to create a Windows Time GPO for all the other domain controllers you would just change it to DomainRole=4.
Now I am going to link my WMI filter to my already configured Authoritative Time Server GPO:
At the end what I have just accomplished is that the Authoritative Time Server GPO will only apply to the domain controller who holds the PDC emulator FSMO role. By configuring the policy in this fashion, I can transfer the PDC role to any domain controller and the policy will follow the role. Also, if the PDC fails and I bring up a new domain controller and seize the PDC emulator role to the new domain controller, the policy will apply on the next policy refresh or by forcing a group policy refresh.
I hope that you have learned a little more on how powerful WMI Filters are and how they can be leveraged to apply Group Policies based on a WMI Filter.
Additional Resources
Windows Management Instrumentation http://msdn.microsoft.com/en-us/library/aa394582(VS.85).aspx
WMI filtering using GPMC http://technet.microsoft.com/en-us/library/cc779036.aspx
Windows Management Instrumentation Command-line http://technet.microsoft.com/en-us/library/cc784189.aspx
- Brian Singleton
Note that this content has also been added to the TechNet Wiki to allow for community editing.
http://social.technet.microsoft.com/wiki/contents/articles/how-to-back-up-and-restore-ntfs-and-share-permissions.aspx
From time to time we are asked how to backup and restore NTFS file system permissions as well as network share permissions. KB article 125996 talks about the network share piece of it, but it does not talk about NTFS permissions.
One thing that has made the NTFS permissions piece of this simpler is the Icacls tool. Icacls was developed for Windows Vista as a replacement for tools such as Cacls, Xcacls, and Xcacls.vbs. It was also included in Service Pack 2 for Windows Server 2003 and Windows Server 2008.
Backup and Restore of Share Permissions
To backup share permissions, export the Shares registry key.
When you want to restore the permissions, double-click shareperms.reg to import it back into the registry.
Use the Reg tool to backup the registry key from the command line:
reg export HKLM\SYSTEM\CurrentControlSet\Services\LanmanServer\Shares shareperms.reg
If you need to restore it at some point, just run:
reg import shareperms.reg
Backup and Restore of NTFS Permissions
Use this command to backup NTFS permissions:
icacls d:\data /save ntfsperms.txt /t /c
The /T switch allows it to get subfolder permissions too. The /C switch allows it to continue even if errors are encountered (although errors will still be displayed).
Use this command to restore them:
icacls d:\ /restore ntfsperms.txt
Note that in the command to save the permissions, I specified the target folder D:\Data, but when I restored them, I specified just D:\ as the target. Icacls is a little funky like that, and here’s why.
If you open the text file with the exported permissions (ntfsperms.txt in the above example), you’ll see that Icacls uses relative paths (in bold below). Underneath the relative paths are the permissions for the folders in Security Descriptor Definition Language (SDDL) format.
data D:AI(A;ID;FA;;;BA)(A;OICIIOID;GA;;;BA)(A;ID;FA;;;SY)(A;OICIIOID;GA;;;SY)(A;OICIID;0x1200a9;;;BU)(A;ID;0x1301bf;;;AU)(A;OICIIOID;SDGXGWGR;;;AU) data\folder1 D:AI(A;ID;FA;;;BA)(A;OICIIOID;GA;;;BA)(A;ID;FA;;;SY)(A;OICIIOID;GA;;;SY)(A;OICIID;0x1200a9;;;BU)(A;ID;0x1301bf;;;AU)(A;OICIIOID;SDGXGWGR;;;AU) data\folder2 D:AI(A;ID;FA;;;BA)(A;OICIIOID;GA;;;BA)(A;ID;FA;;;SY)(A;OICIIOID;GA;;;SY)(A;OICIID;0x1200a9;;;BU)(A;ID;0x1301bf;;;AU)(A;OICIIOID;SDGXGWGR;;;AU)
Had I specified D:\Data in the command to restore the permissions, it would have failed looking for a D:\Data\Data folder:
D:\>icacls d:\data /restore perms.txt d:\data\data: The system cannot find the file specified. Successfully processed 0 files; Failed processing 1 files
You might think specifying D:\ as the target in the restore command may somehow mess up the permissions on other folders at that level, but as you can see from the ntfsperms.txt output file, it only has information about the Data folder and subfolders, so that is all it will change.
- Craig Landis
Hi, Rob here. First I want to thank you guys for reading and participating in our blogging efforts. I had one of you e-mail us and ask about the web site I used in the Kerberos Authentication Troubleshooting blogs and if they could get a copy of it.
The web site was created by our IIS support counterparts and it turns out it was released to the web as DelegConfig. Brian Murphy-Booth has a blog about the web site here. We at AskDS do not support the DelegConfig web site, so if you have questions or comments about it leave your feedback at that blog location.
With this web site you can test Kerberos double hop configurations and the newer delegation types of constrained delegation and constrained delegation with protocol transition from IIS to the following services: SQL, File Server, OLAP Server, or another web server. The reason why this documentation exists is to help customers configure Kerberos delegation to become familiar with all the tasks involved to configure the environment correctly.
NOTE: Review Setup and Known issues.txt from the DelegConfig.zip file for proper ASP.NET version to be installed on the IIS Server.
For more information on this topic as it relates to IIS you can review the below web site location:
Configuring Constrained Delegation for Kerberos (IIS 6.0)http://www.microsoft.com/technet/prodtechnol/WindowsServer2003/Library/IIS/df979570-81f6-4586-83c6-676bb005b13e.mspx?mfr=true
So that this blog is not too long (yeah, I know I am not known for short blogs) we are only going to show you how to configure the SQL server as the backend and how to test it since this is the most common situation where Kerberos delegation is configured. Keep in mind that for learning how Kerberos multi-hop works you do not need to install the full version of SQL. You can use SQL Express, and it can be installed on any operating system.
Registering a Service Principal Name http://technet.microsoft.com/en-us/library/ms191153.aspx
Kerberos Authentication and SQL Server http://technet.microsoft.com/en-us/library/cc280744.aspx
The SQL Server Service can run under basically two types of accounts.
The web site can verify either of these configurations, but there are different steps that need to be followed dependant on which configuration the SQL Server Service is running. Of course with all these configurations it is very important that we have the correct SPNs registered to the correct computer or user account.
I hope that you have been able to learn some new things. All the steps outlined here need to be done when configuring Kerberos delegation and this site will definitely help engineers to understand how Kerberos delegation works.
Have fun learning and testing all the different configurations that are possible with this application!
- Rob Greene
Mark here. As promised here is the second part of Understanding How to Read a Userenv Log (see Part 1 if you missed it). Most of the time when we need to enable Userenv logging is due to a delay of getting to the desktop after entering our credentials. Normally the user will be stuck at “Applying Personal Settings” is most often the scenario we see. The problem can stem from several different problems. One can be that another process, usually the anti-virus, has a lock on a file within the profile and cannot open the file. When this happens the user will get a new default profile. A reboot of the client will temporarily resolve this forcing all handles to be released. This does not always work but at times it will allow the user to logon and receive his old profile. Eventually the problem will come back. There also could be permissions issue or network issues when attempting to load a roaming profile. There are many different scenarios that plague users and loading their profiles.
I am going to continue using a Userenv log that I have where the customer was seeing the desktop hanging at “Applying Personal Settings.” To find the portion where the user starts his logon, search the log file for the user alias that they use to logon with:
USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpUserName = <User1>
You will also see this:
USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpDefaultPath = \\DC1\netlogon\Default User
By default we always look to the Netlogon share on a domain controller for the Default User profile. This goes way back to the old NT 4.0 days and it still is hanging around. Next we resolve the users name to a SID (Security Identifier) as follows:
USERENV(750.754) 22:01:02:812 LoadUserProfile: User sid: S-1-5-<domain sid-rid>
We do a check and see if the user is a local admin on the client they are logging onto:
USERENV(750.754) 22:01:02:812 RestoreUserProfile: User is a Admin
Now we actually go look and see if an existing profile exists or not to determine if we need to create a new one or whether the user has an existing profile:
USERENV(750.754) 22:01:02:812 ExtractProfileFromBackup: A profile already exists USERENV(750.754) 22:01:02:812 PatchNewProfileIfRequred: A profile already exists with the current sid, exitting USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Found entry in profile list for existing local profile USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Local profile image filename = <C:\Documents and Settings\user1> USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Expanded local profile image filename = < C:\Documents and Settings \user1> USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: No local mandatory profile. Error = 2 USERENV(750.754) 22:01:02:812 GetExistingLocalProfileImage: Found local profile image file ok < C:\Documents and Settings \user1\ntuser.dat>
So where do you look to find out if the user has an existing profile?
HKLM\Software\Microsoft\Windows NT\CurrentVersion\ProfileList
Under this key will be a list of SID’s corresponding to each user that has logged onto this client machine. If you highlight the ProfileList key you will notice some values there such as AllUsersProfile, DefaultUserProfile and the ProfilesDirectory. These values tell the system where the default directory is for the profiles then under that we know which directory the All Users and the Default Profile are. Drilling down underneath you can find the SID for the user you are looking for. Highlight it and note the ProfileImagePath value. This will point you to the directory where the system thinks your profile should be. There are other values here as well but we are not going to get into those. Note in the above output we check and see if the profile is a mandatory profile or not. How does it know whether the profile is mandatory or not? See the next line in the output at the end of the string we see Ntuser.dat in the profile path. If the Ntuser ended with a .man that would signify that the profile is mandatory. As you can see it ends with the .dat so the error = 2 means, “The system cannot find the file specified.” You can simply run “net helpmsg 2” from a command prompt to resolve some of the error messages to find out what they actually mean. In this case it did not find the Ntuser.man as the file it was looking for. So another question, what is the ntuser.dat file? This is the actual HKEY_CURRENT_USER hive you see in the registry when opening Regedit. It is simply a registry hive for the user’s profile to contain certain settings like desktop wallpaper, screen saver, application settings, etc. Once the profile is loaded we should see a line in the debug like this:
USERENV(750.754) 22:01:02:874 LoadUserProfile: Leaving with a value of 1.
The value of 1 means it was successful. This is not the time where the desktop starts showing up so don’t get confused here with that - the profile was loaded successfully. This simply means we loaded the Ntuser.dat file into the registry as the HKEY_CURRENT_USER hive. The next thing we do is start the Group Policy Processing for the user account:
USERENV(750.dec) 22:01:03:796 ProcessGPOs: Starting user Group Policy (Background) processing...
We go through the same as we did for the computer account; we need to determine the LDAP path of the user so we know where to look for any policies to apply.
USERENV(750.dec) 22:01:03:828 ProcessGPOs: User name is: CN=User1,OU=Users,OU=TX,OU=USA,DC=Domain,DC=com, Domain name is: Domain USERENV(750.dec) 22:01:03:828 ProcessGPOs: Domain controller is: \\DC1.Domain.COM Domain DN is Domain.COM
I won’t go through all the policy processing as we did in part one as it is all the same. The GPC and the GPT version numbers are checked, the display name, the common name is all the same. To know when we are done applying the user group policies look for the following in the log file:
USERENV(750.dec) 22:08:54:183 ProcessGPOs: User Group Policy has been applied. USERENV(750.dec) 22:08:54:183 ApplyGroupPolicy: Leaving successfully.
So if you notice now between the time we logged in (22:01:02) loaded the profile and applied group policies successfully (22:08:54) took approximately 8 seconds. Also note that the desktop is still not loaded by default, we are not done yet. Now comes the time to run any logon scripts:
USERENV(46c.4c4) 22:08:54:777 LibMain: Process Name: C:\WINNT\System32\WScript.exe
Now we are almost done, the GINA calls userinit.exe which in turn calls explorer.exe. Explorer is the process that brings up the shell which is the desktop with all its icons, etc. So in troubleshooting why it is taking so long for either the Userinit being called or Explorer being called you have to look to the log and see what is occurring.
USERENV(8c4.8c8) 22:08:55:808 LibMain: Process Name: C:\WINNT\system32\userinit.exe USERENV(8d8.8dc) 22:28:57:824 LibMain: Process Name: C:\WINNT\Explorer.EXE
Note the approximately 20 minutes difference in the time stamps of the two events above. So what is going on during this time? This is what was happening:
USERENV(6e4.6d4) 22:10:16:856 GetUserDNSDomainName: Domain name is NT Authority. No DNS domain name available. USERENV(6e4.6d4) 22:10:17:090 ImpersonateUser: Failed to impersonate user with 5.
This was being logged into the Userenv log constantly. If you remember from Part 1, the 6e4 was the PID of the process that was running. In this log we could see that this PID was delaying Explorer from being called to start the shell. The PID 6e4 (hex) resolves to 1764 (decimal). If we look back in Task Manager we can see that the PID resolves to a 3rd party security service that was running. In this case we disabled that service and rebooted. We tested and no other issues came up with a delay in getting to the desktop. Here is another tidbit to help you out in case you are troubleshooting a remote machine. Let’s say someone sends you a Userenv.log file to look over, you see something similar as above but the user has either rebooted or shut down the machine so you have no way to look up that PID. Every time a service restarts or the machine restarts the process will have a new PID. Have the user generate a System Information file by going to Start – Run – Msinfo32 and hit enter. Once the System Information file comes up save the file as a System Information File with a .NFO extension. Now have the user send that file as well then in the left hand column expand Software Environment and highlight Running Tasks. There you will see all the processes running and their PID’s.
I will touch on some aspects of a roaming profile, all the information above has been for local profiles. When using a roaming profile you will see some slight differences in the Userenv log. For example if the roaming profile path is set on the user properties on the Account tab you will see the following:
USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpUserName = <User1> USERENV(750.754) 22:01:02:796 LoadUserProfile: lpProfileInfo->lpProfilePath = \\fileserver\profiles\User1
This tells us that the roaming profile is located on the server called fileserver at the share called profiles then the user name. Once the SID has been resolved to a name we check to see if it is a cross forest logon.
USERENV(750.754) 22:01:02:796 CheckXForestLogon: checking x-forest logon, user handle = 560 USERENV(750.754) 22:01:02:796 CheckXForestLogon: not XForest logon.
There is a policy that allows cross forest roaming profiles to be loaded. By default if user account is located in one forest and they attempt to logon to a machine in another forest they will get a new default profile unless the following policy is set:
Computer Configuration \ Administrative Templates \ System \ Group Policy \ Allow Cross-Forest User Policy and Roaming User Profiles
This policy will need to be set in the domain where the machine account is located. Next we actually map a drive to the share \\fileserver\profiles and most of the time it will be E drive. The drive will look like E:\user1 now. Next we go through the same procedure as before, pinging the DC to determine if we are on a fast link or not. Now we check to see if the user account has ownership of the files in the profile:
USERENV(750.754) 22:01:02:796 CheckRoamingShareOwnership: checking ownership for E:\User11 USERENV(750.754) 22:01:02:796 CheckRoamingShareOwnership: owner is the right user
At times the user may not be the owner of the files located in the share. Let’s say the file server was changed and now points to a new file server then the files copied over manually to the new server share. The Administrators group will most likely be the new owner of the files. So when the user logs on they will get an error attempting to load the profile unless the following policy is set:
Computer Configuration \ Administrative Templates \ System \ User Profiles \ Do not check for user ownership of Roaming Profile Folders
Next we perform the same checks to see if it is a mandatory profile or not then start reconciling the roaming profile with the locally cached profile if one exists. One thing to keep in mind is that all changes made to the profile are done locally and are not propagated to the server share until the user logs off.
I hope these two parts help you in understanding how to read a Userenv log. By no means will you be an expert in reading one the first time. It takes practice and looking at many of them to determine what is happening or not happening as the case may be. Hopefully it will give you a better understanding of how the OS is designed and what is actually occurring during the profile load.
For more information check out some of the following articles:
Interpreting Userenv Log Files http://technet.microsoft.com/en-us/library/cc786775.aspx
Group Policy Wiki http://grouppolicy.editme.com
250842 Troubleshooting Group Policy application problems http://support.microsoft.com/kb/250842
Note that this post has been added to the TechNet Wiki to allow for community editing.
If you notice that DFS Replication (DFSR) is not replicating certain files, one simple reason is that the temporary attribute is set on them. By design, DFSR does not replicate files if they have the temporary attribute set on them, and it cannot be configured to do so.
This may not be obvious because nearly all the normal methods you would use in Windows to check file attributes do not show the temporary attribute. Specifically, all of the following do not show the temporary attribute - Attrib.exe, Explorer's file properties, FileSystemObject in Windows Scripting Host, and CIM_Datafile in WMI. Also, DFSR does not log any errors to the event log or to the debug logs to show temporary files are not being replicated. There is a relevant entry in the debug logs, but it is not an error because this behavior is by design.
The reason DFSR does not replicate files with the temporary attribute set is that they are considered short-lived files that you would never actually want to replicate. Using the temporary attribute on a file keeps that file in memory and saves on disk I/O. Therefore applications can use it on short-lived files to improve performance.
An application can use FILE_ATTRIBUTE_TEMPORARY when calling the CreateFile function if they want a temporary file. But an even better way is to also specify FILE_FLAG_DELETE_ON_CLOSE so the temporary file is deleted when all handles are closed. That way you get the performance benefit of a temporary file (it’s kept in memory) and it is removed when handles are closed so administrators don’t come along and wonder why DFSR isn’t replicating it.
If you have temporary files that you want DFSR to replicate, you may think it is enough to just remove the temporary attribute on those files and be on your way. And you can do that. But since you got in this situation once, it is likely you still have an application that will come right back and create more temporary files. So you need to get at the crux of the issue – why do you want to replicate files that an application is specifically creating to be temporary? Either the application must change its behavior, or you must except that temporary files won’t be replicated, because there is no way to make DFSR replicate files as long as the temporary attribute is set on them.
Checking the Temporary Attribute on a File using Fsutil
But wait, you say, maybe I don’t even know yet if these files that aren’t replicating are temporary! So let’s find out. As mentioned before, almost none of the ways to check attributes in Windows will actually show the temporary attribute. But there is one that does – the handy Fsutil tool that is included in Windows.
fsutil usn readdata c:\data\test.txt
Major Version : 0x2 Minor Version : 0x0 FileRef# : 0x0021000000002350 Parent FileRef# : 0x0003000000005f5e Usn : 0x000000004d431000 Time Stamp : 0x0000000000000000 12:00:00 AM 1/1/1601 Reason : 0x0 Source Info : 0x0 Security Id : 0x5fb File Attributes : 0x120 File Name Length : 0x10 File Name Offset : 0x3c FileName : test.txt
File Attributes is a bitmask that indicates which attributes are set. In the above example, 0x120 indicates the temporary attribute is set because that is 0x100 and 0x20 (Archive) = 0x120.
Here are the possible values:
You combine the values to come up with the File Attributes bitmask value.
If you need a sanity check:
Checking for Temporary Files in the Debug Logs with Findstr
Another way to check if files are not replicating because they have the temporary attribute set is to use Findstr (included in Windows) to look for the FILE_ATTRIBUTE_TEMPORARY text string in the DFSR debug logs.
First you need to extract out all of the debug logs, because all except the active log will be compressed, as indicated by a .GZ extension. The DFSR debug logs (Dfsr*.log and Dfsr*.log.gz) reside by default under %windir%\debug. All the popular compression tools such as Winzip and Winrar can handle .GZ compression.
Let’s say you extracted the debug logs to C:\Logs. You can then run the following Findstr command to look for temporary files.
Findstr FILE_ATTRIBUTE_TEMPORARY c:\logs\dfsr*.log
That will output the entire line for every line in the debug log that contains a match to that string. If it doesn't find any matches, it will return to a prompt and not show anything.
Sample output from a matching entry:
C:\WINDOWS\debug\Dfsr00018.log:20080903 16:14:29.390 1808 USNC 1204 UsnConsumer::ProcessUsnRecord Skipping USN_RECORD with FILE_ATTRIBUTE_TEMPORARY flag:
If it does find any matches, you can then open the specified log file, search on the string FILE_ATTRIBUTE_TEMPORARY (Ctrl+F or Edit | Find in Notepad) and then you will see the actual file name for the file that was skipped because the temporary attribute is set on it.
Removing the Temporary Attribute from Multiple Files with Powershell
So you figured out that DFSR is not replicating some files because they have the temporary attribute set. There is no way to change this behavior in DFSR, so the only option is to live with it, or remove the temporary attribute from the files you want to replicate. An application in your environment has created these temporary files, so just treating the symptom isn’t enough, you need to find the application that creates them and either change its behavior, or accept that those files will not be replicated.
Since Attrib is not aware of the temporary attribute, we need to go to greater lengths to remove it. First you need to have Powershell installed on the machine - www.microsoft.com/powershell
Then bring up a Powershell prompt (Start, Run, Powershell or from the Programs menu) and run this command to remove the temporary attribute from all files in the specified directory, including subdirectories (in this example, D:\Data):
Get-childitem D:\Data -recurse | ForEach-Object -process {if (($_.attributes -band 0x100) -eq 0x100) {$_.attributes = ($_.attributes -band 0xFEFF)}}
If you don’t want it to work against subdirectories just remove the -recurse parameter.
Additional Information
Win32 CreateFile Function http://msdn.microsoft.com/en-us/library/aa363858(VS.85).aspx
It’s Only Temporary http://blogs.msdn.com/larryosterman/archive/2004/04/19/116084.aspx
103237 INFO: Using Temporary Files Can Improve Application Performance http://support.microsoft.com/kb/103237
131324 Use New Flags to Speed Up C Run-time Low-Level I/O Functions http://support.microsoft.com/kb/131324
Designing Distributed File Systems (see Files Not Replicated under DFSR Replication Compatibility) http://technet.microsoft.com/en-us/library/cc772778.aspx
Ned here again. Today's post is short and sweet, but when you need this one you will need it fast and we don't have this publically documented anywhere on TechNet (yet).
Since Windows 2000 SP4, it has been possible to forcibly demote Domain Controllers using the DCPROMO /FORCEREMOVAL command. You could use this switch if:
Naturally you must always follow this up with Metadata Cleanup on other DCs.
However, if you try to run this command on a Windows Server 2008 DC running in Core (no GUI) mode, it will always return:
An answer file or unattend installation command-line parameters must be specified.
And even if you provide an answer file, you will continue to get various prompts and issues that prevent demotion.
So how do we get this to work? With the following command:
dcpromo /forceremoval /demotefsmo:yes /administratorpassword:<the new password>
For example:
dcpromo /forceremoval /demotefsmo:yes /administratorpassword:Password1
So I can already hear the question "But this server did not have any FSMO roles on it - why do I need to add that switch?" The answer is because this not only forces demotion with a FSMO role in place, it also suppresses the warning prompt for FSMO when forcibly demoting.
I tried to come up with a snappier title for this, but I figured most readers that actually needed this post would already be so busy that they wouldn't want any cutesy-pie stuff. :-)
- Ned Pyle