1 /* 2 * Copyright (c) 2015, 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.IOException; 25 import java.lang.management.LockInfo; 26 import java.lang.management.ManagementFactory; 27 import java.lang.management.MonitorInfo; 28 import java.lang.management.ThreadInfo; 29 import java.security.Permission; 30 import java.security.Policy; 31 import java.security.ProtectionDomain; 32 import java.util.ArrayList; 33 import java.util.List; 34 import java.util.concurrent.atomic.AtomicLong; 35 import java.util.logging.Level; 36 import java.util.logging.LogManager; 37 import java.util.logging.Logger; 38 39 40 /** 41 * @test 42 * @bug 8077846 43 * @key randomness 44 * @summary Test that using a reentrant configuration lock does not introduce 45 * new synchronization issues in Logger and LogManager. This test 46 * focuses more particularly on potential deadlock in 47 * drainLoggerRefQueueBounded / readConfiguration / reset 48 * todo: add at randomness 49 * @modules java.logging 50 * java.management 51 * @run main/othervm TestConfigurationLock 52 * @author danielfuchs 53 */ 54 // This test is a best effort to try & detect issues. The test itself will run 55 // for 8secs. This might be unsufficient to detect issues. 56 // To get a greater confidence it is recommended to run this test in a loop: 57 // e.g. use something like: 58 // $ while jtreg -jdk:$JDK -verbose:all \ 59 // test/java/util/logging/TestConfigurationLock.java ; \ 60 // do echo Running test again ; done 61 // and let it run for a few hours... 62 // 63 public class TestConfigurationLock { 64 65 static volatile Exception thrown = null; 66 static volatile boolean goOn = true; 67 static volatile boolean deadlock = false; 68 69 static final double CONFSYNCTHRESHOLD = 0.3; 70 static final double LOGSYNCTHRESHOLD = 0.3; 71 static final int RESETERS = 0; 72 static final int READERS = 3; 73 static final int LOGGERS = 4; 74 static final long TIME = 8 * 1000; // 8 sec. 75 static final long STEP = 1 * 1000; // message every 1 sec. 76 static final int LCOUNT = 50; // 50 loggers created in a row... 77 static final AtomicLong nextLogger = new AtomicLong(0); 78 static final AtomicLong resetCount = new AtomicLong(0); 79 static final AtomicLong readCount = new AtomicLong(0); 80 static final AtomicLong checkCount = new AtomicLong(0); 81 82 static final String BLAH = "blah"; 83 fakeConfExternalLock()84 static Object fakeConfExternalLock() { 85 return LogManager.getLogManager(); 86 } 87 fakeLogExternalLock()88 static Object fakeLogExternalLock() { 89 return LogManager.getLogManager(); 90 } 91 92 93 /** 94 * This test will run both with and without a security manager. 95 * 96 * The test starts a number of threads that will call 97 * LogManager.reset() concurrently (ResetConf), and a number of threads 98 * that will call readConfiguration() (ReadConf), and then starts a 99 * number of threads that will create new loggers concurrently 100 * (AddLogger), and finally two additional threads: 101 * - one (Stopper) that will stop the test after 4secs (TIME ms), 102 * - and one DeadlockDetector that will attempt to detect deadlocks. 103 * If after 4secs no deadlock was detected and no exception was thrown 104 * then the test is considered a success and passes. 105 * 106 * This procedure is done twice: once without a security manager and once 107 * again with a security manager - which means the test takes ~8secs to 108 * run. 109 * 110 * Note that 8sec may not be enough to detect issues if there are some. 111 * This is a best effort test. 112 * 113 * @param args the command line arguments 114 * @throws java.lang.Exception if the test fails 115 */ main(String[] args)116 public static void main(String[] args) throws Exception { 117 118 File conf = new File(System.getProperty("test.src", "./src"), 119 TestConfigurationLock.class.getSimpleName() + ".properties"); 120 if (!conf.canRead()) { 121 throw new IOException("Can't read config file: " + conf.getAbsolutePath()); 122 } 123 System.setProperty("java.util.logging.config.file", conf.getAbsolutePath()); 124 // test without security 125 System.out.println("No security"); 126 test(); 127 128 // test with security 129 System.out.println("\nWith security"); 130 Policy.setPolicy(new Policy() { 131 @Override 132 public boolean implies(ProtectionDomain domain, Permission permission) { 133 if (super.implies(domain, permission)) return true; 134 // System.out.println("Granting " + permission); 135 return true; // all permissions 136 } 137 }); 138 System.setSecurityManager(new SecurityManager()); 139 test(); 140 } 141 142 143 /** 144 * Starts all threads, wait 4secs, then stops all threads. 145 * @throws Exception if a deadlock was detected or an error occurred. 146 */ test()147 public static void test() throws Exception { 148 goOn = true; 149 thrown = null; 150 long sNextLogger = nextLogger.get(); 151 long sUpdateCount = resetCount.get(); 152 long sReadCount = readCount.get(); 153 long sCheckCount = checkCount.get(); 154 List<Thread> threads = new ArrayList<>(); 155 for (int i = 0; i<RESETERS; i++) { 156 threads.add(new ResetConf()); 157 } 158 for (int i = 0; i<READERS; i++) { 159 threads.add(new ReadConf()); 160 } 161 for (int i = 0; i<LOGGERS; i++) { 162 threads.add(new AddLogger()); 163 } 164 threads.add(0, new Stopper(TIME)); 165 threads.stream().forEach(Thread::start); 166 167 Thread deadLockDetector = new DeadlockDetector(); 168 deadLockDetector.start(); 169 deadLockDetector.join(); 170 171 if (!deadlock) { 172 threads.stream().forEach(TestConfigurationLock::join); 173 } else { 174 System.err.println("Deadlock found: exiting forcibly."); 175 Runtime.getRuntime().halt(-1); 176 } 177 178 if (thrown != null) { 179 throw thrown; 180 } 181 System.out.println("Passed: " + (nextLogger.get() - sNextLogger) 182 + " loggers created by " + LOGGERS + " Thread(s),"); 183 System.out.println("\t LogManager.reset() called " 184 + (resetCount.get() - sUpdateCount) + " times by " + RESETERS 185 + " Thread(s)."); 186 System.out.println("\t LogManager.readConfiguration() called " 187 + (readCount.get() - sReadCount) + " times by " + READERS 188 + " Thread(s)."); 189 System.out.println("\t ThreadMXBean.findDeadlockedThreads called " 190 + (checkCount.get() -sCheckCount) + " times by 1 Thread."); 191 192 } 193 join(Thread t)194 static void join(Thread t) { 195 try { 196 t.join(); 197 } catch (Exception x) { 198 fail(x); 199 } 200 } 201 202 static final class ResetConf extends Thread { 203 ResetConf()204 public ResetConf() { 205 setDaemon(true); 206 } 207 208 @Override run()209 public void run() { 210 while (goOn) { 211 try { 212 if (Math.random() > CONFSYNCTHRESHOLD) { 213 // calling reset while holding a lock can increase 214 // deadlock probability... 215 synchronized(fakeConfExternalLock()) { 216 LogManager.getLogManager().reset(); 217 } 218 } else { 219 LogManager.getLogManager().reset(); 220 } 221 Logger blah = Logger.getLogger(BLAH); 222 blah.setLevel(Level.FINEST); 223 blah.fine(BLAH); 224 resetCount.incrementAndGet(); 225 pause(1); 226 } catch (Exception x) { 227 fail(x); 228 } 229 } 230 } 231 } 232 233 static final class ReadConf extends Thread { 234 ReadConf()235 public ReadConf() { 236 setDaemon(true); 237 } 238 239 @Override run()240 public void run() { 241 while (goOn) { 242 try { 243 if (Math.random() > CONFSYNCTHRESHOLD) { 244 // calling readConfiguration while holding a lock can 245 // increase deadlock probability... 246 synchronized(fakeConfExternalLock()) { 247 LogManager.getLogManager().readConfiguration(); 248 } 249 } else { 250 LogManager.getLogManager().readConfiguration(); 251 } 252 Logger blah = Logger.getLogger(BLAH); 253 blah.setLevel(Level.FINEST); 254 blah.fine(BLAH); 255 readCount.incrementAndGet(); 256 pause(1); 257 } catch (Exception x) { 258 fail(x); 259 } 260 } 261 } 262 } 263 264 static final class AddLogger extends Thread { 265 AddLogger()266 public AddLogger() { 267 setDaemon(true); 268 } 269 270 @Override run()271 public void run() { 272 try { 273 while (goOn) { 274 Logger l; 275 Logger foo = Logger.getLogger("foo"); 276 Logger bar = Logger.getLogger("foo.bar"); 277 for (int i=0; i < LCOUNT ; i++) { 278 LogManager manager = LogManager.getLogManager(); 279 if (Math.random() > LOGSYNCTHRESHOLD) { 280 synchronized(fakeLogExternalLock()) { 281 l = Logger.getLogger("foo.bar.l"+nextLogger.incrementAndGet()); 282 } 283 } else { 284 l = Logger.getLogger("foo.bar.l"+nextLogger.incrementAndGet()); 285 } 286 l.setLevel(Level.FINEST); 287 l.fine("I'm fine"); 288 if (!goOn) break; 289 pause(1); 290 } 291 } 292 } catch (InterruptedException | RuntimeException x ) { 293 fail(x); 294 } 295 } 296 } 297 298 static final class DeadlockDetector extends Thread { 299 300 @Override run()301 public void run() { 302 boolean deadlock = false; 303 while(goOn) { 304 try { 305 long[] ids = ManagementFactory.getThreadMXBean().findDeadlockedThreads(); 306 checkCount.incrementAndGet(); 307 ids = ids == null ? new long[0] : ids; 308 if (ids.length == 1) { 309 throw new RuntimeException("Found 1 deadlocked thread: "+ids[0]); 310 } else if (ids.length > 0) { 311 deadlock = true; 312 ThreadInfo[] infos = ManagementFactory.getThreadMXBean() 313 .getThreadInfo(ids, true, true); 314 System.err.println("Found "+ids.length+" deadlocked threads: "); 315 for (ThreadInfo inf : infos) { 316 System.err.println(asString(inf)); 317 } 318 throw new RuntimeException("Found "+ids.length+" deadlocked threads"); 319 } 320 pause(100); 321 } catch(InterruptedException | RuntimeException x) { 322 if (deadlock) deadlock(x); 323 else fail(x); 324 } 325 } 326 } 327 328 } 329 330 static final class Stopper extends Thread { 331 long start; 332 long time; 333 Stopper(long time)334 Stopper(long time) { 335 start = System.currentTimeMillis(); 336 this.time = time; 337 setDaemon(true); 338 } 339 340 @Override run()341 public void run() { 342 try { 343 long rest, previous; 344 int msgCount = 0; 345 previous = time; 346 Logger logger = Logger.getLogger("remaining"); 347 while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) { 348 if (previous == time || previous - rest >= STEP) { 349 logger.log(Level.INFO, "{0}ms remaining...", String.valueOf(rest)); 350 msgCount++; 351 previous = rest == time ? rest -1 : rest; 352 System.gc(); 353 } 354 if (goOn == false) break; 355 pause(Math.min(rest, 100)); 356 } 357 System.err.println(this + ": " + msgCount + " messages."); 358 System.err.flush(); 359 System.out.println(System.currentTimeMillis() - start 360 + " ms elapsed ("+time+ " requested)"); 361 goOn = false; 362 } catch(InterruptedException | RuntimeException x) { 363 fail(x); 364 } 365 } 366 367 } 368 369 // ThreadInfo.toString() only prints 8 frames... asString(ThreadInfo inf)370 static String asString(ThreadInfo inf) { 371 StringBuilder sb = new StringBuilder(); 372 sb.append("\"").append(inf.getThreadName()).append("\"") 373 .append(inf.isDaemon() ? " daemon" : "") 374 .append(" prio=").append(inf.getPriority()) 375 .append(" Id=").append(inf.getThreadId()) 376 .append(" ").append(inf.getThreadState()); 377 if (inf.getLockName() != null) { 378 sb.append(" on ").append(inf.getLockName()); 379 } 380 if (inf.getLockOwnerName() != null) { 381 sb.append(" owned by \"").append(inf.getLockOwnerName()) 382 .append("\" Id=").append(inf.getLockOwnerId()); 383 } 384 if (inf.isSuspended()) { 385 sb.append(" (suspended)"); 386 } 387 if (inf.isInNative()) { 388 sb.append(" (in native)"); 389 } 390 sb.append('\n'); 391 int i = 0; 392 StackTraceElement[] stackTrace = inf.getStackTrace(); 393 for (; i < stackTrace.length; i++) { 394 StackTraceElement ste = stackTrace[i]; 395 sb.append("\tat ").append(ste.toString()); 396 sb.append('\n'); 397 if (i == 0 && inf.getLockInfo() != null) { 398 Thread.State ts = inf.getThreadState(); 399 switch (ts) { 400 case BLOCKED: 401 sb.append("\t- blocked on ").append(inf.getLockInfo()); 402 sb.append('\n'); 403 break; 404 case WAITING: 405 sb.append("\t- waiting on ").append(inf.getLockInfo()); 406 sb.append('\n'); 407 break; 408 case TIMED_WAITING: 409 sb.append("\t- waiting on ").append(inf.getLockInfo()); 410 sb.append('\n'); 411 break; 412 default: 413 } 414 } 415 416 for (MonitorInfo mi : inf.getLockedMonitors()) { 417 if (mi.getLockedStackDepth() == i) { 418 sb.append("\t- locked ").append(mi); 419 sb.append('\n'); 420 } 421 } 422 } 423 if (i < stackTrace.length) { 424 sb.append("\t..."); 425 sb.append('\n'); 426 } 427 428 LockInfo[] locks = inf.getLockedSynchronizers(); 429 if (locks.length > 0) { 430 sb.append("\n\tNumber of locked synchronizers = ").append(locks.length); 431 sb.append('\n'); 432 for (LockInfo li : locks) { 433 sb.append("\t- ").append(li); 434 sb.append('\n'); 435 } 436 } 437 sb.append('\n'); 438 return sb.toString(); 439 } 440 pause(long millis)441 static void pause(long millis) throws InterruptedException { 442 Thread.sleep(millis); 443 } 444 fail(Exception x)445 static void fail(Exception x) { 446 x.printStackTrace(System.err); 447 if (thrown == null) { 448 thrown = x; 449 } 450 goOn = false; 451 } 452 deadlock(Exception x)453 static void deadlock(Exception x) { 454 deadlock = true; 455 System.out.flush(); 456 fail(x); 457 System.err.flush(); 458 } 459 } 460