Eric LuchtMicrosoft SQL Server Escalation Services
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
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
Merge agent logging on or off
MergeAgentLogSeverity
4
2
Merge agent log severity
MergeAgentNumberOfLogFiles
-
5
Number of Merge agent log files to save
MergeAgentLogFileSize
1000000
10000000
Size of each log file
WebSyncLoggingOff
IIS side websync logging on or off
WebSyncLogSeverity
IIS side websync log severity
WebSyncNumberOfLogFiles
Number of log files to save
WebSyncLogFileSize
SQLMergXLoggingOff
SQL Merge ActiveX logging on or off
SQLMergXLogSeverity
SQL Merge ActiveX log severity
SQLMergXNumberOfLogFiles
Number of SQL Merge ActiveX log files to save
SQLMergXLogFileSize
Let’s take a look at an example of a pull subscription to a publication.
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.
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:
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.
On the subscriber server, add the following keys with the values mentioned:
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.
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?
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
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 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
90
RowRetryAdded
:T:, ID, SessionID, download, tablenick, rowguid, ErrorText
100
GenerationSkipped
:T:, ID, SessionID, download, Generation, GenGuid
Here is a sample log with default severity 2 (log modified for clarity. This sync had no changes to be replicated).
UTC DateTime ,
SEV,
CReplDebugLog
2005/08/04 04:07:00.804,
S1,
Starting log file.
CReconcilerTask
INFO: =============== STARTING OF MERGE ===============
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
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,
INFO: Reading profile: AgentID:5, AgentType:4, ProfileName:
2005/08/04 04:07:11.538,
:T:,10,85,0,17,17,17,17,,,
2005/08/04 04:07:11.663,
:T:,20,85,Trading,FASTNFURIOUSSQL,FASTNFURIOUS,FASTNFURIOUSSQL
,TradingPub,Testpull,default,
2005/08/04 04:07:14.444,
:T:,100,85,0,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
Replprov.dll
2005/08/04 04:07:14.600,
:T:,80,85,0,sub,17,,,,,
:T:,70,85,0,pub,17,,,,,
2005/08/04 04:07:16.210,
:T:,100,85,1,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
2005/08/04 04:07:16.257,
:T:,80,85,1,pub,17,,,,,
2005/08/04 04:07:16.288,
:T:,70,85,1,sub,17,,,,,
2005/08/04 04:07:16.694,
:T:,110,85,0,,,,,,,
INFO: ID = 85, Session Highlights:
2005/08/04 04:07:17.100,
INFO: =============== ENDING OF MERGE =================
Here is the same scenario with severity 4:
UTC DateTime
LINE,
8/4/05 4:49 AM
1336
288,
S1
406,
484,
S2
492,
-XCancelEventHandle 0000089C
878,
S4
INFO: Reconciler initialize.
1050,
INFO: Reconciler CoreInitialize.
12724,
13044,
INFO: Using profile parameter: -BcpBatchSize 100000
13020,
INFO: Using profile parameter: -ChangesPerHistory 100
13088,
INFO: Using profile parameter: -DestThreads 2
12865,
INFO: Using profile parameter: -DownloadGenerationsPerBatch 50
12891,
INFO: Using profile parameter: -DownloadReadChangesPerBatch 100
12917,
INFO: Using profile parameter: -DownloadWriteChangesPerBatch 100
12990,
INFO: Using profile parameter: -FastRowCount 1
13001,
INFO: Using profile parameter: -HistoryVerboseLevel 2
13032,
INFO: Using profile parameter: -KeepAliveMessageInterval 300
12746,
INFO: Using profile parameter: -LoginTimeout 15
13242,
INFO: Using profile parameter: -MaxBcpThreads 2
12829,
INFO: Using profile parameter: -MaxDownloadChanges 0
12839,
INFO: Using profile parameter: -MaxUploadChanges 0
13116,
INFO: Using profile parameter: -MetadataRetentionCleanup 1
13057,
INFO: Using profile parameter: -NumDeadlockRetries 5
12940,
INFO: Using profile parameter: -PollingInterval 60 [modified]
12790,
INFO: Using profile parameter: -QueryTimeout 300
13073,
INFO: Using profile parameter: -SrcThreads 2
12965,
INFO: Using profile parameter: -StartQueueTimeout 0
12852,
INFO: Using profile parameter: -UploadGenerationsPerBatch 50
12878,
INFO: Using profile parameter: -UploadReadChangesPerBatch 100
12904,
INFO: Using profile parameter: -UploadWriteChangesPerBatch 100
12929,
INFO: Using profile parameter: -Validate 0
12979,
INFO: Using profile parameter: -ValidateInterval 3600000 [modified]
4947,
INFO: Reconciler CoreReconcile.
4971,
INFO: DB codepage [Upload], SubscriberCodePage = 1252, PublisherCodePage = 1252
Undefined
3020,
S3
INFO: EnumeratingSchemaChanges SubscriberSchemaVersion 55
4534,
:T:,10,86,0,17,17,17,17,,,
4541,
INFO: Read Watermarks:[Upload], SubRec:17, SubSent:17, PubRec:17, PubSent:17
5587,
:T:,20,86,Trading,FASTNFURIOUSSQL,FASTNFURIOUS,FASTNFURIOUSSQL
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,86,0,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
7499,
INFO: MakeGenString: [Upload], GenList = []
2750,
INFO: Update Watermarks:[Upload], SubSent:17
2756,
:T:,80,86,0,sub,17,,,,,
2413,
INFO: Update Watermarks:[Upload], PubRec:17
2419,
:T:,70,86,0,pub,17,,,,,
2907,
DBG: GetReplicaState from Database a12ae6cb-9440-4201-ab44-0970a5b10f23
INFO: EnumerateGenerationRange: [Download], startgen = 17, mingen = 0
DBG: [Download], Command: {call sp_MScheckexistsgeneration (?, ?) }
INFO: MakeGenString: [Download], SrcGen = 17, Skipping (Generation exists)
:T:,100,86,1,17,7e77cb75-f56e-466a-a4ae-10e2d6d139b9,,,,,
INFO: MakeGenString: [Download], GenList = []
INFO: Update Watermarks:[Download], PubSent:17
:T:,80,86,1,pub,17,,,,,
INFO: Update Watermarks:[Download], SubRec:17
:T:,70,86,1,sub,17,,,,,
2929,
DBG: UpdateReplicaState to Database 28ca1a5f-c15b-4acf-90bb-19665fcf98b5
3729,
:T:,110,86,0,,,,,,,
3736,
INFO: ID = 86, Session Highlights:
639,
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
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.
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