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

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%debugdfsrxxxxx.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 recordcreated 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):
    HKLMSYSTEMCurrentControlSetServicesDfsrParametersEnable 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 AuditEvent Source: DFSREvent Category: (3)Event ID: 7002Date: 2/16/2006Time: 10:33:50 AMUser: NT AUTHORITYSYSTEMComputer: M3Description:The DFS Replication service served the following file: Additional Information:Replicated Folder Root: C:SalesReplicated Folder Name: SalesReplicated Folder ID: 3B38DDC2-FFBF-428C-9853-71D2D2D65351File Name: test.txtFile ID: {B4738E50-CED1-4DA0-94CF-0E21345F98F6}-v2328331File Parent ID: {3B38DDC2-FFBF-428C-9853-71D2D2D65351}-v1Partner name: M1.contoso.com

6.    In Event Viewer | Security Events on the downstream partner, you will see:

Event Type: Success AuditEvent Source: DFSREvent Category: (3)Event ID: 7004Date: 2/16/2006Time: 10:33:50 AMUser: NT AUTHORITYSYSTEMComputer: M1Description:The DFS Replication service received the following file: Additional Information:Replicated Folder Root: C:SalesReplicated Folder Name: SalesReplicated Folder ID: 3B38DDC2-FFBF-428C-9853-71D2D2D65351File Name: test.txtFile ID: {B4738E50-CED1-4DA0-94CF-0E21345F98F6}-v2328331File Parent ID: {3B38DDC2-FFBF-428C-9853-71D2D2D65351}-v1Partner 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 \server1rfgoo.txt" -i:FS -recurse:0

Path                    HASHMD5_FILE(Path)
----------------------- --------------------------------
\server1rfgoo.txt    76EC538F73B542A2BEFA18A88717054B

C:Program Files (x86)Log Parser 2.2>LogParser.exe "SELECT Path, HASHMD5_FILE(Path) FROM \server2rfgoo.txt" -i:FS -recurse:0

Path                    HASHMD5_FILE(Path)
----------------------- --------------------------------
\server2rfgoo.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