Compartilhar via

Understanding DFSR debug logging (Part 6: Microsoft Office Word 97-2003 File Modified on Windows Server 2008)

  • Artigo

In this scenario we will see a Microsoft Word 2003 file modified using MS Word 2003 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 to a lesser extent other) applications that use transitional and temporary files in the main file's working directory. Note that other Office file types like Excel, PowerPoint, etc. may behave differently.

(word2003modifyupstream - Dfsr00015 - 2008.log and word2003modifydownstream - Dfsr00012 - 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 "word2003large.doc". The file was already replicated previously.

<Upstream> 20080626 11:32:31.284 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß the real file "word2003large.doc" was opened and Word automatically creates a temporary working file. Because it is both temporary and covered by the $ default filter in DFSR it will not be a candidate for replication.
+ USN_RECORD:
+ RecordLength: 96
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x100000000AC61
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2e688
+ TimeStamp: 20080626 11:32:31.274 Eastern Standard Time
+ Reason: Close Data Extend File Create ß file created new
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x22 ß 0x20+0x2 means hidden file, per GetFileAttributes function.
+ FileNameLength: 34
+ FileNameOffset: 60
+ FileName: ~$rd2003large.doc ß name of file
+
<Upstream> 20080626 11:33:51.191 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß Word creates a pseudo-temporary file
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x100000000AC66
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2f108
+ TimeStamp: 20080626 11:33:51.181 Eastern Standard Time
+ Reason: Close Data Extend Data Overwrite File Create ß file created new with data added
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20 ß not temporary
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRD0002.tmp ß marked with tilde (~) and TMP extension so still filtered out by DFSR by default
+
<Upstream> 20080626 11:33:51.191 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß Word deletes the temporary file (pretty much instantly)
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x100000000AC66 ß same file ID as above. Important to watch FID's with apps that create lots of temporary and pseudo-temporary working files, as the UID/GVSN will not be created most of the time because the file is excluded from replication.
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2f160
+ TimeStamp: 20080626 11:33:51.181 Eastern Standard Time
+ Reason: Close File Delete ß deleted
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRD0002.tmp ß same file as above
+
<Upstream> 20080626 11:33:51.861 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD: ß Word does this again with yet another pseudo-temporary file
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x200000000AC66 ß remember to watch FID's with unreplicated files; there's no guarantee that there won't be lots of files with the same name present in the replicated folder, especially as we can see that Word is not attempting to randomize the name.
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2f9d0
+ TimeStamp: 20080626 11:33:51.861 Eastern Standard Time
+ Reason: Close Data Extend Data Overwrite File Create ß created, added some data
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20 ß not temporary
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRD0003.tmp
+
<Upstream> 20080626 11:33:51.982 3128 USNC 1995 UsnConsumer::UpdateUsnOnly LDB Updating ID Record: ß the real document has an entry added in DFSR database due to USN update (next full line)
+ fid 0x70000000000B9 ß note for later in log entries that do not include UID/GVSN
+ usn 0xa2fb88
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080626 15:30:22.932 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 ß original file has not yet been modified (UID and GVSN match); this is because Word will use the temporary working file for most of its transactions in order to provide 'auto recover document' functionality
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:30:22.932 GMT (0x1c8d7a18ca3f2b2)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 4992549E-7564D836-ED346C90-D5FD88B3
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc ß the file
+
<Upstream> 20080626 11:33:51.982 3128 USNC 1997 UsnConsumer::UpdateUsnOnly USN-only update from USN_RECORD: ß a USN only update means the file is not actually modified in a way that will trigger any form of replication (including metadata)
+ USN_RECORD:
+ RecordLength: 96
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x70000000000B9 ß same file as above
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2fb88
+ TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
+ Reason: Close Object ID Change ß the file is closed without being modified
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 34
+ FileNameOffset: 60
+ FileName: word2003large.doc ß same file as above
+
<Upstream> 20080626 11:33:51.982 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x200000000AC66 ß this is the FID from the working file
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2fc40
+ TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
+ Reason: Basic Info Change Close Data Extend Data Overwrite Data truncation ß data has been added to the file
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRD0003.tmp ß the pseudo-temporary working file
+
<Upstream> 20080626 11:33:51.982 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x200000000AC66
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2fcf0
+ TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
+ Reason: Close Security Change ß the file is closed with a security change
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRD0003.tmp
+
<Upstream> 20080626 11:33:51.982 3128 USNC 2777 UsnConsumer::TombstoneOrDelete LDB Updating ID Record: ß file deleted
+ fid 0x70000000000B9
+ usn 0xa2ff68
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080626 15:30:22.932 GMT
+ present 0 ß deleted
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v65 ßversion goes up (even during a deletion, as a deletion counts as a modification)
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceab9)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 4992549E-7564D836-ED346C90-D5FD88B3
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc ß Word is renaming the original file. This is a prelude to copying data from the pseudo-temporary working files into a new file named the same as the original. This operation is considered a delete/tombstone because the file is being renamed to a filtered extension that will not replicate.
+
<Upstream> 20080626 11:33:51.982 3128 USNC 2782 UsnConsumer::TombstoneOrDelete ID record tombstoned from USN_RECORD:
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x70000000000B9
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2ff68
+ TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
+ Reason: Close Rename New Name ß the word2003large.doc file is renamed to a file named ~wrl004.tmp. Note how the File Reference Number never changed!
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRL0004.tmp ß new name
+
<Upstream> 20080626 11:33:51.982 3128 USNC 3341 UsnConsumer::UidTunnelReanimate LDB Updating ID Record: ß the UID is reused from previous due to the same file name/path
+ fid 0x200000000AC66 ß note that File ID is same as ~WRD0003.tmp
+ usn 0xa30000
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080626 15:33:51.982 GMT
+ present 1 ß added back into the replicated folder
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 ß new GVSN when file recreated
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 ß Old UID reused
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name word2003large.doc ß was ~WRD0003.tmp
+
<Upstream> 20080626 11:33:51.982 3128 USNC 3346 UsnConsumer::UidTunnelReanimate UID tunnelling: ID record reanimated because of UID tunnelling: ß the renaming of the file back into a previous one is counted as a USN reanimation
+ USN_RECORD:
+ RecordLength: 96
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x200000000AC66
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa30000
+ TimeStamp: 20080626 11:33:51.972 Eastern Standard Time
+ Reason: Basic Info Change Close Object ID Change Rename New Name Security Change ß ~WRD0003.tmp is renamed to word2003large.doc
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 34
+ FileNameOffset: 60
+ FileName: word2003large.doc
+
<Upstream> 20080626 11:33:51.992 3128 USNC 1995 UsnConsumer::UpdateUsnOnly LDB Updating ID Record:
+ fid 0x200000000AC66
+ usn 0xa301c8
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080626 15:33:51.982 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name word2003large.doc
+
<Upstream> 20080626 11:33:51.992 3128 USNC 1997 UsnConsumer::UpdateUsnOnly USN-only update from USN_RECORD:
+ USN_RECORD:
+ RecordLength: 96
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x200000000AC66
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa301c8
+ TimeStamp: 20080626 11:33:51.982 Eastern Standard Time
+ Reason: Close Object ID Change ß file closed
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ FileNameLength: 34
+ FileNameOffset: 60
+ FileName: word2003large.doc
+
<Downstream> 20080626 11:33:51.996 3616 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00A4CCE8 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all ß downstream server requests version vectors
<Downstream> 20080626 11:33:51.996 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
<Upstream> 20080626 11:33:52.062 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x70000000000B9
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa30388
+ TimeStamp: 20080626 11:33:52.062 Eastern Standard Time
+ Reason: Basic Info Change Close Object ID Change ß closed the tmp file
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x2
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRL0004.tmp
+
<Upstream> 20080626 11:33:52.062 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
+ USN_RECORD:
+ RecordLength: 88
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x70000000000B9
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa303e0
+ TimeStamp: 20080626 11:33:52.062 Eastern Standard Time
+ Reason: Close File Delete ß deleted the tmp file
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x2
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRL0004.tmp
+
<Upstream> 20080626 11:33:52.062 3128 USNC 1294 UsnConsumer::ProcessUsnRecord Filtered USN_RECORD:
+ USN_RECORD:
+ RecordLength: 96
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x100000000AC61
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa30438
+ TimeStamp: 20080626 11:33:52.062 Eastern Standard Time
+ Reason: Close File Delete ß deleted the original renamed temporary file for the document
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x22
+ FileNameLength: 34
+ FileNameOffset: 60
+ FileName: ~$rd2003large.doc
+
<Downstream> 20080626 11:33:52.286 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00A4CCE8 ß finished processing version vectors
<Downstream> 20080626 11:33:52.286 1092 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..66} ß have received the VV's
+
<Downstream> 20080626 11:33:52.286 1092 INCO 3966 InConnection::ReceiveVvUp Creating new session:6 requestState:00A4CCE8 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..64} ß calculating the version vector delta
+
<Downstream> 20080626 11:33:52.286 3616 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} |-> { 65, 66} ß requesting the actual files from the upstream server based on missing versions
+
<Downstream> 20080626 11:33:52.286 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId
{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
<Upstream> 20080626 11:33:52.292 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:15 changeType:all
<Upstream> 20080626 11:33:52.292 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
<Downstream> 20080626 11:33:52.296 1092 INCO 4803 InConnection::ReceiveUpdates Upstream credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 creditsUsed:1 creditsAvailable:32
<Downstream> 20080626 11:33:52.296 1092 INCO 4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 fileName:word2003large.doc session:6 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3
<Downstream> 20080626 11:33:52.296 3616 MEET 1207 Meet::Install Retries:0 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 updateType:remote ß the file is ready to be received downstream
<Downstream> 20080626 11:33:52.296 1092 INCO 4932 InConnection::ReceiveUpdates Session has been closed. sessionId:6 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3
<Downstream> 20080626 11:33:52.296 3976 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00A4CBF0 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:notify
<Downstream> 20080626 11:33:52.296 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:UpdateRequest reqState:Completed status:0 ptr:00A42780
<Upstream> 20080626 11:33:52.302 4052 SRTR 882 SERVER_RequestUpdates Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} credits:32 requestType:all
<Upstream> 20080626 11:33:52.302 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
<Upstream> 20080626 11:33:52.302 2688 JOIN 1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 name:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß upstream acknowledges that it is ready to have the file pulled
<Upstream> 20080626 11:33:52.302 1516 OUTC 784 OutConnection::OpenFile Received request for update: ß upstream serving file
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 ß this the version of the file to be replicated
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name word2003large.doc ß this is our file to be replicated
+ rdcDesired:1 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3
<Downstream> 20080626 11:33:52.306 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00A4CBF0
<Upstream> 20080626 11:33:52.312 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:16 changeType:notify
<Upstream> 20080626 11:33:52.342 1516 MRSH 4615 Marshaller::Marshal FileAttrs in metadata : 0x20 ß file attributes marshaled
<Upstream> 20080626 11:33:53.703 1516 CSMG 4844 ContentSetManager::UpdateHash LDB Updating ID Record:
+ fid 0x200000000AC66
+ usn 0xa301c8
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080626 15:33:51.982 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 66E49D5D-344B5F47-D192C5EA-6C30377D
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc
+
<Upstream> 20080626 11:33:53.903 1516 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
<Upstream> 20080626 11:33:53.903 1516 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 66-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66-Downloaded.frx ß the file has been staged (compressed, RDC signatures calculated) on the upstream server
<Upstream> 20080626 11:33:53.903 1516 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Upstream> 20080626 11:33:53.903 2688 STAG 108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Upstream> 20080626 11:33:53.963 1516 OUTC 1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 name:word2003large.doc fileSize:4821514 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3 ß the file is truly ready for replication upstream
<Upstream> 20080626 11:33:53.963 1516 SRTR 2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rdc:1 context:00AB0248,00AA1BA8,00000000 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 ptr:00AA3EC0 ß outbound RPC session ready on the upstream server, file can be replicated anytime now
<Downstream> 20080626 11:33:54.169 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Upstream> 20080626 11:33:55.524 3128 USNC 2361 UsnConsumer::UpdateIdRecord LDB Updating ID Record: ß Word touched the file again for some reason. + fid 0x200000000AC66
+ usn 0xa32330
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080626 15:33:51.982 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 ß Upstream, Word changes the file one more time as part of its internal workings. This is going to force the download process to happen all over again below unfortunately. This highlights how applications are often the cause of DFSR replication inefficiencies. Fortunately we will see below that the file was not altered materially and will not need to be restaged.
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name word2003large.doc
+
<Upstream> 20080626 11:33:55.524 3128 USNC 2364 UsnConsumer::UpdateIdRecord ID record updated from USN_RECORD:
+ USN_RECORD:
+ RecordLength: 96
+ MajorVersion: 2
+ MinorVersion: 0
+ FileRefNumber: 0x200000000AC66
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa32330
+ TimeStamp: 20080626 11:33:55.524 Eastern Standard Time
+ Reason: Close Data Overwrite ß file closed again.
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20
+ ParentFileRefNumber: 0xF00000000A781
+ USN: 0xa2f9d0
+ TimeStamp: 20080626 11:33:51.861 Eastern Standard Time
+ Reason: Close Data Extend Data Overwrite File Create ß created, added some data
+ SourceInfo: 0x0
+ SecurityId: 0x0
+ FileAttributes: 0x20 ß not temporary
+ FileNameLength: 24
+ FileNameOffset: 60
+ FileName: ~WRD0003.tmp
+ FileNameLength: 34
+ FileNameOffset: 60
+ FileName: word2003large.doc
+
<Downstream> 20080626 11:33:55.531 3976 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:04569008 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all
<Downstream> 20080626 11:33:55.531 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
<Downstream> 20080626 11:33:55.531 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:04569008
<Downstream> 20080626 11:33:55.531 1092 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..67} ß we had to send the higher version vector info to downstream again
+
<Downstream> 20080626 11:33:55.531 1092 INCO 3966 InConnection::ReceiveVvUp Creating new session:7 requestState:04569008 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..64}
+
<Downstream> 20080626 11:33:55.531 1092 INCO 3982 InConnection::ReceiveVvUp Adding difference from previous session connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDiff:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 65, 66}
+ vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..66}
+
<Downstream> 20080626 11:33:55.531 3976 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} |-> { 67} ß downstream re-requests the update again (the other –v66 update is still ongoing)
+
<Downstream> 20080626 11:33:55.531 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A501C0
<Upstream> 20080626 11:33:55.535 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:17 changeType:all
<Upstream> 20080626 11:33:55.535 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
<Upstream> 20080626 11:33:55.535 4052 SRTR 882 SERVER_RequestUpdates Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} credits:32 requestType:all
<Upstream> 20080626 11:33:55.535 4052 SRTR 1927 SERVER_AsyncPoll Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D}
<Upstream> 20080626 11:33:55.535 2688 JOIN 1167 Join::SubmitUpdate Sent: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 name:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3
<Downstream> 20080626 11:33:55.541 1092 INCO 4803 InConnection::ReceiveUpdates Upstream credits:32 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 creditsUsed:1 creditsAvailable:32
<Downstream> 20080626 11:33:55.541 1092 INCO 4868 InConnection::ReceiveUpdates Received: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 fileName:word2003large.doc session:7 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß downstream ready to pull the updates again.
<Downstream> 20080626 11:33:55.541 3976 UPMG 413 UpdateWorker::ConsumeUpdates Available updates were locked. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Downstream> 20080626 11:33:55.541 1092 INCO 4932 InConnection::ReceiveUpdates Session has been closed. sessionId:7 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 ß the file updates have been transferred over the wire
<Downstream> 20080626 11:33:55.541 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:UpdateRequest reqState:Completed status:0 ptr:00A4CBF0
<Downstream> 20080626 11:33:55.541 3976 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00A4CBF0 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:notify
<Downstream> 20080626 11:33:55.541 1092 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00A4CBF0
<Upstream> 20080626 11:33:55.545 4052 SRTR 1880 SERVER_RequestVersionVector Received from connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:18 changeType:notify
<Downstream> 20080626 11:33:55.721 3616 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
<Downstream> 20080626 11:33:55.721 3616 RDCX 1811 Rdc::SyncClientState::Flush Rdc Need Assembler Statistics: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 fileName:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß the downstream server can now gather statistics about what happened during the file transfer process.
+ TOTAL
+ Compression Ratio 2
+ Target Uncompress Size 4905740 ß the true file size
+ Target Compress Size 4814322 ß file size after being XPRESS compressed in staging directory. Note how the size difference is not great here. In this scenario, the Word document was filled with JPG images which are already compressed.
+ Bytes Received 49704 Signatures: 4718 Data: 44986 ß actual bytes to be sent over the wire thanks to savings from RDC. The breakout here is total bytes, then the number of bytes that are just signature checksums, then the actual data blocks.
+ Signature Bytes Received 4718 1616 3102
+ Number of remote calls 5 Signatures: 3 Needs: 1 Data: 1
+ SEED
+ Rdc Need Size 0 0 0
+ Xpress Blocks 589 589 0
+ Uncompressed Xpress Blocks 7 7 0
+ Blocks copied to target 0 0 0
+ SOURCE
+ Rdc Need Size 113076 0
+ Xpress Blocks 17 0
+ Uncompressed Xpress Blocks 4 0
+ Blocks copied to target 11 0
<Downstream> 20080626 11:33:55.721 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Downstream> 20080626 11:33:55.721 3616 INCO 5610 InConnection::LogTransferActivity Received RDCGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 fileName:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} stagedSize:4821514 ß the file transfer over the wire is complete and the file now exists in staging on the downstream server.
<Downstream> 20080626 11:33:55.721 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Downstream> 20080626 11:33:55.721 3976 STAG 108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Upstream> 20080626 11:33:55.725 4052 RDCX 2833 Rdc::SyncServerState::~SyncServerState RDC Need Reader Statistics: uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß statistics are now written to show what actually was sent over the wire (as opposed to the previous stats which were planned work) + TOTAL
+ Compression Ratio 57
+ RDC Need Size 113076
+ Bytes sent to downstream 49704
+ Uncompressed XPRESS blocks 0
+ Compressed XPRESS blocks 2
+ Copied XPRESS Blocks 13
+ Bytes read using async I/Os 0
<Upstream> 20080626 11:33:55.725 4052 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Downstream> 20080626 11:33:55.781 3616 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 66-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66-Downloaded.frx ß we leave the staging functions and the name of the staged file is written to log
<Downstream> 20080626 11:33:55.781 3616 MRSH 3959 MarshalContext::Initialize Create file:[word2003large-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66.doc] with attributes:0x20 ß data is unmarshalled
<Downstream> 20080626 11:33:55.781 3616 MEET 2585 Meet::TransferToInstalling Transferring content from staging area into Installing updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the staged file is decompressed as a copy into the Installing directory
<Downstream> 20080626 11:33:56.542 3976 UPMG 413 UpdateWorker::ConsumeUpdates Available updates were locked. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Downstream> 20080626 11:33:56.542 3616 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
<Downstream> 20080626 11:33:56.542 3616 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Downstream> 20080626 11:33:56.542 3616 MEET 2032 Meet::Download Download Succeeded : true updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß the copy of the file in the Installing directory is now moved into the replicated folder, replacing an existing copy of the file
<Downstream> 20080626 11:33:56.542 3616 MEET 2772 Meet::InstallRename Move out previous version of same file updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß since this was a modification of an existing file that exists on both servers, the downstream copy must be overwritten. So the older copy downstream is deleted.
<Downstream> 20080626 11:33:56.542 3616 MEET 4867 Meet::MoveOut Moving contents and children out of replica. newName:word2003large-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61.doc updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 record: ß indicates the deletion is occurring downstream
+ fid 0x200000000A6D1
+ usn 0x903d38
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 1
+ meetReanimated 0
+ recUpdateTime 20080626 15:30:27.557 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 ß note the old unmodified version
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:30:22.932 GMT (0x1c8d7a18ca3f2b2)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 4992549E-7564D836-ED346C90-D5FD88B3
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc
+
<Downstream> 20080626 11:33:56.542 3616 MEET 4989 Meet::MoveOut Purge existing file in Deleted updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the older file is moved into the Deleted folder, then purged from the disk
<Downstream> 20080626 11:33:56.542 3616 MEET 4995 Meet::MoveOut RenameDelete file fid:0x200000000A6D1 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß DFSR notes that the old file is gone now.
<Downstream> 20080626 11:33:56.542 3616 MEET 2837 Meet::InstallRename File moved. rootVolume:{3EA8BD01-416E-11DD-A317-806E6F6E6963} parentFid:0xC00000000A514 fidInInstalling:0x900000000A5D4 usn:0x906ec0 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 ß the new copy of the file is copied into the replicated folder.
<Downstream> 20080626 11:33:56.542 3616 MEET 6746 Meet::UpdateIdRecord LDB Updating ID Record: ß Database is updated to reflect the file now existing in the replicated folder
+ fid 0x900000000A5D4
+ usn 0x906ec0
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 1 ß indicates the update was due to replication and not an originating change
+ meetReanimated 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1 ß file is present and accessible by users
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 66E49D5D-344B5F47-D192C5EA-6C30377D ß note that we have a new hash for the file after it was modified
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc
+
<Downstream> 20080626 11:33:56.552 3616 MEET 2949 Meet::InstallRename -> DONE Install-rename completed updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß the process of moving file into the replicated folder is complete
<Downstream> 20080626 11:33:56.552 3616 INCO 5897 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 failures:0 sessionId:6 open:0 updateType:0 processStatus:0 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 update:
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v66
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:51.972 GMT (0x1c8d7a2093ceaba)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 66E49D5D-344B5F47-D192C5EA-6C30377D
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc
+
<Downstream> 20080626 11:33:56.552 3616 MEET 1207 Meet::Install Retries:0 updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 updateType:remote ß note the GVSN changed. This is the subsequent update that occurred when Word re-closed the file as part of its internal processing.
<Downstream> 20080626 11:33:56.562 3620 SRTR 1880 SERVER_RequestVersionVector Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:12 changeType:all
<Downstream> 20080626 11:33:56.562 2716 SRTR 1927 SERVER_AsyncPoll Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9}
<Downstream> 20080626 11:33:56.572 2716 SRTR 1927 SERVER_AsyncPoll Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9}
<Downstream> 20080626 11:33:56.572 2716 SRTR 1880 SERVER_RequestVersionVector Received from connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} seqNumber:13 changeType:notify
<Upstream> 20080626 11:33:56.575 1516 OUTC 784 OutConnection::OpenFile Received request for update: ß the subsequent file change is now being requested
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 00000000-00000000-00000000-00000000 ß note that the change is causing us to recalculate the hash (this is by design)
+ similarity 00000000-00000000-00000000-00000000
+ name word2003large.doc
+ rdcDesired:1 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3
<Upstream> 20080626 11:33:56.575 1516 MRSH 4615 Marshaller::Marshal FileAttrs in metadata : 0x20
<Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00AB0058
<Upstream> 20080626 11:33:56.585 2688 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00AA2038 connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:all
<Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00AA2038
<Upstream> 20080626 11:33:56.585 752 INCO 3959 InConnection::ReceiveVvUp Received VvUp connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvUp:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..66}
+
<Upstream> 20080626 11:33:56.585 752 INCO 3966 InConnection::ReceiveVvUp Creating new session:6 requestState:00AA2038 connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 49..67} <- version vector information updated
+
<Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00AB0058
<Upstream> 20080626 11:33:56.585 2688 INCO 3779 InConnection::ContentSetContext::Hibernate Hibernating: connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Upstream> 20080626 11:33:56.585 2688 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00AB0150 connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} csName:testrf3 changeType:notify
<Upstream> 20080626 11:33:56.585 752 DOWN 2723 AsyncRpcHandler::ProcessReceive Completion. connId:{44747D15-9628-4CA2-8D19-99CE2D1B02E9} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} reqType:VvUpRequest reqState:Completed status:0 ptr:00AB0150
<Downstream> 20080626 11:33:57.543 3976 UPMG 418 UpdateWorker::ConsumeUpdates No pending updates. connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Upstream> 20080626 11:33:57.927 1516 CSMG 4844 ContentSetManager::UpdateHash LDB Updating ID Record: ß the file info is re-added into the database, now with hash below, on the upstream server.
+ fid 0x200000000AC66
+ usn 0xa32330
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080626 15:33:55.524 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 66E49D5D-344B5F47-D192C5EA-6C30377D ß hash is the same as the –v66 version of the file. So the file did not actually change, it was just Word opening, making some non-data change, then closing for reasons unknown.
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc
+
<Upstream> 20080626 11:33:58.077 1516 ASYN 510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:
<Upstream> 20080626 11:33:58.077 1516 STAG 799 StageWriter::CompleteDownloadStage Completed download or stage file 67-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61-{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67-Downloaded.frx ß the file is staged upstream.
<Upstream> 20080626 11:33:58.077 1516 ASYN 1291 AsyncUnbufferedFileReader::Close Async READ Statistics:
<Upstream> 20080626 11:33:58.077 2688 STAG 108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Downstream> 20080626 11:33:58.124 3616 RDCX 808 Rdc::SeedFile::Initialize The hashes coincide. The download is redundant, uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 fileName:word2003large.doc csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} ß after exchanging hash information, the downstream server now realizes that there is no need to replicate the file as it is unchanged upstream.
<Upstream> 20080626 11:33:58.147 1516 OUTC 1534 OutConnection::OpenFile Sent file uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 name:word2003large.doc fileSize:4821514 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rgName:TestRG3
<Upstream> 20080626 11:33:58.147 1516 SRTR 2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} rdc:1 context:00AB0248,00AA1BA8,00000000 uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 ptr:00AA3EC0
<Downstream> 20080626 11:33:58.184 3616 DOWN 5186 [ERROR] DownstreamTransport::RdcGet Failed on connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} rgName:TestRG3 update: ß failed is not an error in this case – it is an acknowledgment that there is no need to replicate the file downstream after all. However the version vector info is sent to keep the DFSR-related metadata about the file in sync going forward.
+ present 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 ß version updated
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 66E49D5D-344B5F47-D192C5EA-6C30377D ß hash unchanged
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc
+ Error:
+ [Error:9047(0x2357) RpcFinalizeContext downstreamtransport.cpp:1096 3616 C The download is redundant]
+ [Error:9047(0x2357) Rdc::SyncClientState::Download rdc.cpp:2546 3616 C The download is redundant]
+ [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:944 3616 C The download is redundant]
+ [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:810 3616 C The download is redundant] ß More spurious 'errors' – a redundant download is not a true error.
<Downstream> 20080626 11:33:58.184 3616 INCO 5599 InConnection::LogTransferActivity Failed to receive RDCGET uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 fileName:word2003large.doc connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8} stagedSize:0 Error:
+ [Error:9047(0x2357) DownstreamTransport::RdcGet downstreamtransport.cpp:5201 3616 C The download is redundant]
+ [Error:9047(0x2357) RpcFinalizeContext downstreamtransport.cpp:1096 3616 C The download is redundant]
+ [Error:9047(0x2357) Rdc::SyncClientState::Download rdc.cpp:2546 3616 C The download is redundant]
+ [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:944 3616 C The download is redundant]
+ [Error:9047(0x2357) Rdc::SeedFile::Initialize rdc.cpp:810 3616 C The download is redundant] ß more info that file download did not need to occur <Downstream> 20080626 11:33:58.184 3616 MEET 2032 Meet::Download Download Succeeded : false updateName:word2003large.doc uid:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61 gvsn:{EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67 connId:{D7E7B14C-8DE9-4198-BA51-B8D13867171D} csName:testrf3 csId:{BDD12194-91A1-4227-AB6B-9C252C6EACB8}
<Downstream> 20080626 11:33:58.194 3616 NTFS 1257 NtfsFileSystem::SetAttributes oldFileAttributes:0x20 newFileAttributes:0x20
<Downstream> 20080626 11:33:58.194 3616 MEET 6746 Meet::UpdateIdRecord LDB Updating ID Record: ß The database is updated to cover the new version info, regardless of the fact that file contents are unchanged
+ fid 0x900000000A5D4
+ usn 0x907280
+ 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 1
+ nameConflict 0
+ attributes 0x20
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v67
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v61
+ parent {BDD12194-91A1-4227-AB6B-9C252C6EACB8}-v1
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080626 15:33:55.524 GMT (0x1c8d7a20b5b0f15)
+ createTime 20080626 15:30:22.912 GMT
+ csId {BDD12194-91A1-4227-AB6B-9C252C6EACB8}
+ hash 66E49D5D-344B5F47-D192C5EA-6C30377D
+ similarity 2C131C03-12383C0B-15071E36-131A0C27
+ name word2003large.doc
+    

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

Comments