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