Intermittent toolkit/content/tests/chrome/test_panel_anchoradjust.xul | Test timed out.

RESOLVED FIXED

Status

()

defect
RESOLVED FIXED
2 years ago
a year ago

People

(Reporter: intermittent-bug-filer, Assigned: enndeakin)

Tracking

({intermittent-failure})

unspecified
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox52 unaffected, firefox-esr52 unaffected, firefox53 wontfix, firefox54 affected, firefox55 affected)

Details

(Whiteboard: [stockwell fixed:product])

Attachments

(2 attachments)

Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
this has picked up in frequency in the last week, 33 failures since last friday :(  Primarily on linux64 debug/asan.

Around March 13th you can see the pickup:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1340413&startday=2017-03-10&endday=2017-03-17&tree=all

doing a few retriggers to help see if there was a change that triggered this to be more frequent:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=linux%20debug%20mochitest-chrome-3%20x64&tochange=950180909fd0e5031a04fcd4cb8f94ff4be72ae6&fromchange=a57d843357e2d93d43e2508de1793f63b355fab9&selectedJob=83437036


I will follow up shortly
Flags: needinfo?(jmaher)
Whiteboard: [stockwell needswork]
shortly is a whole day later!

I ended up doing a few round of retriggers, nothing is standing out as a culprit (orange job == a few different regressions, not always this regression).

the first instance is found here:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2b52802899ae6b4d14481481e0ea37664c48a7d5

I am not sure if that is a root cause since this doesn't happen much, but I have many retriggers on a few revisions prior with no instances.

here is data from the log [0]:
[task 2017-03-17T14:07:27.272930Z] 14:07:27     INFO - TEST-START | toolkit/content/tests/chrome/test_panel.xul
[task 2017-03-17T14:07:27.857787Z] 14:07:27     INFO - GECKO(5499) | MEMORY STAT | vsize 20973989MB | residentFast 1473MB
[task 2017-03-17T14:07:27.875838Z] 14:07:27     INFO - TEST-OK | toolkit/content/tests/chrome/test_panel.xul | took 603ms
[task 2017-03-17T14:07:28.943875Z] 14:07:28     INFO - TEST-START | toolkit/content/tests/chrome/test_panel_anchoradjust.xul
[task 2017-03-17T14:12:34.788378Z] 14:12:34     INFO - TEST-INFO | started process screentopng
[task 2017-03-17T14:12:35.135024Z] 14:12:35     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-17T14:12:35.135103Z] 14:12:35     INFO - Buffered messages logged at 14:07:29
[task 2017-03-17T14:12:35.135142Z] 14:12:35     INFO - must wait for load
[task 2017-03-17T14:12:35.135177Z] 14:12:35     INFO - must wait for focus
[task 2017-03-17T14:12:35.135231Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | anchor moved x 
[task 2017-03-17T14:12:35.135294Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | anchor moved y 
[task 2017-03-17T14:12:35.135352Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | new anchor x 
[task 2017-03-17T14:12:35.135412Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | new anchor y 
[task 2017-03-17T14:12:35.135476Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | new anchor with offset x 
[task 2017-03-17T14:12:35.135537Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | new anchor with offset y 
[task 2017-03-17T14:12:35.135578Z] 14:12:35     INFO - Buffered messages finished
[task 2017-03-17T14:12:35.136762Z] 14:12:35     INFO - TEST-UNEXPECTED-FAIL | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | Test timed out. 
[task 2017-03-17T14:12:35.137369Z] 14:12:35     INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:120:7
[task 2017-03-17T14:12:35.137560Z] 14:12:35     INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:141:7
[task 2017-03-17T14:12:35.138133Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.138770Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.138921Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.139509Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.139656Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.140299Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.140880Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.141064Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.141684Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.142286Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.142448Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.143024Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.143199Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.143787Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.144369Z] 14:12:35     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
[task 2017-03-17T14:12:35.144510Z] 14:12:35     INFO - TestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:379:5
[task 2017-03-17T14:12:35.145108Z] 14:12:35     INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:190:3
[task 2017-03-17T14:12:35.145269Z] 14:12:35     INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:169:5
[task 2017-03-17T14:12:35.145399Z] 14:12:35     INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:262:5
[task 2017-03-17T14:12:35.145497Z] 14:12:35     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
[task 2017-03-17T14:12:35.145642Z] 14:12:35     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
[task 2017-03-17T14:12:35.145815Z] 14:12:35     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
[task 2017-03-17T14:12:35.145912Z] 14:12:35     INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:242:5
[task 2017-03-17T14:12:35.145973Z] 14:12:35     INFO - linkAndHookup@chrome://mochikit/content/harness.xul:59:3
[task 2017-03-17T14:12:35.146064Z] 14:12:35     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
[task 2017-03-17T14:12:35.146126Z] 14:12:35     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
[task 2017-03-17T14:12:35.146294Z] 14:12:35     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
[task 2017-03-17T14:12:35.146353Z] 14:12:35     INFO - getTestList@chrome://mochikit/content/chrome-harness.js:260:3
[task 2017-03-17T14:12:35.146443Z] 14:12:35     INFO - loadTests@chrome://mochikit/content/harness.xul:38:3
[task 2017-03-17T14:12:35.146502Z] 14:12:35     INFO - EventListener.handleEvent*@chrome://mochikit/content/harness.xul:62:5
[task 2017-03-17T14:12:35.795599Z] 14:12:35     INFO - GECKO(5499) | MEMORY STAT | vsize 20974174MB | residentFast 1607MB
[task 2017-03-17T14:12:35.797829Z] 14:12:35     INFO - TEST-OK | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | took 306854ms
[task 2017-03-17T14:12:35.932355Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | no follow anchor x 
[task 2017-03-17T14:12:35.932446Z] 14:12:35     INFO - TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | no follow anchor y 
[task 2017-03-17T14:12:35.932498Z] 14:12:35    ERROR - [SimpleTest.finish()] this test already called finish!
[task 2017-03-17T14:12:35.932577Z] 14:12:35     INFO - TEST-UNEXPECTED-ERROR | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | called finish() multiple times
[task 2017-03-17T14:12:35.932615Z] 14:12:35     INFO - TEST-INFO


and the related screenshot:
https://public-artifacts.taskcluster.net/alLNdL6JTQasYIDWzIFz-Q/0/public/test_info//mozilla-test-fail-screenshot_lYeEHW.png

this is the last test output message we get:
TEST-PASS | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | new anchor with offset y

which aligns with the code here:
https://dxr.mozilla.org/mozilla-central/source/toolkit/content/tests/chrome/window_panel_anchoradjust.xul?q=path%3Awindow_panel_anchoradjust.xul&redirect_type=single#100


typically this test takes <1s:
TEST-OK | toolkit/content/tests/chrome/test_panel_anchoradjust.xul | took 596ms

but we are timing out after 5 minutes :(

I would like to sanity check where we are timing out and if the changeset from bug 1346426 seems possible to trigger this.



[0] https://public-artifacts.taskcluster.net/alLNdL6JTQasYIDWzIFz-Q/0/public/logs/live_backing.log
Blocks: 1346426
Flags: needinfo?(jmaher) → needinfo?(enndeakin)
Comment hidden (Intermittent Failures Robot)
This test was added in bug 1109868; the first failure recorded here happened on the same day. Hopefully Neil can make this test more reliable.
Blocks: 1109868
Assignee

Comment 8

2 years ago
This test is showing two popups, the second one anchored on an element in the first one. The first popup is being hidden and the expectation is that the second popup will get hidden due to the first one not being open anymore.

Testing shows that nsXULPopupManager::UpdatePopupPositions isn't being called on Linux when the test fails. It is fairly easy to workaround in most cases by calling UpdatePopupPositions manually whenever a popup is hidden, and I'll probably add something that does this to fix this test, but it's possible that there is some underlying bug.

I didn't investigate whether nsRefreshDriver::Tick is actually called when it fails, but the part where UpdatePopupPositions is not. Timothy, does this sound like a real bug?
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Flags: needinfo?(enndeakin) → needinfo?(tnikkel)
Resolution: --- → FIXED
Assignee

Updated

2 years ago
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(In reply to Neil Deakin from comment #8)
> This test is showing two popups, the second one anchored on an element in
> the first one. The first popup is being hidden and the expectation is that
> the second popup will get hidden due to the first one not being open anymore.
> 
> Testing shows that nsXULPopupManager::UpdatePopupPositions isn't being
> called on Linux when the test fails. It is fairly easy to workaround in most
> cases by calling UpdatePopupPositions manually whenever a popup is hidden,
> and I'll probably add something that does this to fix this test, but it's
> possible that there is some underlying bug.
> 
> I didn't investigate whether nsRefreshDriver::Tick is actually called when
> it fails, but the part where UpdatePopupPositions is not. Timothy, does this
> sound like a real bug?

No. I don't think it'll tick if there is nothing wanting a tick. So your proposed fix sounds good to me.
Flags: needinfo?(tnikkel)
checking in here, this test is still failing at ~50 failures/week, it sounds like we have an idea of how to fix this, would it be realistic to expect that in the next week (by the end of the month)?
Comment hidden (Intermittent Failures Robot)
Assignee

Comment 12

2 years ago
Assignee: nobody → enndeakin
Attachment #8851549 - Flags: review?(tnikkel)
Attachment #8851549 - Flags: review?(tnikkel) → review+

Comment 13

2 years ago
Pushed by neil@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/16fc5defd30f
check for anchor changes that affect popup positions and visibility whenever a popup is closed, r=tn

Comment 14

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/16fc5defd30f
Status: REOPENED → RESOLVED
Last Resolved: 2 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Please request Aurora/Beta approval on this when you get a chance.
Flags: needinfo?(enndeakin)
Assignee

Comment 16

2 years ago
Comment on attachment 8851549 [details]
update the popup anchors whenever a popup is closed

Approval Request Comment
[Feature/Bug causing the regression]: minor fix causing intermittent test failure
[User impact if declined]: none
[Is this code covered by automated tests?]: fixes test
[Has the fix been verified in Nightly?]:
[Needs manual test from QE? If yes, steps to reproduce]: no
[List of other uplifts needed for the feature/fix]: none, followup for 1109868 
[Is the change risky?]: no
[Why is the change risky/not risky?]: it just manually calls a function that normally gets called every paint, but doesn't in one edge case on linux
[String changes made/needed]: no
Flags: needinfo?(enndeakin)
Attachment #8851549 - Flags: approval-mozilla-beta?
Attachment #8851549 - Flags: approval-mozilla-aurora?
Comment on attachment 8851549 [details]
update the popup anchors whenever a popup is closed

Fix for regression from 53, let's uplift to beta.
Attachment #8851549 - Flags: approval-mozilla-beta?
Attachment #8851549 - Flags: approval-mozilla-beta+
Attachment #8851549 - Flags: approval-mozilla-aurora?
Attachment #8851549 - Flags: approval-mozilla-aurora+

Comment 18

2 years ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/92c2bde2cec8
Whiteboard: [stockwell needswork] → [stockwell fixed]
Comment hidden (Intermittent Failures Robot)
This is still happening :(
Status: RESOLVED → REOPENED
Flags: needinfo?(enndeakin)
Resolution: FIXED → ---
Target Milestone: mozilla55 → ---
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Whiteboard: [stockwell fixed] → [stockwell needswork]
Comment hidden (mozreview-request)
Comment hidden (Intermittent Failures Robot)
Didn't bug 1369488 fix this?
the one instance was on the 15th, the same day the patch landed, I assume this was a failure that occurred prior to the fix.
Whiteboard: [stockwell needswork] → [stockwell fixed:product]

Comment 37

2 years ago
mozreview-review
Comment on attachment 8878901 [details]
Bug 1340413 - Disable test_panel_anchoradjust.xul for linux.

https://reviewboard.mozilla.org/r/150146/#review155064
Attachment #8878901 - Flags: review?(jmaher) → review+

Comment 38

2 years ago
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6e371bef11ca
Disable test_panel_anchoradjust.xul for linux. r=jmaher
marking as leave open since we are disabling a test in order to move forward in porting tests to ubuntu 16.
Why are we disabling it if it's fixed?
Flags: needinfo?(jmaher)
it is not fixed on ubuntu 16.04, only for the 12.04 use case
Flags: needinfo?(jmaher)
Where is a treeherder link to see the failure?
Flags: needinfo?(jmaher)
Here's the latest one that we were using and it didn't have the changes from bug 1369488, it just missed them: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c74afcf988a46f76c1360625042384013e74d0c7

I'm running a push to try with the update now to be sure that it's no longer failing on Ubuntu 16 also (Note: it's possible for there to be other errors in this one as their patches may not have landed yet but this doesn't stop test_panel_anchoradjust.xul from failing if it still does) : 
https://treeherder.mozilla.org/#/jobs?repo=try&revision=096b8ae7384abbe34bc567809213c59a5c9ad584
Flags: needinfo?(jmaher)
(In reply to Greg Mierzwinski [:gmierz] from comment #43)
> Here's the latest one that we were using and it didn't have the changes from
> bug 1369488, it just missed them:
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=c74afcf988a46f76c1360625042384013e74d0c7
> 
> I'm running a push to try with the update now to be sure that it's no longer
> failing on Ubuntu 16 also (Note: it's possible for there to be other errors
> in this one as their patches may not have landed yet but this doesn't stop
> test_panel_anchoradjust.xul from failing if it still does) : 
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=096b8ae7384abbe34bc567809213c59a5c9ad584

Thanks. Looks like test_panel_anchoradjust.xul doesn't fail in that push. So we should be able to re-enable this test.
Flags: needinfo?(gmierz2)
Depends on: 1374627
Ok, I've pushed a patch to enable this test in bug 1374627.
Flags: needinfo?(gmierz2)
Greg, thanks for looking into this and :tnikkel, thanks for pointing out the oversight!
Assignee

Comment 48

2 years ago
This test is enabled so is there anything else to do here?
Flags: needinfo?(enndeakin) → needinfo?(jmaher)
oh, I think we are good!
Status: REOPENED → RESOLVED
Last Resolved: 2 years ago2 years ago
Flags: needinfo?(jmaher)
Resolution: --- → FIXED
Removing leave-open keyword from resolved bugs, per :sylvestre.
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.