Open Bug 1207914 Opened 7 years ago Updated 3 days ago

Intermittent test_bug632379.xhtml,test_bug632379.xul | Test timed out


(Core :: Layout, defect, P3)




Tracking Status
firefox44 --- wontfix
firefox47 --- wontfix
firefox48 --- wontfix
firefox49 --- affected
firefox50 --- disabled
firefox51 --- disabled


(Reporter: philor, Unassigned)



(Keywords: intermittent-failure, leave-open, Whiteboard: [test disabled on linux])


(1 file)

No description provided.
Summary: Intermittent test_bug632379.xul | Test timed ou → Intermittent test_bug632379.xul | Test timed out
Daniel, this is drifting to the top of the orange list as other things get fixed.  Can anyone from layout take a look?  Thanks!
Flags: needinfo?(dholbert)
Punting to tobytailor.  Looking at a recent log, it seems we never print anything for this test:
 14:26:24     INFO -  2784 INFO TEST-START | layout/generic/test/test_bug632379.xul
 14:31:52     INFO -  TEST-INFO | started process screentopng
 14:31:53     INFO -  TEST-INFO | screentopng: exit 0
 14:31:53     INFO -  2785 INFO must wait for load
 14:31:53     INFO -  2786 INFO TEST-UNEXPECTED-FAIL | layout/generic/test/test_bug632379.xul | Test timed out.

For the record, here's a screenshot from when we fail (which is linked alongside "artifact uploaded" in the log above).  Doesn't look like anything's out of the ordinary:

The test itself is here:
...and it looks like all of its work is chained off of a call to "SimpleTest.waitForFocus(doTest);" (added in bug 675201).

So my strawman idea is that we're never receiving focus, and hence never proceeding with the test.

tobytailor, could you add some logging to this test to confirm/deny that hypothesis (and see just how far we get)?  I think you can add logging like e.g. info("about to wait for focus"), info("made it to doTest)", etc.
Depends on: 632379
Flags: needinfo?(dholbert) → needinfo?(tschneider)
[I've added a dependency on the bug which added this test, as well as 2 other bugs about intermittent timeouts in this test over the years -- one of which (bug 675201) was supposedly fixed via this waitForFocus invocation.]
Depends on: 675201, 816065
(In reply to Daniel Holbert [:dholbert] from comment #42)
> So my strawman idea is that we're never receiving focus, and hence never
> proceeding with the test.

(Note: in the post-failure screenshot, it does *look* like the Firefox window has focus. But it seems possible that waitForFocus is failing somehow despite the fact that we have focus.)
Actually, we probably want to add logging to all of the chained async functions here, since any one of them could be the point of failure.

Looks like the expected test flow is approximately:
 * waitForFocus()
  --> async call to doTest(), which opens a menu.
  --> async calls to openSubmenu() (via "onpopupshown" attribute), which opens a submenu via a keypress.
  --> async calls to snapshot(), which either opens a different submenu or invokes the actual test function ("is()"), and eventually calls SimpleTest.finish() which ends the test (and avoids the timeout failure)

Something like that.

So, we need to add info() logging to each of these steps, to see how far we get & where things fall apart.
Assignee: nobody → tschneider
Flags: needinfo?(tschneider)
Attached patch Debugging patch.Splinter Review
Adds logging to each step in this test.
I'll land this for you. (Not sure sheriffs are comfortable landing unreviewed "checkin-needed" patches, even in cases where serious review isn't really merited.)
Keywords: checkin-needed
Comment on attachment 8714538 [details] [diff] [review]
Debugging patch.

BTW, the commit message here wasn't really in the right format. Here's the full commit message:

>Subject: [PATCH] Bug 1207914 - Intermittent test_bug632379.xul | Test timed
> out. try: -b d -p linux -u mochitest-o -t none
> layout/generic/test/test_bug632379.xul | 10 ++++++++++
> 1 file changed, 10 insertions(+)

* It shouldn't have the [PATCH] at the beginning.
* It should have a description of the change (and in this case, a hint that it's not actually a fix) rather than the bug title.
* It probably shouldn't have the "1 file changed, 10 insertions(+)" etc. cruft included in the commit message, if possible. (I assume some hg<-->git tool must be adding that?)  That's probably less of an issue, though.
(I tweaked the commit message to address comment 53 before landing)
I tried running this under rr chaos mode too, and even tho I was as well able to reproduce it on the first try, my results are a bit different. For me, the first "openSubmenu()" call actually does show up, the following "synthesizeKey" doesn't seem to have any effect.
Sorry, I meant to follow up here -- I believe the issue that I captured in rr in comment 60 was different as well, and was just from the window not having focus inside my xvfb session. :-/  This issue seems to start happening after I've done a few xvfb-run commands -- presumably some window inside of the xvfb session starts stealing focus, or something else about xvfb gets crufty.

I repeated comment 60's "xvfb-run rr record -h" experiment after a fresh boot (with a presumably-clean xvfb session), using an increased --run-until-failure repetition-count (500 repetitions I think), and I didn't run into any problems, unfortunately.

--> marking comment 60 as obsolete
Whiteboard: [test disabled on linux]
Pushed by
Skip test_bug632379.xul on Linux for constant timeouts
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Summary: Intermittent test_bug632379.xul | Test timed out → Intermittent test_bug632379.xhtml,test_bug632379.xul | Test timed out

The bug assignee is inactive on Bugzilla, so the assignee is being reset.

Assignee: tschneider → nobody
You need to log in before you can comment on or make changes to this bug.