8005788: Loggers and their corresponding system properties not working correctly
Summary: 1-1 mapping now maintained. Used Context err instead of System.err in several places (after bootstrapping Context). Problematic closing of err stream replaced by @SuppressWarnings("resource")
Reviewed-by: jlaskey, sundar
--- a/nashorn/src/jdk/nashorn/internal/ir/Symbol.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/ir/Symbol.java Tue Jan 08 09:59:28 2013 +0100
@@ -27,6 +27,7 @@
import java.io.PrintWriter;
import jdk.nashorn.internal.codegen.types.Type;
+import jdk.nashorn.internal.runtime.Context;
import jdk.nashorn.internal.runtime.options.Options;
/**
@@ -549,12 +550,7 @@
* @param slot valid bytecode slot, or -1 if not available
*/
public void setSlot(final int slot) {
- if (TRACE_SYMBOL != null) {
- if (TRACE_SYMBOL.equals(name)) {
- System.err.println(name + " gets slot " + slot);
- new Throwable().printStackTrace();
- }
- }
+ trace("SET SLOT " + slot);
this.slot = slot;
}
@@ -574,18 +570,7 @@
* @param type the type
*/
public void setType(final Type type) {
- if (TRACE_SYMBOL == null) {
- setTypeOverride(Type.widest(this.type, type));
- } else {
- final boolean check = TRACE_SYMBOL.equals(getName());
- final Type from = this.type;
- setTypeOverride(Type.widest(this.type, type));
-
- if (check) {
- System.err.println(getName() + " " + from + "=>" + type + " == " + this.type);
- new Throwable().printStackTrace();
- }
- }
+ setTypeOverride(Type.widest(this.type, type));
}
/**
@@ -596,7 +581,11 @@
* @param type the type
*/
public void setTypeOverride(final Type type) {
- this.type = type;
+ final Type old = this.type;
+ if (old != type) {
+ trace("TYPE CHANGE: " + old + "=>" + type + " == " + type);
+ this.type = type;
+ }
}
/**
@@ -607,4 +596,11 @@
public boolean isTopLevel() {
return block instanceof FunctionNode && ((FunctionNode) block).isScript();
}
+
+ private void trace(final String desc) {
+ if (TRACE_SYMBOL != null && TRACE_SYMBOL.equals(name)) {
+ Context.err("SYMBOL: '" + name + "' " + desc);
+ new Throwable().printStackTrace(Context.getContext().getErr());
+ }
+ }
}
--- a/nashorn/src/jdk/nashorn/internal/objects/NativeDebug.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/objects/NativeDebug.java Tue Jan 08 09:59:28 2013 +0100
@@ -27,12 +27,13 @@
import static jdk.nashorn.internal.runtime.ScriptRuntime.UNDEFINED;
-import java.io.PrintStream;
+import java.io.PrintWriter;
import java.util.Objects;
import jdk.nashorn.internal.objects.annotations.Attribute;
import jdk.nashorn.internal.objects.annotations.Function;
import jdk.nashorn.internal.objects.annotations.ScriptClass;
import jdk.nashorn.internal.objects.annotations.Where;
+import jdk.nashorn.internal.runtime.Context;
import jdk.nashorn.internal.runtime.PropertyListenerManager;
import jdk.nashorn.internal.runtime.PropertyMap;
import jdk.nashorn.internal.runtime.ScriptFunction;
@@ -248,9 +249,11 @@
* @param self self reference
* @return undefined
*/
+ @SuppressWarnings("resource")
@Function(attributes = Attribute.NOT_ENUMERABLE, where = Where.CONSTRUCTOR)
public static Object dumpCounters(final Object self) {
- final PrintStream out = System.err;
+ final PrintWriter out = Context.getContext().getErr();
+
out.println("ScriptObject count " + ScriptObject.getCount());
out.println("Scope count " + ScriptObject.getScopeCount());
out.println("ScriptObject listeners added " + PropertyListenerManager.getListenersAdded());
@@ -268,7 +271,9 @@
out.println("Callsite count " + LinkerCallSite.getCount());
out.println("Callsite misses " + LinkerCallSite.getMissCount());
out.println("Callsite misses by site at " + LinkerCallSite.getMissSamplingPercentage() + "%");
+
LinkerCallSite.getMissCounts(out);
+
return UNDEFINED;
}
}
--- a/nashorn/src/jdk/nashorn/internal/runtime/Context.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/Context.java Tue Jan 08 09:59:28 2013 +0100
@@ -72,6 +72,12 @@
};
/**
+ * Get the error stream if applicable and initialized, otherwise stderr
+ * Usually this is the error stream given the context, but for testing and
+ * certain bootstrapping situations we need a default stream
+ */
+
+ /**
* Return the current global scope
* @return current global scope
*/
@@ -119,20 +125,14 @@
* @param str text to write
* @param crlf write a carriage return/new line after text
*/
+ @SuppressWarnings("resource")
public static void err(final String str, final boolean crlf) {
- try (final PrintWriter err = Context.getContext().getErr()) {
- if (err != null) {
- if (crlf) {
- err.println(str);
- } else {
- err.print(str);
- }
+ final PrintWriter err = Context.getContext().getErr();
+ if (err != null) {
+ if (crlf) {
+ err.println(str);
} else {
- if (crlf) {
- System.err.println(str);
- } else {
- System.err.println();
- }
+ err.print(str);
}
}
}
@@ -680,13 +680,11 @@
* Hook to print stack trace for a {@link Throwable} that occurred during
* execution
*
- * TODO: use Context.err
- * .
* @param t throwable for which to dump stack
*/
public static void printStackTrace(final Throwable t) {
if (Context.DEBUG) {
- t.printStackTrace();
+ t.printStackTrace(Context.getContext().getErr());
}
}
--- a/nashorn/src/jdk/nashorn/internal/runtime/DebugLogger.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/DebugLogger.java Tue Jan 08 09:59:28 2013 +0100
@@ -59,8 +59,12 @@
* @param property system property activating the logger on {@code info} level
*/
public DebugLogger(final String loggerName, final String property) {
- this.logger = Logging.getLogger(loggerName);
- this.isEnabled = logger.getLevel() != Level.OFF || (property != null && Options.getBooleanProperty(property));
+ if (property != null && Options.getBooleanProperty(property)) {
+ this.logger = Logging.getOrCreateLogger(loggerName, Level.INFO);
+ } else {
+ this.logger = Logging.getLogger(loggerName);
+ }
+ this.isEnabled = logger.getLevel() != Level.OFF;
}
/**
--- a/nashorn/src/jdk/nashorn/internal/runtime/ECMAException.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/ECMAException.java Tue Jan 08 09:59:28 2013 +0100
@@ -181,11 +181,10 @@
*/
public static Object printStackTrace(final ScriptObject errObj) {
final Object exception = getException(errObj);
- //TODO context err instead of System.err default
if (exception instanceof Throwable) {
- ((Throwable)exception).printStackTrace();
+ ((Throwable)exception).printStackTrace(Context.getContext().getErr());
} else {
- System.err.println("<stack trace not available>");
+ Context.err("<stack trace not available>");
}
return UNDEFINED;
}
--- a/nashorn/src/jdk/nashorn/internal/runtime/ErrorManager.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/ErrorManager.java Tue Jan 08 09:59:28 2013 +0100
@@ -55,7 +55,7 @@
* Constructor
*/
public ErrorManager() {
- this(new PrintWriter(System.err, true));
+ this(new PrintWriter(System.err, true)); //bootstrapping, context may not be initialized
}
/**
--- a/nashorn/src/jdk/nashorn/internal/runtime/Logging.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/Logging.java Tue Jan 08 09:59:28 2013 +0100
@@ -72,17 +72,7 @@
* Get a logger for a given class, generating a logger name based on the
* class name
*
- * @param clazz the class
- * @return the logger
- */
- public static Logger getLogger0(final Class<?> clazz) {
- return Logging.getLogger(Logging.lastPart(clazz.getPackage().getName()));
- }
-
- /**
- * Get a logger for a given name
- *
- * @param name the name to use as key
+ * @param name the name to use as key for the logger
* @return the logger
*/
public static Logger getLogger(final String name) {
@@ -94,6 +84,23 @@
}
/**
+ * Get a logger for a given name or create it if not already there, typically
+ * used for mapping system properties to loggers
+ *
+ * @param name the name to use as key
+ * @param level log lever to reset existing logger with, or create new logger with
+ * @return the logger
+ */
+ public static Logger getOrCreateLogger(final String name, final Level level) {
+ final Logger logger = Logging.loggers.get(name);
+ if (logger == null) {
+ return instantiateLogger(name, level);
+ }
+ logger.setLevel(level);
+ return logger;
+ }
+
+ /**
* Initialization function that is called to instantiate the logging system. It takes
* logger names (keys) and logging labels respectively
*
@@ -114,32 +121,7 @@
}
final String name = Logging.lastPart(key);
-
- final Logger logger = java.util.logging.Logger.getLogger(name);
- for (final Handler h : logger.getHandlers()) {
- logger.removeHandler(h);
- }
-
- logger.setLevel(level);
- logger.setUseParentHandlers(false);
- final Handler c = new ConsoleHandler();
-
- c.setFormatter(new Formatter() {
- @Override
- public String format(final LogRecord record) {
- final StringBuilder sb = new StringBuilder();
-
- sb.append('[')
- .append(record.getLoggerName())
- .append("] ")
- .append(record.getMessage())
- .append('\n');
-
- return sb.toString();
- }
- });
- logger.addHandler(c);
- c.setLevel(level);
+ final Logger logger = instantiateLogger(name, level);
Logging.loggers.put(name, logger);
}
@@ -148,4 +130,34 @@
}
}
+ private static Logger instantiateLogger(final String name, final Level level) {
+ final Logger logger = java.util.logging.Logger.getLogger(name);
+ for (final Handler h : logger.getHandlers()) {
+ logger.removeHandler(h);
+ }
+
+ logger.setLevel(level);
+ logger.setUseParentHandlers(false);
+ final Handler c = new ConsoleHandler();
+
+ c.setFormatter(new Formatter() {
+ @Override
+ public String format(final LogRecord record) {
+ final StringBuilder sb = new StringBuilder();
+
+ sb.append('[')
+ .append(record.getLoggerName())
+ .append("] ")
+ .append(record.getMessage())
+ .append('\n');
+
+ return sb.toString();
+ }
+ });
+ logger.addHandler(c);
+ c.setLevel(level);
+
+ return logger;
+ }
+
}
--- a/nashorn/src/jdk/nashorn/internal/runtime/linker/LinkerCallSite.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/linker/LinkerCallSite.java Tue Jan 08 09:59:28 2013 +0100
@@ -29,8 +29,7 @@
import java.io.FileNotFoundException;
import java.io.FileOutputStream;
-import java.io.OutputStream;
-import java.io.PrintStream;
+import java.io.PrintWriter;
import java.lang.invoke.MethodHandle;
import java.lang.invoke.MethodHandles;
import java.lang.invoke.MethodType;
@@ -275,26 +274,37 @@
}
static class ProfileDumper implements Runnable {
+ @SuppressWarnings("resource")
@Override
public void run() {
- OutputStream out;
+ PrintWriter out = null;
+ boolean fileOutput = false;
try {
- out = new FileOutputStream(PROFILEFILE);
- } catch (final FileNotFoundException e) {
- out = new PrintStream(System.err); //TODO abstraction break- why is this hard coded to System.err when everything else uses the context
- }
+ try {
+ out = new PrintWriter(new FileOutputStream(PROFILEFILE));
+ fileOutput = true;
+ } catch (final FileNotFoundException e) {
+ out = Context.getContext().getErr();
+ }
- try (PrintStream stream = new PrintStream(out)) {
- int index = 0;
- for (final ProfilingLinkerCallSite callSite : profileCallSites) {
- stream.println("" + (index++) + '\t' +
- callSite.getDescriptor().getName() + '\t' +
- callSite.totalTime + '\t' +
- callSite.hitCount);
+ dump(out);
+ } finally {
+ if (out != null && fileOutput) {
+ out.close();
}
}
}
+
+ private static void dump(final PrintWriter out) {
+ int index = 0;
+ for (final ProfilingLinkerCallSite callSite : profileCallSites) {
+ out.println("" + (index++) + '\t' +
+ callSite.getDescriptor().getName() + '\t' +
+ callSite.totalTime + '\t' +
+ callSite.hitCount);
+ }
+ }
}
}
@@ -307,11 +317,7 @@
private static final MethodHandle TRACEVOID = findOwnMH("traceVoid", void.class, MethodHandle.class, Object[].class);
private static final MethodHandle TRACEMISS = findOwnMH("traceMiss", void.class, Object[].class);
- private static final PrintStream out = System.err; //TODO abstraction break- why is this hard coded to System.err when everything else uses the context
-
- /*
- * Constructor
- */
+ private static final PrintWriter out = Context.getContext().getErr();
TracingLinkerCallSite(final NashornCallSiteDescriptor desc) {
super(desc);
@@ -522,7 +528,7 @@
* Dump the miss counts collected so far to a given output stream
* @param out print stream
*/
- public static void getMissCounts(final PrintStream out) {
+ public static void getMissCounts(final PrintWriter out) {
final ArrayList<Entry<String, AtomicInteger>> entries = new ArrayList<>(missCounts.entrySet());
Collections.sort(entries, new Comparator<Map.Entry<String, AtomicInteger>>() {
--- a/nashorn/src/jdk/nashorn/internal/runtime/linker/MethodHandleFactory.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/linker/MethodHandleFactory.java Tue Jan 08 09:59:28 2013 +0100
@@ -25,6 +25,13 @@
package jdk.nashorn.internal.runtime.linker;
+import jdk.nashorn.internal.runtime.ConsString;
+import jdk.nashorn.internal.runtime.Debug;
+import jdk.nashorn.internal.runtime.DebugLogger;
+import jdk.nashorn.internal.runtime.ScriptObject;
+import jdk.nashorn.internal.runtime.options.Options;
+
+import java.io.ByteArrayOutputStream;
import java.io.PrintStream;
import java.lang.invoke.MethodHandle;
import java.lang.invoke.MethodHandles;
@@ -35,29 +42,23 @@
import java.util.Arrays;
import java.util.List;
import java.util.logging.Level;
-import jdk.nashorn.internal.runtime.ConsString;
-import jdk.nashorn.internal.runtime.Debug;
-import jdk.nashorn.internal.runtime.DebugLogger;
-import jdk.nashorn.internal.runtime.ScriptObject;
-import jdk.nashorn.internal.runtime.options.Options;
/**
* This class is abstraction for all method handle, switchpoint and method type
* operations. This enables the functionality interface to be subclassed and
- * instrumented, as it has been proven vital to keep the number of method
+ * intrumensted, as it has been proven vital to keep the number of method
* handles in the system down.
- * <p>
+ *
* All operations of the above type should go through this class, and not
* directly into java.lang.invoke
+ *
*/
public final class MethodHandleFactory {
private static final MethodHandles.Lookup PUBLIC_LOOKUP = MethodHandles.publicLookup();
private static final MethodHandles.Lookup LOOKUP = MethodHandles.lookup();
- private static PrintStream ERR = System.err;
-
- private static final Level TRACE_LEVEL = Level.FINEST;
+ private static final Level TRACE_LEVEL = Level.INFO;
private MethodHandleFactory() {
}
@@ -97,15 +98,26 @@
}
private static final MethodHandleFunctionality STANDARD = new StandardMethodHandleFunctionality();
- private static final MethodHandleFunctionality FUNC =
- Options.getBooleanProperty("nashorn.methodhandles.debug") ?
- (Options.getStringProperty("nashorn.methodhandles.debug","").equals("create") ?
- new TraceCreateMethodHandleFunctionality() :
- new TraceMethodHandleFunctionality())
- : STANDARD;
+ private static final MethodHandleFunctionality FUNC;
+
+ private static final String DEBUG_PROPERTY = "nashorn.methodhandles.debug";
+ private static final DebugLogger LOG = new DebugLogger("methodhandles", DEBUG_PROPERTY);
+
+ static {
+ if (LOG.isEnabled() || Options.getBooleanProperty(DEBUG_PROPERTY)) {
+ if (Options.getStringProperty(DEBUG_PROPERTY, "").equals("create")) {
+ FUNC = new TraceCreateMethodHandleFunctionality();
+ } else {
+ FUNC = new TraceMethodHandleFunctionality();
+ }
+ } else {
+ FUNC = STANDARD;
+ }
+ }
private static final boolean PRINT_STACKTRACE = Options.getBooleanProperty("nashorn.methodhandles.debug.stacktrace");
+
/**
* Return the method handle functionality used for all method handle operations
* @return a method handle functionality implementation
@@ -126,11 +138,7 @@
*/
static Object traceReturn(final DebugLogger logger, final Object value) {
final String str = "\treturn: " + stripName(value) + " [type=" + (value == null ? "null" : stripName(value.getClass()) + ']');
- if (logger != null) {
- logger.log(str, TRACE_LEVEL);
- } else {
- ERR.println(str);
- }
+ logger.log(str, TRACE_LEVEL);
return value;
}
@@ -165,14 +173,19 @@
}
}
- if (logger != null) {
- logger.log(sb.toString(), TRACE_LEVEL);
- } else {
- ERR.print(sb);
- if (PRINT_STACKTRACE) {
- new Throwable().printStackTrace(ERR);
- }
+ assert logger != null;
+ logger.log(sb.toString(), TRACE_LEVEL);
+ stacktrace(logger);
+ }
+
+ private static void stacktrace(final DebugLogger logger) {
+ if (!PRINT_STACKTRACE) {
+ return;
}
+ final ByteArrayOutputStream baos = new ByteArrayOutputStream();
+ final PrintStream ps = new PrintStream(baos);
+ new Throwable().printStackTrace(ps);
+ logger.log(baos.toString(), TRACE_LEVEL);
}
private static String argString(final Object arg) {
@@ -199,18 +212,6 @@
}
/**
- * Add a debug printout to a method handle, tracing parameters and return values. Output
- * will be written to stderr.
- *
- * @param mh method handle to trace
- * @param tag start of trace message
- * @return traced method handle
- */
- public static MethodHandle addDebugPrintout0(final MethodHandle mh, final Object tag) {
- return addDebugPrintout(null, mh, 0, true, tag);
- }
-
- /**
* Add a debug printout to a method handle, tracing parameters and return values
*
* @param logger a specific logger to which to write the output
@@ -240,6 +241,7 @@
return mh;
}
+ assert logger != null;
assert TRACE != null;
MethodHandle trace = MethodHandles.insertArguments(TRACE, 0, logger, tag, paramStart);
@@ -263,7 +265,7 @@
}
/**
- * The standard class that marshals all method handle operations to the java.lang.invoke
+ * The standard class that marshalls all method handle operations to the java.lang.invoke
* package. This exists only so that it can be subclassed and method handles created from
* Nashorn made possible to instrument.
*
@@ -464,7 +466,7 @@
}
public MethodHandle debug(final MethodHandle master, final String str, final Object... args) {
- return addDebugPrintout(null, master, Integer.MAX_VALUE, false, str + ' ' + describe(args));
+ return addDebugPrintout(LOG, master, Integer.MAX_VALUE, false, str + ' ' + describe(args));
}
@Override
@@ -602,7 +604,7 @@
@Override
public SwitchPoint createSwitchPoint() {
final SwitchPoint sp = super.createSwitchPoint();
- ERR.println("createSwitchPoint " + sp);
+ LOG.log("createSwitchPoint " + sp, TRACE_LEVEL);
return sp;
}
@@ -615,7 +617,7 @@
@Override
public MethodType type(final Class<?> returnType, final Class<?>... paramTypes) {
final MethodType mt = super.type(returnType, paramTypes);
- ERR.println("methodType " + returnType + ' ' + Arrays.toString(paramTypes) + ' ' + mt);
+ LOG.log("methodType " + returnType + ' ' + Arrays.toString(paramTypes) + ' ' + mt, TRACE_LEVEL);
return mt;
}
}
@@ -626,7 +628,8 @@
private static class TraceCreateMethodHandleFunctionality extends TraceMethodHandleFunctionality {
@Override
public MethodHandle debug(final MethodHandle master, final String str, final Object... args) {
- ERR.println(str + ' ' + describe(args));
+ LOG.log(str + ' ' + describe(args), TRACE_LEVEL);
+ stacktrace(LOG);
return master;
}
}
--- a/nashorn/src/jdk/nashorn/internal/runtime/options/Options.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/internal/runtime/options/Options.java Tue Jan 08 09:59:28 2013 +0100
@@ -44,19 +44,19 @@
import java.util.TimeZone;
import java.util.TreeMap;
import java.util.TreeSet;
+
import jdk.nashorn.internal.runtime.Logging;
import jdk.nashorn.internal.runtime.QuotedStringTokenizer;
/**
* Manages global runtime options.
- *
*/
public final class Options {
/** Resource tag. */
private final String resource;
/** Error writer. */
- private final PrintWriter errors;
+ private final PrintWriter err;
/** File list. */
private final List<String> files;
@@ -68,14 +68,25 @@
private final TreeMap<String, Option<?>> options;
/**
- * Constructor.
+ * Constructor
+ *
+ * Options will use System.err as the output stream for any errors
*
* @param resource resource prefix for options e.g. "nashorn"
- * @param errors error stream for reporting parse errors
*/
- public Options(final String resource, final PrintWriter errors) {
+ public Options(final String resource) {
+ this(resource, new PrintWriter(System.err, true));
+ }
+
+ /**
+ * Constructor
+ *
+ * @param resource resource prefix for options e.g. "nashorn"
+ * @param err error stream for reporting parse errors
+ */
+ public Options(final String resource, final PrintWriter err) {
this.resource = resource;
- this.errors = errors;
+ this.err = err;
this.files = new ArrayList<>();
this.arguments = new ArrayList<>();
this.options = new TreeMap<>();
@@ -88,22 +99,13 @@
if (v != null) {
set(t.getKey(), createOption(t, v));
} else if (t.getDefaultValue() != null) {
- set(t.getKey(), createOption(t, t.getDefaultValue()));
+ set(t.getKey(), createOption(t, t.getDefaultValue()));
}
}
}
}
/**
- * Constructor
- *
- * @param resource e.g. "nashorn"
- */
- public Options(final String resource) {
- this(resource, new PrintWriter(System.err, true));
- }
-
- /**
* Get the resource for this Options set, e.g. "nashorn"
* @return the resource
*/
@@ -343,17 +345,17 @@
// display extended help information
displayHelp(true);
} else {
- errors.println(((IllegalOptionException)e).getTemplate());
+ err.println(((IllegalOptionException)e).getTemplate());
}
return;
}
if (e != null && e.getMessage() != null) {
- errors.println(getMsg("option.error.invalid.option",
+ err.println(getMsg("option.error.invalid.option",
e.getMessage(),
helpOptionTemplate.getShortName(),
helpOptionTemplate.getName()));
- errors.println();
+ err.println();
return;
}
@@ -368,8 +370,8 @@
public void displayHelp(final boolean extended) {
for (final OptionTemplate t : Options.validOptions) {
if ((extended || !t.isUndocumented()) && t.getResource().equals(resource)) {
- errors.println(t);
- errors.println();
+ err.println(t);
+ err.println();
}
}
}
--- a/nashorn/src/jdk/nashorn/tools/Shell.java Tue Jan 08 08:51:00 2013 +0530
+++ b/nashorn/src/jdk/nashorn/tools/Shell.java Tue Jan 08 09:59:28 2013 +0100
@@ -114,7 +114,7 @@
try {
System.exit(main(System.in, System.out, System.err, args));
} catch (final IOException e) {
- System.err.println(e);
+ System.err.println(e); //bootstrapping, Context.err may not exist
System.exit(IO_ERROR);
}
}