Closed Bug 1340413 Opened 7 years ago Closed 7 years ago

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

Categories

(Toolkit :: UI Widgets, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
Tracking Status
firefox52 --- unaffected
firefox-esr52 --- unaffected
firefox53 --- wontfix
firefox54 --- affected
firefox55 --- affected

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed:product])

Attachments

(2 files)

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)
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
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
Closed: 7 years ago
Flags: needinfo?(enndeakin) → needinfo?(tnikkel)
Resolution: --- → FIXED
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)?
Assignee: nobody → enndeakin
Attachment #8851549 - Flags: review?(tnikkel)
Attachment #8851549 - Flags: review?(tnikkel) → review+
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
https://hg.mozilla.org/mozilla-central/rev/16fc5defd30f
Status: REOPENED → RESOLVED
Closed: 7 years ago7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Please request Aurora/Beta approval on this when you get a chance.
Flags: needinfo?(enndeakin)
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+
https://hg.mozilla.org/releases/mozilla-aurora/rev/92c2bde2cec8
Whiteboard: [stockwell needswork] → [stockwell fixed]
This is still happening :(
Status: RESOLVED → REOPENED
Flags: needinfo?(enndeakin)
Resolution: FIXED → ---
Target Milestone: mozilla55 → ---
Whiteboard: [stockwell fixed] → [stockwell needswork]
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 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+
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!
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
Closed: 7 years ago7 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.