274467 - Add JavaScript stack trace to exceptions

Status: RESOLVED FIXED

(Rhino Graveyard :: Core, enhancement)

Description

[Daniel Gredler]

It would be nice to have a JavaScript stack trace in exceptions thrown by Rhino,
maybe in EcmaError. Right now EcmaError has sourceName, lineNumber, columnNumber
and lineSource, but it would be nice to have this data for each call on the
stack at the time of the error. This would make it much easier for applications
that embed Rhino to debug their problems.

Comment 1

[Igor Bukanov]

Do you use the default compile-to-jvm-classes mode in Rhino? In that case the
standard Java printStackTrace should provide information about error locations
in script.

On the other hand if you use pure interpretation (optimization level == -1),
then Java printStackTrace is useless indeed.

Comment 2

[Attila Szegedi]

Well, our production system is using Rhino in interpreted mode, since it relies 
on continuations. A detailed stack trace would be nice indeed. I understand it 
might be hard to generate, as several invocations of Interpreter.interpret() can 
be on the Java stack, interweaved with calls to Java methods on host objects 
that call back into interpreted JavaScript functions, so it's possible this call 
stack should be maintained in a thread local. Now, instad of updating it on each 
method call, an optimization would be to actually only maintain a stack of top 
frames for Interpreter.interpret() invocations when they transition into Java 
code - the top frame in Interpreter().interpret() call would get pushed on it 
prior to calling a native Java function, and popped from it upon return. On 
exception, the current interpret() would first generate a trace from its own 
frames walking the parentFrame chain starting from its top frame, and then do 
the same for all the other top frames found on the thread local stack.

Comment 3

[Attila Szegedi]

Just a heads-up, I've started working on this; should be done soon. I think I 
found an elegant way to embed the functionality.

Comment 4

[Attila Szegedi]

Attachment: Implementation for the full JavaScript stack trace in Java stack trace

Comment 5

[Attila Szegedi]

Attachment: A small testcase showing the new functionality

Place it into a package named "test"

Comment 6

[Attila Szegedi]

Attachment: Output of the test program

You can see two JavaScript stack trace elements:

...
at script(bar:3)
...
at script(foo:2)
...

belonging to two nested invocations of the interpreter interleaved with Java
stack trace elements.

Comment 7

[Igor Bukanov]

To observations about the patch:

1. It introduces the dependency on JDK 1.4 via direct call to
Throawable.initCause(). Please avoid it. 

2. It makes constructions of RhinoException instances significantly heavier even
when users use class compiler. I think storing just reference to CallFrameHolder
during construction should be enough to print the stack trace if necessary.

Comment 8

[Attila Szegedi]

(In reply to comment #7)
> To observations about the patch:
> 
> 1. It introduces the dependency on JDK 1.4 via direct call to
> Throawable.initCause(). Please avoid it. 
> 

I had to add it so the stack trace is recreated in order for the causes to be 
reflected in the annotated stack trace as well. I further inspected where is it 
called from, and I can get around it by making captureJavaScriptStackTrace() 
package-private, and make sure it's called from Kit.initCause when it is invoked 
with a RhinoException.

> 2. It makes constructions of RhinoException instances significantly heavier 
even
> when users use class compiler. I think storing just reference to 
CallFrameHolder
> during construction should be enough to print the stack trace if necessary.

My only problem with that is that the locations CallFrame objects point (and 
actually the CallFrame objects referred to in the CallFrameHolder) at the time 
the exception is printed can be significantly different than when the exception 
was created. As a remedy for class compiler case, the 
captureJavaScriptStackTrace() could check for cx.interpreterLineCounting == null 
and shortcut the whole dump-to-string-writer business.

Hope it'll be acceptable with these changes.

Comment 9

[Igor Bukanov]

(In reply to comment #8)
> > 2. It makes constructions of RhinoException instances significantly heavier 
> even
> > when users use class compiler. I think storing just reference to 
> CallFrameHolder
> > during construction should be enough to print the stack trace if necessary.
> 
> My only problem with that is that the locations CallFrame objects point (and 
> actually the CallFrame objects referred to in the CallFrameHolder) at the time 
> the exception is printed can be significantly different than when the exception 
> was created.

But then both holder and frame can be stored or the holder can be cloned to get
a frozen copy. Not all exceptions get their stack trace printed and it does not
sound right to execute all the code to produce a string with nicely formated trace.

> 
> Hope it'll be acceptable with these changes.

Sure.

Comment 10

[Attila Szegedi]

Attachment: Another take, now with freezing frames

Okay, I think I understood the concept of freezing call frames and call frame
holders objects and cloning them on-demand. Here's a new version that should
keep the lightweight construction of the exception - only the frame holder is
stored, with all holders and frames reachable from it frozen. I'll attach a new
testcase where the trace is printed from an entirely different interpreter
session, and it works nicely. I even managed to make the printing process as
lightweight as possible, by implementing a special filtering PrintStream and
PrintWriter for the purpose, so no buffering/reparsing of the printed stack
trace is required.

Comment 11

[Attila Szegedi]

Attachment: A small testcase showing the functionality

Comment 12

[Attila Szegedi]

Attachment: Output of the test program

Comment 13

[Igor Bukanov]

(In reply to comment #10)
> Created an attachment (id=173902) [edit]
> Another take, now with freezing frames
> 
> Okay, I think I understood the concept of freezing call frames and call frame
> holders objects and cloning them on-demand. Here's a new version that should
> keep the lightweight construction of the exception - only the frame holder is
> stored, with all holders and frames reachable from it frozen. 

You do not need to freeze frames! Your code to print stack trace just uses idata
and parentFrame, but that would not change during the following calculations in
the Interpreter.interpret. In fact, to print stack trace you just need the heads
of CallFrame chains from each Interpreter invocation on Java stack. So it seems
the exception constructor can  calculate the depth of CallFrameHolder chain,
allocate CallFrame array, fill it with heads of CallFrame chains and store that
in the exception.

Comment 14

[Attila Szegedi]

Attachment: Improvement over the last one - eliminated nearly duplicated code for PrintWriter/PrintStream

I improved the last night's version slightly. There are no longer two separate
classes for printing the stack trace (one PrintStream subclass and one
PrintWriter subclass) with nearly identical code. I kept only the PrintWriter
one, and when printing to a PrintStream is required, I wrap it in an output
stream writer and print writer first. I really wish Sun engineered PrintStream
and PrintWriter so that they implement a common interface declaring all of
their print...() method. Actually, I'm not the only one to wish for this as
witnessed on: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=5035587

Comment 15

[Igor Bukanov]

(In reply to own comment #13)
> (In reply to comment #10)
> > Created an attachment (id=173902) [edit] [edit]
> > Another take, now with freezing frames
> > 
> > Okay, I think I understood the concept of freezing call frames and call frame
> > holders objects and cloning them on-demand. Here's a new version that should
> > keep the lightweight construction of the exception - only the frame holder is
> > stored, with all holders and frames reachable from it frozen. 
> 
> You do not need to freeze frames! Your code to print stack trace just uses idata
> and parentFrame,

That is, of cause, wrong, since the code uses pcSourceLineStart which would
change. So with the above it is necessary to capture array of lines per each
InterpreterFarme that with CallFrame linked list would provide stack trace
information. 

Now that does not sound particularly better then frame freezing since the later
would avoid allocating of any objects if there are no exception handlers in the
Interpreter.interpret.

On the other hand the exception origin information may only change if the
exception is caught in Interpreter.interpret or bellow. If the catch handler
belongs to the Java code, then its execution would not change the interpreter
data in all practical cases. And if it is Interpreter.interpreter that prepares
to execute catch code in JS, then it can explicitly force construction of stack
information.

Thus the idea would be in the exception constructor to store only the current
CallFrameHolder. Then the exception should contain a method to force creation of
stack trace. Interpreter would call the method when preparing to execute the
catch handler in the script. Rhino embedding may also call this method if it
catches RhinoException and plans to do something smart with it besides printing
stack-related information immediately.

Comment 16

[Attila Szegedi]

(In reply to comment #15)
> 
> On the other hand the exception origin information may only change if the
> exception is caught in Interpreter.interpret or bellow. If the catch handler
> belongs to the Java code, then its execution would not change the interpreter
> data in all practical cases. And if it is Interpreter.interpreter that 
prepares
> to execute catch code in JS, then it can explicitly force construction of 
stack
> information.
> 
> Thus the idea would be in the exception constructor to store only the current
> CallFrameHolder. Then the exception should contain a method to force creation 
of
> stack trace. Interpreter would call the method when preparing to execute the
> catch handler in the script. Rhino embedding may also call this method if it
> catches RhinoException and plans to do something smart with it besides 
printing
> stack-related information immediately.

Well, I'm not seeing this either as being particularly better than frame 
freezing. There's again the issue of an exception stack trace being generated 
forcibly even if it might happen that it will never be printed. Also, it exposes 
an implementation detail to an "advanced" embedder - he must remember to call 
the generator method. Granted, this can only be an issue if the embedder happens 
to call an interpreted function/script from the catch block. Frame freezing code 
takes care of all corner cases in a self-contained way, and I don't think 
there's a big cost difference between taking a snapshot of locations for the 
stack trace in the interpreter catch handler vs. making clones of frames in the 
interpreter if it recovers from the exception. Especially since the code for 
management of freezing is already in place, and doing a forcible capture would 
require RhinoException to cache a string containing the printed trace. 
Therefore, frame freezing looks like a more elegant solution to me, but then I'm 
a rather new to the Rhino code and I accept that you have more insight into it.

Comment 17

[Igor Bukanov]

(In reply to comment #16)
> Well, I'm not seeing this either as being particularly better than frame 
> freezing.

Frame freezing would lead to frame cloning if the exception is caught inside
Interpreter.interpret and this is not exactly cheap operation. With a few nested
script frames on top of try /catch in JS generating the stack may be cheaper
then cloning the frames. 

> There's again the issue of an exception stack trace being generated 
> forcibly even if it might happen that it will never be printed. 
> Also, it exposes 
> an implementation detail to an "advanced" embedder - he must remember to call 
> the generator method. Granted, this can only be an issue if the embedder happens 
> to call an interpreted function/script from the catch block.

That would not affect the capturing information. The only case when it would
matter is when the handler would return somehow the exeception object back to
the script before printing the stack trace. But that require to wrap execption
before sending it to JS and Rhino can call the method itself in the wrapping
code. Since code to generate the catch object for native exception would go
through the same path, it would add that forcefull stack creation only in one place.

> Frame freezing code 
> takes care of all corner cases in a self-contained way.

Right, but that requires a lot more code then the original patch and that does
not seems justifiable.

> and I don't think 
> there's a big cost difference between taking a snapshot of locations for the 
> stack trace in the interpreter catch handler vs. making clones of frames in the 
> interpreter if it recovers from the exception. Especially since the code for 
> management of freezing is already in place, and doing a forcible capture would 
> require RhinoException to cache a string containing the printed trace. 
> Therefore, frame freezing looks like a more elegant solution to me, but then I'm 
> a rather new to the Rhino code and I accept that you have more insight into it.

Comment 18

[Attila Szegedi]

Attachment: Yet another try without frame freezing

Okay, here's another try - no frame freezing,
RhinoException.generateStackTrace() called when a frame was found that can
handle the exception, just before StateLoop is continued. generateStackTrace()
also called in printStackTrace() (does nothing if it was already called before)
so it handles the case where the exception bubbles up into Java code where the
trace is printed without it ever being handled at all in the interpreter.

How does it look now?

Comment 19

[Igor Bukanov]

Comment on attachment 173956 [details] [diff] [review]
Yet another try without frame freezing

> 
>             for (;;) {
>                 if (exState != EX_NO_JS_STATE) {
>                     boolean onlyFinally = (exState != EX_CATCH_STATE);
>                     indexReg = getExceptionHandler(frame, onlyFinally);
>                     if (indexReg >= 0) {
>+                        if(throwable instanceof RhinoException) {
>+                            ((RhinoException)throwable).generateStackTrace();
>+                        }
>                         // We caught an exception, restart the loop
>                         // with exception pending the processing at the loop
>                         // start
>                         continue StateLoop;
>                     }

That is not right as it would force stack trace for finally as well and would
miss the case of class compiler between interpreter frames. I suggest to put
the check to WrapFactory before calls to WrapFactory.wrapAsJavaObject.

Otherwise the patch is OK.

Comment 20

[Daniel Gredler]

I just wanted to send a big "Thank You" to Attila for working on this! Much
appreciated!

Comment 21

[Attila Szegedi]

(In reply to comment #20)
> I just wanted to send a big "Thank You" to Attila for working on this! Much
> appreciated!

Well, I thank you for the appreciation. However, I've come under a rather heavy 
load on my pay job, so I'm not sure if I can keep working on it. If it really 
only requires a finishing touch or two, maybe Igor can take it over. Lacking 
this, I might be able to return to it in, like, two weeks.

Comment 22

[Igor Bukanov]

Attachment: Duplicate only mutable information etc.

Changes from the previous version:

1. In the new version RhinoException constructor duplicates the information
that can change during the following execution. Then the captured immune data
are used to augment the native stack trace with script information when
requested.

In particular the patch stores in RhinoException the array of top CallFrame
instances from each interpreter invocation and array of
CallFrame.pcSourceLineStart from all CallFrame instances from all interpreter
invocations. It is relatively lightweight and should not impose noticable
performace penalty if stack is not printed.

2. I replaced CallFrameHolder by a stack of top frames from each interpreter
invocation. In this way there is no need to create an additional object per
each interpreter invocation and creation of array of top frames is simplified.

3. The previous version depended on the fact that JVM would call
PrintWriter.println() to print stack entries. Since there is no any guaranty
that it would stay that way on any JVM where Rhino could run, I changed that to
explicit parsing of the stack trace. To make life even I renamed the
interpreter loop routine to interpreterLoop to have a simple tag to look for.

Comment 23

[Igor Bukanov]

Attachment: Better stack trace

1. Stack trace includes function name when available.

2. Patch tries to decrease the number of various Interpreter.interpret calls
before the real interpretation can start. It makes the interpreter
initialization slightly faster and stack trace looks more clear.

Comment 24

[Igor Bukanov]

Attachment: Test output with the last patch

Comment 25

[Igor Bukanov]

I committed the last patch.

Comment 26

[Attila Szegedi]

Attachment: Patch for wrapping unchecked exceptions from Java method invocations

Recently we had a problem with a NPE occurring in a Java method - it wasn't
wrapped into WrappedException and subsequently we did not see the interpreter
script stack traces. This is because unchecked throwables aren't wrapped into
InvocationTargetException. I changed the relevant code in MemberBox.java to
wrap all exceptions (checked and unchecked) into WrappedException. BTW, this is
now consistent with how JavaMembers.get() and JavaMembers.put() work - they
also wrap all exceptions into WrappedException, not just
InvocationTargetException.

Comment 27

[Attila Szegedi]

Attachment: Patch for wrapping unchecked exceptions from Java method invocations

Sorry, uploaded a wrong file previously

Comment 28

[Attila Szegedi]

Hm... For some reason, before I added the patch Bugzilla showed me an option to 
reopen the bug, now it doesn't.

Comment 29

[Igor Bukanov]

I committed the last patch.

Comment 30

[Attila Szegedi]

Attachment: Patch for adding a "rhinoException" property to error objects

The wrapped exception carrying the embedded script stack trace can become
inaccessible to the calling Java code if the script catches and rethrows
exceptions. I.e.
----------------------------------------------------
try
{
    new java.io.FileInputStream("nonexistant file");
}
catch(e)
{
    throw e;
}
----------------------------------------------------

The Java code invoking the interpreter won't be able to retrieve the
WrappedException that carries the script stack trace. It can only retrieve the
underlying e.javaException using code similar to this:

----------------------------------------------------
Throwable terminationCause;
try
{
    script.exec(cx, scope);
}
catch(JavaScriptException e)
{
    terminationCause = e;
    Object val = e.getValue();
    if(val instanceof Scriptable)
    {
	Object njo = ScriptableObject.getProperty(((Scriptable)val),
"javaException");
	if(njo instanceof NativeJavaObject)
	{
	    val = njo;
	}
	if(val instanceof NativeJavaObject)
	{
	    Object t = ((NativeJavaObject)val).unwrap();
	    while(t instanceof InvocationTargetException)
	    {
		t = ((InvocationTargetException)t).getCause();
	    }
	    if(t instanceof Throwable)
	    {
		terminationCause = (Throwable)t;
	    }
	}
    }	 
}
catch(Throwable t)
{
    terminationCause = t;
}
----------------------------------------------------

I'm attaching a patch that'd add another property to the JavaScript error
object, named "rhinoException" that'd contain the originating RhinoException.
In my above code that attempts to extract the underlying exception from the
JavaScriptException, I could then obtain the RhinoException by calling
ScriptableObject.getProperty with "rhinoException" instead of "javaException".
That way, I could still properly log exceptions with script stack trace even
when the script does a try-catch-rethrow.