Understanding DFSR debug logging (Part 9: File is Renamed on Windows Server 2003 R2)

In this scenario we will see a file renamed 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, and the network (including RPC) are preventing replication from working correctly.  
 
(renamedfileupstream – Dfsr00005 – 2003.log and renamedfiledownstream – Dfsr00006 – 2003.log)
 
These are two Windows Server 2003 servers called 2003MEM01 and 2003MEM02 in the contoso.com domain. The logs are from 2003MEM01 where the file is renamed (upstream) and from 2003MEM02 where it the rename is replicated (downstream). Both servers are participating in the TESTRG2 replication group for the TESTRF2 replicated folder. The file was originally called “mikesdoc.txt” and was then renamed to “davesdoc.txt”.
 
<Upstream> 20080626 15:58:36.910 1440 LDBX  3567 Ldb::Insert Inserting idRecord: ß the original file creation leads to a DFSR database update. We examine this part of the log in order to understand the later rename operation fully.
+       fid               0x2000000002FF0 ß note the file ID as a cross-reference against the UID/GVSN
+       usn               0x9db60
+       uidVisible        0
+       filtered          0
+       journalWrapped    0
+       slowRecoverCheck  0
+       pendingTombstone  0
+       recUpdateTime     16010101 00:00:00.000 GMT
+       present           1 ß the file is present in the replica set
+       nameConflict      0
+       attributes        0x20
+       gvsn              {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28
+       uid               {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 ß note the UID and GVSN are a perfect match. This is the key indicator that the file was just created on this server upstream
+       parent            {5666BB91-265D-42E8-9F57-1B49F4E581B7}-v1
+       fence             16010101 00:00:00.000
+       clock             20080626 19:58:36.910
+       createTime        20080626 19:58:36.910 GMT
+       csId              {5666BB91-265D-42E8-9F57-1B49F4E581B7}
+       hash              00000000-00000000-00000000-00000000
+       similarity        00000000-00000000-00000000-00000000
+       name              mikesdoc.txt ß the file is currently named mikesdoc.txt
<snip – removed all the replication debug log churn that this generates>
<Upstream> 20080626 16:00:17.124 1440 LDBX  3684 Ldb::Update Updating idRecord: ß some time later, a user renames the file on the upstream server. This must be recorded in the DFSR database.
+       fid               0x2000000002FF0 ß note the file ID is unchanged
+       usn               0x9e800
+       uidVisible        1
+       filtered          0
+       journalWrapped    0
+       slowRecoverCheck  0
+       pendingTombstone  0
+       recUpdateTime     20080626 19:58:37.200 GMT
+       present           1
+       nameConflict      0
+       attributes        0x20
+       gvsn              {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 ß GVSN version is incremented to the high watermark on the server. There have been no other changes on the server so the version is only one higher.
+       uid               {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 ß remember that UID will stay the same forever. This helps us track the file.
+       parent            {5666BB91-265D-42E8-9F57-1B49F4E581B7}-v1
+       fence             16010101 00:00:00.000
+       clock             20080626 20:00:17.114
+       createTime        20080626 19:58:04.143 GMT
+       csId              {5666BB91-265D-42E8-9F57-1B49F4E581B7}
+       hash              CE2505D3-E4669977-250B31C1-100B67DE
+       similarity        2A242410-2E100D1A-191A340E-041A1018
+       name              davesdoc.txt ß note the file name has changed.
+      
<Upstream> 20080626 16:00:17.124 1440 USNC  2202 UsnConsumer::UpdateIdRecord ID record updated from USN_RECORD: ß the USN journal has been updated (it is an idiosyncrasy of a multi-threaded DFSR service logging that this does not write before the database update above. Technically the USN journal update *must* have happened first.
+       USN_RECORD:
+       RecordLength:        88
+       MajorVersion:        2
+       MinorVersion:        0
+       FileRefNumber:       0x2000000002ff0 ß note the matching file ID to the above records. Tracking this allows you to cross reference USN and DB record updates in the log.
+       ParentFileRefNumber: 0x1000000002f92
+       USN:                 0x9e800
+       TimeStamp:           20080626 16:00:17.114 Eastern Standard Time
+       Reason:              Close Rename New Name ß the rename operation is made clearer
+       SourceInfo:          0x0
+       SecurityId:          0x1b5
+       FileAttributes:      0x20
+       FileNameLength:      24
+       FileNameOffset:      60
+       FileName:            davesdoc.txt
+      
<Upstream> 20080626 16:00:17.124 1440 LDBX  1228 LdbManager::UpdateVersionVectorCache Wake up callback 00ADF868
<Upstream> 20080626 16:00:17.134 1456 SRTR  1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:6 changeType:all ß the upstream server is asked by the downstream for version vectors, as the4 upstream had sent a change notification  earlier (this is not logged)
<Upstream> 20080626 16:00:17.134 1456 SRTR  1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Upstream> 20080626 16:00:17.144 1456 SRTR   498 SERVER_RequestUpdates Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} credits:32 requestType:all ß upstream server receives a request for pending updates
<Upstream> 20080626 16:00:17.144 1456 SRTR  1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Upstream> 20080626 16:00:17.154 1644 JOIN  1171 Join::SubmitUpdate Sent: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 name:davesdoc.txt connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß information about the updated is sent to the downstream server
<Upstream> 20080626 16:00:17.164 1832 SRTR  1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:7 changeType:notify
<Upstream> 20080626 16:00:17.164 1644 INCO  2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86E70 connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:all
<Upstream> 20080626 16:00:17.164 1424 DOWN  2668 AsyncRpcHandler::ProcessReceive Completion. connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Upstream> 20080626 16:00:17.164 1424 DOWN  2668 AsyncRpcHandler::ProcessReceive Completion. connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86E70
<Upstream> 20080626 16:00:17.174 1424 INCO  2947 InConnection::ReceiveVvUp Received VvUp connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 vvUp:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 10..29}
+      
<Upstream> 20080626 16:00:17.174 1424 INCO  2954 InConnection::ReceiveVvUp Creating new session:3 requestState:00A86E70 connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Upstream> 20080626 16:00:17.174 1644 INCO  2787 InConnection::ContentSetContext::Hibernate Hibernating: connId:{37048901-9F48-4AD8-ADA4-04D4DC682FD8} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7}
<Downstream> 20080626 16:00:17.509  980 INCO  2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86340 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:all
<Downstream> 20080626 16:00:17.509 1472 DOWN  2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:00A8F4A0
<Downstream> 20080626 16:00:17.509 1472 DOWN  2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86340
<Downstream> 20080626 16:00:17.519 1472 INCO  2947 InConnection::ReceiveVvUp Received VvUp connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 vvUp:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 10..29}