Understanding DFSR debug logging (Part 16: File modification with RDC in very granular detail (uses debug severity 5))

  • Article

In this scenario we will see a file modified and how that change is replicated between servers, specifically in regards to RDC similarity usage. The debug log has been set to severity 5 for deeper details than usual. This is useful to understand how efficient RDC is with a given type of file during a controlled modification. It is also more useful to set this level of debug severity for specific troubleshooting so this example will show considerable detail (and chaff) compared to previous entries.

 

(rdcupstream - Dfsr00003 - 2008.log and rdcdownstream - Dfsr00003 - 2008.log)

 

These are two Windows Server 2008 servers called 2008x86SRV10 and 2008x86SRV11 in the contoso.com domain. The logs are from 2008x86SRV10 where the file is created (upstream) and from 2008x86SRV11 where it is replicated (downstream). Both servers are participating in the RDCRG replication group for the RDCRF replicated folder. The file is called “pooltag.txt”. The file was already replicated previously and has now been modified slightly. Before reading this scenario, please review scenario ‘File Modified on Windows Server 2003 R2’.

<Downstream> 20080908 09:40:55.332 808 DOWN 1732 AsyncRpcHandler::RequestVvUp Sent on connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} reqType:VvUpRequest reqState:Pending seqNumber:10 status:0 ptr:00D832E8

<Downstream> 20080908 09:40:55.332 808 DOWN 4095 DownstreamTransport::RequestVvUp Sent on connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} rgName:RDCRG

<Downstream> 20080908 09:40:55.332 808 INCO 3750 InConnection::RequestVvUp Requested upstream version vector. requestState:00D832E8 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} csName:rdcrf changeType:notify ß important note – these three downstream entries being written are actually happening *after* the upstream entries below. The timing is off due to the repro environment (i.e. there is no way to have a change notification occur before a file was changed naturally)

<Upstream> 20080908 09:40:55.341 2880 USNC 2361 UsnConsumer::UpdateIdRecord LDB Updating ID Record: ß The DFSR database is updated to reflect a file being changed

+ fid 0x300000000BA79 ß note the file ID for cross-reference with the USN journal entries

+ usn 0x2618a08

+ uidVisible 1

+ filtered 0

+ journalWrapped 0

+ slowRecoverCheck 0

+ pendingTombstone 0

+ internalUpdate 0

+ dirtyShutdownMismatch 0

+ meetInstallUpdate 0

+ meetReanimated 0

+ recUpdateTime 20080908 16:39:09.319 GMT

+ present 1

+ nameConflict 0

+ attributes 0x20 ß File, not a folder

+ ghostedHeader 0

+ data 0

+ gvsn {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 ß The GVSN has been increased and is higher than the UID. Since this is the only change that has happened since the file was created, it is incremented by one.

+ uid {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 ß The UID reflects that the file was originally created on this server (same GUID)

+ parent {21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}-v1

+ fence 16010101 00:00:00.000

+ clockDecrementedInDirtyShutdown 0

+ clock 20080908 16:40:55.341 GMT (0x1c911d1a9ebf1e5)

+ createTime 20080908 16:39:09.288 GMT

+ csId {21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} ß The content set ID is for the RDCRF replicated folder

+ hash 00000000-00000000-00000000-00000000

+ similarity 00000000-00000000-00000000-00000000

+ name pooltag.txt ß the file in question

+

<Upstream> 20080908 09:40:55.341 2880 RDCS 807 FrsSimilarityManager::Delete Deleteing similarity data. Vol:{3C84BB07-22D1-11DD-862B-806E6F6E6963} FileId:0x300000000BA79 ß existing RDC similarity signature information deleted for the upstream copy fo the file, as it will need to be recalculated during staging. This is part of cross-file similarity only.

<Upstream> 20080908 09:40:55.341 2880 USNC 2364 UsnConsumer::UpdateIdRecord ID record updated from USN_RECORD: ß USN update occurs on upstream partner. Technically the USN update itself occurs before, but this operation also reflects updating the DFSR database with USN information.

+ USN_RECORD:

+ RecordLength: 88

+ MajorVersion: 2

+ MinorVersion: 0

+ FileRefNumber: 0x300000000BA79 ß same File ID as above, it’s the same file

+ ParentFileRefNumber: 0x1000000000A77E

+ USN: 0x2618a08

+ TimeStamp: &nb