OPENDJ-2494 Improve OpenDJ SLF4J implementation

Gaetan Boismal

01.56.2015 c3cd23d56ce13b5bf0c4c8614cafff1179e7da59

OPENDJ-2494 Improve OpenDJ SLF4J implementation

PR-195
This commit improves the OpenDJ SLF4J logger implementation as follow:
* Add a generic LocalizableMessage to log external library messages (e.g
common audit, grizzly, JE).

* If external libraries calls methods that we use in OpenDJ we do not
throw exception any more, we just log the message.

* As third party libraries could use our slf4j implementation, add fast
path checks to ensure that log level is enabled before doing anything.

* Log third party readme debug messages into the debug logger
(instead of the error logger with INFORMATION severity before).

 opendj-server-legacy/pom.xml

@@ -430,6 +430,7 @@
                <messageFile>org/opends/messages/core.properties</messageFile>
                <messageFile>org/opends/messages/dsconfig.properties</messageFile>
                <messageFile>org/opends/messages/extension.properties</messageFile>
                <messageFile>org/opends/messages/external.properties</messageFile>
                <messageFile>org/opends/messages/logger.properties</messageFile>
                <messageFile>org/opends/messages/plugin.properties</messageFile>
                <messageFile>org/opends/messages/protocol.properties</messageFile>
@@ -1633,6 +1634,7 @@
                    <!-- Ignore following message files as we document only serious errors. -->
                    <!-- <messageFileName>access_control</messageFileName> -->
                    <!-- <messageFileName>admin_tool</messageFileName> -->
                    <!-- <messageFileName>external</messageFileName> -->
                    <!-- <messageFileName>quicksetup.properties</messageFileName> -->
                    <!-- <messageFileName>runtime_information.properties</messageFileName> -->
                    <!-- <messageFileName>version.properties</messageFileName> -->

 opendj-server-legacy/src/main/java/org/opends/server/loggers/slf4j/OpenDJLoggerAdapter.java

@@ -25,6 +25,8 @@
 */
package org.opends.server.loggers.slf4j;

import static org.opends.messages.ExternalMessages.INFO_EXTERNAL_LIB_MESSAGE;

import org.forgerock.i18n.LocalizableMessage;
import org.forgerock.i18n.slf4j.LocalizedMarker;
import org.opends.messages.Severity;
@@ -59,8 +61,13 @@
 * However, to support logger calls from external libraries, calls without a Marker are supported,
 * by creating a raw LocalizableMessage on the fly.
 * <p>
 * Note that these methods are never called directly. Instead, OpenDJ code instantiates a LocalizedLogger
 * Note that these methods are never called directly from OpenDJ.
 * Instead, OpenDJ code instantiates a LocalizedLogger
 * which then delegates to the underlying SLF4J logger.
 * <p>
 * For third party libraries (e.g commons-audit, grizzly),
 * messages with trace and debug level will end in the debug logger.
 * Messages with other levels will end in the error logger.
 */
final class OpenDJLoggerAdapter implements Logger {
    /** Name of logger, used as the category. */
@@ -91,39 +98,50 @@
    /** Format a message containing '{}' as arguments placeholder. */
    private String formatMessage(String message, Object...args)
    {
      if (args == null || args.length == 0) {
          return message;
      }
      return MessageFormatter.arrayFormat(message, args).getMessage();
    }

    /** Trace with message only. */
    private void logTraceMessage(String msg) {
    private void publishInDebugLogger(String msg) {
        tracer.trace(msg);
    }

    /** Trace with message and exception. */
    private void logTraceException(String message, Throwable t) {
    private void publishInDebugLogger(String message, Throwable t) {
        tracer.traceException(message, t);
    }

    /**
     * Log a message to {@code ErrorLogger} with the provided severity,
     * extracting {@code LocalizableMessage} from the provided
     * {@code Marker marker} argument.
     * Log a message to {@code ErrorLogger} with the provided severity.
     * <p>
     * If this method is called from OpenDJ libraries,
     * extracting {code LocalizableMessage} from the provided {code Marker marker} argument,
     * otherwise log the provided {@param message}.
     *
     * @param marker
     *            The marker, expected to be an instance of
     *            {@code LocalizedMarker} class, from which message to log is
     *            extracted.
     * @param message
     *            The message to log if this logger is called by external libraries.
     * @param severity
     *            The severity to use when logging message.
     * @param throwable
     *            Exception to log. May be {@code null}.
     */
    private void logError(Marker marker, Severity severity, Throwable throwable) {
    private void publish(Marker marker, String message, Severity severity, Throwable throwable) {
        if (marker instanceof LocalizedMarker) {
            LocalizableMessage message = ((LocalizedMarker) marker).getMessage();
            logError(message, severity, throwable);
            // OpenDJ logs with all severity levels but trace.
            publishInErrorLogger(((LocalizedMarker) marker).getMessage(), severity, throwable);
        } else if (severity == Severity.DEBUG) {
            // Third party messages with debug level go to the debug logger.
            publishInDebugLogger(message, throwable);
        } else {
            throw new IllegalStateException("Expecting the marker to be an instance of LocalizedMarker");
            // Other Third party messages.
            publishInErrorLogger(message, severity, throwable);
        }
    }

@@ -140,16 +158,15 @@
     * @param throwable
     *            Exception to log. May be {@code null}.
     */
    private void logError(String message, Severity severity, Throwable throwable) {
      logError(LocalizableMessage.raw(message), severity, throwable);
    private void publishInErrorLogger(String message, Severity severity, Throwable throwable) {
      // Use a LocalizedMessage template instead of raw() to avoid null message resource name and ID in logs.
      publishInErrorLogger(INFO_EXTERNAL_LIB_MESSAGE.get(message), severity, throwable);
    }

    /** Performs the actual logging to {@code ErrorLogger}. */
    private void logError(LocalizableMessage message, Severity severity, Throwable throwable) {
      ErrorLogger.log(name, severity, message, throwable);
    private void publishInErrorLogger(LocalizableMessage localizableMessage, Severity severity, Throwable throwable) {
        ErrorLogger.log(name, severity, localizableMessage, throwable);
    }


    @Override
    public boolean isTraceEnabled() {
        return DebugLogger.debugEnabled() && tracer.enabled();
@@ -157,22 +174,30 @@

    @Override
    public void trace(String msg) {
        logTraceMessage(msg);
        if (isTraceEnabled()) {
            publishInDebugLogger(msg);
        }
    }

    @Override
    public void trace(Marker marker, String msg) {
        logTraceMessage(msg);
        if (isTraceEnabled()) {
            publishInDebugLogger(msg);
        }
    }

    @Override
    public void trace(String msg, Throwable t) {
        logTraceException(msg, t);
        if (isTraceEnabled()) {
            publishInDebugLogger(msg, t);
        }
    }

    @Override
    public void trace(Marker marker, String msg, Throwable t) {
        logTraceException(msg, t);
        if (isTraceEnabled()) {
            publishInDebugLogger(msg, t);
        }
    }

    @Override
@@ -182,12 +207,16 @@

    @Override
    public void debug(Marker marker, String msg) {
        logError(marker, Severity.INFORMATION, null);
        if (isDebugEnabled()) {
            publish(marker, msg, Severity.INFORMATION, null);
        }
    }

    @Override
    public void debug(Marker marker, String msg, Throwable t) {
        logError(marker, Severity.INFORMATION, t);
        if (isDebugEnabled()) {
            publish(marker, msg, Severity.INFORMATION, t);
        }
    }

    @Override
@@ -197,12 +226,16 @@

    @Override
    public void info(Marker marker, String msg) {
        logError(marker, Severity.NOTICE, null);
        if (isInfoEnabled()) {
            publish(marker, msg, Severity.NOTICE, null);
        }
    }

    @Override
    public void info(Marker marker, String msg, Throwable t) {
        logError(marker, Severity.NOTICE, t);
        if (isInfoEnabled()) {
            publish(marker, msg, Severity.NOTICE, t);
        }
    }

    @Override
@@ -212,12 +245,16 @@

    @Override
    public void warn(Marker marker, String msg) {
        logError(marker, Severity.WARNING, null);
        if (isWarnEnabled()) {
            publish(marker, msg, Severity.WARNING, null);
        }
    }

    @Override
    public void warn(Marker marker, String msg, Throwable t) {
        logError(marker, Severity.WARNING, t);
        if (isWarnEnabled()) {
            publish(marker, msg, Severity.WARNING, t);
        }
    }

    @Override
@@ -227,12 +264,16 @@

    @Override
    public void error(Marker marker, String msg) {
        logError(marker, Severity.ERROR, null);
        if (isErrorEnabled()) {
            publish(marker, msg, Severity.ERROR, null);
        }
    }

    @Override
    public void error(Marker marker, String msg, Throwable t) {
        logError(marker, Severity.ERROR, t);
        if (isErrorEnabled()) {
            publish(marker, msg, Severity.ERROR, t);
        }
    }

    @Override
@@ -262,191 +303,270 @@

    @Override
    public void trace(String message, Object arg) {
      logTraceMessage(formatMessage(message, arg));
        if (isTraceEnabled()) {
            publishInDebugLogger(formatMessage(message, arg));
        }
    }

    @Override
    public void trace(String message, Object arg1, Object arg2) {
      logTraceMessage(formatMessage(message, arg1, arg2));
        if (isTraceEnabled()) {
            publishInDebugLogger(formatMessage(message, arg1, arg2));
        }
    }

    @Override
    public void trace(String message, Object... argArray) {
      logTraceMessage(formatMessage(message, argArray));
        if (isTraceEnabled()) {
            publishInDebugLogger(formatMessage(message, argArray));
        }
    }

    @Override
    public void trace(Marker marker, String message, Object arg) {
      logTraceMessage(formatMessage(message, arg));
        if (isTraceEnabled()) {
            publishInDebugLogger(formatMessage(message, arg));
        }
    }

    @Override
    public void trace(Marker marker, String message, Object arg1, Object arg2) {
      logTraceMessage(formatMessage(message, arg1, arg2));
        if (isTraceEnabled()) {
            publishInDebugLogger(formatMessage(message, arg1, arg2));
        }
    }

    @Override
    public void trace(Marker marker, String message, Object... argArray) {
      logTraceMessage(formatMessage(message, argArray));
        if (isTraceEnabled()) {
            publishInDebugLogger(formatMessage(message, argArray));
        }
    }

    // Methods below should only by used by third-party libraries.
    // Such third-party libraries include, but are not limited to: commons-audit, grizzly, etc.

    @Override
    public void debug(String msg, Throwable t) {
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(msg, (Object[]) null), t);
        }
    }

    @Override
    public void debug(String msg) {
      logError(msg, Severity.INFORMATION, null);
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(msg, (Object[]) null), null);
        }
    }

    @Override
    public void debug(String message, Object arg) {
      logError(formatMessage(message, arg), Severity.INFORMATION, null);
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(message, arg), null);
        }
    }

    @Override
    public void debug(String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.INFORMATION, null);
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(message, arg1, arg2), null);
        }
    }

    @Override
    public void debug(String message, Object... argArray) {
      logError(formatMessage(message, argArray), Severity.INFORMATION, null);
    }

    @Override
    public void debug(String msg, Throwable t) {
      logError(msg, Severity.INFORMATION, t);
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(message, argArray), null);
        }
    }

    @Override
    public void debug(Marker marker, String message, Object arg) {
      logError(formatMessage(message, arg), Severity.INFORMATION, null);
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(message, arg), null);
        }
    }

    @Override
    public void debug(Marker marker, String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.INFORMATION, null);
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(message, arg1, arg2), null);
        }
    }

    @Override
    public void debug(Marker marker, String message, Object... arguments) {
      logError(formatMessage(message, arguments), Severity.INFORMATION, null);
    }

    @Override
    public void info(String msg) {
      logError(msg, Severity.NOTICE, null);
    }

    @Override
    public void info(String message, Object arg) {
      logError(formatMessage(message, arg), Severity.NOTICE, null);
    }

    @Override
    public void info(String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.NOTICE, null);
    }

    @Override
    public void info(String message, Object... argArray) {
      logError(formatMessage(message, argArray), Severity.NOTICE, null);
        if (isDebugEnabled()) {
            publishInDebugLogger(formatMessage(message, arguments), null);
        }
    }

    @Override
    public void info(String msg, Throwable t) {
      logError(msg, Severity.NOTICE, t);
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(msg, (Object[]) null), Severity.INFORMATION, t);
        }
    }

    @Override
    public void info(String msg) {
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(msg, (Object[]) null), Severity.INFORMATION, null);
        }
    }

    @Override
    public void info(String message, Object arg) {
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(message, arg), Severity.INFORMATION, null);
        }
    }

    @Override
    public void info(String message, Object arg1, Object arg2) {
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(message, arg1, arg2), Severity.INFORMATION, null);
        }
    }

    @Override
    public void info(String message, Object... argArray) {
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(message, argArray), Severity.INFORMATION, null);
        }
    }

    @Override
    public void info(Marker marker, String message, Object arg) {
      logError(formatMessage(message, arg), Severity.NOTICE, null);
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(message, arg), Severity.INFORMATION, null);
        }
    }

    @Override
    public void info(Marker marker, String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.NOTICE, null);
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(message, arg1, arg2), Severity.INFORMATION, null);
        }
    }

    @Override
    public void info(Marker marker, String message, Object... arguments) {
      logError(formatMessage(message, arguments), Severity.NOTICE, null);
    }

    @Override
    public void warn(String msg) {
      logError(msg, Severity.WARNING, null);
    }

    @Override
    public void warn(String message, Object arg) {
      logError(formatMessage(message, arg), Severity.WARNING, null);
    }

    @Override
    public void warn(String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.WARNING, null);
    }

    @Override
    public void warn(String message, Object... argArray) {
      logError(formatMessage(message, argArray), Severity.WARNING, null);
        if (isInfoEnabled()) {
            publishInErrorLogger(formatMessage(message, arguments), Severity.INFORMATION, null);
        }
    }

    @Override
    public void warn(String msg, Throwable t) {
      logError(msg, Severity.WARNING, t);
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(msg, (Object[]) null), Severity.WARNING, t);
        }
    }

    @Override
    public void warn(String msg) {
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(msg, (Object[]) null), Severity.WARNING, null);
        }
    }

    @Override
    public void warn(String message, Object arg) {
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(message, arg), Severity.WARNING, null);
        }
    }

    @Override
    public void warn(String message, Object arg1, Object arg2) {
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(message, arg1, arg2), Severity.WARNING, null);
        }
    }

    @Override
    public void warn(String message, Object... argArray) {
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(message, argArray), Severity.WARNING, null);
        }
    }

    @Override
    public void warn(Marker marker, String message, Object arg) {
      logError(formatMessage(message, arg), Severity.WARNING, null);
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(message, arg), Severity.WARNING, null);
        }
    }

    @Override
    public void warn(Marker marker, String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.WARNING, null);
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(message, arg1, arg2), Severity.WARNING, null);
        }
    }

    @Override
    public void warn(Marker marker, String message, Object... arguments) {
      logError(formatMessage(message, arguments), Severity.WARNING, null);
    }

    @Override
    public void error(String msg) {
      logError(msg, Severity.ERROR, null);
    }

    @Override
    public void error(String message, Object arg) {
      logError(formatMessage(message, arg), Severity.ERROR, null);
    }

    @Override
    public void error(String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.ERROR, null);
    }

    @Override
    public void error(String message, Object... arguments) {
      logError(formatMessage(message, arguments), Severity.ERROR, null);
        if (isWarnEnabled()) {
            publishInErrorLogger(formatMessage(message, arguments), Severity.WARNING, null);
        }
    }

    @Override
    public void error(String msg, Throwable t) {
      logError(msg, Severity.ERROR, t);
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(msg, (Object[]) null), Severity.ERROR, t);
        }
    }

    @Override
    public void error(String msg) {
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(msg, Severity.ERROR, null), Severity.ERROR, null);
        }
    }

    @Override
    public void error(String message, Object arg) {
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(message, arg), Severity.ERROR, null);
        }
    }

    @Override
    public void error(String message, Object arg1, Object arg2) {
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(message, arg1, arg2), Severity.ERROR, null);
        }
    }

    @Override
    public void error(String message, Object... arguments) {
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(message, arguments), Severity.ERROR, null);
        }
    }

    @Override
    public void error(Marker marker, String message, Object arg) {
      logError(formatMessage(message, arg), Severity.ERROR, null);
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(message, arg), Severity.ERROR, null);
        }
    }

    @Override
    public void error(Marker marker, String message, Object arg1, Object arg2) {
      logError(formatMessage(message, arg1, arg2), Severity.ERROR, null);
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(message, arg1, arg2), Severity.ERROR, null);
        }
    }

    @Override
    public void error(Marker marker, String message, Object... arguments) {
      logError(formatMessage(message, arguments), Severity.ERROR, null);
        if (isErrorEnabled()) {
            publishInErrorLogger(formatMessage(message, arguments), Severity.ERROR, null);
        }
    }
}

 opendj-server-legacy/src/messages/org/opends/messages/external.properties

New file
@@ -0,0 +1,42 @@
# CDDL HEADER START
#
# The contents of this file are subject to the terms of the
# Common Development and Distribution License, Version 1.0 only
# (the "License").  You may not use this file except in compliance
# with the License.
#
# You can obtain a copy of the license at legal-notices/CDDLv1_0.txt
# or http://forgerock.org/license/CDDLv1.0.html.
# See the License for the specific language governing permissions
# and limitations under the License.
#
# When distributing Covered Code, include this CDDL HEADER in each
# file and include the License file at legal-notices/CDDLv1_0.txt.
# If applicable, add the following below this CDDL HEADER, with the
# fields enclosed by brackets "[]" replaced with your own identifying
# information:
#      Portions Copyright [yyyy] [name of copyright owner]
#
# CDDL HEADER END
#
#      Copyright 2015 ForgeRock AS.

#
# Format string definitions
#
# Keys must be formatted as follows:
#
# [SEVERITY]_[DESCRIPTION]_[ORDINAL]
#
# where:
#
# SEVERITY is one of:
# [ERR, WARN, NOTICE, INFO, DEBUG]
#
# DESCRIPTION is an upper case string providing a hint as to the context of
# the message in upper case with the underscore ('_') character serving as
# word separator
#
# ORDINAL is an integer unique among other ordinals in this file
#
INFO_EXTERNAL_LIB_MESSAGE_1=%s