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

src/share/classes/java/util/logging/LogManager.java

@@ -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
-
-                node.loggerRef = null;  // clear LogNode's weak ref to us
-                node = null;            // clear our ref to LogNode
+            // 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;
+            }
+
+            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

src/share/classes/java/util/logging/Logger.java

@@ -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;
-        while (target != null) {
-            String rbn = target.getResourceBundleName();
-            if (rbn != null) {
-                return rbn;
-            }
-            target = target.getParent();
+    // 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;
         }
-        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;
+        // 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) {
-            final ResourceBundle rb = target.userBundle;
-            if (rb != null) {
-                return rb;
+            final LoggerBundle trb = target.loggerBundle;
+            if (trb.isSystemBundle()) {
+                return SYSTEM_BUNDLE;
             }
-            final String rbn = target.getResourceBundleName();
-            if (rbn != null) {
-                if (!SYSTEM_LOGGER_RB_NAME.equals(rbn)) {
-                    return findResourceBundle(rbn, true);
-                } else {
-                    return null;
-                }
+            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;
+        return NO_RESOURCE_BUNDLE;
     }
 
 }

test/java/util/logging/TestLogConfigurationDeadLock.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.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;
+    }
+}