Closed Bug 1064580 Opened 10 years ago Closed 8 years ago

Intermittent browser_bug982298.js | Test timed out | Found a tab

Categories

(Core :: Layout, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla48
Tracking Status
firefox48 --- fixed

People

(Reporter: RyanVM, Assigned: jaws)

References

Details

(Keywords: intermittent-failure, Whiteboard: [test disabled on e10s])

Attachments

(1 file, 3 obsolete files)

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
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?
Flags: needinfo?(m_kato)
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.
Assignee: nobody → m_kato
Flags: needinfo?(m_kato)
Attached patch fix (obsolete) — Splinter Review
Attachment #8511482 - Flags: review?(roc)
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
Whiteboard: [test disabled on e10s][leave open]
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.
Flags: needinfo?(evilpies)
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.
Flags: needinfo?(evilpies)
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.
Attachment #8727588 - Flags: review?(evilpies) → review+
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.
Assignee: m_kato → jaws
Status: NEW → ASSIGNED
Keywords: checkin-needed
Whiteboard: [test disabled on e10s][leave open] → [test disabled on e10s]
https://hg.mozilla.org/mozilla-central/rev/0f12e087d294
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla48
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.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Whiteboard: [test disabled on e10s]
Target Milestone: mozilla48 → ---
This is seriously bonkers. We should disable this ASAP if a fix isn't imminent.
Flags: needinfo?(jaws)
(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.
Flags: needinfo?(jaws)
Keywords: leave-open
Whiteboard: [test disabled on e10s]
Attachment #8511482 - Attachment is obsolete: true
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/
Attachment #8727588 - Attachment description: MozReview Request: Bug 1064580 - Add definitions for onCurrentSelection to the listeners since RemoteFinder.jsm expects them to be present. Also add an error check in Finder.jsm for empty selections. r?evilpie → 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
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/
Attachment #8727588 - Flags: review+ → review?(evilpies)
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
```
Attachment #8727588 - Flags: review?(evilpies) → review+
Attached patch Patch for check-in (obsolete) — Splinter Review
Thanks for the quick review. Yeah, we can do the setTimeout outside of the Promise. I've made the change as you requested.
Attachment #8727588 - Attachment is obsolete: true
Attachment #8732176 - Attachment is obsolete: true
https://hg.mozilla.org/integration/fx-team/rev/dbba8191f3c1e22505f5e5d5b8537f719eafb51d
Bug 1064580 - Rewrote browser_bug982298.js and added a definition for onMatchesCountResult to the listeners since RemoteFinder.jsm expects it to be present. Also add an error check in Finder.jsm for empty selections. r=evilpie
https://hg.mozilla.org/mozilla-central/rev/dbba8191f3c1
Status: REOPENED → RESOLVED
Closed: 8 years ago8 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla48
You need to log in before you can comment on or make changes to this bug.