How to change the reporting level for the Merge Replication ReplMerg.log

ReplTalk Troubleshooting March 22, 2010

Share this Post

Eric Lucht | Microsoft SQL Server Escalation Services

Logging Options

When the Merge subsystem is initialized, agent logging is automatically enabled using default values. The Agent will begin logging in the replmerg.log being created in the 100\COM (90\COM for SQL 2005) folder. This blog posting covers registry keys used to override the logging level of the Merge Agent.

For details on the Centralized logging feature see BLOG posting: How to use Merge Replication Centralized Logging Feature

Registry Keys

The registry key settings below can be used to override the default logging behavior. Merge replication debug log setting are set as values in the registry under the registry key HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Microsoft SQL Server\100\Replication. These values may or may not exist in the registry. You will have to create them if they don’t exist. Don’t perform these steps if you’re uncomfortable making registry changes.

Value name	Value type	Min	Max	Default	Comments
MergeAgentLoggingOff	DWORD	0	1	0	Merge agent logging on or off
MergeAgentLogSeverity	DWORD	1	4	2	Merge agent log severity
MergeAgentNumberOfLogFiles	DWORD	2	–	5	Number of Merge agent log files to save
MergeAgentLogFileSize	DWORD	1000000	–	10000000	Size of each log file
WebSyncLoggingOff	DWORD	0	1	0	IIS side websync logging on or off
WebSyncLogSeverity	DWORD	1	4	2	IIS side websync log severity
WebSyncNumberOfLogFiles	DWORD	2	–	5	Number of log files to save
WebSyncLogFileSize	DWORD	1000000	–	10000000	Size of each log file
SQLMergXLoggingOff	DWORD	0	1	0	SQL Merge ActiveX logging on or off
SQLMergXLogSeverity	DWORD	1	4	2	SQL Merge ActiveX log severity
SQLMergXNumberOfLogFiles	DWORD	2	–	5	Number of SQL Merge ActiveX log files to save
SQLMergXLogFileSize	DWORD	1000000	–	10000000	Size of each log file

Let’s take a look at an example of a pull subscription to a publication.

Server A -> Publisher\Distributor
Server B -> Subscriber

Merge Agent is running on the subscriber. If the Merge agent is run without adding any additional logging parameters, there will be a replmerg.log created by default in the Program Files\Microsoft SQL Server\100\COM folder in Server B. This log has minimum level of logging. The logging level can be changed by adding the MergeAgentLogSeverity key and setting it to a higher value.

Note: The highest level of logging is very extensive and can cause a huge performance impact for the agent. Use the highest level of logging on an as needed basis.

Logging Exercise

For the purpose of understanding how all of the above works, let’s set up centralized logging. For better clarity, use two instances of SQL Server on two physically separate machines:

Server A: Publisher\Distributor
Server B: Subscriber

Exercise 1

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; make sure there is no existing replmerg.log. If there is one, delete it.

4. Run the Merge agent for the first time.

Note: At this point we have not added any parameters to enable logging. To make sure you can check the registry key mentioned earlier, by default none of the keys are added.

Take a look at the subscriber server’s 100\COM directory.

Do you see a replmerg.log? Yes. So this tells you that in SQL Server 2005, by default, the Merge agent logging is enabled and the log by default will reside in the 100\COM directory on the server where the reconciler is invoked.

So is there a way to disable this logging or increase the level of logging? You can do this by adding the registry keys mentioned above. Let’s add those keys and see what happens.

Exercise 2

On the subscriber server, add the following keys with the values mentioned:

1. Re-name the replmerg.log.

2. Run the merge agent again.

Do you see a new replmerg.log created? If not, then why? How can you enable the logging again?

As you can see, the value for MergeAgentLoggingOff is set to 1, meaning the logging is OFF. If you set it back to 0, then the logging will start again.

Exercise 3

1. Enable logging by setting the value of MergeAgentLoggingOff to 0.

2. Run the merge agent.

3. Take a look at the log file.

What information do you see? Are you able to interpret the information in a meaningful manner? What does the log file contain?

Log Format

The log format is quite different from what it used to be in SQL Server 2000. The log has the following format in general. The amount of information logged depends on the severity setting.

MODULE NAME	DATE	UTC Time	TID	LINE	SEV	MESSAGE
Name of the module that generates the log message	Current date	Time zone independent time	Thread ID of the thread that writes the log line	Line number in the code where the log line is generated	Severity of the log line	Log message. See the tables below to understand the content of this column further

MESSAGE Prefix	Comments
ERROR:	Indicates that an error occurred during the sync. The error message is displayed as part of the message. In most cases, the same message will be displayed on the console and will also be written to the distribution database
WARN:	This indicates that the message is something to make note of, but not lead, to an error right away. There are very few of these
INFO:	This indicated that the message is for information purpose only. Looking through the info: messages that give a good idea about what is going on during the sync. Info: messages are displayed at important phases of the sync. It has information about the watermarks exchanged, generations enumerated, changes sent across etc.
DBG:	These messages are useful to someone who has access to the code. They are used to dig deeper into a problem once it has been narrowed down to a specific phase in the system. These are displayed only at severity 4
:T:	This indicates that the message is a trace record. These messages are uploaded to the central MSmergediag database and used to programmatically troubleshoot the problem. These are written for programmatic analysis and so are hard to read. At severity 3,there will be an info: message that corresponds to every :T: message. The first number following the :T: prefix is the trace id. See the section below for the meaning of each of the trace id
None of the above	When there is no prefix, you can assume it means DBG:

Trace records

Trace id	Friendly name	Format
10	Watermarks	:T:, ID, SessionID, download, SrcRecGen, SrcSentGen, DestRecGen, DestSentGen
20	SessionProperties	:T:, ID, SessionID, publication, publisher, subscriber, distributor, publisherdb, subscriberdb, [default\|websync-[client\|server]]
30	GenerationProcessed	:T:, ID, SessionID, download, Generation, GenGuid ApproxChangesInGeneration
40	RowEnumeration	:T:, ID, SessionID, download, Generation, tablenick, rowguid
50	RowReconcile	:T:, ID, SessionID, download, tablenick, rowguid, REPOLE_CHANGE_TYPE
60	RowCommand	:T:, ID, SessionID, download, Command, tablenick, rowguid
70	SetLastReceivedWatermark	:T:, ID, SessionID, download, Generation
80	SetLastSentWatermark	:T:, ID, SessionID, download, Generation
90	RowRetryAdded	:T:, ID, SessionID, download, tablenick, rowguid, ErrorText
100	GenerationSkipped	:T:, ID, SessionID, download, Generation, GenGuid

Severity 2

Here is a sample log with default severity 2 (log modified for clarity. This sync had no changes to be replicated).

MODULE NAME	UTC DateTime ,	SEV,	MESSAGE
CReplDebugLog	2005/08/04 04:07:00.804,	S1,	Starting log file.
CReconcilerTask	2005/08/04 04:07:00.804,	S1,	INFO: =============== STARTING OF MERGE ===============
CReconcilerTask	2005/08/04 04:07:00.804,	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	2005/08/04 04:07:00.804,	S2,	INFO: [FASTNFURIOUSSQL] -XJOBID 0x5215C27D549664448B4D4575ED8235CA -XJOBNAME [FASTNFURIOUSSQL-TradingPub-Trading-FASTNFURIOUS-Testpull- 0] -XSTEPID 1 -XSUBSYSTEM Merge -XSERVER [FASTNFURIOUS] -XCMDLINE 0 -XCancelEventHandle 00000848
DatabaseReconciler	2005/08/04 04:07:05.444,	S2,	INFO: Reading profile: AgentID:5, AgentType:4, ProfileName:
DatabaseReconciler	2005/08/04 04:07:11.538,	S2,	:T:,10,85,0,17,17,17,17,,,
DatabaseReconciler	2005/08/04 04:07:11.663,	S2,	:T:,20,85,Trading,FASTNFURIOUSSQL,FASTNFURIOUS,FASTNFURIOUSSQL ,TradingPub,Testpull,default,
DatabaseReconciler	2005/08/04 04:07:14.444,	S2,	:T:,100,85,0,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
Replprov.dll	2005/08/04 04:07:14.600,	S2,	:T:,80,85,0,sub,17,,,,,
Replprov.dll	2005/08/04 04:07:14.600,	S2,	:T:,70,85,0,pub,17,,,,,
DatabaseReconciler	2005/08/04 04:07:16.210,	S2,	:T:,100,85,1,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
Replprov.dll	2005/08/04 04:07:16.257,	S2,	:T:,80,85,1,pub,17,,,,,
Replprov.dll	2005/08/04 04:07:16.288,	S2,	:T:,70,85,1,sub,17,,,,,
DatabaseReconciler	2005/08/04 04:07:16.694,	S2,	:T:,110,85,0,,,,,,,
DatabaseReconciler	2005/08/04 04:07:16.694,	S1,	INFO: ID = 85, Session Highlights:
CReconcilerTask	2005/08/04 04:07:17.100,	S1,	INFO: =============== ENDING OF MERGE =================

Severity 4

Here is the same scenario with severity 4:

MODULE NAME	UTC DateTime	TID	LINE,	SEV	MESSAGE
CReplDebugLog	8/4/05 4:49 AM	1336	288,	S1	Starting log file.
CReconcilerTask	8/4/05 4:49 AM	1336	406,	S1	INFO: =============== STARTING OF MERGE ===============
CReconcilerTask	8/4/05 4:49 AM	1336	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 4:49 AM	1336	492,	S2	INFO: [FASTNFURIOUSSQL] -XJOBID 0x5215C27D549664448B4D4575ED8235CA -XJOBNAME [FASTNFURIOUSSQL-TradingPub-Trading-FASTNFURIOUS-Testpull- 0] -XSTEPID 1 -XSUBSYSTEM Merge -XSERVER [FASTNFURIOUS] -XCMDLINE 0 -XCancelEventHandle 0000089C
DatabaseReconciler	8/4/05 4:49 AM	1336	878,	S4	INFO: Reconciler initialize.
DatabaseReconciler	8/4/05 4:49 AM	1336	1050,	S4	INFO: Reconciler CoreInitialize.
DatabaseReconciler	8/4/05 4:49 AM	1336	12724,	S2	INFO: Reading profile: AgentID:5, AgentType:4, ProfileName:
DatabaseReconciler	8/4/05 4:49 AM	1336	13044,	S4	INFO: Using profile parameter: -BcpBatchSize 100000
DatabaseReconciler	8/4/05 4:49 AM	1336	13020,	S4	INFO: Using profile parameter: -ChangesPerHistory 100
DatabaseReconciler	8/4/05 4:49 AM	1336	13088,	S4	INFO: Using profile parameter: -DestThreads 2
DatabaseReconciler	8/4/05 4:49 AM	1336	12865,	S4	INFO: Using profile parameter: -DownloadGenerationsPerBatch 50
DatabaseReconciler	8/4/05 4:49 AM	1336	12891,	S4	INFO: Using profile parameter: -DownloadReadChangesPerBatch 100
DatabaseReconciler	8/4/05 4:49 AM	1336	12917,	S4	INFO: Using profile parameter: -DownloadWriteChangesPerBatch 100
DatabaseReconciler	8/4/05 4:49 AM	1336	12990,	S4	INFO: Using profile parameter: -FastRowCount 1
DatabaseReconciler	8/4/05 4:49 AM	1336	13001,	S4	INFO: Using profile parameter: -HistoryVerboseLevel 2
DatabaseReconciler	8/4/05 4:49 AM	1336	13032,	S4	INFO: Using profile parameter: -KeepAliveMessageInterval 300
DatabaseReconciler	8/4/05 4:49 AM	1336	12746,	S4	INFO: Using profile parameter: -LoginTimeout 15
DatabaseReconciler	8/4/05 4:49 AM	1336	13242,	S4	INFO: Using profile parameter: -MaxBcpThreads 2
DatabaseReconciler	8/4/05 4:49 AM	1336	12829,	S4	INFO: Using profile parameter: -MaxDownloadChanges 0
DatabaseReconciler	8/4/05 4:49 AM	1336	12839,	S4	INFO: Using profile parameter: -MaxUploadChanges 0
DatabaseReconciler	8/4/05 4:49 AM	1336	13116,	S4	INFO: Using profile parameter: -MetadataRetentionCleanup 1
DatabaseReconciler	8/4/05 4:49 AM	1336	13057,	S4	INFO: Using profile parameter: -NumDeadlockRetries 5
DatabaseReconciler	8/4/05 4:49 AM	1336	12940,	S4	INFO: Using profile parameter: -PollingInterval 60 [modified]
DatabaseReconciler	8/4/05 4:49 AM	1336	12790,	S4	INFO: Using profile parameter: -QueryTimeout 300
DatabaseReconciler	8/4/05 4:49 AM	1336	13073,	S4	INFO: Using profile parameter: -SrcThreads 2
DatabaseReconciler	8/4/05 4:49 AM	1336	12965,	S4	INFO: Using profile parameter: -StartQueueTimeout 0
DatabaseReconciler	8/4/05 4:49 AM	1336	12852,	S4	INFO: Using profile parameter: -UploadGenerationsPerBatch 50
DatabaseReconciler	8/4/05 4:49 AM	1336	12878,	S4	INFO: Using profile parameter: -UploadReadChangesPerBatch 100
DatabaseReconciler	8/4/05 4:49 AM	1336	12904,	S4	INFO: Using profile parameter: -UploadWriteChangesPerBatch 100
DatabaseReconciler	8/4/05 4:49 AM	1336	12929,	S4	INFO: Using profile parameter: -Validate 0
DatabaseReconciler	8/4/05 4:49 AM	1336	12979,	S4	INFO: Using profile parameter: -ValidateInterval 3600000 [modified]
DatabaseReconciler	8/4/05 4:49 AM	1336	4947,	S4	INFO: Reconciler CoreReconcile.
DatabaseReconciler	8/4/05 4:49 AM	1336	4971,	S4	INFO: DB codepage [Upload], SubscriberCodePage = 1252, PublisherCodePage = 1252
Undefined	8/4/05 4:49 AM	1336	3020,	S3	INFO: EnumeratingSchemaChanges SubscriberSchemaVersion 55
DatabaseReconciler	8/4/05 4:49 AM	1336	4534,	S2	:T:,10,86,0,17,17,17,17,,,
DatabaseReconciler	8/4/05 4:49 AM	1336	4541,	S4	INFO: Read Watermarks:[Upload], SubRec:17, SubSent:17, PubRec:17, PubSent:17
DatabaseReconciler	8/4/05 4:49 AM	1336	5587,	S2	:T:,20,86,Trading,FASTNFURIOUSSQL,FASTNFURIOUS,FASTNFURIOUSSQL ,TradingPub,Testpull,default,
Replprov.dll	8/4/05 4:49 AM	1336	3016,	S4	INFO: EnumerateGenerationRange: [Upload], startgen = 17, mingen = 0 , maxgen = -1, numgens = 500
Replprov.dll	8/4/05 4:49 AM	1336	3352,	S4	INFO: EnumerateGenerationRange: Added gen = 17
Replprov.dll	8/4/05 4:49 AM	1336	3634,	S4	DBG: [Upload], Command: {call sp_MScheckexistsgeneration (?, ?) }
DatabaseReconciler	8/4/05 4:49 AM	1336	7268,	S4	INFO: MakeGenString: [Upload], SrcGen = 17, Skipping (Generation exists)
DatabaseReconciler	8/4/05 4:49 AM	1336	7418,	S2	:T:,100,86,0,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
DatabaseReconciler	8/4/05 4:49 AM	1336	7499,	S4	INFO: MakeGenString: [Upload], GenList = []
Replprov.dll	8/4/05 4:49 AM	1336	2750,	S4	INFO: Update Watermarks:[Upload], SubSent:17
Replprov.dll	8/4/05 4:49 AM	1336	2756,	S2	:T:,80,86,0,sub,17,,,,,
Replprov.dll	8/4/05 4:49 AM	1336	2413,	S4	INFO: Update Watermarks:[Upload], PubRec:17
Replprov.dll	8/4/05 4:49 AM	1336	2419,	S2	:T:,70,86,0,pub,17,,,,,
Replprov.dll	8/4/05 4:49 AM	1336	2907,	S4	DBG: GetReplicaState from Database a12ae6cb-9440-4201-ab44-0970a5b10f23
Replprov.dll	8/4/05 4:49 AM	1336	2907,	S4	DBG: GetReplicaState from Database a12ae6cb-9440-4201-ab44-0970a5b10f23
Replprov.dll	8/4/05 4:49 AM	1336	3016,	S4	INFO: EnumerateGenerationRange: [Download], startgen = 17, mingen = 0 , maxgen = -1, numgens = 500
Replprov.dll	8/4/05 4:49 AM	1336	3352,	S4	INFO: EnumerateGenerationRange: Added gen = 17
Replprov.dll	8/4/05 4:49 AM	1336	3634,	S4	DBG: [Download], Command: {call sp_MScheckexistsgeneration (?, ?) }
DatabaseReconciler	8/4/05 4:49 AM	1336	7268,	S4	INFO: MakeGenString: [Download], SrcGen = 17, Skipping (Generation exists)
DatabaseReconciler	8/4/05 4:49 AM	1336	7418,	S2	:T:,100,86,1,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
DatabaseReconciler	8/4/05 4:49 AM	1336	7499,	S4	INFO: MakeGenString: [Download], GenList = []
Replprov.dll	8/4/05 4:49 AM	1336	2750,	S4	INFO: Update Watermarks:[Download], PubSent:17
Replprov.dll	8/4/05 4:49 AM	1336	2756,	S2	:T:,80,86,1,pub,17,,,,,
Replprov.dll	8/4/05 4:49 AM	1336	2413,	S4	INFO: Update Watermarks:[Download], SubRec:17
Replprov.dll	8/4/05 4:49 AM	1336	2419,	S2	:T:,70,86,1,sub,17,,,,,
Replprov.dll	8/4/05 4:49 AM	1336	2929,	S4	DBG: UpdateReplicaState to Database 28ca1a5f-c15b-4acf-90bb-19665fcf98b5
Replprov.dll	8/4/05 4:49 AM	1336	2929,	S4	DBG: UpdateReplicaState to Database 28ca1a5f-c15b-4acf-90bb-19665fcf98b5
DatabaseReconciler	8/4/05 4:49 AM	1336	3729,	S2	:T:,110,86,0,,,,,,,
DatabaseReconciler	8/4/05 4:49 AM	1336	3736,	S1	INFO: ID = 86, Session Highlights:
CReconcilerTask	8/4/05 4:49 AM	1336	639,	S1	INFO: =============== ENDING OF MERGE =================

Note: The amount of detail at level 4 logging is almost three times the logging detail you get with severity 3. To give a perspective on the log file size, severity 2 generated a 3KB file, while for the exact same operation, severity 4 generated a 15KB file

Exercise 4 (advanced)

Use the tables given under Log Format and see if you can decode the information in the log file.

Note: The message column has been truncated for clarity.

Exercise 5 (advanced)

1. Create a publication which allows Web Synchronization.

2. Create a Web Sync subscription.

3. Run the Merge agent.

Check the IIS virtual directory. Do you see a websync.log fle generated?

Edited and Posted by: Chris Skorlinski