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