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

Article
03/31/2009

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

- Ned Pyle

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

Additional resources