Closed Bug 861700 Opened 11 years ago Closed 11 years ago

Intermittent browser_705597.js,browser_707862.js | uncaught exception - [object Event] at undefined:undefined

Categories

(Core :: General, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla25
Tracking Status
firefox24 --- fixed
firefox25 --- fixed

People

(Reporter: philor, Assigned: Gavin)

References

Details

(Keywords: intermittent-failure)

https://tbpl.mozilla.org/php/getParsedLog.php?id=21789796&tree=Mozilla-Inbound
Rev5 MacOSX Mountain Lion 10.8 mozilla-inbound opt test mochitest-browser-chrome on 2013-04-14 02:13:05 PDT for push f5f730869f6a
slave: talos-mtnlion-r5-070

09:20:20     INFO -  TEST-START | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_707862.js
09:20:20  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_707862.js | uncaught exception - [object Event] at undefined:undefined
09:20:20     INFO -  Stack trace:
09:20:20     INFO -      JS frame :: chrome://mochikit/content/tests/SimpleTest/SimpleTest.js :: simpletestOnerror :: line 1109
09:20:20     INFO -      native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
09:20:21     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_707862.js | running test_finish
09:20:21     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/components/sessionstore/test/browser_707862.js | finished in 378ms

https://tbpl.mozilla.org/php/getParsedLog.php?id=21789798&tree=Mozilla-Inbound
Rev5 MacOSX Mountain Lion 10.8 mozilla-inbound opt test mochitest-browser-chrome on 2013-04-14 02:13:16 PDT for push f5f730869f6a
slave: talos-mtnlion-r5-054

https://tbpl.mozilla.org/php/getParsedLog.php?id=21795674&tree=Build-System
Rev5 MacOSX Mountain Lion 10.8 build-system opt test mochitest-browser-chrome on 2013-04-14 09:59:57 PDT for push 7143c88f59dc
slave: talos-mtnlion-r5-011
https://tbpl.mozilla.org/php/getParsedLog.php?id=21872805&tree=Mozilla-Inbound
Summary: Intermittent browser_707862.js | uncaught exception - [object Event] at undefined:undefined → Intermittent browser_705597.js,browser_707862.js | uncaught exception - [object Event] at undefined:undefined
Tim, any chance you can take a look at this? It's a pretty recent regression.
Flags: needinfo?(ttaubert)
I would definitely take a look at it if I had the slightest clue what's happening here. "uncaught exception - [object Event] at undefined:undefined" doesn't give me any hint what part of the code/test might be failing...

Do we have any pointers? I can try and see if it's reproducible on my Mac.
Flags: needinfo?(ttaubert)
All I can offer you is what's in the log and point out that it started a few days ago, sorry :(
I can't persuade tbpl to load right now to tell me how close those first inbound instances were to when the patch for bug 845681 was merged there, but that aurora instance in comment 27 was one push after it landed there.
Blocks: 845681
(In reply to Tim Taubert [:ttaubert] from comment #23)
> Do we have any pointers? I can try and see if it's reproducible on my Mac.

Did you ever get a chance to try reproducing locally? As you can see, we still hit this with pretty high frequency.
Flags: needinfo?(ttaubert)
I made some progress debugging this.
Assignee: nobody → gavin.sharp
Debugging history for anyone curious:
First try:
* Push: https://tbpl.mozilla.org/?tree=Try&rev=3cda13682a35
* Failure log: https://tbpl.mozilla.org/php/getParsedLog.php?id=24033227&tree=Try&full=1#error0
* Result: I screwed up the change to SimpleTest.js, but logging in nsJSEventListener::HandleEvent points out the error event in question was a generic nsEvent whose eventStructType was NS_EVENT, and whose message was NS_LOAD_ERROR
* There are only a couple of places in the tree where we use NS_LOAD_ERROR that aren't nsScriptErrorEvents (which have different eventStructType), so I added logging to those places and pushed to try again.

Second try:
* Push: https://tbpl.mozilla.org/?tree=Try&rev=5e9cfc0e9f95
* Failure log: https://tbpl.mozilla.org/php/getParsedLog.php?id=24039467&tree=Try&full=1#error0
* Result: Printing out the event properties still didn't produce anything useful (can't iterate over Xray wrappers?), but it looks like the event is firing from nsScriptElement::ScriptEvaluated. So I added some debugging output to its caller to get more information about the failing script load (source text and script element document URI).

Third try:
* Push: https://tbpl.mozilla.org/?tree=Try&rev=477faee05254
Flags: needinfo?(ttaubert)
OS: Mac OS X → All
Hardware: x86_64 → All
(In reply to :Gavin Sharp (use gavin@gavinsharp.com for email) from comment #312)
> Third try:
> * Push: https://tbpl.mozilla.org/?tree=Try&rev=477faee05254

Scratch that, re-pushed with more useful debugging printfs:

https://tbpl.mozilla.org/?tree=Try&rev=0a5e0cd2c54a
OK, hit the failure again:

https://tbpl.mozilla.org/php/getParsedLog.php?id=24069370&tree=Try&full=1#error0

Looks like a script from about:home is failing to load because it has no inner window in nsScriptLoader::EvaluateScript, and so it fires an onerror event that bubbles up to the chrome window's onerror handler (added by SimpleTest.js). Presumably that's related to the about:home loading and then being torn down in these sessionstore tests, and it's intermittent because it depends on the progress of the load when the window in question is closed, which can vary.

Not sure why this only started happening recently, though, or what the expected behavior here is.
(In reply to :Gavin Sharp (use gavin@gavinsharp.com for email) from comment #324)
> Looks like a script from about:home is failing to load because it has no
> inner window in nsScriptLoader::EvaluateScript

I.e. we are hitting http://hg.mozilla.org/mozilla-central/annotate/b51316b2af6c/content/base/src/nsScriptLoader.cpp#l810

Should that never happen?
Just wanted to say thank you for looking at this Gavin :-)
(sorry to CC you on this frequent orange...)

bz, mrbkap: when do we expect the condition in comment 325 to be hit? Is the issue here that that error should never be firing in this scenario (see comment 324), or does the test harness need to somehow deal with it by not treating it as a fatal error?
Flags: needinfo?(mrbkap)
Flags: needinfo?(bzbarsky)
> bz, mrbkap: when do we expect the condition in comment 325 to be hit?

I guess it could in theory happen if the page has already been unloaded but for some reason we're still trying to run the script...

Bobby recently changed behavior of window.close() a bit, right?  Could that be relevant here?

In any case, if we have no inner, how are we managing to fire an event?  Or is that related to gabor's changes to GetInnerWindow() where we started returning null when we didn't use to?
Flags: needinfo?(gkrizsanits)
Flags: needinfo?(bzbarsky)
Flags: needinfo?(bugs)
Flags: needinfo?(bobbyholley+bmo)
(In reply to Boris Zbarsky (:bz) from comment #358)
> In any case, if we have no inner, how are we managing to fire an event?  Or
> is that related to gabor's changes to GetInnerWindow() where we started
> returning null when we didn't use to?

GetInnerWindow returns null if the document was either destroyed or the document viewer was closed. In any of those cases, does it make sense to let script to be executed? I hope it's not my patch that caused this intermittent, because if it did, that would mean that previously we executed script from a document using a global of another one before my patch...
Flags: needinfo?(gkrizsanits)
Events do fire even when the window isn't current inner window, they just aren't handled.
Chrome event listener may still handle them.
(That has been the behavior in Gecko at least from year 2006, I think)
Flags: needinfo?(bugs)
(In reply to Olli Pettay [:smaug] from comment #360)
> Events do fire even when the window isn't current inner window, they just
> aren't handled.
> Chrome event listener may still handle them.
> (That has been the behavior in Gecko at least from year 2006, I think)

GetScopeObject can still return the inner window after the doc was removed from the docshell, if the window is still alive. An easy way to test if my patch broke this test is to add an additional GetScriptGlobalObject object here if the GetInnerWindow returns null.
(In reply to Boris Zbarsky (:bz) from comment #358)
> Bobby recently changed behavior of window.close() a bit, right?  Could that
> be relevant here?

IIRC, the main observerable change was a slight difference in the duration of time during which we ignore window.close() (particularly observable in cases where we spin the event loop).
Flags: needinfo?(bobbyholley+bmo)
I can't reproduce the orange again on a push that made this change:
https://hg.mozilla.org/try/rev/23e3572d59b1#l3.56

   nsPIDOMWindow *pwin = mDocument->GetInnerWindow();
+  nsCOMPtr<nsIScriptGlobalObject> globalObject;
   if (!pwin) {
+    globalObject = mDocument->GetScriptGlobalObject();
+    //return NS_ERROR_FAILURE;
+  } else {
+    globalObject = do_QueryInterface(pwin);
+  }
+  if (!globalObject)
     return NS_ERROR_FAILURE;
-  }
-  nsCOMPtr<nsIScriptGlobalObject> globalObject = do_QueryInterface(pwin);

So it sounds like the theory from comment 359 is the winner.

Now... how should we fix it?
Component: Session Restore → General
Flags: needinfo?(mrbkap)
Product: Firefox → Core
Gabor or bz, any ideas re: comment 391?

It sounds like we should avoid calling EvaluateScript entirely in this case. Should we just hoist the mDocument->GetInnerWindow null check out of nsScriptLoader::EvaluateScript and into nsScriptLoader::ProcessRequest, and have it not fire any events or try to evaluate the script when it is null?
Flags: needinfo?(gkrizsanits)
That would make sense to me, yes.
Flags: needinfo?(gkrizsanits)
Depends on: 883592
Disabled temporarily to reduce the noise whilst waiting for review in bug 883592, since I suspect it may be a while.

https://hg.mozilla.org/integration/mozilla-inbound/rev/d5bf8119f147
Whiteboard: [test disabled][leave open]
Whether or not bug 883592 fixed it, bug 888031 fixed it by removing the use of about:home in both tests.
Depends on: 888031
And they were already reenabled by bug 883592.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Whiteboard: [test disabled][leave open]
Target Milestone: --- → mozilla25
You need to log in before you can comment on or make changes to this bug.