First published on TechNet on Apr 01, 2009
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 and children out of replica. newName:goodbye.txt-{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 updateName:goodbye.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2record: << in content set terms, files are never ‘deleted’. They are moved out of the content set.
+ fid 0x1000000002FE8
+ usn 0x883a0
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ recUpdateTime 20080625 23:55:41.331 GMT
+ present 1 << the file is still present on the downstream server, we are in process here (on the upstream a file is just deleted and that’s it. On the downstream servers, it will have to transition its way into the ConflictAndDeleted folder.)
+ nameConflict 0
+ attributes 0x20
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25
+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25
+ parent {5666BB91-265D-42E8-9F57-1B49F4E581B7}-v1
+ fence 16010101 00:00:00.000
+ clock 20080625 23:55:41.227
+ createTime 20080625 23:55:41.217 GMT
+ csId {5666BB91-265D-42E8-9F57-1B49F4E581B7}
+ hash CC8863B9-2EAB0BC2-C669B493-00C79510
+ similarity 00000000-00000000-00000000-00000000
+ name goodbye.txt
+
<Upstream> 20080625 19:55:51.592 1624 SRTR 498 SERVER_RequestUpdates Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} credits:32 requestType:all
<Upstream> 20080625 19:55:51.592 1624 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Downstream> 20080625 19:55:51.596 3832 LDBX 3684 Ldb::Update Updating idRecord: << now we update jet database downstream to reflect the deletion. The file has actually now been moved to the ConflictAndDeleted folder and the conflictanddeletedmanifest.xml has been updated (but this is not covered in the deuglogseverity=4 debug logs)
+ fid 0x1000000002FE8
+ usn 0x88608
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 0 << the file is no longer present in the content set
+ nameConflict 0
+ attributes 0x20
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 << the deletion necessitates updating the GVSN
+ 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
+
<Downstream> 20080625 19:55:51.596 3832 MEET 3635 Meet::InstallTombstone -> DONE Install Tombstone complete 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 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} << the tombstone (deletion) process is completed downstream. The file is completely out of the content set.
<Downstream> 20080625 19:55:51.596 3928 INCO 3661 InConnection::ReceiveUpdates Session has been closed. sessionId:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2
<Downstream> 20080625 19:55:51.596 3832 INCO 4378 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 sessionId:3 open:0 updateType:0 processStatus:0 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 update: << the single update from upstream was processed with no errors
+ present 0 << file is no longer present
+ nameConflict 0
+ attributes 0x20
+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26
+ 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
+
<Downstream> 20080625 19:55:51.596 3928 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:UpdateRequest reqState:Completed status:0 ptr:00A86E70
<Upstream> 20080625 19:55:51.602 820 JOIN 1171 Join::SubmitUpdate Sent: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v25 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v26 name:goodbye.txt connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 << upstream server reports completion on the update operation.
<Upstream> 20080625 19:55:51.602 1624 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:7 changeType:notify
<Downstream> 20080625 19:55:51.606 3832 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00ADEE10
<Downstream> 20080625 19:55:51.606 3832 INCO 4617 InConnection::CommitSession Connection in sync connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}
<Downstream> 20080625 19:55:51.606 3904 INCO 2787 InConnection::ContentSetContext::Hibernate Hibernating: connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7}
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 ....
Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows S....
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 Se....
Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Serve....
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 Ser....
Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between tw....
Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream betwee....
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....
Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses d....
Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity....
Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (use....
Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severit....
Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug....
You must be a registered user to add a comment. If you've already registered, sign in. Otherwise, register and sign in.