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