jdk/test/java/util/logging/Logger/isLoggable/TestIsLoggable.java
author dfuchs
Thu, 12 Sep 2013 17:01:39 +0200
changeset 19847 e481217d82f2
permissions -rw-r--r--
8024525: Make Logger log methods call isLoggable() Summary: This changeset makes the various Logger logging method call isLoggable() instead of inlining the level checks. Reviewed-by: mchung, alanb

/*
 * Copyright (c) 2013, Oracle and/or its affiliates. All rights reserved.
 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
 *
 * This code is free software; you can redistribute it and/or modify it
 * under the terms of the GNU General Public License version 2 only, as
 * published by the Free Software Foundation.
 *
 * This code is distributed in the hope that it will be useful, but WITHOUT
 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
 * version 2 for more details (a copy is included in the LICENSE file that
 * accompanied this code).
 *
 * You should have received a copy of the GNU General Public License version
 * 2 along with this work; if not, write to the Free Software Foundation,
 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
 *
 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
 * or visit www.oracle.com if you need additional information or have any
 * questions.
 */
import java.util.Collections;
import java.util.HashMap;
import java.util.List;
import java.util.Locale;
import java.util.Map;
import java.util.concurrent.CopyOnWriteArrayList;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.LogRecord;
import java.util.logging.Logger;

/**
 * @test
 * @bug 8024525
 * @summary checks that isLoggable() can be overridden to control logging.
 * @author danielfuchs
 * @run main/othervm TestIsLoggable
 */
public class TestIsLoggable {

    // This logger can be configured to override its default level
    // for a particular set of thread ids
    public static final class ThreadLogger extends Logger {

       final Map<Long, Level> threadMap =
                Collections.synchronizedMap(new HashMap<Long, Level>());

        public ThreadLogger(String name) {
            super(name, null);
        }

        @Override
        public boolean isLoggable(Level level) {
            final Level threadLevel = threadMap.get(Thread.currentThread().getId());
            if (threadLevel == null) return super.isLoggable(level);
            final int levelValue = threadLevel.intValue();
            final int offValue = Level.OFF.intValue();
            if (level.intValue() < levelValue || levelValue == offValue) {
                return false;
            }
            return true;
        }

    }

    public static final class TestHandler extends Handler {

        final List<String> messages = new CopyOnWriteArrayList<>();

        @Override
        public void publish(LogRecord record) {
            messages.add(record.getMessage());
        }

        @Override
        public void flush() {
        }

        @Override
        public void close() throws SecurityException {
            messages.clear();
        }

    }

    // Sorted list of standard levels
    static final List<Level> LEVELS = Collections.unmodifiableList(
            java.util.Arrays.asList(new Level[] {
                Level.SEVERE, Level.WARNING, Level.INFO, Level.CONFIG,
                Level.FINE, Level.FINER, Level.FINEST
            }));

    // Test cases:
    //   LEV_   test logger.severe(msg) .. logger.finest(msg)
    //   LOG_   logger.log(Level.SEVERE, msg) ... logger.log(Level.FINEST, msg)
    //   LOG1_  logger.log(Level.SEVERE, msg, param1) ...
    //   LOG2_  logger.log(Level.SEVERE, msg, params[]) ...
    //   LOG3_  logger.log(Level.SEVERE, msg, throwable) ...
    //   LOGP_  logger.logp(Level.SEVERE, class, method, msg) ...
    //   LOGP1_ logger.logp(Level.SEVERE, class, method, msg, param1) ...
    //   LOGP2_ logger.logp(Level.SEVERE, class, method, msg, params[]) ...
    //   LOGP3_ logger.logp(Level.SEVERE, class, method, msg, throwable) ...
    public static enum LogTest {
        LEV_SEVERE, LEV_WARNING, LEV_INFO, LEV_CONFIG, LEV_FINE, LEV_FINER, LEV_FINEST,
        LOG_SEVERE, LOG_WARNING, LOG_INFO, LOG_CONFIG, LOG_FINE, LOG_FINER, LOG_FINEST,
        LOG1_SEVERE, LOG1_WARNING, LOG1_INFO, LOG1_CONFIG, LOG1_FINE, LOG1_FINER, LOG1_FINEST,
        LOG2_SEVERE, LOG2_WARNING, LOG2_INFO, LOG2_CONFIG, LOG2_FINE, LOG2_FINER, LOG2_FINEST,
        LOG3_SEVERE, LOG3_WARNING, LOG3_INFO, LOG3_CONFIG, LOG3_FINE, LOG3_FINER, LOG3_FINEST,
        LOGP_SEVERE, LOGP_WARNING, LOGP_INFO, LOGP_CONFIG, LOGP_FINE, LOGP_FINER, LOGP_FINEST,
        LOGP1_SEVERE, LOGP1_WARNING, LOGP1_INFO, LOGP1_CONFIG, LOGP1_FINE, LOGP1_FINER, LOGP1_FINEST,
        LOGP2_SEVERE, LOGP2_WARNING, LOGP2_INFO, LOGP2_CONFIG, LOGP2_FINE, LOGP2_FINER, LOGP2_FINEST,
        LOGP3_SEVERE, LOGP3_WARNING, LOGP3_INFO, LOGP3_CONFIG, LOGP3_FINE, LOGP3_FINER, LOGP3_FINEST;

        // call the method Logger.severe() ... Logger.finest() corresponding
        // to the given level 'l' (severe() for SEVERE etc...)
        public void loglevel(Level l, Logger logger, String message) {
            LogTest test = LogTest.valueOf("LEV_"+l.getName());
            switch(test) {
                case LEV_SEVERE:
                    logger.severe(message);
                    break;
                case LEV_WARNING:
                    logger.warning(message);
                    break;
                case LEV_INFO:
                    logger.info(message);
                    break;
                case LEV_CONFIG:
                    logger.config(message);
                    break;
                case LEV_FINE:
                    logger.fine(message);
                    break;
                case LEV_FINER:
                    logger.finer(message);
                    break;
                case LEV_FINEST:
                    logger.finest(message);
                    break;
            }
        }

        // The threshold at which the logger is expected to start logging.
        // trick: we derive the threshold level from the testcase name...
        public Level threshold() {
            for (Level l : LEVELS ) {
                if (this.toString().endsWith(l.getName())) {
                    return l;
                }
            }
            return Level.OFF;
        }

        // Levels for which the logger is expected to log something.
        public List<Level> loggable() {
            return LEVELS.subList(0, LEVELS.indexOf(threshold())+1);
        }

        // Levels which will be blocked because they are weaker than the
        // threshold()
        public List<Level> weaker() {
            return LEVELS.subList(LEVELS.indexOf(threshold())+1, LEVELS.size());
        }

        // Log a message at this testcase threshold, using this testcase method.
        public void log(Logger logger, String message) {
            log(threshold(), logger, message);
        }

        // Log a message at the given level, using this testcase method.
        public void log(Level level, Logger logger, String message) {
            if (this.toString().startsWith("LOG_")) {
                logger.log(level, message);
            } else if (this.toString().startsWith("LOG1_")) {
                logger.log(level, message, "dummy param");
            } else if (this.toString().startsWith("LOG2_")) {
                logger.log(level, message, new Object[] {"dummy", "param"});
            } else if (this.toString().startsWith("LOG3_")) {
                logger.log(level, message, new Exception("dummy exception"));
            } else if (this.toString().startsWith("LOGP_")) {
                logger.logp(level, "TestCase", "log", message);
            } else if (this.toString().startsWith("LOGP1_")) {
                logger.logp(level, "TestCase", "log", message, "dummy param");
            } else if (this.toString().startsWith("LOGP2_")) {
                logger.logp(level, "TestCase", "log", message,
                        new Object[] {"dummy", "param"});
            } else if (this.toString().startsWith("LOGP3_")) {
                logger.logp(level, "TestCase", "log", message,
                        new Exception("dummy exception"));
            } else if (this.toString().startsWith("LEV_")) {
                loglevel(level, logger, message);
            }
        }

        // String description of the logging method called.
        public String method() {
            if (this.toString().startsWith("LOG_")) {
                return "Logger.log(Level." + threshold().getName() +", msg): ";
            } else if (this.toString().startsWith("LOG1_")) {
                return "Logger.log(Level." + threshold().getName() +", msg, param1): ";
            } else if (this.toString().startsWith("LOG2_")) {
                return "Logger.log(Level." + threshold().getName() +", msg, params[]): ";
            } else if (this.toString().startsWith("LOG3_")) {
                return "Logger.log(Level." + threshold().getName() +", msg, throwable): ";
            } else if (this.toString().startsWith("LEV_")) {
                return "Logger."+threshold().getName().toLowerCase(Locale.ROOT)+"(): ";
            } else if (this.toString().startsWith("LOGP_")) {
                return "Logger.logp(Level." + threshold().getName() +", msg): ";
            } else if (this.toString().startsWith("LOGP1_")) {
                return "Logger.logp(Level." + threshold().getName() +", msg, param1): ";
            } else if (this.toString().startsWith("LOGP2_")) {
                return "Logger.logp(Level." + threshold().getName() +", msg, params[]): ";
            } else if (this.toString().startsWith("LOGP3_")) {
                return "Logger.logp(Level." + threshold().getName() +", msg, throwable): ";
            }
            throw new RuntimeException("Unknown test case: "+this);
        }
    }

    // The purpose of this test is to verify that the various log methods in
    // Logger now call Logger.isLoggable().
    // To do that - we're going to use a subclass of Logger, ThreadLogger, which
    // only overrides isLoggable() - and compare the level it is given to a level
    // it finds in a map indexed with the current thread id.
    // We will register a TestHandler with our ThreadLogger which will store
    // the messages in a messages map. This will allow us to verify whether the
    // logging method we're testing has or hasn't logged.
    //
    // The TestCase enum above allows us to test a combination of every possible
    // log method with every possible level inside a loop - with the
    // exception of exiting/entering/throwing that we will be testing
    // outside of that loop.
    //
    public static void main(String... args) {
        LogManager manager = LogManager.getLogManager();
        ThreadLogger logger = new ThreadLogger("foo.bar");
        //manager.addLogger(logger);
        TestHandler handler = new TestHandler();
        logger.addHandler(handler);

        //By default, logger's level is Level.INFO
        final List<Level> loggable = LEVELS.subList(0, LEVELS.indexOf(Level.INFO)+1);

        // Check our test implementation of logger.isLoggable();
        //
        // Since we haven't put anything in the threadMap, isLoggable() should
        // return true for all levels stronger or equals to Level.INFO.
        // here we're just checking that our implementation of
        // ThreadLogger.isLoggable() returns what we want - we're just testing
        // the test code...
        for (Level level : LEVELS) {
            if (logger.isLoggable(level) != loggable.contains(level)) {
                throw new RuntimeException(level +
                        ": unexpected result for isLoggable(): expected " +
                        (loggable.contains(level)));
            }
        }

        // Test that entering/exiting/throwing call isLoggable()

        // Here we test the default behavior: this call shouldn't log anything
        //   because by default the logger level is Level.INFO and these
        //   methods log at Level.FINER.
        // So by default - these methods don't log anything. We check it here.
        logger.entering("blah", "blah");
        logger.entering("blah", "blah", "blah");
        logger.entering("blah", "blah", new Object[] {"blah"});
        if (!handler.messages.isEmpty()) {
            throw new RuntimeException("Expected empty, got "+handler.messages);
        }

        logger.exiting("blah", "blah");
        logger.exiting("blah", "blah", "blah");
        logger.exiting("blah", "blah", new Object[] {"blah"});
        if (!handler.messages.isEmpty()) {
            throw new RuntimeException("Expected empty, got "+handler.messages);
        }

        logger.throwing("blah", "blah", new Exception("blah"));
        if (!handler.messages.isEmpty()) {
            throw new RuntimeException("Expected empty, got "+handler.messages);
        }

        // Now we're going to put each level in turn in the threadMap.
        // This means that isLoggable(Level.FINER) should now return true if the
        // level in the map is not one of the level in the 'stronger' list below
        // (here stronger=stronger than FINER)
        final List<Level> stronger = LEVELS.subList(0, LEVELS.indexOf(Level.FINER));
        for (Level l : LEVELS) {

            logger.threadMap.put(Thread.currentThread().getId(), l);

            // Check that our implementation of isLoggable(level) now returns true
            // if 'level' is stronger or equals to 'l' - here we're just checking
            // that our implementation of ThreadLogger.isLoggable() returns what
            // we want - we're just testing the test code...
            final List<Level> loggableLevels = LEVELS.subList(0, LEVELS.indexOf(l)+1);
            for (Level level : LEVELS) {
                if (logger.isLoggable(level) != loggableLevels.contains(level)) {
                    throw new RuntimeException(level +
                            ": unexpected result for isLoggable(): expected " +
                            (loggableLevels.contains(level)));
                }
            }

            // These methods should now start to log when the level we put in
            // the map is weaker or equals to Level.FINER.
            // This validates that these methods now call ThreadLogger.isLoggable()
            // since the default level for our logger is still Level.INFO.
            // If the methods didn't call ThreadLogger.isLoggable() they wouldn't
            // log anything, whatever we put in the threadMap...

            logger.entering("blah", "blah");
            logger.entering("blah", "blah", "blah");
            logger.entering("blah", "blah", new Object[] {"blah"});
            if (stronger.contains(l)) {
                if (!handler.messages.isEmpty()) {
                    throw new RuntimeException(l +
                            ": Expected empty, got " + handler.messages);
                }
            } else {
                if (handler.messages.size() != 3) {
                    throw new RuntimeException(l +
                            ": Expected size 3, got " + handler.messages);
                }
            }

            logger.exiting("blah", "blah");
            logger.exiting("blah", "blah", "blah");
            logger.exiting("blah", "blah", new Object[] {"blah"});
            if (stronger.contains(l)) {
                if (!handler.messages.isEmpty()) {
                    throw new RuntimeException(l +
                            ": Expected empty, got " + handler.messages);
                }
            } else {
                if (handler.messages.size() != 6) {
                    throw new RuntimeException(l +
                            ": Expected size 6, got " + handler.messages);
                }
            }

            logger.throwing("blah", "blah", new Exception("blah"));
            if (stronger.contains(l)) {
                if (!handler.messages.isEmpty()) {
                    throw new RuntimeException(l +
                            ": Expected empty, got " + handler.messages);
                }
            } else {
                if (handler.messages.size() != 7) {
                    throw new RuntimeException(l +
                            ": Expected size 7, got " + handler.messages);
                }
            }
            if (!stronger.contains(l)) {
                System.out.println(l + ": Logger.entering/exiting/throwing: " +
                        handler.messages);
            }
            handler.messages.clear();
        }

        // Cleanup so that we can start the next test with a clean plate...
        handler.messages.clear();
        logger.threadMap.clear();

        // Test that each logging method calls isLoggable()
        //
        for (LogTest testCase : LogTest.values()) {
            // Each test case is a combination of:
            //    1. A level to put in the threadMap.
            //    2. A log method to call
            final String method = testCase.method();

            // check our implementation of logger.isLoggable();
            // by default the logger level is Level.INFO, so our implementation
            // of isLoggable() should return true for all levels stronger or
            // equal to INFO and false for the others.
            // We check that here.
            for (Level level : LEVELS) {
                if (logger.isLoggable(level) != loggable.contains(level)) {
                    throw new RuntimeException(level +
                            ": unexpected result for isLoggable(): expected " +
                            (loggable.contains(level)));
                }
            }

            // Check that by default the log method will not log for level
            // weaker than Level.INFO.
            for (Level l : LEVELS.subList(LEVELS.indexOf(Level.INFO) + 1, LEVELS.size())) {
                final String test = method + l + ": ";
                testCase.log(l, logger, "blah");
                if (!handler.messages.isEmpty()) {
                    throw new RuntimeException(test +
                            "Expected empty, got " + handler.messages);
                }
            }

            // Let's put Level.OFF in the threadMap. Nothing should be logged,
            // whichever level is used...
            logger.threadMap.put(Thread.currentThread().getId(), Level.OFF);

            // Check that isLoggable() now always return false.
            for (Level level : LEVELS) {
                if (logger.isLoggable(level)) {
                    throw new RuntimeException(level +
                            ": unexpected result for isLoggable(): expected " +
                            false);
                }
            }

            // Check that the log method of the test case won't log, whatever
            // level we pass to it. This validates that level method calls
            // isLoggable() - because otherwise it would log for levels stronger
            // or equal to INFO.
            for (Level l : LEVELS) {
                final String test = "[threadMap=OFF] " + method + l + ": ";
                testCase.log(l, logger, "blah");
                if (!handler.messages.isEmpty()) {
                    throw new RuntimeException(test +
                            "Expected empty, got " + handler.messages);
                }
            }
            System.out.println("[threadMap=OFF] " + method + "logged " + handler.messages);

            // Now put the testcase's level in the threadMap.
            logger.threadMap.put(Thread.currentThread().getId(), testCase.threshold());

            // The levels for which logging should happen are those that are stronger
            // or equals to the testcase's  thresholds.
            final List<Level> loggableLevels =
                    LEVELS.subList(0, LEVELS.indexOf(testCase.threshold())+1);

            // Check that our implementation of isLoggable() is taking into account
            // what we put in the map.
            for (Level level : LEVELS) {
                if (logger.isLoggable(level) != loggableLevels.contains(level)) {
                    throw new RuntimeException(level +
                            ": unexpected result for isLoggable(): expected " +
                            (loggableLevels.contains(level)));
                }
            }

            // Now check that the log method is indeed calling our implementation
            // of isLoggable(). We do this by first verifying that it won't log
            // for levels weaker than what we put in the map.
            //
            for (Level l : testCase.weaker()) {
                final String test = method + l + ": ";
                testCase.log(l, logger, "blah");
                if (!handler.messages.isEmpty()) {
                    throw new RuntimeException(test +
                            "Expected empty, got " + handler.messages);
                }
            }

            // Then we check that it will log for the testcase threshold.
            final String test2 = method + testCase.threshold() + ": ";
            testCase.log(logger, testCase.threshold() + " blah");
            if (handler.messages.isEmpty()) {
                throw new RuntimeException(test2 +
                        "Expected 1 message, but list is empty");
            }
            if (!handler.messages.contains(testCase.threshold() + " blah")) {
                throw new RuntimeException(test2 + " blah not found: "
                        + handler.messages);
            }
            handler.messages.clear();

            // Now we check that it logs for all 'loggable' level (and doesn't
            // log for the others).
            for (Level l : LEVELS) {
                final String test = method + l + ": ";
                testCase.log(l, logger, l + ": blah");
                if (testCase.loggable().contains(l)) {
                    if (!handler.messages.contains(l + ": blah")) {
                        throw new RuntimeException(test + "blah not found: " +
                                handler.messages);
                    }
                } else {
                    if (handler.messages.contains(l + ": blah")) {
                        throw new RuntimeException(test + "blah found: " +
                                handler.messages);
                    }
                }
            }
            if (handler.messages.size() != testCase.loggable().size()) {
                throw new RuntimeException(method +
                        " Sizes don't match: expected " +
                        testCase.loggable().size() + " got " +
                        handler.messages);
            }

            // Some visual feedback on what happened.
            System.out.println(method + "logged " + handler.messages);

            // Cleanup for next step.
            // Since we're iterating over all possible levels we can be
            // sure that we haven't missed anything.
            // For instance - it could be argued that logger.severe() will
            // always log. But since we have 1 case where we put Level.OFF in
            // the map and we have verified that severe() didn't log in that
            // case, but that it logged in any other case, then we know
            // beyond doubt that it called our implementation of isLoggable().
            logger.threadMap.clear();
            handler.messages.clear();
        }

    }
}