1 /*
2 * Copyright (c) 2014, 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.io.ByteArrayOutputStream;
25 import java.io.OutputStream;
26 import java.io.PrintStream;
27 import java.lang.reflect.Array;
28 import java.lang.reflect.Field;
29 import java.util.concurrent.atomic.AtomicBoolean;
30 import java.util.function.BooleanSupplier;
31 import java.lang.System.Logger;
32 import java.lang.System.Logger.Level;
33 import java.lang.ref.ReferenceQueue;
34 import java.lang.ref.WeakReference;
35 import java.lang.reflect.InvocationTargetException;
36 import java.lang.reflect.Method;
37 import java.security.AllPermission;
38 import java.security.CodeSource;
39 import java.security.Permission;
40 import java.security.PermissionCollection;
41 import java.security.Permissions;
42 import java.security.Policy;
43 import java.security.ProtectionDomain;
44 import java.util.Optional;
45 import java.util.Set;
46 import java.util.stream.Collectors;
47 import java.util.stream.Stream;
48 import jdk.internal.logger.BootstrapLogger;
49 import jdk.internal.logger.LazyLoggers;
50
51 /*
52 * @test
53 * @bug 8140364
54 * @author danielfuchs
55 * @summary JDK implementation specific unit test for JDK internal artifacts.
56 Tests the behavior of bootstrap loggers (and SimpleConsoleLoggers
57 * too).
58 * @modules java.base/jdk.internal.logger
59 * @run main/othervm BootstrapLoggerTest NO_SECURITY
60 * @run main/othervm BootstrapLoggerTest SECURE
61 * @run main/othervm/timeout=120 BootstrapLoggerTest SECURE_AND_WAIT
62 */
63 public class BootstrapLoggerTest {
64
65 static final Method awaitPending;
66 static final Method isAlive;
67 static final Field isBooted;
68 static final Field logManagerInitialized;
69 static {
70 try {
71 isBooted = BootstrapLogger.class.getDeclaredField("isBooted");
72 isBooted.setAccessible(true);
73 // private reflection hook that allows us to test wait until all
74 // the tasks pending in the BootstrapExecutor are finished.
75 awaitPending = BootstrapLogger.class
76 .getDeclaredMethod("awaitPendingTasks");
77 awaitPending.setAccessible(true);
78 // private reflection hook that allows us to test whether
79 // the BootstrapExecutor is alive.
80 isAlive = BootstrapLogger.class
81 .getDeclaredMethod("isAlive");
82 isAlive.setAccessible(true);
83 // private reflection hook that allows us to test whether the LogManager
84 // has initialized and registered with the BootstrapLogger class
85 logManagerInitialized = BootstrapLogger.class
86 .getDeclaredField("logManagerConfigured");
87 logManagerInitialized.setAccessible(true);
88 } catch (Exception ex) {
89 throw new ExceptionInInitializerError(ex);
90 }
91 }
92
93 static void awaitPending() {
94 try {
95 awaitPending.invoke(null);
96 } catch (IllegalAccessException | IllegalArgumentException | InvocationTargetException ex) {
97 ex.printStackTrace(LogStream.err);
98 }
99 }
100
101 /**
102 * We use an instance of this class to check what the logging system has
103 * printed on System.err.
104 */
105 public static class LogStream extends OutputStream {
106
107 final static PrintStream err = System.err;
108 final ByteArrayOutputStream baos = new ByteArrayOutputStream();
109
110 public LogStream() {
111 super();
112 }
113
114 @Override
115 public synchronized void write(int b) {
116 baos.write(b);
117 err.write(b);
118 }
119
120 public String drain() {
121 awaitPending();
122 synchronized(this) {
123 String txt = baos.toString();
124 baos.reset();
125 return txt;
126 }
127 }
128 }
129
130 static enum TestCase {
131 NO_SECURITY, SECURE, SECURE_AND_WAIT
132 }
133
134 public static void main(String[] args) throws Exception {
135 if (args == null || args.length == 0) {
136 args = new String[] { TestCase.SECURE_AND_WAIT.name() };
137 }
138 if (args.length > 1) throw new RuntimeException("Only one argument allowed");
139 TestCase test = TestCase.valueOf(args[0]);
140 System.err.println("Testing: " + test);
141
142
143 // private reflection hook that allows us to simulate a non booted VM
144 final AtomicBoolean vmBooted = new AtomicBoolean(false);
145 isBooted.set(null,(BooleanSupplier) () -> vmBooted.get());
146
147 // We replace System.err to check the messages that have been logged
148 // by the JUL ConsoleHandler and default SimpleConsoleLogger
149 // implementaion
150 final LogStream err = new LogStream();
151 System.setErr(new PrintStream(err));
152
153 if (BootstrapLogger.isBooted()) {
154 throw new RuntimeException("VM should not be booted!");
155 }
156 Logger logger = LazyLoggers.getLogger("foo.bar", Thread.class);
157
158 if (test != TestCase.NO_SECURITY) {
159 LogStream.err.println("Setting security manager");
160 Policy.setPolicy(new SimplePolicy());
161 System.setSecurityManager(new SecurityManager());
162 }
163
164 Level[] levels = {Level.INFO, Level.WARNING, Level.INFO};
165 int index = 0;
166 logger.log(levels[index], "Early message #" + (index+1)); index++;
167 logger.log(levels[index], "Early message #" + (index+1)); index++;
168 LogStream.err.println("VM Booted: " + vmBooted.get());
169 LogStream.err.println("LogManager initialized: " + logManagerInitialized.get(null));
170 logger.log(levels[index], "Early message #" + (index+1)); index++;
171 if (err.drain().contains("Early message")) {
172 // We're expecting that logger will be a LazyLogger wrapping a
173 // BootstrapLogger. The Bootstrap logger will stack the log messages
174 // it receives until the VM is booted.
175 // Since our private hook pretend that the VM is not booted yet,
176 // the logged messages shouldn't have reached System.err yet.
177 throw new RuntimeException("Early message logged while VM is not booted!");
178 }
179
180 // Now pretend that the VM is booted. Nothing should happen yet, until
181 // we try to log a new message.
182 vmBooted.getAndSet(true);
183 LogStream.err.println("VM Booted: " + vmBooted.get());
184 LogStream.err.println("LogManager initialized: " + logManagerInitialized.get(null));
185 if (!BootstrapLogger.isBooted()) {
186 throw new RuntimeException("VM should now be booted!");
187 }
188 if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
189 throw new RuntimeException("LogManager shouldn't be initialized yet!");
190 }
191
192 // Logging a message should cause the BootstrapLogger to replace itself
193 // by a 'real' logger in the LazyLogger. But since the LogManager isn't
194 // initialized yet, this should be a SimpleConsoleLogger...
195 logger.log(Level.INFO, "LOG#4: VM now booted: {0}", vmBooted.get());
196 logger.log(Level.DEBUG, "LOG#5: hi!");
197 SimplePolicy.allowAll.set(Boolean.TRUE);
198 WeakReference<Thread> threadRef = null;
199 ReferenceQueue<Thread> queue = new ReferenceQueue<>();
200 try {
201 Set<Thread> set = Thread.getAllStackTraces().keySet().stream()
202 .filter((t) -> t.getName().startsWith("BootstrapMessageLoggerTask-"))
203 .collect(Collectors.toSet());
204 set.stream().forEach(t -> LogStream.err.println("Found: " + t));
205 if (set.size() > 1) {
206 throw new RuntimeException("Too many bootsrap threads found");
207 }
208 Optional<Thread> t = set.stream().findFirst();
209 if (t.isPresent()) {
210 threadRef = new WeakReference<>(t.get(), queue);
211 }
212 } finally{
213 SimplePolicy.allowAll.set(Boolean.FALSE);
214 }
215 if (!BootstrapLogger.isBooted()) {
216 throw new RuntimeException("VM should still be booted!");
217 }
218 if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
219 throw new RuntimeException("LogManager shouldn't be initialized yet!");
220 }
221
222 // Now check that the early messages we had printed before the VM was
223 // booted have appeared on System.err...
224 String afterBoot = err.drain();
225 for (int i=0; i<levels.length; i++) {
226 String m = levels[i].getName()+": Early message #"+(i+1);
227 if (!afterBoot.contains(m)) {
228 throw new RuntimeException("System.err does not contain: "+m);
229 }
230 }
231 // check that the message logged *after* the VM was booted also printed.
232 if (!afterBoot.contains("INFO: LOG#4")) {
233 throw new RuntimeException("System.err does not contain: "
234 + "INFO: LOG#4");
235 }
236 // check that the debug message was not printed.
237 if (afterBoot.contains("LOG#5")) {
238 throw new RuntimeException("System.err contain: " + "LOG#5");
239 }
240 LogStream.err.println("VM Booted: " + vmBooted.get());
241 LogStream.err.println("LogManager initialized: " + logManagerInitialized.get(null));
242 if (!BootstrapLogger.isBooted()) {
243 throw new RuntimeException("VM should still be booted!");
244 }
245 if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
246 throw new RuntimeException("LogManager shouldn't be initialized yet!");
247 }
248
249 // Now we're going to use reflection to access JUL, and change
250 // the level of the "foo" logger.
251 // We're using reflection so that the test can also run in
252 // configurations where java.util.logging is not present.
253 boolean hasJUL = false;
254 SimplePolicy.allowAll.set(Boolean.TRUE);
255 try {
256 Class<?> loggerClass = Class.forName("java.util.logging.Logger");
257 Class<?> levelClass = Class.forName("java.util.logging.Level");
258 Class<?> handlerClass = Class.forName("java.util.logging.Handler");
259
260 // java.util.logging.Logger.getLogger("foo")
261 // .setLevel(java.util.logging.Level.FINEST);
262 Object fooLogger = loggerClass.getMethod("getLogger", String.class)
263 .invoke(null, "foo");
264 loggerClass.getMethod("setLevel", levelClass)
265 .invoke(fooLogger, levelClass.getField("FINEST").get(null));
266
267 // java.util.logging.Logger.getLogger("").getHandlers()[0]
268 // .setLevel(java.util.logging.Level.ALL);
269 Object rootLogger = loggerClass.getMethod("getLogger", String.class)
270 .invoke(null, "");
271 Object handlers = loggerClass.getMethod("getHandlers").
272 invoke(rootLogger);
273 handlerClass.getMethod("setLevel", levelClass)
274 .invoke(Array.get(handlers, 0), levelClass.getField("ALL")
275 .get(null));
276
277 hasJUL = true;
278 } catch (ClassNotFoundException x) {
279 LogStream.err.println("JUL is not present: class " + x.getMessage()
280 + " not found");
281 hasJUL = false;
282 } finally {
283 SimplePolicy.allowAll.set(Boolean.FALSE);
284 }
285
286 logger.log(Level.DEBUG, "hi now!");
287 String debug = err.drain();
288 if (hasJUL) {
289 if (!((Boolean)logManagerInitialized.get(null)).booleanValue()) {
290 throw new RuntimeException("LogManager should be initialized now!");
291 }
292 if (!debug.contains("FINE: hi now!")) {
293 throw new RuntimeException("System.err does not contain: "
294 + "FINE: hi now!");
295 }
296 } else {
297 if (debug.contains("hi now!")) {
298 throw new RuntimeException("System.err contains: " + "hi now!");
299 }
300 if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
301 throw new RuntimeException("LogManager shouldn't be initialized yet!");
302 }
303 Logger baz = System.getLogger("foo.bar.baz");
304 if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
305 throw new RuntimeException("LogManager shouldn't be initialized yet!");
306 }
307 }
308 Logger bazbaz = null;
309 SimplePolicy.allowAll.set(Boolean.TRUE);
310 try {
311 bazbaz = java.lang.System.LoggerFinder
312 .getLoggerFinder().getLogger("foo.bar.baz.baz", BootstrapLoggerTest.class);
313 } finally {
314 SimplePolicy.allowAll.set(Boolean.FALSE);
315 }
316 if (!((Boolean)logManagerInitialized.get(null)).booleanValue()) {
317 throw new RuntimeException("LogManager should be initialized now!");
318 }
319 Logger bazbaz2 = System.getLogger("foo.bar.baz.baz");
320 if (bazbaz2.getClass() != bazbaz.getClass()) {
321 throw new RuntimeException("bazbaz2.class != bazbaz.class ["
322 + bazbaz2.getClass() + " != "
323 + bazbaz.getClass() + "]");
324 }
325 if (hasJUL != bazbaz2.getClass().getName()
326 .equals("sun.util.logging.internal.LoggingProviderImpl$JULWrapper")) {
327 throw new RuntimeException("Unexpected class for bazbaz: "
328 + bazbaz.getClass().getName()
329 + "\n\t expected: "
330 + "sun.util.logging.internal.LoggingProviderImpl$JULWrapper");
331 }
332
333 // Now we're going to check that the thread of the BootstrapLogger
334 // executor terminates, and that the Executor is GC'ed after that.
335 // This will involve a bit of waiting, hence the timeout=120 in
336 // the @run line.
337 // If this test fails in timeout - we could envisage skipping this part,
338 // or adding some System property to configure the keep alive delay
339 // of the executor.
340 SimplePolicy.allowAll.set(Boolean.TRUE);
341 try {
342 Stream<Thread> stream = Thread.getAllStackTraces().keySet().stream();
343 stream.filter((t) -> t.getName().startsWith("BootstrapMessageLoggerTask-"))
344 .forEach(t -> LogStream.err.println(t));
345 stream = null;
346 if (threadRef != null && test == TestCase.SECURE_AND_WAIT) {
347 Thread t = threadRef.get();
348 if (t != null) {
349 if (!(Boolean)isAlive.invoke(null)) {
350 throw new RuntimeException("Executor already terminated");
351 } else {
352 LogStream.err.println("Executor still alive as expected.");
353 }
354 LogStream.err.println("Waiting for " + t.getName() + " to terminate (join)");
355 t.join(60_000);
356 t = null;
357 }
358 LogStream.err.println("Calling System.gc()");
359 System.gc();
360 LogStream.err.println("Waiting for BootstrapMessageLoggerTask to be gc'ed");
361 while (queue.remove(1000) == null) {
362 LogStream.err.println("Calling System.gc()");
363 System.gc();
364 }
365
366 // Call the reference here to make sure threadRef will not be
367 // eagerly garbage collected before the thread it references.
368 // otherwise, it might not be enqueued, resulting in the
369 // queue.remove() call above to always return null....
370 if (threadRef.get() != null) {
371 throw new RuntimeException("Reference should have been cleared");
372 }
373
374 LogStream.err.println("BootstrapMessageLoggerTask has been gc'ed");
375 // Wait for the executor to be gc'ed...
376 for (int i=0; i<10; i++) {
377 LogStream.err.println("Calling System.gc()");
378 System.gc();
379 if (!(Boolean)isAlive.invoke(null)) break;
380 // It would be unexpected that we reach here...
381 Thread.sleep(1000);
382 }
383
384 if ((Boolean)isAlive.invoke(null)) {
385 throw new RuntimeException("Executor still alive");
386 } else {
387 LogStream.err.println("Executor terminated as expected.");
388 }
389 } else {
390 LogStream.err.println("Not checking executor termination for " + test);
391 }
392 } finally {
393 SimplePolicy.allowAll.set(Boolean.FALSE);
394 }
395 LogStream.err.println(test.name() + ": PASSED");
396 }
397
398 final static class SimplePolicy extends Policy {
399 static final ThreadLocal<Boolean> allowAll = new ThreadLocal<Boolean>() {
400 @Override
401 protected Boolean initialValue() {
402 return Boolean.FALSE;
403 }
404 };
405
406 Permissions getPermissions() {
407 Permissions perms = new Permissions();
408 if (allowAll.get()) {
409 perms.add(new AllPermission());
410 }
411 return perms;
412 }
413
414 @Override
415 public boolean implies(ProtectionDomain domain, Permission permission) {
416 return getPermissions(domain).implies(permission);
417 }
418
419 @Override
420 public PermissionCollection getPermissions(CodeSource codesource) {
421 return getPermissions();
422 }
423
424 @Override
425 public PermissionCollection getPermissions(ProtectionDomain domain) {
426 return getPermissions();
427 }
428
429 }
430 }