Microsoft's official enterprise support blog for AD DS and more
Hi, Ned here again. Mike’s snarky comments notwithstanding, today I am going to talk about how DFSR does and does not replicate file time/date information. I’m also going to give you some advice on examining files to see if they have truly been replicated. Throughout this posting I will be saying ‘file time’, and this also implies ‘file date’.
Let’s get to it.
The Misconceptions
DFSR does not recognize file time changes as a file being modified. Therefore if a file is entirely unchanged in security, in binary contents, or in alternate data streams and has only seen its file time change, the file is not replicated. This is intentional, as we have known third-party applications in the past to only change the time as part of their operations and we did not want to see files get replicated for no reason.
Now this does not mean that DFSR doesn’t replicate time changes. When a file is modified and replicates normally, the downstream copy receives the new file time of the original.
The Proof
So let’s look at this via the DFSR Debug logs (stored as %systemroot%\debug\dfsrxxxxx.log and gz). In this scenario, I used a small internal tool called FILEDATE.EXE to change a files time without otherwise modifying the file.
20080926 14:26:38.403 1524 LDBX 3548 Ldb::Insert Inserting idRecord: <--File created. It had a date of 2003 (it’s the clock.avi in the Windows folder of all computers) + fid 0x3000000002B17 + usn 0x2900f0 + uidVisible 0 + filtered 0 + journalWrapped 0 + slowRecoverCheck 0 + pendingTombstone 0 + recUpdateTime 16010101 00:00:00.000 GMT + present 1 + nameConflict 0 + attributes 0x20 + gvsn {23B2E6F1-67A8-4A63-85D7-9F0F82271203}-v81 + uid {23B2E6F1-67A8-4A63-85D7-9F0F82271203}-v81 <-- UID/GVSN match, this is a new file being added to replication, has never been changed as far as DFSR knows + parent {C7147B8D-CCB9-4EAD-B7BA-36F0D816290F}-v1 + fence 16010101 00:00:00.000 + clock 20080926 18:26:38.403 + createTime 20080926 18:26:38.403 GMT + csId {C7147B8D-CCB9-4EAD-B7BA-36F0D816290F} + hash 00000000-00000000-00000000-00000000 + similarity 00000000-00000000-00000000-00000000 + name clock.avi <-- The file
20080926 14:26:38.418 1524 USNC 2448 UsnConsumer::CreateNewRecord ID record created from USN_RECORD: + USN_RECORD: + RecordLength: 80 + MajorVersion: 2 + MinorVersion: 0 + FileRefNumber: 0x3000000002b17 + ParentFileRefNumber: 0x2000000002360 + USN: 0x2900f0 + TimeStamp: 20080926 14:26:38.403 Eastern Standard Time + Reason: Basic Info Change Close Data Extend Data Overwrite File Create <-- USN update for file being created is written to DFSR DB + SourceInfo: 0x0 + SecurityId: 0x69b + FileAttributes: 0x20 + FileNameLength: 18 + FileNameOffset: 60 + FileName: clock.avi <-- The file
<snipped out boring goo>
20080926 14:26:38.840 2256 OUTC 1056 OutConnection::OpenFile Sent file uid:{23B2E6F1-67A8-4A63-85D7-9F0F82271203}-v81 gvsn:{23B2E6F1-67A8-4A63-85D7-9F0F82271203}-v81 name:clock.avi fileSize:83348 connId:{29AAE012-2D36-4C4C-BCDD-83CCCE2CCDAC} rgName:0byterepro <-- file is replicated out.
<snipped out more boring goo>
20080926 14:27:33.967 1524 LDBX 3665 Ldb::Update Updating idRecord: <-- DFSR DB updated because file has had a USN update + fid 0x3000000002B17 + usn 0x290c40 + uidVisible 1 + filtered 0 + journalWrapped 0 + slowRecoverCheck 0 + pendingTombstone 0 + recUpdateTime 20080926 18:26:38.575 GMT + present 1 + nameConflict 0 + attributes 0x20 + gvsn {23B2E6F1-67A8-4A63-85D7-9F0F82271203}-v81 + uid {23B2E6F1-67A8-4A63-85D7-9F0F82271203}-v81 <-- Note that UID/GVSN unchanged; DFSR does not consider the file to have been modified + parent {C7147B8D-CCB9-4EAD-B7BA-36F0D816290F}-v1 + fence 16010101 00:00:00.000 + clock 20080926 18:26:38.403 + createTime 20080926 18:26:38.387 GMT + csId {C7147B8D-CCB9-4EAD-B7BA-36F0D816290F} + hash 8D69D492-ABA86376-1671B762-8994DE65 + similarity 2B3E1B27-39113214-39173F1F-3D363D08 + name clock.avi
20080926 14:27:33.967 1524 USNC 1879 UsnConsumer::UpdateUsnOnly USN-only update from USN_RECORD: <-- there was a Basic Info change that only affected USN and not the files contents or security + USN_RECORD: + RecordLength: 80 + MajorVersion: 2 + MinorVersion: 0 + FileRefNumber: 0x3000000002b17 + ParentFileRefNumber: 0x2000000002360 + USN: 0x290c40 + TimeStamp: 20080926 14:27:33.952 Eastern Standard Time + Reason: Basic Info Change Close <-- This is date/time being changed to ‘right now’ when I ran FILEDATE.EXE against clock.avi + SourceInfo: 0x0 + SecurityId: 0x69b + FileAttributes: 0x20 + FileNameLength: 18 + FileNameOffset: 60 + FileName: clock.avi
On the downstream server you see… nothing. The GVSN is not updated so DFSR does not believe the file has been modified in a way that requires replication.
How to tell if files are replicating due to modification the right way
Ok, so now you’re probably asking me what is the best way to tell if a file has been modified via replication, since looking at the file time is clearly not reliable. Sometimes people try using byte count, but that is just as bad – if I take a 100KB TXT file and change one character inside it from an A to a Z, how will that affect the byte count? It won’t…
Some better ways would be:
Get comfortable with the DFSR debug logs and examine them. Here is a downstream server that is adding a file it just replicated in to its local Replicated Folder:
20080625 17:42:30.956 2416 MEET 2190 Meet::InstallRename File moved. rootVolume:{05853FA6-411C-11DD-A156-806E6F6E6963} parentFid:0x1000000002F8C fidInInstalling:0x4000000002FCC usn:0x70850 updateName:setuplog.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v16 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v21 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 <-- the updated file ‘setuplog.txt’ is moved in.
<Downstream> 20080625 17:42:30.956 2416 LDBX 3684 Ldb::Update Updating idRecord: <-- the DFSR jet database is updated to reflect that the updated version of the file is now in the content set. + fid 0x4000000002FCC + usn 0x70850 + uidVisible 1 + filtered 0 + journalWrapped 0 + slowRecoverCheck 0 + pendingTombstone 0 + recUpdateTime 16010101 00:00:00.000 GMT + present 1 <-- the file exists in the content set. + nameConflict 0 + attributes 0x20 + gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v21 <-- GVSN now matches the originating server information + uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v16 + parent {5666BB91-265D-42E8-9F57-1B49F4E581B7}-v1 + fence 16010101 00:00:00.000 + clock 20080625 21:42:30.805 + createTime 20080625 21:27:21.734 GMT + csId {5666BB91-265D-42E8-9F57-1B49F4E581B7} + hash 32B91C5A-74967572-4ABBC3A8-C319BB64 + similarity 3F193518-2F152E2B-36262037-05111237 + name setuplog.txt
Enable DFSR File auditing
1. Create the following registry *key* (not value): HKLM\SYSTEM\CurrentControlSet\Services\Dfsr\Parameters\Enable Audit
(Note – there is a space between ‘Enable’ and ‘Audit’)
2. Enable Object Access Auditing for these servers (via local or domain-based group policy) for SUCCESS. 3. Refresh policy with GPUPDATE /FORCE (there should be no need to restart DFSR or the servers) 4. Replicate a new file from upstream to downstream partner. 5. In Event Viewer | Security Events on the upstream partner, you will see:
Event Type: Success Audit Event Source: DFSR Event Category: (3) Event ID: 7002 Date: 2/16/2006 Time: 10:33:50 AM User: NT AUTHORITY\SYSTEM Computer: M3 Description: The DFS Replication service served the following file:
Additional Information: Replicated Folder Root: C:\Sales Replicated Folder Name: Sales Replicated Folder ID: 3B38DDC2-FFBF-428C-9853-71D2D2D65351 File Name: test.txt File ID: {B4738E50-CED1-4DA0-94CF-0E21345F98F6}-v2328331 File Parent ID: {3B38DDC2-FFBF-428C-9853-71D2D2D65351}-v1 Partner name: M1.contoso.com
6. In Event Viewer | Security Events on the downstream partner, you will see:
Event Type: Success Audit Event Source: DFSR Event Category: (3) Event ID: 7004 Date: 2/16/2006 Time: 10:33:50 AM User: NT AUTHORITY\SYSTEM Computer: M1 Description: The DFS Replication service received the following file:
Additional Information: Replicated Folder Root: C:\Sales Replicated Folder Name: Sales Replicated Folder ID: 3B38DDC2-FFBF-428C-9853-71D2D2D65351 File Name: test.txt File ID: {B4738E50-CED1-4DA0-94CF-0E21345F98F6}-v2328331 File Parent ID: {3B38DDC2-FFBF-428C-9853-71D2D2D65351}-v1 Partner name: M3.contoso.com
Use LOGPARSER to give you a checksum comparison
1. Download Logparser Goodness. 2. Calculate the MD5 hash from each copy of the file, for example:
C:\Program Files (x86)\Log Parser 2.2>LogParser.exe "SELECT Path, HASHMD5_FILE(Path) FROM \\server1\rf\goo.txt" -i:FS -recurse:0
Path HASHMD5_FILE(Path) ----------------------- -------------------------------- \\server1\rf\goo.txt 76EC538F73B542A2BEFA18A88717054B
C:\Program Files (x86)\Log Parser 2.2>LogParser.exe "SELECT Path, HASHMD5_FILE(Path) FROM \\server2\rf\goo.txt" -i:FS -recurse:0
Path HASHMD5_FILE(Path) ----------------------- -------------------------------- \\server2\rf\goo.txt BBD8E74F23D7605CB0CDB57A1B25D826
Here I can see that the files are not the same, because the file changed on one and not yet replicated. If they were the same I’d know the files are in sync. Note that this checksum just shows the binary data portions of the file hash. DFSR also calculates metadata such as security ACL's, so a file could be different in more ways than just its contents.
Notes
If you want to understand a bit more about the underlying architecture of NTFS file times (or you just crave a cure for your chronic insomnia), be sure to check out:
Description of NTFS date and time stamps for files and folders
Change Journal Records
File Times
FILETIME Structure
If we don’t chat again, Merry Christmas and a Happy New Year. :-)
- Ned Pyle
PingBack from http://www.ditii.com/2008/12/18/understanding-file-datetime-behavior-in-dfsr-replication/
HI Ned let me just start off by saying that all of your articles have been a real big help in learning about the innter workings of DFS. Do you know if there is an MS Press or other book dealing solely with DFS setup, maintenance, troubleshooting etc.
This article was great in explaining the DFS debug log as it can be a little cryptic. I was hoping you might be able to shed some light on an issue I am seeing. I have yet to be able to find any other info on this online so hopefully you can help.
The other day our hub server used to collect data basically just stopped getting DFS data. Everything in the health check says it is fine but the data stopped replicating and is stuck in the middle of initial replication. The data size has not increased since that day.
I took a look in the debug log and found the following entries on the sending memeber which appear troublesome to me.
20081230 01:18:42.859 2804 DOWN 3671 [ERROR] DownstreamTransport::EstablishSession Failed on connId:{6C9858E7-3728-4439-A51F-6A41DB207805} csId:{C59F70A0-3000-4520-B499-FB400C273CE2} Error:
+ [Error:9027(0x2343) DownstreamTransport::EstablishSession downstreamtransport.cpp:3664 2804 C784 A failure was reported by the remote partner]
+ [Error:9051(0x235b) DownstreamTransport::EstablishSession downstreamtransport.cpp:3664 2804 C783 The content set is not ready]
20081230 01:18:42.859 2804 INCO 2588 InConnection::RestartSession Retrying establish contentset session. connId:{6C9858E7-3728-4439-A51F-6A41DB207805} csId:{C59F70A0-3000-4520-B499-FB400C273CE2} csName:Mandarin_Shared
20081230 01:18:42.859 2804 INCO 563 [WARN] SessionTask::Step (Ignored) Failed, should have already been processed. Error:
As I said I have not been able to find anything online about these messages so Im hoping you can help shed some light on this or at least point me in the right direction.
Thanks
Hi,
Thanks. :) There's no book that I know of, but I have written a 200-page whitepaper on DFSR troubleshooting via the debug logs that I plan on releasing through this blog someday (at least as a series of articles). It's in review currently. Maybe that will meet your needs?
I have seen that a few times in the past when something has happened during initial sync (not sure what - we've not been able to easily reproduce the issue here), and the new content set has lost track of who the Primary server is. To fix this, you can:
1. Make sure you have good backups of the data everywhere.
2. Reset the IsPrimary flag to true on the server you want to be the initial sync master with:
Dfsradmin Membership Set /RGName:<replication group name> /RFName:<replicated folder name> /MemName:<member you want to be primary> /IsPrimary:True
For example, assume you want NA-DC-01 to be primary for the replicated folder DATA in the replication group RG1:
Dfsradmin Membership Set /RGName:RG1 /RFName:DATA /MemName:NA-DC-01 /IsPrimary:True
Run "Dfsrdiag Pollad" against all the members to force them to pick up this change as soon as possible. You can run "Dfsrdiag Pollad /Member:<member name>" to force a poll on a remote member.
- Ned
Thanks for the quick response. The book is definitely somethign i will be looking for. In the meantime I have your blog bookmarked.... lots of good DFS info here.
As far as the issue occurring during the initial sync I am not sure if that is the true problem. When the replication originally failed we removed the replication group. Deleted the data on the second server and then recreated the replication group with a completely different name.
As far as im thinking this should make DFS think that it is a completely new replication group with the correct primary server designated. I let it run overnight and came in the next day but we were still receiving these same error messages.
Could this possibly be caused by some type of error with the receiving member of the DFS replication group. One thing I noticed is that the event log on the receiving member doesnt have the event descriptions available but rather
"The description for Event ID ( 5004 ) in Source ( DFSR ) cannot be found. The local computer may not have the necessary registry information or message DLL files to display messages from a remote computer"
The only way that I can think of to resolve this would be to uninstall DFS reboot and then reinstall from add/remove windows components. The only fear that I have doing this is that it may break the replication groups. Do you have any experience on wether removing, rebooting, reinstalling DFS will cause any undesired side effects?
Mmph. You're right, if you recreated the RG, you;ve already done the IsPrimary step (and much much more).
The event's not being found does make the entire DFSR server component very suspect. If you uninstall DFSR from this server it will no longer be participating in DFSR, but the topology itself will remain because that is stored in AD.
This is wacky enough though I would recommend opening a support case with us rather than me winging it in a blog comment. It would be useful for our engineers to look through all the data and see what exactly is going on here.
Hi Ned
Logparser is definitely good. But I prefer fciv.exe (http://support.microsoft.com/kb/841290) for calculating md5 hash.
Somehow the following seems far simpler to me :D
fciv.exe \\server1\rf\goo.txt
Cheers
M "I have no middlename" W