1 /* 2 * Copyright (c) 2014, 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 */ 23 import java.io.File; 24 import java.io.PrintStream; 25 import java.lang.management.ManagementFactory; 26 import java.lang.management.ThreadInfo; 27 import java.security.Permission; 28 import java.security.Policy; 29 import java.security.ProtectionDomain; 30 import java.util.ArrayList; 31 import java.util.Collections; 32 import java.util.HashSet; 33 import java.util.List; 34 import java.util.Random; 35 import java.util.Set; 36 import java.util.concurrent.atomic.AtomicLong; 37 import java.util.logging.Level; 38 import java.util.logging.LogManager; 39 import java.util.logging.Logger; 40 41 42 /** 43 * @test 44 * @bug 8027670 8029281 45 * @summary Deadlock in drainLoggerRefQueueBounded / readConfiguration 46 * caused by synchronization issues in Logger and LogManager. 47 * @modules java.logging 48 * java.management 49 * @run main/othervm TestLogConfigurationDeadLockWithConf 50 * @author danielfuchs 51 * @key randomness 52 */ 53 // This test is a best effort to try & detect issues. The test itself will run 54 // for 8secs. This is usually sufficient to detect issues. 55 // However to get a greater confidence it is recommended to run this test in a loop: 56 // e.g. use something like: 57 // $ while jtreg -jdk:$JDK -verbose:all \ 58 // test/java/util/logging/TestLogConfigurationDeadLockWithConf.java ; \ 59 // do echo Running test again ; done 60 // and let it run for a few hours... 61 // 62 public class TestLogConfigurationDeadLockWithConf { 63 64 static volatile Exception thrown = null; 65 static volatile boolean goOn = true; 66 67 static final int READERS = 2; 68 static final int LOGGERS = 2; 69 static final long TIME = 4 * 1000; // 4 sec. 70 static final long STEP = 1 * 1000; // message every 1 sec. 71 static final int LCOUNT = 50; // 50 loggers created in a row... 72 static final AtomicLong nextLogger = new AtomicLong(0); 73 static final AtomicLong readCount = new AtomicLong(0); 74 static final AtomicLong checkCount = new AtomicLong(0); 75 76 /** 77 * This test will run both with and without a security manager. 78 * 79 * The test starts a number of threads that will call 80 * LogManager.readConfiguration() concurrently (ReadConf), then starts 81 * a number of threads that will create new loggers concurrently 82 * (AddLogger), and then two additional threads: one (Stopper) that 83 * will stop the test after 4secs (TIME ms), and one DeadlockDetector 84 * that will attempt to detect deadlocks. 85 * If after 4secs no deadlock was detected and no exception was thrown 86 * then the test is considered a success and passes. 87 * 88 * This procedure is done twice: once without a security manager and once 89 * again with a security manager - which means the test takes ~8secs to 90 * run. 91 * 92 * Note that 8sec may not be enough to detect issues if there are some. 93 * This is a best effort test. 94 * 95 * @param args the command line arguments 96 * @throws java.lang.Exception if the test fails. 97 */ main(String[] args)98 public static void main(String[] args) throws Exception { 99 File config = new File(System.getProperty("test.src", "."), 100 "deadlockconf.properties"); 101 if (!config.canRead()) { 102 System.err.println("Can't read config file: test cannot execute."); 103 System.err.println("Please check your test environment: "); 104 System.err.println("\t -Dtest.src=" + System.getProperty("test.src", ".")); 105 System.err.println("\t config file is: " + config.getAbsolutePath()); 106 throw new RuntimeException("Can't read config file: " 107 + config.getAbsolutePath()); 108 } 109 110 System.setProperty("java.util.logging.config.file", 111 config.getAbsolutePath()); 112 113 // test without security 114 System.out.println("No security"); 115 test(); 116 117 // test with security 118 System.out.println("\nWith security"); 119 Policy.setPolicy(new Policy() { 120 @Override 121 public boolean implies(ProtectionDomain domain, Permission permission) { 122 if (super.implies(domain, permission)) return true; 123 // System.out.println("Granting " + permission); 124 return true; // all permissions 125 } 126 }); 127 System.setSecurityManager(new SecurityManager()); 128 test(); 129 } 130 131 static Random rand = new Random(System.currentTimeMillis()); getBarCount()132 private static int getBarCount() { 133 return rand.nextInt(10); 134 } 135 136 /** 137 * Starts all threads, wait 4secs, then stops all threads. 138 * @throws Exception if a deadlock was detected or an error occurred. 139 */ test()140 public static void test() throws Exception { 141 goOn = true; 142 thrown = null; 143 long sNextLogger = nextLogger.get(); 144 long sReadCount = readCount.get(); 145 long sCheckCount = checkCount.get(); 146 List<Thread> threads = new ArrayList<>(); 147 for (int i = 0; i<READERS; i++) { 148 threads.add(new ReadConf()); 149 } 150 for (int i = 0; i<LOGGERS; i++) { 151 threads.add(new AddLogger()); 152 } 153 DeadlockDetector detector = new DeadlockDetector(); 154 threads.add(detector); 155 threads.add(0, new Stopper(TIME)); 156 for (Thread t : threads) { 157 t.start(); 158 } 159 160 // wait for the detector to finish. 161 detector.join(); 162 163 final PrintStream out = thrown == null ? System.out : System.err; 164 165 // Try to wait for all threads to finish. 166 // This is a best effort: if some threads are in deadlock we can't 167 // obviously wait for them, and other threads may have joined in 168 // the deadlock since we last checked. 169 // However, all threads which are succeptible of deadlocking 170 // extend DeamonThread. 171 for (Thread t : threads) { 172 if (t == detector) { 173 continue; 174 } 175 if (detector.deadlocked.contains(t.getId())) { 176 out.println("Skipping deadlocked thread " 177 + t.getClass().getSimpleName() + ": " + t); 178 continue; // don't wait for deadlocked thread: they won't terminate 179 } 180 try { 181 if (detector.deadlocked.isEmpty()) { 182 t.join(); 183 } else { 184 if (t instanceof DaemonThread) { 185 // Some other threads may have join the deadlock. 186 // don't wait forever. 187 t.join(100); 188 } else { 189 // Those threads that don't extend DaemonThread 190 // should be safe from deadlock. 191 out.println("Waiting for " 192 + t.getClass().getSimpleName() + ": " + t); 193 t.join(); 194 } 195 } 196 } catch (Exception x) { 197 fail(x); 198 } 199 } 200 out.println("All threads joined."); 201 202 final String status = thrown == null ? "Passed" : "FAILED"; 203 204 out.println(status + ": " + (nextLogger.get() - sNextLogger) 205 + " loggers created by " + LOGGERS + " Thread(s),"); 206 out.println("\t LogManager.readConfiguration() called " 207 + (readCount.get() - sReadCount) + " times by " + READERS 208 + " Thread(s)."); 209 out.println("\t ThreadMXBean.findDeadlockedThreads called " 210 + (checkCount.get() -sCheckCount) + " times by 1 Thread."); 211 212 if (thrown != null) { 213 out.println("\t Error is: "+thrown.getMessage()); 214 throw thrown; 215 } 216 } 217 218 static class DaemonThread extends Thread { DaemonThread()219 public DaemonThread() { 220 this.setDaemon(true); 221 } 222 } 223 224 static final class ReadConf extends DaemonThread { 225 @Override run()226 public void run() { 227 while (goOn) { 228 try { 229 LogManager.getLogManager().readConfiguration(); 230 readCount.incrementAndGet(); 231 Thread.sleep(1); 232 } catch (Exception x) { 233 fail(x); 234 } 235 } 236 } 237 } 238 239 static final class AddLogger extends DaemonThread { 240 @Override run()241 public void run() { 242 try { 243 while (goOn) { 244 Logger l; 245 int barcount = getBarCount(); 246 for (int i=0; i < LCOUNT ; i++) { 247 l = Logger.getLogger("foo.bar"+barcount+".l"+nextLogger.incrementAndGet()); 248 l.fine("I'm fine"); 249 if (!goOn) break; 250 Thread.sleep(1); 251 } 252 } 253 } catch (InterruptedException | RuntimeException x ) { 254 fail(x); 255 } 256 } 257 } 258 259 static final class DeadlockDetector extends Thread { 260 261 final Set<Long> deadlocked = Collections.synchronizedSet(new HashSet<Long>()); 262 asList(long... ids)263 static List<Long> asList(long... ids) { 264 final List<Long> list = new ArrayList<>(ids.length); 265 for (long id : ids) { 266 list.add(id); 267 } 268 return list; 269 } 270 271 @Override run()272 public void run() { 273 while(goOn) { 274 try { 275 long[] ids = ManagementFactory.getThreadMXBean().findDeadlockedThreads(); 276 checkCount.incrementAndGet(); 277 ids = ids == null ? new long[0] : ids; 278 if (ids.length > 0) { 279 deadlocked.addAll(asList(ids)); 280 } 281 if (ids.length == 1) { 282 throw new RuntimeException("Found 1 deadlocked thread: "+ids[0]); 283 } else if (ids.length > 0) { 284 ThreadInfo[] infos = ManagementFactory.getThreadMXBean().getThreadInfo(ids, Integer.MAX_VALUE); 285 System.err.println("Found "+ids.length+" deadlocked threads: "); 286 for (ThreadInfo inf : infos) { 287 System.err.println(inf.toString()); 288 } 289 throw new RuntimeException("Found "+ids.length+" deadlocked threads"); 290 } 291 Thread.sleep(100); 292 } catch(InterruptedException | RuntimeException x) { 293 fail(x); 294 } 295 } 296 } 297 298 } 299 300 static final class Stopper extends Thread { 301 long start; 302 long time; 303 304 static final Logger logger = Logger.getLogger("remaining"); 305 Stopper(long time)306 Stopper(long time) { 307 start = System.currentTimeMillis(); 308 this.time = time; 309 } 310 311 @Override run()312 public void run() { 313 try { 314 long rest, previous; 315 previous = time; 316 while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) { 317 if (previous == time || previous - rest >= STEP) { 318 logger.log(Level.INFO, 319 "{0}ms remaining...", String.valueOf(rest)); 320 previous = rest == time ? rest -1 : rest; 321 System.gc(); 322 } 323 if (goOn == false) break; 324 Thread.sleep(Math.min(rest, 100)); 325 } 326 System.out.println(System.currentTimeMillis() - start 327 + " ms elapsed ("+time+ " requested)"); 328 goOn = false; 329 } catch(InterruptedException | RuntimeException x) { 330 fail(x); 331 } 332 } 333 334 } 335 fail(Exception x)336 static void fail(Exception x) { 337 x.printStackTrace(); 338 if (thrown == null) { 339 thrown = x; 340 } 341 goOn = false; 342 } 343 } 344