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

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