# HG changeset patch # User plevart # Date 1431851916 -7200 # Node ID 1fcf87dbdc3c4e7d3d3d5b6635a316ef2c967bc3 # Parent d9891f85d583a92cef22976edf22d033fa971eed 8077846: improve locking strategy for readConfiguration(), reset(), and initializeGlobalHandlers() Reviewed-by: dholmes, alanb, mchung Contributed-by: daniel.fuchs@oracle.com, peter.levart@gmail.com diff -r d9891f85d583 -r 1fcf87dbdc3c jdk/src/java.logging/share/classes/java/util/logging/LogManager.java --- a/jdk/src/java.logging/share/classes/java/util/logging/LogManager.java Fri May 15 22:10:29 2015 +0300 +++ b/jdk/src/java.logging/share/classes/java/util/logging/LogManager.java Sun May 17 10:38:36 2015 +0200 @@ -33,6 +33,7 @@ import java.lang.ref.WeakReference; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CopyOnWriteArrayList; +import java.util.concurrent.locks.ReentrantLock; import sun.misc.JavaAWTAccess; import sun.misc.ManagedLocalsThread; import sun.misc.SharedSecrets; @@ -180,10 +181,16 @@ // initialization has been done) private volatile boolean readPrimordialConfiguration; // Have we initialized global (root) handlers yet? - // This gets set to false in readConfiguration - private boolean initializedGlobalHandlers = true; - // True if JVM death is imminent and the exit hook has been called. - private boolean deathImminent; + // This gets set to STATE_UNINITIALIZED in readConfiguration + private static final int + STATE_INITIALIZED = 0, // initial state + STATE_INITIALIZING = 1, + STATE_READING_CONFIG = 2, + STATE_UNINITIALIZED = 3, + STATE_SHUTDOWN = 4; // terminal state + private volatile int globalHandlersState; // = STATE_INITIALIZED; + // A concurrency lock for reset(), readConfiguration() and Cleaner. + private final ReentrantLock configurationLock = new ReentrantLock(); // This list contains the loggers for which some handlers have been // explicitly configured in the configuration file. @@ -264,13 +271,12 @@ // before synchronized block. Otherwise deadlocks are possible. LogManager mgr = manager; - // If the global handlers haven't been initialized yet, we - // don't want to initialize them just so we can close them! - synchronized (LogManager.this) { - // Note that death is imminent. - deathImminent = true; - initializedGlobalHandlers = true; - } + // set globalHandlersState to STATE_SHUTDOWN atomically so that + // no attempts are made to (re)initialize the handlers or (re)read + // the configuration again. This is terminal state. + configurationLock.lock(); + globalHandlersState = STATE_SHUTDOWN; + configurationLock.unlock(); // Do a reset to close all active handlers. reset(); @@ -1314,8 +1320,14 @@ public void reset() throws SecurityException { checkPermission(); + List persistent; - synchronized (this) { + + // We don't want reset() and readConfiguration() + // to run in parallel + configurationLock.lock(); + try { + // install new empty properties props = new Properties(); // make sure we keep the loggers persistent until reset is done. // Those are the loggers for which we previously created a @@ -1323,26 +1335,41 @@ // from being gc'ed until those handlers are closed. persistent = new ArrayList<>(closeOnResetLoggers); closeOnResetLoggers.clear(); - // Since we are doing a reset we no longer want to initialize - // the global handlers, if they haven't been initialized yet. - initializedGlobalHandlers = true; + + // if reset has been called from shutdown-hook (Cleaner), + // or if reset has been called from readConfiguration() which + // already holds the lock and will change the state itself, + // then do not change state here... + if (globalHandlersState != STATE_SHUTDOWN && + globalHandlersState != STATE_READING_CONFIG) { + // ...else user called reset()... + // Since we are doing a reset we no longer want to initialize + // the global handlers, if they haven't been initialized yet. + globalHandlersState = STATE_INITIALIZED; + } + + for (LoggerContext cx : contexts()) { + resetLoggerContext(cx); + } + + persistent.clear(); + } finally { + configurationLock.unlock(); } - for (LoggerContext cx : contexts()) { - Enumeration enum_ = cx.getLoggerNames(); - while (enum_.hasMoreElements()) { - String name = enum_.nextElement(); - Logger logger = cx.findLogger(name); - if (logger != null) { - resetLogger(logger); - } + } + + private void resetLoggerContext(LoggerContext cx) { + Enumeration enum_ = cx.getLoggerNames(); + while (enum_.hasMoreElements()) { + String name = enum_.nextElement(); + Logger logger = cx.findLogger(name); + if (logger != null) { + resetLogger(logger); } } - persistent.clear(); } - // Private method to reset an individual target logger. - private void resetLogger(Logger logger) { - // Close all the Logger's handlers. + private void closeHandlers(Logger logger) { Handler[] targets = logger.getHandlers(); for (Handler h : targets) { logger.removeHandler(h); @@ -1352,6 +1379,14 @@ // Problems closing a handler? Keep going... } } + } + + // Private method to reset an individual target logger. + private void resetLogger(Logger logger) { + // Close all the Logger handlers. + closeHandlers(logger); + + // Reset Logger level String name = logger.getName(); if (name != null && name.equals("")) { // This is the root logger. @@ -1408,48 +1443,74 @@ */ public void readConfiguration(InputStream ins) throws IOException, SecurityException { checkPermission(); - reset(); - // Load the properties + // We don't want reset() and readConfiguration() to run + // in parallel. + configurationLock.lock(); try { - props.load(ins); - } catch (IllegalArgumentException x) { - // props.load may throw an IllegalArgumentException if the stream - // contains malformed Unicode escape sequences. - // We wrap that in an IOException as readConfiguration is - // specified to throw IOException if there are problems reading - // from the stream. - // Note: new IOException(x.getMessage(), x) allow us to get a more - // concise error message than new IOException(x); - throw new IOException(x.getMessage(), x); + if (globalHandlersState == STATE_SHUTDOWN) { + // already in terminal state: don't even bother + // to read the configuration + return; + } + + // change state to STATE_READING_CONFIG to signal reset() to not change it + globalHandlersState = STATE_READING_CONFIG; + try { + // reset configuration which leaves globalHandlersState at STATE_READING_CONFIG + // so that while reading configuration, any ongoing logging requests block and + // wait for the outcome (see the end of this try statement) + reset(); + + try { + // Load the properties + props.load(ins); + } catch (IllegalArgumentException x) { + // props.load may throw an IllegalArgumentException if the stream + // contains malformed Unicode escape sequences. + // We wrap that in an IOException as readConfiguration is + // specified to throw IOException if there are problems reading + // from the stream. + // Note: new IOException(x.getMessage(), x) allow us to get a more + // concise error message than new IOException(x); + throw new IOException(x.getMessage(), x); + } + + // Instantiate new configuration objects. + String names[] = parseClassNames("config"); + + for (String word : names) { + try { + Class clz = ClassLoader.getSystemClassLoader().loadClass(word); + clz.newInstance(); + } catch (Exception ex) { + System.err.println("Can't load config class \"" + word + "\""); + System.err.println("" + ex); + // ex.printStackTrace(); + } + } + + // Set levels on any pre-existing loggers, based on the new properties. + setLevelsOnExistingLoggers(); + + // Note that we need to reinitialize global handles when + // they are first referenced. + globalHandlersState = STATE_UNINITIALIZED; + } catch (Throwable t) { + // If there were any trouble, then set state to STATE_INITIALIZED + // so that no global handlers reinitialization is performed on not fully + // initialized configuration. + globalHandlersState = STATE_INITIALIZED; + // re-throw + throw t; + } + } finally { + configurationLock.unlock(); } - // Instantiate new configuration objects. - String names[] = parseClassNames("config"); - - for (String word : names) { - try { - Class clz = ClassLoader.getSystemClassLoader().loadClass(word); - clz.newInstance(); - } catch (Exception ex) { - System.err.println("Can't load config class \"" + word + "\""); - System.err.println("" + ex); - // ex.printStackTrace(); - } - } - - // Set levels on any pre-existing loggers, based on the new properties. - setLevelsOnExistingLoggers(); - - try { - invokeConfigurationListeners(); - } finally { - // Note that we need to reinitialize global handles when - // they are first referenced. - synchronized (this) { - initializedGlobalHandlers = false; - } - } + // should be called out of lock to avoid dead-lock situations + // when user code is involved + invokeConfigurationListeners(); } /** @@ -1576,20 +1637,41 @@ // Private method to load the global handlers. // We do the real work lazily, when the global handlers // are first used. - private synchronized void initializeGlobalHandlers() { - if (initializedGlobalHandlers) { + private void initializeGlobalHandlers() { + int state = globalHandlersState; + if (state == STATE_INITIALIZED || + state == STATE_SHUTDOWN) { + // Nothing to do: return. return; } - initializedGlobalHandlers = true; - - if (deathImminent) { - // Aaargh... - // The VM is shutting down and our exit hook has been called. - // Avoid allocating global handlers. - return; + // If we have not initialized global handlers yet (or need to + // reinitialize them), lets do it now (this case is indicated by + // globalHandlersState == STATE_UNINITIALIZED). + // If we are in the process of initializing global handlers we + // also need to lock & wait (this case is indicated by + // globalHandlersState == STATE_INITIALIZING). + // If we are in the process of reading configuration we also need to + // wait to see what the outcome will be (this case + // is indicated by globalHandlersState == STATE_READING_CONFIG) + // So in either case we need to wait for the lock. + configurationLock.lock(); + try { + if (globalHandlersState != STATE_UNINITIALIZED) { + return; // recursive call or nothing to do + } + // set globalHandlersState to STATE_INITIALIZING first to avoid + // getting an infinite recursion when loadLoggerHandlers(...) + // is going to call addHandler(...) + globalHandlersState = STATE_INITIALIZING; + try { + loadLoggerHandlers(rootLogger, null, "handlers"); + } finally { + globalHandlersState = STATE_INITIALIZED; + } + } finally { + configurationLock.unlock(); } - loadLoggerHandlers(rootLogger, null, "handlers"); } static final Permission controlPermission = new LoggingPermission("control", null); @@ -1684,7 +1766,7 @@ // Private method to be called when the configuration has // changed to apply any level settings to any pre-existing loggers. - synchronized private void setLevelsOnExistingLoggers() { + private void setLevelsOnExistingLoggers() { Enumeration enum_ = props.propertyNames(); while (enum_.hasMoreElements()) { String key = (String)enum_.nextElement(); diff -r d9891f85d583 -r 1fcf87dbdc3c jdk/test/java/util/logging/LogManager/Configuration/TestConfigurationLock.java --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/jdk/test/java/util/logging/LogManager/Configuration/TestConfigurationLock.java Sun May 17 10:38:36 2015 +0200 @@ -0,0 +1,457 @@ +/* + * Copyright (c) 2015, 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.io.File; +import java.io.IOException; +import java.lang.management.LockInfo; +import java.lang.management.ManagementFactory; +import java.lang.management.MonitorInfo; +import java.lang.management.ThreadInfo; +import java.security.Permission; +import java.security.Policy; +import java.security.ProtectionDomain; +import java.util.ArrayList; +import java.util.List; +import java.util.concurrent.atomic.AtomicLong; +import java.util.logging.Level; +import java.util.logging.LogManager; +import java.util.logging.Logger; + + +/** + * @test + * @bug 8077846 + * @key randomness + * @summary Test that using a reentrant configuration lock does not introduce + * new synchronization issues in Logger and LogManager. This test + * focuses more particularly on potential deadlock in + * drainLoggerRefQueueBounded / readConfiguration / reset + * todo: add at randomness + * @run main/othervm TestConfigurationLock + * @author danielfuchs + */ +// This test is a best effort to try & detect issues. The test itself will run +// for 8secs. This might be unsufficient to detect issues. +// To get a greater confidence it is recommended to run this test in a loop: +// e.g. use something like: +// $ while jtreg -jdk:$JDK -verbose:all \ +// test/java/util/logging/TestConfigurationLock.java ; \ +// do echo Running test again ; done +// and let it run for a few hours... +// +public class TestConfigurationLock { + + static volatile Exception thrown = null; + static volatile boolean goOn = true; + static volatile boolean deadlock = false; + + static final double CONFSYNCTHRESHOLD = 0.3; + static final double LOGSYNCTHRESHOLD = 0.3; + static final int RESETERS = 0; + static final int READERS = 3; + static final int LOGGERS = 4; + static final long TIME = 8 * 1000; // 8 sec. + static final long STEP = 1 * 1000; // message every 1 sec. + static final int LCOUNT = 50; // 50 loggers created in a row... + static final AtomicLong nextLogger = new AtomicLong(0); + static final AtomicLong resetCount = new AtomicLong(0); + static final AtomicLong readCount = new AtomicLong(0); + static final AtomicLong checkCount = new AtomicLong(0); + + static final String BLAH = "blah"; + + static Object fakeConfExternalLock() { + return LogManager.getLogManager(); + } + + static Object fakeLogExternalLock() { + return LogManager.getLogManager(); + } + + + /** + * This test will run both with and without a security manager. + * + * The test starts a number of threads that will call + * LogManager.reset() concurrently (ResetConf), and a number of threads + * that will call readConfiguration() (ReadConf), and then starts a + * number of threads that will create new loggers concurrently + * (AddLogger), and finally two additional threads: + * - one (Stopper) that will stop the test after 4secs (TIME ms), + * - and one DeadlockDetector that will attempt to detect deadlocks. + * If after 4secs no deadlock was detected and no exception was thrown + * then the test is considered a success and passes. + * + * This procedure is done twice: once without a security manager and once + * again with a security manager - which means the test takes ~8secs to + * run. + * + * Note that 8sec may not be enough to detect issues if there are some. + * This is a best effort test. + * + * @param args the command line arguments + * @throws java.lang.Exception if the test fails + */ + public static void main(String[] args) throws Exception { + + File conf = new File(System.getProperty("test.src", "./src"), + TestConfigurationLock.class.getSimpleName() + ".properties"); + if (!conf.canRead()) { + throw new IOException("Can't read config file: " + conf.getAbsolutePath()); + } + System.setProperty("java.util.logging.config.file", conf.getAbsolutePath()); + // test without security + System.out.println("No security"); + test(); + + // test with security + System.out.println("\nWith security"); + Policy.setPolicy(new Policy() { + @Override + public boolean implies(ProtectionDomain domain, Permission permission) { + if (super.implies(domain, permission)) return true; + // System.out.println("Granting " + permission); + return true; // all permissions + } + }); + System.setSecurityManager(new SecurityManager()); + test(); + } + + + /** + * Starts all threads, wait 4secs, then stops all threads. + * @throws Exception if a deadlock was detected or an error occurred. + */ + public static void test() throws Exception { + goOn = true; + thrown = null; + long sNextLogger = nextLogger.get(); + long sUpdateCount = resetCount.get(); + long sReadCount = readCount.get(); + long sCheckCount = checkCount.get(); + List threads = new ArrayList<>(); + for (int i = 0; i CONFSYNCTHRESHOLD) { + // calling reset while holding a lock can increase + // deadlock probability... + synchronized(fakeConfExternalLock()) { + LogManager.getLogManager().reset(); + } + } else { + LogManager.getLogManager().reset(); + } + Logger blah = Logger.getLogger(BLAH); + blah.setLevel(Level.FINEST); + blah.fine(BLAH); + resetCount.incrementAndGet(); + pause(1); + } catch (Exception x) { + fail(x); + } + } + } + } + + final static class ReadConf extends Thread { + + public ReadConf() { + setDaemon(true); + } + + @Override + public void run() { + while (goOn) { + try { + if (Math.random() > CONFSYNCTHRESHOLD) { + // calling readConfiguration while holding a lock can + // increase deadlock probability... + synchronized(fakeConfExternalLock()) { + LogManager.getLogManager().readConfiguration(); + } + } else { + LogManager.getLogManager().readConfiguration(); + } + Logger blah = Logger.getLogger(BLAH); + blah.setLevel(Level.FINEST); + blah.fine(BLAH); + readCount.incrementAndGet(); + pause(1); + } catch (Exception x) { + fail(x); + } + } + } + } + + final static class AddLogger extends Thread { + + public AddLogger() { + setDaemon(true); + } + + @Override + public void run() { + try { + while (goOn) { + Logger l; + Logger foo = Logger.getLogger("foo"); + Logger bar = Logger.getLogger("foo.bar"); + for (int i=0; i < LCOUNT ; i++) { + LogManager manager = LogManager.getLogManager(); + if (Math.random() > LOGSYNCTHRESHOLD) { + synchronized(fakeLogExternalLock()) { + l = Logger.getLogger("foo.bar.l"+nextLogger.incrementAndGet()); + } + } else { + l = Logger.getLogger("foo.bar.l"+nextLogger.incrementAndGet()); + } + l.setLevel(Level.FINEST); + l.fine("I'm fine"); + if (!goOn) break; + pause(1); + } + } + } catch (InterruptedException | RuntimeException x ) { + fail(x); + } + } + } + + final static class DeadlockDetector extends Thread { + + @Override + public void run() { + boolean deadlock = false; + while(goOn) { + try { + long[] ids = ManagementFactory.getThreadMXBean().findDeadlockedThreads(); + checkCount.incrementAndGet(); + ids = ids == null ? new long[0] : ids; + if (ids.length == 1) { + throw new RuntimeException("Found 1 deadlocked thread: "+ids[0]); + } else if (ids.length > 0) { + deadlock = true; + ThreadInfo[] infos = ManagementFactory.getThreadMXBean() + .getThreadInfo(ids, true, true); + System.err.println("Found "+ids.length+" deadlocked threads: "); + for (ThreadInfo inf : infos) { + System.err.println(asString(inf)); + } + throw new RuntimeException("Found "+ids.length+" deadlocked threads"); + } + pause(100); + } catch(InterruptedException | RuntimeException x) { + if (deadlock) deadlock(x); + else fail(x); + } + } + } + + } + + static final class Stopper extends Thread { + long start; + long time; + + Stopper(long time) { + start = System.currentTimeMillis(); + this.time = time; + setDaemon(true); + } + + @Override + public void run() { + try { + long rest, previous; + int msgCount = 0; + previous = time; + Logger logger = Logger.getLogger("remaining"); + while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) { + if (previous == time || previous - rest >= STEP) { + logger.log(Level.INFO, "{0}ms remaining...", String.valueOf(rest)); + msgCount++; + previous = rest == time ? rest -1 : rest; + System.gc(); + } + if (goOn == false) break; + pause(Math.min(rest, 100)); + } + System.err.println(this + ": " + msgCount + " messages."); + System.err.flush(); + System.out.println(System.currentTimeMillis() - start + + " ms elapsed ("+time+ " requested)"); + goOn = false; + } catch(InterruptedException | RuntimeException x) { + fail(x); + } + } + + } + + // ThreadInfo.toString() only prints 8 frames... + static String asString(ThreadInfo inf) { + StringBuilder sb = new StringBuilder(); + sb.append("\"").append(inf.getThreadName()).append("\"") + .append(inf.isDaemon() ? " daemon" : "") + .append(" prio=").append(inf.getPriority()) + .append(" Id=").append(inf.getThreadId()) + .append(" ").append(inf.getThreadState()); + if (inf.getLockName() != null) { + sb.append(" on ").append(inf.getLockName()); + } + if (inf.getLockOwnerName() != null) { + sb.append(" owned by \"").append(inf.getLockOwnerName()) + .append("\" Id=").append(inf.getLockOwnerId()); + } + if (inf.isSuspended()) { + sb.append(" (suspended)"); + } + if (inf.isInNative()) { + sb.append(" (in native)"); + } + sb.append('\n'); + int i = 0; + StackTraceElement[] stackTrace = inf.getStackTrace(); + for (; i < stackTrace.length; i++) { + StackTraceElement ste = stackTrace[i]; + sb.append("\tat ").append(ste.toString()); + sb.append('\n'); + if (i == 0 && inf.getLockInfo() != null) { + Thread.State ts = inf.getThreadState(); + switch (ts) { + case BLOCKED: + sb.append("\t- blocked on ").append(inf.getLockInfo()); + sb.append('\n'); + break; + case WAITING: + sb.append("\t- waiting on ").append(inf.getLockInfo()); + sb.append('\n'); + break; + case TIMED_WAITING: + sb.append("\t- waiting on ").append(inf.getLockInfo()); + sb.append('\n'); + break; + default: + } + } + + for (MonitorInfo mi : inf.getLockedMonitors()) { + if (mi.getLockedStackDepth() == i) { + sb.append("\t- locked ").append(mi); + sb.append('\n'); + } + } + } + if (i < stackTrace.length) { + sb.append("\t..."); + sb.append('\n'); + } + + LockInfo[] locks = inf.getLockedSynchronizers(); + if (locks.length > 0) { + sb.append("\n\tNumber of locked synchronizers = ").append(locks.length); + sb.append('\n'); + for (LockInfo li : locks) { + sb.append("\t- ").append(li); + sb.append('\n'); + } + } + sb.append('\n'); + return sb.toString(); + } + + static void pause(long millis) throws InterruptedException { + Thread.sleep(millis); + } + + static void fail(Exception x) { + x.printStackTrace(System.err); + if (thrown == null) { + thrown = x; + } + goOn = false; + } + + static void deadlock(Exception x) { + deadlock = true; + System.out.flush(); + fail(x); + System.err.flush(); + } +} diff -r d9891f85d583 -r 1fcf87dbdc3c jdk/test/java/util/logging/LogManager/Configuration/TestConfigurationLock.properties --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/jdk/test/java/util/logging/LogManager/Configuration/TestConfigurationLock.properties Sun May 17 10:38:36 2015 +0200 @@ -0,0 +1,22 @@ +######################################################################## +# Logging configuration property file for TestConfigurationLock.java # +######################################################################## + +handlers= java.util.logging.ConsoleHandler + +.level= INFO + +java.util.logging.FileHandler.pattern = %h/java%u.log +java.util.logging.FileHandler.limit = 50000 +java.util.logging.FileHandler.count = 1 +java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter + +java.util.logging.ConsoleHandler.level = INFO +java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter + +blah.level = FINE +foo.bar.l10.level = INFO +foo.bar.l100.level = INFO +foo.bar.l1000.level = INFO + +