How to use Merge Replication Centralized Logging Feature

Eric Lucht
Microsoft SQL Server Escalation Services

Centralized troubleshooting refers to the ability to generate detailed Merge agent log files on both client and Web server (for Web Synchronization), and gather the log files into a central location on the publisher as part of the sync process, no matter where the reconciler is run.  When this is enabled:

  • The log files are generated by default at a minimum logging level
  • Replmerg.log is created in the 100\COM directory when the Merge agent is run.
  • If using Web Sync, a websync.log is also generated in the virtual directory with the minimum logging.
  • If using ActiveX, then SQLMergex.log is created.
  • At the end of the reconciliation, the log file for that sync is automatically uploaded to the publisher and stored in a table in a varbinary (max) column.

For background information on Merge Agent logging options see BLOG posting: How to change the reporting level for the Merge Replication ReplMerg.log

This BLOG posting covers the stored procedures that enable Centralized logging feature.

Supportability Modes

Centralized logging feature makes use of supportability mode to determine the kind of logging and data collection that will be done. Supportability modes are specific to each subscriber, and they can be set for individual subscribers by calling certain administrative stored procedures.

The following are the different supportability modes supported by the centralized logging infrastructure

Supportability mode

Description

0

Centralized troubleshooting functionality is disabled

1

Upload output from the custom script and log files

2

Upload output from the custom script only

3

Upload output from the custom script and log files only for failed syncs

4

Upload output from the custom script and log files only on a message pattern

5

Upload output from the custom script on a message pattern

 

In order to set these options, the following stored procedures have been provided:

sys.sp_addmergelogsettings:

@publication         sysname = NULL,

@subscriber          sysname = NULL,

@subscriber_db             sysname = NULL,

@support_options           int = 1,             // Supportability mode

@web_server          sysname = NULL,

@log_severity        int = 2,

@log_file_path             nvarchar(255) = NULL,

@log_file_name             sysname = NULL,

@log_file_size             int = 10000000,

@no_of_log_files           int = 5,

@upload_interval           int = 0,

@delete_after_upload int = 1,

@custom_script             nvarchar(2000) = NULL,

@message_pattern           nvarchar(2000)= NULL

sys.sp_changemergelogsettings:

@publication         sysname = NULL,

@subscriber          sysname = NULL,

@subscriber_db             sysname = NULL,

@support_options     int = NULL,   // Supportability mode

@web_server          sysname = NULL,

@log_severity        int = NULL,

@log_file_path             nvarchar(255) = NULL,

@log_file_name             sysname = NULL,

@log_file_size             int = NULL,

@no_of_log_files     int = NULL,

@upload_interval     int = NULL,

@delete_after_upload int = NULL,

@custom_script             nvarchar(2000) = NULL,

@message_pattern           nvarchar(2000) = NULL


sys.sp_dropmergelogsettings:

@publication         sysname = NULL,

@subscriber          sysname = NULL,

@subscriber_db             sysname = NULL,

@web_server          sysname = NULL

 

Enabling Supportability Modes

Let’s look at Exercise 1 from the scenario and see what happens when we add a supportability setting for the subscriber

1. Create a publication on a database in Server A.

2. Create a pull subscription on Server B for this publication (set the agent to run “On Demand;” this makes it easier to observe the behavior).

3. Check the 100\COM folder on the subscriber and make sure there is no existing replmerg.log. If there is one, delete it.

4. Add a supportability setting for this subscriber by calling sp_addmergelogsettings with the appropriate parameters, for example, if we take the ‘TradingPub’ scenario.

 use tradingpub

go

sp_addmergelogsettings

    @publication= N'trading',       

    @subscriber=N'fastnfurious',     

    @subscriber_db=N'testpull',

    --@web_server

    @support_options=1,   

    @log_severity=4,

    @log_file_path='C:\Logs',

    @log_file_name='replsupportlog.txt',

    @log_file_size = 10000000,

    @no_of_log_files = 5,

    @upload_interval = 0,

    @delete_after_upload =0

 

When this stored procedure is executed on the published database, it adds a row into the MSMerge_log_settings table, which will be used later by merge agent to determine what kind of logging needs to be done.

5. Run the Merge agent.

What difference do you notice with the logging? What files are created, and where are they created?

A few key things happen when you enable supportability mode for a subscriber:

1. A new log file is created in the directory specified in the sp_addmergelogsettings procedure @log_file_path='C:\Logs', @log_file_name='replsupportlog.txt' at the severity level mentioned.

2. At the end of the sync, the log file is uploaded to the publisher, loaded into the table Msmerge_log_files, and the log is stored in a varbinary(Max) column.

3. The replmerg.log in the 100\COM folder is still created, but the logging is stopped in that file and continued in the above file. The last entry in the replmerg.log will indicate this fact.

Here is the replmerg.log in 100\COM:

MODULE NAME

UTC DateTime

TID

LINE

SEV

MESSAGE

CReplDebugLog

8/4/05 5:24 AM

3324

288

S1

Starting log file.

CReconcilerTask

8/4/05 5:24 AM

3324

406

S1

INFO: =============== STARTING OF MERGE ===============

CReconcilerTask

8/4/05 5:24 AM

3324

484

S2

INFO: CommandLine:  "C:\Program Files\Microsoft SQL Server\100\COM\replmerg.exe"

 -Publisher [FASTNFURIOUSSQL] -PublisherDB [TradingPub] -Publication [Trading]

 -Subscriber [FASTNFURIOUS] -SubscriberDB [Testpull] -SubscriptionType 1

 -SubscriberSecurityMode 1 -Distributor

CReconcilerTask

8/4/05 5:24 AM

3324

492

S2

INFO:   [FASTNFURIOUSSQL] -XJOBID 0x5215C27D549664448B4D4575ED8235CA

-XJOBNAME [FASTNFURIOUSSQL-TradingPub-Trading-FASTNFURIOUS-Testpull- 0]

 -XSTEPID 1 -XSUBSYSTEM Merge -XSERVER [FASTNFURIOUS] -XCMDLINE 0

 -XCancelEventHandle 00000868

DatabaseReconciler

8/4/05 5:24 AM

3324

12724

S2

INFO: Reading profile: AgentID:5, AgentType:4, ProfileName:

DatabaseReconciler

8/4/05 5:24 AM

3324

1740

S1

INFO: Running in supportability mode:1.

Replprov.dll

8/4/05 5:24 AM

3324

19178

S1

INFO: Sev: 4, Mod: 0x00000000, FilePath: C:\Logs, FileName: replmerg.log

, Size: 10000000, Files: 5, UploadReq: 1, DeleteAfterUpload: 0

 

Here is the replsupportlog.txt created in the c:\log directory. Notice that this file is a continuation from the replmerg.log. If supportability mode was not specified, all the information below would have been included in replmerg.log.

MODULE NAME

UTC DateTime

TID

LINE,

SEV,

MESSAGE

CReplDebugLog

8/4/05 5:16 AM

1024

288,

S1,

Starting log file.

DatabaseReconciler

8/4/05 5:16 AM

1024

23669,

S1,

INFO: =============== STARTING OF MERGE ===============

DatabaseReconciler

8/4/05 5:16 AM

1024

4947,

S4,

INFO: Reconciler CoreReconcile.

DatabaseReconciler

8/4/05 5:16 AM

1024

4971,

S4,

INFO: DB codepage [Upload], SubscriberCodePage = 1252

, PublisherCodePage = 1252

Undefined

8/4/05 5:16 AM

1024

3020,

S3,

INFO: EnumeratingSchemaChanges SubscriberSchemaVersion 55

DatabaseReconciler

8/4/05 5:16 AM

1024

4534,

S2,

:T:,10,87,0,17,17,17,17,,,

DatabaseReconciler

8/4/05 5:16 AM

1024

4541,

S4,

INFO: Read Watermarks:[Upload], SubRec:17, SubSent:17, PubRec:17, PubSent:17

DatabaseReconciler

8/4/05 5:16 AM

1024

5587,

S2,

:T:,20,87,Trading,FASTNFURIOUSSQL,FASTNFURIOUS,FASTNFURIOUSSQL

,TradingPub,Testpull,default,

Replprov.dll

8/4/05 5:16 AM

1024

3016,

S4,

INFO: EnumerateGenerationRange: [Upload], startgen = 17, mingen = 0, maxgen =-1

, numgens = 500

Replprov.dll

8/4/05 5:16 AM

1024

3352,

S4,

INFO: EnumerateGenerationRange: Added gen = 17

Replprov.dll

8/4/05 5:16 AM

1024

3634,

S4,

DBG: [Upload], Command: {call sp_MScheckexistsgeneration (?, ?) }

DatabaseReconciler

8/4/05 5:16 AM

1024

7268,

S4,

INFO: MakeGenString: [Upload], SrcGen = 17, Skipping (Generation exists)

DatabaseReconciler

8/4/05 5:16 AM

1024

7418,

S2,

:T:,100,87,0,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,

DatabaseReconciler

8/4/05 5:16 AM

1024

7499,

S4,

INFO: MakeGenString: [Upload], GenList = []

Replprov.dll

8/4/05 5:16 AM

1024

2750,

S4,

INFO: Update Watermarks:[Upload], SubSent:17

Replprov.dll

8/4/05 5:16 AM

1024

2756,

S2,

:T:,80,87,0,sub,17,,,,,

Replprov.dll

8/4/05 5:16 AM

1024

2413,

S4,

INFO: Update Watermarks:[Upload], PubRec:17

Replprov.dll

8/4/05 5:16 AM

1024

2419,

S2,

:T:,70,87,0,pub,17,,,,,

Replprov.dll

8/4/05 5:16 AM

1024

2907,

S4,

DBG: GetReplicaState from Database 28ca1a5f-c15b-4acf-90bb-19665fcf98b5

Replprov.dll

8/4/05 5:16 AM

1024

2907,

S4,

DBG: GetReplicaState from Database 28ca1a5f-c15b-4acf-90bb-19665fcf98b5

Replprov.dll

8/4/05 5:16 AM

1024

3016,

S4,

INFO: EnumerateGenerationRange: [Download], startgen = 17, mingen = 0

, maxgen

Replprov.dll

8/4/05 5:16 AM

1024

3352,

S4,

INFO: EnumerateGenerationRange: Added gen = 17

Replprov.dll

8/4/05 5:16 AM

1024

3634,

S4,

DBG: [Download], Command: {call sp_MScheckexistsgeneration (?, ?) }

DatabaseReconciler

8/4/05 5:16 AM

1024

7268,

S4,

INFO: MakeGenString: [Download], SrcGen = 17, Skipping (Generation exists)

DatabaseReconciler

8/4/05 5:16 AM

1024

7418,

S2,

:T:,100,87,1,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,

DatabaseReconciler

8/4/05 5:16 AM

1024

7499,

S4,

INFO: MakeGenString: [Download], GenList = []

Replprov.dll

8/4/05 5:16 AM

1024

2750,

S4,

INFO: Update Watermarks:[Download], PubSent:17

Replprov.dll

8/4/05 5:16 AM

1024

2756,

S2,

:T:,80,87,1,pub,17,,,,,

Replprov.dll

8/4/05 5:16 AM

1024

2413,

S4,

INFO: Update Watermarks:[Download], SubRec:17

Replprov.dll

8/4/05 5:16 AM

1024

2419,

S2,

:T:,70,87,1,sub,17,,,,,

Replprov.dll

8/4/05 5:16 AM

1024

2929,

S4,

DBG: UpdateReplicaState to Database a1922bd9-0674-43d6-b97c-fce42d4ff5f2

Replprov.dll

8/4/05 5:16 AM

1024

2929,

S4,

DBG: UpdateReplicaState to Database a1922bd9-0674-43d6-b97c-fce42d4ff5f2

DatabaseReconciler

8/4/05 5:16 AM

1024

3729,

S2,

:T:,110,87,0,,,,,,,

DatabaseReconciler

8/4/05 5:16 AM

1024

3736,

S1,

INFO: ID = 87, Session Highlights:

DatabaseReconciler

8/4/05 5:16 AM

1024

23884,

S1,

INFO: =============== STOPPED LOGGING FOR

 UPLOAD OF LOG FILE ===============

 

Uploading the file to the publisher

At the end of the sync, the above file is automatically uploaded to the publisher database, and an entry is added to the Msmerge_log_files table where this file is stored in a varbinary(max) column.

So if you query the table Msmerge_log_files, you will see new entries being added at the end of each sync, depending on the @support_options value.

 
What is the purpose of uploading the file?

The idea behind this is to have a central repository for all the log files, and this can be particularly useful if there are a large number of subscribers in the topology.

Once the file has been uploaded to the table, it can be used for further analysis.

The following is the process for reading the data out of the varbinary (max) column: (yes it is a bit messy)

1.     Create a new folder.

2.     Create a format file called bcp.fmt with the following lines and save it into the above folder:

 

         9.0
         1
         1       SQLBINARY     0       0       ""   1     log_file     ""

 

3.     Run the following command from that folder (change parameter values accordingly for this, for example, TradingPub is used).

 

bcp "select top 1 log_file from tradingpub..MSmerge_log_files where id = 1 and log_file_type in(101,102)" queryout temp1.cab -T -S fastnfurioussql -f bcp.fmt

 

This will give you a cab file named temp1.cab

 

4.     Run the following command to expand the cab file:

 

     expand temp1.cab temp1.log

 

Take a look at temp1.log. What information do you see? The replsupportlog.txt.

Important: Now that you have a fixed length text file, you can load this data into an analysis database and run analysis queries.

 
When to use centralized logging and replmerg.log

When facing a Merge replication problem the above logs should provide you with an idea of what the problem is and where to start looking.

Once you have a fair idea about the problem from the above logs, determine if you need the logging using the centralized troubleshooting, and determine the level required based on the complexity of the problem, frequency of occurrence, etc.

A good guideline for using the highest level of centralized logging is if the problem is reproducible consistently. If that is the case, enable centralized logging at the highest level and get the data and disable the logging immediately so that there is no performance impact.

On the contrary, if the issue is not reproducible and is a random occurrence, you might want to start off with enabling centralized logging at a lower level of logging, and see if that data provides enough information to troubleshoot the issue.

 

Edited and Posted by: Chris Skorlinski