test/jdk/java/util/logging/LoggingDeadlock2.java - platform/libcore - Git at Google

 /*
  * Copyright (c) 2006, 2017, Oracle and/or its affiliates. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
  * under the terms of the GNU General Public License version 2 only, as
  * published by the Free Software Foundation.
  *
  * This code is distributed in the hope that it will be useful, but WITHOUT
  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  * version 2 for more details (a copy is included in the LICENSE file that
  * accompanied this code).
  *
  * You should have received a copy of the GNU General Public License version
  * 2 along with this work; if not, write to the Free Software Foundation,
  * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
  *
  * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
  * or visit www.oracle.com if you need additional information or have any
  * questions.
  */

 /*
  * @test
  * @bug     6467152 6716076 6829503 8132550
  * @summary deadlock occurs in LogManager initialization and JVM termination
  * @author  Serguei Spitsyn / Hitachi / Martin Buchholz
  *
  * @build    LoggingDeadlock2
  * @run  main LoggingDeadlock2
  * @key randomness
  */

 /*
  *
  * There is a clear deadlock between LogManager.<clinit> and
  * Cleaner.run() methods.
  * T1 thread:
  *   The LogManager.<clinit> creates LogManager.manager object,
  *   sets shutdown hook with the Cleaner class and then waits
  *   to lock the LogManager.manager monitor.
  * T2 thread:
  *   It is started by the System.exit() as shutdown hook thread.
  *   It locks the LogManager.manager monitor and then calls the
  *   static methods of the LogManager class (in this particular
  *   case it is a trick of the inner classes implementation).
  *   It is waits when the LogManager.<clinit> is completed.
  *
  * This is a regression test for this bug.
  */

 import java.util.Arrays;
 import java.util.List;
 import java.util.Random;
 import java.util.concurrent.CyclicBarrier;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.logging.LogManager;
 import java.io.File;
 import java.io.IOException;
 import java.io.InputStream;
 import java.io.InputStreamReader;
 import java.io.Reader;
 import java.util.concurrent.TimeUnit;

 public class LoggingDeadlock2 {

     // ask child process to dumpstack after 60secs
     public static final long DUMP_STACK_FREQUENCY_MS = 60000;

     // A marker that allows to validate the subprocess output.
     public static final String MARKER = "$";

     public static void realMain(String arg[]) throws Throwable {
         try {
             System.out.println(javaChildArgs);
             ProcessBuilder pb = new ProcessBuilder(javaChildArgs);
             ProcessResults r = run(pb.start());
             equal(r.exitValue(), 99);

             // output of subprocess should end with "$"
             final String out = r.out();
             final String trailingOutput = out.indexOf(MARKER) > -1
                     ? out.substring(out.indexOf(MARKER)+MARKER.length())
                     : out;
             equal(trailingOutput, "");
             equal(r.err(), "");
             equal(out.startsWith("JavaChild started"), true);
             equal(out.endsWith("$"), true);
         } catch (Throwable t) { unexpected(t); }
     }

     public static class JavaChild {
         public static void main(String args[]) throws Throwable {
             System.out.println("JavaChild started");

             final CyclicBarrier startingGate = new CyclicBarrier(2);
             final Throwable[] thrown = new Throwable[1];

             // Some random variation, to help tickle races.
             final Random rnd = new Random();
             final long seed = rnd.nextLong();
             rnd.setSeed(seed);
             System.out.println("seed=" + seed);
             final boolean dojoin = rnd.nextBoolean();
             final int JITTER = 1024;
             final int iters1 = rnd.nextInt(JITTER);
             final int iters2 = JITTER - iters1;
             final AtomicInteger counter = new AtomicInteger(0);
             System.out.println("dojoin=" + dojoin);
             System.out.println("iters1=" + iters1);
             System.out.println("iters2=" + iters2);

             Thread exiter = new Thread() {
                 public void run() {
                     try {
                         startingGate.await();
                         for (int i = 0; i < iters1; i++)
                             counter.getAndIncrement();
                         System.exit(99);
                     } catch (Throwable t) {
                         t.printStackTrace();
                         System.exit(86);
                     }
                 }};
             exiter.start();

             System.out.println("exiter started");

             // signal end of verbose output
             System.out.print(MARKER);
             System.out.flush();

             startingGate.await();
             for (int i = 0; i < iters2; i++)
                 counter.getAndIncrement();
             // This may or may not result in a first call to
             // Runtime.addShutdownHook after shutdown has already
             // commenced.
             LogManager.getLogManager();

             if (dojoin) {
                 exiter.join();
                 if (thrown[0] != null)
                     throw new Error(thrown[0]);
                 check(counter.get() == JITTER);
             }
         }
     }

     //----------------------------------------------------------------
     // The rest of this test is copied from ProcessBuilder/Basic.java
     //----------------------------------------------------------------
     private static final String javaExe =
         System.getProperty("java.home") +
         File.separator + "bin" + File.separator + "java";
     private static final String jstackExe =
         System.getProperty("java.home") +
         File.separator + "bin" + File.separator + "jstack";

     private static final String classpath =
         System.getProperty("java.class.path");

     private static final List<String> javaChildArgs =
         Arrays.asList(new String[]
             { javaExe, "-classpath", classpath,
               "LoggingDeadlock2$JavaChild"});

     private static class ProcessResults {
         private final String out;
         private final String err;
         private final int exitValue;
         private final Throwable throwable;

         public ProcessResults(String out,
                               String err,
                               int exitValue,
                               Throwable throwable) {
             this.out = out;
             this.err = err;
             this.exitValue = exitValue;
             this.throwable = throwable;
         }

         public String out()          { return out; }
         public String err()          { return err; }
         public int exitValue()       { return exitValue; }

         public String toString() {
             StringBuilder sb = new StringBuilder();
             sb.append("<STDOUT>\n" + out() + "</STDOUT>\n")
                 .append("<STDERR>\n" + err() + "</STDERR>\n")
                 .append("exitValue = " + exitValue + "\n");
             if (throwable != null)
                 sb.append(throwable.getStackTrace());
             return sb.toString();
         }
     }

     private static class StreamAccumulator extends Thread {
         private final InputStream is;
         private final StringBuilder sb = new StringBuilder();
         private Throwable throwable = null;

         public String result () throws Throwable {
             if (throwable != null)
                 throw throwable;
             return sb.toString();
         }

         StreamAccumulator (InputStream is) {
             this.is = is;
         }

         public void run() {
             try {
                 Reader r = new InputStreamReader(is);
                 int n;
                 while ((n = r.read()) > 0) {
                     sb.append((char)n);

                     // prints everything immediately to System.out so that we can
                     // see the traces even in the event of a test timeout
                     System.out.write((char)n);
                     System.out.flush();

                 }
             } catch (Throwable t) {
                 throwable = t;
             } finally {
                 try { is.close(); }
                 catch (Throwable t) { throwable = t; }
             }
         }
     }

     /**
      * If the child process deadlocks, then the parent may fail in timeout.
      * In that case, we won't have any interesting traces, unless we manage
      * to get a thread dump from the child.
      * It is unsure whether obtaining a thread dump from a deadlocked child
      * will work - but maybe we could see something if the timeout is a false
      * positive (the child has not deadlocked but hasn't managed to fully start
      * yet, for instance).
      * The idea here is to periodically try to obtain a thread dump from the
      * child, every 60sec - which should be always less than the jtreg timeout.
      */
     private static class TimeoutThread extends Thread {
         final long ms;
         final Process process;
         TimeoutThread(long ms, Process p) {
             super("TimeoutThread");
             setDaemon(true);
             this.ms = ms;
             this.process = p;
         }

         @Override
         public void run() {
             long start = System.nanoTime();
             try {
                 while (true) {
                     sleep(ms);
                     System.err.println("Timeout reached: " + ms);
                     if (process.isAlive()) {
                         long pid = process.pid();
                         ProcessBuilder jstack = new ProcessBuilder(jstackExe, String.valueOf(pid));
                         System.err.println("Dumping subprocess stack: " + pid);
                         Process p = jstack.inheritIO().start();
                         p.waitFor(ms, TimeUnit.MILLISECONDS);
                     } else {
                         System.err.println("Process is not alive!");
                         break;
                     }
                 }
             } catch (InterruptedException ex) {
                 System.err.println("Interrupted: " + ex);
             } catch (IOException io) {
                 System.err.println("Failed to get stack from subprocess");
                 io.printStackTrace();
             }
         }


     }

     private static ProcessResults run(Process p) {
         Throwable throwable = null;
         int exitValue = -1;
         String out = "";
         String err = "";

         StreamAccumulator outAccumulator =
             new StreamAccumulator(p.getInputStream());
         StreamAccumulator errAccumulator =
             new StreamAccumulator(p.getErrorStream());

         try {
             System.out.println("Waiting for child process to exit");
             outAccumulator.start();
             errAccumulator.start();

             // ask subprocess to dump stack every 60 secs.
             new TimeoutThread(DUMP_STACK_FREQUENCY_MS, p).start();

             exitValue = p.waitFor();
             System.out.println("\nChild exited with status: " + exitValue);

             outAccumulator.join();
             errAccumulator.join();

             out = outAccumulator.result();
             err = errAccumulator.result();
         } catch (Throwable t) {
             throwable = t;
         }

         return new ProcessResults(out, err, exitValue, throwable);
     }

     //--------------------- Infrastructure ---------------------------
     static volatile int passed = 0, failed = 0;
     static void pass() {passed++;}
     static void fail() {failed++; Thread.dumpStack();}
     static void fail(String msg) {System.out.println(msg); fail();}
     static void unexpected(Throwable t) {failed++; t.printStackTrace();}
     static void check(boolean cond) {if (cond) pass(); else fail();}
     static void check(boolean cond, String m) {if (cond) pass(); else fail(m);}
     static void equal(Object x, Object y) {
         if (x == null ? y == null : x.equals(y)) pass();
         else fail(x + " not equal to " + y);}
     public static void main(String[] args) throws Throwable {
         try {realMain(args);} catch (Throwable t) {unexpected(t);}
         System.out.printf("%nPassed = %d, failed = %d%n%n", passed, failed);
         if (failed > 0) throw new AssertionError("Some tests failed");}
 }
	/*
	* Copyright (c) 2006, 2017, Oracle and/or its affiliates. All rights reserved.
	* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
	*
	* This code is free software; you can redistribute it and/or modify it
	* under the terms of the GNU General Public License version 2 only, as
	* published by the Free Software Foundation.
	*
	* This code is distributed in the hope that it will be useful, but WITHOUT
	* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
	* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
	* version 2 for more details (a copy is included in the LICENSE file that
	* accompanied this code).
	*
	* You should have received a copy of the GNU General Public License version
	* 2 along with this work; if not, write to the Free Software Foundation,
	* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
	*
	* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
	* or visit www.oracle.com if you need additional information or have any
	* questions.
	*/

	/*
	* @test
	* @bug 6467152 6716076 6829503 8132550
	* @summary deadlock occurs in LogManager initialization and JVM termination
	* @author Serguei Spitsyn / Hitachi / Martin Buchholz
	*
	* @build LoggingDeadlock2
	* @run main LoggingDeadlock2
	* @key randomness
	*/

	/*
	*
	* There is a clear deadlock between LogManager.<clinit> and
	* Cleaner.run() methods.
	* T1 thread:
	* The LogManager.<clinit> creates LogManager.manager object,
	* sets shutdown hook with the Cleaner class and then waits
	* to lock the LogManager.manager monitor.
	* T2 thread:
	* It is started by the System.exit() as shutdown hook thread.
	* It locks the LogManager.manager monitor and then calls the
	* static methods of the LogManager class (in this particular
	* case it is a trick of the inner classes implementation).
	* It is waits when the LogManager.<clinit> is completed.
	*
	* This is a regression test for this bug.
	*/

	import java.util.Arrays;
	import java.util.List;
	import java.util.Random;
	import java.util.concurrent.CyclicBarrier;
	import java.util.concurrent.atomic.AtomicInteger;
	import java.util.logging.LogManager;
	import java.io.File;
	import java.io.IOException;
	import java.io.InputStream;
	import java.io.InputStreamReader;
	import java.io.Reader;
	import java.util.concurrent.TimeUnit;

	public class LoggingDeadlock2 {

	// ask child process to dumpstack after 60secs
	public static final long DUMP_STACK_FREQUENCY_MS = 60000;

	// A marker that allows to validate the subprocess output.
	public static final String MARKER = "$";

	public static void realMain(String arg[]) throws Throwable {
	try {
	System.out.println(javaChildArgs);
	ProcessBuilder pb = new ProcessBuilder(javaChildArgs);
	ProcessResults r = run(pb.start());
	equal(r.exitValue(), 99);

	// output of subprocess should end with "$"
	final String out = r.out();
	final String trailingOutput = out.indexOf(MARKER) > -1
	? out.substring(out.indexOf(MARKER)+MARKER.length())
	: out;
	equal(trailingOutput, "");
	equal(r.err(), "");
	equal(out.startsWith("JavaChild started"), true);
	equal(out.endsWith("$"), true);
	} catch (Throwable t) { unexpected(t); }
	}

	public static class JavaChild {
	public static void main(String args[]) throws Throwable {
	System.out.println("JavaChild started");

	final CyclicBarrier startingGate = new CyclicBarrier(2);
	final Throwable[] thrown = new Throwable[1];

	// Some random variation, to help tickle races.
	final Random rnd = new Random();
	final long seed = rnd.nextLong();
	rnd.setSeed(seed);
	System.out.println("seed=" + seed);
	final boolean dojoin = rnd.nextBoolean();
	final int JITTER = 1024;
	final int iters1 = rnd.nextInt(JITTER);
	final int iters2 = JITTER - iters1;
	final AtomicInteger counter = new AtomicInteger(0);
	System.out.println("dojoin=" + dojoin);
	System.out.println("iters1=" + iters1);
	System.out.println("iters2=" + iters2);

	Thread exiter = new Thread() {
	public void run() {
	try {
	startingGate.await();
	for (int i = 0; i < iters1; i++)
	counter.getAndIncrement();
	System.exit(99);
	} catch (Throwable t) {
	t.printStackTrace();
	System.exit(86);
	}
	}};
	exiter.start();

	System.out.println("exiter started");

	// signal end of verbose output
	System.out.print(MARKER);
	System.out.flush();

	startingGate.await();
	for (int i = 0; i < iters2; i++)
	counter.getAndIncrement();
	// This may or may not result in a first call to
	// Runtime.addShutdownHook after shutdown has already
	// commenced.
	LogManager.getLogManager();

	if (dojoin) {
	exiter.join();
	if (thrown[0] != null)
	throw new Error(thrown[0]);
	check(counter.get() == JITTER);
	}
	}
	}

	//----------------------------------------------------------------
	// The rest of this test is copied from ProcessBuilder/Basic.java
	//----------------------------------------------------------------
	private static final String javaExe =
	System.getProperty("java.home") +
	File.separator + "bin" + File.separator + "java";
	private static final String jstackExe =
	System.getProperty("java.home") +
	File.separator + "bin" + File.separator + "jstack";

	private static final String classpath =
	System.getProperty("java.class.path");

	private static final List<String> javaChildArgs =
	Arrays.asList(new String[]
	{ javaExe, "-classpath", classpath,
	"LoggingDeadlock2$JavaChild"});

	private static class ProcessResults {
	private final String out;
	private final String err;
	private final int exitValue;
	private final Throwable throwable;

	public ProcessResults(String out,
	String err,
	int exitValue,
	Throwable throwable) {
	this.out = out;
	this.err = err;
	this.exitValue = exitValue;
	this.throwable = throwable;
	}

	public String out() { return out; }
	public String err() { return err; }
	public int exitValue() { return exitValue; }

	public String toString() {
	StringBuilder sb = new StringBuilder();
	sb.append("<STDOUT>\n" + out() + "</STDOUT>\n")
	.append("<STDERR>\n" + err() + "</STDERR>\n")
	.append("exitValue = " + exitValue + "\n");
	if (throwable != null)
	sb.append(throwable.getStackTrace());
	return sb.toString();
	}
	}

	private static class StreamAccumulator extends Thread {
	private final InputStream is;
	private final StringBuilder sb = new StringBuilder();
	private Throwable throwable = null;

	public String result () throws Throwable {
	if (throwable != null)
	throw throwable;
	return sb.toString();
	}

	StreamAccumulator (InputStream is) {
	this.is = is;
	}

	public void run() {
	try {
	Reader r = new InputStreamReader(is);
	int n;
	while ((n = r.read()) > 0) {
	sb.append((char)n);

	// prints everything immediately to System.out so that we can
	// see the traces even in the event of a test timeout
	System.out.write((char)n);
	System.out.flush();

	}
	} catch (Throwable t) {
	throwable = t;
	} finally {
	try { is.close(); }
	catch (Throwable t) { throwable = t; }
	}
	}
	}

	/**
	* If the child process deadlocks, then the parent may fail in timeout.
	* In that case, we won't have any interesting traces, unless we manage
	* to get a thread dump from the child.
	* It is unsure whether obtaining a thread dump from a deadlocked child
	* will work - but maybe we could see something if the timeout is a false
	* positive (the child has not deadlocked but hasn't managed to fully start
	* yet, for instance).
	* The idea here is to periodically try to obtain a thread dump from the
	* child, every 60sec - which should be always less than the jtreg timeout.
	*/
	private static class TimeoutThread extends Thread {
	final long ms;
	final Process process;
	TimeoutThread(long ms, Process p) {
	super("TimeoutThread");
	setDaemon(true);
	this.ms = ms;
	this.process = p;
	}

	@Override
	public void run() {
	long start = System.nanoTime();
	try {
	while (true) {
	sleep(ms);
	System.err.println("Timeout reached: " + ms);
	if (process.isAlive()) {
	long pid = process.pid();
	ProcessBuilder jstack = new ProcessBuilder(jstackExe, String.valueOf(pid));
	System.err.println("Dumping subprocess stack: " + pid);
	Process p = jstack.inheritIO().start();
	p.waitFor(ms, TimeUnit.MILLISECONDS);
	} else {
	System.err.println("Process is not alive!");
	break;
	}
	}
	} catch (InterruptedException ex) {
	System.err.println("Interrupted: " + ex);
	} catch (IOException io) {
	System.err.println("Failed to get stack from subprocess");
	io.printStackTrace();
	}
	}


	}

	private static ProcessResults run(Process p) {
	Throwable throwable = null;
	int exitValue = -1;
	String out = "";
	String err = "";

	StreamAccumulator outAccumulator =
	new StreamAccumulator(p.getInputStream());
	StreamAccumulator errAccumulator =
	new StreamAccumulator(p.getErrorStream());

	try {
	System.out.println("Waiting for child process to exit");
	outAccumulator.start();
	errAccumulator.start();

	// ask subprocess to dump stack every 60 secs.
	new TimeoutThread(DUMP_STACK_FREQUENCY_MS, p).start();

	exitValue = p.waitFor();
	System.out.println("\nChild exited with status: " + exitValue);

	outAccumulator.join();
	errAccumulator.join();

	out = outAccumulator.result();
	err = errAccumulator.result();
	} catch (Throwable t) {
	throwable = t;
	}

	return new ProcessResults(out, err, exitValue, throwable);
	}

	//--------------------- Infrastructure ---------------------------
	static volatile int passed = 0, failed = 0;
	static void pass() {passed++;}
	static void fail() {failed++; Thread.dumpStack();}
	static void fail(String msg) {System.out.println(msg); fail();}
	static void unexpected(Throwable t) {failed++; t.printStackTrace();}
	static void check(boolean cond) {if (cond) pass(); else fail();}
	static void check(boolean cond, String m) {if (cond) pass(); else fail(m);}
	static void equal(Object x, Object y) {
	if (x == null ? y == null : x.equals(y)) pass();
	else fail(x + " not equal to " + y);}
	public static void main(String[] args) throws Throwable {
	try {realMain(args);} catch (Throwable t) {unexpected(t);}
	System.out.printf("%nPassed = %d, failed = %d%n%n", passed, failed);
	if (failed > 0) throw new AssertionError("Some tests failed");}
	}