8029281: Synchronization issues in Logger and LogManager
Fixes several race conditions in logging which have been at the root cause of intermittent test failures. Reviewed-by: mchung, plevart
This commit is contained in:
parent
23803430bb
commit
2c97b5c5cb
@ -146,7 +146,14 @@ public class LogManager {
|
||||
// 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 @@ public class LogManager {
|
||||
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 @@ public class LogManager {
|
||||
// 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 @@ public class LogManager {
|
||||
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 @@ public class LogManager {
|
||||
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 @@ public class LogManager {
|
||||
|
||||
// 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 @@ public class LogManager {
|
||||
// - 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
|
||||
|
@ -218,12 +218,46 @@ import sun.reflect.Reflection;
|
||||
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 @@ public class Logger {
|
||||
* @return localization bundle name (may be {@code null})
|
||||
*/
|
||||
public String getResourceBundleName() {
|
||||
return resourceBundleName;
|
||||
return loggerBundle.resourceBundleName;
|
||||
}
|
||||
|
||||
/**
|
||||
@ -710,8 +744,9 @@ public class Logger {
|
||||
// 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 @@ public class Logger {
|
||||
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 @@ public class Logger {
|
||||
}
|
||||
|
||||
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 @@ public class Logger {
|
||||
// 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 @@ public class Logger {
|
||||
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 @@ public class Logger {
|
||||
}
|
||||
|
||||
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 @@ public class Logger {
|
||||
|
||||
|
||||
// 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;
|
||||
}
|
||||
|
||||
}
|
||||
|
255
jdk/test/java/util/logging/TestLogConfigurationDeadLock.java
Normal file
255
jdk/test/java/util/logging/TestLogConfigurationDeadLock.java
Normal file
@ -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;
|
||||
}
|
||||
}
|
534
jdk/test/java/util/logging/TestLoggerBundleSync.java
Normal file
534
jdk/test/java/util/logging/TestLoggerBundleSync.java
Normal file
@ -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;
|
||||
}
|
||||
}
|
Loading…
Reference in New Issue
Block a user