AppSuite:OX 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
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):
if [type] == "LogX" {
json {
source => "message"
}
date {
match => ["timestamp", "ISO8601"]
timezone => "Europe/Berlin"
remove_field => ["timestamp"]
}
}
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 [-a | -d] [-c <contextid> [-u <userid>] | -s <sessionid>] [-l <logger_name_1>=<logger_level_x> ...] [-U <JMX-User> -P <JMX-Password> [-p <JMX-Port>]]
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}
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. quotaCONFIGURATION: The category for a configuration issue (e.g. missing required property)CONFLICT: The category for conflicting dataCONNECTIVITY: The category for a connectivity issue, e.g. broken/lost TCP connectionERROR: The category for an errorPERMISSION_DENIED: The category for a permission-denied issueSERVICE_DOWN: The category for a missing service or system, e.g. databaseTRUNCATED: The category for truncated dataTRY_AGAIN: The category for a try-again issueUSER_INPUT: The category for an invalid user inputWARNING: 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:39,489+0200� WARN [Start Level: Equinox Container: c0c886a6-b250-0015-13ab-e76fa445f503]� com.openexchange.database.internal.ReplicationMonitor.checkFallback(ReplicationMonitor.java:126) com.openexchange.exception.OXException: DBP-0001 Categories=SERVICE_DOWN Message='Cannot get connection to config DB.' exceptionID=-1771518749-1
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]
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.