util/logging/LoggingDeadlock2.java

/*
 * 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");}
}