1 /*
2  * Copyright (c) 2013, 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.lang.management.ManagementFactory;
24 import java.lang.management.ThreadInfo;
25 import java.security.Permission;
26 import java.security.Policy;
27 import java.security.ProtectionDomain;
28 import java.util.ArrayList;
29 import java.util.List;
30 import java.util.concurrent.atomic.AtomicLong;
31 import java.util.logging.LogManager;
32 import java.util.logging.Logger;
33 
34 
35 /**
36  * @test
37  * @bug 8029281 8027670
38  * @summary Synchronization issues in Logger and LogManager. This test
39  *       focusses more particularly on potential deadlock in
40  *       drainLoggerRefQueueBounded / readConfiguration
41  * @run main/othervm TestLogConfigurationDeadLock
42  * @author danielfuchs
43  */
44 // This test is a best effort to try & detect issues. The test itself will run
45 // for 8secs. This is usually unsufficient to detect issues.
46 // To get a greater confidence it is recommended to run this test in a loop:
47 // e.g. use something like:
48 // $ while jtreg -jdk:$JDK -verbose:all  \
49 //      test/java/util/logging/TestLogConfigurationDeadLock.java ; \
50 //      do echo Running test again ; done
51 // and let it run for a few hours...
52 //
53 public class TestLogConfigurationDeadLock {
54 
55     static volatile Exception thrown = null;
56     static volatile boolean goOn = true;
57 
58     static final int READERS = 2;
59     static final int LOGGERS = 2;
60     static final long TIME = 4 * 1000; // 4 sec.
61     static final long STEP = 1 * 1000;  // message every 1 sec.
62     static final int  LCOUNT = 50; // 50 loggers created in a row...
63     static final AtomicLong nextLogger = new AtomicLong(0);
64     static final AtomicLong readCount = new AtomicLong(0);
65     static final AtomicLong checkCount = new AtomicLong(0);
66 
67     /**
68      * This test will run both with and without a security manager.
69      *
70      * The test starts a number of threads that will call
71      *     LogManager.readConfiguration() concurrently (ReadConf), then starts
72      *     a number of threads that will create new loggers concurrently
73      *     (AddLogger), and then two additional threads: one (Stopper) that
74      *     will stop the test after 4secs (TIME ms), and one DeadlockDetector
75      *     that will attempt to detect deadlocks.
76      * If after 4secs no deadlock was detected and no exception was thrown
77      * then the test is considered a success and passes.
78      *
79      * This procedure is done twice: once without a security manager and once
80      * again with a security manager - which means the test takes ~8secs to
81      * run.
82      *
83      * Note that 8sec may not be enough to detect issues if there are some.
84      * This is a best effort test.
85      *
86      * @param args the command line arguments
87      */
main(String[] args)88     public static void main(String[] args) throws Exception {
89 
90         // test without security
91         System.out.println("No security");
92         test();
93 
94         // test with security
95         System.out.println("\nWith security");
96         Policy.setPolicy(new Policy() {
97             @Override
98             public boolean implies(ProtectionDomain domain, Permission permission) {
99                 if (super.implies(domain, permission)) return true;
100                 // System.out.println("Granting " + permission);
101                 return true; // all permissions
102             }
103         });
104         System.setSecurityManager(new SecurityManager());
105         test();
106     }
107 
108     /**
109      * Starts all threads, wait 4secs, then stops all threads.
110      * @throws Exception if a deadlock was detected or an error occurred.
111      */
test()112     public static void test() throws Exception {
113           goOn = true;
114           thrown = null;
115           long sNextLogger = nextLogger.get();
116           long sReadCount  = readCount.get();
117           long sCheckCount = checkCount.get();
118           List<Thread> threads = new ArrayList<>();
119           for (int i = 0; i<READERS; i++) {
120               threads.add(new ReadConf());
121           }
122           for (int i = 0; i<LOGGERS; i++) {
123               threads.add(new AddLogger());
124           }
125           threads.add(new DeadlockDetector());
126           threads.add(0, new Stopper(TIME));
127           for (Thread t : threads) {
128               t.start();
129           }
130           for (Thread t : threads) {
131               try {
132                   t.join();
133               } catch (Exception x) {
134                   fail(x);
135               }
136           }
137           if (thrown != null) {
138               throw thrown;
139           }
140           System.out.println("Passed: " + (nextLogger.get() - sNextLogger)
141                   + " loggers created by " + LOGGERS + " Thread(s),");
142           System.out.println("\t LogManager.readConfiguration() called "
143                   + (readCount.get() - sReadCount) + " times by " + READERS
144                   + " Thread(s).");
145           System.out.println("\t ThreadMXBean.findDeadlockedThreads called "
146                   + (checkCount.get() -sCheckCount) + " times by 1 Thread.");
147 
148     }
149 
150 
151     final static class ReadConf extends Thread {
152         @Override
run()153         public void run() {
154             while (goOn) {
155                 try {
156                     LogManager.getLogManager().readConfiguration();
157                     readCount.incrementAndGet();
158                     Thread.sleep(1);
159                 } catch (Exception x) {
160                     fail(x);
161                 }
162             }
163         }
164     }
165 
166     final static class AddLogger extends Thread {
167         @Override
run()168         public void run() {
169             try {
170                 while (goOn) {
171                     Logger l;
172                     Logger foo = Logger.getLogger("foo");
173                     Logger bar = Logger.getLogger("foo.bar");
174                     for (int i=0; i < LCOUNT ; i++) {
175                         l = Logger.getLogger("foo.bar.l"+nextLogger.incrementAndGet());
176                         l.fine("I'm fine");
177                         if (!goOn) break;
178                         Thread.sleep(1);
179                     }
180                 }
181             } catch (InterruptedException | RuntimeException x ) {
182                 fail(x);
183             }
184         }
185     }
186 
187     final static class DeadlockDetector extends Thread {
188 
189         @Override
run()190         public void run() {
191             while(goOn) {
192                 try {
193                     long[] ids = ManagementFactory.getThreadMXBean().findDeadlockedThreads();
194                     checkCount.incrementAndGet();
195                     ids = ids == null ? new long[0] : ids;
196                     if (ids.length == 1) {
197                         throw new RuntimeException("Found 1 deadlocked thread: "+ids[0]);
198                     } else if (ids.length > 0) {
199                         ThreadInfo[] infos = ManagementFactory.getThreadMXBean()
200                             .getThreadInfo(ids, Integer.MAX_VALUE);
201                         System.err.println("Found "+ids.length+" deadlocked threads: ");
202                         for (ThreadInfo inf : infos) {
203                             System.err.println(inf.toString());
204                         }
205                         throw new RuntimeException("Found "+ids.length+" deadlocked threads");
206                     }
207                     Thread.sleep(100);
208                 } catch(InterruptedException | RuntimeException x) {
209                     fail(x);
210                 }
211             }
212         }
213 
214     }
215 
216     static final class Stopper extends Thread {
217         long start;
218         long time;
219 
Stopper(long time)220         Stopper(long time) {
221             start = System.currentTimeMillis();
222             this.time = time;
223         }
224 
225         @Override
run()226         public void run() {
227             try {
228                 long rest, previous;
229                 previous = time;
230                 while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) {
231                     if (previous == time || previous - rest >= STEP) {
232                         Logger.getLogger("remaining").info(String.valueOf(rest)+"ms remaining...");
233                         previous = rest == time ? rest -1 : rest;
234                         System.gc();
235                     }
236                     if (goOn == false) break;
237                     Thread.sleep(Math.min(rest, 100));
238                 }
239                 System.out.println(System.currentTimeMillis() - start
240                         + " ms elapsed ("+time+ " requested)");
241                 goOn = false;
242             } catch(InterruptedException | RuntimeException x) {
243                 fail(x);
244             }
245         }
246 
247     }
248 
fail(Exception x)249     static void fail(Exception x) {
250         x.printStackTrace();
251         if (thrown == null) {
252             thrown = x;
253         }
254         goOn = false;
255     }
256 }
257