util/logging/TestLoggerBundleSync.java

/*
 * 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 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;
    }
}