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

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

  • Comments 1
  • Likes

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

<snip – removed all the replication debug log churn that this generates>

<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

+      

<Downstream> 20080626 16:00:17.529 1472 DOWN  2668 AsyncRpcHandler::ProcessReceive Completion. connId:{39D5F13D-B2D1-484D-B57E-E369C8F8C6DD} csId:{5666BB91-

 

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