Filed by: egao [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=251034558&repo=try
Full log: https://queue.taskcluster.net/v1/task/Yu5WSam5Q-6rjPZHYKtE7A/runs/0/artifacts/public/logs/live_backing.log

Platform: macosx1014-mojave
Test: mochtiest-chrome

Context:
23:00:34 INFO - TEST-START | dom/tests/mochitest/chrome/test_bug1224790-1.xul
23:01:00 INFO - GECKO(2155) | 2019-06-10 23:01:00.698 firefox[2155:22364] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
23:06:03 INFO - TEST-INFO | started process screencapture
23:06:03 INFO - TEST-INFO | screencapture: exit 0
23:06:03 INFO - Buffered messages logged at 23:00:34
23:06:03 INFO - must wait for load
23:06:03 INFO - must wait for load
23:06:03 INFO - must wait for focus
23:06:03 INFO - Buffered messages logged at 23:00:35
23:06:03 INFO - must wait for load
23:06:03 INFO - must wait for focus
23:06:03 INFO - must wait for focus
23:06:03 INFO - Buffered messages finished
23:06:03 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/chrome/test_bug1224790-1.xul | Test timed out.
23:06:03 INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:275:18
23:06:03 INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:121:22
23:06:03 INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:142:7
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:06:03 INFO - TestRunner.runTests/<@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:381:20
23:06:03 INFO - promise callbackTestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:368:50
23:06:03 INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:201:14
23:06:03 INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:180:12
23:06:03 INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:273:12
23:06:03 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
23:06:03 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
23:06:03 INFO - EventHandlerNonNullgetTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
23:06:03 INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:253:5
23:06:03 INFO - linkAndHookup@chrome://mochikit/content/harness.xul:45:3
23:06:03 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
23:06:03 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
23:06:03 INFO - EventHandlerNonNullgetTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
23:06:03 INFO - getTestList@chrome://mochikit/content/chrome-harness.js:251:3
23:06:03 INFO - loadTests@chrome://mochikit/content/harness.xul:24:3
23:06:03 INFO - EventListener.handleEvent*@chrome://mochikit/content/harness.xul:48:12
23:06:04 INFO - GECKO(2155) | MEMORY STAT | vsize 7581MB | residentFast 333MB | heapAllocated 79MB
23:06:04 INFO - TEST-OK | dom/tests/mochitest/chrome/test_bug1224790-1.xul | took 329997ms
23:06:04 INFO - TEST-START | dom/tests/mochitest/chrome/test_bug1224790-2.xul
23:11:34 INFO - Not taking screenshot here: see the one that was previously logged
23:11:34 INFO - Buffered messages logged at 23:06:04
23:11:34 INFO - must wait for load
23:11:34 INFO - must wait for load
23:11:34 INFO - must wait for focus
23:11:34 INFO - Buffered messages logged at 23:06:05
23:11:34 INFO - must wait for load
23:11:34 INFO - must wait for focus
23:11:34 INFO - Buffered messages finished
23:11:34 INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/chrome/test_bug1224790-2.xul | Test timed out.
23:11:34 INFO - SimpleTest.ok@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:275:18
23:11:34 INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:121:22
23:11:34 INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:142:7
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - setTimeout handlerTestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:163:5
23:11:34 INFO - TestRunner.runTests/<@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:381:20
23:11:34 INFO - promise callbackTestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:368:50
23:11:34 INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:201:14
23:11:34 INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:180:12
23:11:34 INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:273:12
23:11:34 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
23:11:34 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
23:11:34 INFO - EventHandlerNonNullgetTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
23:11:34 INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:253:5
23:11:34 INFO - linkAndHookup@chrome://mochikit/content/harness.xul:45:3
23:11:34 INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
23:11:34 INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
23:11:34 INFO - EventHandlerNonNullgetTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
23:11:34 INFO - getTestList@chrome://mochikit/content/chrome-harness.js:251:3
23:11:34 INFO - loadTests@chrome://mochikit/content/harness.xul:24:3
23:11:34 INFO - EventListener.handleEvent@chrome://mochikit/content/harness.xul:48:12
23:11:35 INFO - GECKO(2155) | MEMORY STAT | vsize 7597MB | residentFast 332MB | heapAllocated 80MB
23:11:35 INFO - TEST-OK | dom/tests/mochitest/chrome/test_bug1224790-2.xul | took 330450ms

:hsinyi - this appears to be a new failure observed on macosx1014 platform, which is in the works as the successor of macosx1010. Could you take a look, or pass on the ni to someone that maybe able to do so? Thanks!

I'm not really sure who should ask for.
Masayuki or :arai, do you know if there's some limitation, such as synthesizeNativeOSXClick, on mac 10.14 version that causes this new failure?

it might require extra privilege about accessibility, to simulate mouse event.
I'll look into it this weekend

Well, I really don't know about it. Arai-san, thank you for taking it.

I get "Accessibility Access (Events)" dialog when I call CGEventPost API,
and I have to open Preferences, Security & Privacy pane, Privacy tab, and check "Terminal" (or the application that invokes ./mach test).
That's the reason why the test fails on macOS 10.14, that added sandboxing around that.

https://developer.apple.com/library/archive/documentation/Security/Conceptual/AppSandboxDesignGuide/DesigningYourSandbox/DesigningYourSandbox.html

Posting keyboard or mouse events to another app

You cannot sandbox an app that controls another app. Posting keyboard or
mouse events using functions like CGEventPost offers a way to circumvent
this restriction, and is therefore not allowed from a sandboxed app.

and I think, configuring all environment to allow that isn't reasonable solution.
so, we'll need to disable the test.

what's the plan about automation and macos versions?
will all instances be replaced/updated to macOS 10.14 or later?
or will there be any 10.13 or older instances?

if former, the test just needs to be disabled or removed, given that cannot be tested "automatically".
if latter, the test needs to detect the environment somehow and run only if possible.

Thank you, :arai for the good questions.
:egao, could you please answer :arai's questions in comment 6?

:arai - as far as I am aware, we are converting all macosx1010 machines to macosx1014, and macosx1010 will be deprecated at that point. The timeline is unclear, but my aim is to have most if not all of the tests running on macosx1014 by end of this month.

So it sounds like we need to disable the test or removed.

synthesizeNativeOSXClick uses CGEventPost, that needs "Accessibility Access
(Events)" on macOS 10.14 or later, and cannot be tested in automation without
human interaction to add the access.

Kats is fixing this in bug 1549052.

:mstange - thanks for heads up, will test this suite as well when bug 1549052 lands in central.

bug 1549052 touches different part.
this bug is about synthesizeNativeOSXClick function in EventUtils.js, that uses js-ctypes to call CGEventPost.
I think we might be able to do similar thing as the patch there to perform native click in the function.

but, given it's Objective-C call, calling it from ctypes is somewhat complicated.
I know it's possible, and I have some wrapper code written before, but I'm not sure introducing whole those things into EventUtils.js makes sense.

or maybe we should move the code to native part?

Oohh, I see, I didn't realize that. Let me look at this in more detail.

Pushed a try with the changes in bug 1549052, but these tests continue to fail.

I will post a patch to disable these tests against this bug, but investigations (if any) can continue if desired.

will check if we can move the synthesizeNativeOSXClick code to C++ part

https://hg.mozilla.org/mozilla-central/rev/15a08d101dd7

looks like we can use synthesizeNativeMouseEvent in EventUtils.js.
some files are using it to emulate click.
I think adding synthesizeNativeMouseClick would make them simpler.

this would be part of bug 1126772, but I'll leave EventUtils.synthesize things there.

Depends on D39603

The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?

no

The leave-open keyword is there and there is no activity for 6 months.
:jstutte, maybe it's time to close this bug?

Hi Markus, are there any news here? Thank you!

FYI, Bug 1659494 has introduced the synthesizeNativeMouseClick in EventUtils.

I'll try to rebase the patch next week. The test that these patches fix is currently disabled.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9c8464597918e3c961fd30957b311ea1e9eaf14c

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5f5d628c9a6e4e88052394209d54a45fa5a932d4

Looks greenish now: https://treeherder.mozilla.org/#/jobs?repo=try&revision=b12946f722b1d592a8c66d3365d975ed4432389f

https://hg.mozilla.org/mozilla-central/rev/21e13390db4f
https://hg.mozilla.org/mozilla-central/rev/b86d52383964

The leave-open keyword is there and there is no activity for 6 months.
:arai, maybe it's time to close this bug?

Thanks.
the above patch fixed the issue, for firefox 83