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

Ned Pyle · ‎Apr 04 2019

First published on TechNet on Apr 01, 2009

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

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

+

<Downstream> 20080626 16:00:17.519 1472 INCO 2954 InConnection::ReceiveVvUp Creating new session:3 requestState:00A86340 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2

<Downstream> 20080626 16:00:17.519 980 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} |-> { 29}

+

<Downstream> 20080626 16:00:17.519 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.529 1472 INCO 3534 InConnection::ReceiveUpdates Upstream credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2

<Downstream> 20080626 16:00:17.529 1472 INCO 3597 InConnection::ReceiveUpdates Received: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 fileName:davesdoc.txt session:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 << all update info about the file name modification has been received. Note in all the logs previous there is no RDCGET, no RAWGET, no staging, and no indications of the file actually being moved. This is because a rename operation only requires metadata to be sent over the wire in RPC.

<Downstream> 20080626 16:00:17.529 980 MEET 1190 Meet::Install Retries:0 updateName:davesdoc.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 << The ‘installation’ has succeeded (not that anything is actually being installed)

<Downstream> 20080626 16:00:17.529 980 LDBX 3684 Ldb::Update Updating idRecord: << the DFSR database is updated downstream

+ fid 0x2000000002FEE

+ usn 0xa3f40

+ uidVisible 1

+ filtered 0

+ journalWrapped 0

+ slowRecoverCheck 0

+ pendingTombstone 0

+ recUpdateTime 16010101 00:00:00.000 GMT

+ present 1

+ nameConflict 0

+ attributes 0x20

+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 << note the GVSN has been updated

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

+ 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

+

<Downstream> 20080626 16:00:17.529 980 MEET 2770 Meet::InstallMove -> DONE Install-move completed updateName:davesdoc.txt uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v28 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} << at this point the file has been renamed in the replicated folder downstream

<Downstream> 20080626 16:00:17.529 1472 INCO 3661 InConnection::ReceiveUpdates Session has been closed. sessionId:3 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 << the actual ‘replication’ operation is complete.

<Downstream> 20080626 16:00:17.529 980 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:

+ present 1

+ nameConflict 0

+ attributes 0x20

+ gvsn {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v29

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

+ 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

+

Products (50)

Special Topics (27)

Video Hub (462)

Most Active Hubs

Most Active Hubs

Video Hub

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