Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)

Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)

  • Comments 1
  • Likes

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 on Windows Server 2008)
Understanding DFSR debug logging (Part 4: A Very Small File Added to Replicated Folder on Windows Server 2008)
Understanding DFSR debug logging (Part 5: File Modified on Windows Server 2003 R2)
Understanding DFSR debug logging (Part 6: Microsoft Office Word 97-2003 File Modified on Windows Server 2008)
Understanding DFSR debug logging (Part 7: Microsoft Office Word 2007 File Modified on Windows Server 2008)
Understanding DFSR debug logging (Part 8: File Deleted from Windows Server 2003 R2)
Understanding DFSR debug logging (Part 9: File is Renamed on Windows Server 2003 R2)
Understanding DFSR debug logging (Part 10: File Conflicted between two Windows Server 2008)
Understanding DFSR debug logging (Part 11: Directory created on Windows Server 2003 R2)
Understanding DFSR debug logging (Part 12: Domain Controller Bind and Config Polling on Windows Server 2008)
Understanding DFSR debug logging (part 13: A New Replication Group and Replicated Folder between two Windows Server 2008 members)
Understanding DFSR debug logging (Part 14: A sharing violation due to a file locked upstream between two Windows Server 2008)
Understanding DFSR debug logging (Part 15: Pre-Seeded Data Usage during Initial Sync)
Understanding DFSR debug logging (Part 16: File modification with RDC in very granular detail (uses debug severity 5))
Understanding DFSR debug logging (Part 17: Replication failing because of blocked RPC ports (uses debug severity 5))
Understanding DFSR debug logging (Part 18: LDAP queries failing due to network (uses debug severity 5))
Understanding DFSR debug logging (Part 19: File Blocked Inbound by a File Screen Filter Driver (uses debug severity 5))
Understanding DFSR debug logging (Part 20: Skipped temporary and filtered files (uses debug severity 5))
Understanding DFSR debug logging (Part 21: File replication performance from throttling (uses debug severity 5))

- Ned Pyle

  • 237 Microsoft Team blogs searched, 106 blogs have new articles in the pa st 7 days. 256 new articles