Event Lifecycle Logging
Overview
Event lifecycle logging, also called trace logging, is used for creating highly detailed log files for describing the flow of events.
The generated log files are stored by default in the following locations:
On the server: in the server's
data directory, in a folder called
traceLoggingOn the client : in the current directory where the client application was started from, in a folder called
clientTraceLoggingEach store (i.e. channel or queue) for which the trace logger is enabled will have its own folder under the trace logger folder, with the same name as the store. In the store's folder, a file trace.log will be created, containing information for only the events that are relevant to this particular store.
If you wish to change the default folder for trace logging, set the value of the system property com.softwareag.um.server.log.TraceLoggerPath (on the server) or com.softwareag.um.client.log.TraceLoggerPath (on the client) as required. The value of the property is read only once during server/client initialization.
Log messages are not directly flushed into the trace log files for performance optimization. There is a buffer of 32KB and a scheduled task responsible for flushing the messages. The interval for flushing the messages can be configured via the system property com.softwareag.um.log.TraceFlushInterval. The default value is 15 seconds. This means that the trace log messages will be flushed to the trace log file when one of the following is true:
the buffer of 32KB is full
the trace flush interval has been reached
To enable the trace logger, some log4j dependencies must be added to the classpath of the Java application that will be traced. This is already done for the Universal Messaging server in the server's Server_Common.conf file. The log4j dependencies are:
log4j-api.jar log4j-core.jar Performance Impact
Due to the nature of the feature, a drop in the performance of the server is expected when trace logging is enabled. The reason behind this is that some frequently used paths of the event flow are accessed and enriched with log messages. Below you can find the expected drop in the message throughput in different cases:
If event lifecycle logging is disabled - no impact on performance.
If event lifecycle logging is enabled with INFO log level:
Channels - up to 60% degradation
Channels with durables - up to 50% degradation
Queues - up to 50% degradation
If event lifecycle logging is enabled with TRACE log level:
Channels - up to 70% degradation
Channels with durables - up to 60% degradation
Queues - up to 60% degradation
Configuration Properties on the Server
A configuration group called Trace Logging Config is available on the server.
For more information on this configuration group see the section
Realm Configuration in the Enterprise Manager documentation in the
Administration Guide.
The trace logger can be enabled by any of the following means:
Using the AdminAPI.
This can be done by the nConfigGroup object as in this example:
nRealmNode realmNode =
new nRealmNode(new nSessionAttributes("nsp://localhost:9000"));
// get trace logging config group
nConfigGroup logConfGrp = realmNode.getConfigGroup( "Trace Logging Config");
// configure log level to info
logConfGrp.find("TraceStoreLogLevel").setValue(
String.valueOf(StoreLogConfigLevel.INFO.ordinal()));
// configure the maximum size trace.log file can reach in MB
logConfGrp.find("TraceStoreLogSize").setValue(Integer.toString(10));
// configure the maximum size the trace folder can reach in MB
logConfGrp.find("TraceFolderLogSize").setValue(Integer.toString(1024));
// enable trace logger for all stores
logConfGrp.find("TraceStores").setValue("*");
// save configuration
realmNode.commitConfig(logConfGrp);
realmNode.close();
Using the Enterprise Manager. There are settings in the
Realm Configuration tab that you can set up as required.
Using Command Central. In the Command Central UI, the
Trace Logging configuration can be found in
General Properties after you click the
Configuration tab.
Client APIs and Client System Properties
Client APIs and system properties allow the configuration of event lifecycle logging on the client.
The client APIs are located in nConstants:
setTraceFolderLogSize(int) setTraceStoreLogSize(int) setTraceStoreLogLevel(StoreLogConfigLevel) setTraceStores(String) setTraceLoggerPath(String) Important:
When this API is used to change the trace logger folder while the event lifecycle logging feature is enabled and log messages are being written to the log files, all log files present in the previous trace logger path will be zipped and new trace log files will be created in the specified folder for the stores which are enabled for trace logging.
Alternatively, you can use the following system properties on the client. They have the same effect as the methods in the nConstants class:
com.softwareag.um.client.log.TraceFolderLogSize com.softwareag.um.client.log.TraceStoreLogSize com.softwareag.um.client.log.TraceStoreLogLevel com.softwareag.um.client.log.TraceStores com.softwareag.um.client.log.TraceLoggerPath All system properties are read only once at client initialization.
Generating a unique ID
The additional property com.softwareag.um.client.GenerateEventUID can be used for generating a unique ID when an event is created on the client side.
When this property is set to "true", a unique ID will be generated on the client side and will be put into the nConsumeEvent tag in order to allow easier tracing of the event on the client and the server. This ID will be generated only when ALL of the following three conditions are met:
The tag of the generated
nConsumeEvent is empty, and
The
uuid property is not generated in the
fEventDictionary of the
nConsumeEvent, and
The
messageID is not populated in the
nHeader of the
nConsumeEvent.
Example of a setup on the client
nConstants.setTraceStoreLogLevel(StoreLogConfigLevel.TRACE);
nConstants.setTraceStores("*");
nConstants.setTraceLoggerPath("./clientTraceLog");
try {
nConstants.setTraceStoreLogSize(10);
nConstants.setTraceFolderLogSize(1024);
} catch (nIllegalArgumentException e) {
e.printStackTrace();
}
Disabling Log4J Logging in an OSGi Environment
When Universal Messaging connects to applications in an OSGi environment, you can disable the Log4J2 logging using the following property:
Dcom.softwareag.um.log.TraceLoggerProviderClass=com.pcbsys.foundation.logger.storelogger.NoopLoggerProvider
Behavior of the Trace Log Files
A trace log is created per store when the log level of the trace logger is set to INFO or TRACE and there are stores enabled for tracing via the TraceStores configuration property. When the specified TraceStoreLogSize value is reached, the trace log file will be zipped and a new one will be created. When the size of the trace logging folder reaches the value set in the TraceFolderLogSize property, the oldest zip files will be deleted.
Important:
Important
The value of TraceFolderLogSize can sometimes be ignored. This will happen if the following equation is true :
(number of stores to be traced) * (TraceStoreLogSize value) > (TraceFolderLogSize value)
Let's look at the following example :
1. TraceStoreLogSize is set to 100MB and TraceFolderLogSize is set to 1024MB (1GB)
2. There are 15 stores on the server/client and trace logging is enabled for all of them
Then the value of TraceFolderLogSize will be ignored because 15 * 100 > 1024.
Basic Examples
Here are some basic examples of event lifecycle trace logs presenting the format and the information that can be found in them.
Example 1: A channel is created and one event is published to it
On the client:
[2020-03-13 16:45:42.801 CEST][INFO][Created channel successfully.
attr={type=Reliable, JMSEngine=false, TTL=0, capacity=0, ID=-1,
spindleSize=50000, isClusterWide=false}, conn=,
Conn={SSID:ec2200000000,Local:127.0.0.1:58153,URL:nsp://127.0.0.1:26000}]
[nSession][Time-limited test]
[2020-03-13 16:45:43.184 CEST][INFO][Sending publish request. nPublished={EID=0,
tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8}, conn=, Conn={SSID:ec2200000000,
Local:127.0.0.1:58153.URL:nsp://127.0.0.1:26000}][nChannelImpl][Time-limited test]
On the server:
[2020-03-13 16:45:42.737 CEST][INFO][Store created successfully.
attr={, type=Reliable, JMSEngine=false, TTL=0, capacity=0, ID=47045869343854696,
spindleSize=50000, isClustered=false}, connId=127.0.0.1:58153]
[nUserStoreCreationHandler][ReadPool:0]
[2020-03-13 16:45:43.188 CEST][TRACE][Publish request received.
nPublished={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8},
conn=127.0.0.1:58153][nUserPublishHandler][ReadPool:1]
[2020-03-13 16:45:43.220 CEST][TRACE][Sending event to fanout.
nPublished={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8},
conn=127.0.0.1:58153][nUserPublishHandler][ReadPool:1]
[2020-03-13 16:45:43.221 CEST][INFO][Processing in fanout.
nPublished={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8}]
[nChannelEngine][ReadPool:1]
[2020-03-13 16:45:43.221 CEST][TRACE][Storing event in channel.
nPublished={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8}]
[cChannelList][ReadPool:1]
[2020-03-13 16:45:43.223 CEST][INFO][Returning from fanout.
nPublished={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8}, count=0]
[nChannelEngine][ReadPool:1]
Example 2: A channel is obtained and an async subscriber which receives one event is added to it
On the client:
[2020-03-14 15:02:40.148 CEST][TRACE][Adding asynchronous subscriber.
isInfiniteWindow=false, windowSize=0, selector=null, maintainPriority=false,
eid=0, messagingValidator=No,
Conn={SSID:1d1200000000,Local:127.0.0.1:60408,URL:nsp://127.0.0.1:26000}]
[nChannelImpl][Time-limited test]
[2020-03-14 15:02:40.149 CEST][INFO][Successful addition of asynchronous subscriber.
requestId=54, Conn={SSID:1d1200000000,Local:127.0.0.1:60408,
URL:nsp://127.0.0.1:26000}][nChannelImpl][Time-limited test]
[2020-03-14 15:02:40.228 CEST][TRACE][Publishing response to client.
nConsumeEvent={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8, redelivery=0}]
[nClientChannelList][UM-Connection-Reader:3 Active]
[2020-03-14 15:02:40.228 CEST][TRACE][Received event on client.
nConsumeEvent={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8, redelivery=0}]
[nClientChannelList][UM-Connection-Reader:3 Active]
[2020-03-14 15:02:40.231 CEST][INFO][Received event for asynchronous subscriber.
nConsumeEvent={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8, redelivery=0}]
[nClientChannelList][UM-Event-Processing-Pool: 3:0]
On the server:
[2020-03-14 15:02:40.148 CEST][INFO][Adding asynchronous subscriber.
EID=0, selector=, requestId=54, connId=127.0.0.1:60408, sessionId=1d1200000000]
[nUserSubscribeHandler][ReadPool:2]
[2020-03-14 15:02:40.194 CEST][INFO][Channel recovery attempting to write event to client.
connId=127.0.0.1:60408, event={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8}]
[nChannelRecoveryTask][Recovery Pool:1]
[2020-03-14 15:02:40.195 CEST][TRACE][Event written to subscriber.
nPublished={EID=0, tag=dedef12f-967a-44c5-bfd2-95d4ffaf3cf8 }]
[nChannelRecoveryTask][Recovery Pool:1]