1/*
2 * Copyright (c) 2013, 2016, 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 */
23import java.lang.management.ManagementFactory;
24import java.lang.management.ThreadInfo;
25import java.security.Permission;
26import java.security.Policy;
27import java.security.ProtectionDomain;
28import java.util.ArrayList;
29import java.util.List;
30import java.util.concurrent.atomic.AtomicLong;
31import java.util.logging.LogManager;
32import java.util.logging.Logger;
33
34
35/**
36 * @test
37 * @bug 8029281 8027670
38 * @summary Synchronization issues in Logger and LogManager. This test
39 *       focusses more particularly on potential deadlock in
40 *       drainLoggerRefQueueBounded / readConfiguration
41 * @modules java.logging
42 *          java.management
43 * @run main/othervm TestLogConfigurationDeadLock
44 * @author danielfuchs
45 */
46// This test is a best effort to try & detect issues. The test itself will run
47// for 8secs. This is usually unsufficient to detect issues.
48// To get a greater confidence it is recommended to run this test in a loop:
49// e.g. use something like:
50// $ while jtreg -jdk:$JDK -verbose:all  \
51//      test/java/util/logging/TestLogConfigurationDeadLock.java ; \
52//      do echo Running test again ; done
53// and let it run for a few hours...
54//
55public class TestLogConfigurationDeadLock {
56
57    static volatile Exception thrown = null;
58    static volatile boolean goOn = true;
59
60    static final int READERS = 2;
61    static final int LOGGERS = 2;
62    static final long TIME = 4 * 1000; // 4 sec.
63    static final long STEP = 1 * 1000;  // message every 1 sec.
64    static final int  LCOUNT = 50; // 50 loggers created in a row...
65    static final AtomicLong nextLogger = new AtomicLong(0);
66    static final AtomicLong readCount = new AtomicLong(0);
67    static final AtomicLong checkCount = new AtomicLong(0);
68
69    /**
70     * This test will run both with and without a security manager.
71     *
72     * The test starts a number of threads that will call
73     *     LogManager.readConfiguration() concurrently (ReadConf), then starts
74     *     a number of threads that will create new loggers concurrently
75     *     (AddLogger), and then two additional threads: one (Stopper) that
76     *     will stop the test after 4secs (TIME ms), and one DeadlockDetector
77     *     that will attempt to detect deadlocks.
78     * If after 4secs no deadlock was detected and no exception was thrown
79     * then the test is considered a success and passes.
80     *
81     * This procedure is done twice: once without a security manager and once
82     * again with a security manager - which means the test takes ~8secs to
83     * run.
84     *
85     * Note that 8sec may not be enough to detect issues if there are some.
86     * This is a best effort test.
87     *
88     * @param args the command line arguments
89     */
90    public static void main(String[] args) throws Exception {
91
92        // test without security
93        System.out.println("No security");
94        test();
95
96        // test with security
97        System.out.println("\nWith security");
98        Policy.setPolicy(new Policy() {
99            @Override
100            public boolean implies(ProtectionDomain domain, Permission permission) {
101                if (super.implies(domain, permission)) return true;
102                // System.out.println("Granting " + permission);
103                return true; // all permissions
104            }
105        });
106        System.setSecurityManager(new SecurityManager());
107        test();
108    }
109
110    /**
111     * Starts all threads, wait 4secs, then stops all threads.
112     * @throws Exception if a deadlock was detected or an error occurred.
113     */
114    public static void test() throws Exception {
115          goOn = true;
116          thrown = null;
117          long sNextLogger = nextLogger.get();
118          long sReadCount  = readCount.get();
119          long sCheckCount = checkCount.get();
120          List<Thread> threads = new ArrayList<>();
121          for (int i = 0; i<READERS; i++) {
122              threads.add(new ReadConf());
123          }
124          for (int i = 0; i<LOGGERS; i++) {
125              threads.add(new AddLogger());
126          }
127          threads.add(new DeadlockDetector());
128          threads.add(0, new Stopper(TIME));
129          for (Thread t : threads) {
130              t.start();
131          }
132          for (Thread t : threads) {
133              try {
134                  t.join();
135              } catch (Exception x) {
136                  fail(x);
137              }
138          }
139          if (thrown != null) {
140              throw thrown;
141          }
142          System.out.println("Passed: " + (nextLogger.get() - sNextLogger)
143                  + " loggers created by " + LOGGERS + " Thread(s),");
144          System.out.println("\t LogManager.readConfiguration() called "
145                  + (readCount.get() - sReadCount) + " times by " + READERS
146                  + " Thread(s).");
147          System.out.println("\t ThreadMXBean.findDeadlockedThreads called "
148                  + (checkCount.get() -sCheckCount) + " times by 1 Thread.");
149
150    }
151
152
153    static final class ReadConf extends Thread {
154        @Override
155        public void run() {
156            while (goOn) {
157                try {
158                    LogManager.getLogManager().readConfiguration();
159                    readCount.incrementAndGet();
160                    Thread.sleep(1);
161                } catch (Exception x) {
162                    fail(x);
163                }
164            }
165        }
166    }
167
168    static final class AddLogger extends Thread {
169        @Override
170        public void run() {
171            try {
172                while (goOn) {
173                    Logger l;
174                    Logger foo = Logger.getLogger("foo");
175                    Logger bar = Logger.getLogger("foo.bar");
176                    for (int i=0; i < LCOUNT ; i++) {
177                        l = Logger.getLogger("foo.bar.l"+nextLogger.incrementAndGet());
178                        l.fine("I'm fine");
179                        if (!goOn) break;
180                        Thread.sleep(1);
181                    }
182                }
183            } catch (InterruptedException | RuntimeException x ) {
184                fail(x);
185            }
186        }
187    }
188
189    static final class DeadlockDetector extends Thread {
190
191        @Override
192        public void run() {
193            while(goOn) {
194                try {
195                    long[] ids = ManagementFactory.getThreadMXBean().findDeadlockedThreads();
196                    checkCount.incrementAndGet();
197                    ids = ids == null ? new long[0] : ids;
198                    if (ids.length == 1) {
199                        throw new RuntimeException("Found 1 deadlocked thread: "+ids[0]);
200                    } else if (ids.length > 0) {
201                        ThreadInfo[] infos = ManagementFactory.getThreadMXBean()
202                            .getThreadInfo(ids, Integer.MAX_VALUE);
203                        System.err.println("Found "+ids.length+" deadlocked threads: ");
204                        for (ThreadInfo inf : infos) {
205                            System.err.println(inf.toString());
206                        }
207                        throw new RuntimeException("Found "+ids.length+" deadlocked threads");
208                    }
209                    Thread.sleep(100);
210                } catch(InterruptedException | RuntimeException x) {
211                    fail(x);
212                }
213            }
214        }
215
216    }
217
218    static final class Stopper extends Thread {
219        long start;
220        long time;
221
222        Stopper(long time) {
223            start = System.currentTimeMillis();
224            this.time = time;
225        }
226
227        @Override
228        public void run() {
229            try {
230                long rest, previous;
231                previous = time;
232                while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) {
233                    if (previous == time || previous - rest >= STEP) {
234                        Logger.getLogger("remaining").info(String.valueOf(rest)+"ms remaining...");
235                        previous = rest == time ? rest -1 : rest;
236                        System.gc();
237                    }
238                    if (goOn == false) break;
239                    Thread.sleep(Math.min(rest, 100));
240                }
241                System.out.println(System.currentTimeMillis() - start
242                        + " ms elapsed ("+time+ " requested)");
243                goOn = false;
244            } catch(InterruptedException | RuntimeException x) {
245                fail(x);
246            }
247        }
248
249    }
250
251    static void fail(Exception x) {
252        x.printStackTrace();
253        if (thrown == null) {
254            thrown = x;
255        }
256        goOn = false;
257    }
258}
259