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