OpenJDK / jdk8u / jdk8u / jdk
changeset 8929:9f624e115c6b
8029281: Synchronization issues in Logger and LogManager
Summary: Fixes several race conditions in logging which have been at the root cause of intermittent test failures.
Reviewed-by: mchung, plevart
author | dfuchs |
---|---|
date | Wed, 04 Dec 2013 01:58:37 +0100 |
parents | accd6ffd4b3f |
children | e1bc55ddf1ad |
files | src/share/classes/java/util/logging/LogManager.java src/share/classes/java/util/logging/Logger.java test/java/util/logging/TestLogConfigurationDeadLock.java test/java/util/logging/TestLoggerBundleSync.java |
diffstat | 4 files changed, 932 insertions(+), 69 deletions(-) [+] |
line wrap: on
line diff
--- a/src/share/classes/java/util/logging/LogManager.java Tue Dec 03 15:52:16 2013 -0800 +++ b/src/share/classes/java/util/logging/LogManager.java Wed Dec 04 01:58:37 2013 +0100 @@ -146,7 +146,14 @@ // The global LogManager object private static final LogManager manager; - private Properties props = new Properties(); + // 'props' is assigned within a lock but accessed without it. + // Declaring it volatile makes sure that another thread will not + // be able to see a partially constructed 'props' object. + // (seeing a partially constructed 'props' object can result in + // NPE being thrown in Hashtable.get(), because it leaves the door + // open for props.getProperties() to be called before the construcor + // of Hashtable is actually completed). + private volatile Properties props = new Properties(); private final static Level defaultLevel = Level.INFO; // The map of the registered listeners. The map value is the registration @@ -670,7 +677,7 @@ if (logger == null) { // Hashtable holds stale weak reference // to a logger which has been GC-ed. - removeLogger(name); + ref.dispose(); } return logger; } @@ -756,7 +763,7 @@ // It's possible that the Logger was GC'ed after a // drainLoggerRefQueueBounded() call above so allow // a new one to be registered. - removeLogger(name); + ref.dispose(); } else { // We already have a registered logger with the given name. return false; @@ -808,10 +815,8 @@ return true; } - // note: all calls to removeLogger are synchronized on LogManager's - // intrinsic lock - void removeLogger(String name) { - namedLoggers.remove(name); + synchronized void removeLoggerRef(String name, LoggerWeakRef ref) { + namedLoggers.remove(name, ref); } synchronized Enumeration<String> getLoggerNames() { @@ -993,6 +998,7 @@ private String name; // for namedLoggers cleanup private LogNode node; // for loggerRef cleanup private WeakReference<Logger> parentRef; // for kids cleanup + private boolean disposed = false; // avoid calling dispose twice LoggerWeakRef(Logger logger) { super(logger, loggerRefQueue); @@ -1002,14 +1008,45 @@ // dispose of this LoggerWeakRef object void dispose() { - if (node != null) { - // if we have a LogNode, then we were a named Logger - // so clear namedLoggers weak ref to us - node.context.removeLogger(name); - name = null; // clear our ref to the Logger's name + // Avoid calling dispose twice. When a Logger is gc'ed, its + // LoggerWeakRef will be enqueued. + // However, a new logger of the same name may be added (or looked + // up) before the queue is drained. When that happens, dispose() + // will be called by addLocalLogger() or findLogger(). + // Later when the queue is drained, dispose() will be called again + // for the same LoggerWeakRef. Marking LoggerWeakRef as disposed + // avoids processing the data twice (even though the code should + // now be reentrant). + synchronized(this) { + // Note to maintainers: + // Be careful not to call any method that tries to acquire + // another lock from within this block - as this would surely + // lead to deadlocks, given that dispose() can be called by + // multiple threads, and from within different synchronized + // methods/blocks. + if (disposed) return; + disposed = true; + } - node.loggerRef = null; // clear LogNode's weak ref to us - node = null; // clear our ref to LogNode + final LogNode n = node; + if (n != null) { + // n.loggerRef can only be safely modified from within + // a lock on LoggerContext. removeLoggerRef is already + // synchronized on LoggerContext so calling + // n.context.removeLoggerRef from within this lock is safe. + synchronized (n.context) { + // if we have a LogNode, then we were a named Logger + // so clear namedLoggers weak ref to us + n.context.removeLoggerRef(name, this); + name = null; // clear our ref to the Logger's name + + // LogNode may have been reused - so only clear + // LogNode.loggerRef if LogNode.loggerRef == this + if (n.loggerRef == this) { + n.loggerRef = null; // clear LogNode's weak ref to us + } + node = null; // clear our ref to LogNode + } } if (parentRef != null) { @@ -1062,7 +1099,7 @@ // - maximum: 10.9 ms // private final static int MAX_ITERATIONS = 400; - final synchronized void drainLoggerRefQueueBounded() { + final void drainLoggerRefQueueBounded() { for (int i = 0; i < MAX_ITERATIONS; i++) { if (loggerRefQueue == null) { // haven't finished loading LogManager yet
--- a/src/share/classes/java/util/logging/Logger.java Tue Dec 03 15:52:16 2013 -0800 +++ b/src/share/classes/java/util/logging/Logger.java Wed Dec 04 01:58:37 2013 +0100 @@ -218,12 +218,46 @@ public class Logger { private static final Handler emptyHandlers[] = new Handler[0]; private static final int offValue = Level.OFF.intValue(); - private LogManager manager; + + static final String SYSTEM_LOGGER_RB_NAME = "sun.util.logging.resources.logging"; + + // This class is immutable and it is important that it remains so. + private static final class LoggerBundle { + final String resourceBundleName; // Base name of the bundle. + final ResourceBundle userBundle; // Bundle set through setResourceBundle. + private LoggerBundle(String resourceBundleName, ResourceBundle bundle) { + this.resourceBundleName = resourceBundleName; + this.userBundle = bundle; + } + boolean isSystemBundle() { + return SYSTEM_LOGGER_RB_NAME.equals(resourceBundleName); + } + static LoggerBundle get(String name, ResourceBundle bundle) { + if (name == null && bundle == null) { + return NO_RESOURCE_BUNDLE; + } else if (SYSTEM_LOGGER_RB_NAME.equals(name) && bundle == null) { + return SYSTEM_BUNDLE; + } else { + return new LoggerBundle(name, bundle); + } + } + } + + // This instance will be shared by all loggers created by the system + // code + private static final LoggerBundle SYSTEM_BUNDLE = + new LoggerBundle(SYSTEM_LOGGER_RB_NAME, null); + + // This instance indicates that no resource bundle has been specified yet, + // and it will be shared by all loggers which have no resource bundle. + private static final LoggerBundle NO_RESOURCE_BUNDLE = + new LoggerBundle(null, null); + + private volatile LogManager manager; private String name; private final CopyOnWriteArrayList<Handler> handlers = new CopyOnWriteArrayList<>(); - private String resourceBundleName; // Base name of the bundle. - private ResourceBundle userBundle; // Bundle set through setResourceBundle. + private volatile LoggerBundle loggerBundle = NO_RESOURCE_BUNDLE; private volatile boolean useParentHandlers = true; private volatile Filter filter; private boolean anonymous; @@ -641,7 +675,7 @@ * @return localization bundle name (may be {@code null}) */ public String getResourceBundleName() { - return resourceBundleName; + return loggerBundle.resourceBundleName; } /** @@ -710,8 +744,9 @@ // resource bundle and then call "void log(LogRecord)". private void doLog(LogRecord lr) { lr.setLoggerName(name); - final ResourceBundle bundle = getEffectiveResourceBundle(); - final String ebname = getEffectiveResourceBundleName(); + final LoggerBundle lb = getEffectiveLoggerBundle(); + final ResourceBundle bundle = lb.userBundle; + final String ebname = lb.resourceBundleName; if (ebname != null && bundle != null) { lr.setResourceBundleName(ebname); lr.setResourceBundle(bundle); @@ -1757,8 +1792,6 @@ return useParentHandlers; } - static final String SYSTEM_LOGGER_RB_NAME = "sun.util.logging.resources.logging"; - private static ResourceBundle findSystemResourceBundle(final Locale locale) { // the resource bundle is in a restricted package return AccessController.doPrivileged(new PrivilegedAction<ResourceBundle>() { @@ -1801,11 +1834,12 @@ } Locale currentLocale = Locale.getDefault(); + final LoggerBundle lb = loggerBundle; // Normally we should hit on our simple one entry cache. - if (userBundle != null && - name.equals(resourceBundleName)) { - return userBundle; + if (lb.userBundle != null && + name.equals(lb.resourceBundleName)) { + return lb.userBundle; } else if (catalog != null && currentLocale.equals(catalogLocale) && name.equals(catalogName)) { return catalog; @@ -1864,17 +1898,18 @@ // Synchronized to prevent races in setting the fields. private synchronized void setupResourceInfo(String name, Class<?> callersClass) { - if (resourceBundleName != null) { + final LoggerBundle lb = loggerBundle; + if (lb.resourceBundleName != null) { // this Logger already has a ResourceBundle - if (resourceBundleName.equals(name)) { + if (lb.resourceBundleName.equals(name)) { // the names match so there is nothing more to do return; } // cannot change ResourceBundles once they are set throw new IllegalArgumentException( - resourceBundleName + " != " + name); + lb.resourceBundleName + " != " + name); } if (name == null) { @@ -1890,7 +1925,10 @@ throw new MissingResourceException("Can't find " + name + " bundle", name, ""); } - resourceBundleName = name; + + // if lb.userBundle is not null we won't reach this line. + assert lb.userBundle == null; + loggerBundle = LoggerBundle.get(name, null); } /** @@ -1920,16 +1958,16 @@ } synchronized (this) { - final boolean canReplaceResourceBundle = resourceBundleName == null - || resourceBundleName.equals(baseName); + LoggerBundle lb = loggerBundle; + final boolean canReplaceResourceBundle = lb.resourceBundleName == null + || lb.resourceBundleName.equals(baseName); if (!canReplaceResourceBundle) { throw new IllegalArgumentException("can't replace resource bundle"); } - userBundle = bundle; - resourceBundleName = baseName; + loggerBundle = LoggerBundle.get(baseName, bundle); } } @@ -2082,45 +2120,44 @@ // Private method to get the potentially inherited - // resource bundle name for this Logger. - // May return null - private String getEffectiveResourceBundleName() { - Logger target = this; + // resource bundle and resource bundle name for this Logger. + // This method never returns null. + private LoggerBundle getEffectiveLoggerBundle() { + final LoggerBundle lb = loggerBundle; + if (lb.isSystemBundle()) { + return SYSTEM_BUNDLE; + } + + // first take care of this logger + final ResourceBundle b = getResourceBundle(); + if (b != null && b == lb.userBundle) { + return lb; + } else if (b != null) { + // either lb.userBundle is null or getResourceBundle() is + // overriden + final String rbName = getResourceBundleName(); + return LoggerBundle.get(rbName, b); + } + + // no resource bundle was specified on this logger, look up the + // parent stack. + Logger target = this.parent; while (target != null) { - String rbn = target.getResourceBundleName(); - if (rbn != null) { - return rbn; + final LoggerBundle trb = target.loggerBundle; + if (trb.isSystemBundle()) { + return SYSTEM_BUNDLE; + } + if (trb.userBundle != null) { + return trb; + } + final String rbName = target.getResourceBundleName(); + if (rbName != null) { + return LoggerBundle.get(rbName, + findResourceBundle(rbName, true)); } target = target.getParent(); } - return null; - } - - - private ResourceBundle getEffectiveResourceBundle() { - Logger target = this; - if (SYSTEM_LOGGER_RB_NAME.equals(resourceBundleName)) return null; - ResourceBundle localRB = getResourceBundle(); - if (localRB != null) { - return localRB; - } - - while (target != null) { - final ResourceBundle rb = target.userBundle; - if (rb != null) { - return rb; - } - final String rbn = target.getResourceBundleName(); - if (rbn != null) { - if (!SYSTEM_LOGGER_RB_NAME.equals(rbn)) { - return findResourceBundle(rbn, true); - } else { - return null; - } - } - target = target.getParent(); - } - return null; + return NO_RESOURCE_BUNDLE; } }
--- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/test/java/util/logging/TestLogConfigurationDeadLock.java Wed Dec 04 01:58:37 2013 +0100 @@ -0,0 +1,255 @@ +/* + * 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.lang.management.ManagementFactory; +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.LogManager; +import java.util.logging.Logger; + + +/** + * @test + * @bug 8029281 8027670 + * @summary Synchronization issues in Logger and LogManager. This test + * focusses more particularly on potential deadlock in + * drainLoggerRefQueueBounded / readConfiguration + * @run main/othervm TestLogConfigurationDeadLock + * @author danielfuchs + */ +// This test is a best effort to try & detect issues. The test itself will run +// for 8secs. This is usually 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/TestLogConfigurationDeadLock.java ; \ +// do echo Running test again ; done +// and let it run for a few hours... +// +public class TestLogConfigurationDeadLock { + + static volatile Exception thrown = null; + static volatile boolean goOn = true; + + static final int READERS = 2; + static final int LOGGERS = 2; + static final long TIME = 4 * 1000; // 4 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 readCount = new AtomicLong(0); + static final AtomicLong checkCount = new AtomicLong(0); + + /** + * This test will run both with and without a security manager. + * + * The test starts a number of threads that will call + * LogManager.readConfiguration() concurrently (ReadConf), then starts + * a number of threads that will create new loggers concurrently + * (AddLogger), and then 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 + */ + public static void main(String[] args) throws Exception { + + // 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 sReadCount = readCount.get(); + long sCheckCount = checkCount.get(); + List<Thread> threads = new ArrayList<>(); + for (int i = 0; i<READERS; i++) { + threads.add(new ReadConf()); + } + for (int i = 0; i<LOGGERS; i++) { + threads.add(new AddLogger()); + } + threads.add(new DeadlockDetector()); + threads.add(0, new Stopper(TIME)); + for (Thread t : threads) { + t.start(); + } + for (Thread t : threads) { + try { + t.join(); + } catch (Exception x) { + fail(x); + } + } + if (thrown != null) { + throw thrown; + } + System.out.println("Passed: " + (nextLogger.get() - sNextLogger) + + " loggers created by " + LOGGERS + " Thread(s),"); + System.out.println("\t LogManager.readConfiguration() called " + + (readCount.get() - sReadCount) + " times by " + READERS + + " Thread(s)."); + System.out.println("\t ThreadMXBean.findDeadlockedThreads called " + + (checkCount.get() -sCheckCount) + " times by 1 Thread."); + + } + + + final static class ReadConf extends Thread { + @Override + public void run() { + while (goOn) { + try { + LogManager.getLogManager().readConfiguration(); + readCount.incrementAndGet(); + Thread.sleep(1); + } catch (Exception x) { + fail(x); + } + } + } + } + + final static class AddLogger extends Thread { + @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++) { + l = Logger.getLogger("foo.bar.l"+nextLogger.incrementAndGet()); + l.fine("I'm fine"); + if (!goOn) break; + Thread.sleep(1); + } + } + } catch (InterruptedException | RuntimeException x ) { + fail(x); + } + } + } + + final static class DeadlockDetector extends Thread { + + @Override + public void run() { + 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) { + ThreadInfo[] infos = ManagementFactory.getThreadMXBean().getThreadInfo(ids); + System.err.println("Found "+ids.length+" deadlocked threads: "); + for (ThreadInfo inf : infos) { + System.err.println(inf.toString()); + } + throw new RuntimeException("Found "+ids.length+" deadlocked threads"); + } + Thread.sleep(100); + } catch(InterruptedException | RuntimeException x) { + fail(x); + } + } + } + + } + + static final class Stopper extends Thread { + long start; + long time; + + Stopper(long time) { + start = System.currentTimeMillis(); + this.time = time; + } + + @Override + public void run() { + try { + long rest, previous; + previous = time; + while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) { + if (previous == time || previous - rest >= STEP) { + Logger.getLogger("remaining").info(String.valueOf(rest)+"ms remaining..."); + previous = rest == time ? rest -1 : rest; + System.gc(); + } + if (goOn == false) break; + Thread.sleep(Math.min(rest, 100)); + } + System.out.println(System.currentTimeMillis() - start + + " ms elapsed ("+time+ " requested)"); + goOn = false; + } catch(InterruptedException | RuntimeException x) { + fail(x); + } + } + + } + + static void fail(Exception x) { + x.printStackTrace(); + if (thrown == null) { + thrown = x; + } + goOn = false; + } +}
--- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/test/java/util/logging/TestLoggerBundleSync.java Wed Dec 04 01:58:37 2013 +0100 @@ -0,0 +1,534 @@ +/* + * 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.lang.management.ManagementFactory; +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.ListResourceBundle; +import java.util.Objects; +import java.util.ResourceBundle; +import java.util.concurrent.Callable; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.FutureTask; +import java.util.concurrent.atomic.AtomicLong; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; + +/** + * @test + * @bug 8029281 8028763 + * @summary Attempts to detect synchronization issues with getResourceBundle() + * and getResourceBundleName(). It might also detect issues in the way + * that the logger tree is cleaned up after a logger has been garbage + * collected. This test helped find the root cause of 8029092, so if + * this test fails one might also expect failures in + * java/util/logging/Logger/logrb/TestLogrbResourceBundle.java and + * java/util/logging/Logger/setResourceBundle/TestSetResourceBundle.java. + * Note that this is a best effort test. Running it in a loop to + * reproduce intermittent issues can be a good idea. + * @run main/othervm TestLoggerBundleSync + * @author danielfuchs + */ +public class TestLoggerBundleSync { + + static volatile Exception thrown = null; + static volatile boolean goOn = true; + + static final int READERS = 3; + static final long TIME = 4 * 1000; // 4 sec. + static final long STEP = 1 * 1000; // message every 1 sec. + static final int LCOUNT = 50; // change bundle 50 times... + static final AtomicLong setRBcount = new AtomicLong(0); + static final AtomicLong setRBNameCount = new AtomicLong(0); + static final AtomicLong getRBcount = new AtomicLong(0); + static final AtomicLong checkCount = new AtomicLong(0); + static final AtomicLong nextLong = new AtomicLong(0); + + public static class MyBundle extends ListResourceBundle { + @Override + protected Object[][] getContents() { + return new Object[][] { + {"dummy", "foo"} + }; + } + } + + public static final class MyBundle1 extends MyBundle { }; + public static final class MyBundle2 extends MyBundle { }; + public static final class MyBundle3 extends MyBundle { }; + + + public static final class LoggerRB { + public final String resourceBundleName; + public final ResourceBundle userBundle; + public LoggerRB(String name, ResourceBundle bundle) { + resourceBundleName = name; + userBundle = bundle; + } + } + + static final List<Class<? extends ResourceBundle>> classes = new ArrayList<>(); + static { + classes.add(MyBundle1.class); + classes.add(MyBundle2.class); + classes.add(MyBundle3.class); + } + + + /** + * This test will run both with and without a security manager. + * + * The test starts a number of threads that will attempt to concurrently + * set resource bundles on Logger, and verifies the consistency of the + * obtained results. + * + * This is a best effort test. + * + * @param args the command line arguments + */ + public static void main(String[] args) throws Exception { + + try { + // 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(); + } finally { + SetRB.executor.shutdownNow(); + SetRBName.executor.shutdownNow(); + } + } + + /** + * Starts all threads, wait 15secs, 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 sGetRBCount = getRBcount.get(); + long sSetRBCount = setRBcount.get(); + long sSetRBNameCount = setRBNameCount.get(); + long sCheckCount = checkCount.get(); + long sNextLong = nextLong.get(); + List<Thread> threads = new ArrayList<>(); + for (Class<? extends ResourceBundle> type : classes) { + threads.add(new SetRB(type)); + threads.add(new SetRBName(type)); + } + for (int i =0 ; i < READERS ; i++) { + threads.add(new GetRB()); + } + threads.add(new DeadlockDetector()); + threads.add(0, new Stopper(TIME)); + for (Thread t : threads) { + t.start(); + } + for (Thread t : threads) { + try { + t.join(); + } catch (Exception x) { + fail(x); + } + } + if (thrown != null) { + throw thrown; + } + System.out.println("Passed: " + (nextLong.longValue() - sNextLong) + + " unique loggers created"); + System.out.println("\t " +(getRBcount.get() - sGetRBCount) + + " loggers tested by " + READERS + " Thread(s),"); + System.out.println("\t " + (setRBcount.get() - sSetRBCount) + + " resource bundles set by " + classes.size() + " Thread(s),"); + System.out.println("\t " + (setRBNameCount.get() - sSetRBNameCount) + + " resource bundle names set by " + classes.size() + " Thread(s),"); + System.out.println("\t ThreadMXBean.findDeadlockedThreads called " + + (checkCount.get() -sCheckCount) + " times by 1 Thread."); + + } + + final static class GetRB extends Thread { + final static class MyHandler extends Handler { + volatile ResourceBundle rb; + volatile String rbName; + @Override + public synchronized void publish(LogRecord record) { + rb = record.getResourceBundle(); + rbName = record.getResourceBundleName(); + } + + @Override + public void flush() { + } + + @Override + public void close() throws SecurityException { + } + }; + final MyHandler handler = new MyHandler(); + @Override + public void run() { + try { + handler.setLevel(Level.FINEST); + while (goOn) { + Logger l; + Logger foo = Logger.getLogger("foo"); + Logger bar = Logger.getLogger("foo.bar"); + for (long i=0; i < nextLong.longValue() + 100 ; i++) { + if (!goOn) break; + l = Logger.getLogger("foo.bar.l"+i); + final ResourceBundle b = l.getResourceBundle(); + final String name = l.getResourceBundleName(); + if (b != null) { + if (!name.equals(b.getBaseBundleName())) { + throw new RuntimeException("Unexpected bundle name: " + +b.getBaseBundleName()); + } + } + Logger ll = Logger.getLogger(l.getName()+".bie.bye"); + ResourceBundle hrb; + String hrbName; + ll.setLevel(Level.FINEST); + ll.addHandler(handler); + ll.fine("dummy"); + ll.removeHandler(handler); + hrb = handler.rb; + hrbName = handler.rbName; + if (name != null) { + if (!name.equals(hrbName)) { + throw new RuntimeException("Unexpected bundle name: " + +hrb.getBaseBundleName()); + } + if (!name.equals(hrb.getBaseBundleName())) { + throw new RuntimeException("Unexpected bundle name: " + +hrb.getBaseBundleName()); + } + } + + getRBcount.incrementAndGet(); + if (!goOn) break; + Thread.sleep(1); + } + } + } catch (Exception x) { + fail(x); + } + } + } + + final static class SetRB extends Thread { + final Class<? extends ResourceBundle> type; + final static ExecutorService executor = Executors.newSingleThreadExecutor(); + final static class CheckRBTask implements Callable<Exception> { + final Logger logger; + volatile String rbName; + volatile ResourceBundle rb; + + public CheckRBTask(Logger logger) { + this.logger = logger; + } + + @Override + public Exception call() throws Exception { + try { + final String name = logger.getResourceBundleName(); + if (!Objects.equals(name, rbName)) { + throw new RuntimeException("Unexpected rbname for " + + logger.getName() + ": " + name); + } + final ResourceBundle b = logger.getResourceBundle(); + if (b != rb) { + throw new RuntimeException("Unexpected rb for " + + logger.getName() + ": " + b); + } + } catch(Exception x) { + return x; + } + return null; + } + + public void check() throws Exception { + final FutureTask<Exception> futureTask = new FutureTask<>(this); + executor.submit(futureTask); + Exception x = futureTask.get(); + if ( x != null) { + throw new RuntimeException("Check failed: "+x,x); + } + } + } + SetRB(Class<? extends ResourceBundle> type) { + super("SetRB["+type.getSimpleName()+"]"); + this.type = type; + } + @Override + public void run() { + try { + while (goOn) { + Logger l; + Logger foo = Logger.getLogger("foo"); + Logger bar = Logger.getLogger("foo.bar"); + l = Logger.getLogger("foo.bar.l"+nextLong.incrementAndGet()); + final CheckRBTask checkTask = new CheckRBTask(l); + checkTask.check(); + + for (int i=0; i < LCOUNT ; i++) { + if (!goOn) break; + + ResourceBundle b = ResourceBundle.getBundle(type.getName()); + try { + l.setResourceBundle(b); + checkTask.rb = b; + checkTask.rbName = type.getName(); + checkTask.check(); + if (!goOn) break; + + String name = l.getResourceBundleName(); + ResourceBundle bb = l.getResourceBundle(); + if (!type.getName().equals(name)) { + throw new RuntimeException(this.getName() + + ": Unexpected name: "+name); + } + if (!b.getBaseBundleName().equals(name)) { + throw new RuntimeException(this.getName() + + ": Unexpected base name: " + + b.getBaseBundleName()); + } + if (b != bb) { + throw new RuntimeException(this.getName() + + ": Unexpected bundle: "+bb); + } + setRBcount.incrementAndGet(); + } catch (IllegalArgumentException x) { + final String name = l.getResourceBundleName(); + if (!name.startsWith(MyBundle.class.getName())) { + throw new RuntimeException(this.getName() + + ": Unexpected name: "+name, x); + } else if (type.getName().equals(name)) { + throw new RuntimeException(this.getName() + + ": Unexpected exception for "+name, x); + } + throw x; + } + l.fine("I'm fine"); + if (!goOn) break; + Thread.sleep(1); + } + } + } catch (Exception x) { + fail(x); + } + } + } + + final static class SetRBName extends Thread { + int nexti = 0; + final Class<? extends ResourceBundle> type; + final static ExecutorService executor = Executors.newSingleThreadExecutor(); + final static class CheckRBNameTask implements Callable<Exception> { + final Logger logger; + volatile String rbName; + + public CheckRBNameTask(Logger logger) { + this.logger = logger; + } + + @Override + public Exception call() throws Exception { + try { + final String name = logger.getResourceBundleName(); + if (!Objects.equals(name, rbName)) { + throw new RuntimeException("Unexpected rbname for " + + logger.getName() + ": " + name); + } + final ResourceBundle b = logger.getResourceBundle(); + if (!Objects.equals(b == null ? null : b.getBaseBundleName(), rbName)) { + throw new RuntimeException("Unexpected base name for " + + logger.getName() + ": " + b.getBaseBundleName()); + } + } catch(Exception x) { + return x; + } + return null; + } + + public void check() throws Exception { + final FutureTask<Exception> futureTask = new FutureTask<>(this); + executor.submit(futureTask); + Exception x = futureTask.get(); + if ( x != null) { + throw new RuntimeException("Check failed: "+x,x); + } + } + + } + SetRBName(Class<? extends ResourceBundle> type) { + super("SetRB["+type.getSimpleName()+"]"); + this.type = type; + } + @Override + public void run() { + try { + while (goOn) { + Logger foo = Logger.getLogger("foo"); + Logger bar = Logger.getLogger("foo.bar"); + Logger l = Logger.getLogger("foo.bar.l"+nextLong.incrementAndGet()); + final CheckRBNameTask checkTask = new CheckRBNameTask(l); + checkTask.check(); + + for (int i=0; i < LCOUNT ; i++) { + if (!goOn) break; + + try { + Logger l2 = Logger.getLogger(l.getName(), type.getName()); + if (l2 != l) { + System.err.println("**** ERROR WITH "+l.getName()); + throw new RuntimeException("l2 != l [" + + l2 + "(" + l2.getName() + ") != " + + l + "(" + l.getName() + ")]"); + } + checkTask.rbName = type.getName(); + checkTask.check(); + if (!goOn) break; + + String name = l.getResourceBundleName(); + ResourceBundle bb = l.getResourceBundle(); + if (!type.getName().equals(name)) { + throw new RuntimeException(this.getName() + + ": Unexpected name: "+name); + } + if (!bb.getBaseBundleName().equals(name)) { + throw new RuntimeException(this.getName() + + ": Unexpected base name: " + + bb.getBaseBundleName()); + } + setRBNameCount.incrementAndGet(); + } catch (IllegalArgumentException x) { + final String name = l.getResourceBundleName(); + if (!name.startsWith(MyBundle.class.getName())) { + throw new RuntimeException(this.getName() + + ": Unexpected name: "+name, x); + } else if (type.getName().equals(name)) { + throw new RuntimeException(this.getName() + + ": Unexpected exception for "+name, x); + } + throw x; + } + l.fine("I'm fine"); + if (!goOn) break; + Thread.sleep(1); + } + } + } catch (Exception x) { + fail(x); + } + } + } + + final static class DeadlockDetector extends Thread { + + @Override + public void run() { + 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) { + ThreadInfo[] infos = ManagementFactory.getThreadMXBean().getThreadInfo(ids); + System.err.println("Found "+ids.length+" deadlocked threads: "); + for (ThreadInfo inf : infos) { + System.err.println(inf.toString()); + } + throw new RuntimeException("Found "+ids.length+" deadlocked threads"); + } + Thread.sleep(100); + } catch(InterruptedException | RuntimeException x) { + fail(x); + } + } + } + + } + + static final class Stopper extends Thread { + long start; + long time; + + Stopper(long time) { + start = System.currentTimeMillis(); + this.time = time; + } + + @Override + public void run() { + try { + long rest, previous; + previous = time; + while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) { + if (previous == time || previous - rest >= STEP) { + Logger.getLogger("remaining").info(String.valueOf(rest)+"ms remaining..."); + previous = rest == time ? rest -1 : rest; + System.gc(); + } + if (goOn == false) break; + Thread.sleep(Math.min(rest, 100)); + } + System.out.println(System.currentTimeMillis() - start + + " ms elapsed ("+time+ " requested)"); + goOn = false; + } catch(InterruptedException | RuntimeException x) { + fail(x); + } + } + + } + + static void fail(Exception x) { + x.printStackTrace(); + if (thrown == null) { + thrown = x; + } + goOn = false; + } +}