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
--- a/jdk/src/share/classes/java/util/logging/LogManager.java Tue Dec 03 15:52:16 2013 -0800
+++ b/jdk/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/jdk/src/share/classes/java/util/logging/Logger.java Tue Dec 03 15:52:16 2013 -0800
+++ b/jdk/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/jdk/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/jdk/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;
+ }
+}