Microsoft's official enterprise support blog for AD DS and more
Ned here. From one of our MSIT bloggers-in-arms, Brian Puhl:
10 years ago, Microsoft’s largest internal domain was upgraded to Windows 2000 becoming the first production Active Directory, and it’s still going strong… Dn: DC=redmond,DC=corp,DC=microsoft,DC=com whenCreated: 4/9/1999 7:49:12 PM Pacific Daylight Time;
10 years ago, Microsoft’s largest internal domain was upgraded to Windows 2000 becoming the first production Active Directory, and it’s still going strong…
Dn: DC=redmond,DC=corp,DC=microsoft,DC=com whenCreated: 4/9/1999 7:49:12 PM Pacific Daylight Time;
Happy birthday Redmond domain, here's to many more. In honor of the event, here's a rather creepy picture.
- Ned ‘Party Hat’ Pyle
Hello, David Everett here. I recently encountered an issue where authentication was failing across numerous forests after a second kerberos trust was made with a forest. Unlike most implementations of Active Directory which have a forest root and child domains that share a common DNS Namespace hierarchy, this customer had several forests sharing the same DNS Namespace, with CONTOSO.COM being the root of the DNS tree.
The customer presented a very complex Visio diagram of their forests complete with all the trust relationships. While authentication issues were occurring in many of the forests I’m only citing those forests and domains that are of interest in an effort to simplify things.
Existing Forests and Trust Relationships:
The following trusts were already in place for about a year with no issues prior to the addition of a new forest trust:
A new two-way forest trust between CONTOSO.COM and TOWN.COUNTY.CONTOSO.COM was added and authentication in several forests began to fail.
Some of the errors encountered:
After the second forest trust was added an Administrator of SUBDIVISION.TOWN.COUNTY.CONTOSO.COM logged onto a DC in SUBDIVISION and tried to connect to REALM.COUNTY.CONTOSO.COM in Active Directory Users and Computers only to get this error:
Active Directory Windows cannot connect to the new domain because: The system detected a possible attempt to compromise security. Please ensure that you can contact the server that authenticated you.
Active Directory
Windows cannot connect to the new domain because: The system detected a possible attempt to compromise security. Please ensure that you can contact the server that authenticated you.
When the SUBDIVISION administrator failed to connect the following event was logged in the System event log of the SUBDIVISION DC:
Event Type: Warning Event Source: LSASRV Event Category: SPNEGO (Negotiator) Event ID: 40960 Date: 3/13/2009 Time: 12:13:31 PM User: N/A Computer: SUBDC01 Description: The Security System detected an authentication error for the server ldap/RELDC1.realm.county.contoso.com. The failure code from authentication protocol Kerberos was "The name or SID of the domain specified is inconsistent with the trust information for that domain. (0xc000019b)".
Here are some other events and errors you might see referencing domains in other forests that have trusts with the DC logging the event:
Event Type: Error Event Source: KDC Event Category: None Event ID: 12 Date: 3/9/2009 Time: 10:10:45 AM User: N/A Computer: SUBDC01 Description: A request failed from client realm OTHER.NESTED.CONTOSO.COM for a ticket in realm TOWN.COUNTY.CONTOSO.COM. This failed because a trust link between the realms is non transitive. And Active Directory Windows cannot connect to the new domain because: Logon Failure: The machine you are logging onto is protected by an authentication firewall. The specified account is not allowed to authenticate to the machine.
Event Type: Error Event Source: KDC Event Category: None Event ID: 12 Date: 3/9/2009 Time: 10:10:45 AM User: N/A Computer: SUBDC01 Description: A request failed from client realm OTHER.NESTED.CONTOSO.COM for a ticket in realm TOWN.COUNTY.CONTOSO.COM. This failed because a trust link between the realms is non transitive.
And
Windows cannot connect to the new domain because: Logon Failure: The machine you are logging onto is protected by an authentication firewall. The specified account is not allowed to authenticate to the machine.
Understanding the Problem:
When a Forest Trust is created a Name Suffix Route is dynamically added to both sides of the Forest Trust Properties. The Name Suffix Route is comprised of the DNS name suffix of the trusted forest root and a wildcard (*) precedes the DNS name suffix to allow for child domains to be trusted implicitly. The name suffix looks like this: *.CONTOSO.COM.
Name Suffixes Routing controls routing of authentication traffic. When an account attempts to authenticate and that account does not exist in the local domain, the Name Suffix Route is used to direct authentication requests to the trusted forest root domain.
Prior to the addition of the new forest trust a Name Suffix Route of *.CONTOSO.COM existed on the REALM.COUNTY.CONTOSO.COM side of the two-way forest trust between the REALM.COUNTY.CONTOSO.COM and CONTOSO.COM.
Problems only developed after the new two-way forest trust show below was added between CONTOSO.COM and TOWN.COUNTY.CONTOSO.COM. Authentication traffic from TOWN intended for REALM was being sent to CONTOSO. Likewise, authentication traffic from REALM intended for the TOWN forest was being sent to CONTOSO. This occurred because of a dynamically created Name Suffix Route of *.contoso.com that was added to the TOWN.COUNTY.CONTOSO.COM side of the trust.
In most environments the dynamically created Name Suffix Route of *.<forestroot>.<tld> would not cause issues. However, in this customer’s environment a Name Suffix Route of *.<forestroot>.<tld> caused all authentication requests to be sent to the wrong forest. Since the Forest is the security boundary authentication requests stopped at the CONTOSO.COM forest and did not implicitly follow the DNS Hierarchy.
Correcting the problem:
When more than two Forest reside in the same DNS namespace, and the root of that DNS tree is also an Active Directory forest, logic must be added to the Name Suffix Route to ensure authentication traffic is routed to the correct forest root. This can be accomplished by adding Exclusions to the Name Suffix Routes.
1. Exclusions were added to the existing forest trust between REALM and CONTOSO. On the REALM side of the trust properties the following Exclusion had to be added to the *.CONTOSO.COM Name Suffix Route: TOWN.COUNTY.CONTOSO.COM NOTE: The * is automatically added in front of the suffix 2. After the new two-way forest trust was created between TOWN and CONTOSO we added the following Exclusion to the *.CONTOSO.COM Name Suffix Route on the TOWN side of the trust: REALM.COUNTY.CONTOSO.COM NOTE: The * was automatically added in front of the suffix
1. Exclusions were added to the existing forest trust between REALM and CONTOSO. On the REALM side of the trust properties the following Exclusion had to be added to the *.CONTOSO.COM Name Suffix Route:
TOWN.COUNTY.CONTOSO.COM
NOTE: The * is automatically added in front of the suffix
2. After the new two-way forest trust was created between TOWN and CONTOSO we added the following Exclusion to the *.CONTOSO.COM Name Suffix Route on the TOWN side of the trust:
REALM.COUNTY.CONTOSO.COM
NOTE: The * was automatically added in front of the suffix
More reading:
Routing name suffixes across forests
http://technet.microsoft.com/en-us/library/cc784334.aspx
Exclude name suffixes from routing to a local forest
http://technet.microsoft.com/en-us/library/cc758388.aspx
I hope you find this useful.
UPDATE: Made changes to the diagrams to fix an error and makes things a bit more readable. Nice catch, Randy!
- David ‘Monochrome’ Everett
Ned again. As promised, here is the complete list of links for the recent 21-part DFSR Debug Log analysis series as well as downloadable versions of the series in Word 2007, Word 2003-97, XPS, and PDF formats. I have also included the debug logs I referenced as a separate ZIP file.
Understanding DFSR debug logging Understanding DFSR debug logging (Part 1: Logging Levels, Log Format, GUID’s)Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)Understanding DFSR debug logging (Part 3: The Log Scenario Format, File Added to Replicated Folder on Windows Server 2008)Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008) Understanding DFSR debug logging (Part 5: File Modified on Windows Server 2003 R2)Understanding DFSR debug logging (Part 6: Microsoft Office Word 97-2003 File Modified on Windows Server 2008)Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)Understanding DFSR debug logging (Part 8: File Deleted from Windows Server 2003 R2) Understanding DFSR debug logging (Part 9: File is Renamed on Windows Server 2003 R2)Understanding DFSR debug logging (Part 10: File Conflicted between two Windows Server 2008)Understanding DFSR debug logging (Part 11: Directory created on Windows Server 2003 R2)Understanding DFSR debug logging (Part 12: Domain Controller Bind and Config Polling on Windows Server 2008)Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream between two Windows Server 2008) Understanding DFSR debug logging (Part 15: Pre-Seeded Data Usage during Initial Sync)Understanding DFSR debug logging (Part 16: File modification with RDC in very granular detail (uses debug severity 5))Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses debug severity 5))Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity 5))Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (uses debug severity 5))Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severity 5))Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))
Downloadable Versions (all 21-parts in one document)
DOCX, DOC, XPS, PDF
Download the sample log files
ZIP
- Ned Pyle
In this final scenario we will see a file being replicated successfully, but where the replication appears to be very slow. A bandwidth throttle has been configured within the DFSR replication group schedule to restrict traffic to 128Kbps. This is useful in understanding how throttling works as well as determining that slow replication has been configured intentionally.
(throttleupstream - Dfsr00010 - 2008.log and throttledownstream - Dfsr00012 - 2008.log)
These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x86SRV11 in the contoso.com domain. The logs are from 2008x86SRV10 (the upstream) and 2008x86SRV11 (the downstream). The replication schedule is at 128 Kilobits per second and the file being replicated is named “imageres.dll”. Debug logging severity is set to 5 to see additional details.
<Upstream> 20080909 17:01:15.186 2880 USNC 2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record: ß file is created on the upstream server.
+ fid 0x500000000BB0A
+ usn 0x27d2a30
+ uidVisible 0
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90
+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90
+ parent {43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080910 00:01:15.186 GMT (0x1c912d857ca1d84)
+ createTime 20080910 00:01:15.186 GMT
+ csId {43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name imageres.dll ß file named ‘imageres.dll’
+
<Upstream> 20080909 17:01:15.186 2880 USNC 2615 UsnConsumer::CreateNewRecord ID record created from USN_RECORD:
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x500000000BB0A
+ ParentFileRefNumber: 0xC00000000BA6B
+ USN: 0x27d2a30
+ TimeStamp: 20080909 17:01:15.186 Pacific Standard Time
+ Reason: Basic Info Change Close Data Extend Data Overwrite File Create
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: imageres.dll
<Upstream> 20080909 17:01:15.186 2880 LDBX 4300 Ldb::UpdateLastVersion Updating lastVersion:90
<Upstream> 20080909 17:01:15.186 2880 LDBX 3340 LdbManager::WakeUpSleepers Wake up callback 009786F8
<Upstream> 20080909 17:01:15.186 2956 UPST 1399 UpstreamTransport::FlushVvUp 002F58A8
<Upstream> 20080909 17:01:15.186 2956 UPST 1417 UpstreamTransport::FlushVvUp send connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} seqNumber:12 status:0 vvGeneration:8 vvUp:
<Upstream> 20080909 17:01:15.186 3980 SRTR 1880 SERVER_RequestVersionVector Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} seqNumber:13 changeType:all
<Upstream> 20080909 17:01:15.186 3980 SRTR 1927 SERVER_AsyncPoll Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85}
<Upstream> 20080909 17:01:15.186 3980 UPST 1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:002F58A8
<Upstream> 20080909 17:01:15.186 2956 UPST 1417 UpstreamTransport::FlushVvUp send connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} seqNumber:13 status:0 vvGeneration:8 vvUp:{0E1F0993-5130-4BB2-B409-FD13366B9A0C} |-> { 32, 33}
+ {5CB120DE-D2C2-452A-8280-B45FC155224F} |-> { 84..90}
<Upstream> 20080909 17:01:15.186 3980 SRTR 882 SERVER_RequestUpdates Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} credits:32 requestType:all
<Upstream> 20080909 17:01:15.186 3980 UPST 88 UpdateBuffer::UpdateBuffer UpdateBuffer created. connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D}
<Upstream> 20080909 17:01:15.202 2956 JOIN 1122 Join::SubmitUpdate LDB Updating ID Record:
+ uidVisible 1
+ recUpdateTime 20080910 00:01:15.186 GMT
+ createTime 20080910 00:01:14.874 GMT
+ name imageres.dll
<Upstream> 20080909 17:01:15.202 3980 SRTR 1927 SERVER_AsyncPoll Received from connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85}
<Upstream> 20080909 17:01:15.202 3980 UPST 1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:002F5308
<Upstream> 20080909 17:01:15.202 2956 JOIN 1167 Join::SubmitUpdate Sent: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 name:imageres.dll connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} csName:throttlerf
<snipped out information documented in other scenarios>
<Downstream> 20080909 17:01:18.905 3188 STAG 1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 state: Downloading (refCount==1)
<Downstream> 20080909 17:01:18.905 3188 STAG 4113 Staging::OpenForWrite name:imageres.dll uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 ß upstream server ready to replicate file
<Downstream> 20080909 17:01:18.905 3188 DOWN 6256 DownstreamTransport::DownloadFileAsync rpcAsyncState:045AE088
<Downstream> 20080909 17:01:18.905 3188 DOWN 5970 DownstreamTransport::RpcAsyncPipeDownload rpcAsyncState:045AE088
<Upstream> 20080909 17:01:18.921 696 SRTR 2529 RpcAsyncPipeState::RpcAsyncPipeState this:009210A0 rpcAsyncState:002F58A8 context:00933280 bytePipe:002E8590
<Upstream> 20080909 17:01:18.921 696 SRTR 3051 RawGetFileDataAsyncState::RawGetFileDataAsyncState 009210A0
<Upstream> 20080909 17:01:18.921 696 SRTR 2596 RpcAsyncPipeState::Start this:009210A0
<Upstream> 20080909 17:01:18.921 696 SRTR 2710 RpcAsyncPipeState::InitializeDataReader Starting pipe thread. this:009210A0
<Upstream> 20080909 17:01:18.921 3784 SRTR 3079 RawGetFileDataAsyncState::DataPipeThread Entering data pipe thread. this:009210A0
<Upstream> 20080909 17:04:31.134 928 CFAD 10450 Config::AdReader::Peek Subscriptions Checksum, old = 20953, new = 20953
<Upstream> 20080909 17:09:07.506 3784 SRTR 3132 RawGetFileDataAsyncState::DataPipeThread Exiting data pipe thread. this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2940 RpcAsyncPipeState::Process Push eof this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2969 RpcAsyncPipeState::Process Completing this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2648 RpcAsyncPipeState::ProcessIoCompletion Release this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 3056 RawGetFileDataAsyncState::~RawGetFileDataAsyncState 009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2553 RpcAsyncPipeState::CloseDataPipe this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2556 RpcAsyncPipeState::CloseDataPipe Shutting down pipe. this:009210A0
<Upstream> 20080909 17:09:07.506 3832 SRTR 2543 RpcAsyncPipeState::~RpcAsyncPipeState this:009210A0
<Upstream> 20080909 17:09:41.148 928 CFAD 10450 Config::AdReader::Peek Subscriptions Checksum, old = 20953, new = 20953
<Downstream> 20080909 17:01:23.327 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 4100 ms (waitResult 258) ß downstream DFSR service replicates a percentage of the file at full bandwidth, then artificially stops replicating.
<Downstream> 20080909 17:01:25.030 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 1700 ms (waitResult 258)
<Downstream> 20080909 17:01:28.436 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 3400 ms (waitResult 258)
<Downstream> 20080909 17:01:38.437 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 10000 ms (waitResult 258)
<Downstream> 20080909 17:01:50.344 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 11900 ms (waitResult 258)
<Downstream> 20080909 17:02:02.751 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 12400 ms (waitResult 258)
<snipped out many repeats of this>
<Downstream> 20080909 17:14:55.987 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 5600 ms (waitResult 258)
<Downstream> 20080909 17:14:58.299 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 2300 ms (waitResult 258)
<Downstream> 20080909 17:15:01.909 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 3600 ms (waitResult 258)
<Downstream> 20080909 17:15:09.018 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 7100 ms (waitResult 258)
<Downstream> 20080909 17:15:18.518 3188 DOWN 6631 BandwidthThrottler::WaitOneInterval Throttling: Waited for 9500 ms (waitResult 258) ß After roughly 14 minutes the file has been replicated
<Downstream> 20080909 17:15:18.518 3188 DOWN 6093 DownstreamTransport::RpcAsyncPipeDownload Wait completion rpcAsyncState:045AE088 ß RPC file download session pipe can be closed.
<Downstream> 20080909 17:15:18.550 3188 INCO 5735 InConnection::RdcGet Update syncInfoHistory
<Downstream> 20080909 17:15:18.550 3188 INCO 5610 InConnection::LogTransferActivity Received RAWGET uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 fileName:imageres.dll connId:{9569E157-9E0A-4AE0-B62C-90D23303DE85} csId:{43F13D7D-F9B1-42C6-B90C-7BC8DC2EB16D} stagedSize:12597886
<Downstream> 20080909 17:15:18.550 3188 MEET 1970 Meet::Download Done downloading content updateName:imageres.dll uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v90 ß file has been copied to the staging directory on the downstream server.
This wraps up the 21 part blog series on reading the DFSR debug logs. I hope you found this interesting and helpful.
Understanding DFSR debug logging (Part 1: Logging Levels, Log Format, GUID’s)Understanding DFSR debug logging (Part 2: Nested Fields, Module ID's)Understanding DFSR debug logging (Part 3: The Log Scenario Format, File Added to Replicated Folder on Windows Server 2008)Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008) Understanding DFSR debug logging (Part 5: File Modified on Windows Server 2003 R2)Understanding DFSR debug logging (Part 6: Microsoft Office Word 97-2003 File Modified on Windows Server 2008)Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)Understanding DFSR debug logging (Part 8: File Deleted from Windows Server 2003 R2) Understanding DFSR debug logging (Part 9: File is Renamed on Windows Server 2003 R2)Understanding DFSR debug logging (Part 10: File Conflicted between two Windows Server 2008)Understanding DFSR debug logging (Part 11: Directory created on Windows Server 2003 R2)Understanding DFSR debug logging (Part 12: Domain Controller Bind and Config Polling on Windows Server 2008)Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream between two Windows Server 2008) Understanding DFSR debug logging (Part 15: Pre-Seeded Data Usage during Initial Sync)Understanding DFSR debug logging (Part 16: File modification with RDC in very granular detail (uses debug severity 5))Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses debug severity 5))Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity 5))Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (uses debug severity 5))Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severity 5))Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))
In this scenario we will see a pair of files being created on an upstream server. One of the files is marked with the TEMPORARY attribute and one has an extension of TMP which is being filtered by DFSR. This will show the common scenarios of files which do not appear to ever replicate for unknown reasons.
(tempfilesupstream - Dfsr00008 - 2008.log)
These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x86SRV11 in the contoso.com domain. The log is from 2008x86SRV10 where the file is created. The files are realtemp.doc (which has temp attribute set) and pseudotemp.tmp (which is filtered by DFSR).
<Upstream> 20080908 13:43:09.067 3856 USNC 1244 UsnConsumer::ProcessUsnRecord Skipping USN_RECORD with FILE_ATTRIBUTE_TEMPORARY flag: ß the USN journal update process will mark when files are filtered for any reason. In this case the file is structurally temporary due to an attribute.
+ FileRefNumber: 0x80000000000B6
+ ParentFileRefNumber: 0x70000000000B3
+ USN: 0x268e058
+ TimeStamp: 20080908 13:43:09.052 Pacific Standard Time
+ Reason: Close Security Change
+ FileAttributes: 0x120 ß 0x20 (file) & 0x100 (temporary)
+ FileName: realtemp.doc ß the file called ‘realtemp.doc’
<Upstream> 20080908 13:43:09.083 3856 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß In this case the USN update is filtered because the file has a name matching the DFSR file filters (by default, ~*, *tmp, *.bak)
+ FileRefNumber: 0x50000000000B4
+ USN: 0x268e160
+ TimeStamp: 20080908 13:43:09.083 Pacific Standard Time
+ Reason: Close Rename New Name
+ FileAttributes: 0x20 ß file, not a folder
+ FileNameLength: 28
+ FileName: pseudotemp.tmp ß file ends with extension of TMP and is filtered
In this scenario we will see an attempted file replication. The downstream partner is running the File Server Resource Manager role with file screens configured and these screens are not matched to the DFSR file filters. The debug log has been set to severity 5 for deeper details than usual.
(filescreenupstream - Dfsr00008 - 2008.log and filescreendownstream - Dfsr00009 - 2008.log)
These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x86SRV11 in the contoso.com domain. The logs are from 2008x86SRV10 where the file is created (upstream) and from 2008x86SRV11 where it is replicated (downstream). Both servers are participating in the FsrmRg replication group for the FsrmRf replicated folder. The file is called “spoolsv.exe”. FSRM is configured with the default “block executable files” file screen.
<Upstream> 20080908 13:21:16.113 3264 USNC 2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record: ß File created upstream
+ fid 0x300000000BACF
+ usn 0x2685058
+ gvsn {5CB120DE-D2C2-452A-8280-B45FC155224F}-v39
+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v39
+ parent {9D619939-CA99-497B-90F1-D667B4D76F05}-v1
+ clock 20080908 20:21:16.113 GMT (0x1c911f0721d8af3)
+ createTime 20080908 20:21:16.113 GMT
+ csId {9D619939-CA99-497B-90F1-D667B4D76F05}
+ name spoolsv.exe ß file named ‘spoolsv.exe’
<Upstream> 20080908 13:21:16.113 3264 USNC 2615 UsnConsumer::CreateNewRecord ID record created from USN_RECORD:
+ FileRefNumber: 0x300000000BACF
+ ParentFileRefNumber: 0x60000000000B3
+ USN: 0x2685058
+ TimeStamp: 20080908 13:21:16.113 Pacific Standard Time
+ FileNameLength: 22
+ FileName: spoolsv.exe
<Upstream> 20080908 13:21:16.113 3264 LDBX 4300 Ldb::UpdateLastVersion Updating lastVersion:39
<Upstream> 20080908 13:21:16.113 3264 LDBX 3340 LdbManager::WakeUpSleepers Wake up callback 008753C0
<Upstream> 20080908 13:21:16.113 3460 UPST 1399 UpstreamTransport::FlushVvUp 00201800
<Upstream> 20080908 13:21:16.113 3460 UPST 1417 UpstreamTransport::FlushVvUp send connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csId:{9D619939-CA99-497B-90F1-D667B4D76F05} seqNumber:10 status:0 vvGeneration:5 vvUp:
<Upstream> 20080908 13:21:16.128 2748 SRTR 1880 SERVER_RequestVersionVector Received from connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csId:{9D619939-CA99-497B-90F1-D667B4D76F05} seqNumber:11 changeType:all
<Upstream> 20080908 13:21:16.128 2748 SRTR 1927 SERVER_AsyncPoll Received from connId:{4373FD61-670B-4687-846B-C8D8A71E0044}
<Upstream> 20080908 13:21:16.128 2748 UPST 1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:00201800
<snipped out operations covered in detail in earlier sections>
<Downstream> 20080908 13:21:16.525 2036 MEET 2822 Meet::InstallRename Moving contents from Installing to final destination. Attributes:0x20 updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf ß file has been RDC-reconstructed on the downstream partner
<Downstream> 20080908 13:21:16.525 2036 MEET 1638 Meet::InstallStep Done installing file updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf ß downstream server will now copy the file into replicated folder.
<Downstream> 20080908 13:21:16.525 2036 MEET 1641 Meet::InstallStep Deleting fid in installing updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf
<Downstream> 20080908 13:21:16.525 2036 MEET 1263 Meet::Install -> WAIT Error processing update. updateName:spoolsv.exe uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 connId:{4373FD61-670B-4687-846B-C8D8A71E0044} csName:fsrmrf csId:{9D619939-CA99-497B-90F1-D667B4D76F05} code:5 Error: ß the FSRM datascrn filter driver now blocks the write operation from occurring on the downstream server, as remotely added EXE files are not allowed. The error is unfortunately bubbled as ‘access denied’, but security is not related here at all, it’s just the error returned by the filter driver.
+ [Error:5(0x5) Meet::InstallStep meet.cpp:1657 2036 W Access is denied.]
+ [Error:5(0x5) Meet::InstallRename meet.cpp:2960 2036 W Access is denied.]
+ [Error:5(0x5) NtfsFileSystem::Move ntfsfilesystem.cpp:1188 2036 W Access is denied.]
+ [Error:5(0x5) NtfsFileSystem::Move ntfsfilesystem.cpp:999 2036 W Access is denied.]
+ [Error:5(0x5) FileUtil::RenameByHandle fileutil.cpp:386 2036 W Access is denied.]
+ [Error:5(0x5) FileUtil::RenameByHandle fileutil.cpp:383 2036 W Access is denied.]
<Upstream> 20080908 13:21:16.535 2748 SRTR 1772 SERVER_RdcClose uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v39 csId:{9D619939-CA99-497B-90F1-D667B4D76F05} connId:{4373FD61-670B-4687-846B-C8D8A71E0044}
<Upstream> 20080908 13:21:16.535 2748 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
New KB articles related to Directory Services for the week of 3/28-4/5.
969535
Roaming user profiles are ignored if the network connection to the remote server that stores the roaming user profile is slow
963044
On a computer that runs Windows Vista or Windows Server 2008, after you rename, delete, or move the files in a network share that is hosted on a Windows Vista or Windows Server 2008-based computer, files are still listed in the network share
969060
IIS logging for Windows Integrated authentication
969862
German Version of AGPM translates "State" incorrectly
967696
The memory usage of the Windows Server 2008 Active Directory Certificate Services (Certsrv.exe) may keep increasing when third-party plug-ins are installed and certificate requests are rejected
961981
The tracing option for Group Policy Preferences uses incorrect code in the German version of Windows Server 2008-based systems
955162
A check box in the German edition of Windows Server 2008 was translated incorrectly from the English edition
968733
The SYSVOL share migration from FRS to DFSR fails on Windows Server 2008 R2 Beta-based servers if a disjoint namespace is configured
In this scenario we will see a DFSR server attempt to contact its DC through LDAP to read the current replication topology. LDAP lookups are being blocked by ‘firewall/network/DC down’ so there are no responses.
(ldapblocked - Dfsr00008 - 2008.log)
These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x64FSDC01 in the contoso.com domain. The log is from 2008x86SRV10 where the file is created. The other server is a domain controller. Review scenario “Domain Controller Bind and Configuration Polling on Windows Server 2008”.
<Upstream> 20080908 11:19:23.236 3940 CFAD 2159 [ERROR] Config::AdQuery::Search Failed to ldap_search_ext_s(). Error:Server Down base:CN=2008X86FSRV10,CN=Computers,DC=contoso,DC=com ß domain controller is not responding to an LDAP search request for the sending computer’s own DN
<Upstream> 20080908 11:19:23.236 3940 CFAD 8456 Config::AdConfig::IsConnected Lost connection to AD. Error:
+ [Error:58(0x3a) Config::AdQuery::StartSearch ad.cpp:2261 3940 W The specified server cannot perform the requested operation.] ß it’s important to note that DC connectivity errors will not all be LDAP-only. This error 58 is a WINERROR.H translated to “The specified server cannot perform the requested operation” with err.exe
+ [Error:58(0x3a) Config::AdQuery::StartSearch ad.cpp:2204 3940 W The specified server cannot perform the requested operation.]
+ [Error:58(0x3a) Config::AdQuery::Search ad.cpp:2169 3940 W The specified server cannot perform the requested operation.]
+ [Error:81(0x51) Config::AdQuery::Search ad.cpp:2169 3940 U Server Down] ß the other extended error is actually an LDAP error that will translate with err.exe to LDAP_SERVER_DOWN in WINLDAP.H
<Upstream> 20080908 11:19:42.174 3940 CFAD 317 Config::AdConnection::Connect Binding to dcAddr:\\10.10.0.101 dcDnsName:\\2008x64FDC01.contoso.com ß this is the DC where the LDAP bind is being attempted against. It returns both IP and DNS name.
<Upstream> 20080908 11:19:42.174 3940 CFAD 149 Config::AdConnection::BindToAd Trying to connect. hostName:2008x64FDC01.contoso.com
<Upstream> 20080908 11:20:03.175 3940 CFAD 3021 [ERROR] Config::AdSession::Connect Failed to ldap_connect(). timeout:30 Error:Server Down
<Upstream> 20080908 11:20:03.175 3940 CFAD 179 [ERROR] Config::AdConnection::BindToAd Failed to bind to AD. Error:[Error:58(0x3a) Config::AdSession::Connect ad.cpp:3027 3940 W The specified server cannot perform the requested operation.]
<Upstream> 20080908 11:20:03.175 3940 CFAD 149 Config::AdConnection::BindToAd Trying to connect. hostName:10.10.0.101
<Upstream> 20080908 11:20:24.192 3940 CFAD 3021 [ERROR] Config::AdSession::Connect Failed to ldap_connect(). timeout:30 Error:Server Down
<Upstream> 20080908 11:20:24.192 3940 CFAD 179 [ERROR] Config::AdConnection::BindToAd Failed to bind to AD. Error:[Error:58(0x3a) Config::AdSession::Connect ad.cpp:3027 3940 W The specified server cannot perform the requested operation.]
<Upstream> 20080908 11:20:24.192 3940 SCFG 1888 [WARN] ServiceConfig::DsPollIsDue Failed to enable lightweight polling. Error:
+ [Error:160(0xa0) Config::AdConfig::ConnectToLocalDc ad.cpp:8326 3940 W One or more arguments are not correct.] ß misleading error, the previous LDAP failure caused another operation to return this error
+ [Error:160(0xa0) Config::AdConfig::Connect ad.cpp:8077 3940 W One or more arguments are not correct.]
+ [Error:160(0xa0) Config::AdConnection::Connect adconnection.cpp:365 3940 W One or more arguments are not correct.]
+ [Error:160(0xa0) Config::AdConnection::BindToAd adconnection.cpp:184 3940 W One or more arguments are not correct.]