1 /*
2 * Copyright (c) 2006, 2012, 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
24 /*
25 * @test
26 * @bug 6467152 6716076 6829503
27 * @summary deadlock occurs in LogManager initialization and JVM termination
28 * @author Serguei Spitsyn / Hitachi / Martin Buchholz
29 *
30 * @build LoggingDeadlock2
31 * @run main LoggingDeadlock2
32 * @key randomness
33 */
34
35 /*
36 *
37 * There is a clear deadlock between LogManager.<clinit> and
38 * Cleaner.run() methods.
39 * T1 thread:
40 * The LogManager.<clinit> creates LogManager.manager object,
41 * sets shutdown hook with the Cleaner class and then waits
42 * to lock the LogManager.manager monitor.
43 * T2 thread:
44 * It is started by the System.exit() as shutdown hook thread.
45 * It locks the LogManager.manager monitor and then calls the
46 * static methods of the LogManager class (in this particular
47 * case it is a trick of the inner classes implementation).
48 * It is waits when the LogManager.<clinit> is completed.
49 *
50 * This is a regression test for this bug.
51 */
52
53 import java.util.Arrays;
54 import java.util.List;
55 import java.util.Random;
56 import java.util.concurrent.CyclicBarrier;
57 import java.util.concurrent.atomic.AtomicInteger;
58 import java.util.logging.LogManager;
59 import java.io.File;
60 import java.io.IOException;
61 import java.io.InputStream;
62 import java.io.InputStreamReader;
63 import java.io.Reader;
64 import java.util.concurrent.TimeUnit;
65
66 public class LoggingDeadlock2 {
67
68 // ask child process to dumpstack after 60secs
69 public static final long DUMP_STACK_FREQUENCY_MS = 60000;
70
71 // A marker that allows to validate the subprocess output.
72 public static final String MARKER = "$";
73
74 public static void realMain(String arg[]) throws Throwable {
75 try {
76 System.out.println(javaChildArgs);
77 ProcessBuilder pb = new ProcessBuilder(javaChildArgs);
78 ProcessResults r = run(pb.start());
79 equal(r.exitValue(), 99);
80
81 // output of subprocess should end with "$"
82 final String out = r.out();
83 final String trailingOutput = out.indexOf(MARKER) > -1
84 ? out.substring(out.indexOf(MARKER)+MARKER.length())
85 : out;
86 equal(trailingOutput, "");
87 equal(r.err(), "");
88 equal(out.startsWith("JavaChild started"), true);
89 equal(out.endsWith("$"), true);
90 } catch (Throwable t) { unexpected(t); }
91 }
92
93 public static class JavaChild {
94 public static void main(String args[]) throws Throwable {
95 System.out.println("JavaChild started");
96
97 final CyclicBarrier startingGate = new CyclicBarrier(2);
98 final Throwable[] thrown = new Throwable[1];
99
100 // Some random variation, to help tickle races.
101 final Random rnd = new Random();
102 final long seed = rnd.nextLong();
103 rnd.setSeed(seed);
104 System.out.println("seed=" + seed);
105 final boolean dojoin = rnd.nextBoolean();
106 final int JITTER = 1024;
107 final int iters1 = rnd.nextInt(JITTER);
108 final int iters2 = JITTER - iters1;
109 final AtomicInteger counter = new AtomicInteger(0);
110 System.out.println("dojoin=" + dojoin);
111 System.out.println("iters1=" + iters1);
112 System.out.println("iters2=" + iters2);
113
114 Thread exiter = new Thread() {
115 public void run() {
116 try {
117 startingGate.await();
118 for (int i = 0; i < iters1; i++)
119 counter.getAndIncrement();
120 System.exit(99);
121 } catch (Throwable t) {
122 t.printStackTrace();
123 System.exit(86);
124 }
125 }};
126 exiter.start();
127
128 System.out.println("exiter started");
129
130 // signal end of verbose output
131 System.out.print(MARKER);
132 System.out.flush();
133
134 startingGate.await();
135 for (int i = 0; i < iters2; i++)
136 counter.getAndIncrement();
137 // This may or may not result in a first call to
138 // Runtime.addShutdownHook after shutdown has already
139 // commenced.
140 LogManager.getLogManager();
141
142 if (dojoin) {
143 exiter.join();
144 if (thrown[0] != null)
145 throw new Error(thrown[0]);
146 check(counter.get() == JITTER);
147 }
148 }
149 }
150
151 //----------------------------------------------------------------
152 // The rest of this test is copied from ProcessBuilder/Basic.java
153 //----------------------------------------------------------------
154 private static final String javaExe =
155 System.getProperty("java.home") +
156 File.separator + "bin" + File.separator + "java";
157 private static final String jstackExe =
158 System.getProperty("java.home") +
159 File.separator + "bin" + File.separator + "jstack";
160
161 private static final String classpath =
162 System.getProperty("java.class.path");
163
164 private static final List<String> javaChildArgs =
165 Arrays.asList(new String[]
166 { javaExe, "-classpath", classpath,
167 "LoggingDeadlock2$JavaChild"});
168
169 private static class ProcessResults {
170 private final String out;
171 private final String err;
172 private final int exitValue;
173 private final Throwable throwable;
174
175 public ProcessResults(String out,
176 String err,
177 int exitValue,
178 Throwable throwable) {
179 this.out = out;
180 this.err = err;
181 this.exitValue = exitValue;
182 this.throwable = throwable;
183 }
184
185 public String out() { return out; }
186 public String err() { return err; }
187 public int exitValue() { return exitValue; }
188
189 public String toString() {
190 StringBuilder sb = new StringBuilder();
191 sb.append("<STDOUT>\n" + out() + "</STDOUT>\n")
192 .append("<STDERR>\n" + err() + "</STDERR>\n")
193 .append("exitValue = " + exitValue + "\n");
194 if (throwable != null)
195 sb.append(throwable.getStackTrace());
196 return sb.toString();
197 }
198 }
199
200 private static class StreamAccumulator extends Thread {
201 private final InputStream is;
202 private final StringBuilder sb = new StringBuilder();
203 private Throwable throwable = null;
204
205 public String result () throws Throwable {
206 if (throwable != null)
207 throw throwable;
208 return sb.toString();
209 }
210
211 StreamAccumulator (InputStream is) {
212 this.is = is;
213 }
214
215 public void run() {
216 try {
217 Reader r = new InputStreamReader(is);
218 int n;
219 while ((n = r.read()) > 0) {
220 sb.append((char)n);
221
222 // prints everything immediately to System.out so that we can
223 // see the traces even in the event of a test timeout
224 System.out.write((char)n);
225 System.out.flush();
226
227 }
228 } catch (Throwable t) {
229 throwable = t;
230 } finally {
231 try { is.close(); }
232 catch (Throwable t) { throwable = t; }
233 }
234 }
235 }
236
237 /**
238 * If the child process deadlocks, then the parent may fail in timeout.
239 * In that case, we won't have any interesting traces, unless we manage
240 * to get a thread dump from the child.
241 * It is unsure whether obtaining a thread dump from a deadlocked child
242 * will work - but maybe we could see something if the timeout is a false
243 * positive (the child has not deadlocked but hasn't managed to fully start
244 * yet, for instance).
245 * The idea here is to periodically try to obtain a thread dump from the
246 * child, every 60sec - which should be always less than the jtreg timeout.
247 */
248 private static class TimeoutThread extends Thread {
249 final long ms;
250 final Process process;
251 TimeoutThread(long ms, Process p) {
252 super("TimeoutThread");
253 setDaemon(true);
254 this.ms = ms;
255 this.process = p;
256 }
257
258 @Override
259 public void run() {
260 long start = System.nanoTime();
261 try {
262 while (true) {
263 sleep(ms);
264 System.err.println("Timeout reached: " + ms);
265 if (process.isAlive()) {
266 long pid = process.getPid();
267 ProcessBuilder jstack = new ProcessBuilder(jstackExe, String.valueOf(pid));
268 System.err.println("Dumping subprocess stack: " + pid);
269 Process p = jstack.inheritIO().start();
270 p.waitFor(ms, TimeUnit.MILLISECONDS);
271 } else {
272 System.err.println("Process is not alive!");
273 break;
274 }
275 }
276 } catch (InterruptedException ex) {
277 System.err.println("Interrupted: " + ex);
278 } catch (IOException io) {
279 System.err.println("Failed to get stack from subprocess");
280 io.printStackTrace();
281 }
282 }
283
284
285 }
286
287 private static ProcessResults run(Process p) {
288 Throwable throwable = null;
289 int exitValue = -1;
290 String out = "";
291 String err = "";
292
293 StreamAccumulator outAccumulator =
294 new StreamAccumulator(p.getInputStream());
295 StreamAccumulator errAccumulator =
296 new StreamAccumulator(p.getErrorStream());
297
298 try {
299 System.out.println("Waiting for child process to exit");
300 outAccumulator.start();
301 errAccumulator.start();
302
303 // ask subprocess to dump stack every 60 secs.
304 new TimeoutThread(DUMP_STACK_FREQUENCY_MS, p).start();
305
306 exitValue = p.waitFor();
307 System.out.println("\nChild exited with status: " + exitValue);
308
309 outAccumulator.join();
310 errAccumulator.join();
311
312 out = outAccumulator.result();
313 err = errAccumulator.result();
314 } catch (Throwable t) {
315 throwable = t;
316 }
317
318 return new ProcessResults(out, err, exitValue, throwable);
319 }
320
321 //--------------------- Infrastructure ---------------------------
322 static volatile int passed = 0, failed = 0;
323 static void pass() {passed++;}
324 static void fail() {failed++; Thread.dumpStack();}
325 static void fail(String msg) {System.out.println(msg); fail();}
326 static void unexpected(Throwable t) {failed++; t.printStackTrace();}
327 static void check(boolean cond) {if (cond) pass(); else fail();}
328 static void check(boolean cond, String m) {if (cond) pass(); else fail(m);}
329 static void equal(Object x, Object y) {
330 if (x == null ? y == null : x.equals(y)) pass();
331 else fail(x + " not equal to " + y);}
332 public static void main(String[] args) throws Throwable {
333 try {realMain(args);} catch (Throwable t) {unexpected(t);}
334 System.out.printf("%nPassed = %d, failed = %d%n%n", passed, failed);
335 if (failed > 0) throw new AssertionError("Some tests failed");}
336 }