8145686: SimpleConsoleLogger and LogRecord should take advantage of StackWalker to skip classes implementing System.Logger

Methods defined on classes implementing System.Logger will be skipped when looking for the calling method.

Reviewed-by: mchung
This commit is contained in:
Daniel Fuchs 2015-12-21 13:30:58 +01:00
parent 7295899326
commit 72bed9c5df
4 changed files with 456 additions and 29 deletions

View File

@ -28,6 +28,7 @@ package jdk.internal.logger;
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 @@ public class SimpleConsoleLogger extends LoggerConfiguration
* CallerFinder is a stateful predicate.
*/
static final class CallerFinder implements Predicate<StackWalker.StackFrame> {
static final StackWalker WALKER = StackWalker.getInstance();
private static final StackWalker WALKER;
static {
final PrivilegedAction<StackWalker> 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 @@ public class SimpleConsoleLogger extends LoggerConfiguration
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 @@ public class SimpleConsoleLogger extends LoggerConfiguration
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 @@ public class SimpleConsoleLogger extends LoggerConfiguration
}
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 @@ public class SimpleConsoleLogger extends LoggerConfiguration
// 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;
}

View File

@ -29,10 +29,12 @@ import java.util.*;
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 @@ public class LogRecord implements java.io.Serializable {
* CallerFinder is a stateful predicate.
*/
static final class CallerFinder implements Predicate<StackWalker.StackFrame> {
static final StackWalker WALKER = StackWalker.getInstance();
private static final StackWalker WALKER;
static {
final PrivilegedAction<StackWalker> action =
() -> StackWalker.getInstance(StackWalker.Option.RETAIN_CLASS_REFERENCE);
WALKER = AccessController.doPrivileged(action);
}
/**
* Returns StackFrame of the caller's frame.
@ -715,8 +722,9 @@ public class LogRecord implements java.io.Serializable {
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) {

View File

@ -43,13 +43,16 @@ import java.util.function.Supplier;
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 @@ import java.util.stream.Stream;
* @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 @@ public class DefaultLoggerTest {
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 @@ public class DefaultLoggerTest {
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<String> 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<String> 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 @@ public class DefaultLoggerTest {
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 class DefaultLoggerTest {
}
public static void test(boolean hasRequiredPermissions) {
test(Function.identity(), hasRequiredPermissions);
}
public static void test(Function<Logger, Logger> wrapper, boolean hasRequiredPermissions) {
ResourceBundle loggerBundle = ResourceBundle.getBundle(MyLoggerBundle.class.getName());
final Map<Logger, String> loggerDescMap = new HashMap<>();
@ -294,7 +496,7 @@ public class DefaultLoggerTest {
// - 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 @@ public class DefaultLoggerTest {
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 @@ public class DefaultLoggerTest {
// 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) {

View File

@ -44,17 +44,21 @@ import java.util.function.Supplier;
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 @@ import sun.util.logging.PlatformLogger;
* @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 @@ public class BaseDefaultLoggerFinderTest {
}
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 @@ public class BaseDefaultLoggerFinderTest {
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<String> 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<String> 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 @@ public class BaseDefaultLoggerFinderTest {
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 class BaseDefaultLoggerFinderTest {
}
public static void test(TestLoggerFinder provider, boolean hasRequiredPermissions) {
test(provider, Function.identity(), hasRequiredPermissions);
}
public static void test(TestLoggerFinder provider, Function<Logger, Logger> wrapper, boolean hasRequiredPermissions) {
ResourceBundle loggerBundle = ResourceBundle.getBundle(MyLoggerBundle.class.getName());
final Map<Logger, String> 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());