Closed Bug 947574 Opened 6 years ago Closed 5 years ago

Intermittent browser_426329.js | This test exceeded the timeout threshold. It should be rewritten or split up.

Categories

(Firefox :: Search, defect)

x86_64
Linux
defect
Not set
Points:
3

Tracking

()

RESOLVED FIXED
Firefox 34
Iteration:
34.3
Tracking Status
firefox32 --- fixed
firefox33 --- fixed
firefox34 --- fixed
firefox-esr24 --- unaffected
firefox-esr31 --- fixed
b2g-v1.4 --- wontfix
b2g-v2.0 --- fixed
b2g-v2.1 --- fixed

People

(Reporter: philor, Assigned: jaws)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 2 obsolete files)

https://tbpl.mozilla.org/php/getParsedLog.php?id=31607431&tree=Mozilla-Inbound
Rev3 Fedora 12x64 mozilla-inbound debug test mochitest-browser-chrome on 2013-12-06 20:25:19 PST for push baf7b0f169a1
slave: talos-r3-fed64-064

20:44:23     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | History cleared
20:44:24     INFO -  [Parent 2871] WARNING: NS_ENSURE_TRUE(window) failed: file ../../../dom/base/nsLocation.cpp, line 43
20:44:24     INFO -  ++DOMWINDOW == 49 (0x75f7018) [pid = 2871] [serial = 4518] [outer = 0x61cf938]
20:44:24  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.
20:44:24     INFO -  TEST-INFO | MEMORY STAT vsize after test: 2547089408
20:44:24     INFO -  TEST-INFO | MEMORY STAT residentFast after test: 472879104
20:44:24     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | finished in 34992ms
While working on bug 992911, I see this failing consistently on linux bc1:
https://tbpl.mozilla.org/?tree=Try&rev=0dc92485e09c (linux debug, linux64 opt+debug)

Here is a link to a direct log:
https://tbpl.mozilla.org/php/getParsedLog.php?id=38340589&tree=Try#error3

And a snippet from the log:
13:04:59     INFO -  TEST-START | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js
13:04:59     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | got search-go-button
13:04:59     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | Engine was added.
13:04:59     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | currentEngine set
13:04:59     INFO -  [4791] WARNING: NS_ENSURE_TRUE(aSelection->GetRangeCount()) failed: file /builds/slave/try-lx-d-000000000000000000000/build/editor/libeditor/base/nsEditor.cpp, line 3801
13:04:59     INFO -  [4791] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/slave/try-lx-d-000000000000000000000/build/editor/libeditor/base/nsEditor.cpp, line 3780
13:04:59     INFO -  [4791] WARNING: NS_ENSURE_SUCCESS(res, res) failed with result 0x80004005: file /builds/slave/try-lx-d-000000000000000000000/build/editor/libeditor/text/nsTextEditRules.cpp, line 418
13:05:03     INFO -  ++DOCSHELL 0x9da1270 == 7 [pid = 4791] [id = 7]
13:05:03     INFO -  ++DOMWINDOW == 16 (0x9da1888) [pid = 4791] [serial = 16] [outer = (nil)]
13:05:03     INFO -  [4791] WARNING: NS_ENSURE_TRUE(globalObject && globalObject->GetGlobalJSObject()) failed: file /builds/slave/try-lx-d-000000000000000000000/build/content/html/document/src/nsHTMLContentSink.cpp, line 740
13:05:03     INFO -  ++DOMWINDOW == 17 (0x9e3b0d0) [pid = 4791] [serial = 17] [outer = 0x9da1888]
13:05:03     INFO -  [4791] WARNING: NS_ENSURE_TRUE(window) failed: file /builds/slave/try-lx-d-000000000000000000000/build/dom/base/nsLocation.cpp, line 45
13:05:03     INFO -  ++DOMWINDOW == 18 (0x9881620) [pid = 4791] [serial = 18] [outer = 0x9da1888]
13:05:03     INFO -  ++DOCSHELL 0x92490c8 == 8 [pid = 4791] [id = 8]
13:05:03     INFO -  ++DOMWINDOW == 19 (0x9db6040) [pid = 4791] [serial = 19] [outer = (nil)]
13:05:03     INFO -  ++DOMWINDOW == 20 (0x9aa78d0) [pid = 4791] [serial = 20] [outer = 0x9db6040]
13:05:03     INFO -  ++DOMWINDOW == 21 (0x9d02858) [pid = 4791] [serial = 21] [outer = 0x9db6040]
13:05:06     INFO -  --DOMWINDOW == 20 (0x92b8000) [pid = 4791] [serial = 2] [outer = 0x92fd3b0] [url = about:blank]
13:05:06     INFO -  --DOMWINDOW == 19 (0x9aa78d0) [pid = 4791] [serial = 20] [outer = 0x9db6040] [url = about:blank]
13:05:06     INFO -  --DOMWINDOW == 18 (0xa69f4a8) [pid = 4791] [serial = 9] [outer = 0xa5c52d8] [url = about:blank]
13:05:12     INFO -  --DOMWINDOW == 17 (0x9e3b0d0) [pid = 4791] [serial = 17] [outer = (nil)] [url = about:blank]
13:05:18     INFO -  --DOMWINDOW == 16 (0xa7d2838) [pid = 4791] [serial = 12] [outer = (nil)] [url = about:blank]
13:05:43     INFO -  [4791] WARNING: CacheIndex::SetupDirectoryEnumerator() - Entries directory doesn't exist!: file /builds/slave/try-lx-d-000000000000000000000/build/netwerk/cache2/CacheIndex.cpp, line 2474
13:05:44     INFO -  Not taking screenshot here: see the one that was previously logged
13:05:44  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | Test timed out
13:05:44     INFO -  TEST-INFO | MEMORY STAT vsize after test: 613036032
13:05:44     INFO -  TEST-INFO | MEMORY STAT residentFast after test: 234369024
13:05:44     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/components/search/test/browser_426329.js | finished in 45142ms


The question is, why would this be failing when running the subdirectory standalone?  Are we expecting data to be loaded in the background?

Sadly enough on my local linux64 machine, I couldn't reproduce this by running "mach mochitest-browser browser/components/search/test".

I also see 2 other bugs related to this test: bug 918009 and bug 951614.
Blocks: run-by-dir
Gavin, you have authored a lot of recent changes to this test, can you weigh in here on what you think might be going on?  I am happy to try stuff out.
Flags: needinfo?(gavin.sharp)
My changes were mostly unrelated to the test itself :)

The timeout from comment 0 is strange, it looks like GC is being triggered by new window opens and that makes things take a long time (I assume this only occurs on debug builds). We could split up the test to address it.

Your failure looks entirely different, and probably merits its own bug. I can't seem to easily reproduce it.
Flags: needinfo?(gavin.sharp)
https://hg.mozilla.org/mozilla-central/rev/5c1d0ebc9f91
Assignee: nobody → gavin.sharp
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 32
Assignee: gavin.sharp → nobody
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Target Milestone: Firefox 32 → ---
This test fails intemittently for linux bc1 jobs, as can be seen in a recent try push: https://tbpl.mozilla.org/?tree=Try&rev=43c85fb644ef

The goal is to turn these on as --run-by-dir, we don't have too many tests that are problematic(19 total), if we can fix the easy ones now that will help! :)

Gavin, can you figure out why these might still be failing intermittently while running the tests in only browser/components/search/test directory?
Flags: needinfo?(gavin.sharp)
I'm adding this bug to our priority backlog for the next iteration, so we can expect it to be assigned August 5th.
Flags: needinfo?(gavin.sharp)
Status: REOPENED → NEW
Flags: firefox-backlog+
Points: --- → 3
QA Whiteboard: [qa-]
Assignee: nobody → jaws
Status: NEW → ASSIGNED
Iteration: --- → 34.2
Attached patch Patch (obsolete) — Splinter Review
Try is closed so I can't push it there. But this patch forces the focus to change before the next test starts, which fixes the failures locally for me.
Attachment #8472732 - Flags: review?(gijskruitbosch+bugs)
Comment on attachment 8472732 [details] [diff] [review]
Patch

Review of attachment 8472732 [details] [diff] [review]:
-----------------------------------------------------------------

Clearing review for now because of the commented-out/early-return things + waitForFocus.

::: browser/components/search/test/browser_426329.js
@@ +97,5 @@
> +  searchBar = BrowserSearch.searchBar;
> +
> +  let windowFocused = Promise.defer();
> +  SimpleTest.waitForFocus(windowFocused.resolve, window);
> +  window.focus();

waitForFocus calls window.focus for you if it isn't focused; you shouldn't need to manually call window.focus here.

@@ +114,5 @@
> +  return deferred.promise;
> +}
> +
> +add_task(function() {
> +  yield promiseSetEngine();

This is kind of sad... we should really get task-based setup and cleanup functions in the mochitest framework... :-\

@@ +141,5 @@
> +     "Alt+Return key loaded results in foreground tab");
> +  is(event.originalTarget.URL, expectedURL(searchBar.value), "testAltReturn opened correct search page");
> +});
> +
> +//Shift key has no effect for now, so skip it

I'm confused - this was not skipped in the old test; why are we skipping it now?

@@ +161,5 @@
> +add_task(function testLeftClick() {
> +  yield prepareTest();
> +  simulateClick({ button: 0 }, searchButton);
> +  let event = yield promiseOnLoad();
> +  is(gBrowser.tabs.length, preTabNo, "LeftClick did not open new tab");

I'm confused. How come we're back to preTabNo here, without any tabs being closed since we checked against preTabNo + 1 ?

Ideally, it would also be nice if all these numbers weren't going to be off-by-one as soon as a single test fails (ie right now it'd have a knock-on effect).

@@ +192,5 @@
> +  is(event.originalTarget.URL, expectedURL(searchBar.value), "testShiftMiddleClick opened correct search page");
> +});
> +
> +// prevent the search buttonmenu from opening during the drag tests
> +function promisePreventPopupShowing() {

Hrmpf. Not a big fan of having both this and the 1-line-different promisePopupShowing, but I'm not sure how to have a clear parameter that just does the preventDefault bit. Passing in a function is verbose on the caller's side, and it's weird to pass a callback function to a function returning a promise. The promise callbacks will be called async, so we can't use those. We could use a boolean, but that has clarity issues. String param is icky. Pick one of the above depending on your good judgment? Keeping it like this might be fine.

@@ +238,5 @@
> +    is(gBrowser.tabs.length, preTabNo, "RightClick did not open new tab");
> +    is(gBrowser.currentURI.spec, "about:blank", "RightClick did nothing");
> +  }, 5000);
> +});
> +*/

Err... why is this commented out?

@@ +264,5 @@
> +    ok(count > 0, "form history entry '" + searchEntries[i] + "' should exist");
> +  }
> +});
> +
> +function* promisePopupShown(aPopup) {

Please put this in head.js if it doesn't exist there already.
Attachment #8472732 - Flags: review?(gijskruitbosch+bugs)
(In reply to :Gijs Kruitbosch (intermittently here 14-15 August; then away until 19th) from comment #18)
> @@ +141,5 @@
> > +     "Alt+Return key loaded results in foreground tab");
> > +  is(event.originalTarget.URL, expectedURL(searchBar.value), "testAltReturn opened correct search page");
> > +});
> > +
> > +//Shift key has no effect for now, so skip it
> 
> I'm confused - this was not skipped in the old test; why are we skipping it
> now?

Yes, it was skipped in the old test, see http://hg.mozilla.org/mozilla-central/annotate/5299864050ee/browser/components/search/test/browser_426329.js#l84
(In reply to Jared Wein [:jaws] (please needinfo? me) from comment #19)
> (In reply to :Gijs Kruitbosch (intermittently here 14-15 August; then away
> until 19th) from comment #18)
> > @@ +141,5 @@
> > > +     "Alt+Return key loaded results in foreground tab");
> > > +  is(event.originalTarget.URL, expectedURL(searchBar.value), "testAltReturn opened correct search page");
> > > +});
> > > +
> > > +//Shift key has no effect for now, so skip it
> > 
> > I'm confused - this was not skipped in the old test; why are we skipping it
> > now?
> 
> Yes, it was skipped in the old test, see
> http://hg.mozilla.org/mozilla-central/annotate/5299864050ee/browser/
> components/search/test/browser_426329.js#l84

D'oh. Sorry I missed that - the diff is pretty... terrible (not the best excuse, but hey). :-(
(In reply to :Gijs Kruitbosch (intermittently here 14-15 August; then away until 19th) from comment #18)
> @@ +161,5 @@
> > +add_task(function testLeftClick() {
> > +  yield prepareTest();
> > +  simulateClick({ button: 0 }, searchButton);
> > +  let event = yield promiseOnLoad();
> > +  is(gBrowser.tabs.length, preTabNo, "LeftClick did not open new tab");
> 
> I'm confused. How come we're back to preTabNo here, without any tabs being
> closed since we checked against preTabNo + 1 ?
> 
> Ideally, it would also be nice if all these numbers weren't going to be
> off-by-one as soon as a single test fails (ie right now it'd have a knock-on
> effect).

prepareTest resets preTabNo at the beginning of each of these tests.
Comment on attachment 8473235 [details] [diff] [review]
Patch v2

Review of attachment 8473235 [details] [diff] [review]:
-----------------------------------------------------------------

r=me assuming this is green on try (is open again, AIUI?), and you address the comments below one way or another (for some "no, I'm not going to do that" is perfectly legit; for others, not so much :-) )

::: browser/components/search/test/browser_426329.js
@@ +72,5 @@
> +  let deferred = Promise.defer();
> +  var ss = Services.search;
> +
> +  function observer(aSub, aTopic, aData) {
> +    switch (aData) {

Nit:

if (aData == "engine-removed") {
  ...
}

@@ +124,5 @@
> +
> +  is(gBrowser.tabs.length, preTabNo, "Return key did not open new tab");
> +  is(event.originalTarget, preSelectedBrowser.contentDocument,
> +     "Return key loaded results in current tab");
> +  is(event.originalTarget.URL, expectedURL(searchBar.value), "testReturn opened correct search page");

Part of me thinks this can be refactored into a function like:

function checkLoadEventForSearch(sourceDescription, expectNewTab, expectForeground) {
  is(gBrowser.tabs.length, preTabNo + (expectNewTab ? 1 : 0), ...);
  if (!expectNewTab) {
    is(event.originalTarget, preSelectedBrowser.contentDocument, ...);
  } else {
    isnot(event.originalTarget, preSelectedBrowser.contentDocument, ...);
    if (expectForeground) {
      is(event.originalTarget, gBrowser.contentDocument, ...);
    } else {
      isnot(event.originalTarget, gBrowser.contentDocument, ...);
    }
  }
  is(event.originalTarget.URL, expectedURL(searchBar.value), ...);
}

which you can just call from all the different permutations with a sourceDescription of how you caused the load event (click, return, whatever), and which then does the right checks with the right description describing what we expect for what kind of event.

Or maybe I'm overthinking this. It's late and I'm trying to parse all the individual comparisons which seem very similar, and so I get crazy ideas like this. :-)

@@ +192,5 @@
> +});
> +
> +add_task(function testDropText() {
> +  yield prepareTest();
> +  let promisePreventPopup = promiseEvent(searchBar, "popupshowing", true);

The previous version of this test also checked that we loaded a page, and then forgot to check the URI (as compared with the click/return tests). You seem to have removed the load check. Was that intentional? Wouldn't it make more sense to both check the load and check its URL? Same for the next test.

@@ +213,5 @@
> +  yield prepareTest();
> +  let promisePreventPopup = promiseEvent(searchBar, "popupshowing", true);
> +  ChromeUtils.synthesizeDrop(searchBar.searchButton, searchBar.searchButton, [[ {type: "text/uri-list", data: "http://www.mozilla.org" } ]], "copy", window);
> +  yield promisePreventPopup;
> +  is(searchBar.value, "More Text", "drop text/uri-list on searchbar");

Nit: this implicitly relies on the previous test. Maybe assign to searchBar.value either in prepareTest or in this test?

Further nit: AFAICT the purpose of this (sub)test is to see that this does nothing - perhaps the is() check should clarify that. I was confused for a bit how "More Text" was related to "http://www.mozilla.org/" :-)

@@ +253,5 @@
> +
> +add_task(function testAutocomplete() {
> +  var popup = searchBar.textbox.popup;
> +  searchBar.textbox.showHistoryPopup();
> +  yield promiseEvent(popup, "popupshown");

Nit: you should store the promise in an intermediate before calling showHistoryPopup, and then yield on the intermediate. Right now, this could theoretically race if popupshown gets called before you create the event listener.

@@ +265,5 @@
> +  let count = yield countEntries();
> +  ok(count == 0, "History cleared");
> +});
> +
> +// modified from toolkit/components/satchel/test/test_form_autocomplete.html

You moved the other utility functions up; please move these two, too. :-)

@@ +287,5 @@
> +  return entries;
> +}
> +
> +add_task(function asyncCleanup() {
> +    searchBar.value = "";

nit: indentation
Attachment #8473235 - Flags: review?(gijskruitbosch+bugs) → review+
(In reply to Matthew N. [:MattN] from comment #24)
> https://hg.mozilla.org/integration/fx-team/rev/70b77e14d448

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #26)
> Looks like that patch made OSX perma-fail. Backed out.

FWIW the try push I was given was: https://tbpl.mozilla.org/?tree=Try&rev=aadde0cfa228
Yup, looks like other platforms are passing fine. Just OSX was failing.
Iteration: 34.2 → 34.3
QA Whiteboard: [qa-]
Flags: qe-verify-
https://hg.mozilla.org/mozilla-central/rev/a62e8b6878ee
Status: ASSIGNED → RESOLVED
Closed: 6 years ago5 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Whiteboard: [fixed in fx-team]
Target Milestone: --- → Firefox 34
You need to log in before you can comment on or make changes to this bug.