In this log we will see the DFSR service being started and follow the process of initialization up to the point where the service is fully functional. This is useful to understand in order to troubleshoot issues where problems within Active Directory, Network Communication, XML reading, or Registry reading are preventing the DFSR service from starting or initializing for replication.  

 

(svcstartandpolling - Dfsr00009 - 2008.log)

 

These are two Windows Server 2008 servers called 2008MEM01 and 2008MEM02 in the fabrikam.com domain. The log is from 2008MEM01 where the DFSR service was started. It’s is participating in the TESTRG replication group for the TESTRF replicated folder and its only partner is 2008MEM02.

 

<Upstream> 20080624 14:41:09.203  852 CREG   733 Config::RegConfig::ReadConfigFilePath Location of valueName:Replica Set Configuration File is location:\\.\C:\SYSTEM VOLUME INFORMATION\DFSR\Config\Replica_7C81CA1E-F956-4A9E-BCE5-E3A2D1ACDD1D.XML ß find the path to XML from registry

<Upstream> 20080624 14:41:09.203  852 FCFG   131 Configuration::ReadVolumeConfig Reading all volume configuration files.

<Upstream> 20080624 14:41:09.203  852 CREG   733 Config::RegConfig::ReadConfigFilePath Location of valueName:Volume Configuration File is location:\\.\C:\System Volume Information\DFSR\Config\Volume_6A7E9F21-4169-11DD-AF51-806E6F6E6963.XML ß find path to XML from registry

<Upstream> 20080624 14:41:09.203  852 CXML  2748 Config::XmlReader::PostProcessVolumeConfig Found volume. path:\\.\C: volumeId:{6A7E9F21-4169-11DD-AF51-806E6F6E6963}

<Upstream> 20080624 14:41:09.203  852 CXML  2757 Config::XmlReader::PostProcessVolumeConfig Overwriting dbPath. oldPath:\\.\C:\System Volume Information\DFSR newPath:\\.\C:\System Volume Information\DFSR ß location of the DFSR database is forced into XML

<Upstream> 20080624 14:41:19.208  852 CFAD   317 Config::AdConnection::Connect Binding to dcAddr:\\10.60.0.1 dcDnsName:\\2008DC01.fabrikam.com

<Upstream> 20080624 14:41:19.208  852 CFAD   149 Config::AdConnection::BindToAd Trying to connect. hostName:2008DC01.fabrikam.com

<Upstream> 20080624 14:41:19.238  852 CFAD   168 Config::AdConnection::BindToAd Bound. hostName:2008DC01.fabrikam.com

<Upstream> 20080624 14:41:19.238  852 CFAD   205 Config::AdConnection::BindToDc Try to bind. hostName:\\2008DC01.fabrikam.com domainName:<null>

<Upstream> 20080624 14:41:19.318  852 CFAD   215 Config::AdConnection::BindToDc Bound. hostName:\\2008DC01.fabrikam.com domainName:<null> ß five lines above cover the bind to DC we will use until DFSR service is restarted (it does not matter if DC goes offline; we will then use the XML files that were read in above instead)

<Upstream> 20080624 14:41:19.318  852 CFAD  7530 Config::AdConfig::ReadRootNamingContexts Default Naming Context DN:DC=fabrikam,DC=com

<Upstream> 20080624 14:41:19.318  852 CFAD  7531 Config::AdConfig::ReadRootNamingContexts Schema Naming Context DN:cn=sites,cn=configuration,dc=fabrikam,dc=com

<Upstream> 20080624 14:41:19.318  852 CFAD  7533 Config::AdConfig::ReadRootNamingContexts Services DN:cn=services,cn=configuration,dc=fabrikam,dc=com

<Upstream> 20080624 14:41:19.318  852 CFAD  7534 Config::AdConfig::ReadRootNamingContexts Domain Controllers DN:ou=domain controllers,DC=fabrikam,DC=com

<Upstream> 20080624 14:41:19.318  852 CFAD  7535 Config::AdConfig::ReadRootNamingContexts Computers DN:cn=computers,DC=fabrikam,DC=com

<Upstream> 20080624 14:41:19.318  852 CFAD  7536 Config::AdConfig::ReadRootNamingContexts System DN:cn=system,DC=fabrikam,DC=com

<Upstream> 20080624 14:41:19.318  852 CFAD  7537 Config::AdConfig::ReadRootNamingContexts Sites DN:cn=sites,cn=configuration,dc=fabrikam,dc=com ß We find the above seven naming contexts, as they may all include DFSR-related information (including SYSVOL information or DFSN usage).

<Upstream> 20080624 14:41:19.328  852 CFAD  7697 Config::AdConfig::CheckSchemaVersion DMD object:CN=Schema,CN=Configuration,DC=fabrikam,DC=com, objectVersion:44 ß Schema version is checked so that service knows if DFSR is supported by the forest

<Upstream> 20080624 14:41:19.368  852 CREG  1207 Config::RegReader::IsSysVolCommitFlagSet key: System\CurrentControlSet\Services\DFSR\Parameters\SysVols\Demoting SysVols valueName:'SysVol Information is Committed' result:0

<Upstream> 20080624 14:41:19.378  852 EVNT   725 EventLog::Report Logging eventId:1206 parameterCount:1

<Upstream> 20080624 14:41:19.378  852 EVNT   745 EventLog::Report         eventId:1206 parameter1:\\2008DC01.fabrikam.com ß event log is updated with 1206 to reflect which DC was bound

<Upstream> 20080624 14:41:19.398  852 ADWR  1038 Config::AdWriter::CreateSysVolObjects [SYSVOL] IsDc:0 isSysVolCreated:0

<Upstream> 20080624 14:41:19.398  852 ADWR  1041 Config::AdWriter::CreateSysVolObjects [SYSVOL] Not a DC ß determine that this server is not a DC and SYSVOL operations will not be possible

<Upstream> 20080624 14:41:19.448  852 CFAD  7348 Config::AdConfig::TranslateDn Cracked Domain:fabrikam.com

<Upstream> 20080624 14:41:19.448  852 CFAD  7349 Config::AdConfig::TranslateDn Cracked Name  :FABRIKAM\2008MEM02$ ß get NetBIOS SAM name of DFSR partner server given the above domain

<Upstream> 20080624 14:41:19.448  852 CFAD  7348 Config::AdConfig::TranslateDn Cracked Domain:fabrikam.com

<Upstream> 20080624 14:41:19.448  852 CFAD  7349 Config::AdConfig::TranslateDn Cracked Name  :S-1-5-21-2013982821-2378084203-3048728933-1104 <-get domain SID of DFSR partner server given the above domain

<Upstream> 20080624 14:41:19.458  852 CCTX  1251 VolumeIdTable::Rebuild Processing volume:\\?\Volume{6a7e9f21-4169-11dd-af51-806e6f6e6963}\ path:\\.\C: serialNumber:5236588249460846150 ß find volumes and their serial numbers

<Upstream> 20080624 14:41:19.478  852 CCTX  1099 VolumeIdTable::ReadVolumeInfo Ignoring volume:\\?\Volume{6a7e9f24-4169-11dd-af51-806e6f6e6963}\ (remote, cd-rom or removable)

<Upstream> 20080624 14:41:19.478  852 CCTX  1099 VolumeIdTable::ReadVolumeInfo Ignoring volume:\\?\Volume{6a7e9f25-4169-11dd-af51-806e6f6e6963}\ (remote, cd-rom or removable)

<Upstream> 20080624 14:41:19.578  852 CFAD  8625 Config::AdConfig::UpdateSpn Binding to dcAddr:\\10.60.0.1 dcDnsName:\\2008DC01.fabrikam.com

<Upstream> 20080624 14:41:19.578  852 CFAD  8653 Config::AdConfig::UpdateSpn spnList:Dfsr-12F9A27C-BF97-4787-9364-D31B6C55EB04/2008mem01.fabrikam.com

<Upstream> 20080624 14:41:19.578  852 CFAD  8659 Config::AdConfig::UpdateSpn SPN already registered. spn:Dfsr-12F9A27C-BF97-4787-9364-D31B6C55EB04/2008mem01.fabrikam.com ß Register the Service Principal Name for the service unless already present

<Upstream> 20080624 14:41:19.578  852 CFAD  8653 Config::AdConfig::UpdateSpn spnList:HOST/2008MEM01

<Upstream> 20080624 14:41:19.578  852 CFAD  8653 Config::AdConfig::UpdateSpn spnList:HOST/2008mem01.fabrikam.com ß get the HOST SPN’s for this server

<Upstream> 20080624 14:41:19.578  852 CXML  3225 Config::XmlWriter::CreateSVIDirectory Created System Volume Information folder under path:\\.\C:\SYSTEM VOLUME INFORMATION\DFSR

<Upstream> 20080624 14:41:19.578  852 CXML  3279 Config::XmlWriter::CreateDirectoryW Directory already exists, path:\\.\C:\SYSTEM VOLUME INFORMATION\DFSR

<Upstream> 20080624 14:41:19.578  852 CXML  3279 Config::XmlWriter::CreateDirectoryW Directory already exists, path:\\.\C:\SYSTEM VOLUME INFORMATION\DFSR\Config ß Create the hidden operating system System Volume Information folder structure if it does not already exist

<Upstream> 20080624 14:41:19.578  852 CXML  1837 Config::XmlConfig::CreateDocument Create root node: DfsrReplicationGroupConfig

<Upstream> 20080624 14:41:19.578  852 CXML  3922 Config::XmlWriter::WriteReplicaSetConfigFile Reading old replica config file at path:\\.\C:\SYSTEM VOLUME INFORMATION\DFSR\Config\Replica_7C81CA1E-F956-4A9E-BCE5-E3A2D1ACDD1D.XML ß recreate the replica XML file

<Upstream> 20080624 14:41:19.588  852 CXML  3540 Config::XmlWriter::WriteVolumeConfigFile Write volume configure file:\\.\C:\System Volume Information\DFSR\Config\Volume_6A7E9F21-4169-11DD-AF51-806E6F6E6963.XML ß recreate the volume XML file

<Upstream> 20080624 14:41:19.588  852 CXML  1837 Config::XmlConfig::CreateDocument Create root node: DfsrVolumeConfig

<Upstream> 20080624 14:41:19.598  852 SYSM  3868 Migration::SysVolMigration::Connect [MIG] Trying to connect to Local or any writable Dc AD

<Upstream> 20080624 14:41:19.598  852 CFAD   317 Config::AdConnection::Connect Binding to dcAddr:\\10.60.0.1 dcDnsName:\\2008DC01.fabrikam.com

<Upstream> 20080624 14:41:19.598  852 CFAD   149 Config::AdConnection::BindToAd Trying to connect. hostName:2008DC01.fabrikam.com

<Upstream> 20080624 14:41:19.598  852 CFAD   168 Config::AdConnection::BindToAd Bound. hostName:2008DC01.fabrikam.com

<Upstream> 20080624 14:41:19.598  852 CFAD   205 Config::AdConnection::BindToDc Try to bind. hostName:\\2008DC01.fabrikam.com domainName:<null>

<Upstream> 20080624 14:41:19.608  852 CFAD   215 Config::AdConnection::BindToDc Bound. hostName:\\2008DC01.fabrikam.com domainName:<null>

<Upstream> 20080624 14:41:19.608  852 CFAD  7697 Config::AdConfig::CheckSchemaVersion DMD object:CN=Schema,CN=Configuration,DC=fabrikam,DC=com, objectVersion:44

<Upstream> 20080624 14:41:19.778  852 CREG  1207 Config::RegReader::IsSysVolCommitFlagSet key: System\CurrentControlSet\Services\DFSR\Parameters\SysVols\Seeding SysVols valueName:'SysVol Information is Committed' result:0 ß seven previous lines cover a special out-of-band AD connection to see what DFSR SYSVOL migration state is in.

<Upstream> 20080624 14:41:19.778  852 SCFG   956 ServiceConfig::ProcessAdPollConfigEvents Received AD Poll event with 1 Volume configuration changes

<Upstream> 20080624 14:41:19.778  852 SCFG   959 ServiceConfig::ProcessAdPollConfigEvents Received AD Poll event with 1 Replication Group configuration changes ß Information has been retrieved from AD via LDAP lookups. This will always be numbered by the actual count of volumes and RG’s, not the number of changes found.

<Upstream> 20080624 14:41:19.788  852 RSMG   142 ReplicaSetManager::Initialize Initialize replication group rgName:TestRG ß found one RG called TestRG

<Upstream> 20080624 14:41:19.788  852 RSMG   908 ReplicaSetManager::AddInConnection Creating new inbound connection connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} rgName:TestRG ß found the one inbound connection reflected by this RG and its GUID

<Upstream> 20080624 14:41:19.788  852 RSMG  1273 ReplicaSetManager::AddOrUpdateConnection New or updated outbound connection object. connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} rgName:TestRG

<Upstream> 20080624 14:41:19.788  852 CCTX  2391 ConfigContext::ApplyDiff Adding new volume to ConfigContext. volumePath:\\.\C:

<Upstream> 20080624 14:41:19.788  852 FREP   400 FrsReplicator::UpdateVolume Create Volume:6A7E9F21-4169-11DD-AF51-806E6F6E6963

<Upstream> 20080624 14:41:19.788  852 CCTX  3237 ConfigContext::DumpReplicaConfig Dumping Replica global config context

<Upstream> 20080624 14:41:19.788  852 CPAR  2476 Config::ParamBlock::Print  [[ DfsrReplicationGroup ]] ß now we begin reading the RG global configuration information from cn=TestRG,cn=dfsr-globalsettings,cn=system,dc=fabrikam,dc=com. It is critical to understand that these reads in the log are from the configuration XML files, where the LDAP query results are cached. When troubleshooting both the LDAP queries and the local XML reads must be examined.

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print LastChangeNumber: 12 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  1244 Config::DateTimeParam::Print LastChangeTime:  6/24/2008 18:41:19 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print LastChangeSource: 2008DC01.fabrikam.com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print Description: <null> [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print ReplicationGroupGuid: 7C81CA1E-F956-4A9E-BCE5-E3A2D1ACDD1D [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print ReplicationGroupName: TestRG [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print ReplicationGroupDn: CN=TestRG,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print ReplicationGroupType: 0 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print TombstoneExpiryInMin: 86400 [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print DefaultScheduleInUtc: FALSE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print DefaultSchedule.Sunday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF ß

Tnis represents the schedule in HEX. A hex value (0-F) represents the bandwidth usage for each 15 minute interval in an hour. F=Full, E=256Mbps, D=128Mbps, C=64Mbps, B=32Mbps, A=16Mbps, 9=8Mbps, 8=4Mbps, 7=2Mbps, 6=1Mbps, 5=512Kbps, 4=256Kbps, 3=128Kbps,2=64Kbps, 1=16Kbps, 0=No replication. Note that these are bits per second, not bytes.

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print DefaultSchedule.Monday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print DefaultSchedule.Tuesday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print DefaultSchedule.Wednesday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print DefaultSchedule.Thursday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print DefaultSchedule.Friday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print DefaultSchedule.Saturday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

ß The above highlighted XML cached LDAP attribute reads are about the RG configuration, including distinguishedName, description, objectGUID, msDFSR-ReplicationGroupType, msDFSR-TombstoneExpiryInMin, msDFSR-Schedule, and name. Also covers the AD replication metadata information of which DC originated latest change, the originating time, and number of times the RG has been changed.

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print ReplicatedFolderGuid: 175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  2476 Config::ParamBlock::Print  [[ DfsrMember ]] ß now we begin reading the member global configuration information cached in XML from cn=<GUID of msDFSR-member>,cn=Topology,cn=TestRG,cn=dfsr-globalsettings,cn=system,dc=fabrikam,dc=com. These are backlink follows.

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print MemberGuid: E1023470-7BF7-403D-B9A6-CBDA8F877F71 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print MemberName: 2008MEM01 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print MemberDn: CN=412d1a14-d5ec-4a0f-ab78-fa17dd0a7537,CN=Topology,CN=TestRG,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print MemberDns: 2008mem01.fabrikam.com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print MemberPeerNetGroupName: <null> [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print Keywords: <null> [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR  2476 Config::ParamBlock::Print  [[ DfsrConnection ]] ß now we begin reading the member global configuration information cached in XML from cn=<GUID of msdfsr-Connection>,cn=<GUID of msDFSR-member>,cn=Topology,cn=TestRG,cn=dfsr-globalsettings,cn=system,dc=fabrikam,dc=com. We will do this twice – once for each connection object between servers. In this case there are two total, as well will see below.

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print ConnectionGuid: DEDD774B-4094-40BF-987A-B38CAFCC86E0 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print ConnectionDn: CN=4b4813da-e705-4f40-b148-e3eab2d55bd8,CN=412d1a14-d5ec-4a0f-ab78-fa17dd0a7537,CN=Topology,CN=TestRG,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print PartnerGuid: EDAE85D2-373F-4526-9153-7535C722C6FE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print PartnerName: 2008MEM02 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print PartnerDn: CN=5c8cce4c-c344-4b8f-a5c6-cd040bd625cf,CN=Topology,CN=TestRG,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print PartnerDns: 2008mem02.fabrikam.com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print PartnerPrincName: FABRIKAM\2008MEM02$ [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print PartnerSid: S-1-5-21-2013982821-2378084203-3048728933-1104 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print Enabled: TRUE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print Inbound: TRUE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print Keywords: <null> [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print RdcEnabled: TRUE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print RdcMinFileSizeInKb: 64 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print ScheduleInUtc: FALSE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print Schedule.Sunday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print Schedule.Monday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print Schedule.Tuesday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print Schedule.Wednesday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print Schedule.Thursday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print Schedule.Friday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

<Upstream> 20080624 14:41:19.788  852 CPAR  1933 Config::ScheduleParam::Print Schedule.Saturday: FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF,FFFF

ßThe above XML-cached LDAP attribute reads return connection-specific configuration information, including objectGUID, DN, msDFSR-ComputerReference, fromServer, msDFSR-Enabled, msDFSR-RdcEnabled, msDFSR-RdcMinFileSizeInKb, msDFSR-ComputerReference, msDFSR-MemberReferenceBL, and msDFSR-Schedule.  We also return Netbios SAM names, DNS names, and SID’s from the crack name operations.

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print ReplicatedFolderGuid: 175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  2476 Config::ParamBlock::Print  [[ DfsrConnection ]] ß we will repeat the above operation, but now for the other connection object. (Snipped out for readability).

<Upstream> 20080624 14:41:19.788  852 CCTX  3250 ConfigContext::DumpVolumeConfig Dumping Volume global config context

<Upstream> 20080624 14:41:19.788  852 CPAR  2476 Config::ParamBlock::Print  [[ DfsrVolume ]] ß now we begin reading the volume configuration machine. This I not stored anywhere in LDAP and is enumerated at DFSR service startup

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print VolumeGuid: 6A7E9F21-4169-11DD-AF51-806E6F6E6963 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   911 Config::PathParam::Print VolumePath: \\.\C: [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   298 Config::QWordParam::Print SerialNumber: 2887331398 [Flags:0x1] ß volume serial number (internal to DFSR, will not match data in DISKPART)

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print LastChangeNumber: 12 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  1244 Config::DateTimeParam::Print LastChangeTime:  6/24/2008 18:41:19 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print LastChangeSource: 2008DC01.fabrikam.com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   911 Config::PathParam::Print DatabasePath: \\.\C:\System Volume Information\DFSR [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print MinNtfsJournalSizeInMb: 512 [Flags:0x1] ß USN Journal size, can be read with FSUTIL.EXE

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print UsnCheckPoint: 10 [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print MaxJetSessions: 64 [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR  2476 Config::ParamBlock::Print  [[ DfsrReplicatedFolder ]] ß now we begin reading the XML-cached LDAP RF global configuration information from cn=TestRF,cn=content,cn=TestRG,cn=dfsr-globalsettings,cn=system,dc=fabrikam,dc=com

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print ReplicatedFolderGuid: 175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print ReplicatedFolderDn: CN=testrf,CN=Content,CN=TestRG,CN=DFSR-GlobalSettings,CN=System,DC=fabrikam,DC=com [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print ReplicatedFolderName: testrf [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print ReplicationGroupGuid: 7C81CA1E-F956-4A9E-BCE5-E3A2D1ACDD1D [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR  1050 Config::GuidParam::Print MemberGuid: E1023470-7BF7-403D-B9A6-CBDA8F877F71 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   911 Config::PathParam::Print RootPath: c:\testrf [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print RootSizeInMb: 10240 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   911 Config::PathParam::Print StagingPath: c:\testrf\DfsrPrivate\Staging [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print StagingSizeInMb: 4096 [Flags:0x1] ß staging quota size, not real size.

<Upstream> 20080624 14:41:19.788  852 CPAR   911 Config::PathParam::Print ConflictPath: c:\testrf\DfsrPrivate\ConflictAndDeleted [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print ConflictSizeInMb: 660 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print FileFilter: ~*, *.bak, *.tmp [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print DirectoryFilter:  [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print Ghosted: FALSE [Flags:0x1] ß Ghosting is an unshipped feature that still logs

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print CacheObeyConnectionSchedule: FALSE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print MinAgeInCacheInMin: 0 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   204 Config::DWordParam::Print MaxAgeInCacheInMin: 0 [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print Enabled: TRUE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print IsPrimary: FALSE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print ReadOnly: FALSE [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print DisableSaveDeletes: FALSE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print DisableReanimateDeletes: FALSE [Flags:0x1]

<Upstream> 20080624 14:41:19.788  852 CPAR   390 Config::BoolParam::Print SharedStaging: FALSE [Flags:0x0]

<Upstream> 20080624 14:41:19.788  852 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] ß default list of files excluded from staging XPRESS compression, see KB951003

<Upstream> 20080624 14:41:19.788  852 CPAR   556 Config::StringParam::Print Description: <null> [Flags:0x0]

ß the LDAP configuration reads end here. Most of the above entries are self-explanatory.

<Upstream> 20080624 14:41:20.299 1848 DBCJ  1903 ChangeJournal::Start Start reading journal on volumeId:\\.\C: at usnNumber:10320448. journalId:128587295648302192 ß find and read latest information from USN journal

<Upstream> 20080624 14:41:20.299 1848 VLMG  1158 VolumeManager::Initialize Volume initialized. volId:\\.\C: ß done examining the volume’s readiness

<Upstream> 20080624 14:41:20.299 1848 CSMG  1757 ContentSetManager::Run csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf state:Normal ß Good idea to note the GUID and name here for future reference

<Upstream> 20080624 14:41:20.299 1848 CSMG  1779 ContentSetManager::Run Scheduling restart now csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf ptr:008640E0

<Upstream> 20080624 14:41:20.299 1848 CSMG  1757 ContentSetManager::Run csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf state:Normal ß the replicated folder (content set) is started up

<Upstream> 20080624 14:41:20.299 1848 CSMG   837 ContentSetManager::Initialize csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf ptr:008640E0

<Upstream> 20080624 14:41:20.309 1848 CSMG  2262 ContentSetManager::CheckContentSetState Updating content set record csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf ghosted:0 readOnly:0 readOnlySince:16010101 00:00:00.000 ß ghosting info should be ignored (unshipped feature tht still has some logging remnants in Win2008). The readonly flag/date refers to the msDFSR-ReadOnly, of which modification is unsupported.

<Upstream> 20080624 14:41:20.309 1848 CSMG  2298 ContentSetManager::CheckContentSetState Content set csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} state:Normal

<Upstream> 20080624 14:41:20.309 1848 STAG  2600 Staging::ScanStagingDirectory Staging space usage is: 1077248

<Upstream> 20080624 14:41:20.319 1848 DOWN  3181 DownstreamTransport::SetupBinding Setting authentication information for partner: FABRIKAM\2008MEM02$ ß Kerberos TGS is used here. NTLM is not supported with DFSR.

<Upstream> 20080624 14:41:20.319 1848 DOWN  3363 DownstreamTransport::SetupBinding Setup connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} remoteAddress:2008mem02.fabrikam.com  stringBinding:[5bc1ed07-f5f5-485f-9dfd-6fd0acf9a23c@ncacn_ip_tcp:2008mem02.fabrikam.com] ß an RPC outbound connection using RPC_C_AUTHN_LEVEL_PKT_PRIVACY is made to the other DFSR server 2008mem02. We also gain the useful information of what the connection GUID for this replication group is.

<Upstream> 20080624 14:41:20.329 1848 DOWN  3900 DownstreamTransport::EstablishConnection Established connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} rgName:TestRG transport:9160536 ß RPC connection was established successfully.

<Upstream> 20080624 14:41:20.329 1848 INCO  2942 InConnection::ConnectNetwork New connection connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} transport:008BC758 unghostTransport:00000000

<Upstream> 20080624 14:41:20.339 1848 INCO  2945 InConnection::ConnectNetwork connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} fatalRemoteError:0

<Upstream> 20080624 14:41:20.339 1848 INCO  3040 InConnection::ReConnectAsync transport:008BC758 unghostTransport:00000000

<Upstream> 20080624 14:41:20.339 1848 INCO  3101 InConnection::ReConnectAsync Connection established with partner 2008mem02.fabrikam.com. connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} rgName:TestRG ßthe conection with partner 2008mem02 is done successfully.

<Upstream> 20080624 14:41:20.339 1848 DOWN  3431 DownstreamTransport::AttachIn ptr:008BC758

<Upstream> 20080624 14:41:20.339 3332 INCO  3750 InConnection::RequestVvUp Requested upstream version vector. requestState:008BC9D8 connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf changeType:notify ß current version vector is requested from the partner server

<Upstream> 20080624 14:41:20.349 2920 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} reqType:VvUpRequest reqState:Completed status:0 ptr:008BC9D8

<Upstream> 20080624 14:41:20.349 2920 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:008BC8E0

<Upstream> 20080624 14:41:20.349 3332 INCO  3750 InConnection::RequestVvUp Requested upstream version vector. requestState:008BC9D8 connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf changeType:all ß server asks upstream partner for its current version vector high watermark number.

<Upstream> 20080624 14:41:20.359 3304 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} reqType:VvUpRequest reqState:Completed status:0 ptr:008BC9D8

<Upstream> 20080624 14:41:20.369 2920 INCO  3959 InConnection::ReceiveVvUp Received VvUp connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf vvUp:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 10..40}

+       {910170E6-8BD6-49A9-85F1-A2F3FF43C76B} |-> { 10} ß 10 this is the current high watermark version vector on the remote server 2008mem02 (i.e. the next VV will be 11). 40 is the current VV high watermark on the local DFSR server, so its next version will be 41.

+      

<Upstream> 20080624 14:41:20.369 2920 INCO  3966 InConnection::ReceiveVvUp Creating new session:1 requestState:008BC9D8 connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf vvDown:{EDE2D64E-1306-4C7C-B568-449A98371AA2} |-> { 10..40}

+       {910170E6-8BD6-49A9-85F1-A2F3FF43C76B} |-> { 10}

+      

<Upstream> 20080624 14:41:20.369 2920 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{00000000-0000-0000-0000-000000000000} reqType:AsyncPollRequest reqState:Completed status:0 ptr:008BC8E0

<Upstream> 20080624 14:41:20.369 1848 INCO  3779 InConnection::ContentSetContext::Hibernate Hibernating: connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501}

<Upstream> 20080624 14:41:20.369 1848 INCO  3750 InConnection::RequestVvUp Requested upstream version vector. requestState:008BC9D8 connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} csName:testrf changeType:notify ß the upstream 2008mem02 server is requested to send its current VV

<Upstream> 20080624 14:41:20.369 2920 DOWN  2723 AsyncRpcHandler::ProcessReceive Completion. connId:{DEDD774B-4094-40BF-987A-B38CAFCC86E0} csId:{175F2B6A-289F-4CA8-AF8B-4D9BF1A2C501} reqType:VvUpRequest reqState:Completed status:0 ptr:008BC9D8 ß the downstream server 2008mem02 is sent the upstream 2008mem01’s current VV of 40.

<Upstream> 20080624 14:41:22.853 3904 SRTR   712 SERVER_EstablishConnection Succeeded on connId:{F5A520C4-154C-460E-B8EF-0867D4F92AAE} replicaSetId:{7C81CA1E-F956-4A9E-BCE5-E3A2D1ACDD1D} rgName:TestRG partnerAddress:2008mem02.fabrikam.com ß the RPC replication connection is now fully formed and ready to replicate files.

 

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