Understanding DFSR debug logging (Part 11: Directory created on Windows Server 2003 R2)

Ned Pyle · ‎Apr 04 2019

First published on TechNet on Apr 02, 2009

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

(addedfolderupstream - Dfsr00006 - 2003.log and addedfolderdownstream - Dfsr00007 - 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 folder is created (upstream) and from 2003MEM02 where it the creation is replicated (downstream). Both servers are participating in the TESTRG2 replication group for the TESTRF2 replicated folder. The folder was called “subfolder”.

<Upstream> 20080627 10:34:47.983 692 LDBX 3567 Ldb::Insert Inserting idRecord: << the DFSR database is being updated upstream

+ fid 0x1000000002FF8 << note the file ID. This useful for cross referencing with USN updates in the log

+ usn 0xb6370

+ uidVisible 0

+ filtered 0

+ journalWrapped 0

+ slowRecoverCheck 0

+ pendingTombstone 0

+ recUpdateTime 16010101 00:00:00.000 GMT

+ present 1

+ nameConflict 0

+ attributes 0x10 << marks the object as a folder, not a file

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

+ uid {B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 << UID and GVSN match, this shows the change as an original creation on the upstream server

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

+ fence 16010101 00:00:00.000

+ clock 20080627 14:34:47.983

+ createTime 20080627 14:34:47.983 GMT

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

+ hash 00000000-00000000-00000000-00000000

+ similarity 00000000-00000000-00000000-00000000

+ name subfolder << the folder is named ‘subfolder’

+

<Upstream> 20080627 10:34:48.043 692 USNC 2448 UsnConsumer::CreateNewRecord ID record created from USN_RECORD: << the USN journal has been updated. Note that this actually occurred before the database being updated, it is just a log idiosyncrasy that the debug log entry occurs later.

+ USN_RECORD:

+ RecordLength: 80

+ MajorVersion: 2

+ MinorVersion: 0

+ FileRefNumber: 0x1000000002ff8 << note that File ID is the same as above

+ ParentFileRefNumber: 0x1000000002f92

+ USN: 0xb6370

+ TimeStamp: 20080627 10:34:47.983 Eastern Standard Time

+ Reason: Close Rename New Name << the folder object is newly created.

+ SourceInfo: 0x0

+ SecurityId: 0x1af

+ FileAttributes: 0x10 << it’s a folder, not a file

+ FileNameLength: 18

+ FileNameOffset: 60

+ FileName: subfolder << named ‘subfolder’

+

<Upstream> 20080627 10:34:48.043 692 LDBX 4083 Ldb::InsertWalkerJob Inserting dirWalkerJob:uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 moveType:MoveIn (1) at time:20080627 14:34:47.983 << a DirWalker job is created. Dirwalker checks that when a folder is created, what sub folders/files it contains.

<Upstream> 20080627 10:34:48.063 692 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00ADF8C0

<Upstream> 20080627 10:34:48.063 692 DIRW 511 DirWalkerTask::QueueMoveinJob Queuing move-in. uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 fid:0x1000000002FF8 name:subfolder << the dirwalker job is queued for running

<Upstream> 20080627 10:34:48.063 172 DIRW 256 DirWalkerTask::Run Start walking directory. << the dirwalker job runs

<Upstream> 20080627 10:34:48.063 172 DIRW 937 DirWalkerTask::MoveinStep Starting to process move-in job. uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 << the results of the dirwalker job are evaluated.

<Upstream> 20080627 10:34:48.063 172 DIRW 101 DirWalkerTask::Job::Finish MoveIn csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 << the dirwalker job is complete. This was very fast here as there were no sub-files or folders.

<Upstream> 20080627 10:34:48.063 172 DIRW 786 DirWalkerTask::RemoveJob Removing job type:1 uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 << the Dirwalker job is ready to be removed.

<Upstream> 20080627 10:34:48.063 172 LDBX 4119 Ldb::DeleteWalkerJob Deleting dirWalkerJob. uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 << the dirwalker job is removed

<Upstream> 20080627 10:34:48.063 172 DIRW 303 DirWalkerTask::Run Exit.

<Upstream> 20080627 10:34:48.083 1176 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:4 changeType:all

<Upstream> 20080627 10:34:48.083 1176 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}

<Upstream> 20080627 10:34:48.093 1176 SRTR 498 SERVER_RequestUpdates Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} credits:32 requestType:all

<Upstream> 20080627 10:34:48.093 1176 SRTR 1304 SERVER_AsyncPoll Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}

<Downstream> 20080627 10:34:48.098 1788 INCO 2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86E70 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:all << the downstream server requests version vector info from the upstream partner

<Downstream> 20080627 10:34:48.098 1720 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> 20080627 10:34:48.103 172 LDBX 3684 Ldb::Update Updating idRecord: << DFSR database updated to reflect that the folder is available for replication now, with a visible UID (this is slightly different than files, since folders can contain other objects)

+ fid 0x1000000002FF8

+ usn 0xb6370

+ uidVisible 1

+ filtered 0

+ journalWrapped 0

+ slowRecoverCheck 0

+ pendingTombstone 0

+ recUpdateTime 20080627 14:34:47.983 GMT

+ present 1

+ nameConflict 0

+ attributes 0x10

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

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

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

+ fence 16010101 00:00:00.000

+ clock 20080627 14:34:47.983

+ createTime 20080627 14:34:35.555 GMT

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

+ hash 00000000-00000000-00000000-00000000

+ similarity 00000000-00000000-00000000-00000000

+ name subfolder

+

<Upstream> 20080627 10:34:48.103 172 JOIN 1171 Join::SubmitUpdate Sent: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 name:subfolder connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 << the upstream server sends downstream the update information metadata. Since this is a folder an actual ‘folder’ is not sent, just security, name, and parent info.

<Upstream> 20080627 10:34:48.103 1176 SRTR 1257 SERVER_RequestVersionVector Received from connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} seqNumber:5 changeType:notify

<Upstream> 20080627 10:34:48.103 1620 OUTC 588 OutConnection::OpenFile Received request for update: << the upstream server is requested to serve the folder to the downstream

+ present 1

+ nameConflict 0

+ attributes 0x10

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

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

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

+ fence 16010101 00:00:00.000

+ clock 20080627 14:34:47.983

+ createTime 20080627 14:34:35.555 GMT

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

+ hash 00000000-00000000-00000000-00000000

+ similarity 00000000-00000000-00000000-00000000

+ name subfolder

+ rdcDesired:1 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} rgName:TestRG2

<Upstream> 20080627 10:34:48.103 1620 OUTC 1056 OutConnection::OpenFile Sent file uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 name:subfolder fileSize:360 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} rgName:TestRG2 << the folder is being sent

<Upstream> 20080627 10:34:48.103 1620 MRSH 3487 Marshaller::Marshal FileAttrs in metadata : 0x10 << the folder data was marshaled for RPC

<Downstream> 20080627 10:34:48.108 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86E70

<Downstream> 20080627 10:34:48.108 1720 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..30}

+

<Downstream> 20080627 10:34:48.108 1720 INCO 2954 InConnection::ReceiveVvUp Creating new session:2 requestState:00A86E70 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 << downstream server has received the version vector info

<Downstream> 20080627 10:34:48.108 1788 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} |-> { 30} << the version is 30

+

<Downstream> 20080627 10:34:48.108 1720 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> 20080627 10:34:48.128 1720 INCO 3534 InConnection::ReceiveUpdates Upstream credits:32 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2

<Downstream> 20080627 10:34:48.128 1720 INCO 3597 InConnection::ReceiveUpdates Received: uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 fileName:subfolder session:2 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 << the downstream server receives the marshaled folder metadata information

<Downstream> 20080627 10:34:48.128 1788 MEET 1190 Meet::Install Retries:0 updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 << the new folder is ready to be created in the downstream replicated folder. Note the lack of staging, installing process. There is no RDC or compression used in folder object replication.

<Downstream> 20080627 10:34:48.128 1720 INCO 3661 InConnection::ReceiveUpdates Session has been closed. sessionId:2 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2

<Downstream> 20080627 10:34:48.128 2008 INCO 2761 InConnection::RequestVvUp Requested upstream version vector. requestState:00A86E70 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} csName:testrf2 changeType:notify

<Downstream> 20080627 10:34:48.128 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:UpdateRequest reqState:Completed status:0 ptr:00A86340

<Downstream> 20080627 10:34:48.128 1788 MRSH 2957 MarshalContext::Initialize Create file:[subfolder-{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30] with attributes:0x10 << the folder is created in the downstream server replicated folder

<Downstream> 20080627 10:34:48.128 1788 INCO 4112 InConnection::LogTransferActivity Received RAWGET uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 fileName:subfolder connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} stagedSize:356 << the process of replication is logged as a RAWGET (i.e. no RDC). While there is info on ‘stagedsize’ it is not actually staged, this is a logging idiosyncrasy.

<Downstream> 20080627 10:34:48.128 1788 MEET 1898 Meet::Download Download Succeeded : true updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} << the replication process has completed and the folder has been successfully ‘downloaded’.

<Downstream> 20080627 10:34:48.128 1788 MEET 2190 Meet::InstallRename File moved. rootVolume:{05853FA6-411C-11DD-A156-806E6F6E6963} parentFid:0x1000000002F8C fidInInstalling:0x1000000002FF3 usn:0xbbe88 updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 << the subfolder now fully exists in the replicated folder.

<Downstream> 20080627 10:34:48.128 1788 LDBX 3567 Ldb::Insert Inserting idRecord: << the DFSR database is updated on the downstream server to track the new subfolder

+ fid 0x1000000002FF3

+ usn 0xbbe88

+ uidVisible 1

+ filtered 0

+ journalWrapped 0

+ slowRecoverCheck 0

+ pendingTombstone 0

+ recUpdateTime 16010101 00:00:00.000 GMT

+ present 1

+ nameConflict 0

+ attributes 0x10

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

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

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

+ fence 16010101 00:00:00.000

+ clock 20080627 14:34:47.983

+ createTime 20080627 14:34:35.555 GMT

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

+ hash BD3BC9A8-67A8EA8B-B5D77ACF-4DBD26A0

+ similarity 00000000-00000000-00000000-00000000

+ name subfolder

+

<Downstream> 20080627 10:34:48.128 1720 DOWN 2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} reqType:VvUpRequest reqState:Completed status:0 ptr:00A86E70

<Downstream> 20080627 10:34:48.158 1788 MEET 2233 Meet::InstallRename -> DONE Install-rename completed updateName:subfolder uid:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 gvsn:{B0DAFB7F-1E6D-401E-ADEC-2494F4A345A6}-v30 connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2 csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7} << the installation process has been completed.

<Downstream> 20080627 10:34:48.158 1788 INCO 4378 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 sessionId:2 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 0x10

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

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

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

+ fence 16010101 00:00:00.000

+ clock 20080627 14:34:47.983

+ createTime 20080627 14:34:35.555 GMT

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

+ hash BD3BC9A8-67A8EA8B-B5D77ACF-4DBD26A0

+ similarity 00000000-00000000-00000000-00000000

+ name subfolder

+

<Downstream> 20080627 10:34:48.168 1788 LDBX 1228 LdbManager::UpdateVersionVectorCache Wake up callback 00AD6080

<Downstream> 20080627 10:34:48.168 1788 INCO 4617 InConnection::CommitSession Connection in sync connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD}

<Downstream> 20080627 10:34:48.168 1788 UPMG 413 UpdateWorker::ConsumeUpdates No pending updates. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csName:testrf2

<Downstream> 20080627 10:34:48.168 2008 INCO 2787 InConnection::ContentSetContext::Hibernate Hibernating: connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-265D-42E8-9F57-1B49F4E581B7}

Products (50)

Special Topics (27)

Video Hub (462)

Most Active Hubs

Most Active Hubs

Video Hub

Understanding DFSR debug logging (Part 11: Directory created on Windows Server 2003 R2)