Understanding DFSR debug logging (Part 8: File Deleted from Windows Server 2003 R2)
Published Apr 04 2019 01:59 PM 765 Views
Microsoft

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....

Co-Authors
Version history
Last update:
‎Jun 08 2023 01:39 PM
Updated by: