Closed Bug 503244 Opened 15 years ago Closed 11 years ago

Log exceptions thrown from event listener callbacks in the error console

Categories

(Core :: DOM: Core & HTML, defect)

x86
Windows 7
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla27

People

(Reporter: alfredkaseltzer, Assigned: bzbarsky)

References

Details

(Keywords: regression)

Attachments

(3 files, 1 obsolete file)

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US; rv:1.9.2a1pre) Gecko/20090708 Minefield/3.6a1pre (.NET CLR 3.5.30729)
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US; rv:1.9.2a1pre) Gecko/20090708 Minefield/3.6a1pre (.NET CLR 3.5.30729)

Any errors thrown from an event handler called via a simulated event will not show up in the Error Console.


Reproducible: Always

Steps to Reproduce:
1.Create a javascript function that throws an event.
2.Call that function via a simulated event (createEvent,initEvent,dispatchEvent for example)
Actual Results:  
The error thrown doesn't appear in the Error Console.

Expected Results:  
Displayed exception information in the Error Console.

I've attached a some code that illustrates this.

In previous versions, the following error would be logged when opening this page:

Error: [Exception... "'Error: error' when calling method: [nsIDOMEventListener::handleEvent]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "JS frame :: http://7e2617e61ec94e3/wiggles/home/default.html :: <TOP_LEVEL> :: line 15"  data: no]
Source File: http://example.com/
Line: 15

I've been able to reproduce this on XP SP3 and Windows 7 RC1 (build 7100).
Attached file no error logged in 3.5
Assignee: nobody → general
Component: General → JavaScript Engine
Product: Firefox → Core
QA Contact: general → general
Version: unspecified → Trunk
Was able to reproduce on Firefox 3.5.2 on Mac OS 10.5.7 with the following code: http://gist.github.com/165294
This HTML file should throw an error when opened in a browser. Doesn't in FF 3.5.2.
Tobie, can you reproduce this in Firefox's safe mode?  Also, how about if you toggle jit.chrome to false in about:config?
Yes, reproduced it in safe mode with jit.chrome both set to false (default on my install, FWIW) and to true.
Ok thanks!  This this regress in the 3.5 release?  Like it worked in Firefox 3.0.X but not in 3.5.X?
Status: UNCONFIRMED → NEW
Ever confirmed: true
Correct.
I confirm it's a regression. In 3.0.13 safe mode, test page correctly throws:

Error: [Exception... "'resized!' when calling method: [nsIDOMEventListener::handleEvent]"  nsresult: "0x8057001e (NS_ERROR_XPC_JS_THREW_STRING)"  location: "JS frame :: file:///Users/tobie/Desktop/test.html :: <TOP_LEVEL> :: line 8"  data: no]
Source File: file:///Users/tobie/Desktop/test.html
Line: 8
Keywords: regression
Using the testcase from bug 574941, I found that the stack looks like this, as one would expect:

#0  js::Interpret (cx=0x9912750, entryFrame=0xb39fe0a0, inlineCallCount=0, interpMode=JSINTERP_NORMAL) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsinterp.cpp:6191
#1  0x02604dec in js::RunScript (cx=0x9912750, script=0x9ef6140, fp=0xb39fe0a0) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsinterp.cpp:653
#2  0x026052eb in js::Invoke (cx=0x9912750, argsRef=..., flags=8192) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsinterp.cpp:740
#3  0x026058cb in js::ExternalInvoke (cx=0x9912750, thisv=..., fval=..., argc=1, argv=0xbfb6c718, rval=0xbfb6c790) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsinterp.cpp:863
#4  0x02569a9e in JS_CallFunctionValue (cx=0x9912750, obj=0xb253f8f8 [Object HTMLDocument], fval=$jsval(0xb253f038 [Object Function <unnamed>]), argc=1, argv=0xbfb6c718, rval=0xbfb6c790)
    at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsapi.cpp:5173
#5  0x01a324a8 in nsXPCWrappedJSClass::CallMethod (this=0x942b110, wrapper=0x965fa00, methodIndex=3, info=0x8fba708, nativeParams=0xbfb6ca6c)
    at /home/t_mattjo/src/firefox/mozilla-central/js/src/xpconnect/src/xpcwrappedjsclass.cpp:1672
#6  0x01a29307 in nsXPCWrappedJS::CallMethod (this=0x965fa00, methodIndex=3, info=0x8fba708, params=0xbfb6ca6c) at /home/t_mattjo/src/firefox/mozilla-central/js/src/xpconnect/src/xpcwrappedjs.cpp:588
#7  0x021ae5db in PrepareAndDispatch (methodIndex=3, self=0x9da5c20, args=0xbfb6cb44) at /home/t_mattjo/src/firefox/mozilla-central/xpcom/reflect/xptcall/src/md/unix/xptcstubs_gcc_x86_unix.cpp:95
#8  0x01302906 in nsEventListenerManager::HandleEventSubType (this=0x9f1ba88, aListenerStruct=0x9b68ef0, aListener=0x9da5c20, aDOMEvent=0x92bf378, aCurrentTarget=0x911d3b0, aPhaseFlags=2, aPusher=0xbfb6ce48)
    at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventListenerManager.cpp:1127
#9  0x01302cee in nsEventListenerManager::HandleEventInternal (this=0x9f1ba88, aPresContext=0x9ce4dd0, aEvent=0x92fe558, aDOMEvent=0xbfb6ce60, aCurrentTarget=0x911d3b0, aFlags=2, aEventStatus=0xbfb6ce64, aPusher=
    0xbfb6ce48) at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventListenerManager.cpp:1222
#10 0x0132d0d8 in nsEventListenerManager::HandleEvent (this=0x9f1ba88, aPresContext=0x9ce4dd0, aEvent=0x92fe558, aDOMEvent=0xbfb6ce60, aCurrentTarget=0x911d3b0, aFlags=2, aEventStatus=0xbfb6ce64, aPusher=0xbfb6ce48)
    at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventListenerManager.h:146
#11 0x0132d59a in nsEventTargetChainItem::HandleEvent (this=0x9432c08, aVisitor=..., aFlags=2, aMayHaveNewListenerManagers=0, aPusher=0xbfb6ce48)
    at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventDispatcher.cpp:212
#12 0x0132b394 in nsEventTargetChainItem::HandleEventTargetChain (this=0x9432aa8, aVisitor=..., aFlags=6, aCallback=0x0, aMayHaveNewListenerManagers=0, aPusher=0xbfb6ce48)
    at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventDispatcher.cpp:364
#13 0x0132bf23 in nsEventDispatcher::Dispatch (aTarget=0x94eb298, aPresContext=0x9ce4dd0, aEvent=0x92fe558, aDOMEvent=0x92bf378, aEventStatus=0xbfb6cf94, aCallback=0x0, aTargets=0x0)
    at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventDispatcher.cpp:628
#14 0x0132c2d6 in nsEventDispatcher::DispatchDOMEvent (aTarget=0x94eb298, aEvent=0x0, aDOMEvent=0x92bf378, aPresContext=0x9ce4dd0, aEventStatus=0xbfb6cf94)
    at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventDispatcher.cpp:691
#15 0x013031e6 in nsEventListenerManager::DispatchEvent (this=0x93b06b0, aEvent=0x92bf378, _retval=0xbfb6d024) at /home/t_mattjo/src/firefox/mozilla-central/content/events/src/nsEventListenerManager.cpp:1345
#16 0x01235a91 in nsDOMEventRTTearoff::DispatchEvent (this=0x9ec44b8, aEvt=0x92bf378, _retval=0xbfb6d024) at /home/t_mattjo/src/firefox/mozilla-central/content/base/src/nsGenericElement.cpp:2040
#17 0x01a89df9 in nsIDOMEventTarget_DispatchEvent (cx=0x9912750, argc=1, vp=0xb39fe060) at dom_quickstubs.cpp:13959
#18 0x02608c24 in js::CallJSNative (cx=0x9912750, native=0x1a89c89 <nsIDOMEventTarget_DispatchEvent(JSContext*, uintN, jsval*)>, argc=1, vp=0xb39fe060)
    at /home/t_mattjo/src/firefox/mozilla-central/js/src/jscntxtinlines.h:701
#19 0x0283b994 in js::Interpret (cx=0x9912750, entryFrame=0xb39fe030, inlineCallCount=0, interpMode=JSINTERP_NORMAL) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsinterp.cpp:4799
#20 0x02604dec in js::RunScript (cx=0x9912750, script=0x92eded8, fp=0xb39fe030) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsinterp.cpp:653
#21 0x026060f7 in js::Execute (cx=0x9912750, chain=0xb253d280 [Object Window], script=0x92eded8, prev=0x0, flags=0, result=0x0) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsinterp.cpp:1028
#22 0x02569180 in EvaluateUCScriptForPrincipalsCommon (cx=0x9912750, obj=0xb253d280 [Object Window], principals=0x9d5f774, chars=0x9c3f778, length=232, filename=
    0x9c5c178 "https://bug503244.bugzilla.mozilla.org/attachment.cgi?id=393539", lineno=4, rval=0x0, compileVersion=JSVERSION_DEFAULT) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsapi.cpp:5059
#23 0x0256922b in JS_EvaluateUCScriptForPrincipalsVersion (cx=0x9912750, obj=0xb253d280 [Object Window], principals=0x9d5f774, chars=0x9c3f778, length=232, filename=
    0x9c5c178 "https://bug503244.bugzilla.mozilla.org/attachment.cgi?id=393539", lineno=4, rval=0x0, version=JSVERSION_DEFAULT) at /home/t_mattjo/src/firefox/mozilla-central/js/src/jsapi.cpp:5075
#24 0x014fb13e in nsJSContext::EvaluateString (this=0x9912708, aScript=..., aScopeObject=0xb253d280, aPrincipal=0x9d5f770, aURL=0x9c5c178 "https://bug503244.bugzilla.mozilla.org/attachment.cgi?id=393539", aLineNo=4, 
    aVersion=0, aRetValue=0x0, aIsUndefined=0xbfb6e3f8) at /home/t_mattjo/src/firefox/mozilla-central/dom/base/nsJSEnvironment.cpp:1460
#25 0x01275fdd in nsScriptLoader::EvaluateScript (this=0x9129bf0, aRequest=0x9f219a0, aScript=...) at /home/t_mattjo/src/firefox/mozilla-central/content/base/src/nsScriptLoader.cpp:906

where the top frame is the throw instruction.

In nsXPCWrappedJSClass::CallMethod we correctly determine that the event handler was unsuccessful, and call

>        return CheckForException(ccx, name, GetInterfaceName(), forceReport);

In CheckForException, we determine it's a JS exception and attempt to report it:

>            if(reportable && is_js_exception &&
>               cx->errorReporter != xpcWrappedJSErrorReporter)
>            {
>                reportable = !JS_ReportPendingException(cx);
>            }

This correctly ends up in NS_ScriptErrorReporter, but then we discover that there is another JS stack frame, so we don't bother reporting.  Back in nsXPCWrappedJSClass::CheckForException, we save the exception on the XPC context:

>            // Whether or not it passes the 'reportable' test, it might
>            // still be an error and we have to do the right thing here...
>            if(NS_FAILED(e_result))
>            {
>                ccx.GetThreadData()->SetException(xpc_exception);
>                return e_result;
>            }

and then clear the pending exception on cx because there's and AutoClearPendingException object on the stack.

I'm not really sure who calls GetThreadData)->GetException in the codebase, but there's no other XPConnect machinery in the original call stack, and the cx's pending exception has been cleared, so it doesn't surprise me very much that we lose the exception here.  Thoughts, those in the know?
Assignee: general → nobody
Component: JavaScript Engine → DOM
QA Contact: general → general
I would like to underscore how painful this bug is.  The company I work for has a large Javascript based application based on Prototype.js.  Much of the code is triggered around firing events via dispatchEvent.  With errors not being reported our suite of Unit tests are failing with no notice.  To debug error we have to add try/catch blocks all over the handlers to try to see if there is a problem.
Regression range would be very useful.
This is also a blocker here and I quite fail to understand how it does not impact more people.
Are there no regression test tools based on the possibility to simulate event handlers? How are they not impacted by this?
After a failed attempt to try to compile mozilla-central from 2008 (thus preventing me from doing an hg bisect), I started going through old nightly builds.

This works: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2008/09/2008-09-26-02-mozilla-central/

Unfortunately, no builds after that until http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2008/11/2008-11-07-01-mozilla-central/ will start up for me, which shows the bug.

I guess that just narrows the regression down to being introduced in 3.1b2. Does that help?
Okay, I discovered that the win32 nightly builds from October 2008 actually start up, so I did a bit more digging.

Works: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2008/10/2008-10-12-03-mozilla-central/
Does not work: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2008/10/2008-10-13-03-mozilla-central/

Not much changed on the 12th. Could it have been http://hg.mozilla.org/mozilla-central/rev/46edde157751 ?
Could you look at the changesets of those builds and
give a link to the regression range.
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=<changeset1>&tochange=<changeset2>
You can get the changeset from about:buildconfig
Olli, given that bug 455436 introduced the code in NS_ScriptErrorReporter that short-circuits if a previous JS stack frame is found, I think it's safe to say that it caused the change in behaviour here.
Blocks: 455436
I suspect the correct fix here (and possibly bug 502718 as well) will be along the lines of what bug 489671 did - when the event handler is triggered, we want to pretend that no previous JS frames exist. Boris, any thoughts? Presumably, the main thing causing the fix for bug 489671 not to work is that nsXPCWrappedJSClass::CheckForException clears the pending exception, so the later machinery can't do anything about it.
Whoops, forgot to cc bz when directly addressing him in comment 22.
That seems like the obvious fix here, yes.  I suspect that the real issue is that we're not going through nsJSContext::CallEventHandler at all in this case, so we're not hitting the code that I changed in bug 489671.

Can we just set aside the frame chain in the event listener manager before calling handleEvent on the listener?
I'll look into that potential solution.
Assignee: nobody → josh
Huh, to add some new JS API stuff to ELM. Please no. XPConnect should be
wise enough to do such things.
But if hacking ELM is the only solution, be *very* careful with performance.
Everything under nsEventListenerManager::HandleEventInternal shows up in the
performance profiles. (There are anyway still things to optimize, but I
certainly don't want to make things slower.)
Well.  ELM is already manually pushing nsJSContexts, right?  We can just make whatever it does there also set aside the frame chain.
Well, ELM just relies on nsCxPusher to do the right thing when
nsPIDOMEventTarget is passed as a parameter. And we're trying to get rid of that
cx pushing anyway.

How fast or slow is  it to set aside the frame chain?
Good question.  It used to be just a bit of pointer-twiddling, but at this point it looks like it might be doing something with the stack.  Luke?
You're right Boris.

Incidentally, I was just looking at the JS_SaveFrameChain usage for a different reason and wondering if there could not be a better, less-hacky solution to this errors-getting-eaten problem.  I admit I don't really understand all the constraints at play here for NS_ScriptErrorReporter; I'm just wishfully asking since one day I'd like to remove JS_SaveFrameChain in lieu changes to the JSAPI to make continuing/breaking current call chain explicit at the call site.
I've got a patch which makes the error show up. I've pushed to try at http://tbpl.mozilla.org/?tree=Try&rev=cbb29a306532
So far the patch seems to have busted test_bug390488.html and test_bug549170.html, but I can't reproduce the second one locally. The first breakage is obvious - since we now chop any frames before the event handler, we no longer see the simulateClick caller in the stack. Is this the intended/desired behaviour?
The moved QI call in the patch will certainly show up in the profiles
(but perhaps that is just a leftover since there is anyway some 
commented-out code).
Also, doesn't nsContentUtils::GetCurrentJSContext return just the same
context we pushed in the HandleEventInternal?
Could we do something faster?

http://mozilla.pettay.fi/moztests/events/event_speed_3.html
could work for profiling this case.

About bug 390488, what do other browsers do?
Google Chrome 6-13 shows simulateClick, onClick, anonymous, checkForStacks.
Trying to stir the pot.

It seems we were close to a fix then all activity died on this bug.
Attaching a WIP so that I don't lose all my work if I start ignoring this bug for another five months.
I need to run my perf tests with and without the patch. 
I would be surprised if this doesn't slow down event handling.
Also, is this the right level to do this stuff. What about other
interfaces with [function]? Do they have the same problem?
Attachment #569822 - Attachment is obsolete: true
Results for http://mozilla.pettay.fi/moztests/events/event_speed_3.html:

without patch: avg of 30 results (total tests 50) : 3569ms
with patch: avg of 30 results (total tests 50) : 3643.6666666666665ms
Note, the tests in comment 42 were from rev cc66accc8181 and using depth 100.
Try run for bd51b9bf9001 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=bd51b9bf9001
Results (out of 256 total builds):
    success: 195
    warnings: 61
Builds available at http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/josh@joshmatthews.net-bd51b9bf9001
>3500ms? Were you using a debug  build? I get something like 300ms without the patch on this machine.

And also, do we have the same problem with other [function] interfaces? If so, the
code should go to XPconnect.
There's a related Firebug issue:
http://code.google.com/p/fbug/issues/detail?id=3016

Sebastian
We just had another request:
http://code.google.com/p/fbug/issues/detail?id=5818

All other major browsers throw the error in this case.

Sebastian
bholley, could we handle this somewhere in xpconnect level?
This certainly doesn't belong to ELM, since we have plenty of other callbacks too.
(In reply to Olli Pettay [:smaug] from comment #48)
> bholley, could we handle this somewhere in xpconnect level?
> This certainly doesn't belong to ELM, since we have plenty of other
> callbacks too.

I don't grok the issue here well enough to answer without digging. Maybe jdm has a better sense?
It's always _felt_ like something we should be handling at the xpconnect level whenever I've stepped through the code and watched it reset the exception data, but I really can't give any better insight than that.
Severity: major → normal
Summary: Simulated event handler errors being eaten → Log exceptions thrown from event handler callbacks in the error console
Depends on: 835643
Depends on: 862627
jdm, are you still working on this and/or what needs to happen to move this forward? :-)
Flags: needinfo?(josh)
We're going to get this for free with bug 862627. There's no real point in attacking it until that happens, in my opinion.
Flags: needinfo?(josh)
What needs to happen to move this along is fixing our window teardown insanity so I can land bug 862627, at which point this will Just Work.
Just FYI, I've been working on an addon that shows the stack trace in the console recently. Code at https://github.com/DavidBruant/usefulStackTrace
I've worked the last couple of days to get a stack trace for the test case of this bug. My issue wasn't so much about DOM code than it was about catching an error before DOMContentLoaded...
Anyway. Get the code, follow the instructions in the readme and you should be able to enjoy error messages and stack traces even if the error was thrown from an event handler.

This addon has a lot of room for improvement (submitting to a.m.o would be a start :-/), but at least, no error will be missing if you have it enabled with the webconsole open. The addon works in Firefox 24+ (should work in Firefox 23).
Summary: Log exceptions thrown from event handler callbacks in the error console → Log exceptions thrown from event listener callbacks in the error console
Blocks: 865916
Whiteboard: [Australis:P?][Australis:M?]
Whiteboard: [Australis:P?][Australis:M?]
Blocks: 908954
No longer blocks: 865916
Fixed by bug 862627.
Target Milestone: --- → mozilla27
Assignee: josh → bzbarsky
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Works for me, thanks!

Sebastian
woo!  Great fix, this is wonderful to see.
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: