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 }