test/jdk/java/util/logging/LoggingDeadlock2.java
changeset 47216 71c04702a3d5
parent 44640 590dec7cadb4
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/test/jdk/java/util/logging/LoggingDeadlock2.java	Tue Sep 12 19:03:39 2017 +0200
@@ -0,0 +1,336 @@
+/*
+ * 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");}
+}