Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)

Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)

  • Comments 1
  • Likes

In this scenario we will see a Microsoft Word 2007 file modified and how that change is replicated between servers. This is useful to understand in order to troubleshoot issues where problems within the USN journal, the DFSR JET database, the staging folder structure, and the network (including RPC) are preventing replication from working correctly.   This also covers a practice often used by MS Office and other applications that use transitional and temporary files in the main file’s working directory.

 

(word2007modifiedupstream - Dfsr00018 - 2008.log and word2007modifieddownstream - Dfsr00015 - 2008.log)

 

These are two Windows Server 2008 servers called 2008MEM01 and 2008MEM02 in the fabrikam.com domain. The logs are from 2008MEM01 where the file is modified (upstream) and from 2008MEM02 where it is replicated (downstream). Both servers are participating in the TESTRG3 replication group for the TESTRF3 replicated folder. The file is called “modifiedword2007.docx”. The file was already replicated previously.

 

<Upstream> 20080626 13:46:11.290 4040 USNC  1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ßA temporary working file is created upstream, which is related to the real file the user just opened. The file is filtered because it has temporary attribute set as well as starts with a tilde (which is filtered by default)

+       USN_RECORD:

+       RecordLength:        104

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x300000000AC68 ß note file ID for later, since a number of files will be created/renamed/overwritten in the Word 2007 processing

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a270

+       TimeStamp:           20080626 13:46:11.290 Eastern Standard Time

+       Reason:              Close Data Extend File Create ß file created

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x22 ß hidden bit set on a file

+       FileNameLength:      42

+       FileNameOffset:      60

+       FileName:            ~$difiedword2007.docx ß temporary working file name for autorecovery

+      

<Upstream> 20080626 13:46:38.485 4040 USNC  1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß27 seconds later another pseudo-temporary file is created (not truly temporary but has a TMP extension that will be filtered by default by DFSR)

+       USN_RECORD:

+       RecordLength:        88

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x100000000AC69 ß different File ID so we know it’s a different file

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a438

+       TimeStamp:           20080626 13:46:38.485 Eastern Standard Time

+       Reason:              Basic Info Change Close Data Extend Data Overwrite File Create ß created and wrote data

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20 ß not truly temporary

+       FileNameLength:      24

+       FileNameOffset:      60

+       FileName:            4ED0A5C5.tmp ß temporary working file name

+      

<Upstream> 20080626 13:46:38.485 4040 USNC  1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:

+       USN_RECORD:

+       RecordLength:        88

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x100000000AC69 ß same file as above

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a4e8

+       TimeStamp:           20080626 13:46:38.485 Eastern Standard Time

+       Reason:              Close Security Change ß security change on the file

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20

+       FileNameLength:      24

+       FileNameOffset:      60

+       FileName:            4ED0A5C5.tmp ß same file name as above (and it’s the same real file as File ID matches)

+      

<Upstream> 20080626 13:46:38.505 4040 USNC  2612 UsnConsumer::CreateNewRecord LDB Inserting ID Record: ß this file is created ‘new’. However this is actually a rename of the ‘4ED0A5C5.tmp’ file. Because this was previously filtered, it was not counted as a creation so the UID and GVSN will reflect a new file below.

+       fid                             0x100000000AC69 ßnote File ID matches the tmp file above

+       usn                             0xa5a7c8

+       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 ß now live in the replicated folder

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 ß GVSN and UID match, so this is considered a new file (again, even though not truly new, previous version was filtered out)

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.505 GMT (0x1c8d7b495a970e4)

+       createTime                      20080626 17:46:38.505 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            modifiedword2007.docx ß Note the name is the original file name now.

+      

<Upstream> 20080626 13:46:38.555 4040 USNC  2615 UsnConsumer::CreateNewRecord ID record created from USN_RECORD:

+       USN_RECORD:

+       RecordLength:        104

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x100000000AC69 ß note file ID same as the previous tmp file

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a7c8

+       TimeStamp:           20080626 13:46:38.505 Eastern Standard Time

+       Reason:              Basic Info Change Close Object ID Change Rename New Name Security Change ß the 4ED0A5C5.tmp file is renamed to modifiedword2007.docx, and other data is changed in the file

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20

+       FileNameLength:      42

+       FileNameOffset:      60

+       FileName:            modifiedword2007.docx

+      

<Upstream> 20080626 13:46:38.555 4040 USNC  2361 UsnConsumer::UpdateIdRecord LDB Updating ID Record: ß the file is being closed after modification.

+       fid                             0x100000000AC69

+       usn                             0xa5a898

+       uidVisible                      0

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080626 17:46:38.505 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 ßVersion incremented due to modification.

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:46:38.505 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            modifiedword2007.docx

+      

<Upstream> 20080626 13:46:38.555 4040 USNC  2364 UsnConsumer::UpdateIdRecord ID record updated from USN_RECORD:

+       USN_RECORD:

+       RecordLength:        104

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x100000000AC69

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a898

+       TimeStamp:           20080626 13:46:38.515 Eastern Standard Time

+       Reason:              Close Security Change

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20

+       FileNameLength:      42

+       FileNameOffset:      60

+       FileName:            modifiedword2007.docx

+      

<Upstream> 20080626 13:46:38.555 4040 USNC  2777 UsnConsumer::TombstoneOrDelete LDB Updating ID Record: ß the original copy of the file is being deleted as it gets overwritten by the copy of the file upstream (this is still Word’s internal behavior, we have not yet done any replication obviously)

+       fid                             0x300000000AC66 ß the file ID is different because this was the older file

+       usn                             0xa5a900

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080626 17:34:11.530 GMT

+       present                         0 ß no longer in the replicated folder

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 ß Deletion still counts as a version increase

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 ß note the old UID

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            22894EE1-C5DBE0DE-F63EF65F-B42162E4

+       similarity                      3622212A-1A3A3706-23381636-00212E2E

+       name                            modifiedword2007.docx

+      

<Upstream> 20080626 13:46:38.555 4040 USNC  2782 UsnConsumer::TombstoneOrDelete ID record tombstoned from USN_RECORD: ß USN journal updated to reflect the ‘deletion’ of the original word file, as it is now filtered.

+       USN_RECORD:

+       RecordLength:        88

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x300000000AC66 ß old file ID

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a900

+       TimeStamp:           20080626 13:46:38.515 Eastern Standard Time

+       Reason:              Close Object ID Change Rename New Name ß note how Word is renaming the file again prior to deletion.

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20

+       FileNameLength:      24

+       FileNameOffset:      60

+       FileName:            52E1E902.tmp

+      

<Upstream> 20080626 13:46:38.555 4040 USNC  1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß the original word file is now finally truly deleted

+       USN_RECORD:

+       RecordLength:        88

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x300000000AC66

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a958

+       TimeStamp:           20080626 13:46:38.515 Eastern Standard Time

+       Reason:              Close File Delete ß delete flag

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20

+       FileNameLength:      24

+       FileNameOffset:      60

+       FileName:            52E1E902.tmp

+      

<Upstream> 20080626 13:46:38.595 4040 USNC  1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß the temporary working file is now deleted as well.

+       USN_RECORD:

+       RecordLength:        104

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x300000000AC68

+       ParentFileRefNumber: 0xF00000000A781

+       USN:                 0xa5a9b0

+       TimeStamp:           20080626 13:46:38.585 Eastern Standard Time

+       Reason:              Close File Delete ß deleted flag

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x22

+       FileNameLength:      42

+       FileNameOffset:      60

+       FileName:            ~$difiedword2007.docx

+

<Downstream> 20080626 13:46:38.637 4036 INCO  3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00B4D7A8 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all ß downstream requests outstanding changes

<Downstream> 20080626 13:46:38.637 3980 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00BCA1B0

<Upstream> 20080626 13:46:38.935 2284 SRTR  1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:4 changeType:all

<Upstream> 20080626 13:46:38.935 2284 SRTR  1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} ß upstream receives the version vector request

<Upstream> 20080626 13:46:38.945 3132 SRTR   882 SERVER_RequestUpdates Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} credits:32 requestType:all

<Upstream> 20080626 13:46:38.945 3132 SRTR  1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}

<Upstream> 20080626 13:46:38.945 2072 JOIN  1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 name:modifiedword2007.docx connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß information about the update is sent to downstream server

<Upstream> 20080626 13:46:38.945 2072 JOIN  1122 Join::SubmitUpdate LDB Updating ID Record: ß upstream sends change info

+       fid                             0x100000000AC69

+       usn                             0xa5a898

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080626 17:46:38.555 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 ß note the GVSN matches the final copy of file that was modified upstream

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 ß note UID as well

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            modifiedword2007.docx ß the file

+      

<Upstream> 20080626 13:46:38.945 2072 JOIN  1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 name:modifiedword2007.docx connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß update info was sent successfully

<Upstream> 20080626 13:46:38.955 2284 SRTR  1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:5 changeType:notify

<Downstream> 20080626 13:46:38.957 3980 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00B4D7A8

<Downstream> 20080626 13:46:38.957 3980 INCO  3959 InConnection::ReceiveVvUp Received VvUp connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvUp:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..81} ß the VV update

+      

<Downstream> 20080626 13:46:38.957 3980 INCO  3966 InConnection::ReceiveVvUp Creating new session:2 requestState:00B4D7A8 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..78}

+      

<Downstream> 20080626 13:46:38.957 4036 INCO  4619 InConnection::RequestUpdates Requesting updates. credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 79..81}

+      

<Downstream> 20080626 13:46:38.957 3980 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00BCA1B0

<Downstream> 20080626 13:46:38.967 3980 INCO  4803 InConnection::ReceiveUpdates Upstream credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 creditsUsed:2 creditsAvailable:32

<Downstream> 20080626 13:46:38.967 3980 INCO  4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 fileName:modifiedword2007.docx session:2 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3

<Downstream> 20080626 13:46:38.967 3980 INCO  4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 fileName:modifiedword2007.docx session:2 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß note how DFSR is trying to replicate two versions of the original file, with two separate UID’s. This is due to how Word 2007 makes copies of the files and overwrites them, leading to two distinct replication change packages being done. One is a delete and one is a replicate.

<Downstream> 20080626 13:46:38.967 3980 INCO  4932 InConnection::ReceiveUpdates Session has been closed. sessionId:2 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3

<Downstream> 20080626 13:46:38.967 3980 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:UpdateRequest reqState:Completed status:0 ptr:00B4D8A0

<Downstream> 20080626 13:46:38.967 4036 MEET  1207 Meet::Install Retries:0 updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 updateType:remote

<Downstream> 20080626 13:46:38.967 2928 MEET  1207 Meet::Install Retries:0 updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 updateType:remote

<Downstream> 20080626 13:46:38.967 2880 INCO  3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00B53398 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:notify

<Downstream> 20080626 13:46:38.977 3980 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00B53398

<Downstream> 20080626 13:46:38.987 4036 MEET  4867 Meet::MoveOut Moving contents and children out of replica. newName:modifiedword2007-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v77.docx updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 record: ß Original version of the file that was previous replicated is deleted, because the original one was truly deleted upstream (not modified – Word 2007 does not truly modify files). A moveout is a delete in DFSR.

+       fid                             0x100000000A766

+       usn                             0x929d88

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               1

+       meetReanimated                  0

+       recUpdateTime                   20080626 17:34:12.343 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v77 ß previous version of the file

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 ß different UID than our new file we just ‘modified’

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:34:11.530 GMT (0x1c8d7b2d86e2ef4)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            22894EE1-C5DBE0DE-F63EF65F-B42162E4

+       similarity                      3622212A-1A3A3706-23381636-00212E2E

+       name                            modifiedword2007.docx

+      

<Upstream> 20080626 13:46:38.996 4032 OUTC   784 OutConnection::OpenFile Received request for update: ß file is being served upstream

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 ß this is our new version of the file

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            modifiedword2007.docx ß same file name

+       rdcDesired:1 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3

<Upstream> 20080626 13:46:38.996 4032 MRSH  4615 Marshaller::Marshal FileAttrs in metadata : 0x20

<Downstream> 20080626 13:46:38.997 4036 MEET  6746 Meet::UpdateIdRecord LDB Updating ID Record:

+       fid                             0x100000000A766 ß previous file’s FID

+       usn                             0x92d188

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   16010101 00:00:00.000 GMT

+       present                         0 ß the previous file is being deleted.

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 ß UID is for the older file

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            22894EE1-C5DBE0DE-F63EF65F-B42162E4

+       similarity                      3622212A-1A3A3706-23381636-00212E2E

+       name                            modifiedword2007.docx

+      

<Downstream> 20080626 13:46:38.997 4036 MEET  4794 Meet::InstallTombstone -> DONE Install Tombstone complete updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß The file is tombstoned in the database. This means that a reference to the file remains for 30 days in the DFSR DB downstream but the actual file has now been removed.

<Downstream> 20080626 13:46:38.997 4036 INCO  5897 InConnection::UpdateProcessed Received Update. updatesLeft:1 processed:1 failures:0 sessionId:2 open:0 updateType:0 processStatus:0 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 update: ß the update (which was a delete) has been processed

+       present                         0

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v81

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v76

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            22894EE1-C5DBE0DE-F63EF65F-B42162E4

+       similarity                      3622212A-1A3A3706-23381636-00212E2E

+       name                            modifiedword2007.docx

+      

<Downstream> 20080626 13:46:38.997 4036 UPMG   418 UpdateWorker::ConsumeUpdates No pending updates. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}

<Upstream> 20080626 13:46:39.106 4032 CSMG  4844 ContentSetManager::UpdateHash LDB Updating ID Record: ß the database is updated to reflect the file hash of the later version of the file. Apparently the file has changed somewhat as we have a new hash.

+       fid                             0x100000000AC69

+       usn                             0xa5a898

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080626 17:46:38.555 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            5FE417F1-498E8A23-73693A0F-6D8FA626 ß note how hash differs from previous

+       similarity                      3622212A-1A2D3706-23381636-00212E2E

+       name                            modifiedword2007.docx

+      

<Upstream> 20080626 13:46:39.276 4032 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Upstream> 20080626 13:46:39.276 4032 STAG   799 StageWriter::CompleteDownloadStage Completed download or stage file 80-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80-Downloaded.frx ß the v80 version of the file is staged upstream

<Upstream> 20080626 13:46:39.276 4032 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Upstream> 20080626 13:46:39.276 4032 OUTC  1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 name:modifiedword2007.docx fileSize:397852 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3 ß the v80 version of the file is now being served from upstream

<Upstream> 20080626 13:46:39.276 4032 SRTR  2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rdc:1 context:00E69008,00EBAD08,00000000 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 ptr:00DF62C8

<Downstream> 20080626 13:46:39.378 2928 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Downstream> 20080626 13:46:39.378 2928 STAG   987 StageWriter::AbortDownloadStage Successfully aborted staging file 1-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v1-Downloading.frx. Deleted. ß downstream, the previously staged copy of the file (v79) must be deleted as it is being superceded by the quickly-sent next version of v80.

<Downstream> 20080626 13:46:39.378 2928 RDCX  1590 [WARN] Rdc::SeedFile::UseRelated (Ignored) Failed. uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 fileName:modifiedword2007.docx csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} (related: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v1 fileName:modifiedword2007.docx csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}) Error:[Error:9024(0x2340) Rdc::SeedFile::UseRelated rdc.cpp:1499 2928 C The file meta data is not synchronized with the file system] ß The RDC signature calculation process must be stopped while it was working on the previously staged file. The message about ‘meta data not synched’ refers to this as well.

<Downstream> 20080626 13:46:39.378 2928 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Downstream> 20080626 13:46:39.378 2928 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Downstream> 20080626 13:46:39.378 2928 STAG   987 StageWriter::AbortDownloadStage Successfully aborted staging file 1-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v1-Downloading.frx. Deleted. ß the previously staged file has been removed from downstream staging directory.

<Downstream> 20080626 13:46:39.378 2928 RDCX  1590 [WARN] Rdc::SeedFile::UseRelated (Ignored) Failed. uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 fileName:modifiedword2007.docx csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} (related: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v1 fileName:modifiedword2007.docx csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}) Error:[Error:9024(0x2340) Rdc::SeedFile::UseRelated rdc.cpp:1499 2928 C The file meta data is not synchronized with the file system]

<Downstream> 20080626 13:46:39.378 2928 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Upstream> 20080626 13:46:40.027 2284 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Downstream> 20080626 13:46:40.039 2928 INCO  5610 InConnection::LogTransferActivity Received RAWGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 fileName:modifiedword2007.docx connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} stagedSize:397852 ß the replication of the newer version of file is complete. Note the RAWGET which shows RDC could not be used in this scenario.

<Downstream> 20080626 13:46:40.089 2928 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Downstream> 20080626 13:46:40.089 2928 STAG   799 StageWriter::CompleteDownloadStage Completed download or stage file 80-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80-Downloaded.frx

<Downstream> 20080626 13:46:40.089 2928 MRSH  3959 MarshalContext::Initialize Create file:[modifiedword2007-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80.docx] with attributes:0x20 ß the latest version is successfully staged downstream.

<Downstream> 20080626 13:46:40.089 2928 MEET  2585 Meet::TransferToInstalling Transferring content from staging area into Installing updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the file is decompressed from staging into the Installing directory.

<Upstream> 20080626 13:46:40.187 2072 INCO  3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00DFB6B8 connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all

<Upstream> 20080626 13:46:40.187 4032 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00E6C5B8

<Downstream> 20080626 13:46:40.189 2928 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Downstream> 20080626 13:46:40.189 2928 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Downstream> 20080626 13:46:40.189 2928 MEET  2032 Meet::Download Download Succeeded : true updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß The downstream server considers the file to be fully replicated over and staged and decompressed.

<Downstream> 20080626 13:46:40.189 2928 MEET  2837 Meet::InstallRename File moved. rootVolume:{3EA8BD01-416E-11DD-A317-806E6F6E6963} parentFid:0xC00000000A514 fidInInstalling:0x100000000A76A usn:0x92ee98 updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the file is then written into the actual replicated folder on the downstream server, overwriting any existing

<Downstream> 20080626 13:46:40.189 2928 MEET  6759 Meet::InsertIdRecord LDB Inserting ID Record: ß DFSR database updated downstream with info about the file.

+       fid                             0x100000000A76A

+       usn                             0x92ee98

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               1 ß the file exists due to inbound replication

+       meetReanimated                  0

+       recUpdateTime                   16010101 00:00:00.000 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80

+       uid                             {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79

+       parent                          {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080626 17:46:38.515 GMT (0x1c8d7b495aaf803)

+       createTime                      20080626 17:30:25.894 GMT

+       csId                            {BDD12194-91A1-4227-AB6B-9C252C6EACB8}

+       hash                            5FE417F1-498E8A23-73693A0F-6D8FA626

+       similarity                      3622212A-1A2D3706-23381636-00212E2E

+       name                            modifiedword2007.docx

+      

<Downstream> 20080626 13:46:40.189 2928 MEET  2949 Meet::InstallRename -> DONE Install-rename completed updateName:modifiedword2007.docx uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v79 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v80 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß the file is now in the replicated folder and the operation is complete

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))

-          Ned Pyle