JSLEE Logging
Logging
Logging in the JSLEE is controlled by logback, a comprehensive Java logging framework built on the SLF4J logging framework. The logback and SLF4J logging ecosystem is comprehensive, and it is possible to put together a suitable production or test configuration based on the below.
Due to the range of configuration options related to logback, please refer to the logback site for detailed documentation.
Configuring Logging
Logging is configured through a logback.xml
configuration, the path to which can be provided on the command line
when running the JSLEE by using the -Dlogback.configurationFile
command line option. For example, the default
system control file executes the JSLEE in this manner:
java --add-modules java.se --add-exports java.base/jdk.internal.ref=ALL-UNNAMED \
--add-opens java.base/java.lang=ALL-UNNAMED --add-opens java.base/java.nio=ALL-UNNAMED \
--add-opens java.base/sun.nio.ch=ALL-UNNAMED --add-opens java.management/sun.management=ALL-UNNAMED \
--add-opens jdk.management/com.sun.management.internal=ALL-UNNAMED \
-XX:+HeapDumpOnOutOfMemoryError -XX:NativeMemoryTracking=detail \
-Dvertx.cacheDirBase=/opt/nsquared/jslee/bin \
-Dlogback.configurationFile=/opt/nsquared/jslee/etc/server/logback.xml \
-classpath <full classpath of all libs> \
nz.co.nsquared.slee.core.JSLEEServer /opt/nsquared/jslee/etc/server/server.json
The logback configuration file is defined as /opt/nsquared/jslee/etc/server/logback.xml
.
The Default Configuration
A default logback configuration is included within the JSLEE jar as a resource. This can be overridden with
an explicit -Dlogback.configurationFile
option given to Java on execution. The debug highlights the defaults:
21:32:13,578 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
21:32:13,584 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
21:32:13,642 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/jlove/Documents/dev/product/n2jslee/build/resources/main/logback.xml]
21:32:13,843 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
The default configuration file is kept simple, with only console output at the INFO
level:
<configuration>
<appender class="ch.qos.logback.core.ConsoleAppender" name="CONSOLE">
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>INFO</level>
</filter>
<encoder>
<pattern>%date %-5level [%-26thread] [%-35file:%-4line] [%-20X{n2ServiceName}] %msg%n</pattern>
</encoder>
</appender>
<!-- Appenders filter out undesirable levels individually, so this level should be set to TRACE. -->
<root level="TRACE">
<appender-ref ref="CONSOLE"/>
</root>
<!-- TRACE logging separates to another file, and by default we want to suppress this, so use the WARN level -->
<logger level="WARN" name="TRACE" additivity="false"/>
<!--
Some of our libraries generate some debug which we really don't need
so we remove debug/info output from these
-->
<logger level="ERROR" name="io.netty"/>
<logger level="INFO" name="org.mongodb.driver"/>
<!-- if we don't do this, we get a whole bunch of FileUtil access debug lines, which is just useless -->
<logger level="INFO" name="oshi"/>
<logger level="INFO" name="com.hazelcast"/>
</configuration>
Production Configuration
A full production example configuration file is included in all distributions. It can be found at:
/opt/nsquared/jslee/etc/server/logback-example.xml
Note that this example configuration must be customised as all appenders are included:
<root level="TRACE">
<appender-ref ref="FILE_APPLICATION"/>
<appender-ref ref="FILE_TRACE"/>
<appender-ref ref="CONSOLE"/>
<appender-ref ref="SYSLOG"/>
<appender-ref ref="SIFT_FILE_APPLICATION"/>
</root>
Select and customise the appender(s) relevant for your deployment, and remove or comment out the others. It is
recommended that SIFT_FILE_APPLICATION
and FILE_TRACE
are kept, at a minimum.
Automated Configuration Reload
To ensure that logging configuration can be reloaded in running JSLEE processes, always configure your logback
configuration file to auto-scan regularly. This can be enabled by using the scan
option on the root element:
<configuration scan="true" scanPeriod="30 seconds">
...
</configuration>
JSLEE Customizations
Custom “MDC” Variables
The JSLEE is defined by its services, and will often be deployed in multi-node setups. Three custom variables are included to help manage log output, the most useful of which are the per-service/per-service type variables:
- The custom variable
n2NodeName
defines the node name as given by the configuration variableserver-name
in theserver.json
variable. This variable generally determines the server name the JSLEE is run on. - The custom variable
n2ServiceName
is the name of the service as configured in the server’sserver.json
file, and must be unique per service configured. - The custom variable
n2SystemName
defines the type of service running. This is a predetermined fixed string, unique to each type of service (e.g. the Redis service uses the stringRedis
).
Custom MDC variables such as n2ServiceName
can be included in output lines using the %X
formatting function:
<pattern>%date %-5level [%-26thread] [%-35file:%-4line] [%-20X{n2ServiceName}] %msg%n</pattern>
allowing their value to be included in log lines. In addition, the logback sifting appender can be used to separate log lines by MDC variable, e.g. to separate files (as is done in the example production configuration):
<appender class="ch.qos.logback.classic.sift.SiftingAppender" name="SIFT_FILE_APPLICATION">
<discriminator>
<key>n2ServiceName</key>
<defaultValue>jslee</defaultValue>
</discriminator>
<sift>
<appender name="SIFTFA-${n2ServiceName}" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- rolling file append config -->
</appender>
</sift>
</appender>
Per-Service Configuration Logging
Using the MDC configuration shown above, per-service configuration files will be created by a running service.
To enable per-service log levels, use a turboFilter
. This example shows all services of the type Redis
will
log to the DEBUG
log level (with the default log level set to INFO
):
<turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
<Key>systemName</Key>
<DefaultThreshold>INFO</DefaultThreshold>
<MDCValueLevelPair>
<value>Redis</value>
<level>DEBUG</level>
</MDCValueLevelPair>
</turboFilter>
By combining both SiftingAppender
configuration and turboFilter
configuration, a high degree of control can be
gained over log output in the JSLEE.
End-to-End Message Tracing
The end-to-end message tracing solution in the JSLEE supports the tracing of messages received/sent across the JSLEE:
- Over external connections, e.g. over HTTP, Diameter, SMPP or Redis
- Via the internal JSLEE event bus.
Using end-to-end message tracing provides a complete view on the manner in which messages transit the JSLEE.
Note that as end-to-end message tracing is performed using Logback and the JSLEE Logging framework, enabling this does impact performance of the JSLEE slightly. The end-to-end message tracing framework is not designed as a replacement for EDRs within the JSLEE, but as a complement to them.
End-to-end message tracing utilises a separate logging hierarchy to the standard logging hierarchy based on Java classes. All end-to-end message tracing is built within the name hierarchy:
TRACE.<system name of service>.<service name, from server.json>[.<endpoint name of endpoint>]
By default, message tracing is disabled, except for the printing of warning messages. This is done using the following logback configuration:
<logger level="WARN" name="TRACE" additivity="false"/>
The name
field in the logger
configuration identifies the first section (TRACE
) the logger applies to, and
the minimum threshold for log messages to be printed. By using TRACE
as the first part to the hierarchy, and
separating the end-to-end message logging from the standard Java class based hierarchy, significant separation
between normal logging and message logging is achieved.
Additionally, end-to-end logging uses Logback Markers for additional filtering. Each end-to-end tracing log line includes the message’s class name as a marker. This enables filtering based on message type. An important use case of this is to suppress management events by default.
The production example file enables message tracing with the following snippets of XML from logback-example.xml
:
<configuration>
<!-- snip -->
<turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
<Marker>JsleeManagementEvent</Marker>
<onMatch>DENY</onMatch>
</turboFilter>
<!-- snip -->
<appender class="ch.qos.logback.core.rolling.RollingFileAppender" name="MESSAGE_TRACE_FILE">
<!-- snip -->
</appender>
<!-- snip -->
<logger name="TRACE" additivity="false">
<appender-ref ref="MESSAGE_TRACE_FILE" />
</logger>
<!-- snip -->
</configuration>
The turboFilter
by default disables messages derived from the JsleeManagementEvent
class. Management events would
otherwise generate significant noise in a log under normal circumstances.
Unlike the default configuration, the TRACE
logger defines no minimum log level. This enables, by default, log
messages for all events sent over the JSLEE, both internally and to/from external sources.
To disable internal event logging, add level='INFO'
to the TRACE
logger. Per service (or even endpoint) configuration
can further control end-to-end message logging.