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

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

  • Comments 1
  • Likes

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}

 

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 on Windows Server 2008)
Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008)
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 Server 2008)
Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)
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 Server 2008)
Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)
Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream between two Windows Server 2008)
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 debug severity 5))
Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses debug severity 5))
Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity 5))
Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (uses debug severity 5))
Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severity 5))
Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))

 

-          Ned Pyle

  • 237 Microsoft Team blogs searched, 115 blogs have new articles in the past 7 days. 327 new articles found