OpenJDK / jdk / jdk10
changeset 25985:aa1e188ea8bf
8054480: Test java/util/logging/TestLoggerBundleSync.java fails: Unexpected bundle name: null
Summary: This is due to a race condition in the test where one GetRB thread can receive a stale LogRecord comming from another GetRB thread.
Reviewed-by: dholmes
author | dfuchs |
---|---|
date | Thu, 14 Aug 2014 15:18:11 +0200 |
parents | 61659e1c7433 |
children | 12bcf9a5994f |
files | jdk/test/java/util/logging/TestLoggerBundleSync.java |
diffstat | 1 files changed, 47 insertions(+), 5 deletions(-) [+] |
line wrap: on
line diff
--- a/jdk/test/java/util/logging/TestLoggerBundleSync.java Thu Aug 14 13:43:02 2014 +0200 +++ b/jdk/test/java/util/logging/TestLoggerBundleSync.java Thu Aug 14 15:18:11 2014 +0200 @@ -58,6 +58,7 @@ */ public class TestLoggerBundleSync { + static final boolean VERBOSE = false; static volatile Exception thrown = null; static volatile boolean goOn = true; @@ -65,6 +66,7 @@ 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); @@ -150,6 +152,7 @@ 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)); @@ -181,21 +184,58 @@ + " 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."); } final static class GetRB extends Thread { - final static class MyHandler extends Handler { + final class MyHandler extends Handler { volatile ResourceBundle rb; volatile String rbName; volatile int count = 0; @Override public synchronized void publish(LogRecord record) { - count++; - rb = record.getResourceBundle(); - rbName = record.getResourceBundleName(); + 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 @@ -207,6 +247,7 @@ } }; final MyHandler handler = new MyHandler(); + @Override public void run() { try { @@ -234,9 +275,10 @@ + handler.getLevel()); } final int countBefore = handler.count; + handler.reset(); ll.setLevel(Level.FINEST); ll.addHandler(handler); - ll.fine("dummy"); + ll.log(Level.FINE, "dummy {0}", this); ll.removeHandler(handler); final int countAfter = handler.count; if (countBefore == countAfter) {