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 */ 23 24import java.lang.management.ManagementFactory; 25import java.lang.management.ThreadInfo; 26import java.security.Permission; 27import java.security.Policy; 28import java.security.ProtectionDomain; 29import java.util.ArrayList; 30import java.util.List; 31import java.util.ListResourceBundle; 32import java.util.Objects; 33import java.util.ResourceBundle; 34import java.util.concurrent.Callable; 35import java.util.concurrent.ExecutorService; 36import java.util.concurrent.Executors; 37import java.util.concurrent.FutureTask; 38import java.util.concurrent.atomic.AtomicLong; 39import java.util.logging.Handler; 40import java.util.logging.Level; 41import java.util.logging.LogRecord; 42import java.util.logging.Logger; 43 44/** 45 * @test 46 * @bug 8029281 8028763 47 * @summary Attempts to detect synchronization issues with getResourceBundle() 48 * and getResourceBundleName(). It might also detect issues in the way 49 * that the logger tree is cleaned up after a logger has been garbage 50 * collected. This test helped find the root cause of 8029092, so if 51 * this test fails one might also expect failures in 52 * java/util/logging/Logger/logrb/TestLogrbResourceBundle.java and 53 * java/util/logging/Logger/setResourceBundle/TestSetResourceBundle.java. 54 * Note that this is a best effort test. Running it in a loop to 55 * reproduce intermittent issues can be a good idea. 56 * @modules java.logging 57 * java.management 58 * @run main/othervm TestLoggerBundleSync 59 * @author danielfuchs 60 */ 61public class TestLoggerBundleSync { 62 63 static final boolean VERBOSE = false; 64 static volatile Exception thrown = null; 65 static volatile boolean goOn = true; 66 67 static final int READERS = 3; 68 static final long TIME = 4 * 1000; // 4 sec. 69 static final long STEP = 1 * 1000; // message every 1 sec. 70 static final int LCOUNT = 50; // change bundle 50 times... 71 static final AtomicLong ignoreLogCount = new AtomicLong(0); 72 static final AtomicLong setRBcount = new AtomicLong(0); 73 static final AtomicLong setRBNameCount = new AtomicLong(0); 74 static final AtomicLong getRBcount = new AtomicLong(0); 75 static final AtomicLong checkCount = new AtomicLong(0); 76 static final AtomicLong nextLong = new AtomicLong(0); 77 78 public static class MyBundle extends ListResourceBundle { 79 @Override 80 protected Object[][] getContents() { 81 return new Object[][] { 82 {"dummy", "foo"} 83 }; 84 } 85 } 86 87 public static final class MyBundle1 extends MyBundle { }; 88 public static final class MyBundle2 extends MyBundle { }; 89 public static final class MyBundle3 extends MyBundle { }; 90 91 92 public static final class LoggerRB { 93 public final String resourceBundleName; 94 public final ResourceBundle userBundle; 95 public LoggerRB(String name, ResourceBundle bundle) { 96 resourceBundleName = name; 97 userBundle = bundle; 98 } 99 } 100 101 static final List<Class<? extends ResourceBundle>> classes = new ArrayList<>(); 102 static { 103 classes.add(MyBundle1.class); 104 classes.add(MyBundle2.class); 105 classes.add(MyBundle3.class); 106 } 107 108 109 /** 110 * This test will run both with and without a security manager. 111 * 112 * The test starts a number of threads that will attempt to concurrently 113 * set resource bundles on Logger, and verifies the consistency of the 114 * obtained results. 115 * 116 * This is a best effort test. 117 * 118 * @param args the command line arguments 119 */ 120 public static void main(String[] args) throws Exception { 121 122 try { 123 // test without security 124 System.out.println("No security"); 125 test(); 126 127 // test with security 128 System.out.println("\nWith security"); 129 Policy.setPolicy(new Policy() { 130 @Override 131 public boolean implies(ProtectionDomain domain, Permission permission) { 132 if (super.implies(domain, permission)) return true; 133 // System.out.println("Granting " + permission); 134 return true; // all permissions 135 } 136 }); 137 System.setSecurityManager(new SecurityManager()); 138 test(); 139 } finally { 140 SetRB.executor.shutdownNow(); 141 SetRBName.executor.shutdownNow(); 142 } 143 } 144 145 /** 146 * Starts all threads, wait 15secs, then stops all threads. 147 * @throws Exception if a deadlock was detected or an error occurred. 148 */ 149 public static void test() throws Exception { 150 goOn = true; 151 thrown = null; 152 long sGetRBCount = getRBcount.get(); 153 long sSetRBCount = setRBcount.get(); 154 long sSetRBNameCount = setRBNameCount.get(); 155 long sCheckCount = checkCount.get(); 156 long sNextLong = nextLong.get(); 157 long sIgnoreLogCount = ignoreLogCount.get(); 158 List<Thread> threads = new ArrayList<>(); 159 for (Class<? extends ResourceBundle> type : classes) { 160 threads.add(new SetRB(type)); 161 threads.add(new SetRBName(type)); 162 } 163 for (int i =0 ; i < READERS ; i++) { 164 threads.add(new GetRB()); 165 } 166 threads.add(new DeadlockDetector()); 167 threads.add(0, new Stopper(TIME)); 168 for (Thread t : threads) { 169 t.start(); 170 } 171 for (Thread t : threads) { 172 try { 173 t.join(); 174 } catch (Exception x) { 175 fail(x); 176 } 177 } 178 if (thrown != null) { 179 throw thrown; 180 } 181 System.out.println("Passed: " + (nextLong.longValue() - sNextLong) 182 + " unique loggers created"); 183 System.out.println("\t " +(getRBcount.get() - sGetRBCount) 184 + " loggers tested by " + READERS + " Thread(s),"); 185 System.out.println("\t " + (setRBcount.get() - sSetRBCount) 186 + " resource bundles set by " + classes.size() + " Thread(s),"); 187 System.out.println("\t " + (setRBNameCount.get() - sSetRBNameCount) 188 + " resource bundle names set by " + classes.size() + " Thread(s),"); 189 System.out.println("\t " + (ignoreLogCount.get() - sIgnoreLogCount) 190 + " log messages emitted by other GetRB threads were ignored" 191 + " to ensure MT test consistency,"); 192 System.out.println("\t ThreadMXBean.findDeadlockedThreads called " 193 + (checkCount.get() -sCheckCount) + " times by 1 Thread."); 194 195 } 196 197 static final class GetRB extends Thread { 198 final class MyHandler extends Handler { 199 volatile ResourceBundle rb; 200 volatile String rbName; 201 volatile int count = 0; 202 @Override 203 public synchronized void publish(LogRecord record) { 204 Object[] params = record.getParameters(); 205 // Each GetRB thread has its own handler, but since they 206 // log into the same logger, each handler may receive 207 // messages emitted by other threads. 208 // This means that GetRB#2.handler may receive a message 209 // emitted by GetRB#1 at a time where the resource bundle 210 // was still null. 211 // To avoid falling into this trap, the GetRB thread passes 212 // 'this' as argument to the messages it logs - which does 213 // allow us here to ignore messages that where not emitted 214 // by our own GetRB.this thread... 215 if (params.length == 1) { 216 if (params[0] == GetRB.this) { 217 // The message was emitted by our thread. 218 count++; 219 rb = record.getResourceBundle(); 220 rbName = record.getResourceBundleName(); 221 } else { 222 // The message was emitted by another thread: just 223 // ignore it, as it may have been emitted at a time 224 // where the resource bundle was still null, and 225 // processing it may overwrite the 'rb' and 'rbName' 226 // recorded from the message emitted by our own thread. 227 if (VERBOSE) { 228 System.out.println("Ignoring message logged by " + params[0]); 229 } 230 ignoreLogCount.incrementAndGet(); 231 } 232 } else { 233 ignoreLogCount.incrementAndGet(); 234 System.err.println("Unexpected message received"); 235 } 236 } 237 238 void reset() { 239 rbName = null; 240 rb = null; 241 } 242 243 @Override 244 public void flush() { 245 } 246 247 @Override 248 public void close() throws SecurityException { 249 } 250 }; 251 final MyHandler handler = new MyHandler(); 252 253 @Override 254 public void run() { 255 try { 256 handler.setLevel(Level.FINEST); 257 while (goOn) { 258 Logger l; 259 Logger foo = Logger.getLogger("foo"); 260 Logger bar = Logger.getLogger("foo.bar"); 261 for (long i=0; i < nextLong.longValue() + 100 ; i++) { 262 if (!goOn) break; 263 l = Logger.getLogger("foo.bar.l"+i); 264 final ResourceBundle b = l.getResourceBundle(); 265 final String name = l.getResourceBundleName(); 266 if (b != null) { 267 if (!name.equals(b.getBaseBundleName())) { 268 throw new RuntimeException("Unexpected bundle name: " 269 +b.getBaseBundleName()); 270 } 271 } 272 Logger ll = Logger.getLogger(l.getName()+".bie.bye"); 273 ResourceBundle hrb; 274 String hrbName; 275 if (handler.getLevel() != Level.FINEST) { 276 throw new RuntimeException("Handler level is not finest: " 277 + handler.getLevel()); 278 } 279 final int countBefore = handler.count; 280 handler.reset(); 281 ll.setLevel(Level.FINEST); 282 ll.addHandler(handler); 283 ll.log(Level.FINE, "dummy {0}", this); 284 ll.removeHandler(handler); 285 final int countAfter = handler.count; 286 if (countBefore == countAfter) { 287 throw new RuntimeException("Handler not called for " 288 + ll.getName() + "("+ countAfter +")"); 289 } 290 hrb = handler.rb; 291 hrbName = handler.rbName; 292 if (name != null) { 293 // if name is not null, then it implies that it 294 // won't change, since setResourceBundle() cannot 295 // replace a non null name. 296 // Since we never set the resource bundle on 'll', 297 // then ll must inherit its resource bundle [name] 298 // from l - and therefor we should find it in 299 // handler.rb/handler.rbName 300 if (!name.equals(hrbName)) { 301 throw new RuntimeException("Unexpected bundle name: " 302 +hrbName); 303 } 304 // here we know that hrbName is not null so hrb 305 // should not be null either. 306 if (!name.equals(hrb.getBaseBundleName())) { 307 throw new RuntimeException("Unexpected bundle name: " 308 +hrb.getBaseBundleName()); 309 } 310 } 311 312 // Make sure to refer to 'l' explicitly in order to 313 // prevent eager garbage collecting before the end of 314 // the test (JDK-8030192) 315 if (!ll.getName().startsWith(l.getName())) { 316 throw new RuntimeException("Logger " + ll.getName() 317 + "does not start with expected prefix " 318 + l.getName()); 319 } 320 321 getRBcount.incrementAndGet(); 322 if (!goOn) break; 323 Thread.sleep(1); 324 } 325 } 326 } catch (Exception x) { 327 fail(x); 328 } 329 } 330 } 331 332 static final class SetRB extends Thread { 333 final Class<? extends ResourceBundle> type; 334 static final ExecutorService executor = Executors.newSingleThreadExecutor(); 335 static final class CheckRBTask implements Callable<Exception> { 336 final Logger logger; 337 volatile String rbName; 338 volatile ResourceBundle rb; 339 340 public CheckRBTask(Logger logger) { 341 this.logger = logger; 342 } 343 344 @Override 345 public Exception call() throws Exception { 346 try { 347 final String name = logger.getResourceBundleName(); 348 if (!Objects.equals(name, rbName)) { 349 throw new RuntimeException("Unexpected rbname for " 350 + logger.getName() + ": " + name); 351 } 352 final ResourceBundle b = logger.getResourceBundle(); 353 if (b != rb) { 354 throw new RuntimeException("Unexpected rb for " 355 + logger.getName() + ": " + b); 356 } 357 } catch(Exception x) { 358 return x; 359 } 360 return null; 361 } 362 363 public void check() throws Exception { 364 final FutureTask<Exception> futureTask = new FutureTask<>(this); 365 executor.submit(futureTask); 366 Exception x = futureTask.get(); 367 if ( x != null) { 368 throw new RuntimeException("Check failed: "+x,x); 369 } 370 } 371 } 372 SetRB(Class<? extends ResourceBundle> type) { 373 super("SetRB["+type.getSimpleName()+"]"); 374 this.type = type; 375 } 376 @Override 377 public void run() { 378 try { 379 while (goOn) { 380 Logger l; 381 Logger foo = Logger.getLogger("foo"); 382 Logger bar = Logger.getLogger("foo.bar"); 383 l = Logger.getLogger("foo.bar.l"+nextLong.incrementAndGet()); 384 final CheckRBTask checkTask = new CheckRBTask(l); 385 checkTask.check(); 386 387 for (int i=0; i < LCOUNT ; i++) { 388 if (!goOn) break; 389 390 ResourceBundle b = ResourceBundle.getBundle(type.getName()); 391 try { 392 l.setResourceBundle(b); 393 checkTask.rb = b; 394 checkTask.rbName = type.getName(); 395 checkTask.check(); 396 if (!goOn) break; 397 398 String name = l.getResourceBundleName(); 399 ResourceBundle bb = l.getResourceBundle(); 400 if (!type.getName().equals(name)) { 401 throw new RuntimeException(this.getName() 402 + ": Unexpected name: "+name); 403 } 404 if (!b.getBaseBundleName().equals(name)) { 405 throw new RuntimeException(this.getName() 406 + ": Unexpected base name: " + 407 b.getBaseBundleName()); 408 } 409 if (b != bb) { 410 throw new RuntimeException(this.getName() 411 + ": Unexpected bundle: "+bb); 412 } 413 setRBcount.incrementAndGet(); 414 } catch (IllegalArgumentException x) { 415 final String name = l.getResourceBundleName(); 416 if (!name.startsWith(MyBundle.class.getName())) { 417 throw new RuntimeException(this.getName() 418 + ": Unexpected name: "+name, x); 419 } else if (type.getName().equals(name)) { 420 throw new RuntimeException(this.getName() 421 + ": Unexpected exception for "+name, x); 422 } 423 throw x; 424 } 425 l.fine("I'm fine"); 426 if (!goOn) break; 427 Thread.sleep(1); 428 } 429 } 430 } catch (Exception x) { 431 fail(x); 432 } 433 } 434 } 435 436 static final class SetRBName extends Thread { 437 int nexti = 0; 438 final Class<? extends ResourceBundle> type; 439 static final ExecutorService executor = Executors.newSingleThreadExecutor(); 440 static final class CheckRBNameTask implements Callable<Exception> { 441 final Logger logger; 442 volatile String rbName; 443 444 public CheckRBNameTask(Logger logger) { 445 this.logger = logger; 446 } 447 448 @Override 449 public Exception call() throws Exception { 450 try { 451 final String name = logger.getResourceBundleName(); 452 if (!Objects.equals(name, rbName)) { 453 throw new RuntimeException("Unexpected rbname for " 454 + logger.getName() + ": " + name); 455 } 456 final ResourceBundle b = logger.getResourceBundle(); 457 if (!Objects.equals(b == null ? null : b.getBaseBundleName(), rbName)) { 458 throw new RuntimeException("Unexpected base name for " 459 + logger.getName() + ": " + b.getBaseBundleName()); 460 } 461 } catch(Exception x) { 462 return x; 463 } 464 return null; 465 } 466 467 public void check() throws Exception { 468 final FutureTask<Exception> futureTask = new FutureTask<>(this); 469 executor.submit(futureTask); 470 Exception x = futureTask.get(); 471 if ( x != null) { 472 throw new RuntimeException("Check failed: "+x,x); 473 } 474 } 475 476 } 477 SetRBName(Class<? extends ResourceBundle> type) { 478 super("SetRB["+type.getSimpleName()+"]"); 479 this.type = type; 480 } 481 @Override 482 public void run() { 483 try { 484 while (goOn) { 485 Logger foo = Logger.getLogger("foo"); 486 Logger bar = Logger.getLogger("foo.bar"); 487 Logger l = Logger.getLogger("foo.bar.l"+nextLong.incrementAndGet()); 488 final CheckRBNameTask checkTask = new CheckRBNameTask(l); 489 checkTask.check(); 490 491 for (int i=0; i < LCOUNT ; i++) { 492 if (!goOn) break; 493 494 try { 495 Logger l2 = Logger.getLogger(l.getName(), type.getName()); 496 if (l2 != l) { 497 System.err.println("**** ERROR WITH "+l.getName()); 498 throw new RuntimeException("l2 != l [" 499 + l2 + "(" + l2.getName() + ") != " 500 + l + "(" + l.getName() + ")]"); 501 } 502 checkTask.rbName = type.getName(); 503 checkTask.check(); 504 if (!goOn) break; 505 506 String name = l.getResourceBundleName(); 507 ResourceBundle bb = l.getResourceBundle(); 508 if (!type.getName().equals(name)) { 509 throw new RuntimeException(this.getName() 510 + ": Unexpected name: "+name); 511 } 512 if (!bb.getBaseBundleName().equals(name)) { 513 throw new RuntimeException(this.getName() 514 + ": Unexpected base name: " 515 + bb.getBaseBundleName()); 516 } 517 setRBNameCount.incrementAndGet(); 518 } catch (IllegalArgumentException x) { 519 final String name = l.getResourceBundleName(); 520 if (!name.startsWith(MyBundle.class.getName())) { 521 throw new RuntimeException(this.getName() 522 + ": Unexpected name: "+name, x); 523 } else if (type.getName().equals(name)) { 524 throw new RuntimeException(this.getName() 525 + ": Unexpected exception for "+name, x); 526 } 527 throw x; 528 } 529 l.fine("I'm fine"); 530 if (!goOn) break; 531 Thread.sleep(1); 532 } 533 } 534 } catch (Exception x) { 535 fail(x); 536 } 537 } 538 } 539 540 static final class DeadlockDetector extends Thread { 541 542 @Override 543 public void run() { 544 while(goOn) { 545 try { 546 long[] ids = ManagementFactory.getThreadMXBean().findDeadlockedThreads(); 547 checkCount.incrementAndGet(); 548 ids = ids == null ? new long[0] : ids; 549 if (ids.length == 1) { 550 throw new RuntimeException("Found 1 deadlocked thread: "+ids[0]); 551 } else if (ids.length > 0) { 552 ThreadInfo[] infos = ManagementFactory.getThreadMXBean().getThreadInfo(ids); 553 System.err.println("Found "+ids.length+" deadlocked threads: "); 554 for (ThreadInfo inf : infos) { 555 System.err.println(inf.toString()); 556 } 557 throw new RuntimeException("Found "+ids.length+" deadlocked threads"); 558 } 559 Thread.sleep(100); 560 } catch(InterruptedException | RuntimeException x) { 561 fail(x); 562 } 563 } 564 } 565 566 } 567 568 static final class Stopper extends Thread { 569 long start; 570 long time; 571 572 Stopper(long time) { 573 start = System.currentTimeMillis(); 574 this.time = time; 575 } 576 577 @Override 578 public void run() { 579 try { 580 long rest, previous; 581 previous = time; 582 while (goOn && (rest = start - System.currentTimeMillis() + time) > 0) { 583 if (previous == time || previous - rest >= STEP) { 584 Logger.getLogger("remaining").info(String.valueOf(rest)+"ms remaining..."); 585 previous = rest == time ? rest -1 : rest; 586 System.gc(); 587 } 588 if (goOn == false) break; 589 Thread.sleep(Math.min(rest, 100)); 590 } 591 System.out.println(System.currentTimeMillis() - start 592 + " ms elapsed ("+time+ " requested)"); 593 goOn = false; 594 } catch(InterruptedException | RuntimeException x) { 595 fail(x); 596 } 597 } 598 599 } 600 601 static void fail(Exception x) { 602 x.printStackTrace(); 603 if (thrown == null) { 604 thrown = x; 605 } 606 goOn = false; 607 } 608} 609