/*
* Copyright (c) 2013, 2016, 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.
* @modules java.logging
* java.management
* @run main/othervm TestLoggerBundleSync
* @author danielfuchs
*/
public class TestLoggerBundleSync {
static final boolean VERBOSE = false;
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 ignoreLogCount = new AtomicLong(0);
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();
long sIgnoreLogCount = ignoreLogCount.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 " + (ignoreLogCount.get() - sIgnoreLogCount)
+ " log messages emitted by other GetRB threads were ignored"
+ " to ensure MT test consistency,");
System.out.println("\t ThreadMXBean.findDeadlockedThreads called "
+ (checkCount.get() -sCheckCount) + " times by 1 Thread.");
}
static final class GetRB extends Thread {
final class MyHandler extends Handler {
volatile ResourceBundle rb;
volatile String rbName;
volatile int count = 0;
@Override
public synchronized void publish(LogRecord record) {
Object[] params = record.getParameters();
// Each GetRB thread has its own handler, but since they
// log into the same logger, each handler may receive
// messages emitted by other threads.
// This means that GetRB#2.handler may receive a message
// emitted by GetRB#1 at a time where the resource bundle
// was still null.
// To avoid falling into this trap, the GetRB thread passes
// 'this' as argument to the messages it logs - which does
// allow us here to ignore messages that where not emitted
// by our own GetRB.this thread...
if (params.length == 1) {
if (params[0] == GetRB.this) {
// The message was emitted by our thread.
count++;
rb = record.getResourceBundle();
rbName = record.getResourceBundleName();
} else {
// The message was emitted by another thread: just
// ignore it, as it may have been emitted at a time
// where the resource bundle was still null, and
// processing it may overwrite the 'rb' and 'rbName'
// recorded from the message emitted by our own thread.
if (VERBOSE) {
System.out.println("Ignoring message logged by " + params[0]);
}
ignoreLogCount.incrementAndGet();
}
} else {
ignoreLogCount.incrementAndGet();
System.err.println("Unexpected message received");
}
}
void reset() {
rbName = null;
rb = null;
}
@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;
if (handler.getLevel() != Level.FINEST) {
throw new RuntimeException("Handler level is not finest: "
+ handler.getLevel());
}
final int countBefore = handler.count;
handler.reset();
ll.setLevel(Level.FINEST);
ll.addHandler(handler);
ll.log(Level.FINE, "dummy {0}", this);
ll.removeHandler(handler);
final int countAfter = handler.count;
if (countBefore == countAfter) {
throw new RuntimeException("Handler not called for "
+ ll.getName() + "("+ countAfter +")");
}
hrb = handler.rb;
hrbName = handler.rbName;
if (name != null) {
// if name is not null, then it implies that it
// won't change, since setResourceBundle() cannot
// replace a non null name.
// Since we never set the resource bundle on 'll',
// then ll must inherit its resource bundle [name]
// from l - and therefor we should find it in
// handler.rb/handler.rbName
if (!name.equals(hrbName)) {
throw new RuntimeException("Unexpected bundle name: "
+hrbName);
}
// here we know that hrbName is not null so hrb
// should not be null either.
if (!name.equals(hrb.getBaseBundleName())) {
throw new RuntimeException("Unexpected bundle name: "
+hrb.getBaseBundleName());
}
}
// Make sure to refer to 'l' explicitly in order to
// prevent eager garbage collecting before the end of
// the test (JDK-8030192)
if (!ll.getName().startsWith(l.getName())) {
throw new RuntimeException("Logger " + ll.getName()
+ "does not start with expected prefix "
+ l.getName());
}
getRBcount.incrementAndGet();
if (!goOn) break;
Thread.sleep(1);
}
}
} catch (Exception x) {
fail(x);
}
}
}
static final class SetRB extends Thread {
final Class<? extends ResourceBundle> type;
static final ExecutorService executor = Executors.newSingleThreadExecutor();
static final 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);
}
}
}
static final class SetRBName extends Thread {
int nexti = 0;
final Class<? extends ResourceBundle> type;
static final ExecutorService executor = Executors.newSingleThreadExecutor();
static final 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);
}
}
}
static final 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;
}
}