1 /*
   2  * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved.
   3  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
   4  *
   5  * This code is free software; you can redistribute it and/or modify it
   6  * under the terms of the GNU General Public License version 2 only, as
   7  * published by the Free Software Foundation.
   8  *
   9  * This code is distributed in the hope that it will be useful, but WITHOUT
  10  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  11  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  12  * version 2 for more details (a copy is included in the LICENSE file that
  13  * accompanied this code).
  14  *
  15  * You should have received a copy of the GNU General Public License version
  16  * 2 along with this work; if not, write to the Free Software Foundation,
  17  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  18  *
  19  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  20  * or visit www.oracle.com if you need additional information or have any
  21  * questions.
  22  */
  23 import java.io.File;
  24 import java.io.PrintStream;
  25 import java.lang.management.ManagementFactory;
  26 import java.lang.management.ThreadInfo;
  27 import java.security.Permission;
  28 import java.security.Policy;
  29 import java.security.ProtectionDomain;
  30 import java.util.ArrayList;
  31 import java.util.Collections;
  32 import java.util.HashSet;
  33 import java.util.List;
  34 import java.util.Random;
  35 import java.util.Set;
  36 import java.util.concurrent.atomic.AtomicLong;
  37 import java.util.logging.Level;
  38 import java.util.logging.LogManager;
  39 import java.util.logging.Logger;
  40 
  41 
  42 /**
  43  * @test
  44  * @bug 8027670 8029281
  45  * @summary Deadlock in drainLoggerRefQueueBounded / readConfiguration
  46  *          caused by synchronization issues in Logger and LogManager.
  47  * @run main/othervm TestLogConfigurationDeadLockWithConf
  48  * @author danielfuchs
  49  * @key randomness
  50  */
  51 // This test is a best effort to try & detect issues. The test itself will run
  52 // for 8secs. This is usually sufficient to detect issues.
  53 // However to get a greater confidence it is recommended to run this test in a loop:
  54 // e.g. use something like:
  55 // $ while jtreg -jdk:$JDK -verbose:all  \
  56 //      test/java/util/logging/TestLogConfigurationDeadLockWithConf.java ; \
  57 //      do echo Running test again ; done
  58 // and let it run for a few hours...
  59 //
  60 public class TestLogConfigurationDeadLockWithConf {
  61 
  62     static volatile Exception thrown = null;
  63     static volatile boolean goOn = true;
  64 
  65     static final int READERS = 2;
  66     static final int LOGGERS = 2;
  67     static final long TIME = 4 * 1000; // 4 sec.
  68     static final long STEP = 1 * 1000;  // message every 1 sec.
  69     static final int  LCOUNT = 50; // 50 loggers created in a row...
  70     static final AtomicLong nextLogger = new AtomicLong(0);
  71     static final AtomicLong readCount = new AtomicLong(0);
  72     static final AtomicLong checkCount = new AtomicLong(0);
  73 
  74     /**
  75      * This test will run both with and without a security manager.
  76      *
  77      * The test starts a number of threads that will call
  78      *     LogManager.readConfiguration() concurrently (ReadConf), then starts
  79      *     a number of threads that will create new loggers concurrently
  80      *     (AddLogger), and then two additional threads: one (Stopper) that
  81      *     will stop the test after 4secs (TIME ms), and one DeadlockDetector
  82      *     that will attempt to detect deadlocks.
  83      * If after 4secs no deadlock was detected and no exception was thrown
  84      * then the test is considered a success and passes.
  85      *
  86      * This procedure is done twice: once without a security manager and once
  87      * again with a security manager - which means the test takes ~8secs to
  88      * run.
  89      *
  90      * Note that 8sec may not be enough to detect issues if there are some.
  91      * This is a best effort test.
  92      *
  93      * @param args the command line arguments
  94      * @throws java.lang.Exception if the test fails.
  95      */
  96     public static void main(String[] args) throws Exception {
  97         File config =  new File(System.getProperty("test.src", "."),
  98                         "deadlockconf.properties");
  99         if (!config.canRead()) {
 100             System.err.println("Can't read config file: test cannot execute.");
 101             System.err.println("Please check your test environment: ");
 102             System.err.println("\t -Dtest.src=" + System.getProperty("test.src", "."));
 103             System.err.println("\t config file is: " + config.getAbsolutePath());
 104             throw new RuntimeException("Can't read config file: "
 105                 + config.getAbsolutePath());
 106         }
 107 
 108         System.setProperty("java.util.logging.config.file",
 109                config.getAbsolutePath());
 110 
 111         // test without security
 112         System.out.println("No security");
 113         test();
 114 
 115         // test with security
 116         System.out.println("\nWith security");
 117         Policy.setPolicy(new Policy() {
 118             @Override
 119             public boolean implies(ProtectionDomain domain, Permission permission) {
 120                 if (super.implies(domain, permission)) return true;
 121                 // System.out.println("Granting " + permission);
 122                 return true; // all permissions
 123             }
 124         });
 125         System.setSecurityManager(new SecurityManager());
 126         test();
 127     }
 128 
 129     static Random rand = new Random(System.currentTimeMillis());
 130     private static int getBarCount() {
 131         return rand.nextInt(10);
 132     }
 133 
 134     /**
 135      * Starts all threads, wait 4secs, then stops all threads.
 136      * @throws Exception if a deadlock was detected or an error occurred.
 137      */
 138     public static void test() throws Exception {
 139           goOn = true;
 140           thrown = null;
 141           long sNextLogger = nextLogger.get();
 142           long sReadCount  = readCount.get();
 143           long sCheckCount = checkCount.get();
 144           List<Thread> threads = new ArrayList<>();
 145           for (int i = 0; i<READERS; i++) {
 146               threads.add(new ReadConf());
 147           }
 148           for (int i = 0; i<LOGGERS; i++) {
 149               threads.add(new AddLogger());
 150           }
 151           DeadlockDetector detector = new DeadlockDetector();
 152           threads.add(detector);
 153           threads.add(0, new Stopper(TIME));
 154           for (Thread t : threads) {
 155               t.start();
 156           }
 157 
 158           // wait for the detector to finish.
 159           detector.join();
 160 
 161           final PrintStream out = thrown == null ? System.out : System.err;
 162 
 163           // Try to wait for all threads to finish.
 164           // This is a best effort: if some threads are in deadlock we can't
 165           //    obviously wait for them, and other threads may have joined in
 166           //    the deadlock since we last checked.
 167           //    However, all threads which are succeptible of deadlocking
 168           //    extend DeamonThread.
 169           for (Thread t : threads) {
 170               if (t == detector) {
 171                   continue;
 172               }
 173               if (detector.deadlocked.contains(t.getId())) {
 174                   out.println("Skipping deadlocked thread "
 175                           + t.getClass().getSimpleName() + ": " + t);
 176                   continue; // don't wait for deadlocked thread: they won't terminate
 177               }
 178               try {
 179                   if (detector.deadlocked.isEmpty()) {
 180                       t.join();
 181                   } else {
 182                       if (t instanceof DaemonThread) {
 183                           // Some other threads may have join the deadlock.
 184                           // don't wait forever.
 185                           t.join(100);
 186                       } else {
 187                           // Those threads that don't extend DaemonThread
 188                           // should be safe from deadlock.
 189                           out.println("Waiting for "
 190                                   + t.getClass().getSimpleName() + ": " + t);
 191                           t.join();
 192                       }
 193                   }
 194               } catch (Exception x) {
 195                   fail(x);
 196               }
 197           }
 198           out.println("All threads joined.");
 199 
 200           final String status = thrown == null ? "Passed" : "FAILED";
 201 
 202           out.println(status + ": " + (nextLogger.get() - sNextLogger)
 203                   + " loggers created by " + LOGGERS + " Thread(s),");
 204           out.println("\t LogManager.readConfiguration() called "
 205                   + (readCount.get() - sReadCount) + " times by " + READERS
 206                   + " Thread(s).");
 207           out.println("\t ThreadMXBean.findDeadlockedThreads called "
 208                   + (checkCount.get() -sCheckCount) + " times by 1 Thread.");
 209 
 210           if (thrown != null) {
 211               out.println("\t Error is: "+thrown.getMessage());
 212               throw thrown;
 213           }
 214     }
 215 
 216     static class DaemonThread extends Thread {
 217         public DaemonThread() {
 218             this.setDaemon(true);
 219         }
 220     }
 221 
 222     final static class ReadConf extends DaemonThread {
 223         @Override
 224         public void run() {
 225             while (goOn) {
 226                 try {
 227                     LogManager.getLogManager().readConfiguration();
 228                     readCount.incrementAndGet();
 229                     Thread.sleep(1);
 230                 } catch (Exception x) {
 231                     fail(x);
 232                 }
 233             }
 234         }
 235     }
 236 
 237     final static class AddLogger extends DaemonThread {
 238         @Override
 239         public void run() {
 240             try {
 241                 while (goOn) {
 242                     Logger l;
 243                     int barcount = getBarCount();
 244                     for (int i=0; i < LCOUNT ; i++) {
 245                         l = Logger.getLogger("foo.bar"+barcount+".l"+nextLogger.incrementAndGet());
 246                         l.fine("I'm fine");
 247                         if (!goOn) break;
 248                         Thread.sleep(1);
 249                     }
 250                 }
 251             } catch (InterruptedException | RuntimeException x ) {
 252                 fail(x);
 253             }
 254         }
 255     }
 256 
 257     final static class DeadlockDetector extends Thread {
 258 
 259         final Set<Long> deadlocked = Collections.synchronizedSet(new HashSet<Long>());
 260 
 261         static List<Long> asList(long... ids) {
 262             final List<Long> list = new ArrayList<>(ids.length);
 263             for (long id : ids) {
 264                 list.add(id);
 265             }
 266             return list;
 267         }
 268 
 269         @Override
 270         public void run() {
 271             while(goOn) {
 272                 try {
 273                     long[] ids = ManagementFactory.getThreadMXBean().findDeadlockedThreads();
 274                     checkCount.incrementAndGet();
 275                     ids = ids == null ? new long[0] : ids;
 276                     if (ids.length > 0) {
 277                         deadlocked.addAll(asList(ids));
 278                     }
 279                     if (ids.length == 1) {
 280                         throw new RuntimeException("Found 1 deadlocked thread: "+ids[0]);
 281                     } else if (ids.length > 0) {
 282                         ThreadInfo[] infos = ManagementFactory.getThreadMXBean().getThreadInfo(ids, Integer.MAX_VALUE);
 283                         System.err.println("Found "+ids.length+" deadlocked threads: ");
 284                         for (ThreadInfo inf : infos) {
 285                             System.err.println(inf.toString());
 286                         }
 287                         throw new RuntimeException("Found "+ids.length+" deadlocked threads");
 288                     }
 289                     Thread.sleep(100);
 290                 } catch(InterruptedException | RuntimeException x) {
 291                     fail(x);
 292                 }
 293             }
 294         }
 295 
 296     }
 297 
 298     static final class Stopper extends Thread {
 299         long start;
 300         long time;
 301 
 302         static final Logger logger = Logger.getLogger("remaining");
 303 
 304         Stopper(long time) {
 305             start = System.currentTimeMillis();
 306             this.time = time;
 307         }
 308 
 309         @Override
 310         public void run() {
 311             try {
 312                 long rest, previous;
 313                 previous = time;
 314                 while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) {
 315                     if (previous == time || previous - rest >= STEP) {
 316                         logger.log(Level.INFO,
 317                                 "{0}ms remaining...", String.valueOf(rest));
 318                         previous = rest == time ? rest -1 : rest;
 319                         System.gc();
 320                     }
 321                     if (goOn == false) break;
 322                     Thread.sleep(Math.min(rest, 100));
 323                 }
 324                 System.out.println(System.currentTimeMillis() - start
 325                         + " ms elapsed ("+time+ " requested)");
 326                 goOn = false;
 327             } catch(InterruptedException | RuntimeException x) {
 328                 fail(x);
 329             }
 330         }
 331 
 332     }
 333 
 334     static void fail(Exception x) {
 335         x.printStackTrace();
 336         if (thrown == null) {
 337             thrown = x;
 338         }
 339         goOn = false;
 340     }
 341 }
--- EOF ---