# HG changeset patch # User dfuchs # Date 1450701058 -3600 # Node ID 734a1c90ce864c2e54915aeb31ae1e14b8e9f59a # Parent 1d23e916f1890034b064c33b28c4e8a334ade164 8145686: SimpleConsoleLogger and LogRecord should take advantage of StackWalker to skip classes implementing System.Logger Summary: methods defined on classes implementing System.Logger will be skipped when looking for the calling method. Reviewed-by: mchung diff -r 1d23e916f189 -r 734a1c90ce86 jdk/src/java.base/share/classes/jdk/internal/logger/SimpleConsoleLogger.java --- a/jdk/src/java.base/share/classes/jdk/internal/logger/SimpleConsoleLogger.java Mon Dec 21 13:43:53 2015 +0800 +++ b/jdk/src/java.base/share/classes/jdk/internal/logger/SimpleConsoleLogger.java Mon Dec 21 13:30:58 2015 +0100 @@ -28,6 +28,7 @@ import java.io.PrintStream; import java.io.PrintWriter; import java.io.StringWriter; +import java.lang.StackWalker.StackFrame; import java.security.AccessController; import java.security.PrivilegedAction; import java.time.ZonedDateTime; @@ -180,7 +181,16 @@ * CallerFinder is a stateful predicate. */ static final class CallerFinder implements Predicate { - static final StackWalker WALKER = StackWalker.getInstance(); + private static final StackWalker WALKER; + static { + final PrivilegedAction action = new PrivilegedAction<>() { + @Override + public StackWalker run() { + return StackWalker.getInstance(StackWalker.Option.RETAIN_CLASS_REFERENCE); + } + }; + WALKER = AccessController.doPrivileged(action); + } /** * Returns StackFrame of the caller's frame. @@ -210,8 +220,9 @@ lookingForLogger = !isLoggerImplFrame(cname); return false; } - // We've found the relevant frame. - return !skipLoggingFrame(cname) && !isLoggerImplFrame(cname); + // Continue walking until we've found the relevant calling frame. + // Skips logging/logger infrastructure. + return !isFilteredFrame(t); } private boolean isLoggerImplFrame(String cname) { @@ -281,8 +292,8 @@ return Formatting.getSimpleFormat(defaultPropertyGetter); } - public static boolean skipLoggingFrame(String cname) { - return Formatting.skipLoggingFrame(cname); + public static boolean isFilteredFrame(StackFrame st) { + return Formatting.isFilteredFrame(st); } @Override @@ -393,16 +404,19 @@ } - static boolean skipLoggingFrame(String cname) { + static boolean isFilteredFrame(StackFrame st) { // skip logging/logger infrastructure + if (System.Logger.class.isAssignableFrom(st.getDeclaringClass())) { + return true; + } // fast escape path: all the prefixes below start with 's' or 'j' and // have more than 12 characters. + final String cname = st.getClassName(); char c = cname.length() < 12 ? 0 : cname.charAt(0); if (c == 's') { // skip internal machinery classes if (cname.startsWith("sun.util.logging.")) return true; - if (cname.startsWith("sun.reflect.")) return true; if (cname.startsWith("sun.rmi.runtime.Log")) return true; } else if (c == 'j') { // Message delayed at Bootstrap: no need to go further up. @@ -410,10 +424,7 @@ // skip public machinery classes if (cname.startsWith("jdk.internal.logger.")) return true; if (cname.startsWith("java.util.logging.")) return true; - if (cname.startsWith("java.lang.System$Logger")) return true; - if (cname.startsWith("java.lang.reflect.")) return true; if (cname.startsWith("java.lang.invoke.MethodHandle")) return true; - if (cname.startsWith("java.lang.invoke.LambdaForm")) return true; if (cname.startsWith("java.security.AccessController")) return true; } diff -r 1d23e916f189 -r 734a1c90ce86 jdk/src/java.logging/share/classes/java/util/logging/LogRecord.java --- a/jdk/src/java.logging/share/classes/java/util/logging/LogRecord.java Mon Dec 21 13:43:53 2015 +0800 +++ b/jdk/src/java.logging/share/classes/java/util/logging/LogRecord.java Mon Dec 21 13:30:58 2015 +0100 @@ -29,10 +29,12 @@ import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.atomic.AtomicLong; import java.io.*; +import java.security.AccessController; +import java.security.PrivilegedAction; import java.time.Clock; import java.util.function.Predicate; -import static jdk.internal.logger.SimpleConsoleLogger.skipLoggingFrame; +import static jdk.internal.logger.SimpleConsoleLogger.isFilteredFrame; /** * LogRecord objects are used to pass logging requests between @@ -685,7 +687,12 @@ * CallerFinder is a stateful predicate. */ static final class CallerFinder implements Predicate { - static final StackWalker WALKER = StackWalker.getInstance(); + private static final StackWalker WALKER; + static { + final PrivilegedAction action = + () -> StackWalker.getInstance(StackWalker.Option.RETAIN_CLASS_REFERENCE); + WALKER = AccessController.doPrivileged(action); + } /** * Returns StackFrame of the caller's frame. @@ -715,8 +722,9 @@ lookingForLogger = !isLoggerImplFrame(cname); return false; } - // skip logging/logger infrastructure and reflection calls - return !skipLoggingFrame(cname); + // Continue walking until we've found the relevant calling frame. + // Skips logging/logger infrastructure. + return !isFilteredFrame(t); } private boolean isLoggerImplFrame(String cname) { diff -r 1d23e916f189 -r 734a1c90ce86 jdk/test/java/lang/System/Logger/default/DefaultLoggerTest.java --- a/jdk/test/java/lang/System/Logger/default/DefaultLoggerTest.java Mon Dec 21 13:43:53 2015 +0800 +++ b/jdk/test/java/lang/System/Logger/default/DefaultLoggerTest.java Mon Dec 21 13:30:58 2015 +0100 @@ -43,13 +43,16 @@ import java.lang.System.LoggerFinder; import java.lang.System.Logger; import java.lang.System.Logger.Level; +import java.lang.reflect.InvocationTargetException; +import java.lang.reflect.Method; +import java.util.function.Function; import java.util.logging.Handler; import java.util.logging.LogRecord; import java.util.stream.Stream; /** * @test - * @bug 8140364 + * @bug 8140364 8145686 * @summary Tests default loggers returned by System.getLogger, and in * particular the implementation of the the System.Logger method * performed by the default binding. @@ -59,6 +62,8 @@ * @run main/othervm -Xbootclasspath/a:boot DefaultLoggerTest NOSECURITY * @run main/othervm -Xbootclasspath/a:boot DefaultLoggerTest NOPERMISSIONS * @run main/othervm -Xbootclasspath/a:boot DefaultLoggerTest WITHPERMISSIONS + * @run main/othervm -Xbootclasspath/a:boot DefaultLoggerTest WITHCUSTOMWRAPPERS + * @run main/othervm -Xbootclasspath/a:boot DefaultLoggerTest WITHREFLECTION * @author danielfuchs */ public class DefaultLoggerTest { @@ -232,7 +237,8 @@ static final AccessSystemLogger accessSystemLogger = new AccessSystemLogger(); - static enum TestCases {NOSECURITY, NOPERMISSIONS, WITHPERMISSIONS}; + static enum TestCases {NOSECURITY, NOPERMISSIONS, WITHPERMISSIONS, + WITHCUSTOMWRAPPERS, WITHREFLECTION}; static void setSecurityManager() { if (System.getSecurityManager() == null) { @@ -240,12 +246,179 @@ System.setSecurityManager(new SecurityManager()); } } + + /** + * The CustomLoggerWrapper makes it possible to verify that classes + * which implements System.Logger will be skipped when looking for + * the calling method. + */ + static class CustomLoggerWrapper implements Logger { + + Logger impl; + public CustomLoggerWrapper(Logger logger) { + this.impl = Objects.requireNonNull(logger); + } + + + @Override + public String getName() { + return impl.getName(); + } + + @Override + public boolean isLoggable(Level level) { + return impl.isLoggable(level); + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Throwable thrwbl) { + impl.log(level, rb, string, thrwbl); + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Object... os) { + impl.log(level, rb, string, os); + } + + @Override + public void log(Level level, Object o) { + impl.log(level, o); + } + + @Override + public void log(Level level, String string) { + impl.log(level, string); + } + + @Override + public void log(Level level, Supplier splr) { + impl.log(level, splr); + } + + @Override + public void log(Level level, String string, Object... os) { + impl.log(level, string, os); + } + + @Override + public void log(Level level, String string, Throwable thrwbl) { + impl.log(level, string, thrwbl); + } + + @Override + public void log(Level level, Supplier splr, Throwable thrwbl) { + Logger.super.log(level, splr, thrwbl); + } + + @Override + public String toString() { + return super.toString() + "(impl=" + impl + ")"; + } + + } + + /** + * The ReflectionLoggerWrapper additionally makes it possible to verify + * that code which use reflection to call System.Logger will be skipped + * when looking for the calling method. + */ + static class ReflectionLoggerWrapper implements Logger { + + Logger impl; + public ReflectionLoggerWrapper(Logger logger) { + this.impl = Objects.requireNonNull(logger); + } + + private Object invoke(Method m, Object... params) { + try { + return m.invoke(impl, params); + } catch (IllegalAccessException | IllegalArgumentException + | InvocationTargetException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public String getName() { + return impl.getName(); + } + + @Override + public boolean isLoggable(Level level) { + return impl.isLoggable(level); + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Throwable thrwbl) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, ResourceBundle.class, String.class, Throwable.class), + level, rb, string, thrwbl); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Object... os) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, ResourceBundle.class, String.class, Object[].class), + level, rb, string, os); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, String string) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, String.class), + level, string); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, String string, Object... os) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, String.class, Object[].class), + level, string, os); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, String string, Throwable thrwbl) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, String.class, Throwable.class), + level, string, thrwbl); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + + @Override + public String toString() { + return super.toString() + "(impl=" + impl + ")"; + } + + } + public static void main(String[] args) { if (args.length == 0) args = new String[] { "NOSECURITY", "NOPERMISSIONS", - "WITHPERMISSIONS" + "WITHPERMISSIONS", + "WITHCUSTOMWRAPPERS", + "WITHREFLECTION" }; // 1. Obtain destination loggers directly from the LoggerFinder @@ -276,6 +449,31 @@ allowControl.get().set(control); } break; + case WITHCUSTOMWRAPPERS: + System.out.println("\n*** With Security Manager, with control permission, using custom Wrappers\n"); + setSecurityManager(); + final boolean previous = allowControl.get().get(); + try { + allowControl.get().set(true); + test(CustomLoggerWrapper::new, true); + } finally { + allowControl.get().set(previous); + } + break; + case WITHREFLECTION: + System.out.println("\n*** With Security Manager," + + " with control permission," + + " using reflection while logging\n"); + setSecurityManager(); + final boolean before = allowControl.get().get(); + try { + allowControl.get().set(true); + test(ReflectionLoggerWrapper::new, true); + } finally { + allowControl.get().set(before); + } + break; + default: throw new RuntimeException("Unknown test case: " + testCase); } @@ -284,6 +482,10 @@ } public static void test(boolean hasRequiredPermissions) { + test(Function.identity(), hasRequiredPermissions); + } + + public static void test(Function wrapper, boolean hasRequiredPermissions) { ResourceBundle loggerBundle = ResourceBundle.getBundle(MyLoggerBundle.class.getName()); final Map loggerDescMap = new HashMap<>(); @@ -294,7 +496,7 @@ // - and AccessSystemLogger.getLogger("foo") Logger sysLogger1 = null; try { - sysLogger1 = accessSystemLogger.getLogger("foo"); + sysLogger1 = wrapper.apply(accessSystemLogger.getLogger("foo")); loggerDescMap.put(sysLogger1, "AccessSystemLogger.getLogger(\"foo\")"); } catch (AccessControlException acx) { if (hasRequiredPermissions) { @@ -306,7 +508,7 @@ throw new RuntimeException("unexpected exception: " + acx, acx); } - Logger appLogger1 = System.getLogger("foo"); + Logger appLogger1 = wrapper.apply(System.getLogger("foo")); loggerDescMap.put(appLogger1, "System.getLogger(\"foo\");"); if (appLogger1 == sysLogger1) { @@ -316,13 +518,13 @@ // 2. Test loggers returned by: // - System.getLogger(\"foo\", loggerBundle) // - and AccessSystemLogger.getLogger(\"foo\", loggerBundle) - Logger appLogger2 = - System.getLogger("foo", loggerBundle); + Logger appLogger2 = wrapper.apply( + System.getLogger("foo", loggerBundle)); loggerDescMap.put(appLogger2, "System.getLogger(\"foo\", loggerBundle)"); Logger sysLogger2 = null; try { - sysLogger2 = accessSystemLogger.getLogger("foo", loggerBundle); + sysLogger2 = wrapper.apply(accessSystemLogger.getLogger("foo", loggerBundle)); loggerDescMap.put(sysLogger2, "AccessSystemLogger.getLogger(\"foo\", loggerBundle)"); } catch (AccessControlException acx) { if (hasRequiredPermissions) { diff -r 1d23e916f189 -r 734a1c90ce86 jdk/test/java/lang/System/LoggerFinder/internal/BaseDefaultLoggerFinderTest/BaseDefaultLoggerFinderTest.java --- a/jdk/test/java/lang/System/LoggerFinder/internal/BaseDefaultLoggerFinderTest/BaseDefaultLoggerFinderTest.java Mon Dec 21 13:43:53 2015 +0800 +++ b/jdk/test/java/lang/System/LoggerFinder/internal/BaseDefaultLoggerFinderTest/BaseDefaultLoggerFinderTest.java Mon Dec 21 13:30:58 2015 +0100 @@ -44,17 +44,21 @@ import java.lang.System.LoggerFinder; import java.lang.System.Logger; import java.lang.System.Logger.Level; +import java.lang.reflect.InvocationTargetException; +import java.lang.reflect.Method; import java.security.AccessController; import java.security.PrivilegedAction; import java.util.Locale; +import java.util.Objects; import java.util.concurrent.atomic.AtomicReference; +import java.util.function.Function; import jdk.internal.logger.DefaultLoggerFinder; import jdk.internal.logger.SimpleConsoleLogger; import sun.util.logging.PlatformLogger; /** * @test - * @bug 8140364 + * @bug 8140364 8145686 * @summary JDK implementation specific unit test for the base DefaultLoggerFinder. * Tests the behavior of DefaultLoggerFinder and SimpleConsoleLogger * implementation. @@ -65,6 +69,8 @@ * @run main/othervm -Xbootclasspath/a:boot -Djava.system.class.loader=CustomSystemClassLoader BaseDefaultLoggerFinderTest NOSECURITY * @run main/othervm -Xbootclasspath/a:boot -Djava.system.class.loader=CustomSystemClassLoader BaseDefaultLoggerFinderTest NOPERMISSIONS * @run main/othervm -Xbootclasspath/a:boot -Djava.system.class.loader=CustomSystemClassLoader BaseDefaultLoggerFinderTest WITHPERMISSIONS + * @run main/othervm -Xbootclasspath/a:boot -Djava.system.class.loader=CustomSystemClassLoader BaseDefaultLoggerFinderTest WITHCUSTOMWRAPPERS + * @run main/othervm -Xbootclasspath/a:boot -Djava.system.class.loader=CustomSystemClassLoader BaseDefaultLoggerFinderTest WITHREFLECTION * @author danielfuchs */ public class BaseDefaultLoggerFinderTest { @@ -172,7 +178,8 @@ } - static enum TestCases {NOSECURITY, NOPERMISSIONS, WITHPERMISSIONS}; + static enum TestCases {NOSECURITY, NOPERMISSIONS, WITHPERMISSIONS, + WITHCUSTOMWRAPPERS, WITHREFLECTION}; static void setSecurityManager() { if (System.getSecurityManager() == null) { @@ -261,12 +268,173 @@ return b.append(name).append("=").append(value).append('\n'); } + static class CustomLoggerWrapper implements Logger { + + Logger impl; + public CustomLoggerWrapper(Logger logger) { + this.impl = Objects.requireNonNull(logger); + } + + + @Override + public String getName() { + return impl.getName(); + } + + @Override + public boolean isLoggable(Level level) { + return impl.isLoggable(level); + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Throwable thrwbl) { + impl.log(level, rb, string, thrwbl); + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Object... os) { + impl.log(level, rb, string, os); + } + + @Override + public void log(Level level, Object o) { + impl.log(level, o); + } + + @Override + public void log(Level level, String string) { + impl.log(level, string); + } + + @Override + public void log(Level level, Supplier splr) { + impl.log(level, splr); + } + + @Override + public void log(Level level, String string, Object... os) { + impl.log(level, string, os); + } + + @Override + public void log(Level level, String string, Throwable thrwbl) { + impl.log(level, string, thrwbl); + } + + @Override + public void log(Level level, Supplier splr, Throwable thrwbl) { + Logger.super.log(level, splr, thrwbl); + } + + @Override + public String toString() { + return super.toString() + "(impl=" + impl + ")"; + } + + } + /** + * The ReflectionLoggerWrapper additionally makes it possible to verify + * that code which use reflection to call System.Logger will be skipped + * when looking for the calling method. + */ + static class ReflectionLoggerWrapper implements Logger { + + Logger impl; + public ReflectionLoggerWrapper(Logger logger) { + this.impl = Objects.requireNonNull(logger); + } + + private Object invoke(Method m, Object... params) { + try { + return m.invoke(impl, params); + } catch (IllegalAccessException | IllegalArgumentException + | InvocationTargetException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public String getName() { + return impl.getName(); + } + + @Override + public boolean isLoggable(Level level) { + return impl.isLoggable(level); + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Throwable thrwbl) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, ResourceBundle.class, String.class, Throwable.class), + level, rb, string, thrwbl); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, ResourceBundle rb, String string, Object... os) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, ResourceBundle.class, String.class, Object[].class), + level, rb, string, os); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, String string) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, String.class), + level, string); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, String string, Object... os) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, String.class, Object[].class), + level, string, os); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + @Override + public void log(Level level, String string, Throwable thrwbl) { + try { + invoke(System.Logger.class.getMethod( + "log", Level.class, String.class, Throwable.class), + level, string, thrwbl); + } catch (NoSuchMethodException ex) { + throw new RuntimeException(ex); + } + } + + + @Override + public String toString() { + return super.toString() + "(impl=" + impl + ")"; + } + + } + + public static void main(String[] args) { if (args.length == 0) { args = new String[] { //"NOSECURITY", "NOPERMISSIONS", - "WITHPERMISSIONS" + "WITHPERMISSIONS", + "WITHCUSTOMWRAPPERS", + "WITHREFLECTION" }; } Locale.setDefault(Locale.ENGLISH); @@ -355,6 +523,40 @@ allowControl.get().set(control); } break; + case WITHCUSTOMWRAPPERS: + System.out.println("\n*** With Security Manager, with control permission and custom Wrapper\n"); + System.out.println(TestLoggerFinder.conf.get()); + setSecurityManager(); + final boolean previous = allowControl.get().get(); + try { + allowControl.get().set(true); + provider = getLoggerFinder(expectedClass); + if (!provider.getClass().getName().equals("BaseDefaultLoggerFinderTest$BaseLoggerFinder")) { + throw new RuntimeException("Unexpected provider: " + provider.getClass().getName()); + } + test(provider, CustomLoggerWrapper::new, true); + } finally { + allowControl.get().set(previous); + } + break; + case WITHREFLECTION: + System.out.println("\n*** With Security Manager," + + " with control permission," + + " using reflection while logging\n"); + System.out.println(TestLoggerFinder.conf.get()); + setSecurityManager(); + final boolean before = allowControl.get().get(); + try { + allowControl.get().set(true); + provider = getLoggerFinder(expectedClass); + if (!provider.getClass().getName().equals("BaseDefaultLoggerFinderTest$BaseLoggerFinder")) { + throw new RuntimeException("Unexpected provider: " + provider.getClass().getName()); + } + test(provider, ReflectionLoggerWrapper::new, true); + } finally { + allowControl.get().set(before); + } + break; default: throw new RuntimeException("Unknown test case: " + testCase); } @@ -363,17 +565,21 @@ } public static void test(TestLoggerFinder provider, boolean hasRequiredPermissions) { + test(provider, Function.identity(), hasRequiredPermissions); + } + + public static void test(TestLoggerFinder provider, Function wrapper, boolean hasRequiredPermissions) { ResourceBundle loggerBundle = ResourceBundle.getBundle(MyLoggerBundle.class.getName()); final Map loggerDescMap = new HashMap<>(); - System.Logger sysLogger = accessSystemLogger.getLogger("foo"); + System.Logger sysLogger = wrapper.apply(accessSystemLogger.getLogger("foo")); loggerDescMap.put(sysLogger, "accessSystemLogger.getLogger(\"foo\")"); - System.Logger localizedSysLogger = accessSystemLogger.getLogger("fox", loggerBundle); + System.Logger localizedSysLogger = wrapper.apply(accessSystemLogger.getLogger("fox", loggerBundle)); loggerDescMap.put(localizedSysLogger, "accessSystemLogger.getLogger(\"fox\", loggerBundle)"); - System.Logger appLogger = System.getLogger("bar"); + System.Logger appLogger = wrapper.apply(System.getLogger("bar")); loggerDescMap.put(appLogger,"System.getLogger(\"bar\")"); - System.Logger localizedAppLogger = System.getLogger("baz", loggerBundle); + System.Logger localizedAppLogger = wrapper.apply(System.getLogger("baz", loggerBundle)); loggerDescMap.put(localizedAppLogger,"System.getLogger(\"baz\", loggerBundle)"); testLogger(provider, loggerDescMap, "foo", null, sysLogger, accessSystemLogger.getClass());