AppSuite:OX Logging

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, if it's logger belongs to a configured whitelist. The whitelist is configured in logback.xml:

<property scope="context" name="com.openexchange.logging.filter.loggerWhitelist" value="com.openexchange" />

The whitelists purpose is to avoid flooding your log files with unwanted tracing events from e.g. 3rd party libraries. The "value"-attribute can be adjusted. It may contain a comma-separated list of loggers. It's hierarchical. That means 'com.openexchange' also allows all child-loggers.

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. The whitelist is configured as shown above.

<configuration>
...
  <property scope="context" name="com.openexchange.logging.filter.loggerWhitelist" value="com.openexchange" />
...
  <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 whitelist and 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.

Remote logging to logstash

This information is valid from 7.6.2 on.

In 7.6.2 we introduced a new feature that allows the OX server to log directly to a logstash[2] server.

To enable that feature you will need (besides the logstash server) to add/enable the OX logstash appender in the logback.xml file:

<property scope="context" name="com.openexchange.logback.extensions.logstash.enabled" value="true" />
<property scope="context" name="com.openexchange.logback.extensions.logstash.alwaysPersistEvents" value="true" />
<property scope="context" name="com.openexchange.logback.extensions.logstash.loadFactor" value="0.67" />
<appender name="LOGSTASH" class="com.openexchange.logback.extensions.logstash.LogstashSocketAppender">
  <remoteHost>localhost</remoteHost>
  <port>31337</port>
  <reconnectionDelay>10000</reconnectionDelay>
  <eventDelayLimit>30000</eventDelayLimit>
  <encoder class="com.openexchange.logback.extensions.logstash.LogstashEncoder"/>
  <queueSize>2048</queueSize>
</appender>

The three properties defined at the beginning of the XML snippet have the following use:

• com.openexchange.logback.extensions.logstash.enabled - This flag is used to enable the JMX metrics for the event queue size in the appender
• com.openexchange.logback.extensions.logstash.alwaysPersistEvents - If set to true, then log events that are in queue and can not be send to the logstash server (for what ever reason) are persisted to open-xchange-console.log as JSON formated logstash events.
• com.openexchange.logback.extensions.logstash.loadFactor - The load factor of the queue before flushing it.

The logstash appender has to then be referenced to the root logger:

<root level="INFO">
  <appender-ref ref="LOGSTASH" />
</root>

Of course the logstash server should also be appropriately configured. You can add the following lines in your input configuration:

# For LogX
tcp {
  port => 31337
  type => "LogX"
  codec => line {
    charset => "UTF-8"
    format => "string" 
  }
}

And the following filter to your filter configuration (note that you will have to adjust your timezone). The ruby code block is only needed for Elasticsearch version 2.0 or newer.

if [type] == "LogX" {
   json {
     source => "message"
   }
   date {
       match => ["timestamp", "ISO8601"]
       timezone => "Europe/Berlin"
       remove_field => ["timestamp"]
   }
   ruby {
     code => "event.to_hash.keys.each { |k| event[ k.gsub('.','_') ] = event.remove(k) if k.include?'.' }"
   }
}

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. It is also possible to create a filter for a user or a context or a session and set the level of the desired loggers independently.

Syntax

logconf -d] [-c <contextid> [-u <userid>] | -s <sessionid>] [-l <logger_name>=<logger_level> ...] -A <masterAdmin> -P <masterAdminPassword> [-p <RMI-Port>] [-s <RMI-Server | [-oec <category_1>,...] | [-cf] | [-lf] | [-ll [<logger_1> ...] | [dynamic]] | [-le] | [-h]

logconf -oec <category_1>,...

logconf [-cf] | [-lf] | [-ll [<logger_1> ...] | [dynamic]] | [-le] | [-h]

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
-cf,--clear-filters	Clear all logging filters
-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 <logger_1>=<loglevel_x> ... <logger_n>=<loglevel_y>	Define the log level for the specified loggers
-le, --list-exception-category	Get a list with all supressed exception categories
-lf, --list-filters	Get a list with all logging filters of the system
-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, comma separated

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}

Logging Filters vs. Loggers vs. Exception Categories

As already mentioned in the beginning, with this command line tool you can do multiple things, therefore there are different "categories" of data objects so to speak, i.e. Logging Filters, Loggers and Exception Categories. Hence, specific flags of the tool are explicitly used for only one of these data object categories and nowhere else (with the exception of the -l flag):

1. Manage logging filters for
   • Sessions
   • Contexts
   • Context/User tuples

   For the above three cases the -a, -d and -lf flags are relevant

2. Change the log level of already existing loggers of the system

   For this case the -l and -ll flags are relevant

3. Suppress the stack-traces for defined exception categories

   For this case only the -oec flag is relevant

Exception Categories vs. Log Levels

The OX server defines different categories to the OX exceptions that are thrown during the operation. Those categories should not be confused with the logging levels {OFF, ERROR, WARN, INFO, DEBUG, TRACE, ALL} of the logback framework which are described here.

The following list briefly describes each OX exception category.

• CAPACITY: The category for a 3rd party system when reporting capacity restrictions, e.g. quota
• CONFIGURATION: The category for a configuration issue (e.g. missing required property)
• CONFLICT: The category for conflicting data
• CONNECTIVITY: The category for a connectivity issue, e.g. broken/lost TCP connection
• ERROR: The category for an error
• PERMISSION_DENIED: The category for a permission-denied issue
• SERVICE_DOWN: The category for a missing service or system, e.g. database
• TRUNCATED: The category for truncated data
• TRY_AGAIN: The category for a try-again issue
• USER_INPUT: The category for an invalid user input
• WARNING: The category for a warning displayed to the user

Examples of a few category log entries

Stack-traces are omitted for clarity's sake.

USER_INPUT

2015-09-01T15:35:33,582+0200 ERROR [OXWorker-0000006] com.openexchange.exception.OXException: MSG-1013 Categories=USER_INPUT Message='Message could not be sent to the following recipients: [invalid@non-existing.tld] (550 - 550 5.1.1 <invalid@non-existing.tld>: Recipient address rejected: User unknown in virtual mailbox table)' exceptionID=-1316379722-11

TRY_AGAIN

2015-09-01T15:58:59,009+0200 ERROR [RMI TCP Connection(4)-127.0.0.1] com.openexchange.consistency.Consistency.erroroutput(Consistency.java:551)
com.openexchange.exception.OXException: SRV-0001 Categories=TRY_AGAIN Message='The required service com.openexchange.database.DatabaseService is temporary not available. Please try again later.' exceptionID=251360648-2

SERVICE_DOWN

2015-09-01T16:06:40,017+0200 ERROR [Thread-12] com.openexchange.database.migration.internal.DBMigrationExecutor.run(DBMigrationExecutor.java:152)
com.openexchange.exception.OXException: DBP-0001 Categories=SERVICE_DOWN Message='Cannot get connection to config DB.' exceptionID=-1771518749-4

2015-09-01T16:07:07,803+0200 WARN [OXTimer-0000007] com.openexchange.push.impl.balancing.reschedulerpolicy.PermanentListenerRescheduler.reschedule(PermanentListenerRescheduler.java:332)
Failed to distribute permanent listeners among cluster nodes
com.openexchange.exception.OXException: DBP-0001 Categories=SERVICE_DOWN Message='Cannot get connection to config DB.' exceptionID=-1771518749-6

Command output

INFO/ERROR/WARNING: [msg1, msg2, ... msgn]

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

Examples

Create a user/context filter for user 1618, context 314 and loggers c.o.mail and c.o.appsuite with levels TRACE and DEBUG respectively

# logconf -u 1618 -c 314 -a -l com.openexchange.appsuite=DEBUG com.openexchange.mail=TRACE

INFO: [Created new filter for user with ID "1618", in context with ID "314" and policy "ACCEPT", Added logger "com.openexchange.mail" with level "TRACE", Added logger "com.openexchange.appsuite" with level "DEBUG"]

Remove a logger from a user/context filter with user 1618 and context 314

# logconf -u 1618 -c 314 -d -l com.openexchange.appsuite

INFO: [Removed logger "com.openexchange.appsuite" from user filter for user with ID "1618", context with ID "314" and policy "ACCEPT"]

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

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

INFO: [Setting log level for "com.openexchange.appsuite" to "DEBUG", Setting log level for "com.openexchange.usm" to "DEBUG"]

Suppress category CONFIGURATION and CONNECTIVITY

# logconf -oec CONFIGURATION CONNECTIVITY

INFO: [Setting suppressed Exception Categories to CONFIGURATION,CONNECTIVITY]

MDC properties explanation

__threadId=1618

The thread identifier

com.openexchange.ajax.action=autologin

The AJAX action

com.openexchange.ajax.module=login

The AJAX module for the AJAX action

com.openexchange.grizzly.queryString=action=autologin&client=open-xchange-appsuite&rampup=true&rampupFor=open-xchange-appsuite&version=7.6.2-22

The complete query string that is contained in the request URL after the path

com.openexchange.grizzly.method"

The HTTP method

com.openexchange.grizzly.remoteAddress=1.2.3.4

The client's IP address (depends on the configuration described here)

com.openexchange.grizzly.remotePort=65127

The client's port

com.openexchange.grizzly.requestURI=/ajax/login

The request URI without any parameters

com.openexchange.grizzly.serverName=10.0.0.1

The host name of the server to which the request was sent. It is the value of the part before ":" in the 'Host' header value, if any, or the resolved server name, or the server IP address (depends on the configuration described here)

com.openexchange.grizzly.servletPath=/ajax/login

The part of this request's URL that calls the servlet. This path starts with a "/" character and includes either the servlet name or a path to the servlet, but does not include any extra path information or a query string.

com.openexchange.grizzly.session=35387551837281237793.koxg4l7scaj0qgxpmh1d

The sticky session identifier from Apache to the OX backend

com.openexchange.grizzly.threadName=OXWorker-0001337

The middleware's thread name

com.openexchange.grizzly.userAgent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:40.0) Gecko/20100101 Firefox/40.0

The content of the 'User-Agent' header.

com.openexchange.request.trackingId=983767a5c98646a988247b0ef83d6bb3

The tracking identifier of the request

com.openexchange.session.authId=342dfecaf0f5425f9b70b13115835e9a

The authentication identifier of the session

com.openexchange.session.clientId=open-xchange-appsuite

The client identifier

com.openexchange.session.contextId=27

The context identifier

com.openexchange.session.loginName=oxdude

The login name

com.openexchange.session.sessionId=faf5223338ea4371aacbbb9745a934a1

The session identifier

com.openexchange.session.userId=2

The user identifier

com.openexchange.session.userName=oxdude

The user name

com.openexchange.database.schema=oxdatabase_7

The database schema

com.openexchange.mail.accountId

The mail account identifier used in the request

com.openexchange.mail.host

The mail host used in the requst

com.openexchange.mail.login

The login identifier used to login to the mail server

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.