Closed Bug 848935 Opened 7 years ago Closed 7 years ago

Intermittent browser_aboutHome.js | Test timed out | Found a tab after previous test timed out: about:home | browser_bug676619.js timeout, found tab, and a leak

Categories

(Firefox :: General, defect)

All
macOS
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 23

People

(Reporter: RyanVM, Assigned: mak)

References

Details

(Keywords: intermittent-failure, Whiteboard: [about-home])

Possible regression from Bug #823547?

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

Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound debug test mochitest-browser-chrome on 2013-03-05 16:49:14 PST for push c72da9fe6160
slave: talos-r4-snow-079

16:51:23  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_aboutHome.js | Test timed out
16:51:23  WARNING -  This is a harness error.
16:51:23     INFO -  args: ['/usr/sbin/screencapture', '-C', '-x', '-t', 'png', '/var/folders/Hs/HsDn6a9SG8idoIya6p9mtE+++TI/-Tmp-/mozilla-test-fail_E_GEfr']
16:51:27     INFO -  SCREENSHOT: <see log>
16:51:27     INFO -  INFO TEST-END | chrome://mochitests/content/browser/browser/base/content/test/browser_aboutHome.js | finished in 32014ms
16:51:27  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_aboutHome.js | Found a tab after previous test timed out: about:home
16:51:27  WARNING -  This is a harness error.
Assignee: nobody → mak77
Marco, have you had a chance to look at this? :-)
Flags: needinfo?(mak77)
not yet.
I suspect one of the 2 handlers is firing too late sometimes, but synchronization is really hairy here, as well as it's hard to reproduce both locally and on try (before pushing the changes I ran 40-50 b-c on try and none of them failed).
I will try to add debugging spew asap.
Flags: needinfo?(mak77)
Whiteboard: [about-home] → [about-home][disable-me 2013-04-01]
Whiteboard: [about-home][disable-me 2013-04-01] → [about-home][disable-me 2013-04-01][leave open]
interesting:

08:42:24     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/browser_aboutHome.js | last-update still exists
08:42:24     INFO -  TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_aboutHome.js | Cleanup
08:42:24     INFO -  WARNING: NS_ENSURE_TRUE(mMutable) failed: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/netwerk/base/src/nsSimpleURI.cpp, line 265
08:42:24  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_aboutHome.js | Test timed out

The test finished at "last-update still exists", then we remove the current tab ("clean")... at that point it should exit the loop and finish(), indeed the screenshot confirms everything is ready to continue to the next test, but that doesn't happen.

I wonder if this is an issue related to the usage of Task in the harness, at first glance doesn't look like a bug in the test :(
Paolo, since you implemented Task and some Promises, do you have any idea whether the test is doing something wrong or whether in some case Task may mis-handle something in the mochitest-browser harness?
ehr was intended to be a needinfo
Flags: needinfo?(paolo.mozmail)
(In reply to TinderboxPushlog Robot from comment #151)
> RyanVM
> https://tbpl.mozilla.org/php/getParsedLog.php?id=21209910&tree=Mozilla-Aurora
> Rev5 MacOSX Mountain Lion 10.8 mozilla-aurora opt test
> mochitest-browser-chrome on 2013-03-28 08:57:29
> slave: talos-mtnlion-r5-033
> 
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_aboutHome.js | Have data for today.
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_aboutHome.js | Test timed out
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_aboutHome.js | Found a tab after previous test timed out: about:home
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_contextSearchTabPosition.js | Have data for today.
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_contextSearchTabPosition.js | Test timed out
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_urlbar_search_healthreport.js | FHR has data for today.
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/base/content/test/
> browser_urlbar_search_healthreport.js | Test timed out
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/components/search/test/
> browser_healthreport.js | Have data for today.
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/components/search/test/
> browser_healthreport.js | Have data for today.
> TEST-UNEXPECTED-FAIL |
> chrome://mochitests/content/browser/browser/components/search/test/
> browser_healthreport.js | Test timed out

This was something else, sorry for the mis-star.
(In reply to Marco Bonardo [:mak] (Away Mar 27 - Apr 2) from comment #133)
> Paolo, since you implemented Task and some Promises, do you have any idea
> whether the test is doing something wrong or whether in some case Task may
> mis-handle something in the mochitest-browser harness?

The use of Task.jsm in this test is correct. By following the test flow, it
would seem that an exception is thrown the last time "removeCurrentTab" is
called. We could get more information by catching task errors this way (I've
not tested it yet):

  Task.spawn(function () {
    // ...
  }).then(null, function (ex) ok(false, "Error: " + ex));

I bumped the [disable-me] date by a few days to allow this attempt.
Flags: needinfo?(paolo.mozmail)
Whiteboard: [about-home][disable-me 2013-04-01][leave open] → [about-home][disable-me 2013-04-05][leave open]
added exception catch to debug further
https://hg.mozilla.org/integration/mozilla-inbound/rev/a4ee183c4c25

Fwiw about home changed recently, and the ratio of failures have reduced, so it really looks like a timing issue...
The Task failure is not hit in these 2 cases, instead the call to cw.ensureSnippetsMapThen(function (aSnippetsMap)... never calls back.
The timeout screenshot shows an empty page...
another try inspired by the empty window
https://hg.mozilla.org/integration/mozilla-inbound/rev/f664c87a974a
These last 3 timeouts are enforced by the harness, I will push a requestLongertimeout(2) that should finally solve this.
this should do it
https://hg.mozilla.org/integration/mozilla-inbound/rev/be68c4410046
Whiteboard: [about-home][disable-me 2013-04-05][leave open] → [about-home]
https://hg.mozilla.org/mozilla-central/rev/be68c4410046
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 23
Depends on: 1260330
You need to log in before you can comment on or make changes to this bug.