https://tbpl.mozilla.org/php/getParsedLog.php?id=47336579&tree=Fx-Team WINNT 6.2 fx-team opt test mochitest-browser-chrome-1 on 2014-09-03 11:32:38 PDT for push e4d0c551410e slave: t-w864-ix-097 11:35:29 INFO - 154 INFO TEST-START | chrome://mochitests/content/browser/browser/base/content/test/general/browser_bug575561.js 11:35:37 INFO - 1409769337404 GMPInstallManager.simpleCheckAndInstall INFO Last check was: 1409769337 seconds ago, minimum seconds: 86400 11:35:37 INFO - 1409769337404 GMPInstallManager._getURL INFO Using override url: http://127.0.0.1:8888/dummy-gmp-manager.xml 11:35:37 INFO - 1409769337405 GMPInstallManager._getURL INFO Using url (with replacement): http://127.0.0.1:8888/dummy-gmp-manager.xml 11:35:37 INFO - 1409769337406 GMPInstallManager.checkForAddons INFO sending request to: http://127.0.0.1:8888/dummy-gmp-manager.xml 11:35:37 INFO - 1409769337412 GMPInstallManager.onLoadXML INFO request completed downloading document 11:35:37 INFO - 1409769337412 GMPInstallManager.onLoadXML INFO allowNonBuiltIn: false 11:35:37 INFO - 1409769337412 GMPInstallManager.parseResponseXML WARN got node name: html, expected: updates 11:35:37 INFO - 1409769337413 GMPInstallManager.simpleCheckAndInstall ERROR Could not check for addons 11:36:14 INFO - TEST-INFO | screenshot: exit status 0 11:36:14 INFO - dumping last 6 message(s) 11:36:14 INFO - if you need more context, please use SimpleTest.requestCompleteLog() in your test 11:36:14 INFO - 155 INFO checking window state 11:36:14 INFO - 156 INFO Waiting for browser load 11:36:14 INFO - 157 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: "http://example.com/browser/browser/base/content/test/general/app_bug575561.html" line: 0}] 11:36:14 INFO - 158 INFO TEST-FAIL | chrome://mochitests/content/browser/browser/base/content/test/general/browser_bug575561.js | A promise chain failed to handle a rejection 11:36:14 INFO - 159 INFO Console message: 1409769339009 Services.HealthReport.HealthReporter WARN Recording new remote ID: 9a5860f0-8c5c-464f-841a-7979ed5403a9 11:36:14 INFO - 160 INFO Console message: 1409769339025 Services.DataReporting.Policy WARN Hard error submitting data: Server failure. 11:36:14 INFO - 161 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/general/browser_bug575561.js | Test timed out 11:36:14 INFO - 162 INFO TEST-OK | chrome://mochitests/content/browser/browser/base/content/test/general/browser_bug575561.js | took 45029ms 11:36:14 INFO - 163 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/general/browser_bug575561.js | Found a tab after previous test timed out: about:blank

Bug 961867 just touched this test today. Coincidence?

Mossop: I saw your IRC comment yesterday. Does the line below from the log help? 04:41:36 INFO - if you need more context, please use SimpleTest.requestCompleteLog() in your test

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #4) > Mossop: I saw your IRC comment yesterday. Does the line below from the log > help? > 04:41:36 INFO - if you need more context, please use > SimpleTest.requestCompleteLog() in your test Sure, but 6 lines as the default seems way too few. Why is it so low?

Good question, ask the people who maintain the harness?

I backed out bug 961867

Thank you

Backed out the back out.

Since this is a rare orange I'm going to leave the code in the tree for now and work on fixing the test rather than fixing the backout.

This test is all windows line endings so since fixing that meant a total blame change anyway I also switched it to using tasks and promises. Looks a lot cleaner now. I added some logging to try to see what is going on more when this does fail but so far it's passed 10 runs on tbpl with no failure so maybe the async promise stuff has fixed it?

Comment on attachment 8485841 [details] [diff] [review] patch Review of attachment 8485841 [details] [diff] [review]: ----------------------------------------------------------------- r=me with using .click() and adding the .isTopLevel check in some way. ::: browser/base/content/test/general/browser_bug575561.js @@ +41,5 @@ > + yield waitForDocLoadComplete(); > + > + is(browser.contentDocument.location.href, linkLocation, "Link should not open in a new tab"); > + > + return promiseExecuteSoon(); I think you don't need to return a promise here. The promise of the overall task will be resolved at the end and the test will continue on the next tick. @@ +49,5 @@ > + let event = yield promiseWaitForEvent(gBrowser.tabContainer, "TabOpen", true); > + ok(true, "Link should open a new tab"); > + > + yield waitForDocLoadComplete(event.target.linkedBrowser); > + yield promiseExecuteSoon(); Promises always resolve on the next tick, so you can do |yield Promise.resolve()| here. @@ +55,5 @@ > + gBrowser.removeCurrentTab(); > +}); > + > +let testLink = Task.async(function*(aLinkIndex, pinTab, expectNewTab, testSubFrame) { > + let appTab = gBrowser.addTab("http://example.com/browser/browser/base/content/test/general/app_bug575561.html", {skipAnimation: true}); Could move that url to a const at the top. @@ +60,5 @@ > + if (pinTab) > + gBrowser.pinTab(appTab); > + gBrowser.selectedTab = appTab; > + > + yield waitForDocLoadComplete(); Shouldn't we pass gBrowser.selectedBrowser here? Also, waitForDocLoadComplete() doesn't seem to check for webProgress.isTopLevel so could resolve when the test page's iframe loads and is a potential source for intermittent failures. @@ +62,5 @@ > + gBrowser.selectedTab = appTab; > + > + yield waitForDocLoadComplete(); > + > + let browser = gBrowser.getBrowserForTab(appTab); let browser = appTab.linkedBrowser; or gBrowser.selectedBrowser. @@ +64,5 @@ > + yield waitForDocLoadComplete(); > + > + let browser = gBrowser.getBrowserForTab(appTab); > + if (testSubFrame) > + browser = browser.contentDocument.getElementsByTagName("iframe")[0]; browser = browser.contentDocument.querySelector("iframe"); @@ +76,5 @@ > + else > + promise = waitForPageLoad(browser, linkLocation); > + > + info("Clicking " + links[aLinkIndex].textContent); > + EventUtils.sendMouseEvent({type:"click"}, links[aLinkIndex], browser.contentWindow); Would links[aLinkIndex].click() also work here? That is usually less error-prone and doesn't require focus. ::: browser/base/content/test/general/head.js @@ +109,5 @@ > } > > +function promiseExecuteSoon() { > + return new Promise((resolve) => executeSoon(resolve)); > +} We don't need this as said in earlier comments.

(In reply to Tim Taubert [:ttaubert] from comment #18) > @@ +60,5 @@ > > + if (pinTab) > > + gBrowser.pinTab(appTab); > > + gBrowser.selectedTab = appTab; > > + > > + yield waitForDocLoadComplete(); > > Shouldn't we pass gBrowser.selectedBrowser here? waitForDocLoadComplete defaults to gBrowser so there is no need. > Also, waitForDocLoadComplete() doesn't seem to check for > webProgress.isTopLevel so could resolve when the test page's iframe loads > and is a potential source for intermittent failures. waitForDocLoadComplete waits for the NETWORK stop state. This happens when all network activity in all frames in the browser complete. So it should only fire when every frame completes loading regardless of whether the toplevel ended first or last. If I added an isTopLevel check I'd have to rework the part of the test that waits for only the inner frame to load.

(In reply to Dave Townsend [:mossop] from comment #20) > (In reply to Tim Taubert [:ttaubert] from comment #18) > > Shouldn't we pass gBrowser.selectedBrowser here? > > waitForDocLoadComplete defaults to gBrowser so there is no need. Hmm, if there's another document loading in the same tabbrowser, couldn't that interfere here? > waitForDocLoadComplete waits for the NETWORK stop state. This happens when > all network activity in all frames in the browser complete. So it should > only fire when every frame completes loading regardless of whether the > toplevel ended first or last. If I added an isTopLevel check I'd have to > rework the part of the test that waits for only the inner frame to load. Ah, sorry. I confused that with STATE_WINDOW. Carry on.

(In reply to Tim Taubert [:ttaubert] from comment #21) > (In reply to Dave Townsend [:mossop] from comment #20) > > (In reply to Tim Taubert [:ttaubert] from comment #18) > > > Shouldn't we pass gBrowser.selectedBrowser here? > > > > waitForDocLoadComplete defaults to gBrowser so there is no need. > > Hmm, if there's another document loading in the same tabbrowser, couldn't > that interfere here? When listening to the progress listener on gBrowser you effectively are listening to the progress of gBrowser.selectedBrowser.

Updated from review comments.

Latest try run: https://tbpl.mozilla.org/?tree=Try&rev=b8070d87c481

Comment on attachment 8486812 [details] [diff] [review] Updated patch Please use checkin-needed in the future. Plays more nicely with our bug marking tools :)

We've seen a few of these failures most days but none since this was checked in so maybe the timing changes have resolved this? Either way there isn't a lot I can do until I get a full log if it fails again so let's hope this is fixed for now.