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