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, however 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 without 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:

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:

  1. Over external connections, e.g. over HTTP, Diameter, SMPP or Redis
  2. 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 compliment 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.