--- /dev/null 2015-11-20 17:44:31.000000000 +0100 +++ new/jdk/test/java/lang/System/LoggerFinder/internal/BootstrapLogger/BootstrapLoggerTest.java 2015-11-20 17:44:31.000000000 +0100 @@ -0,0 +1,430 @@ +/* + * Copyright (c) 2014, 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.ByteArrayOutputStream; +import java.io.OutputStream; +import java.io.PrintStream; +import java.lang.reflect.Array; +import java.lang.reflect.Field; +import java.util.concurrent.atomic.AtomicBoolean; +import java.util.function.BooleanSupplier; +import java.lang.System.Logger; +import java.lang.System.Logger.Level; +import java.lang.ref.ReferenceQueue; +import java.lang.ref.WeakReference; +import java.lang.reflect.InvocationTargetException; +import java.lang.reflect.Method; +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.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; + +/* + * @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 + * @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 awaitPending; + static final Method isAlive; + static final Field isBooted; + static final Field logManagerInitialized; + static { + try { + isBooted = BootstrapLogger.class.getDeclaredField("isBooted"); + isBooted.setAccessible(true); + // private reflection hook that allows us to test wait until all + // the tasks pending in the BootstrapExecutor are finished. + awaitPending = BootstrapLogger.class + .getDeclaredMethod("awaitPendingTasks"); + awaitPending.setAccessible(true); + // 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 void awaitPending() { + try { + awaitPending.invoke(null); + } catch (IllegalAccessException | IllegalArgumentException | InvocationTargetException ex) { + ex.printStackTrace(LogStream.err); + } + } + + /** + * We use an instance of this class to check what the logging system has + * printed on System.err. + */ + public static class LogStream extends OutputStream { + + final static PrintStream err = System.err; + final ByteArrayOutputStream baos = new ByteArrayOutputStream(); + + public LogStream() { + super(); + } + + @Override + public synchronized void write(int b) { + baos.write(b); + err.write(b); + } + + public String drain() { + awaitPending(); + synchronized(this) { + String txt = baos.toString(); + baos.reset(); + return txt; + } + } + } + + 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); + isBooted.set(null,(BooleanSupplier) () -> 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); + + 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 threadRef = null; + ReferenceQueue queue = new ReferenceQueue<>(); + try { + Set 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 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 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); + } 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 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 allowAll = new ThreadLocal() { + @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(); + } + + } +}