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 }