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

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

  • Comments 1
  • Likes

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:           20080908 09:40:55.341 Pacific Standard Time

+       Reason:              Close Data Extend Data Overwrite ß the file has been modified

+       SourceInfo:          0x0

+       SecurityId:          0x0

+       FileAttributes:      0x20 ß file, not a folder

+       FileNameLength:      22

+       FileNameOffset:      60

+       FileName:            pooltag.txt ß file is the ‘pooltag.txt’ covered by this scenario

+      

<Upstream> 20080908 09:40:55.341 2880 LDBX  4300 Ldb::UpdateLastVersion Updating lastVersion:18

<Upstream> 20080908 09:40:55.341 2880 LDBX  3340 LdbManager::WakeUpSleepers Wake up callback 00887470

<Upstream> 20080908 09:40:55.341 2708 UPST  1399 UpstreamTransport::FlushVvUp 001A17F0

<Upstream> 20080908 09:40:55.341 2708 UPST  1417 UpstreamTransport::FlushVvUp send connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} seqNumber:8 status:0 vvGeneration:4 vvUp:

<Upstream> 20080908 09:40:55.341 2632 SRTR  1880 SERVER_RequestVersionVector Received from connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} seqNumber:9 changeType:all

<Upstream> 20080908 09:40:55.341 2632 SRTR  1927 SERVER_AsyncPoll Received from connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5}

<Upstream> 20080908 09:40:55.341 2632 UPST  1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:001A17F0

<Upstream> 20080908 09:40:55.341 2708 UPST  1399 UpstreamTransport::FlushVvUp 001A17F0

<Upstream> 20080908 09:40:55.341 2708 UPST  1417 UpstreamTransport::FlushVvUp send connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} seqNumber:9 status:0 vvGeneration:4 vvUp:{5CB120DE-D2C2-452A-8280-B45FC155224F} |-> { 16..18}

+      

<Upstream> 20080908 09:40:55.341 2632 SRTR   882 SERVER_RequestUpdates Received from connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} credits:32 requestType:all ß Upstream server receives a request from downstream to send update information

<Upstream> 20080908 09:40:55.341 2632 UPST    88 UpdateBuffer::UpdateBuffer UpdateBuffer created. connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Upstream> 20080908 09:40:55.341 2632 SRTR  1927 SERVER_AsyncPoll Received from connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5}

<Upstream> 20080908 09:40:55.341 2632 UPST  1297 UpstreamTransport::AddAsyncPoll Inserted new async request rpcStatePtr:001A11B0

<Upstream> 20080908 09:40:55.341 2708 JOIN  1167 Join::SubmitUpdate Sent: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 name:pooltag.txt connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} csName:rdcrf ß Upstream sends update information to the downstream server through RPC.

<Upstream> 20080908 09:40:55.341 2708 UPST   145 UpdateBuffer::SubmitUpdate Update buffered. connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} updateCount:0 totalCredits:32 updateUid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 updateGvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

<Upstream> 20080908 09:40:55.341 2708 UPST   221 UpdateBuffer::FlushUpdates Completing async updates call. connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} updateCount:1 totalCredits:32 status:0 completionStatus:0

<Upstream> 20080908 09:40:55.341 2708 UPST    98 UpdateBuffer::~UpdateBuffer UpdateBuffer deleted. connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Upstream> 20080908 09:40:55.341 2632 SRTR  2136 InitializeFileTransferAsyncState::Start 00844750

<Upstream> 20080908 09:40:55.341 2036 SRTR  2177 InitializeFileTransferAsyncState::ProcessIoCompletion 00844750

<Upstream> 20080908 09:40:55.341 2036 OUTC   784 OutConnection::OpenFile Received request for update: ß Upstream server now prepared to serve the modified file

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       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}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            pooltag.txt

+       rdcDesired:1 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} rgName:RDCRG

<Upstream> 20080908 09:40:55.341 2036 RDCX   639 Rdc::MyFRS_RDC_FILEINFO::ComputeRecursionDepth RecursionDepth = 1, filesize=123431 ß Upstream server prepares to calculate RDC data for a file

<Upstream> 20080908 09:40:55.341 2036 OUTC   875 OutConnection::OpenFile rdcDesired=1, filesize=123431, rdcMinFileSizeInKb=64, rdcSignatureLevels=1 ß RDC configuration data (RDC should be used, file size, minimum size that RDC can be used with, how many signature levels can be used (i.e. signatures of signatures – depends on file size))

<Upstream> 20080908 09:40:55.341 2036 OUTC  2188 OutConnection::GetStageReaderOrWriter ß Check if the file is already staged correctly with up to date hash and signatures. In this case it’s not.

+       fid                             0x300000000BA79

+       usn                             0x2618a08

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080908 16:40:55.341 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       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}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            pooltag.txt

+       Failed to get stage reader as the file is not staged ß notes that staging will now need to occur as the file did not already exist with the same info

<Upstream> 20080908 09:40:55.341 2036 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloading (refCount==1) ß the file is locked in the replicated folder temporarily so that it cannot be modified while being copied into staging.

<Upstream> 20080908 09:40:55.341 2036 STAG  4305 Staging::FindAllFiles Older version found:17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-Downloaded.frx ß find any older staged versions of the file so that they can be deleted prior to superseding

<Upstream> 20080908 09:40:55.341 2952 SRTR  1880 SERVER_RequestVersionVector Received from connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} seqNumber:10 changeType:notify

<Downstream> 20080908 09:40:55.348 2152 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} reqType:VvUpRequest reqState:Completed status:0 ptr:00D832E8

<Upstream> 20080908 09:40:55.373 2036 STAG  4113 Staging::OpenForWrite name:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 ß file now copied into staging and compressed with XPRESS

<Upstream> 20080908 09:40:55.373 2036 OUTC  2225 OutConnection::GetStageReaderOrWriter ß the file has been staged and is ready to be acted upon by RDC

+       fid                             0x300000000BA79

+       usn                             0x2618a08

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080908 16:40:55.341 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       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}

+       hash                            00000000-00000000-00000000-00000000

+       similarity                      00000000-00000000-00000000-00000000

+       name                            pooltag.txt

+       StageReader:00000000 StageWriter:0083F750 Policy:0

<Upstream> 20080908 09:40:55.373 2036 RDCX   639 Rdc::MyFRS_RDC_FILEINFO::ComputeRecursionDepth RecursionDepth = 1, filesize=123699 ß information about the file that will be used by RDC processing (size here is uncompressed)

<Upstream> 20080908 09:40:55.373 2036 RDCX  3622 Rdc::FrsSignatureIndexFile::Open Opening FrsSignatureIndexFile OK for write Levels=1..1 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 ß Alternate datastream of RDC opened

<Upstream> 20080908 09:40:55.373 2036 RDCX   462 StreamToIndex RDC generate begin: (0..1), uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} ß RDC signature generation begins

<Upstream> 20080908 09:40:55.373 2036 RDCX   176 SignatureGenerator Level=0, Depth = 1 ß depth refers to ‘signatures of signatures’. A larger file can have signatures created based on other signatures.

<Upstream> 20080908 09:40:55.373 2036 RDCX   208 SignatureGenerator Similarity enabled

<Upstream> 20080908 09:40:55.373 2036 MRSH  4615 Marshaller::Marshal FileAttrs in metadata : 0x20

<Upstream> 20080908 09:40:55.373 2036 RDCX   504 StreamToIndex RDC generate end: (0..1), uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} ß RDC signature generation is complete

<Upstream> 20080908 09:40:55.373 2036 CSMG  4844 ContentSetManager::UpdateHash LDB Updating ID Record: ß Hash and RDC similarity data now added to the DFSR database

+       fid                             0x300000000BA79

+       usn                             0x2618a08

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               0

+       meetReanimated                  0

+       recUpdateTime                   20080908 16:40:55.341 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       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}

+       hash                            4EE34B30-5AE41344-E837A741-2F45F5D9 ß file hash checksum now set

+       similarity                      2F003931-38353202-2221050D-34192B12 ß similarity ‘master’ checksum now set

+       name                            pooltag.txt

+      

<Upstream> 20080908 09:40:55.482 2036 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Upstream> 20080908 09:40:55.482 2036 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloaded (refCount==1)

<Upstream> 20080908 09:40:55.482 2036 STAG  3012 Staging::UpdateContentSetInfo Update contentInfoHistory

<Upstream> 20080908 09:40:55.482 2036 STAG  2739 Staging::AddCommitFile File added: 49152 access time: 20080908 16:40:55.341 reserved: 0 new usage: 98304

<Upstream> 20080908 09:40:55.482 2036 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloading (refCount==0)

<Upstream> 20080908 09:40:55.482 2036 STAG   799 StageWriter::CompleteDownloadStage Completed download or stage file 18-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18-Downloaded.frx ß file now fully staged and ready to serve

<Upstream> 20080908 09:40:55.482 2036 OUTC  1313 OutConnection::OpenFile WRITE_FILE_TO_STAGE record.simData=(2F003931-38353202-2221050D-34192B12,4EE34B30-5AE41344-E837A741-2F45F5D9)

<Upstream> 20080908 09:40:55.482 2036 OUTC  1476 OutConnection::OpenFile Prepare to serve over RDC uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt fileSize:123699  connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} rgName:RDCRG ß RDC signature information can be sent to the downstream partner through RPC so that the downstream can request the blocks for any missing signatures on the downstream copy

<Upstream> 20080908 09:40:55.482 2036 RDCX  3067 Rdc::SyncServerState::CreateReaders RDC Creating readers: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} ß read signature info from the staged file in order to send to downstream

<Upstream> 20080908 09:40:55.482 2036 RDCX  3622 Rdc::FrsSignatureIndexFile::Open Opening FrsSignatureIndexFile OK for read Levels=1..1 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

<Upstream> 20080908 09:40:55.482 2036 RDCX  3093 Rdc::SyncServerState::CreateReaders Opening level:1

<Upstream> 20080908 09:40:55.482 2708 STAG   108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Upstream> 20080908 09:40:55.482 2708 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Partial (refCount==1)

<Upstream> 20080908 09:40:55.482 2708 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Partial (refCount==0)

<Upstream> 20080908 09:40:55.482 2708 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloading (refCount==1)

<Upstream> 20080908 09:40:55.482 2708 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloading (refCount==0)

<Upstream> 20080908 09:40:55.482 2708 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloaded (refCount==1) ß previously staged version of the file locked for deletion

<Upstream> 20080908 09:40:55.482 2708 STAG  2840 Staging::FileDeleted File deleted: 49152 access time: 20080908 16:39:09.648 new usage: 49152

<Upstream> 20080908 09:40:55.482 2708 STAG  3012 Staging::UpdateContentSetInfo Update contentInfoHistory

<Upstream> 20080908 09:40:55.482 2708 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloaded (refCount==0)

<Upstream> 20080908 09:40:55.482 2708 STAG   223 StagingCleanupTask::DeleteQueuedFiles Deleted uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 ß older version of the staged file deleted

<Downstream> 20080908 09:40:55.488 1044 DOWN  1272 WrapRpcInitializeFileTransferAsync 0

<Downstream> 20080908 09:40:55.488 1044 RDCX   764 Rdc::SeedFile::Initialize RDC signatureLevels:1, uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt fileSize(approx):131072 csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} enableSim=1 ß downstream server must read signature information from its own copy of the file now in order to compare with upstream

<Downstream> 20080908 09:40:55.488 1044 RDCX   833 Rdc::SeedFile::Initialize Level is 1

<Downstream> 20080908 09:40:55.488 1044 RDCX   902 Rdc::SeedFile::Initialize enableSimilarity=1, simData=2F003931-38353202-2221050D-34192B12,4EE34B30-5AE41344-E837A741-2F45F5D9

<Upstream> 20080908 09:40:55.498 2036 OUTC  1534 OutConnection::OpenFile Sent file uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 name:pooltag.txt fileSize:45314 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} rgName:RDCRG ß file is not truly being sent yet, this is a misleading log entry. Downstream is still deciding what it needs, the upstream is ready to send.

<Upstream> 20080908 09:40:55.498 2036 OUTC  1542 OutConnection::OpenFile Update syncInfoHistory

<Upstream> 20080908 09:40:55.498 2036 SRTR  2357 InitializeFileTransferAsyncState::ProcessIoCompletion Initialized connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} rdc:1 context:0084BC10,008B4C28,00000000 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 ptr:00844750

<Downstream> 20080908 09:40:55.504 1044 RDCX  1262 Rdc::SeedFile::UseSimilar similarrelated (SimMatches=14) uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} (related: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}) ß downstream has decided to use RDC between these two GVSN versions of the file (which has matching UID)

<Downstream> 20080908 09:40:55.504 1044 OUTC  2188 OutConnection::GetStageReaderOrWriter ß check to see if the file is already staged on downstream so that signatures can be compared.

+       fid                             0x300000000BA2C

+       usn                             0x26331a8

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               1

+       meetReanimated                  0

+       recUpdateTime                   20080908 16:39:09.656 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 ß this is the previous version.

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

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

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080908 16:39:09.319 GMT (0x1c911d16aba44f8)

+       createTime                      20080908 16:39:09.288 GMT

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

+       hash                            038209BA-4AAA2DF7-FAAF1C1D-7A61284A

+       similarity                      3B003931-38353202-2221050D-34193912

+       name                            pooltag.txt

+       Failed to get stage reader as the file is not staged ß not yet staged downstream

<Downstream> 20080908 09:40:55.504 1044 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloading (refCount==1) ß file locked in order to be staged downstream

<Downstream> 20080908 09:40:55.504 1044 STAG  4113 Staging::OpenForWrite name:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 ß file written into staging

<Downstream> 20080908 09:40:55.504 1044 OUTC  2225 OutConnection::GetStageReaderOrWriter

+       fid                             0x300000000BA2C

+       usn                             0x26331a8

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               1

+       meetReanimated                  0

+       recUpdateTime                   20080908 16:39:09.656 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

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

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080908 16:39:09.319 GMT (0x1c911d16aba44f8)

+       createTime                      20080908 16:39:09.288 GMT

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

+       hash                            038209BA-4AAA2DF7-FAAF1C1D-7A61284A

+       similarity                      3B003931-38353202-2221050D-34193912

+       name                            pooltag.txt

+       StageReader:00000000 StageWriter:00D7F750 Policy:0

<Downstream> 20080908 09:40:55.504 1044 SETT   153 Settings::GenericDwordSetting::operator () Assigned default value. valueName:AsyncReadThresholdBytes value:262144

<Downstream> 20080908 09:40:55.504 1044 RDCX  1510 Rdc::SeedFile::UseRelated Staging "UIDRelated" file uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} (related: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52})

<Downstream> 20080908 09:40:55.504 1044 RDCX  3622 Rdc::FrsSignatureIndexFile::Open Opening FrsSignatureIndexFile OK for write Levels=1..1 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

<Downstream> 20080908 09:40:55.504 1044 RDCX   462 StreamToIndex RDC generate begin: (0..1), uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Downstream> 20080908 09:40:55.504 1044 RDCX   176 SignatureGenerator Level=0, Depth = 1

<Downstream> 20080908 09:40:55.504 1044 RDCX   208 SignatureGenerator Similarity enabled

<Downstream> 20080908 09:40:55.504 1044 MRSH  4615 Marshaller::Marshal FileAttrs in metadata : 0x20

<Downstream> 20080908 09:40:55.520 1044 RDCX   504 StreamToIndex RDC generate end: (0..1), uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Downstream> 20080908 09:40:55.598 1044 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Downstream> 20080908 09:40:55.598 1044 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloaded (refCount==1)

<Downstream> 20080908 09:40:55.598 1044 STAG  3012 Staging::UpdateContentSetInfo Update contentInfoHistory

<Downstream> 20080908 09:40:55.598 1044 STAG  2739 Staging::AddCommitFile File added: 49152 access time: 20080908 16:40:55.504 reserved: 0 new usage: 53248

<Downstream> 20080908 09:40:55.598 1044 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloading (refCount==0)

<Downstream> 20080908 09:40:55.598 1044 STAG   799 StageWriter::CompleteDownloadStage Completed download or stage file 17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-Downloaded.frx

<Downstream> 20080908 09:40:55.598 1044 RDCC    91 RdcCache::Find 0xF00000000A77E pooltag.txt ß similarity_table being used to find a similar file reference

<Downstream> 20080908 09:40:55.598 1044 RDCC   232 RdcCache::MatchSuffix Nothing found for \\.\c:\rdcrf\DfsrPrivate\ConflictAndDeleted\pooltag.txt*

<Downstream> 20080908 09:40:55.598 1044 RDCC   284 RdcCache::MatchPaths 0xF00000000A77E pooltag.txt (root: 0xF00000000A77E)

<Downstream> 20080908 09:40:55.598 1044 RDCX  3622 Rdc::FrsSignatureIndexFile::Open Opening FrsSignatureIndexFile OK for read Levels=1..1 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

<Downstream> 20080908 09:40:55.598 1044 RDCX  2265 Rdc::SeedFile::OpenSeedSigDB Using seed file for uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} seed(type:UIDRelated uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 fileName:pooltag.txt depth=1)

<Downstream> 20080908 09:40:55.598 1044 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloading (refCount==1)

<Downstream> 20080908 09:40:55.598 1044 STAG  4305 Staging::FindAllFiles Older version found:17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-Downloaded.frx

<Downstream> 20080908 09:40:55.613 1044 STAG  4113 Staging::OpenForWrite name:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

<Downstream> 20080908 09:40:55.613 1044 RDCX  3622 Rdc::FrsSignatureIndexFile::Open Opening FrsSignatureIndexFile OK for write Levels=1..1 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

<Downstream> 20080908 09:40:55.613 1044 XRNA    55 XpressRdcNeedAssembler::XpressRdcNeedAssembler this:00E19D18

<Downstream> 20080908 09:40:55.613 1044 XRNA   967 XpressRdcNeedAssembler::GetSourceRdcNeedDataAsync Starting RDC source thread. this:00E19D18

<Downstream> 20080908 09:40:55.613 2564 SETT   153 Settings::GenericDwordSetting::operator () Assigned default value. valueName:AsyncRpcDownloadMinSizeInBytes value:65536

<Downstream> 20080908 09:40:55.613 2564 XRNA   833 XpressRdcNeedAssembler::GetSourceRdcNeedDataThread Entering RDC source need download thread. this:00E19D18 (use RPC async pipe:0)

<Downstream> 20080908 09:40:55.613 2564 XRNA   919 XpressRdcNeedAssembler::GetSourceRdcNeedDataThread Exiting RDC source need download thread. this:00E19D18

<Downstream> 20080908 09:40:55.613 1044 XRNA   276 XpressRdcNeedAssembler::ProcessRdcNeeds All needs processed. this:00E19D18

<Downstream> 20080908 09:40:55.613 1044 XRNA   291 XpressRdcNeedAssembler::FinalizeRpcDownload Shutting down RPC pipe thread this:00E19D18

<Upstream> 20080908 09:40:55.623 2952 SRTR  1513 SERVER_RdcGetSignatures Sent context:0084BC10,008B4C28,00000000 level:1 offset:0 length:65536, sizeRead:1050 uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Upstream> 20080908 09:40:55.623 2952 SRTR  1604 SERVER_RdcPushSourceNeeds offset:0, length: 2020

<Upstream> 20080908 09:40:55.623 2952 SRTR  1604 SERVER_RdcPushSourceNeeds offset:121665, length: 2034

<Upstream> 20080908 09:40:55.623 2952 SRTR  1623 SERVER_RdcPushSourceNeeds Received context:0084BC10,008B4C28,00000000, needCount:2 ß RDC signature ‘needs’ sent through RPC to downstream

<Upstream> 20080908 09:40:55.623 2952 SRTR  1727 SERVER_RdcGetFileData Sent context:0084BC10,008B4C28,00000000 2013

<Upstream> 20080908 09:40:55.623 2952 SRTR  1727 SERVER_RdcGetFileData Sent context:0084BC10,008B4C28,00000000 0 ß RDC blocks arrive through RPC to the downstream server

<Downstream> 20080908 09:40:55.692 1044 ASYN   510 AsyncUnbufferedFileWriter::Close Async WRITE Statistics:

<Downstream> 20080908 09:40:55.692 1044 RDCX  1811 Rdc::SyncClientState::Flush Rdc Need Assembler Statistics: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} ß RDC statistics written to log about what was sent over wire (could be seen in Performance monitor as well, to some extent)

+       TOTAL

+       Compression Ratio            64

+       Target Uncompress Size            123699 ß raw size of the file

+       Target Compress Size               45118 ß XPRESS compressed size of the file

+       Bytes Received                      3063 Signatures:       1050 Data:       2013 ß data sent over the wire (bytes of signatures, bytes of file blocks)

+       Signature Bytes Received            1050           1050

+       Number of remote calls                 4 Signatures:          1 Needs:          1 Data:          2

+       SEED

+       Rdc Need Size                          0             0

+       Xpress Blocks                         15            15

+       Uncompressed Xpress Blocks             2             2

+       Blocks copied to target               13            13

+       SOURCE

+       Rdc Need Size                       4054           0

+       Xpress Blocks                          3           0

+       Uncompressed Xpress Blocks             1           0

+       Blocks copied to target                0           0

<Downstream> 20080908 09:40:55.692 1044 XRNA    89 XpressRdcNeedAssembler::~XpressRdcNeedAssembler this:00E19D18

<Downstream> 20080908 09:40:55.692 1044 INCO  5735 InConnection::RdcGet Update syncInfoHistory

<Downstream> 20080908 09:40:55.692 1044 INCO  5610 InConnection::LogTransferActivity Received RDCGET uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 fileName:pooltag.txt connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} stagedSize:45314

<Downstream> 20080908 09:40:55.692 1044 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Downstream> 20080908 09:40:55.692 1044 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloaded (refCount==0)

<Downstream> 20080908 09:40:55.692 1044 MEET  1970 Meet::Download Done downloading content updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß data done being replicated to downstream

<Downstream> 20080908 09:40:55.692 1044 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloaded (refCount==1) ß downstream copy of the file locked for adding RDC data

<Downstream> 20080908 09:40:55.692 1044 STAG  3012 Staging::UpdateContentSetInfo Update contentInfoHistory

<Downstream> 20080908 09:40:55.692 1044 STAG  2739 Staging::AddCommitFile File added: 49152 access time: 20080908 16:40:55.598 reserved: 0 new usage: 102400 ß file blocks added to the downstream staged file

<Downstream> 20080908 09:40:55.692 1044 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloading (refCount==0)

<Downstream> 20080908 09:40:55.692 1044 STAG   799 StageWriter::CompleteDownloadStage Completed download or stage file 18-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18-Downloaded.frx ß staging and replicating done for the file downstream

<Downstream> 20080908 09:40:55.692 1044 MEET  2570 Meet::TransferToInstalling ß file now needs to be decompressed into the Installing folder.

<Downstream> 20080908 09:40:55.692 1044 MRSH  3959 MarshalContext::Initialize Create file:[pooltag-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18.txt] with attributes:0x20

<Downstream> 20080908 09:40:55.692 1044 MEET  2585 Meet::TransferToInstalling Transferring content from staging area into Installing updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß ready to process file copy into the Installing directory (now decompressed)

<Downstream> 20080908 09:40:55.692  808 STAG   108 StagingCleanupTask::Run Start to cleanup private staging directory. csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Downstream> 20080908 09:40:55.692  808 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Partial (refCount==1)

<Downstream> 20080908 09:40:55.692  808 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Partial (refCount==0)

<Downstream> 20080908 09:40:55.692  808 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloading (refCount==1)

<Downstream> 20080908 09:40:55.692  808 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloading (refCount==0)

<Downstream> 20080908 09:40:55.692  808 STAG  1218 Staging::LockedFiles::Lock Successfully locked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloaded (refCount==1)

<Upstream> 20080908 09:40:55.701 2952 SRTR  1772 SERVER_RdcClose uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5}

<Upstream> 20080908 09:40:55.701 2952 RDCX  2833 Rdc::SyncServerState::~SyncServerState RDC Need Reader Statistics: uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} ß upstream server logs RDC statistics for Performance counter historical information

+       TOTAL                       

+       Compression Ratio            25

+       RDC Need Size                4054

+       Bytes sent to downstream     3063

+       Uncompressed XPRESS blocks   0

+       Compressed XPRESS blocks     1

+       Copied XPRESS Blocks         0

+       Bytes read using async I/Os  0

<Upstream> 20080908 09:40:55.701 2952 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Upstream> 20080908 09:40:55.701 2952 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloaded (refCount==0)

<Downstream> 20080908 09:40:55.707 1044 ASYN  1291 AsyncUnbufferedFileReader::Close Async READ Statistics:

<Downstream> 20080908 09:40:55.707 1044 MEET  2618 Meet::TransferToInstalling Obtaining fid of the newly installed file updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf

<Downstream> 20080908 09:40:55.707 1044 MEET  2631 Meet::TransferToInstalling Read 123699 bytes, wrote 123699 bytes updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß file decompressed from Staging into Installing with real name

<Downstream> 20080908 09:40:55.707 1044 MEET  2032 Meet::Download Download Succeeded : true updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} ß The staging and Installing folder processing is done on the downstream

<Downstream> 20080908 09:40:55.707 1044 FIDL   110 FidLockMan::Lock Read: 0xF00000000A77E

<Downstream> 20080908 09:40:55.707 1044 FIDL   115 FidLockMan::Lock Write: 0x300000000BA2C

<Downstream> 20080908 09:40:55.707 1044 FIDL   115 FidLockMan::Lock Write: 0x300000000BA2F

<Downstream> 20080908 09:40:55.707 1044 FIDL   135 FidLockMan::Lock read: 1 write: 2 0

<Downstream> 20080908 09:40:55.707 1044 MEET  1434 Meet::InstallStep Start transaction

<Downstream> 20080908 09:40:55.707 1044 MEET  5486 Meet::FindUidRelated Obtain USN information for file on disk

<Downstream> 20080908 09:40:55.707 1044 MEET  3840 Meet::ProcessUid Uid related found uidRelated:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf

<Downstream> 20080908 09:40:55.707 1044 MEET  5694 Meet::LocalDominates Remote version dominates localgvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß this is not a true conflict occurring, this is a side effect of the level 5 debug verbosity. It is simply a conflict check.

<Downstream> 20080908 09:40:55.707 1044 MEET  5274 Meet::FindNameRelated Access name conflicting file. updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf

<Downstream> 20080908 09:40:55.707 1044 MEET  4256 Meet::GetNameRelated Name related not found. updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß Not a conflict

<Downstream> 20080908 09:40:55.707 1044 MEET  3034 Meet::UidInheritEnabled UidInheritEnabled:0 updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf

<Downstream> 20080908 09:40:55.707 1044 MEET  2772 Meet::InstallRename Move out previous version of same file updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß previous version of the file must now be overwritten.

<Downstream> 20080908 09:40:55.707 1044 MEET  4867 Meet::MoveOut Moving contents and children out of replica. newName:pooltag-{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17.txt updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf record: ß previous version is overwritten. This actually causes a deletion to occur as we will see below.

+       fid                             0x300000000BA2C

+       usn                             0x26331a8

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               1

+       meetReanimated                  0

+       recUpdateTime                   20080908 16:39:09.656 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

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

+       fence                           16010101 00:00:00.000

+       clockDecrementedInDirtyShutdown 0

+       clock                           20080908 16:39:09.319 GMT (0x1c911d16aba44f8)

+       createTime                      20080908 16:39:09.288 GMT

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

+       hash                            038209BA-4AAA2DF7-FAAF1C1D-7A61284A

+       similarity                      3B003931-38353202-2221050D-34193912

+       name                            pooltag.txt

+      

<Downstream> 20080908 09:40:55.707 1044 MEET  4989 Meet::MoveOut Purge existing file in Deleted updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß the older version of the file had been moved to the Deleted folder. It is then purged and is gone from the file system.

<Downstream> 20080908 09:40:55.707 1044 MEET  4995 Meet::MoveOut RenameDelete file fid:0x300000000BA2C updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß old version of the file is gone.

<Downstream> 20080908 09:40:55.707 1044 MEET  2796 Meet::InstallRename Tunneling last access time in Installing. lastAccessTime: 20080908 16:39:09.288 updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß the last accessed time of the previous file is ‘tunnelled’ (i.e. written to) the new copy of the file in the Installing directory before the file is written to the replicated folder.

<Downstream> 20080908 09:40:55.707 1044 MEET  2822 Meet::InstallRename Moving contents from Installing to final destination. Attributes:0x20 updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß file moved from Installing to the real replicated folder downstream.

<Downstream> 20080908 09:40:55.707 1044 MEET  2837 Meet::InstallRename File moved. rootVolume:{3C84BB07-22D1-11DD-862B-806E6F6E6963} parentFid:0xF00000000A77E fidInInstalling:0x300000000BA2F usn:0x26359b8 updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß the move from Installing to the RF is complete

<Downstream> 20080908 09:40:55.707 1044 MEET  2866 Meet::InstallRename Update database with new contents updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß the DFSR database must now be updated to reflect the new file information now that the file is replicated and ready for end user access.

<Downstream> 20080908 09:40:55.707 1044 MEET  2940 Meet::InstallRename Updating database. updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf

<Downstream> 20080908 09:40:55.707 1044 MEET  6746 Meet::UpdateIdRecord LDB Updating ID Record: ß DFSR database updated with the new GVSN, hash, and similarity information

+       fid                             0x300000000BA2F

+       usn                             0x26359b8

+       uidVisible                      1

+       filtered                        0

+       journalWrapped                  0

+       slowRecoverCheck                0

+       pendingTombstone                0

+       internalUpdate                  0

+       dirtyShutdownMismatch           0

+       meetInstallUpdate               1

+       meetReanimated                  0

+       recUpdateTime                   16010101 00:00:00.000 GMT

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 ß Now matches upstream GVSN

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       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}

+       hash                            4EE34B30-5AE41344-E837A741-2F45F5D9

+       similarity                      2F003931-38353202-2221050D-34192B12

+       name                            pooltag.txt

+      

<Downstream> 20080908 09:40:55.707 1044 RDCS   807 FrsSimilarityManager::Delete Deleteing similarity data. Vol:{3C84BB07-22D1-11DD-862B-806E6F6E6963} FileId:0x300000000BA2C

<Downstream> 20080908 09:40:55.707 1044 MEET  2949 Meet::InstallRename -> DONE Install-rename completed updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52}

<Downstream> 20080908 09:40:55.707 1044 MEET  1638 Meet::InstallStep Done installing file updateName:pooltag.txt uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csName:rdcrf ß file replication done for this updated version of the file

<Downstream> 20080908 09:40:55.707 1044 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18 state: Downloaded (refCount==0)

<Downstream> 20080908 09:40:55.707 1044 INCO  5897 InConnection::UpdateProcessed Received Update. updatesLeft:0 processed:1 failures:0 sessionId:3 open:0 updateType:0 processStatus:0 connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} csName:rdcrf update:

+       present                         1

+       nameConflict                    0

+       attributes                      0x20

+       ghostedHeader                   0

+       data                            0

+       gvsn                            {5CB120DE-D2C2-452A-8280-B45FC155224F}-v18

+       uid                             {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17

+       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}

+       hash                            4EE34B30-5AE41344-E837A741-2F45F5D9

+       similarity                      2F003931-38353202-2221050D-34192B12

+       name                            pooltag.txt

+      

<Downstream> 20080908 09:40:55.707  808 STAG  2840 Staging::FileDeleted File deleted: 49152 access time: 20080908 16:40:55.692 new usage: 53248

<Downstream> 20080908 09:40:55.707  808 STAG  3012 Staging::UpdateContentSetInfo Update contentInfoHistory

<Downstream> 20080908 09:40:55.707  808 STAG  1266 Staging::LockedFiles::Unlock Unlocked file UID: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 GVSN: {5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 state: Downloaded (refCount==0)

<Downstream> 20080908 09:40:55.707  808 STAG   223 StagingCleanupTask::DeleteQueuedFiles Deleted uid:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 gvsn:{5CB120DE-D2C2-452A-8280-B45FC155224F}-v17 ß previous version of staged file is deleted

<Downstream> 20080908 09:40:55.707 1044 LDBX  3340 LdbManager::WakeUpSleepers Wake up callback 00DC73C0

<Downstream> 20080908 09:40:55.707 1044 INCO  6169 InConnection::CommitSession Committing connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} csName:rdcrf session:3 delta:1 newVersionVector intervals:1 vector:{5CB120DE-D2C2-452A-8280-B45FC155224F} |-> { 16..18}

+      

<Downstream> 20080908 09:40:55.707 1044 INCO  1909 InConnection::InSync Checking for in sync. connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5}

<Downstream> 20080908 09:40:55.707 1044 INCO  6194 InConnection::CommitSession Connection in sync connId:{68E26C24-5C97-47A2-9F54-0309E426B2C5} csId:{21A87CB1-5E1D-47A0-A47A-4DF9A4F93C52} csName:rdcrf commitedSessionsWithUpdateFailures:0

<Downstream> 20080908 09:40:55.707 1044 INCO  6200 InConnection::CommitSession Update syncInfoHistory

<Downstream> 20080908 09:40:55.707 1044 HIST  1177 StateHistory::Update Fire sync info record state update ß downstream server is now completely in sync with upstream and has no receieving backlog

+       syncGuid               {403E4E1A-2E57-4DEA-AD75-808855B6EE9F}

+       state                  In Sync

+       initReason             Schedule

+       connectionGuid         {68E26C24-5C97-47A2-9F54-0309E426B2C5}

+       replicationGroupGuid   {5CB973F5-6B04-40D6-AAD9-85F2855F6AC5}

+       replicationGroupName   RDCRG

+       memberGuid             {3D0C9825-BC62-4D16-94F8-BC73BC3438D4}

+       memberName             2008X86FSRV11

+       updatedNotTransferred  0

+       updatedTransferred     1

+       updatedToBeTransferred 1

+       byteTransferred        45314

+       tombstonesGenerated    0

+       conflictsGenerated     0

+       currentForceReplicationEndTime 16010101 00:00:00.000

+       currentForceReplicationBandwidthlevel *

+      

 

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, 106 blogs have new articles in the pa st 7 days. 256 new articles