AppSuite:OX Logging

Revision as of 10:19, 19 December 2013 by Ioannis.chouklis (talk | contribs) (Parameters)
This information is valid from 7.4.2 on.
Server-side Logging


With OX App Suite 7.4.2 the groupware server introduces LOGBack as logging implementation. Formerly log4j 1.2 or java.util.logging have been used for logging. As of now the package 'open-xchange-log4j' has become obsolete and LOGBack is entirely contained in 'open-xchange-core'. No additional packages are needed even for syslog-based logging or sophisticated logging configurations anymore. Log4j and java.util.logging have been completely replaced by LOGBack.

For Operators

Configuration

LOGBacks configuration is defined in /opt/open-xchange/etc/logback.xml. We ship the file pre-configured for new installations and set some useful defaults. Without any changes, the groupware writes log files to /var/log/open-xchange. See chapter #Backward Compatibility for detailed information on product upgrades from older versions. See LOGBack manual for details on configuring LOGBack.

Backward Compatibility

Configuration Migration

In most cases no further work should be necessary after upgrading to OX App Suite 7.4.2. Based on your existing logging configuration (/opt/open-xchange/etc/file-logging.properties or /opt/open-xchange/etc/log4j.xml) we automatically migrate custom configured logger levels via package post installation scripts to the new logback configuration.

We also configure file-based logging or syslog-based logging in accordance with the default configuration of the formerly used logging implementation. That means depending whether open-xchange-log4j was installed or not, the package post installation scripts modify the default logback configuration to send logs to a remote syslog daemon. You don't have to change anything if

  • you use plain file logging and did not modify the 'handler'-section in file-logging.properties.
  • you use syslog-based logging via log4j and did not change the configured 'SERVER_LOG' appender.

Please note: If you customized handlers or appenders you have to port your changes manually to /opt/open-xchange/etc/logback.xml. See LOGBack manual for details.

Log File Format

We keep the former default layout for log events on product upgrades. So nothing should break if you wrote your own log file parser.

Please note: We also ship a pre-configured new log file layout. You are strongly encouraged to use this one for file-based logging, as it provides more information and is better structured than the old one. To enable it, change the appender reference of appender ASYNC to FILE instead of FILE_COMPAT in /opt/open-xchange/etc/logback.xml.

Before:

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  ...
  <appender-ref ref="FILE_COMPAT" />
</appender>

After:

<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  ...
  <appender-ref ref="FILE" />
</appender>

New Features

Config-based Asynchronous Logging

Publishing log events to files, syslogd or the like is performed asynchronously. Therefore the root loggers appender is set to 'ASYNC', which is configured as follows:

<configuration>
...
  <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <queueSize>2048</queueSize>
    <discardingThreshold>0</discardingThreshold>
    <includeCallerData>true</includeCallerData>
    <appender-ref ref="FILE" />
  </appender>
...
</configuration>

The most important property is "appender-ref". It denotes the name of the appender, that finally writes log events out in some way. A detailed description of the other parameters can be found here: [1].

If you introduce your own log appender, only change the above mentioned 'appender-ref' property. Don't remove or deactivate the configuration for asynchronous logging! It might decrease the applications performance significantly.

Suppression Of Stacktraces

It is possible to suppress Java stacktraces in log messages for configured categories. Those categories are part of OX App Suites internal error and exception handling. Suppression can be configured in server.properties by adjusting the value for 'com.openexchange.log.suppressedCategories'. See below excerpt of /opt/open-xchange/etc/server.properties:

...
# Specify the OXException categories (comma separated) to be suppressed when logging.
# The Exception itself will still be logged as configured, but the StackTraces are omitted.
# Valid categories are ERROR, TRY_AGAIN, USER_INPUT, PERMISSION_DENIED, CONFIGURATION, CONNECTIVITY, SERVICE_DOWN, TRUNCATED, CONFLICT, CAPACITY, WARNING
# Default is USER_INPUT.
com.openexchange.log.suppressedCategories=USER_INPUT
...

Tracing Of Sessions, Users and Contexts

It is possible to enable extended logging for defined scopes like sessions, users or contexts at a whole. This means that every log event which belongs to a configured scope will be logged despite of it's level.

Example: Imagine logback is configured to log on level 'INFO' and additionally the logger 'com.openexchange.example.SomeLogger' is only allowed to log warnings and errors.

<configuration>
...
  <root level="INFO">
    <appender-ref ref="ASYNC" />
  </root>
  <logger name="com.openexchange.example.SomeLogger" level="WARN"/>
...
</configuration>

If tracing is activated for user '5' in context '1', events belonging to this user are written out, even if they deceed the configured thresholds. I.e. you can find log entries with level 'DEBUG' from logger 'com.openexchange.example.SomeLogger' that belong to the traced user.

2013-12-09 15:29:31,641 DEBUG [OXWorker-0000001] com.openexchange.example.SomeLogger
Some very useful debug message.
 com.openexchange.session.sessionId=711c651fa4c94dc0894c733c92bc77d4
 com.openexchange.session.contextId=1
 com.openexchange.session.userId=5
 com.openexchange.session.userName=oxuser
 ...

The decision whether to log such an event is based on the context information that every log event carries along. These information is structured as key-value-pairs and always printed below the log events message. Afterwards it's easy to find the tracing events in the log file. You just have to search for 'com.openexchange.session.contextId=1' and 'com.openexchange.session.userId=5'. If you trace a specific session, according events can be found with looking for 'com.openexchange.session.sessionId=session_id_to_trace'.

New Log Event Layout

We ship a new default layout for log events that

  • contains a more precise timestamp
  • carries the name of the current thread
  • is easier to parse

Example:

2013-12-11 12:41:35,660 INFO  [LoginPerformer-0000003] com.openexchange.caching.internal.JCSCache
Cache 'UserPermissionBits' is operating in distributed mode
 com.openexchange.ajax.action=login
 com.openexchange.ajax.requestNumber=5
 ...

Please note: The new layout applys only for fresh installations. On upgrades you have to enable it manually. See #Log File Format for details.

logconf CLT

The above mentioned features can be managed via the logconf command line tool (/opt/open-xchange/sbin/logconf). It creates log filters for sessions, context and (user/context) tuples, suppresses stacktraces for defined exception categories and dynamically changes log levels of specified loggers.

Parameters

-h,--help Prints usage of the command line tool
-a,--add Flag to add the filter)
-d,--delete Flag to delete the filter
-c,--context <contextid> The context id for which to create the log filter
-s,--session <sessionid> The session id for which to create the log filter
-u,--user <userid> The user id for which to create the log filter
-s,--session <sessionid> The session id for which to create the log filter
-l,--level <loglevel> <logger name 1> ... <logger name n> Define the log level for the specified loggers
-le, --list-exception-category Get a list with all supressed exception categories
-is, --include-stacktraces Signals to set whether to include stack trace information in HTTP-API JSON responses
-ll, --list-loggers Get a list with all loggers of the system.

Can optionally have a list with loggers as arguments, i.e. -ll <logger1> <logger2> OR the keyword 'dynamic' that instructs the command line tool to fetch all dynamically modified loggers. Any other keyword is then ignored, and a full list will be retrieved.

-oec, --override-exception-categories <category name> Override the exception categories to be suppressed

Follow switches are valid if JMX authentication is enabled

-U, --JMX-User <username> JMX username
-P, --JMX-Password <password> JMX password
-p, --JMX-Port <port> JMX port

The flags -a and -d are mutually exclusive. Valid log levels: {OFF, ERROR, WARN, INFO, DEBUG, TRACE, ALL} Valid categories: {ERROR, USER_INPUT, CONFIGURATION, PERMISSION_DENIED, TRY_AGAIN, CONNECTIVITY, SERVICE_DOWN, TRUNCATED, CONFLICT, CAPACITY, WARNING}

Command output

Operation [operation name] with parameters: {...} succeeded.

Examples

Create a user/context filter for user 1618 and context 314

# logconf -u 1618 -c 314 -a

Operation filterUser with parameters: {1618, 314} succeeded.

Change the log level for the com.openexchange.appsuite logger

# logconf -l DEBUG com.openexchange.appsuite com.openexchange.usm

Operation setLogLevel with parameters: {DEBUG, com.openexchange.appsuite, com.openexchange.usm} succeeded.

Suppress category CONFIGURATION and CONNECTIVITY

# logconf -oec CONFIGURATION CONNECTIVITY

Operation overrideExceptionCategories with parameters: {CONFIGURATION, CONNECTIVITY} succeeded.

For Developers

Instantiate Loggers

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Clazz {

    private static final Logger LOG = LoggerFactory.getLogger(Clazz.class);

    ...

}

Using Apache Commons Logging as logging facade is depracted as of OX App Suite 7.4.2. Formerly we used own wrapper classes to enable extended logging features. With the current logging implementation this is not necessary anymore. Obtaining loggers via

com.openexchange.log.Log.loggerFor(Clazz.class); or
com.openexchange.log.LogFactory.getLog(Clazz.class); or
com.openexchange.log.Log.valueOf(LogFactory.getLog(Clazz.class));

still works for backward compatibility, but should not be used for new classes. Existing classes should be ported to SLF4J, when touched during refactorings, bugfixes etc.

Of course it is also required to fix the corresponding bundles META-INF/MANIFEST.MF file.

Remove

com.openexchange.log
org.apache.commons.logging

Add

org.slf4j

Logging Statements

With SLF4J you should avoid code like this:

if (LOG.isDebugEnabled()) {
    LOG.debug("Some debug message for user " + userId + " in context " + contextId + ".");
}

Instead relinquish the if-statement completely and make use of SLF4Js printf()-like syntax for log statements:

LOG.debug("Some debug message for user {} in context {}.", userId, contextId);

Please read What is the fastest way of (not) logging? for details.