Eric LuchtMicrosoft 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:
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.
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:
@support_options int = NULL, // Supportability mode
@log_severity int = NULL,
@log_file_size int = NULL,
@no_of_log_files int = NULL,
@upload_interval int = NULL,
@delete_after_upload int = NULL,
@message_pattern nvarchar(2000) = NULL
sys.sp_dropmergelogsettings:
@web_server sysname = NULL
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
406
INFO: =============== STARTING OF MERGE ===============
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
492
INFO: [FASTNFURIOUSSQL] -XJOBID 0x5215C27D549664448B4D4575ED8235CA
-XJOBNAME [FASTNFURIOUSSQL-TradingPub-Trading-FASTNFURIOUS-Testpull- 0]
-XSTEPID 1 -XSUBSYSTEM Merge -XSERVER [FASTNFURIOUS] -XCMDLINE 0
-XCancelEventHandle 00000868
DatabaseReconciler
12724
INFO: Reading profile: AgentID:5, AgentType:4, ProfileName:
1740
INFO: Running in supportability mode:1.
Replprov.dll
19178
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.
LINE,
SEV,
8/4/05 5:16 AM
1024
288,
S1,
23669,
4947,
S4,
INFO: Reconciler CoreReconcile.
4971,
INFO: DB codepage [Upload], SubscriberCodePage = 1252
, PublisherCodePage = 1252
Undefined
3020,
S3,
INFO: EnumeratingSchemaChanges SubscriberSchemaVersion 55
4534,
S2,
:T:,10,87,0,17,17,17,17,,,
4541,
INFO: Read Watermarks:[Upload], SubRec:17, SubSent:17, PubRec:17, PubSent:17
5587,
:T:,20,87,Trading,FASTNFURIOUSSQL,FASTNFURIOUS,FASTNFURIOUSSQL
,TradingPub,Testpull,default,
3016,
INFO: EnumerateGenerationRange: [Upload], startgen = 17, mingen = 0, maxgen =-1
, numgens = 500
3352,
INFO: EnumerateGenerationRange: Added gen = 17
3634,
DBG: [Upload], Command: {call sp_MScheckexistsgeneration (?, ?) }
7268,
INFO: MakeGenString: [Upload], SrcGen = 17, Skipping (Generation exists)
7418,
:T:,100,87,0,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
7499,
INFO: MakeGenString: [Upload], GenList = []
2750,
INFO: Update Watermarks:[Upload], SubSent:17
2756,
:T:,80,87,0,sub,17,,,,,
2413,
INFO: Update Watermarks:[Upload], PubRec:17
2419,
:T:,70,87,0,pub,17,,,,,
2907,
DBG: GetReplicaState from Database 28ca1a5f-c15b-4acf-90bb-19665fcf98b5
INFO: EnumerateGenerationRange: [Download], startgen = 17, mingen = 0
, maxgen
DBG: [Download], Command: {call sp_MScheckexistsgeneration (?, ?) }
INFO: MakeGenString: [Download], SrcGen = 17, Skipping (Generation exists)
:T:,100,87,1,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
INFO: MakeGenString: [Download], GenList = []
INFO: Update Watermarks:[Download], PubSent:17
:T:,80,87,1,pub,17,,,,,
INFO: Update Watermarks:[Download], SubRec:17
:T:,70,87,1,sub,17,,,,,
2929,
DBG: UpdateReplicaState to Database a1922bd9-0674-43d6-b97c-fce42d4ff5f2
3729,
:T:,110,87,0,,,,,,,
3736,
INFO: ID = 87, Session Highlights:
23884,
INFO: =============== STOPPED LOGGING FOR
UPLOAD OF LOG FILE ===============
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.
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 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