LoggerTest.java

/*
 * ModeShape (http://www.modeshape.org)
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *       http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */
package org.modeshape.common.logging;

import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertSame;
import static org.junit.Assert.fail;
import java.io.StringWriter;
import java.util.ArrayList;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.LinkedList;
import java.util.List;
import java.util.Map;
import org.apache.log4j.Appender;
import org.apache.log4j.Level;
import org.apache.log4j.SimpleLayout;
import org.apache.log4j.WriterAppender;
import org.apache.log4j.spi.LoggingEvent;
import org.apache.log4j.spi.ThrowableInformation;
import org.modeshape.common.i18n.I18n;
import org.junit.After;
import org.junit.Before;
import org.junit.BeforeClass;
import org.junit.Test;

/**
 * Test the {@link org.modeshape.common.logging.Logger} class, ensuring that it uses Log4J appropriately. The {@link org.modeshape.common.logging.Logger} class uses the SLF4J generalized
 * logging framework, which can sit on top of multiple logging frameworks, including Log4J. Therefore, this test assumes that
 * SLF4J works correctly for all logging frameworks, then the {@link org.modeshape.common.logging.Logger} class can be tested by using it and checking the
 * resulting Log4J output.
 * <p>
 * To ensure that the Log4J configuration used in the remaining tests (in <code>src/test/resources/log4j.properties</code>)
 * does not interfere with this test, the underlying Log4J logger is obtained before each test and programmatically reconfigured
 * and, after each test, is then restored to it's previous state. This reconfiguration involves identifying and removing all of
 * the {@link Appender Log4J Appender} on the tree of Log4J loggers, and substituting a special {@link LogRecorder Appender} that
 * records the log messages in memory. During the test, this in-memory list of log messages is checked by the test case using
 * standard assertions to verify the proper order and content of the log messages. After each of the tests, all of the original
 * Adapters are restored to the appropriate Log4J loggers.
 * </p>
 */
public class LoggerTest {

    public static I18n errorMessageWithNoParameters;
    public static I18n warningMessageWithNoParameters;
    public static I18n infoMessageWithNoParameters;
    public static I18n errorMessageWithTwoParameters;
    public static I18n warningMessageWithTwoParameters;
    public static I18n infoMessageWithTwoParameters;
    public static I18n errorMessageWithException;
    public static I18n warningMessageWithException;
    public static I18n infoMessageWithException;
    public static I18n errorMessageWithNullException;
    public static I18n warningMessageWithNullException;
    public static I18n infoMessageWithNullException;
    public static I18n someMessage;

    private LogRecorder log;
    private Logger logger;
    private org.apache.log4j.Logger log4jLogger;
    private Map<String, List<Appender>> existingAppendersByLoggerName = new HashMap<String, List<Appender>>();

    @BeforeClass
    public static void beforeAll() {
        // Initialize the I18n static fields ...
        I18n.initialize(LoggerTest.class);
    }

    @Before
    public void beforeEach() {
        logger = Logger.getLogger(LoggerTest.class);

        // Find all of the existing appenders on all of the loggers, and
        // remove them all (keeping track of which appender they're on)
        log4jLogger = org.apache.log4j.Logger.getLogger(logger.getName());
        org.apache.log4j.Logger theLogger = log4jLogger;
        while (theLogger != null) {
            List<Appender> appenders = new ArrayList<Appender>();
            Enumeration<?> previousAppenders = theLogger.getAllAppenders();
            while (previousAppenders.hasMoreElements()) {
                appenders.add((Appender)previousAppenders.nextElement());
            }
            existingAppendersByLoggerName.put(theLogger.getName(), appenders);
            theLogger.removeAllAppenders();
            theLogger = (org.apache.log4j.Logger)theLogger.getParent();
        }

        // Set up the appender from which we can easily grab the content of the log during the tests.
        // This assumes we're using Log4J. Also, the Log4J properties should specify that the
        // logger for this particular class.
        log = new LogRecorder();
        log4jLogger = org.apache.log4j.Logger.getLogger(logger.getName());
        log4jLogger.addAppender(this.log);
        log4jLogger.setLevel(Level.ALL);
    }

    @After
    public void afterEach() {
        // Put all of the existing appenders onto the correct logger, and remove the testing appender ...
        for (Map.Entry<String, List<Appender>> entry : this.existingAppendersByLoggerName.entrySet()) {
            String loggerName = entry.getKey();
            List<Appender> appenders = entry.getValue();
            org.apache.log4j.Logger theLogger = org.apache.log4j.Logger.getLogger(loggerName);
            theLogger.removeAllAppenders(); // removes the testing appender, if on this logger
            for (Appender appender : appenders) {
                theLogger.addAppender(appender);
            }
        }
    }

    @Test
    public void shouldLogAppropriateMessagesIfSetToAllLevel() {
        log4jLogger.setLevel(Level.ALL);
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with no parameters");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with no parameters");
        log.removeFirst(Logger.Level.INFO, "This is an info message with no parameters");
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with no parameters");
        log.removeFirst(Logger.Level.TRACE, "This is a trace message with no parameters");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldLogAppropriateMessagesIfLog4jSetToTraceLevel() {
        log4jLogger.setLevel(Level.TRACE);
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with no parameters");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with no parameters");
        log.removeFirst(Logger.Level.INFO, "This is an info message with no parameters");
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with no parameters");
        log.removeFirst(Logger.Level.TRACE, "This is a trace message with no parameters");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldLogAppropriateMessagesIfLog4jSetToDebugLevel() {
        log4jLogger.setLevel(Level.DEBUG);
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with no parameters");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with no parameters");
        log.removeFirst(Logger.Level.INFO, "This is an info message with no parameters");
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with no parameters");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldLogAppropriateMessagesIfLog4jSetToInfoLevel() {
        log4jLogger.setLevel(Level.INFO);
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with no parameters");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with no parameters");
        log.removeFirst(Logger.Level.INFO, "This is an info message with no parameters");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldLogAppropriateMessagesIfLog4jSetToWarningLevel() {
        log4jLogger.setLevel(Level.WARN);
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with no parameters");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with no parameters");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldLogAppropriateMessagesIfLog4jSetToErrorLevel() {
        log4jLogger.setLevel(Level.ERROR);
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with no parameters");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldLogNoMessagesIfLog4jSetToOffLevel() {
        log4jLogger.setLevel(Level.OFF);
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldNotAcceptMessageWithNonNullAndNullParameters() {
        logger.error(errorMessageWithTwoParameters, "first", null);
        logger.warn(warningMessageWithTwoParameters, "first", null);
        logger.info(infoMessageWithTwoParameters, "first", null);
        logger.debug("This is a debug message with a {0} parameter and the {1} parameter", "first", null);
        logger.trace("This is a trace message with a {0} parameter and the {1} parameter", "first", null);

        log.removeFirst(Logger.Level.ERROR, "This is an error message with a first parameter and the null parameter");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with a first parameter and the null parameter");
        log.removeFirst(Logger.Level.INFO, "This is an info message with a first parameter and the null parameter");
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with a first parameter and the null parameter");
        log.removeFirst(Logger.Level.TRACE, "This is a trace message with a first parameter and the null parameter");
        assertEquals(false, log.hasEvents());
    }

    @Test( expected = IllegalArgumentException.class )
    public void shouldNotAcceptErrorMessageWithTooFewParameters() {
        logger.error(errorMessageWithTwoParameters, (Object[])null);
    }

    @Test( expected = IllegalArgumentException.class )
    public void shouldNotAcceptWarningMessageWithTooFewParameters() {
        logger.warn(warningMessageWithTwoParameters, (Object[])null);
    }

    @Test( expected = IllegalArgumentException.class )
    public void shouldNotAcceptInfoMessageWithTooFewParameters() {
        logger.info(infoMessageWithTwoParameters, (Object[])null);
    }

    @Test( expected = IllegalArgumentException.class )
    public void shouldNotAcceptDebugMessageWithTooFewParameters() {
        logger.debug("This is a debug message with a {0} parameter and the {1} parameter", (Object[])null);
    }

    @Test( expected = IllegalArgumentException.class )
    public void shouldNotAcceptTraceMessageWithTooFewParameters() {
        logger.trace("This is a trace message with a {0} parameter and the {1} parameter", (Object[])null);
    }

    @Test
    public void shouldAcceptMessageWithNoParameters() {
        logger.error(errorMessageWithNoParameters);
        logger.warn(warningMessageWithNoParameters);
        logger.info(infoMessageWithNoParameters);
        logger.debug("This is a debug message with no parameters");
        logger.trace("This is a trace message with no parameters");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with no parameters");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with no parameters");
        log.removeFirst(Logger.Level.INFO, "This is an info message with no parameters");
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with no parameters");
        log.removeFirst(Logger.Level.TRACE, "This is a trace message with no parameters");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldAcceptMessageWithObjectAndPrimitiveParameters() {
        logger.error(errorMessageWithTwoParameters, "first", 2);
        logger.warn(warningMessageWithTwoParameters, "first", 2);
        logger.info(infoMessageWithTwoParameters, "first", 2);
        logger.debug("This is a debug message with a {0} parameter and the {1} parameter", "first", 2);
        logger.trace("This is a trace message with a {0} parameter and the {1} parameter", "first", 2);

        log.removeFirst(Logger.Level.ERROR, "This is an error message with a first parameter and the 2 parameter");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with a first parameter and the 2 parameter");
        log.removeFirst(Logger.Level.INFO, "This is an info message with a first parameter and the 2 parameter");
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with a first parameter and the 2 parameter");
        log.removeFirst(Logger.Level.TRACE, "This is a trace message with a first parameter and the 2 parameter");
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldAcceptMessageAndThrowable() {
        Throwable t = new RuntimeException("This is the runtime exception message");
        logger.error(t, errorMessageWithException);
        logger.warn(t, warningMessageWithException);
        logger.info(t, infoMessageWithException);
        logger.debug(t, "This is a debug message with an exception");
        logger.trace(t, "This is a trace message with an exception");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with an exception", RuntimeException.class);
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with an exception", RuntimeException.class);
        log.removeFirst(Logger.Level.INFO, "This is an info message with an exception", RuntimeException.class);
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with an exception", RuntimeException.class);
        log.removeFirst(Logger.Level.TRACE, "This is a trace message with an exception", RuntimeException.class);
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldAcceptMessageAndNullThrowable() {
        Throwable t = null;
        logger.error(t, errorMessageWithNullException);
        logger.warn(t, warningMessageWithNullException);
        logger.info(t, infoMessageWithNullException);
        logger.debug(t, "This is a debug message with a null exception");
        logger.trace(t, "This is a trace message with a null exception");

        log.removeFirst(Logger.Level.ERROR, "This is an error message with a null exception");
        log.removeFirst(Logger.Level.WARNING, "This is a warning message with a null exception");
        log.removeFirst(Logger.Level.INFO, "This is an info message with a null exception");
        log.removeFirst(Logger.Level.DEBUG, "This is a debug message with a null exception");
        log.removeFirst(Logger.Level.TRACE, "This is a trace message with a null exception");
        assertEquals(false, log.hasEvents());
    }

    public void shouldQuietlyAcceptNullMessage() {
        logger.error(null);
        logger.warn(null);
        logger.info(null);
        logger.debug(null);
        logger.trace(null);

        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldAcceptNullMessageAndThrowable() {
        Throwable t = new RuntimeException("This is the runtime exception message in LoggerTest");
        logger.error(t, null);
        logger.warn(t, null);
        logger.info(t, null);
        logger.debug(t, null);
        logger.trace(t, null);

        log.removeFirst(Logger.Level.ERROR, null, RuntimeException.class);
        log.removeFirst(Logger.Level.WARNING, null, RuntimeException.class);
        log.removeFirst(Logger.Level.INFO, null, RuntimeException.class);
        log.removeFirst(Logger.Level.DEBUG, null, RuntimeException.class);
        log.removeFirst(Logger.Level.TRACE, null, RuntimeException.class);
        assertEquals(false, log.hasEvents());
    }

    @Test
    public void shouldAcceptNullThrowableInError() {
        logger.error((Throwable)null, someMessage);
        logger.warn((Throwable)null, someMessage);
        logger.info((Throwable)null, someMessage);
        logger.debug((Throwable)null, "some message");
        logger.trace((Throwable)null, "some message");

        log.removeFirst(Logger.Level.ERROR, "some message");
        log.removeFirst(Logger.Level.WARNING, "some message");
        log.removeFirst(Logger.Level.INFO, "some message");
        log.removeFirst(Logger.Level.DEBUG, "some message");
        log.removeFirst(Logger.Level.TRACE, "some message");
    }

    @Test
    public void shouldSupportAskingWhetherLoggingLevelsAreEnabled() {
        logger.isErrorEnabled();
        logger.isWarnEnabled();
        logger.isInfoEnabled();
        logger.isDebugEnabled();
        logger.isTraceEnabled();
    }

    /**
     * A special Log4J Appender that records log messages and whose content can be
     * {@link #removeFirst(org.modeshape.common.logging.Logger.Level, String, Class) validated} to ensure that the log contains
     * messages in the proper order and with the proper content.
     */
    public class LogRecorder extends WriterAppender {

        private final LinkedList<LoggingEvent> events = new LinkedList<LoggingEvent>();
        private int lineNumber;

        public LogRecorder( StringWriter writer ) {
            super(new SimpleLayout(), writer);
        }

        public LogRecorder() {
            this(new StringWriter());
        }

        @Override
        protected void subAppend( LoggingEvent event ) {
            super.subAppend(event);
            this.events.add(event);
        }

        public LoggingEvent removeFirst() {
            if (hasEvents()) {
                ++lineNumber;
                return this.events.removeFirst();
            }
            return null;
        }

        public boolean hasEvents() {
            return this.events.size() != 0;
        }

        /**
         * Remove the message that is currently at the front of the log, and verify that it contains the supplied information.
         * 
         * @param expectedLevel the level that the next log message should have
         * @param expectedMessageExpression the message that the next log message should have, or a regular expression that would
         *        match the log message
         * @param expectedExceptionClass the exception class that was expected, or null if there should not be an exception
         */
        public void removeFirst( Logger.Level expectedLevel,
                                 String expectedMessageExpression,
                                 Class<? extends Throwable> expectedExceptionClass ) {
            if (!hasEvents()) {
                fail("Expected log message but found none: " + expectedLevel + " - " + expectedMessageExpression);
            }
            LoggingEvent event = removeFirst();

            // Check the log message ...
            if (expectedMessageExpression != null && event.getMessage() == null) {
                fail("Log line " + lineNumber + " was missing expected message: " + expectedMessageExpression);
            } else if (expectedMessageExpression == null && event.getMessage() != null) {
                fail("Log line " + lineNumber + " had unexpected message: " + event.getMessage());
            } else if (expectedMessageExpression != null) {
                String actual = event.getMessage().toString();
                // Treat as a regular expression, which works for both regular expressions and strings ...
                if (!actual.matches(expectedMessageExpression)) {
                    fail("Log line " + lineNumber + " differed: \nwas     :\t" + actual + "\nexpected:\t"
                         + expectedMessageExpression);
                }
            } // else they are both null

            // Check the exception ...
            ThrowableInformation throwableInfo = event.getThrowableInformation();
            if (expectedExceptionClass == null && throwableInfo != null) {
                fail("Log line " + lineNumber + " had unexpected exception: "
                     + event.getThrowableInformation().getThrowableStrRep());
            } else if (expectedExceptionClass != null && throwableInfo == null) {
                fail("Log line " + lineNumber + " was missing expected exception of type "
                     + expectedExceptionClass.getCanonicalName());
            } else if (expectedExceptionClass != null && throwableInfo != null) {
                Throwable actualException = throwableInfo.getThrowable();
                assertSame(expectedExceptionClass, actualException.getClass());
            } // else they are both null
        }

        public void removeFirst( Logger.Level expectedLevel,
                                 String expectedMessageExpression ) {
            removeFirst(expectedLevel, expectedMessageExpression, null);
        }
    }

}