--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/jdk/test/java/lang/System/LoggerFinder/internal/BootstrapLogger/BootstrapLoggerTest.java Fri Nov 20 19:26:16 2015 +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<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);
+ } 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();
+ }
+
+ }
+}