Understanding DFSR debug logging (Part 8: File Deleted from Windows Server 2003 R2)

In this scenario we will see a file deleted 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.  

 

(deletedfileupstream – Dfsr00004 – 2003.log and deletedfiledownstream – Dfsr00005 – 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 deleted (upstream) and from 2003MEM02 where it the deletion is replicated (downstream). Both servers are participating in the TESTRG2 replication group for the TESTRF2 replicated folder. The file is called “goodbye.txt”.

 

<Upstream> 20080625 19:55:51.522  800 LDBX  3684 Ldb::Update Updating idRecord: ß the DFSR jet DB is updated because the file is changing (even a delete is a change to the state of the file; file references stay in the database for 30 days to allow for reanimation)

+       fid               0x2000000002FED

+       usn               0x81c50

+       uidVisible        1

+       filtered          0

+       journalWrapped    0

+       slowRecoverCheck  0

+       pendingTombstone  0

+       recUpdateTime     20080625 23:55:41.318 GMT

+       present           0 ß The file does not exist in the content set anymore

+       nameConflict      0

+       attributes        0x20

+       gvsn              {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 ß GVSN goes up (state changed)

+       uid               {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25

+       parent            {5666BB91-265D-42E8-9F57-1B49F4E581B7}-v1

+       fence             16010101 00:00:00.000

+       clock             20080625 23:55:51.502

+       createTime        20080625 23:55:41.217 GMT

+       csId              {5666BB91-265D-42E8-9F57-1B49F4E581B7}

+       hash              00000000-00000000-00000000-00000000

+       similarity        00000000-00000000-00000000-00000000

+       name              goodbye.txt

+      

<Upstream> 20080625 19:55:51.532  800 USNC  2599 UsnConsumer::TombstoneOrDelete ID record tombstoned from USN_RECORD:ß USN journal must be updated to reflect the deletion.

+       USN_RECORD:

+       RecordLength:        80

+       MajorVersion:        2

+       MinorVersion:        0

+       FileRefNumber:       0x2000000002fed

+       ParentFileRefNumber: 0x5000000002fa7

+       USN:                 0x81c50

+       TimeStamp:           20080625 19:55:51.502 Eastern Standard Time ß good to know the exact time as deletions are not usually important unless it was unexpected and root cause is being analyzed.

+       Reason:              Close Rename New Name

+       SourceInfo:          0x0

+       SecurityId:          0x1c7

+       FileAttributes:      0x20

+       FileNameLength:      14

+       FileNameOffset:      60

+       FileName:            goodbye.txt

+      

<Upstream> 20080625 19:55:51.532  800 LDBX  1228 LdbManager::UpdateVersionVectorCache Wake up callback 00AD6308

<Downstream> 20080625 19:55:51.546 3832 INCO  3347 InConnection::RequestUpdates Requesting updates. credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 requestType:all cursor:{00000000-0000-0000-0000-000000000000}-v0 delta::{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6} |-> { 26} ß downstream server request version vector of upstream server

+      

<Downstream> 20080625 19:55:51.546 3928 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

<Upstream> 20080625 19:55:51.582 1624 SRTR  1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:6 changeType:all ß VV request received.

<Upstream> 20080625 19:55:51.582 1624 SRTR  1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}

<Downstream> 20080625 19:55:51.586 3928 INCO  3534 InConnection::ReceiveUpdates Upstream credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß downstream server request

<Downstream> 20080625 19:55:51.586 3928 INCO  3597 InConnection::ReceiveUpdates Received: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 fileName:goodbye.txt session:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 ß the ‘data’ is replicated. Keep in mind that when replicating metadata changes (file rename, attribute data, security data, or file deletion) the actual file is not sent over the wire. There is no staging in or out. Only information necessary to describe the metadata is sent via RPC; in this case, just the ‘delete’.

<Downstream> 20080625 19:55:51.586 3832 MEET  1190 Meet::Install Retries:0 updateName:goodbye.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 ß the update was received on the downstream.

<Downstream> 20080625 19:55:51.586 3832 MEET  3700 Meet::MoveOut Moving contents a