ConfigMgr 2012 DRS Initialization Internals

This post has been republished via RSS; it originally appeared at: Configuration Manager Archive articles.

First published on TECHNET on Jan 21, 2015

https://blogs.technet.microsoft.com/umairkhan/2015/01/21/configmgr-2012-drs-initialization-internals/

 

Hi Folks,

 

I have tried explaining the DRS Initialization internals so that we have better understanding in troubleshooting the issue as Initialization is a major part of troubleshooting in DRS cases. I have used some techniques to stop the messages in the SQL Service broker. This is for educational purposes and we should not touch these settings in the DB without knowing or consult from a Microsoft Technician .

 

This post assumes that you have knowledge of working with DRS and have gone through the below articles:

 

http://blogs.technet.com/b/umairkhan/archive/2014/02/18/configmgr-2012-data-replication-service-drs-unleashed.aspx

 

http://blogs.technet.com/b/sudheesn/archive/2012/10/21/drs-initialization-in-configuration-manager-2012.aspx

 

Before starting, A question that I have:

1. When a new Primary site is just installed and then requests the global data from the CAS, how does the request reach the CAS?

 

In putting this question to few of my colleagues, some said it might be via SQL. Next thing is what in SQL, Service Broker may be? Then the question was the Replication is yet not initialized, DRS is not yet working so how come SSB. Then some changed the answer that it could be a file. Well, then when asked to check, found, we never see the sender moving a file up to CAS in initialization. Answer was NO. So it was definitely SQL (May be SQL inbuilt replication? Some said) well when asked to check, found, we didn’t even have SQL replication feature enabled in lab. Still curious?

 

The Answer is we do that via SQL Service broker . But then they asked me the same question that DRS is not yet initialized how come SSB is used? To understand this, we have to know that DRS as a technical term comes only after the initialization is completed. Initialization is done by RCM thread. Remember vaguely that RCM is a component residing both a ConfigMgr thread and SQL? Rings a bell :)

 

Just see the SQL Service Broker queues that are created as a part of the installation –

 

 

Here ConfigMgrDRSQueue comes into picture in the DRS which is only after the initialization completes. For the initialization we use the ConfigMgrRCMQueue :)

 

Coming to the point, I am just testing how an Initialization happens by dropping a ‘ Replication Configuration.PUB’ in the Primary RCM.box.

 

I just disabled the activation on the ConfigMgrRCMQueue on the CAS. To those who do not know, generally when a message is received in a queue it automatically calls the procedure that will be used to process that message (Hence SSB is an asynchronous way) if the ACTIVATION STATUS is ON (which is by default). So setting it to OFF, means the message will remain in the queue without getting processed (So that we can see the message.Do not play with this )

 

USE [CM_CAS]
GO
ALTER QUEUE [dbo].[ConfigMgrRCMQueue] WITH STATUS = ON ,
RETENTION = OFF , ACTIVATION ( STATUS = OFF , PROCEDURE_NAME = 
[dbo].[spRCMActivation] , MAX_QUEUE_READERS = 1 , EXECUTE AS N'dbo' ), 
POISON_MESSAGE_HANDLING (STATUS = ON)

Now going back to the Primary site , we have dropped the ‘Replication Configuration.PUB’ in RCM.box.

 

RCMCtrl.log:

 

Checking if initialization request is needed for replication group Replication Configuration from site CAS.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:57 AM         4508 (0x119C)
 
Building request init for 6 tables in publication Replication Configuration from site CAS.  SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)
 
ColumnXML output: <TABLE NAME="ArticleData"><COLUMN COLUMN_ID="1" NAME="ARTICLENAME" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="256" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="2" NAME="TYPE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="8" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="3" NAME="REPLICATIONID" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="4" NAME="FILTERCOLUMN" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="256" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="5" NAME="ISCOLUMNTRACKED" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="6" NAME="CCARPOPULATED" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="7" NAME="FIRETRIGGERSONBCP" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="8" NAME="OPTIONALFLAG" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="1" DEFINITION="([dbo].[fn_SMSDefaultZero]())" /><COLUMN COLUMN_ID="9" NAME="MASTERTABLESCHEMA" TYPENAME="xml" TYPEID="241" MAX_LENGTH="-1" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /></TABLE>                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)
 
ColumnXML output: <TABLE NAME="GlobalSchemaChangeHistory"><COLUMN COLUMN_ID="1" NAME="TABLENAME" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="256" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="2" NAME="BUILDVERSION" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="64" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="3" NAME="REPLICATIONID" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="4" NAME="LASTMODIFIEDSITECODE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="10" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="5" NAME="REVISIONNUMBER" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="6" NAME="TABLESCHEMA" TYPENAME="xml" TYPEID="241" MAX_LENGTH="-1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /></TABLE>  SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)
 
ColumnXML output: <TABLE NAME="ReplicationData"><COLUMN COLUMN_ID="1" NAME="ID" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="2" NAME="REPLICATIONPATTERN" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="40" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="3" NAME="REPLICATIONGROUP" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="510" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="4" NAME="SYNCINTERVAL" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="5" NAME="ISPUSH" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="6" NAME="TRANSPORTTYPE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="40" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="7" NAME="REPLICATIONPRIORITY" TYPENAME="tinyint" TYPEID="48" MAX_LENGTH="1" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="8" NAME="INCLUDERESERVEDRANGES" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="9" NAME="FLAGS" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /></TABLE>            SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)
 
ColumnXML output: <TABLE NAME="SCCMAutoUpdates"><COLUMN COLUMN_ID="1" NAME="ID" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="2" NAME="NAME" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="512" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="3" NAME="UPDATE_BODY" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="-1" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="4" NAME="UPDATEVERSION" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="64" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="5" NAME="MINREQUIREDSITEVERSION" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="64" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="6" NAME="MAXREQUIREDSITEVERSION" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="64" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="7" NAME="ACTIVE" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="1" DEFINITION="((0))" /><COLUMN COLUMN_ID="8" NAME="UPDATEOPTION" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="9" NAME="APPLIEDOPTION" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /></TABLE>                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)
 
ColumnXML output: <TABLE NAME="ServerData"><COLUMN COLUMN_ID="1" NAME="ID" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="2" NAME="NAME" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="512" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="3" NAME="SITECODE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="6" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="4" NAME="SERVERROLE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="20" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="5" NAME="SQLINSTANCE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="544" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="6" NAME="SQLPORT" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="7" NAME="CONFIGMGRDATABASE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="128" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="8" NAME="SITESTATUS" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="9" NAME="RECOVERYCOUNT" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /></TABLE>   SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)
 
ColumnXML output: <TABLE NAME="UpgradeVersionMap"><COLUMN COLUMN_ID="1" NAME="NAME" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="510" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="2" NAME="INTERNALCONTROL" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="3" NAME="BUILDNUMBER" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /></TABLE>                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)
 
STATMSG: ID=7801 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_REPLICATION_CONFIGURATION_MONITOR" SYS=CM12PR1.uk.lab SITE=PR1 PID=4076 TID=4508 GMTDATE=Wed Jan 21 19:29:58.618 2015 ISTR0="PR1" ISTR1="Replication Configuration" ISTR2="CAS" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0           SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)

Now to understand which tables will be asked for a particular replication group, try this:

 

select * from articledata where replicationid= (select ID from vReplicationData
 where ReplicationGroup = 'Replication Configuration')

 

 

Now that we have seen the RCMCtrl.log, lets see the same in the VLogs (Primary) as the component resides here too. Also could be handy many a times RCMCtrl rolls over.

 

select * from VLogs where Logtext not like '%not sending changes%' and Logtext
 not like '%no changes detected%' order by logline desc

Output:

INFO: Received DRS_SubscriptionInvalid from Site PR1 for replication group: Replication Configuration and fulfilling site: CAS and requesting site: PR1
 
INFO: DRS_SubscriptionInvalid is for full initialization - marking required replication group.
 
INFO: Finished processing DRS_SubscriptionInvalid from Site PR1 for replication group: Replication Configuration
 
INFO: Creating initialization request for 6 articles in replication group Replication Configuration from site CAS.  -- 01/22/2015 00:29:57
 
Built the init request XML for replication group Replication Configuration for site CAS.  -- 01/22/2015 00:29:58

 

Now what does the above lines signify?

 

Remember the first question I asked? Yes, DRS_SubscriptionInvalid is the message that gets created to let the CAS to know that my subscription has become invalid and I need to the data again for this group.

 

Also to troubleshoot the issue, In the SPDiagDRS, we will see the site goes in the Maintenance mode, And the InitializationStatus for the group Replication Configuration will become ‘Required’. Just to take you back to the different states of the replication group see below:

 


Number Format as we see in ‘InitializationStatus’ column in the table RCM_DRSInitializationTracking


Description as we see in the SPDiagDRS


0


'Unknown'


1


'Required'


2


'Requested'


3


'PendingCreation'


4


'PackageCreated'


5


'PendingApplication'


6


'Active'


7


'Aborted'


99


'Failed'

 

Now after we see the line ‘Built the init request’, it creates the message called as DRS_InitRequest for requesting the data from the CAS. It is only now in the SPDiagDRS we will the InitializationStatus for the group Replication Configuration will become ‘Requested’

 

One more thing to note in the RCMCtrl.log:

 

Changed the status of ConfigMgrDRSQueue to OFF if it exists.           SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM           4508 (0x119C)
 
Set the SiteMaintenanceMode registry key to 1   SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:29:58 AM         4508 (0x119C)

 

See below the Snapshot of the queues on the Primary at this time -

 

 

Now we should know that the ConfigMgrDRSQueue becomes disabled by default until the site comes out of maintenance mode. This again helps us to know that DRS is something that comes into picture after initialization.

 

Now coming back to the CAS Site, Now as I have put the activation to OFF manually, we will see the message in the ConfigMgrQueue in the CAS waiting to be processed.

 

select * from [ConfigMgrRCMQueue]

 

See the message_type_name column, we got the DRS_SubscriptionInvalid and the DRS_InitRequest waiting to be processed.

 

Changed the activation to ON again so that it can process the message.

In the VLogs on CAS now, this would make more sense now -

 

 
INFO: Received DRS_SubscriptionInvalid from Site PR1 for replication group: Replication Configuration and fulfilling site: CAS and requesting site: PR1
 
INFO: Received DRS_InitRequest from Site PR1 for replication group: Replication Configuration
 
INFO: DRS_SubscriptionInvalid is for full initialization - marking required replication group.
 
INFO: Finished processing DRS_SubscriptionInvalid from Site PR1 for replication group: Replication Configuration

In the RCMCtrl.log on the CAS now –

 

Checking if we need to create an initialization package for replication group Replication Configuration for site PR1.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:14 AM         3372 (0x0D2C)
 
STATMSG: ID=7802 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_REPLICATION_CONFIGURATION_MONITOR" SYS=CM12CAS.uk.lab SITE=CAS PID=3032 TID=3372 GMTDATE=Wed Jan 21 19:33:14.977 2015 ISTR0="PR1" ISTR1="Replication Configuration" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0           SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:14 AM         3372 (0x0D2C)
 
Flushing DRS queue messages coming from PR1 for replication group Replication Configuration.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:15 AM         3372 (0x0D2C)
 
Changed the status of ConfigMgrDRSQueue to OFF if it exists.           SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:15 AM           3372 (0x0D2C)
 
Processing Replication success.             SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:15 AM         3408 (0x0D50)
 
Rcm control is waiting for file change notification or timeout after 60 seconds.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:15 AM         1964 (0x07AC)
 
Cleaning the RCM inbox if there are any *.RCM files for further change notifications....    SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:15 AM         1964 (0x07AC)
 
Rcm control is waiting for file change notification or timeout after 60 seconds.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:15 AM         1964 (0x07AC)
 
Changed the status of ConfigMgrDRSQueue to ON if it exists.            SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:17 AM           3372 (0x0D2C)
 
Files will be copied to directory E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:17 AM         3372 (0x0D2C)
 
Cab File to be sent will be copied to directory E:\ConfigMgr\inboxes\rcm.box\CabFiles.   SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:17 AM         3372 (0x0D2C)
 
Creating version file E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\32678.version                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:17 AM         3372 (0x0D2C)
 
Creating trackingGuid file E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\1bb60e36-0db7-4d9b-8674-d1e25eb16b00.trackingGuid  SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:17 AM         3372 (0x0D2C)
 
Creating pubName file E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\Replication Configuration-CAS.pubName                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:18 AM         3372 (0x0D2C)
 
Table XML: <TABLE NAME="ArticleData"><COLUMN COLUMN_ID="1" NAME="ARTICLENAME" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="256" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="2" NAME="TYPE" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="8" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="3" NAME="REPLICATIONID" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="4" NAME="FILTERCOLUMN" TYPENAME="nvarchar" TYPEID="231" MAX_LENGTH="256" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="5" NAME="ISCOLUMNTRACKED" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="6" NAME="CCARPOPULATED" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="7" NAME="FIRETRIGGERSONBCP" TYPENAME="bit" TYPEID="104" MAX_LENGTH="1" IS_NULLABLE="0" HAS_DEFAULTVALUE="0" /><COLUMN COLUMN_ID="8" NAME="OPTIONALFLAG" TYPENAME="int" TYPEID="56" MAX_LENGTH="4" IS_NULLABLE="1" HAS_DEFAULTVALUE="1" DEFINITION="([dbo].[fn_SMSDefaultZero]())" /><COLUMN COLUMN_ID="9" NAME="MASTERTABLESCHEMA" TYPENAME="xml" TYPEID="241" MAX_LENGTH="-1" IS_NULLABLE="1" HAS_DEFAULTVALUE="0" /></TABLE>                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:19 AM         3372 (0x0D2C)
 
Calling BCP out with SELECT ARTICLENAME, TYPE, REPLICATIONID, FILTERCOLUMN, ISCOLUMNTRACKED, CCARPOPULATED, FIRETRIGGERSONBCP, OPTIONALFLAG, MASTERTABLESCHEMA~FROM ArticleData, E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\ArticleData.bcp, E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\bcpErrors.errors.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:19 AM         3372 (0x0D2C)
 
Saved rowcount [850] to file [E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\ArticleData.bcp.rowcount] successfully.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:19 AM         3372 (0x0D2C)
 
Successfully created BCP file [E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\ArticleData.bcp] with rows [850] based on SQL query [SELECT ARTICLENAME, TYPE, REPLICATIONID, FILTERCOLUMN, ISCOLUMNTRACKED, CCARPOPULATED, FIRETRIGGERSONBCP, OPTIONALFLAG, MASTERTABLESCHEMA~FROM ArticleData]             SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:19 AM           3372 (0x0D2C)
 
BCP out result is 0. SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:19 AM         3372 (0x0D2C)

 

I have skipped the other tables that were BCP Out. Just taking one to explain what that means.

We create a <TableName>.bcp file for every table (referred as article) that is actually containing the table data and <TableName>.bcp.rowcount which contains the number of rows that were in that table. So that at the destination when the check happens before insertion the number of rows if lost or tampered would be detected and the data would be marked invalid.

 

If the BCP completes successfully, the result would be 0.

 

Skipping all nodes elements except type TABLE.  SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:20 AM         3372 (0x0D2C)
 
Calling drs_init_send method now with parameters E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817 and PR1.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:20 AM         3372 (0x0D2C)
 
Starting to compress files under folder [E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817\] to [E:\ConfigMgr\inboxes\rcm.box\CabFiles\PR1_B97186CC-FCB7-43D8-A24E-7C9DF3903F12.cab] ...                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:20 AM         3372 (0x0D2C)

 

Once the BCPOut for all tables completes it will then call the drs_init_send method and start compressing the file as .CAB in RCM.box\Cabfiles as you can see.

 

Deleting all files under folder [E:\ConfigMgr\inboxes\rcm.box\a8ee5788-cb43-4af5-894c-3685313fb817].                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:20 AM         3372 (0x0D2C)
 
Created minijob to send compressed copy of DRS INIT BCP Package to site PR1. Tranfer root = E:\ConfigMgr\inboxes\rcm.box\CabFiles\PR1_B97186CC-FCB7-43D8-A24E-7C9DF3903F12.cab.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:20 AM         3372 (0x0D2C)

 

Once the compressions completes, the RCM creates a MiniJob to send this to the primary site. After this line we know we have to check the legacy file replication (Schedule -> Sender)

 

Sender.log:

Attempt to write 9930 bytes to \\CM12PR1.uk.lab\SMS_SITE\1000HCAS.PCK at position 1024        SMS_LAN_SENDER 1/22/2015 12:33:46 AM                3192 (0x0C78)
 
Wrote 9930 bytes to \\CM12PR1.uk.lab\SMS_SITE\1000HCAS.PCK at position 1024         SMS_LAN_SENDER 1/22/2015 12:33:46 AM         3192 (0x0C78)
 
Sending completed [E:\ConfigMgr\inboxes\rcm.box\CabFiles\PR1_B97186CC-FCB7-43D8-A24E-7C9DF3903F12.cab]    SMS_LAN_SENDER                1/22/2015 12:33:46 AM         3192 (0x0C78)

 

Now checking the InitializationStatus in the SpDiagDRS,

 

So until the time the BCPOut happens and the compression is not completed we are at the status 3 which means Pending creation . Now when we see the line ‘created minijob ….’ Which means the package was creates and marked for sending, would make the status 4 as ‘ Package Created ’ in the SpDiagDRS.

 

The status would remain the same until the Package is send to the destination and once the destination receives the package and starts BCPIn the status changes to 5 meaning ‘ PendingApplication ’. From here if the BCPIn (bulk copy) succeeds then it will change the Initialization Status to 6 meaning ACTIVE or if the BCPIn fails the status would change to 99 meaning ‘ Error’.

 

Now going to the Primary SQL for snippets of the SSB messages received from the CAS SSB. (Note that I have filtered for the spRCMActivation meaning only for the message arriving at the ConfigMgrRCMQueue which plays a part in the DRS Initialization)

 

select * from VLogs where Logtext not like '%not sending changes%' and Logtext
 not like '%no changes detected%' and ProcedureName like 
'%spRCMActivation%' order by logline desc

Output:

spRCMActivation      INFO: Received DRS_InitPackageCreated for replication group: Replication Configuration NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_InitRequestReceived for replication group: Replication Configuration NULL   NULL   2
 
spRCMActivation      INFO: Finished processing DRS_SubscriptionInvalid from Site PR1 for replication group: Replication Configuration    NULL   NULL   2
 
spRCMActivation      INFO: DRS_SubscriptionInvalid is for full initialization - marking required replication group. NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_SubscriptionInvalid from Site PR1 for replication group: Replication Configuration and fulfilling site: CAS and requesting site: PR1 NULL   NULL   2

So the topmost message that was received DRS_InitPackageCreated was which is possibly the last message (processing this message changes the InitializationStatus to 4 meaning ‘PackageCreated’) after which the sending starts from CAS to the PRI.

 

RCMCtrl.log for Primary

 

Checking bcpDirectory E:\ConfigMgr\inboxes\rcm.box\684B6617-7F29-451B-815B-78E42C46A0C3                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Found files for publication Replication Configuration-CAS.  SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM                4508 (0x119C)
 
Publication names match. Checking vesrion.         SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Found our tracking guid          SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Initializing to version number 32678.    SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Publication Replication Configuration has ID 1.     SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Flushing DRS queue messages coming from CAS for replication group Replication Configuration.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Executing pre-snapshot stored procedures for group Replication Configuration. SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Processing Replication success.             SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         2124 (0x084C)
 
Pre-snapshot stored procedures for group Replication Configuration finished. Applying bcp files.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:52 AM         4508 (0x119C)
 
Removing old data for global table ... [EXEC spSMSTruncateGlobalTable ArticleData]      SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:53 AM         4508 (0x119C)
 
Rcm control is waiting for file change notification or timeout after 60 seconds.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:53 AM         4880 (0x1310)
 
Cleaning the RCM inbox if there are any *.RCM files for further change notifications....    SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:53 AM         4880 (0x1310)
 
Rcm control is waiting for file change notification or timeout after 60 seconds.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:53 AM         4880 (0x1310)
 
Rowcount from file [E:\ConfigMgr\inboxes\rcm.box\684B6617-7F29-451B-815B-78E42C46A0C3\ArticleData.bcp.rowcount] is [850].                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:53 AM         4508 (0x119C)
 
Successfully bulk copied file [E:\ConfigMgr\inboxes\rcm.box\684B6617-7F29-451B-815B-78E42C46A0C3\ArticleData.bcp] into table [ArticleData] with rows [850].               SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:53 AM         4508 (0x119C)

<Removing the same limes for other tables and continuing the log>

 

Bcp files have been applied. Executing post-snapshot stored procedures for group Replication Configuration.                SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:54 AM         4508 (0x119C)
 
Post-snapshot stored procedures for group Replication Configuration finished. SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:54 AM         4508 (0x119C)
 
STATMSG: ID=7805 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_REPLICATION_CONFIGURATION_MONITOR" SYS=CM12PR1.uk.lab SITE=PR1 PID=4076 TID=4508 GMTDATE=Wed Jan 21 19:33:54.608 2015 ISTR0="Replication Configuration" ISTR1="CAS" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0           SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:54 AM         4508 (0x119C)
 
Sent InitFinished message to CAS for replication ID 1.         SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:54 AM                4508 (0x119C)
 
STATMSG: ID=7816 SEV=E LEV=M SOURCE="SMS Server" COMP="SMS_REPLICATION_CONFIGURATION_MONITOR" SYS=CM12PR1.uk.lab SITE=PR1 PID=4076 TID=2124 GMTDATE=Wed Jan 21 19:33:55.812 2015 ISTR0="PR1" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0          SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:55 AM         2124 (0x084C)
 
Setting site PR1 to status ReplicationActive.        SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:55 AM         2124 (0x084C)
 
Set the SiteMaintenanceMode registry key to 0   SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:55 AM         2124 (0x084C)
 
STATMSG: ID=7821 SEV=I LEV=M SOURCE="SMS Server" COMP="SMS_REPLICATION_CONFIGURATION_MONITOR" SYS=CM12PR1.uk.lab SITE=PR1 PID=4076 TID=2124 GMTDATE=Wed Jan 21 19:33:55.933 2015 ISTR0="" ISTR1="" ISTR2="" ISTR3="" ISTR4="" ISTR5="" ISTR6="" ISTR7="" ISTR8="" ISTR9="" NUMATTRS=0          SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:55 AM         2124 (0x084C)
 
Changed the status of ConfigMgrDRSQueue to ON if it exists.            SMS_REPLICATION_CONFIGURATION_MONITOR                1/22/2015 12:33:55 AM           2124 (0x084C)

The lines above make more sense now and once the bulk copy completes a DRS_InitFinished is send to the CAS to mark the end of Initialization for the group.

 

On CAS in the VLogs filtered for SpRCMActivation, we can see the below messages. Note that we also send the DRS_ApplyingBcp message when the BCPIn is in progress. The number after the parenthesis is the percent complete. At last when the complete happens, An InitFinished message is send and received in the CAS as shown below which marks the InitializationStatus 6 or Active for the group.

 

 
spRCMActivation      INFO: Received DRS_InitFinished from Site PR1 for replication group: Replication Configuration with Version 295202   NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_ApplyingBcp (99) from site PR1 for replication group: Replication Configuration  NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_ApplyingBcp (99) from site PR1 for replication group: Replication Configuration  NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_ApplyingBcp (98) from site PR1 for replication group: Replication Configuration  NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_ApplyingBcp (98) from site PR1 for replication group: Replication Configuration  NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_ApplyingBcp (96) from site PR1 for replication group: Replication Configuration  NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_ApplyingBcp (95) from site PR1 for replication group: Replication Configuration  NULL   NULL   2
 
spRCMActivation      INFO: Received DRS_ApplyingBcp (59) from site PR1 for replication group: Replication Configuration  NULL   NULL   2

 

So that completes the initialization flow for the DRS. Yes things could not be as smooth as shown here but the flow will help in identifying where the issue is and then fix the same. For knowing more about troubleshooting the DRS you can follow:

http://blogs.technet.com/b/umairkhan/archive/2014/03/25/configmgr-2012-drs-troubleshooting-faqs.aspx

 

Hope it helps!

 

Umair Khan
Support Escalation Engineer Microsoft System Center Configuration Manager


Disclaimer: This posting is provided "AS IS" with no warranties and confers no rights.

Leave a Reply

Your email address will not be published. Required fields are marked *

*

This site uses Akismet to reduce spam. Learn how your comment data is processed.