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

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:

MergeAgentLoggingOff

DWORD

1

MergeAgentLogSeverity     

DWORD

4

MergeAgentNumberOfLogFiles 

DWORD

5

MergeAgentLogFileSize    

DWORD

100000

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