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