Intermittent browser/base/content/test/general/browser_plainTextLinks.js | Test timed out -

RESOLVED FIXED in Firefox 55

Status

()

Firefox
General
RESOLVED FIXED
8 months ago
5 months ago

People

(Reporter: Treeherder Bug Filer, Assigned: jandem)

Tracking

(Depends on: 1 bug, {intermittent-failure})

unspecified
Firefox 55
intermittent-failure
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr45 unaffected, firefox-esr52 unaffected, firefox53 unaffected, firefox54 unaffected, firefox55+ fixed)

Details

(Whiteboard: [stockwell fixed:timing])

Attachments

(1 attachment)

(Reporter)

Description

8 months ago
treeherder
Filed by: philringnalda [at] gmail.com

https://treeherder.mozilla.org/logviewer.html#?job_id=88058189&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/CZ11cq95Q7aNljJiX9zDMA/runs/0/artifacts/public/logs/live_backing.log

Comment 1

8 months ago
7 failures in 867 pushes (0.008 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 4
* autoland: 2
* oak: 1

Platform breakdown:
* linux64: 4
* linux32: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-04-03&endday=2017-04-09&tree=all

Comment 2

7 months ago
12 failures in 894 pushes (0.013 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 7
* mozilla-inbound: 4
* mozilla-central: 1

Platform breakdown:
* linux32: 8
* linux64: 4

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-04-10&endday=2017-04-16&tree=all

Comment 3

7 months ago
7 failures in 817 pushes (0.009 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 4
* oak: 1
* mozilla-inbound: 1
* mozilla-central: 1

Platform breakdown:
* linux32: 4
* linux64: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-04-17&endday=2017-04-23&tree=all

Comment 4

7 months ago
13 failures in 883 pushes (0.015 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 6
* mozilla-central: 3
* graphics: 2
* autoland: 2

Platform breakdown:
* linux64: 7
* linux32: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-04-24&endday=2017-04-30&tree=all

Comment 5

6 months ago
15 failures in 820 pushes (0.018 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 12
* autoland: 2
* try: 1

Platform breakdown:
* linux64: 13
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-05-29&endday=2017-06-04&tree=all

Comment 6

6 months ago
This failure spiked in frequency with changes from bug 1358135:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=linux%20opt-mochitest-browser-chrome-7&tochange=c7f34448197790499d4709a6e5a36aa7aa876b1b&fromchange=90df8b3f52d60d79b2730153f97300039019b694
Blocks: 1358135
Flags: needinfo?(jdemooij)

Updated

6 months ago
Whiteboard: [stockwell needswork]

Comment 7

6 months ago
76 failures in 148 pushes (0.514 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* mozilla-inbound: 32
* autoland: 28
* mozilla-central: 13
* try: 2
* cedar: 1

Platform breakdown:
* linux64: 60
* linux32: 14
* linux64-nightly: 1
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-05&endday=2017-06-05&tree=all
(Assignee)

Comment 8

6 months ago
(In reply to Geoff Brown [:gbrown] from comment #6)
> This failure spiked in frequency with changes from bug 1358135:

It's likely unrelated to that bug.

Gijs, since you're familiar with browser tests, does anything look suspicious to you here:

http://searchfox.org/mozilla-central/rev/d441cb24482c2e5448accaf07379445059937080/browser/base/content/test/general/browser_plainTextLinks.js#121-142

The logs suggest we fail after a different number of tests each time so maybe a timing issue with these events?
Flags: needinfo?(gijskruitbosch+bugs)

Comment 9

6 months ago
The screenshots don't have a popup menu, so my first suggestion would be to add info() logging to browser/base/content/test/general/browser_plainTextLinks.js in order to distinguish whether sending the context menu event to the content process is not working, the popup is just not showing, or if we're getting stuck waiting for the context menu to disappear again because it's already disappeared, or something. As it is it's not clear to me off-hand which of these it is. I have even fewer ideas about what might be causing this timeout. :-\
Flags: needinfo?(gijskruitbosch+bugs)

Comment 10

6 months ago
68 failures in 132 pushes (0.515 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* mozilla-inbound: 22
* autoland: 20
* mozilla-central: 17
* try: 9

Platform breakdown:
* linux64: 51
* linux32: 15
* linux64-nightly: 1
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-06&endday=2017-06-06&tree=all
(Assignee)

Comment 11

6 months ago
Thanks Gijs, I'll do a Try push with some info() logging now.
(Assignee)

Comment 12

6 months ago
I did some retriggers and the |await popupShownPromise;| never "returns":

http://searchfox.org/mozilla-central/rev/20963d7269b1b14d455f47bc0260d0653015bf84/browser/base/content/test/general/browser_plainTextLinks.js#135

It seems to be pretty random: sometimes it's the first loop iteration, sometimes the 5th, but it's always this "await".

So, we're synthesizing a mouse event but the context menu never opens?

Comment 13

6 months ago
(In reply to Jan de Mooij [:jandem] from comment #12)
> I did some retriggers and the |await popupShownPromise;| never "returns":
> 
> http://searchfox.org/mozilla-central/rev/
> 20963d7269b1b14d455f47bc0260d0653015bf84/browser/base/content/test/general/
> browser_plainTextLinks.js#135
> 
> It seems to be pretty random: sometimes it's the first loop iteration,
> sometimes the 5th, but it's always this "await".
> 
> So, we're synthesizing a mouse event but the context menu never opens?

That's what that would mean, yeah. I don't really know why that would happen, or what changes in the JS engine would have to do with it... :S
(Assignee)

Comment 14

6 months ago
This one has a weird screenshot btw:

https://treeherder.mozilla.org/logviewer.html#?job_id=105189307&repo=try&lineNumber=3378

https://public-artifacts.taskcluster.net/Qx2DVtFjSHCbTwlO97yYgQ/0/public/test_info//mozilla-test-fail-screenshot_ayDru2.png

It shows about:printpreview. Is it possible some other test is interfering?

Comment 15

6 months ago
(In reply to Jan de Mooij [:jandem] from comment #14)
> This one has a weird screenshot btw:
> 
> https://treeherder.mozilla.org/logviewer.
> html#?job_id=105189307&repo=try&lineNumber=3378
> 
> https://public-artifacts.taskcluster.net/Qx2DVtFjSHCbTwlO97yYgQ/0/public/
> test_info//mozilla-test-fail-screenshot_ayDru2.png
> 
> It shows about:printpreview. Is it possible some other test is interfering?

It looks like the next test is a print preview test, so I suppose the screenshot is simply late? I don't see the previous test using print preview at all.

Of course, the screenshot being late is a separate bug. :jmaher, do you know who could look into that?
Flags: needinfo?(jmaher)
(Assignee)

Comment 16

6 months ago
So we don't need to call waitForExplicitFinish() here?

Comment 17

6 months ago
(In reply to Jan de Mooij [:jandem] from comment #16)
> So we don't need to call waitForExplicitFinish() here?

It's a task/async function, so no. The test framework is supposed to wait for the test to finish, but because the promise for the popup to show never resolves, it never does, and eventually hits the hard limit and times out the test.

Comment 18

6 months ago
Ah, one suggestion: It's possible the popup is shown *before* we start listening for popupshown, because we're first waiting for the synthesizeMouse to come back from the content process. To try this, omit the 'await' in front of the synthesizeMouse call. Then we'll sync set up the popupshown listener, which might help.
(In reply to Jan de Mooij [:jandem] from comment #12)
> So, we're synthesizing a mouse event but the context menu never opens?

That reminds me of the discussion in bug 1357082.
(Assignee)

Comment 20

6 months ago
(In reply to :Gijs from comment #18)
> Ah, one suggestion: It's possible the popup is shown *before* we start
> listening for popupshown, because we're first waiting for the
> synthesizeMouse to come back from the content process. To try this, omit the
> 'await' in front of the synthesizeMouse call. Then we'll sync set up the
> popupshown listener, which might help.

It still fails unfortunately :( Also note that this is without e10s.

(In reply to Geoff Brown [:gbrown] from comment #19)
> (In reply to Jan de Mooij [:jandem] from comment #12)
> > So, we're synthesizing a mouse event but the context menu never opens?
> 
> That reminds me of the discussion in bug 1357082.

Hm, that bug was also filed 2 months ago.

Comment 21

6 months ago
120 failures in 182 pushes (0.659 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 54
* mozilla-inbound: 44
* try: 13
* mozilla-central: 9

Platform breakdown:
* linux64: 92
* linux32: 26
* linux64-nightly: 1
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-07&endday=2017-06-07&tree=all
Just to add to the pain and pressure: I don't know how frequent this is on the trunk (beyond the gut feeling of "insanely frequent") but I do know from retriggering that on DevEdition after we merge trunk to beta on Monday, it's going to fail 80% of the time, a frequency indistinguishable from permaorange, so it'll be a tree-closer there. And to be sure, I backed out bug 1358135 and did a trunk-as-devedition try push, and got zero instances of this.

[Tracking Requested - why for this release]: merge bustage, closed tree, delayed b1
status-firefox53: --- → unaffected
status-firefox54: --- → unaffected
status-firefox55: --- → affected
status-firefox-esr45: --- → unaffected
status-firefox-esr52: --- → unaffected
tracking-firefox55: --- → ?
(Assignee)

Comment 23

6 months ago
I'll try a few more things today and else I can back out bug 1358135 today or tomorrow. It's not going to fix this completely though, it will just make this less frequent again.

Comment 24

6 months ago
I think we can either try the approach from bug 1357082, or compare with what https://dxr.mozilla.org/mozilla-central/source/browser/base/content/test/general/contextmenu_common.js#260 does (maybe we need to add assertions the popup has really closed, and/or change focus in the document, or something?), or we could look at synthesizing the mouse differently in non-e10s, or we could look at centering the mouse position instead of the hardcoded +3 offset. All of these are a little grasping-at-straws-ish because I still have no idea why this is failing. On its face, the code doesn't even look all that different from the code in contextMenu_common.js, which is still working fine, so I'm a bit lost.

It might also help to add more diagnostic info() logging to the BTU.synthesizeMouse...() code to see what's going on there.

Finally, we could disable the test on Linux non-debug, but that feels like a cop-out. If we don't get this sorted prior to uplift, then we could still do that for beta though.

Comment 25

6 months ago
That said, it's also worrying me slightly that the backout 'worked' in resolving this issue. Jan, does the patch in bug 1358135 not affect debug builds?
(Assignee)

Comment 26

6 months ago
Thanks Gijs! I'll add logging to synthesizeMouse to see if that reveals anything.

(In reply to :Gijs from comment #25)
> That said, it's also worrying me slightly that the backout 'worked' in
> resolving this issue. Jan, does the patch in bug 1358135 not affect debug
> builds?

The patch affects debug and opt builds. But given that we had this intermittent before (it just became more frequent now), I think it's just a timing difference or something.

Stay tuned.
(Assignee)

Comment 27

6 months ago
I can no longer repro this on Try if I add this before the await:

  await new Promise(resolve => setTimeout(resolve, 10));

I'll try to narrow it down a bit more.
Tracking 55+ per Comment 22.
tracking-firefox55: ? → +
:gijs, thanks for asking about the print preview screenshot for the non print preview test failure.  I have filed bug 1371347 to look into it.
Flags: needinfo?(jmaher)

Comment 30

6 months ago
108 failures in 172 pushes (0.628 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 49
* mozilla-inbound: 39
* mozilla-central: 12
* try: 7
* cedar: 1

Platform breakdown:
* linux64: 74
* linux32: 29
* linux64-devedition: 3
* linux64-nightly: 1
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-08&endday=2017-06-08&tree=all
(Assignee)

Comment 31

6 months ago
Current status: retrying the synthesizeMouse call makes this less frequent, but the hidePopup thing has the same issue. I tried to fix that too but I still get oranges on Try.

I give up. I spent way too much time on this already - I'll back out bug 1358135 part 2 later today after I test a few things on Try.
Not sure if this helps...but it seems like there is something wrong in the popup stuff. I've been working on bug 1335894 (a bug in the migration of mochitest-chrome to ubuntu 16.04) and it looks like the problem is coming from somewhere in this file: https://dxr.mozilla.org/mozilla-central/source/layout/xul/nsMenuPopupFrame.cpp

For that bug, the position is somewhat off and I think it's because one of the 'POPUPALIGNMENT*' variables is giving incorrect values. (specifically 'POPUPALIGNMENT_BOTTOMLEFT' for the bug I've been working on).

I thought I'd mention this here since you're having a problem with the hidePopup, and I'm having problems in openPopup, (using 'start_after' or 'after_start').
(Assignee)

Comment 33

6 months ago
(In reply to :Gijs from comment #24)
> Finally, we could disable the test on Linux non-debug, but that feels like a
> cop-out. If we don't get this sorted prior to uplift, then we could still do
> that for beta though.

What do you think about disabling this on Linux non-e10s opt for now? It's not great but backing out bug 1358135 for this is also unfortunate, and if the plan is to stop running non-e10s tests in the not-so-distant future...

I've spent a lot of time Try-debugging this and there's something weird with the popup/events, but I'm still not sure what. It's pretty random and seems to depend on timing - triggering a GC at the start of the test makes it fail much less frequently.
Flags: needinfo?(gijskruitbosch+bugs)

Comment 34

6 months ago
(In reply to Jan de Mooij [:jandem] from comment #33)
> (In reply to :Gijs from comment #24)
> > Finally, we could disable the test on Linux non-debug, but that feels like a
> > cop-out. If we don't get this sorted prior to uplift, then we could still do
> > that for beta though.
> 
> What do you think about disabling this on Linux non-e10s opt for now? It's
> not great but backing out bug 1358135 for this is also unfortunate, and if
> the plan is to stop running non-e10s tests in the not-so-distant future...

wfm. Thanks for all the effort you've put into this. Please make sure when doing this that the disabling also applies to pgo (review for that should probably come from RyanVM or similar).
Flags: needinfo?(gijskruitbosch+bugs)

Comment 35

6 months ago
112 failures in 153 pushes (0.732 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 39
* mozilla-inbound: 31
* mozilla-central: 23
* try: 19

Platform breakdown:
* linux64: 81
* linux32: 29
* linux64-nightly: 1
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-09&endday=2017-06-09&tree=all
(Assignee)

Comment 36

6 months ago
I did some more Try-debugging actually and what's happening with my slightly modified testcase is something like this:

(1) We fire the popupshown event for the context menu.

(2) Then the GTK window receives the "focus_out" event and calls nsWindow::OnContainerFocusOutEvent.

(3) There we call CheckForRollup which will hide the menu.

(4) Now the menu is hidden so when the test calls hidePopup() nothing will happen.

I wonder if (1) should happen after (2). I can add some more logging to see what happens when the test *passes*.
(Assignee)

Comment 37

6 months ago
(In reply to Jan de Mooij [:jandem] from comment #36)
> I wonder if (1) should happen after (2). I can add some more logging to see
> what happens when the test *passes*.

Actually my logging already confirms this: when the test fails we get the focus-out event immediately *after* popupshown. When the test passes we get focus-out *before* dispatching popupshown.
(Assignee)

Comment 38

5 months ago
Created attachment 8876416 [details] [diff] [review]
Patch

This works around the context menu issue and is green on Try (with many retriggers).
Assignee: nobody → jdemooij
Status: NEW → ASSIGNED
Flags: needinfo?(jdemooij)
Attachment #8876416 - Flags: review?(gijskruitbosch+bugs)

Comment 39

5 months ago
Comment on attachment 8876416 [details] [diff] [review]
Patch

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

::: browser/base/content/test/general/browser_plainTextLinks.js
@@ +149,5 @@
> +    // On Linux non-e10s it's possible the menu was closed by a focus-out event
> +    // on the window. Work around this by calling hidePopup only if the menu
> +    // hasn't been closed yet. See bug 1352709 comment 36.
> +    if (contentAreaContextMenu.state === "closed") {
> +      continue;

Alternatively, maybe we could move the creation of popupHiddenPromise to immediately after the creation of the popupShownPromise? Then we'd catch the popuphidden event even if it happens before we call .hidePopup(). I'm happy either way.
Attachment #8876416 - Flags: review?(gijskruitbosch+bugs) → review+

Comment 40

5 months ago
44 failures in 53 pushes (0.83 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* try: 15
* mozilla-inbound: 11
* autoland: 11
* mozilla-central: 7

Platform breakdown:
* linux64: 30
* linux32: 12
* linux64-nightly: 1
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-10&endday=2017-06-10&tree=all

Comment 41

5 months ago
Pushed by jandemooij@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1b58c5233eaa
Fix browser_plainTextLinks.js to work around some context menu issues. r=Gijs
(Assignee)

Comment 42

5 months ago
(In reply to :Gijs from comment #39)
> Alternatively, maybe we could move the creation of popupHiddenPromise to
> immediately after the creation of the popupShownPromise? Then we'd catch the
> popuphidden event even if it happens before we call .hidePopup(). I'm happy
> either way.

Not a bad idea. I kept the patch as is though, I'm tired of this test and don't want to break something subtle last minute :)

Comment 43

5 months ago
595 failures in 864 pushes (0.689 failures/push) were associated with this bug in the last 7 days. 

This is the #1 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **  

Repository breakdown:
* autoland: 220
* mozilla-inbound: 197
* mozilla-central: 93
* try: 81
* cedar: 4

Platform breakdown:
* linux64: 438
* linux32: 138
* linux64-nightly: 7
* linux32-nightly: 7
* linux64-devedition: 4
* linux64-qr: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-05&endday=2017-06-11&tree=all
https://hg.mozilla.org/mozilla-central/rev/1b58c5233eaa
Status: ASSIGNED → RESOLVED
Last Resolved: 5 months ago
status-firefox55: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55

Updated

5 months ago
Depends on: 1372466
Whiteboard: [stockwell needswork] → [stockwell fixed:timing]

Comment 45

5 months ago
4 failures in 814 pushes (0.005 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 3
* mozilla-central: 1

Platform breakdown:
* linux64: 3
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-12&endday=2017-06-18&tree=all

Comment 46

5 months ago
1 failures in 892 pushes (0.001 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* try: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1352709&startday=2017-06-19&endday=2017-06-25&tree=all
You need to log in before you can comment on or make changes to this bug.