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