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

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