Retriggers confirm that this is a regression from bug 997101. https://tbpl.mozilla.org/php/getParsedLog.php?id=47631348&tree=Mozilla-Inbound Ubuntu VM 12.04 x64 mozilla-inbound opt test mochitest-e10s-browser-chrome-3 on 2014-09-08 15:20:46 PDT for push 0d30e40d7fc0 slave: tst-linux64-spot-667 15:22:57 INFO - 30 INFO TEST-START | chrome://mochitests/content/browser/toolkit/content/tests/browser/browser_bug982298.js 15:23:12 INFO - 1410214992749 GMPInstallManager.simpleCheckAndInstall INFO Last check was: 1410214993 seconds ago, minimum seconds: 86400 15:23:12 INFO - 1410214992751 GMPInstallManager._getURL INFO Using override url: http://127.0.0.1:8888/dummy-gmp-manager.xml 15:23:12 INFO - 1410214992753 GMPInstallManager._getURL INFO Using url (with replacement): http://127.0.0.1:8888/dummy-gmp-manager.xml 15:23:12 INFO - 1410214992755 GMPInstallManager.checkForAddons INFO sending request to: http://127.0.0.1:8888/dummy-gmp-manager.xml 15:23:12 INFO - 1410214992767 GMPInstallManager.onLoadXML INFO request completed downloading document 15:23:12 INFO - 1410214992768 GMPInstallManager.onLoadXML INFO allowNonBuiltIn: false 15:23:12 INFO - 1410214992769 GMPInstallManager.parseResponseXML WARN got node name: html, expected: updates 15:23:12 INFO - 1410214992770 GMPInstallManager.simpleCheckAndInstall ERROR Could not check for addons 15:23:42 INFO - Xlib: extension "RANDR" missing on display ":0". 15:23:43 INFO - TEST-INFO | screentopng: exit 0 15:23:43 INFO - dumping last 5 message(s) 15:23:43 INFO - if you need more context, please use SimpleTest.requestCompleteLog() in your test 15:23:43 INFO - 31 INFO checking window state 15:23:43 INFO - 32 INFO Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html;base64,PHRleHRhcmVhIGlkPSJ0ZXh0YXJlYTEiIHJvdz0yPkZpcmVmb3gKCkZpcmVmb3gKCgoKCgoKCgoKPC90ZXh0YXJlYT48YSBocmVmPSJhYm91dDpibGFuayI+Ymxhbms8L2E+" line: 0}] 15:23:43 INFO - 33 INFO Console message: [JavaScript Warning: "Key event not available on some keyboard layouts: key="c" modifiers="accel,alt"" {file: "chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js" line: 150}] 15:23:43 INFO - 34 INFO Console message: 1410214992799 Services.HealthReport.HealthReporter WARN Saved state file does not exist. 15:23:43 INFO - 35 INFO Console message: 1410214992800 Services.HealthReport.HealthReporter WARN No prefs data found. 15:23:43 INFO - 36 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/content/tests/browser/browser_bug982298.js | Test timed out - expected PASS 15:23:43 INFO - 37 INFO TEST-OK | chrome://mochitests/content/browser/toolkit/content/tests/browser/browser_bug982298.js | took 45049ms 15:23:43 INFO - 38 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/content/tests/browser/browser_bug982298.js | Found a tab after previous test timed out: data:text/html;base64,PHRleHRhcmVhIGlkPSJ0ZXh0YXJlYTEiIHJvdz0yPkZpcmVmb3gKCkZpcmVmb3gKCgoKCgoKCgoKPC90ZXh0YXJlYT48YSBocmVmPSJhYm91dDpibGFuayI+Ymxhbms8L2E+ - expected PASS

https://tbpl.mozilla.org/php/getParsedLog.php?id=47561215&tree=Mozilla-Inbound https://tbpl.mozilla.org/php/getParsedLog.php?id=47580373&tree=Mozilla-Inbound https://tbpl.mozilla.org/php/getParsedLog.php?id=47627720&tree=Mozilla-Inbound

It seems likely to me that this test has a race condition in its test() method: https://mxr.mozilla.org/mozilla-central/source/toolkit/content/tests/browser/browser_bug982298.js Specifically it seems that between the gBrowser.addTab() call and the browser.addEventListener("load",...) call the tabs content could load. If that happens then the event handler for the "load" event will never run and the test will time out as seen above. Bug 997101 making pages load faster, which would be consistent with making us fail the race sometimes. Makoto Kato, you wrote this this test. Can you comment on whether the above is correct?

And maybe fix the test?

(In reply to Jonathan Watt [:jwatt] from comment #2) > It seems likely to me that this test has a race condition in its test() > method: > > https://mxr.mozilla.org/mozilla-central/source/toolkit/content/tests/browser/ > browser_bug982298.js > > Specifically it seems that between the gBrowser.addTab() call and the > browser.addEventListener("load",...) call the tabs content could load. If > that happens then the event handler for the "load" event will never run and > the test will time out as seen above. > > Bug 997101 making pages load faster, which would be consistent with making > us fail the race sometimes. > > Makoto Kato, you wrote this this test. Can you comment on whether the above > is correct? I think that this is correct.

even if apply fix, problem isn't fixed yet.... I will investigate this again.. humm.....

Disabled on e10s. https://hg.mozilla.org/integration/mozilla-inbound/rev/14ab6eb9f270

Tom, I placed a bunch of logging statements throughout this test and am able to confirm that it is hanging because the listener's onFindResult is not getting called. RemoteFinder.jsm is throwing an exception of: > [JavaScript Error: "l[callback] is undefined" {file: "resource://gre/modules/RemoteFinder.jsm" line: 79}] Could a new RemoteFinder be instantiated between the call to addResultListener and the results being returned? See https://hg.mozilla.org/try/rev/927dae7315be for my changeset with the logging statements, and https://treeherder.mozilla.org/logviewer.html#?job_id=17382512&repo=try#L2658 for the spot in the log where this exception occurs.

Before I try to dig deeper into a timing issue here, could you check if "l" is maybe a different message aka "Finder:MatchesResult" (seems likely) or "Finder:CurrentSelectionResult". (probably not this one). In that case just adding those callback functions to the listener object would help.

Review commit: https://reviewboard.mozilla.org/r/38519/diff/#index_header See other reviews: https://reviewboard.mozilla.org/r/38519/

Comment on attachment 8727588 [details] MozReview Request: Bug 1064580 - Add definitions for onCurrentSelection and onMatchesCountResult to the listeners since RemoteFinder.jsm expects them to be present. Also add an error check in Finder.jsm for empty selections. r?evilpie https://reviewboard.mozilla.org/r/38519/#review35191 Some of those infos seems a bit unecessary however.

They helped me debug this, and may help someone again if this goes intermittent. They aren't included in the log by default unless SimpleTest.requestCompleteLog() is called in the file.

Doesn't really seem to be fixed, though I don't know whether it was merely horribly frequent before, like it is now, or was hideously frequent before and the current state is an improvement.

This is seriously bonkers. We should disable this ASAP if a fix isn't imminent.

(In reply to Ryan VanderMeulen [:RyanVM] from comment #206) > This is seriously bonkers. We should disable this ASAP if a fix isn't > imminent. Yeah we should back out. I thought comment #203 was backing it out but I now see that it didn't happen. It's on my radar but not the first on my list to fix right now.

Rewrote the test and pushed it to try, all green with 18 runs of M-e10s(bc2) which contains this test. https://treeherder.mozilla.org/#/jobs?repo=try&revision=19e19e03bb27 Note that in a previous try run [1], the test timed out and the screenshot showed "abc" in the findbar. "abc" gets put in the findbar from browser_bug1198465.js, which I've modified in this patch to use `yield BrowserTestUtils.removeTab`. [1] https://treeherder.mozilla.org/logviewer.html#?job_id=18174469&repo=try

Comment on attachment 8727588 [details] MozReview Request: Bug 1064580 - Add definitions for onCurrentSelection and onMatchesCountResult to the listeners since RemoteFinder.jsm expects them to be present. Also add an error check in Finder.jsm for empty selections. r?evilpie Review request updated; see interdiff: https://reviewboard.mozilla.org/r/38519/diff/1-2/

Comment on attachment 8727588 [details] MozReview Request: Bug 1064580 - Add definitions for onCurrentSelection and onMatchesCountResult to the listeners since RemoteFinder.jsm expects them to be present. Also add an error check in Finder.jsm for empty selections. r?evilpie Review request updated; see interdiff: https://reviewboard.mozilla.org/r/38519/diff/2-3/

Comment on attachment 8727588 [details] MozReview Request: Bug 1064580 - Add definitions for onCurrentSelection and onMatchesCountResult to the listeners since RemoteFinder.jsm expects them to be present. Also add an error check in Finder.jsm for empty selections. r?evilpie Review request updated; see interdiff: https://reviewboard.mozilla.org/r/38519/diff/3-4/

Comment on attachment 8727588 [details] MozReview Request: Bug 1064580 - Add definitions for onCurrentSelection and onMatchesCountResult to the listeners since RemoteFinder.jsm expects them to be present. Also add an error check in Finder.jsm for empty selections. r?evilpie https://reviewboard.mozilla.org/r/38519/#review37551 ::: toolkit/content/tests/browser/browser_bug982298.js:38 (Diff revision 4) > + "sendAsyncMessage(\"ScrollDone\", { });" > + browser.messageManager.loadFrameScript("data:text/javascript;base64," + > + btoa(scrollTest), false); > + yield awaitScrollDone; > + info("got ScrollDone event"); > + yield BrowserTestUtils.loadURI(browser, "about:blank"); Wow, this is like 10x easier to understand now. ::: toolkit/content/tests/browser/browser_bug982298.js:67 (Diff revision 4) > - } catch (e) { > + } catch (e) { > + info("got exception from onFindAgainCommand: " + e); > - } > + } > - cleanup(); > - }, 0); > + }, 0); > -} > + }); Why put everything inside the promise, instead of having doing `yield awaitFindResult` like above? So like: ``` awaitFindResult = Promise ... setTimeout(...) yield awaitFindResult ```

Thanks for the quick review. Yeah, we can do the setTimeout outside of the Promise. I've made the change as you requested.