1710139 - Perma dom/events/test/test_hover_mouseleave.html | [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run. Maybe the test terminated prematurely -- use SimpleTest.waitForExplicitFinish

Status: RESOLVED FIXED

(Core :: DOM: UI Events & Focus Handling, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=339095901&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZLt5TvgkRd6ikv8riJGhog/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-05-07T18:20:07.587Z] 18:20:07     INFO - TEST-START | dom/events/test/test_hover_mouseleave.html
[task 2021-05-07T18:20:07.601Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.614Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.631Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.632Z] 18:20:07     INFO - GECKO(1543) | [Child 1581, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm:751
[task 2021-05-07T18:20:07.633Z] 18:20:07     INFO - GECKO(1543) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-05-07T18:20:07.639Z] 18:20:07     INFO - GECKO(1543) | [Child 1613, Main Thread] WARNING: nsAppShell::Exit() called redundantly: file /builds/worker/checkouts/gecko/widget/cocoa/nsAppShell.mm:751
[task 2021-05-07T18:20:07.643Z] 18:20:07     INFO - GECKO(1543) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-05-07T18:20:07.646Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.664Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.682Z] 18:20:07     INFO - GECKO(1543) | [Child 1581, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-05-07T18:20:07.683Z] 18:20:07     INFO - GECKO(1543) | [Child 1581, Main Thread] WARNING: '!obs', file /builds/worker/checkouts/gecko/toolkit/components/sessionstore/RestoreTabContentObserver.cpp:58
[task 2021-05-07T18:20:07.693Z] 18:20:07     INFO - GECKO(1543) | [Child 1581, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4442
[task 2021-05-07T18:20:07.694Z] 18:20:07     INFO - GECKO(1543) | [Child 1613, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3357
[task 2021-05-07T18:20:07.695Z] 18:20:07     INFO - GECKO(1543) | [Child 1613, Main Thread] WARNING: '!obs', file /builds/worker/checkouts/gecko/toolkit/components/sessionstore/RestoreTabContentObserver.cpp:58
[task 2021-05-07T18:20:07.697Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.704Z] 18:20:07     INFO - GECKO(1543) | [Child 1613, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4442
[task 2021-05-07T18:20:07.714Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.717Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.730Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:20:07.747Z] 18:20:07     INFO - GECKO(1543) | [Child 1553, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
[task 2021-05-07T18:25:28.312Z] 18:25:28     INFO - TEST-INFO | started process screencapture
[task 2021-05-07T18:25:28.548Z] 18:25:28     INFO - TEST-INFO | screencapture: exit 0
[task 2021-05-07T18:25:28.549Z] 18:25:28     INFO - Buffered messages logged at 18:20:07
[task 2021-05-07T18:25:28.549Z] 18:25:28     INFO - must wait for load
[task 2021-05-07T18:25:28.550Z] 18:25:28     INFO - must wait for focus
[task 2021-05-07T18:25:28.550Z] 18:25:28     INFO - Buffered messages finished
[task 2021-05-07T18:25:28.550Z] 18:25:28     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_hover_mouseleave.html | Test timed out. - 
[task 2021-05-07T18:25:29.471Z] 18:25:29     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-07T18:25:29.472Z] 18:25:29     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_hover_mouseleave.html | [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run.  Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish(). - got 1, expected +0
[task 2021-05-07T18:25:29.472Z] 18:25:29     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:500:14
[task 2021-05-07T18:25:29.472Z] 18:25:29     INFO -     afterCleanup@SimpleTest/SimpleTest.js:1560:18
[task 2021-05-07T18:25:29.472Z] 18:25:29     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1636:7
[task 2021-05-07T18:25:29.472Z] 18:25:29     INFO -     SimpleTest.finish@SimpleTest/SimpleTest.js:1656:3
[task 2021-05-07T18:25:29.472Z] 18:25:29     INFO -     killTest@SimpleTest/TestRunner.js:194:22
[task 2021-05-07T18:25:29.481Z] 18:25:29     INFO - GECKO(1543) | MEMORY STAT | vsize 6687MB | residentFast 143MB | heapAllocated 13MB
[task 2021-05-07T18:25:29.495Z] 18:25:29     INFO - TEST-OK | dom/events/test/test_hover_mouseleave.html | took 321908ms
[task 2021-05-07T18:25:29.514Z] 18:25:29    ERROR - TEST-UNEXPECTED-FAIL | /tests/dom/events/test/test_hover_mouseleave.html logged result after SimpleTest.finish(): [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run.  Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish().

Comment 1

[Andreea Pavel [:apavel]]

Hi Mike, is this a regression of bug 1706048?

Comment 2

[Intermittent Failures Robot]

21 failures in 547 pushes (0.038 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 7

Platform and build breakdown:

• macosx1015-64-qr: 8
  • debug: 7
  • opt: 1
• linux1804-64-qr: 2
  • opt: 1
  • debug: 1
• linux1804-64-asan: 1
  • opt: 1
• windows10-64-qr: 3
  • debug: 2
  • opt: 1
• windows10-64-shippable-qr: 2
  • opt: 2
• linux1804-64-shippable-qr: 2
  • opt: 2
• macosx1015-64-shippable-qr: 2
  • opt: 2
• linux1804-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1710139&startday=2021-05-07&endday=2021-05-07&tree=all

Comment 3

[Natalia Csoregi [:nataliaCs]]

This has switched to tier 1: https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=linux%2C18.04%2Cx64%2Cwebrender%2Cdebug%2Cmochitests%2Cwith%2Cfission%2Cenabled%2Ctest-linux1804-64-qr%2Fdebug-mochitest-plain-fis-e10s%2C2&revision=f9bdd1b929f234f4defb8c2344c24d4e3b2547bc&selectedTaskRun=LlgVOtLvQH-hW0EJKoihtQ.0

Comment 4

[Natalia Csoregi [:nataliaCs]]

Did a round of retriggers and backfills on a TIER 1 job but the test doesn't always run on the same job, so I added all mochitest fission jobs on Linux 18.04 x64 WebRender debug within this range:
https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&tochange=7f3071ee22e042d5c7240e7ce52783bddef8255d&fromchange=f0a781b6d1ccab380e8cb7478e9e15ea8d05ad7a&searchStr=Linux%2C18.04%2Cx64%2CWebRender%2Cdebug%2Cmochitest%2Cfission&selectedTaskRun=DyQMq3YwT1a94XP9YbaCWQ.0

Also backfilled a tier 2 job: https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&tochange=86a2163e7a475f2b9310a278365499778e8ca6e0&fromchange=2730f2d2cf9db4121e6b6b94014e5467f6c8bdab&searchStr=OS%2CX%2C10.15%2CWebRender%2Cdebug%2CMochitests%2Cwith%2Cfission%2Cenabled%2Ctest-macosx1015-64-qr%2Fdebug-mochitest-plain-fis-e10s%2C1&selectedTaskRun=H61eBE6oSI6d2p3OWHYcFQ.0

Failures point to Bug 1709125, and are seen in https://treeherder.mozilla.org/jobs?repo=try&revision=aceeab022972411c33444228a4bc8e827c5cab95&group_state=expanded&selectedTaskRun=AcjQ9sa7RYSf5drABMJlgw.0 as well

Tested the backout: https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&revision=95c2218e8494f7b258b6b2f4f91748db58b4cef0 hence pushing the backout on autoland.

Comment 5

[Natalia Csoregi [:nataliaCs]]

Backed out Bug 1709125 : https://hg.mozilla.org/integration/autoland/rev/0c8028d891714aecff3bf9adc7b1870995c7f861

Comment 6

[Intermittent Failures Robot]

46 failures in 91 pushes (0.505 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 35
• mozilla-central: 11

Platform and build breakdown:

• windows10-64-qr: 7
  • opt: 4
  • debug: 3
• linux1804-64-qr: 12
  • debug: 8
  • opt: 4
• macosx1015-64-qr: 9
  • opt: 4
  • debug: 5
• linux1804-64-asan: 5
  • opt: 5
• linux1804-64-shippable-qr: 4
  • opt: 4
• windows10-64-shippable-qr: 4
  • opt: 4
• macosx1015-64-shippable-qr: 4
  • opt: 4
• linux1804-64-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1710139&startday=2021-05-08&endday=2021-05-08&tree=all

Comment 7

[Intermittent Failures Robot]

86 failures in 3279 pushes (0.026 failures/push) were associated with this bug in the last 7 days.

This is the #11 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: 68
• mozilla-central: 18

Platform and build breakdown:

• macosx1015-64-qr: 18
  • debug: 13
  • opt: 5
• linux1804-64-qr: 32
  • opt: 5
  • debug: 27
• linux1804-64-asan: 6
  • opt: 6
• windows10-64-qr: 10
  • debug: 5
  • opt: 5
• windows10-64-shippable-qr: 6
  • opt: 6
• linux1804-64-shippable-qr: 6
  • opt: 6
• macosx1015-64-shippable-qr: 6
  • opt: 6
• linux1804-64-shippable: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1710139&startday=2021-05-03&endday=2021-05-09&tree=all

Comment 8

[Mike Conley (:mconley) (:⚙️)]

Sounds like comment 1 got answered, and this was caused by bug 1709125.