The Rhino SLEE uses the Apache Log4j 2 logging framework to provide logging facilities for SLEE components and deployed services.

Tip
The Logging Management MBean

Rhino SLEE allows changes to logging configuration at runtime. This is useful for capturing log information to diagnose a problem, without having to restart the SLEE. You configure logging using the Logging Management MBean, through the command console. This MBean lets you query the log configuration, and for most subsystems effect immediate changes (some require a node restart for performance reasons).

Rhino’s logging system includes logger names, log levels, log appenders, filters, and tracers.

Asynchronous Logging

The Log4j 2 logging architecture provides a new approach to asynchronous logging. It uses asynchronous loggers, which submit log events to a work queue for later handling by the appropriate appenders.

More details can be found in the Log4j 2 async loggers documentation

Rhino offers support for mixed synchronous and asynchronous logging through logger configuration commands. Correctly configuring asynchronous logging has some complexity, discussed in how to Configure a Logger.

Mapped Diagnostic Context

Rhino 2.6 introduces access to the Mapped Diagnostic Context (MDC) as a tool to tag and correlate log messages throughout an activity’s life cycle. This tagging can be combined with the new filters to allow very fine grained control of logging and tracing.

A simple SIP example of useful context would be including the P-charging-vector header. As this uniquely identifies a single call, it becomes trivial to identify all log messages related to handling an individual call. Identification (or filtering) remains simple even under load, with multiple calls handled in parallel.

The Logging Context Facility discusses MDC in greater detail.

Logger names

Subsystems within the Rhino SLEE send log messages to specific loggers. For example, the rhino.facility.alarm logger periodically receives messages about which alarms are currently active within the Rhino SLEE.

Examples of logger names include:

  • root — the root logger, from which all loggers are derived (can be used to change the log level for all loggers at once)

  • rhino — main Rhino logger

  • rhino.management — for log messages related to Rhino management systems

  • trace.<namespace>.<deployable_type>.<notification_source>.<tracer name> — loggers used by deployed SLEE components that use tracers. By default these keys appear abbreviated in console and file logs. Details of tracer abbreviation can be found at Tracer pattern converter.

Log levels

Log levels can be assigned to individual loggers to filter how much information the SLEE produces:

Log level Information sent
 OFF

No messages sent to logs (not recommended).

 FATAL

Error messages for unrecoverable errors only (not recommended).

 ERROR

Error messages (not recommended).

 WARN

Warning messages.

 INFO

Informational messages (especially during node startup or deployment of new resource adaptors or services). The default.

 DEBUG

Detailed log messages. Used for debugging by Metaswitch Rhino SLEE developers.

 TRACE

Finest level. Not currently used.

 ALL

All of the above.

Each log level will log all messages for that log level and above. For example, if a logger is set to the INFO level (the default), all of the log messages logged at the INFO, WARN, ERROR, and FATAL levels will be logged as well.

If a logger is not assigned a log level, it inherits its parent’s. For example, if the rhino.management logger has not been assigned a log level, it will have the same effective log level as the rhino logger.

The root logger is a special logger which is considered the parent of all other loggers. By default, the root logger is configured with the INFO log level. In this way, all other logger will output log messages at the INFO log level or above unless explicitly configured otherwise.

Warning
Use INFO

A lot of useful or crucial information is output at the INFO log level. Because of this, setting log levels to WARN, ERROR or FATAL is not recommended.

Log appenders

System administrators can use the console to create some simple log appenders. Full appender creation is available through the Rhino Element Manager (REM). These append log messages to destinations such as the console, a log file, socket, or Unix syslog daemon. At runtime, when Rhino logs a message (as permitted by the log level of the associated logger), Rhino sends the message to the log appender for writing. Types of log appenders include:

  • file appenders — which append messages to files (and may be rolling file appenders)

  • console appenders — which send messages to the Rhino console

  • socket appenders — Append to a network socket. Either raw, or syslog formatted.

  • custom appenders — which can do a wide variety of things. Common "custom" apenders are used to append to various kinds of database.

Rolling file appenders

Typically, to manage disk usage, administrators are interested in sending log messages to a set of rolling files. They do this by setting up rolling file appenders which:

  • create new log files if the current one gets too large

  • rename old log files as numbered backups

  • delete old logs when a certain number of them have been archived.

Log files roll over when they exceed the configured size i.e. size is checked after logging each message, if the log file is larger than the maximum the next message will be written to a new file. Since Rhino 2.6.0 only the SDK rolls over log files on node restart. Production nodes use a size-based policy only.

You can configure the size and number of rolled-over log files and the rollover behaviour. Options include size-based, time-based and on node-restart. All configurations described for Log4j 2 are valid: https://logging.apache.org/log4j/2.x/manual/appenders.html#RollingFileAppender

An example logging config containing a complex rollover strategy that increments file numbers, retaining up to 4 historical files younger than 30 days:

        <appender name="RhinoLog" plugin-name="RollingFile">
            <layout name="RhinoLogLayout" plugin-name="PatternLayout">
                <property name="pattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%logger] <%threadName> %mdc : %msg%n%throwable"/>
                <property name="header" value="${rhinoVersionHeader}"/>
            </layout>
            <property name="filePattern" value="${logDir}/rhino.log.%i"/>
            <property name="fileName" value="${logDir}/rhino.log"/>
            <component name="RhinoLogPolicy" plugin-name="SizeBasedTriggeringPolicy">
                <property name="size" value="100MB"/>
            </component>
            <component name="RhinoLogStrategy" plugin-name="NotifyingRolloverStrategy">
                <property name="min" value="1"/>
                <property name="max" value="2147483647"/>
                <component name="deleteAction" plugin-name="Delete">
                    <property name="basePath" value="${logDir}"/>
                    <property name="maxDepth" value="1"/>
                    <component name="fileName" plugin-name="IfFileName">
                        <property name="glob" value="rhino.log.*"/>
                    </component>
                    <component name="any" plugin-name="IfAny">
                        <component name="lastmodified" plugin-name="IfLastModified">
                            <property name="age" value="30d"/>
                        </component>
                        <component name="fileCount" plugin-name="IfAccumulatedFileCount">
                            <property name="exceeds" value="4"/>
                        </component>
                    </component>
                </component>
            </component>
        </appender>

Default appenders

By default, the Rhino SLEE comes configured with the following appenders active:

Appender Where it sends messages Logger name Type of appender
 RhinoLog

the Rhino logs directory (work/log/rhino.log)

 root

a rolling file appender

 STDERR

the Rhino console where a node is running (in a standard error stream)

 root

a console appender

 ConfigLog

work/log/config.log

 rhino.config

a rolling file appender

Warning
New appenders won’t receive messages until associated with at least one logger

By default, a newly created log appender is not associated with any loggers, so will not receive any log messages.

Appender additivity

If a logger has its additivity flag set to true, all of the output of its log statements goes to all of its appenders and ancestors. If a specific ancestor has its additivity flag set to false, then the output goes to all appenders and ancestors up to and including that specific ancestor — but not to appenders in any of that ancestor’s ancestors. (By default, logger additivity flags are set to true.}

Note See Apache’s Log4j 2 Architecture page for details on additivity.

Filters

Filters can be applied to both loggers and appenders to restrict the set of log messages that are reported by a logger or through an appender. They provide a more flexible limiting approach than log level alone. Configuring filters can be performed using the Rhino Element Manager or by modifying an export of the logging configuration. A list of the filters available by default and their configuration properties can be found in the Log4j 2 filter documentation

An example filter configuration setting for limiting log levels to Finer in namespace volte and Info in all other namespaces is shown below:

                <component plugin-name="DynamicThresholdFilter">
                    <property name="defaultThreshold" value="Finer"/>
                    <property name="key" value="namespace"/>
                    <component plugin-name="KeyValuePair">
                        <property name="key" value="volte"/>
                        <property name="value" value="Warning"/>
                    </component>
                </component>

If three trace messages are emitted by the service

tracer.warning("TransparentDataCache(MMTEL-Services) (RepositoryDataAccessKey{REPOSITORY_DATA, userId=tel:+34600000002, userIdType=IMPU, serviceIndication=MMTEL-Services}): [DoUDR] failed to send request")
tracer.finer("Cache gave immediate response. Latency: 1 ms")
tracer.finest("Removing service indication: MMTEL-Services from the session state list.Initial items: [MMTEL-Services]")

With the service deployed in namespace volte only the Warning will be logged:

2017-11-14 13:35:38.123+1300 Warning [trace.sh_cache_ra.sh-cache-ra] <jr-4> {ns=volte, txID=101:210487189646097} TransparentDataCache(MMTEL-Services) (RepositoryDataAccessKey{REPOSITORY_DATA, userId=tel:+34600000002, userIdType=IMPU, serviceIndication=MMTEL-Services}): [DoUDR] failed to send request

otherwise both the Finer and Warning messages will be logged:

2017-11-14 13:35:38.123+1300 Warning [trace.sh_cache_ra.sh-cache-ra] <jr-4> {ns=mmtel, txID=101:210487189646097} TransparentDataCache(MMTEL-Services) (RepositoryDataAccessKey{REPOSITORY_DATA, userId=tel:+34600000002, userIdType=IMPU, serviceIndication=MMTEL-Services}): [DoUDR] failed to send request
2017-11-14 13:35:38.137+1300 Finer   [trace.volte_sentinel_sip.2_7_0_copy_1.volte_sentinel_sip.sentinel.sbb] <jr-4> {ns=mmtel, txID=101:210487189646097} Cache gave immediate response. Latency: 1 ms

The default threshold of Finer will cause the Finest message to never be logged.

Logging plugins

Rhino contains several logging plugins to extend the functionality of Log4j 2 to aid SLEE management and provide additional context to logs.

  • NotifyingRolloverStrategy

  • NotifyingDirectWriteRolloverStrategy

  • LogNotificationAppender

  • PolledMemoryAppender

NotifyingRolloverStrategy

An extended variant of the DefaultRolloverStrategy providing an API for components to receive notification of log file rollover. The RolloverNotificationListener can be registered to receive a callback whenever a log file is rolled over. This strategy should be used instead of the Log4j 2 DefaultRolloverStrategy so Rhino can send notifications to monitoring systems.

NotifyingDirectWriteRolloverStrategy

An extended variant of the DirectWriteRolloverStrategy providing an API for components to receive notification of log file rollover. The RolloverNotificationListener can be registered to receive a callback whenever a log file is rolled over. This strategy should be used instead of the Log4j 2 DirectWriteRolloverStrategy so Rhino can send notifications to monitoring systems.

LogNotificationAppender

A log appender for delivering log messages to a listener inside the application. This is used to send log messages to JMX monitoring clients and as SNMP notifications. It is only necessary to use the LogNotificationAppender if using SNMP to receive log messages.

TraceNotificationAppender

A log appender for delivering log messages to a listener inside the application that extracts tracer messages to send as `TraceNotification`s. This is used to send tracer messages to JMX monitoring clients such as REM. It is necessary to use the TraceNotificationAppender if using JMX to receive tracer messages. Without an instance of this appender in the log configuration REM instances connecting to this Rhino instance will not be able to receive or display tracer messages.

PolledMemoryAppender

A log appender that stores messages in an internal buffer that the REM can poll for live log watching. This implementation is only of use when log output is infrequent enough for human monitoring and has a minor performance cost. It will be removed in a future release of Rhino. We recommend that log files or an external log server be used as the primary log output.

Note See Logging plugins for instructions on enabling additional appender types.

Other plugins

The Log4j 2 project (https://logging.apache.org/log4j/2.x) provides a number of plugins for extending the functionality of Log4j 2. These plugins provide appenders for sending logs to a number of log servers, files and databases, layouts for configuring the format of log messages, and filters to restrict the logging of messages. System integrators or operators can create plugins to add further functionality or support for other log handling systems.

Rhino log configuration properties

Rhino log configuration variables include a rhino namespace containing options useful for providing additional context in log files. These are:

  • ${rhino:node-id}: The node ID of the Rhino node that wrote the log message parameterised with this variable

  • ${rhino:version}: The version of Rhino running at the time the log message parameterised with this variable was written

Tracer objects

SLEE 1.1 provides tracer objects for logging messages from deployed components.

Rhino logs all messages sent to a Tracer under the trace.<notification source>.<tracer name> logger.

In an extension of the SLEE specification Rhino allows configuration of tracer levels at coarser grain than the component tracer. This extended functionality is accessed through the Rhino logging configuration. For example setloglevel trace Finest will set the default tracer level to Finest. All tracers not explicitly set will log at levels from Finest up. To support this SLEE extension root tracers for individual notification sources inherit their levels from the trace logger. It is also permitted to unset the root tracer level for a given notification source using setTracerLevel. Unsetting the root tracer level reverts to using the inherited level.

A further extension of the SLEE specification allows for full use of logging management commands against Tracers. A SLEE 1.1 Tracer may have appenders and filters added to further customise tracing output, both to JMX notifications, and logging destinations. Any supported appender may be used, so logging destinations are not restricted to file only.

Tracer log levels

Log levels for trace messages are logged at the level they are emitted.

Warning SLEE 1.0-based application components can still use the trace facility (defined in the JAIN SLEE 1.0 specification) for logging, however the trace facility has been deprecated for JAIN SLEE 1.1.
Previous page Next page
Rhino Version 3.2