Ask the Directory Services Team

31 MIN READ

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

Former Employee

Apr 04, 2019

First published on TechNet on Apr 08, 2009

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 of 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 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 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 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 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 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)

<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 receiving 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