First published on TechNet on Apr 06, 2009
In this scenario we will see a new Replication Group and Replicated Folder created. The upstream replicated folder will contain a few files that do not yet exist on the downstream member. This is useful to understand as one of the most common troubleshooting areas in DFSR is the actual configuration and initial synchronization phase.
(newrgrfprimary - Dfsr00020 - 2008.log and newrgrfnonauth - Dfsr00017 - 2008.log)
These are two Windows Server 2008 servers called 2008MEM01 and 2008MEM02 in the fabrikam.com domain. The logs are from 2008MEM01 (which is the Primary, aka authoritative, member) and from 2008MEM02 (which is the non-authoritative member). Both servers are participating in the NEWRG1 replication group for the NEWRF1 replicated folder.
This log has a significant portion of data removed for readability – review previous sections for configuration and large file add.
<Downstream> 20080627 11:48:55.634 300 RSMG 142 ReplicaSetManager::Initialize Initialize replication group rgName:NewRG1 << The replica set manager is initializing the replication group on the downstream partner. Because each member of an RG must find out about the topology from the DC it is bound to, and because each member checks on its own schedule, all members will find out at different times.
<Downstream> 20080627 11:48:55.634 300 RSMG 908 ReplicaSetManager::AddInConnection Creating new inbound connection connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} rgName:NewRG1
<Downstream> 20080627 11:48:55.634 300 RSMG 1273 ReplicaSetManager::AddOrUpdateConnection New or updated outbound connection object. connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} rgName:NewRG1 << inbound and outbound connections are made.
<Downstream> 20080627 11:48:55.634 300 CCTX 2401 ConfigContext::ApplyDiff Updating volume in ConfigContext, volumePath:\\.\C:
<Downstream> 20080627 11:48:55.634 300 FREP 450 FrsReplicator::UpdateVolume Update Volume:3EA8BD01-416E-11DD-A317-806E6F6E6963
<Downstream> 20080627 11:48:55.634 300 VLMG 2327 VolumeManager::AddContentSet Initializing contentSet. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 << the new replicated folder is initialized
<Downstream> 20080627 11:48:55.634 300 CSMG 546 ContentSetManager::ContentSetManager csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00CC3AA0
<Downstream> 20080627 11:48:55.634 300 CCTX 3237 ConfigContext::DumpReplicaConfig Dumping Replica global config context << entries below must be evaluated from LDAP lookups and written into the XML config files. These are highlighted for reading but are largely self-explanatory:
<Downstream> 20080627 11:48:55.634 300 CPAR 2476 Config::ParamBlock::Print [[ DfsrReplicatedFolder ]]
<Downstream> 20080627 11:48:55.634 300 CPAR 1050 Config::GuidParam::Print ReplicatedFolderGuid: 05631532-B65C-45AF-BB49-F237ACB6CF7C [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 556 Config::StringParam::Print ReplicatedFolderDn: CN=NewRF1,CN=Content,CN=NewRG1,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 556 Config::StringParam::Print ReplicatedFolderName: NewRF1 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 1050 Config::GuidParam::Print ReplicationGroupGuid: 33DACEEE-D60C-4BF1-911C-EA5C487A78CB [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 1050 Config::GuidParam::Print MemberGuid: 0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 911 Config::PathParam::Print RootPath: c:\newrf1 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 204 Config::DWordParam::Print RootSizeInMb: 10240 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 911 Config::PathParam::Print StagingPath: c:\newrf1\DfsrPrivate\Staging [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 204 Config::DWordParam::Print StagingSizeInMb: 4096 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 911 Config::PathParam::Print ConflictPath: c:\newrf1\DfsrPrivate\ConflictAndDeleted [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 204 Config::DWordParam::Print ConflictSizeInMb: 660 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 556 Config::StringParam::Print FileFilter: ~*, *.bak, *.tmp [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 556 Config::StringParam::Print DirectoryFilter: [Flags:0x0]
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print Ghosted: FALSE [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print CacheObeyConnectionSchedule: FALSE [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 204 Config::DWordParam::Print MinAgeInCacheInMin: 0 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 204 Config::DWordParam::Print MaxAgeInCacheInMin: 0 [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print Enabled: TRUE [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print IsPrimary: FALSE [Flags:0x1] << this server is not authoritative for this replica set
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print ReadOnly: FALSE [Flags:0x0]
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print DisableSaveDeletes: FALSE [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print DisableReanimateDeletes: FALSE [Flags:0x1]
<Downstream> 20080627 11:48:55.634 300 CPAR 390 Config::BoolParam::Print SharedStaging: FALSE [Flags:0x0]
<Downstream> 20080627 11:48:55.634 300 CPAR 556 Config::StringParam::Print CompressedExtensions: WMA,WMV,ZIP,JPG,MPG,MPEG,M1V,MP2,MP3,MPA,CAB,WAV,SND,AU,ASF,WM,AVI,Z,GZ,TGZ,FRX [Flags:0x0]
<Downstream> 20080627 11:48:55.634 300 CPAR 556 Config::StringParam::Print Description: <null> [Flags:0x0]
<Downstream> 20080627 11:48:55.634 2764 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:Normal << content set manager not triggers the RF to be created
<Downstream> 20080627 11:48:55.634 2764 CSMG 1779 ContentSetManager::Run Scheduling restart now csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00CC3AA0
<Downstream> 20080627 11:48:55.634 2764 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:Normal
<Downstream> 20080627 11:48:55.634 2764 CSMG 837 ContentSetManager::Initialize csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00CC3AA0 << the replica set is initialized
<Downstream> 20080627 11:48:55.634 2764 CSMG 2298 ContentSetManager::CheckContentSetState Content set csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} state:InitialBuilding
0080627 11:48:55.634 2764 CSMG 3182 ContentSetManager::CreateRootRecord Adding root record csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ghosted:0 << a base record must be added to the DFSR database to identify where the replicated folder tree starts.
<Downstream> 20080627 11:48:55.634 2764 CSMG 3298 ContentSetManager::CreateRootRecord LDB Inserting ID Record: << DFSR DB updated for the RF root record.
+ fid 0x800000000A751
+ usn 0x944b40
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1
+ nameConflict 0
+ attributes 0x10 << the object is a folder
+ ghostedHeader 0
+ data 0
+ gvsn {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
+ uid {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1 << note that the UID/GVSN will match and when creating the very first RF of all time on a server, will start with v1
+ parent {00000000-0000-0000-0000-000000000000}-v0
+ fence 16010101 00:00:00.000 (I)
+ clockDecrementedInDirtyShutdown 0
+ clock 20080627 15:48:26.547 GMT (0x1c8d86d3cf03e5c)
+ createTime 20080627 15:48:26.547 GMT
+ csId {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name newrf1 << the replicated folder name on the file system
+
<Downstream> 20080627 11:48:55.644 2764 LDBX 4028 Ldb::Insert Inserting contentSetRecord: << the database on this volume is set to initial building status
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59}
+ state: InitialBuilding
+ startVersion: v24
+ authRebuilding: 0
+ stageVolumeSerialNumber: 0
+ stageFid: 0x0
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Downstream> 20080627 11:48:55.684 2764 STAG 2600 Staging::ScanStagingDirectory Staging space usage is: 0 << staging space is checked
<Downstream> 20080627 11:48:55.684 2764 STAG 6158 StagingManager::RegisterContentSetsOnPath {05631532-B65C-45AF-BB49-F237ACB6CF7C} added to the replicated folder list. << the replicated folder GUID is now registered
<Downstream> 20080627 11:48:55.684 2764 LDBX 4062 Ldb::Update Updating contentSetRecord: << The staging directory file ID is now registered in the database
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59}
+ state: InitialBuilding
+ startVersion: v24
+ authRebuilding: 0
+ stageVolumeSerialNumber: 3a34b62834b5e753
+ stageFid: 0x100000000A77F
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Downstream> 20080627 11:48:55.694 2764 CSMG 1274 ContentSetManager::Initialize Walk replica set to initialize or fix up database. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 << DFSR now needs to initialize the replicated folder by walking the directory to find any child objects.
<Downstream> 20080627 11:48:55.694 2764 DIRW 515 DirWalkerTask::QueueMoveinJob Queuing move-in. uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1 fid:0x800000000A751 name:newrf1 << dir walker will walk the replicated folder for objects
<Downstream> 20080627 11:48:55.694 480 DIRW 256 DirWalkerTask::Run Start walking directory. << replicated folder is dir walked
<Downstream> 20080627 11:48:55.694 480 DIRW 945 DirWalkerTask::MoveinStep Starting to process move-in job. uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
<Downstream> 20080627 11:48:55.694 480 DIRW 101 DirWalkerTask::Job::Finish MoveIn csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1 << dirwalk is done for the replicated folder
<Downstream> 20080627 11:48:55.694 480 DIRW 793 DirWalkerTask::RemoveJob Removing job type:1 uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
<Downstream> 20080627 11:48:55.694 480 LDBX 4386 Ldb::DeleteWalkerJob Deleting dirWalkerJob. uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
<Downstream> 20080627 11:48:55.694 480 EVNT 725 EventLog::Report Logging eventId:4102 parameterCount:6 << a 4102 event is logged to show that the downstream (non-authoritative, non-primary) server is ready for initial sync replication to begin.
<Downstream> 20080627 11:48:55.694 480 EVNT 745 EventLog::Report eventId:4102 parameter1:05631532-B65C-45AF-BB49-F237ACB6CF7C
<Downstream> 20080627 11:48:55.694 480 EVNT 745 EventLog::Report eventId:4102 parameter2:c:\newrf1
<Downstream> 20080627 11:48:55.694 480 EVNT 745 EventLog::Report eventId:4102 parameter3:NewRF1
<Downstream> 20080627 11:48:55.694 480 EVNT 745 EventLog::Report eventId:4102 parameter4:NewRG1
<Downstream> 20080627 11:48:55.694 480 EVNT 745 EventLog::Report eventId:4102 parameter5:33DACEEE-D60C-4BF1-911C-EA5C487A78CB
<Downstream> 20080627 11:48:55.694 480 EVNT 745 EventLog::Report eventId:4102 parameter6:0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59
<Downstream> 20080627 11:48:55.694 480 CSMG 2897 ContentSetManager::SetContentSetState Set content set state. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} newState:InitialSync(Sync) (auth:0) << the server is now in initial sync state
<Downstream> 20080627 11:48:55.694 480 LDBX 4062 Ldb::Update Updating contentSetRecord: << database is updated to reflect this state
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59}
+ state: InitialSync(Sync)
+ startVersion: v24
+ authRebuilding: 0
+ stageVolumeSerialNumber: 3a34b62834b5e753
+ stageFid: 0x100000000A77F
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Downstream> 20080627 11:48:55.704 480 CSMG 2697 ContentSetManager::DbBuildComplete Finished scanning content set and building database info: {05631532-B65C-45AF-BB49-F237ACB6CF7C} Transition from InitialBuilding to InitialSync(Sync)
<Downstream> 20080627 11:48:55.704 480 DIRW 303 DirWalkerTask::Run Exit.
<Downstream> 20080627 11:48:55.704 2764 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:InitialBuilding
<Downstream> 20080627 11:48:55.704 2764 CSMG 1779 ContentSetManager::Run Scheduling restart now csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00CC3AA0
<Downstream> 20080627 11:48:55.704 2764 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:InitialBuilding
<Downstream> 20080627 11:48:55.704 2764 CSMG 837 ContentSetManager::Initialize csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00CC3AA0
<Downstream> 20080627 11:48:55.704 2764 CSMG 2262 ContentSetManager::CheckContentSetState Updating content set record csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ghosted:0 readOnly:0 readOnlySince:16010101 00:00:00.000
<Downstream> 20080627 11:48:55.704 2764 CSMG 2298 ContentSetManager::CheckContentSetState Content set csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} state:InitialSync(Sync)
<Downstream> 20080627 11:48:55.704 2764 STAG 2600 Staging::ScanStagingDirectory Staging space usage is: 0
<Downstream> 20080627 11:48:55.714 480 DOWN 3181 DownstreamTransport::SetupBinding Setting authentication information for partner: FABRIKAM\2008MEM01$ << server now tries to start contacting its partner for replication.
<Downstream> 20080627 11:48:55.714 480 DOWN 3363 DownstreamTransport::SetupBinding Setup connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} remoteAddress:2008mem01.fabrikam.com stringBinding:[5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c@ncacn_ip_tcp:2008mem01.fabrikam.com] << an RPC connection is attempted to the remote partner
<Downstream> 20080627 11:48:55.714 480 DOWN 3868 [WARN] DownstreamTransport::EstablishConnection Failed. Try flat name.
+ [Error:9027(0x2343) DownstreamTransport::EstablishConnection downstreamtransport.cpp:3853 480 C A failure was reported by the remote partner]
+ [Error:9026(0x2342) DownstreamTransport::EstablishConnection downstreamtransport.cpp:3853 480 C The connection is invalid] << A “connection is invalid” error means that the other server is not yet aware of this replication topology
<Downstream> 20080627 11:48:55.714 480 DOWN 3181 DownstreamTransport::SetupBinding Setting authentication information for partner: FABRIKAM\2008MEM01$
<Downstream> 20080627 11:48:55.714 480 DOWN 3363 DownstreamTransport::SetupBinding Setup connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} remoteAddress:2008mem01.fabrikam.com stringBinding:[5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c@ncacn_ip_tcp:2008mem01]
<Downstream> 20080627 11:48:55.714 480 DOWN 3887 [ERROR] DownstreamTransport::EstablishConnection EstablishConnection failed. connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} rgName:NewRG1 Error:
+ [Error:9027(0x2343) DownstreamTransport::EstablishConnection downstreamtransport.cpp:3853 480 C A failure was reported by the remote partner]
+ [Error:9026(0x2342) DownstreamTransport::EstablishConnection downstreamtransport.cpp:3853 480 C The connection is invalid]
<Downstream> 20080627 11:48:55.714 480 DOWN 6954 BandwidthThrottler::PrepareForShutdown ptr:00CCB538
<Downstream> 20080627 11:48:55.714 480 DOWN 6963 BandwidthThrottler::PrepareForShutdown Preparing for Shutdown
<< <snipped out constant retries to other member 2008mem01 that has not yet picked up the configuration yet from AD polling>
<Upstream> 20080627 11:53:14.698 324 RSMG 142 ReplicaSetManager::Initialize Initialize replication group rgName:NewRG1 << the upstream server has now picked up the change from LDAP polling
<Upstream> 20080627 11:53:14.698 324 RSMG 908 ReplicaSetManager::AddInConnection Creating new inbound connection connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} rgName:NewRG1
<Upstream> 20080627 11:53:14.698 324 RSMG 1273 ReplicaSetManager::AddOrUpdateConnection New or updated outbound connection object. connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} rgName:NewRG1
<Upstream> 20080627 11:53:14.698 324 CCTX 2401 ConfigContext::ApplyDiff Updating volume in ConfigContext, volumePath:\\.\C:
<Upstream> 20080627 11:53:14.698 324 FREP 450 FrsReplicator::UpdateVolume Update Volume:6A7E9F21-4169-11DD-AF51-806E6F6E6963
<Upstream> 20080627 11:53:14.708 324 VLMG 2327 VolumeManager::AddContentSet Initializing contentSet. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1
<Upstream> 20080627 11:53:14.708 324 CSMG 546 ContentSetManager::ContentSetManager csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00B766B0
<Upstream> 20080627 11:53:14.708 324 CPAR 2476 Config::ParamBlock::Print [[ DfsrReplicationGroup ]]
<Upstream> 20080627 11:53:14.708 324 CPAR 204 Config::DWordParam::Print LastChangeNumber: 1 [Flags:0x0]
<Upstream> 20080627 11:53:14.708 324 CPAR 1244 Config::DateTimeParam::Print LastChangeTime: 6/27/2008 15:53:14 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print LastChangeSource: 2008dc01.fabrikam.com [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print Description: <null> [Flags:0x0]
<Upstream> 20080627 11:53:14.708 324 CPAR 1050 Config::GuidParam::Print ReplicationGroupGuid: 33DACEEE-D60C-4BF1-911C-EA5C487A78CB [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print ReplicationGroupName: NewRG1 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 2476 Config::ParamBlock::Print [[ DfsrConnection ]]
<Upstream> 20080627 11:53:14.708 324 CPAR 1050 Config::GuidParam::Print ConnectionGuid: AF7B6836-D323-4A01-9448-09680B9ACAF5 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print ConnectionDn: CN=45c15215-2233-4e88-aa87-48b75867d7e6,CN=7ee30623-f21f-489d-aa4b-6bdc73dbccc9,CN=Topology,CN=NewRG1,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 1050 Config::GuidParam::Print PartnerGuid: 0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print PartnerName: 2008MEM02 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print PartnerDn: CN=264ffb2a-ac64-4f0b-9701-c9d9c85cb27f,CN=Topology,CN=NewRG1,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print PartnerDns: 2008mem02.fabrikam.com [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print PartnerPrincName: FABRIKAM\2008MEM02$ [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 2476 Config::ParamBlock::Print [[ DfsrReplicatedFolder ]]
<Upstream> 20080627 11:53:14.708 324 CPAR 1050 Config::GuidParam::Print ReplicatedFolderGuid: 05631532-B65C-45AF-BB49-F237ACB6CF7C [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print ReplicatedFolderDn: CN=NewRF1,CN=Content,CN=NewRG1,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print ReplicatedFolderName: NewRF1 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 1050 Config::GuidParam::Print ReplicationGroupGuid: 33DACEEE-D60C-4BF1-911C-EA5C487A78CB [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 1050 Config::GuidParam::Print MemberGuid: 5EF77FE2-B1BF-41B4-9DA6-51F6549F523E [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 911 Config::PathParam::Print RootPath: C:\NewRF1 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 204 Config::DWordParam::Print RootSizeInMb: 10240 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 911 Config::PathParam::Print StagingPath: C:\NewRF1\DfsrPrivate\Staging [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 204 Config::DWordParam::Print StagingSizeInMb: 4096 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 911 Config::PathParam::Print ConflictPath: C:\NewRF1\DfsrPrivate\ConflictAndDeleted [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 204 Config::DWordParam::Print ConflictSizeInMb: 660 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print FileFilter: ~*, *.bak, *.tmp [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 556 Config::StringParam::Print DirectoryFilter: [Flags:0x0]
<Upstream> 20080627 11:53:14.708 324 CPAR 390 Config::BoolParam::Print Ghosted: FALSE [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 390 Config::BoolParam::Print CacheObeyConnectionSchedule: FALSE [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 204 Config::DWordParam::Print MinAgeInCacheInMin: 0 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 204 Config::DWordParam::Print MaxAgeInCacheInMin: 0 [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 390 Config::BoolParam::Print Enabled: TRUE [Flags:0x1]
<Upstream> 20080627 11:53:14.708 324 CPAR 390 Config::BoolParam::Print IsPrimary: TRUE [Flags:0x1] << This server is the upstream and is marked as Primary. It will authoritative for all data.
<Upstream> 20080627 11:53:14.708 3836 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:Normal
<Upstream> 20080627 11:53:14.708 3836 CSMG 837 ContentSetManager::Initialize csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00B766B0
<Upstream> 20080627 11:53:14.708 3836 CSMG 2298 ContentSetManager::CheckContentSetState Content set csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} state:InitialBuilding
<Upstream> 20080627 11:53:14.708 3836 CSMG 3182 ContentSetManager::CreateRootRecord Adding root record csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ghosted:0
<Upstream> 20080627 11:53:14.718 3820 CFAD 7697 Config::AdConfig::CheckSchemaVersion DMD object:CN=Schema,CN=Configuration,DC=fabrikam,DC=com, objectVersion:44
<Upstream> 20080627 11:53:14.738 3836 CSMG 3298 ContentSetManager::CreateRootRecord LDB Inserting ID Record: << root replicated folder record created in the database.
+ fid 0x700000000AC58
+ usn 0xa73000
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1
+ nameConflict 0
+ attributes 0x10
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v82 << GVSN now set to match server GUID. The version is high because there has been other files replicated on this server in a different RG previously.
+ uid {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1 << UID is set to v1 to mark the first folder created on server.
+ parent {00000000-0000-0000-0000-000000000000}-v0
+ fence 16010101 00:00:00.000 P
+ clockDecrementedInDirtyShutdown 0
+ clock 20080627 15:46:41.522 GMT (0x1c8d86cfe56c4bc)
+ createTime 20080627 15:45:37.768 GMT
+ csId {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name NewRF1
+
<Upstream> 20080627 11:53:14.818 3836 LDBX 4028 Ldb::Insert Inserting contentSetRecord: << the database is updated to mark initial building on the Primary server
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {5EF77FE2-B1BF-41B4-9DA6-51F6549F523E}
+ state: InitialBuilding
+ startVersion: v81
+ authRebuilding: 0
+ stageVolumeSerialNumber: 0
+ stageFid: 0x0
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Upstream> 20080627 11:53:14.988 3836 STAG 2600 Staging::ScanStagingDirectory Staging space usage is: 0
<Upstream> 20080627 11:53:14.988 3836 STAG 6158 StagingManager::RegisterContentSetsOnPath {05631532-B65C-45AF-BB49-F237ACB6CF7C} added to the replicated folder list.
<Upstream> 20080627 11:53:14.998 3836 LDBX 4062 Ldb::Update Updating contentSetRecord:
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {5EF77FE2-B1BF-41B4-9DA6-51F6549F523E}
+ state: InitialBuilding
+ startVersion: v81
+ authRebuilding: 0
+ stageVolumeSerialNumber: 48ac1944ac192e46
+ stageFid: 0x100000000AC80
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Upstream> 20080627 11:53:14.998 3836 CSMG 1274 ContentSetManager::Initialize Walk replica set to initialize or fix up database. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1
<Upstream> 20080627 11:53:14.998 3836 DIRW 515 DirWalkerTask::QueueMoveinJob Queuing move-in. uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1 fid:0x700000000AC58 name:NewRF1
<Upstream> 20080627 11:53:14.998 676 DIRW 256 DirWalkerTask::Run Start walking directory. << all files on the Primary server are now walked
<Upstream> 20080627 11:53:14.998 676 DIRW 945 DirWalkerTask::MoveinStep Starting to process move-in job. uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
<Upstream> 20080627 11:53:14.998 676 DIRW 2428 DirWalkerTask::CreateOneRecord LDB Inserting ID Record: << the first file is found by the dirwalker job. In this case it is a copy of ‘explorer.exe’
+ fid 0x100000000AC7C
+ usn 0xa71e60
+ uidVisible 0
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 16010101 00:00:00.000 GMT
+ present 1
+ nameConflict 0
+ attributes 0x20 << it’s a file, not a folder
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v83
+ uid {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v83 << the file UID and GVSN must match at this point
+ parent {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1 << We can tell by the parent that the file is directly in the root of the replicated folder
+ fence 16010101 00:00:00.000 P
+ clockDecrementedInDirtyShutdown 0
+ clock 20080627 15:46:41.600 GMT (0x1c8d86cfe62a5f4)
+ createTime 20080627 15:46:41.522 GMT
+ csId {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name explorer.exe << file name
+
<snipped out several other files that are in original log, for simpler reading>
<Upstream> 20080627 11:53:14.998 676 DIRW 101 DirWalkerTask::Job::Finish MoveIn csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1 << dir walking is done
<Upstream> 20080627 11:53:14.998 676 DIRW 793 DirWalkerTask::RemoveJob Removing job type:1 uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
<Upstream> 20080627 11:53:14.998 676 LDBX 4386 Ldb::DeleteWalkerJob Deleting dirWalkerJob. uid:{05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
<Upstream> 20080627 11:53:14.998 676 EVNT 725 EventLog::Report Logging eventId:4112 parameterCount:6 << a 4112 event is written the event logs in order to mark that the upstream Primary member is now done with its initial sync processing and ready to serve files.
<Upstream> 20080627 11:53:14.998 676 EVNT 745 EventLog::Report eventId:4112 parameter1:05631532-B65C-45AF-BB49-F237ACB6CF7C
<Upstream> 20080627 11:53:14.998 676 EVNT 745 EventLog::Report eventId:4112 parameter2:C:\NewRF1
<Upstream> 20080627 11:53:14.998 676 EVNT 745 EventLog::Report eventId:4112 parameter3:NewRF1
<Upstream> 20080627 11:53:14.998 676 EVNT 745 EventLog::Report eventId:4112 parameter4:NewRG1
<Upstream> 20080627 11:53:14.998 676 EVNT 745 EventLog::Report eventId:4112 parameter5:33DACEEE-D60C-4BF1-911C-EA5C487A78CB
<Upstream> 20080627 11:53:14.998 676 EVNT 745 EventLog::Report eventId:4112 parameter6:5EF77FE2-B1BF-41B4-9DA6-51F6549F523E
<Upstream> 20080627 11:53:15.008 676 CSMG 4599 ContentSetManager::UpdateRootFence LDB Updating ID Record: << a root fence marks data in the content set as authoritative for any conflicts
+ fid 0x700000000AC58
+ usn 0xa73000
+ uidVisible 1
+ filtered 0
+ journalWrapped 0
+ slowRecoverCheck 0
+ pendingTombstone 0
+ internalUpdate 0
+ dirtyShutdownMismatch 0
+ meetInstallUpdate 0
+ meetReanimated 0
+ recUpdateTime 20080627 15:53:14.748 GMT
+ present 1
+ nameConflict 0
+ attributes 0x10
+ ghostedHeader 0
+ data 0
+ gvsn {EDE2D64E-1306-4C7C-B568-449A98371AA2}-v82
+ uid {05631532-B65C-45AF-BB49-F237ACB6CF7C}-v1
+ parent {00000000-0000-0000-0000-000000000000}-v0
+ fence 16010101 00:00:00.000
+ clockDecrementedInDirtyShutdown 0
+ clock 20080627 15:46:41.522 GMT (0x1c8d86cfe56c4bc)
+ createTime 20080627 15:45:37.768 GMT
+ csId {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ hash 00000000-00000000-00000000-00000000
+ similarity 00000000-00000000-00000000-00000000
+ name NewRF1
+
<Upstream> 20080627 11:53:15.008 676 CSMG 2897 ContentSetManager::SetContentSetState Set content set state. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} newState:Normal (auth:0) << Initial sync is now done as far as the authoritative server is concerned. Its state for the replicated folder is set to Normal.
<Upstream> 20080627 11:53:15.008 676 LDBX 4062 Ldb::Update Updating contentSetRecord:
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {5EF77FE2-B1BF-41B4-9DA6-51F6549F523E}
+ state: Normal
+ startVersion: v81
+ authRebuilding: 0
+ stageVolumeSerialNumber: 48ac1944ac192e46
+ stageFid: 0x100000000AC80
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Upstream> 20080627 11:53:15.008 676 CSMG 2697 ContentSetManager::DbBuildComplete Finished scanning content set and building database info: {05631532-B65C-45AF-BB49-F237ACB6CF7C} Transition from InitialBuilding to Normal << replica set is in Normal mode now
<Upstream> 20080627 11:53:15.008 676 DIRW 303 DirWalkerTask::Run Exit.
<Upstream> 20080627 11:53:15.008 3836 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:InitialBuilding
<Upstream> 20080627 11:53:15.008 3836 CSMG 1779 ContentSetManager::Run Scheduling restart now csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00B766B0
<Upstream> 20080627 11:53:15.008 3836 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:InitialBuilding
<Upstream> 20080627 11:53:15.008 3836 CSMG 837 ContentSetManager::Initialize csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00B766B0
<Upstream> 20080627 11:53:15.008 3836 CSMG 2262 ContentSetManager::CheckContentSetState Updating content set record csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ghosted:0 readOnly:0 readOnlySince:16010101 00:00:00.000
<Upstream> 20080627 11:53:15.008 3836 CSMG 2298 ContentSetManager::CheckContentSetState Content set csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} state:Normal
<Upstream> 20080627 11:53:15.008 3836 STAG 2600 Staging::ScanStagingDirectory Staging space usage is: 0
<Upstream> 20080627 11:53:15.018 676 DOWN 3181 DownstreamTransport::SetupBinding Setting authentication information for partner: FABRIKAM\2008MEM02$
<Upstream> 20080627 11:53:15.018 676 DOWN 3363 DownstreamTransport::SetupBinding Setup connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} remoteAddress:2008mem02.fabrikam.com stringBinding:[5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c@ncacn_ip_tcp:2008mem02.fabrikam.com]
<Upstream> 20080627 11:53:15.028 676 DOWN 3900 DownstreamTransport::EstablishConnection Established connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} rgName:NewRG1 transport:12012224
<Upstream> 20080627 11:53:15.028 676 INCO 2942 InConnection::ConnectNetwork New connection connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} transport:00B74AC0 unghostTransport:00000000
<Upstream> 20080627 11:53:15.028 676 INCO 2945 InConnection::ConnectNetwork connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} fatalRemoteError:0
<Upstream> 20080627 11:53:15.028 676 INCO 3040 InConnection::ReConnectAsync transport:00B74AC0 unghostTransport:00000000
<Upstream> 20080627 11:53:15.028 676 INCO 3101 InConnection::ReConnectAsync Connection established with partner 2008mem02.fabrikam.com. connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} rgName:NewRG1
<Upstream> 20080627 11:53:15.028 676 DOWN 3431 DownstreamTransport::AttachIn ptr:00B74AC0
<Upstream> 20080627 11:53:15.028 3856 DOWN 3991 [ERROR] DownstreamTransport::EstablishSession Failed on connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} rgName:NewRG1 Error:
+ [Error:9027(0x2343) DownstreamTransport::EstablishSession downstreamtransport.cpp:3984 3856 C A failure was reported by the remote partner]
+ [Error:9051(0x235b) DownstreamTransport::EstablishSession downstreamtransport.cpp:3984 3856 C The content set is not ready]
20080627 11:53:15.028 3856 INCO 3566 InConnection::RestartSession Retrying establish contentset session. connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1
<Upstream> 20080627 11:53:15.028 3856 INCO 774 [WARN] SessionTask::Step (Ignored) Failed, should have already been processed. Error:
+ [Error:9027(0x2343) InConnection::EstablishSession inconnection.cpp:3657 3856 C A failure was reported by the remote partner]
+ [Error:9027(0x2343) DownstreamTransport::EstablishSession downstreamtransport.cpp:4005 3856 C A failure was reported by the remote partner]
+ [Error:9027(0x2343) DownstreamTransport::EstablishSession downstreamtransport.cpp:3984 3856 C A failure was reported by the remote partner]
+ [Error:9051(0x235b) DownstreamTransport::EstablishSession downstreamtransport.cpp:3984 3856 C The content set is not ready]
<< <snipped out repeated retries because partner server is still running through initial sync phase>
<Downstream> 20080627 11:53:16.081 292 SRTR 712 SERVER_EstablishConnection Succeeded on connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} replicaSetId:{33DACEEE-D60C-4BF1-911C-EA5C487A78CB} rgName:NewRG1 partnerAddress:2008mem01.fabrikam.com
<Downstream> 20080627 11:53:16.081 292 SRTR 784 [WARN] SERVER_EstablishSession Failed on connId:{AF7B6836-D323-4A01-9448-09680B9ACAF5} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} Error:
+ [Error:9051(0x235b) UpstreamTransport::EstablishSession upstreamtransport.cpp:707 292 C The content set is not ready]
+ [Error:9051(0x235b) OutConnection::EstablishSession outconnection.cpp:2623 292 C The content set is not ready]
<< <snipped out repeated retries because partner server is still running through initial sync phase on iself>
<Upstream> 20080627 11:57:25.809 3832 SRTR 712 SERVER_EstablishConnection Succeeded on connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} replicaSetId:{33DACEEE-D60C-4BF1-911C-EA5C487A78CB} rgName:NewRG1 partnerAddress:2008mem02.fabrikam.com
<Upstream> 20080627 11:57:25.819 3832 OUTC 2610 OutConnection::EstablishSession Replacing content set. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} rgName:NewRG1
<Upstream> 20080627 11:57:25.819 3836 LDBX 4062 Ldb::Update Updating contentSetRecord:
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {5EF77FE2-B1BF-41B4-9DA6-51F6549F523E}
+ state: Normal
+ startVersion: v81
+ authRebuilding: 0
+ stageVolumeSerialNumber: 48ac1944ac192e46
+ stageFid: 0x100000000AC80
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Upstream> 20080627 11:57:25.819 3836 CSMG 2340 ContentSetManager::UpdateLastOnlineTime Last online time updated: <Upstream> 20080627 15:57:25.819 csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C}
<Upstream> 20080627 11:57:25.829 2172 SRTR 1927 SERVER_AsyncPoll Received from connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} << upstream server receives polling request from downstream
<Upstream> 20080627 11:57:25.829 3832 SRTR 794 SERVER_EstablishSession Established connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} << an RPC connection is established between both servers.
<Upstream> 20080627 11:57:25.839 1128 SRTR 1880 SERVER_RequestVersionVector Received from connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} seqNumber:1 changeType:notify << upstream receives request for his version vector information
<Upstream> 20080627 11:57:25.839 1128 SRTR 1880 SERVER_RequestVersionVector Received from connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} seqNumber:2 changeType:all
<Upstream> 20080627 11:57:25.839 1128 SRTR 1927 SERVER_AsyncPoll Received from connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B}
<Upstream> 20080627 11:57:25.849 1128 SRTR 882 SERVER_RequestUpdates Received from connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} credits:32 requestType:all
<Upstream> 20080627 11:57:25.849 1128 SRTR 1927 SERVER_AsyncPoll Received from connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B}
<Upstream> 20080627 11:57:25.849 676 MRSH 4615 Marshaller::Marshal FileAttrs in metadata : 0x10
<snipped out file replication operations that are better documented in previous scenarios>
<Downstream> 20080627 11:57:29.025 480 ISYN 65 InitialSyncManager::ReturnToken InitialSync sync step finished. Delete all session tasks. << downstream the initial sync task is being removed.
<Downstream> 20080627 11:57:29.025 480 CSMG 2746 ContentSetManager::InitialSyncStepSyncComplete InitialSync sync step completed. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} transition from InitialSync(Sync) to InitialSync(Cleanup). << The initial sync cleanup removes references to the sync.
<Downstream> 20080627 11:57:29.025 480 CSMG 2897 ContentSetManager::SetContentSetState Set content set state. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} newState:InitialSync(Cleanup) (auth:0)
<Downstream> 20080627 11:57:29.025 480 LDBX 4062 Ldb::Update Updating contentSetRecord: << Database set to cleanup mode for this replica set
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59}
+ state: InitialSync(Cleanup)
+ startVersion: v24
+ authRebuilding: 0
+ stageVolumeSerialNumber: 3a34b62834b5e753
+ stageFid: 0x100000000A77F
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Downstream> 20080627 11:57:29.035 480 INCO 6194 InConnection::CommitSession Connection in sync connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 commitedSessionsWithUpdateFailures:0 << downstream server believes it is successfully in sync without any remaining files.
<Downstream> 20080627 11:57:29.035 480 UPMG 418 UpdateWorker::ConsumeUpdates No pending updates. connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csName:NewRF1 csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C}
<Downstream> 20080627 11:57:29.035 3628 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:InitialSync(Sync)
<Downstream> 20080627 11:57:29.035 3628 UPMG 535 UpdateManager::Finalize Finalizing UpdateManager connId:{FFC8C463-846D-4C16-8B37-19978C20FF8B} csName:NewRF1 csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C}
<Downstream> 20080627 11:57:29.035 3628 CSMG 1779 ContentSetManager::Run Scheduling restart now csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00CC3AA0
<Downstream> 20080627 11:57:29.035 3628 CSMG 1757 ContentSetManager::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 state:InitialSync(Sync)
<Downstream> 20080627 11:57:29.035 3628 CSMG 837 ContentSetManager::Initialize csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ptr:00CC3AA0
<Downstream> 20080627 11:57:29.035 3628 CSMG 2262 ContentSetManager::CheckContentSetState Updating content set record csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} csName:NewRF1 ghosted:0 readOnly:0 readOnlySince:16010101 00:00:00.000
<Downstream> 20080627 11:57:29.035 3628 CSMG 2298 ContentSetManager::CheckContentSetState Content set csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} state:InitialSync(Cleanup)
<Downstream> 20080627 11:57:29.035 3628 STAG 2600 Staging::ScanStagingDirectory Staging space usage is: 1695744 << staging area is checked for usage and now contains ~1.5MB of data
<Downstream> 20080627 11:57:29.045 3628 CSMG 2769 ContentSetManager::StartInitialSyncCleanup csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C}
<Downstream> 20080627 11:57:29.045 3748 ISYN 97 InitialSyncCleanupTask::Run csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C}
<Downstream> 20080627 11:57:29.045 3748 CSMG 2785 ContentSetManager::InitialSyncStepCleanupComplete InitialSync cleanup step completed. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} transition from InitialSync(Cleanup) to Normal << cleanup tasks are done and the downstream server is ready to leave initial sync
<Downstream> 20080627 11:57:29.045 3748 EVNT 725 EventLog::Report Logging eventId:4104 parameterCount:6 << a 4104 event is logged to event viewer which states initial sync done.
<Downstream> 20080627 11:57:29.045 3748 EVNT 745 EventLog::Report eventId:4104 parameter1:05631532-B65C-45AF-BB49-F237ACB6CF7C
<Downstream> 20080627 11:57:29.045 3748 EVNT 745 EventLog::Report eventId:4104 parameter2:c:\newrf1
<Downstream> 20080627 11:57:29.045 3748 EVNT 745 EventLog::Report eventId:4104 parameter3:NewRF1
<Downstream> 20080627 11:57:29.045 3748 EVNT 745 EventLog::Report eventId:4104 parameter4:NewRG1
<Downstream> 20080627 11:57:29.045 3748 EVNT 745 EventLog::Report eventId:4104 parameter5:33DACEEE-D60C-4BF1-911C-EA5C487A78CB
<Downstream> 20080627 11:57:29.045 3748 EVNT 745 EventLog::Report eventId:4104 parameter6:0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59
<Downstream> 20080627 11:57:29.045 3748 CSMG 2897 ContentSetManager::SetContentSetState Set content set state. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C} newState:Normal (auth:0)
<Downstream> 20080627 11:57:29.045 3748 LDBX 4062 Ldb::Update Updating contentSetRecord: << the database is updated to mark RF in normal mode.
+ contentSetId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}
+ memberId: {0C33B8DA-F55A-4F85-BA95-CCD84C4E7F59}
+ state: Normal
+ startVersion: v24
+ authRebuilding: 0
+ stageVolumeSerialNumber: 3a34b62834b5e753
+ stageFid: 0x100000000A77F
+ isTombstone: 0
+ readOnlySince: 16010101 00:00:00.000
+ beingDeleted: 0
+ dbLossRecover: 0
+
<Downstream> 20080627 11:57:29.045 3748 CSMG 2829 ContentSetManager::InitialSyncComplete Finished initial sync. csId: {05631532-B65C-45AF-BB49-F237ACB6CF7C}. transition from InitialSync(Cleanup) to Normal
<Downstream> 20080627 11:57:29.045 3748 ISYN 115 InitialSyncCleanupTask::Run Exit. csId:{05631532-B65C-45AF-BB49-F237ACB6CF7C}
remoteAddress:2008mem01.fabrikam.com stringBinding:[5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c@ncacn_ip_tcp:2008mem01.fabrikam.com]
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 ...
Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows S...
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 Se...
Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Serve...
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 Ser...
Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between tw...
Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream betwee...
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...
Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses d...
Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity...
Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (use...
Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severit...
Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug...
