--- old/src/java.logging/share/classes/java/util/logging/LogManager.java 2015-04-24 19:02:54.000000000 +0200 +++ new/src/java.logging/share/classes/java/util/logging/LogManager.java 2015-04-24 19:02:53.000000000 +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.SharedSecrets; @@ -180,9 +181,12 @@ private volatile boolean readPrimordialConfiguration; // Have we initialized global (root) handlers yet? // This gets set to false in readConfiguration - private boolean initializedGlobalHandlers = true; + private volatile boolean initializeGlobalHandlersCalled = true; + private volatile boolean initializeGlobalHandlersDone = true; // True if JVM death is imminent and the exit hook has been called. - private boolean deathImminent; + private volatile boolean deathImminent; + // A concurrency lock for reset() and readConfiguration(). + private final ReentrantLock configurationLock = new ReentrantLock(); // This list contains the loggers for which some handlers have been // explicitly configured in the configuration file. @@ -263,13 +267,14 @@ // before synchronized block. Otherwise deadlocks are possible. LogManager mgr = manager; + // Note that death is imminent. + deathImminent = true; + // 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; - } + // So we're going to pretend that initializeGlobalHandlers has + // been called. + initializeGlobalHandlersCalled = true; // Do a reset to close all active handlers. reset(); @@ -954,7 +959,7 @@ try { Class clz = ClassLoader.getSystemClassLoader().loadClass(type); Handler hdl = (Handler) clz.newInstance(); - // Check if there is a property defining the + // Check if there is a property defining the // this handler's level. String levs = getProperty(type + ".level"); if (levs != null) { @@ -1314,7 +1319,12 @@ public void reset() throws SecurityException { checkPermission(); List persistent; - synchronized (this) { + + // We don't want reset() and readConfiguration() + // to run in parallel + configurationLock.lock(); + try { + props = new Properties(); // make sure we keep the loggers persistent until reset is done. // Those are the loggers for which we previously created a @@ -1324,24 +1334,30 @@ 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; + initializeGlobalHandlersCalled = true; + + 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); @@ -1351,6 +1367,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. @@ -1407,48 +1431,59 @@ */ public void readConfiguration(InputStream ins) throws IOException, SecurityException { checkPermission(); - reset(); - // Load the properties - 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); - } + // We don't want reset() and readConfiguration() to run + // in parallel. + configurationLock.lock(); - // Instantiate new configuration objects. - String names[] = parseClassNames("config"); + boolean propertiesReloaded = false; + try { + reset(); - for (String word : names) { + // Load the properties 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(); + props.load(ins); + propertiesReloaded = true; + } 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); } - } - // Set levels on any pre-existing loggers, based on the new properties. - setLevelsOnExistingLoggers(); + // 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; + // Note: Marking global handlers as not initialized must be done + // before unlocking. + if (propertiesReloaded) { + initializeGlobalHandlersCalled = initializeGlobalHandlersDone = false; } + configurationLock.unlock(); } + + invokeConfigurationListeners(); } /** @@ -1575,20 +1610,40 @@ // 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() { + if (initializeGlobalHandlersCalled && initializeGlobalHandlersDone) { + // 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 + // initializeGlobalHandlersCalled == false). + // If we are in the process of initializing global handlers we + // also need to lock & wait (this case is indicated by + // initializeGlobalHandlersDone == false). + // So if either initializeGlobalHandlersCalled or + // initializeGlobalHandlersDone are false we need to acquire the lock. + configurationLock.lock(); + try { + if (initializeGlobalHandlersCalled) return; // recursive call + // set initializeGlobalHandlersCalled first to avoid getting an + // infinite recursion when loadLoggerHandlers(...) is going to + // call addHandler(...) + initializeGlobalHandlersCalled = true; + initializeGlobalHandlersDone = false; + + if (deathImminent) { + // Aaargh... + // The VM is shutting down and our exit hook has been called. + // Avoid allocating global handlers. + return; + } + loadLoggerHandlers(rootLogger, null, "handlers"); + } finally { + initializeGlobalHandlersDone = true; + configurationLock.unlock(); } - loadLoggerHandlers(rootLogger, null, "handlers"); } static final Permission controlPermission = new LoggingPermission("control", null); @@ -1683,7 +1738,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(); --- /dev/null 2015-04-24 19:02:55.000000000 +0200 +++ new/test/java/util/logging/LogManager/Configuration/TestConfigurationLock.java 2015-04-24 19:02:54.000000000 +0200 @@ -0,0 +1,456 @@ +/* + * 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.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 + * @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(); + } +} --- /dev/null 2015-04-24 19:02:55.000000000 +0200 +++ new/test/java/util/logging/LogManager/Configuration/TestConfigurationLock.properties 2015-04-24 19:02:55.000000000 +0200 @@ -0,0 +1,64 @@ +############################################################ +# Default Logging Configuration File +# +# You can use a different file by specifying a filename +# with the java.util.logging.config.file system property. +# For example java -Djava.util.logging.config.file=myfile +############################################################ + +############################################################ +# Global properties +############################################################ + +# "handlers" specifies a comma separated list of log Handler +# classes. These handlers will be installed during VM startup. +# Note that these classes must be on the system classpath. +# By default we only configure a ConsoleHandler, which will only +# show messages at the INFO and above levels. +handlers= java.util.logging.ConsoleHandler + +# To also add the FileHandler, use the following line instead. +#handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler + +# Default global logging level. +# This specifies which kinds of events are logged across +# all loggers. For any given facility this global level +# can be overriden by a facility specific level +# Note that the ConsoleHandler also has a separate level +# setting to limit messages printed to the console. +.level= INFO + +############################################################ +# Handler specific properties. +# Describes specific configuration info for Handlers. +############################################################ + +# default file output is in user's home directory. +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 + +# Limit the message that are printed on the console to INFO and above. +java.util.logging.ConsoleHandler.level = INFO +java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter + +# Example to customize the SimpleFormatter output format +# to print one-line log message like this: +# : [] +# +# java.util.logging.SimpleFormatter.format=%4$s: %5$s [%1$tc]%n + +############################################################ +# Facility specific properties. +# Provides extra control for each logger. +############################################################ + +# For example, set the com.xyz.foo logger to only log SEVERE +# messages: +blah.level = FINE +foo.bar.l10.level = INFO +foo.bar.l100.level = INFO +foo.bar.l1000.level = INFO + +