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