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