Understanding File Date/Time behavior in DFSR Replication (and better ways of knowing that a file has replicated)

Understanding File Date/Time behavior in DFSR Replication (and better ways of knowing that a file has replicated)

  • Comments 6
  • Likes

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:

    + [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]

    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