/*
* Copyright (c) 2014, 2016, Oracle and/or its affiliates. All rights reserved.
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
*
* This code is free software; you can redistribute it and/or modify it
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*/
import java.io.PrintStream;
import java.lang.ref.ReferenceQueue;
import java.lang.ref.WeakReference;
import java.lang.reflect.Array;
import java.lang.reflect.Field;
import java.lang.reflect.Method;
import java.lang.System.Logger;
import java.lang.System.Logger.Level;
import java.security.AllPermission;
import java.security.CodeSource;
import java.security.Permission;
import java.security.PermissionCollection;
import java.security.Permissions;
import java.security.Policy;
import java.security.ProtectionDomain;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.Optional;
import java.util.Set;
import java.util.stream.Collectors;
import java.util.stream.Stream;
import jdk.internal.logger.BootstrapLogger;
import jdk.internal.logger.LazyLoggers;
import java.lang.reflect.Module;
/*
* @test
* @bug 8140364
* @author danielfuchs
* @summary JDK implementation specific unit test for JDK internal artifacts.
Tests the behavior of bootstrap loggers (and SimpleConsoleLoggers
* too).
* @modules java.base/jdk.internal.logger:+open
* java.logging
* @build BootstrapLoggerUtils LogStream
* @run main/othervm BootstrapLoggerTest NO_SECURITY
* @run main/othervm BootstrapLoggerTest SECURE
* @run main/othervm/timeout=120 BootstrapLoggerTest SECURE_AND_WAIT
*/
public class BootstrapLoggerTest {
static final Method isAlive;
static final Field logManagerInitialized;
static {
try {
// private reflection hook that allows us to test whether
// the BootstrapExecutor is alive.
isAlive = BootstrapLogger.class
.getDeclaredMethod("isAlive");
isAlive.setAccessible(true);
// private reflection hook that allows us to test whether the LogManager
// has initialized and registered with the BootstrapLogger class
logManagerInitialized = BootstrapLogger.class
.getDeclaredField("logManagerConfigured");
logManagerInitialized.setAccessible(true);
} catch (Exception ex) {
throw new ExceptionInInitializerError(ex);
}
}
static enum TestCase {
NO_SECURITY, SECURE, SECURE_AND_WAIT
}
public static void main(String[] args) throws Exception {
if (args == null || args.length == 0) {
args = new String[] { TestCase.SECURE_AND_WAIT.name() };
}
if (args.length > 1) throw new RuntimeException("Only one argument allowed");
TestCase test = TestCase.valueOf(args[0]);
System.err.println("Testing: " + test);
// private reflection hook that allows us to simulate a non booted VM
final AtomicBoolean vmBooted = new AtomicBoolean(false);
BootstrapLoggerUtils.setBootedHook(() -> vmBooted.get());
// We replace System.err to check the messages that have been logged
// by the JUL ConsoleHandler and default SimpleConsoleLogger
// implementaion
final LogStream err = new LogStream();
System.setErr(new PrintStream(err));
if (BootstrapLogger.isBooted()) {
throw new RuntimeException("VM should not be booted!");
}
Logger logger = LazyLoggers.getLogger("foo.bar", Thread.class.getModule());
if (test != TestCase.NO_SECURITY) {
LogStream.err.println("Setting security manager");
Policy.setPolicy(new SimplePolicy());
System.setSecurityManager(new SecurityManager());
}
Level[] levels = {Level.INFO, Level.WARNING, Level.INFO};
int index = 0;
logger.log(levels[index], "Early message #" + (index+1)); index++;
logger.log(levels[index], "Early message #" + (index+1)); index++;
LogStream.err.println("VM Booted: " + vmBooted.get());
LogStream.err.println("LogManager initialized: " + logManagerInitialized.get(null));
logger.log(levels[index], "Early message #" + (index+1)); index++;
if (err.drain().contains("Early message")) {
// We're expecting that logger will be a LazyLogger wrapping a
// BootstrapLogger. The Bootstrap logger will stack the log messages
// it receives until the VM is booted.
// Since our private hook pretend that the VM is not booted yet,
// the logged messages shouldn't have reached System.err yet.
throw new RuntimeException("Early message logged while VM is not booted!");
}
// Now pretend that the VM is booted. Nothing should happen yet, until
// we try to log a new message.
vmBooted.getAndSet(true);
LogStream.err.println("VM Booted: " + vmBooted.get());
LogStream.err.println("LogManager initialized: " + logManagerInitialized.get(null));
if (!BootstrapLogger.isBooted()) {
throw new RuntimeException("VM should now be booted!");
}
if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
throw new RuntimeException("LogManager shouldn't be initialized yet!");
}
// Logging a message should cause the BootstrapLogger to replace itself
// by a 'real' logger in the LazyLogger. But since the LogManager isn't
// initialized yet, this should be a SimpleConsoleLogger...
logger.log(Level.INFO, "LOG#4: VM now booted: {0}", vmBooted.get());
logger.log(Level.DEBUG, "LOG#5: hi!");
SimplePolicy.allowAll.set(Boolean.TRUE);
WeakReference<Thread> threadRef = null;
ReferenceQueue<Thread> queue = new ReferenceQueue<>();
try {
Set<Thread> set = Thread.getAllStackTraces().keySet().stream()
.filter((t) -> t.getName().startsWith("BootstrapMessageLoggerTask-"))
.collect(Collectors.toSet());
set.stream().forEach(t -> LogStream.err.println("Found: " + t));
if (set.size() > 1) {
throw new RuntimeException("Too many bootsrap threads found");
}
Optional<Thread> t = set.stream().findFirst();
if (t.isPresent()) {
threadRef = new WeakReference<>(t.get(), queue);
}
} finally{
SimplePolicy.allowAll.set(Boolean.FALSE);
}
if (!BootstrapLogger.isBooted()) {
throw new RuntimeException("VM should still be booted!");
}
if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
throw new RuntimeException("LogManager shouldn't be initialized yet!");
}
// Now check that the early messages we had printed before the VM was
// booted have appeared on System.err...
String afterBoot = err.drain();
for (int i=0; i<levels.length; i++) {
String m = levels[i].getName()+": Early message #"+(i+1);
if (!afterBoot.contains(m)) {
throw new RuntimeException("System.err does not contain: "+m);
}
}
// check that the message logged *after* the VM was booted also printed.
if (!afterBoot.contains("INFO: LOG#4")) {
throw new RuntimeException("System.err does not contain: "
+ "INFO: LOG#4");
}
// check that the debug message was not printed.
if (afterBoot.contains("LOG#5")) {
throw new RuntimeException("System.err contain: " + "LOG#5");
}
LogStream.err.println("VM Booted: " + vmBooted.get());
LogStream.err.println("LogManager initialized: " + logManagerInitialized.get(null));
if (!BootstrapLogger.isBooted()) {
throw new RuntimeException("VM should still be booted!");
}
if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
throw new RuntimeException("LogManager shouldn't be initialized yet!");
}
// Now we're going to use reflection to access JUL, and change
// the level of the "foo" logger.
// We're using reflection so that the test can also run in
// configurations where java.util.logging is not present.
boolean hasJUL = false;
SimplePolicy.allowAll.set(Boolean.TRUE);
try {
Class<?> loggerClass = Class.forName("java.util.logging.Logger");
Class<?> levelClass = Class.forName("java.util.logging.Level");
Class<?> handlerClass = Class.forName("java.util.logging.Handler");
// java.util.logging.Logger.getLogger("foo")
// .setLevel(java.util.logging.Level.FINEST);
Object fooLogger = loggerClass.getMethod("getLogger", String.class)
.invoke(null, "foo");
loggerClass.getMethod("setLevel", levelClass)
.invoke(fooLogger, levelClass.getField("FINEST").get(null));
// java.util.logging.Logger.getLogger("").getHandlers()[0]
// .setLevel(java.util.logging.Level.ALL);
Object rootLogger = loggerClass.getMethod("getLogger", String.class)
.invoke(null, "");
Object handlers = loggerClass.getMethod("getHandlers").
invoke(rootLogger);
handlerClass.getMethod("setLevel", levelClass)
.invoke(Array.get(handlers, 0), levelClass.getField("ALL")
.get(null));
hasJUL = true;
} catch (ClassNotFoundException x) {
LogStream.err.println("JUL is not present: class " + x.getMessage()
+ " not found");
hasJUL = false;
} finally {
SimplePolicy.allowAll.set(Boolean.FALSE);
}
logger.log(Level.DEBUG, "hi now!");
String debug = err.drain();
if (hasJUL) {
if (!((Boolean)logManagerInitialized.get(null)).booleanValue()) {
throw new RuntimeException("LogManager should be initialized now!");
}
if (!debug.contains("FINE: hi now!")) {
throw new RuntimeException("System.err does not contain: "
+ "FINE: hi now!");
}
} else {
if (debug.contains("hi now!")) {
throw new RuntimeException("System.err contains: " + "hi now!");
}
if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
throw new RuntimeException("LogManager shouldn't be initialized yet!");
}
Logger baz = System.getLogger("foo.bar.baz");
if (((Boolean)logManagerInitialized.get(null)).booleanValue()) {
throw new RuntimeException("LogManager shouldn't be initialized yet!");
}
}
Logger bazbaz = null;
SimplePolicy.allowAll.set(Boolean.TRUE);
try {
bazbaz = java.lang.System.LoggerFinder
.getLoggerFinder().getLogger("foo.bar.baz.baz", BootstrapLoggerTest.class.getModule());
} finally {
SimplePolicy.allowAll.set(Boolean.FALSE);
}
if (!((Boolean)logManagerInitialized.get(null)).booleanValue()) {
throw new RuntimeException("LogManager should be initialized now!");
}
Logger bazbaz2 = System.getLogger("foo.bar.baz.baz");
if (bazbaz2.getClass() != bazbaz.getClass()) {
throw new RuntimeException("bazbaz2.class != bazbaz.class ["
+ bazbaz2.getClass() + " != "
+ bazbaz.getClass() + "]");
}
if (hasJUL != bazbaz2.getClass().getName()
.equals("sun.util.logging.internal.LoggingProviderImpl$JULWrapper")) {
throw new RuntimeException("Unexpected class for bazbaz: "
+ bazbaz.getClass().getName()
+ "\n\t expected: "
+ "sun.util.logging.internal.LoggingProviderImpl$JULWrapper");
}
// Now we're going to check that the thread of the BootstrapLogger
// executor terminates, and that the Executor is GC'ed after that.
// This will involve a bit of waiting, hence the timeout=120 in
// the @run line.
// If this test fails in timeout - we could envisage skipping this part,
// or adding some System property to configure the keep alive delay
// of the executor.
SimplePolicy.allowAll.set(Boolean.TRUE);
try {
Stream<Thread> stream = Thread.getAllStackTraces().keySet().stream();
stream.filter((t) -> t.getName().startsWith("BootstrapMessageLoggerTask-"))
.forEach(t -> LogStream.err.println(t));
stream = null;
if (threadRef != null && test == TestCase.SECURE_AND_WAIT) {
Thread t = threadRef.get();
if (t != null) {
if (!(Boolean)isAlive.invoke(null)) {
throw new RuntimeException("Executor already terminated");
} else {
LogStream.err.println("Executor still alive as expected.");
}
LogStream.err.println("Waiting for " + t.getName() + " to terminate (join)");
t.join(60_000);
t = null;
}
LogStream.err.println("Calling System.gc()");
System.gc();
LogStream.err.println("Waiting for BootstrapMessageLoggerTask to be gc'ed");
while (queue.remove(1000) == null) {
LogStream.err.println("Calling System.gc()");
System.gc();
}
// Call the reference here to make sure threadRef will not be
// eagerly garbage collected before the thread it references.
// otherwise, it might not be enqueued, resulting in the
// queue.remove() call above to always return null....
if (threadRef.get() != null) {
throw new RuntimeException("Reference should have been cleared");
}
LogStream.err.println("BootstrapMessageLoggerTask has been gc'ed");
// Wait for the executor to be gc'ed...
for (int i=0; i<10; i++) {
LogStream.err.println("Calling System.gc()");
System.gc();
if (!(Boolean)isAlive.invoke(null)) break;
// It would be unexpected that we reach here...
Thread.sleep(1000);
}
if ((Boolean)isAlive.invoke(null)) {
throw new RuntimeException("Executor still alive");
} else {
LogStream.err.println("Executor terminated as expected.");
}
} else {
LogStream.err.println("Not checking executor termination for " + test);
}
} finally {
SimplePolicy.allowAll.set(Boolean.FALSE);
}
LogStream.err.println(test.name() + ": PASSED");
}
final static class SimplePolicy extends Policy {
static final ThreadLocal<Boolean> allowAll = new ThreadLocal<Boolean>() {
@Override
protected Boolean initialValue() {
return Boolean.FALSE;
}
};
Permissions getPermissions() {
Permissions perms = new Permissions();
if (allowAll.get()) {
perms.add(new AllPermission());
}
return perms;
}
@Override
public boolean implies(ProtectionDomain domain, Permission permission) {
return getPermissions(domain).implies(permission);
}
@Override
public PermissionCollection getPermissions(CodeSource codesource) {
return getPermissions();
}
@Override
public PermissionCollection getPermissions(ProtectionDomain domain) {
return getPermissions();
}
}
}