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

[task 2021-09-07T16:07:39.293Z] 16:07:39     INFO - TEST-START | /editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent
[task 2021-09-07T16:07:39.294Z] 16:07:39     INFO - Closing window 69aaabe4-1f09-41bd-85a6-70b3182df5bf
[task 2021-09-07T16:07:39.387Z] 16:07:39     INFO - {'actions': [{'type': 'none', 'actions': [{'type': 'pause', 'duration': 16}, {'type': 'pause', 'duration': 16}], 'id': '0'}, {'type': 'key', 'actions': [{'type': 'keyDown', 'value': 'a'}, {'type': 'keyUp', 'value': 'a'}], 'id': '1'}]}
[task 2021-09-07T16:07:39.471Z] 16:07:39     INFO - {'actions': [{'type': 'none', 'actions': [{'type': 'pause', 'duration': 16}, {'type': 'pause', 'duration': 16}], 'id': '2'}, {'type': 'key', 'actions': [{'type': 'keyDown', 'value': 'a'}, {'type': 'keyUp', 'value': 'a'}], 'id': '3'}]}
[task 2021-09-07T16:07:39.540Z] 16:07:39     INFO - {'actions': [{'type': 'none', 'actions': [{'type': 'pause', 'duration': 16}, {'type': 'pause', 'duration': 16}], 'id': '4'}, {'type': 'key', 'actions': [{'type': 'keyDown', 'value': 'a'}, {'type': 'keyUp', 'value': 'a'}], 'id': '5'}]}
[task 2021-09-07T16:07:39.625Z] 16:07:39     INFO - 
[task 2021-09-07T16:07:39.625Z] 16:07:39     INFO - TEST-PASS | /editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent | Wait for load event 
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - TEST-FAIL | /editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent | execCommand("insertText", false, "typed value") in <textarea> - assert_equals: The value shouldn't be modified by "insertText" command expected "default value" but got "typed value"
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - @http://web-platform.test:8000/editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent:51:18
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:2087:25
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - promise_test/tests.promise_tests</<@http://web-platform.test:8000/resources/testharness.js:638:36
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - promise_test/tests.promise_tests<@http://web-platform.test:8000/resources/testharness.js:637:20
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - TEST-FAIL | /editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent | execCommand("delete") in <textarea> - assert_equals: The value shouldn't be modified by "delete" command expected "default value" but got ""
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - @http://web-platform.test:8000/editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent:63:18
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:2087:25
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - promise_test/tests.promise_tests</<@http://web-platform.test:8000/resources/testharness.js:638:36
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - promise_test/tests.promise_tests<@http://web-platform.test:8000/resources/testharness.js:637:20
[task 2021-09-07T16:07:39.628Z] 16:07:39     INFO - TEST-UNEXPECTED-PASS | /editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent | <textarea> is hidden by "keydown" event listener - expected FAIL
[task 2021-09-07T16:07:39.629Z] 16:07:39     INFO - TEST-INFO | expected FAIL
[task 2021-09-07T16:07:39.631Z] 16:07:39     INFO - ..
[task 2021-09-07T16:07:39.632Z] 16:07:39     INFO - TEST-OK | /editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=parent | took 338ms
[task 2021-09-07T16:07:39.634Z] 16:07:39     INFO - PID 6308 | 1631030859626	Marionette	INFO	Stopped listening on port 51660
[task 2021-09-07T16:07:39.678Z] 16:07:39     INFO - PID 6308 | JavaScript error: resource:///modules/Interactions.jsm, line 201: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-09-07T16:07:40.103Z] 16:07:40     INFO - PID 6308 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-09-07T16:07:40.319Z] 16:07:40     INFO - Browser exited with return code 0
[task 2021-09-07T16:07:40.324Z] 16:07:40     INFO - Closing logging queue
[task 2021-09-07T16:07:40.324Z] 16:07:40     INFO - queue closed
[task 2021-09-07T16:07:40.457Z] 16:07:40     INFO - Application command: Z:\task_163102894813357\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_163102894813357\AppData\Local\Temp\tmpkb2mindt
[task 2021-09-07T16:07:40.470Z] 16:07:40     INFO - PID 5784 | 1631030857475	Marionette	INFO	Marionette enabled
[task 2021-09-07T16:07:40.473Z] 16:07:40     INFO - PID 5784 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_163102894813357\\AppData\\Local\\Temp\\tmpkt530e4a\\search.json.mozlz4", (void 0)))
[task 2021-09-07T16:07:40.474Z] 16:07:40     INFO - PID 5784 | 1631030859474	Marionette	INFO	Listening on port 51692
[task 2021-09-07T16:07:40.475Z] 16:07:40     INFO - Starting runner
[task 2021-09-07T16:07:41.511Z] 16:07:41     INFO - TEST-START | /editing/other/edit-in-textcontrol-immediately-after-hidden.tentative.html?editor=textarea&hide-target=editor

Hmm, it probably means that something randomly runs while dispatching a keydown element and it flushes pending notifications which includes destroying the target editor. So editor won't handle it and unexpectedly passes the test.

Ah, perhaps, I got it. keypress event is dispatched separately from keydown event, and editor handles the keypress event.
After PresShell::EventHandler dispatches any user input event, it tries to flush pending notifications of IMEContentObserver:
https://searchfox.org/mozilla-central/rev/1761c710b035d7dc8892dfa8e56589b4e095221f/layout/base/PresShell.cpp#8153,8158

Then, IMEContentObserver will put it into the queue to wait next vsync:
https://searchfox.org/mozilla-central/rev/1761c710b035d7dc8892dfa8e56589b4e095221f/dom/events/IMEContentObserver.cpp#1426,1436-1437

Therefore, only when the test runs fast, i.e., in PGO build or Opt build, the vsync message comes before the following keypress event. Then, it flushes pending layout and it causes destroying the TextEditor, finally, the keypress event won't be handled in the editor and gets expected result.

In other words, this could happen in the wild randomly. So I think that we need to make keypress event is dispatched as a default action of the preceding keydown event, but it's really hard to fix it because of requiring a lot of changes under widget/. It was already filed as bug 1181501 and bug 1560766.

(It's fine to disable the test only in opt builds.)

I have no idea how to make the test result stable except fixing the failure 😋

Here is the first try:
https://treeherder.mozilla.org/jobs?repo=try&revision=f7e66637baf1b3bfe00f3b5f0397d195bf56cc9d

There are two permanent failures. One is the case of <input> element in editing/other/insert-paragraph-in-void-element.tentative.html. However, I know this is just a hidden bug, not a regression, although I'm not sure the reason. Collapsing Selection might be going down to the anonymous subtree for <input>. I'll check it more.
https://treeherder.mozilla.org/jobs?repo=try&revision=f7e66637baf1b3bfe00f3b5f0397d195bf56cc9d&selectedTaskRun=PYtSlovQQ8SEHK-Co5IhEA.0

The other is the failures of test_editor_for_input_with_autocomplete.html. I have no idea what's going on for this. Perhaps, autocomplete popup behavior is canceled or something by the new flush?? I keep investigating this.
https://treeherder.mozilla.org/jobs?repo=try&revision=f7e66637baf1b3bfe00f3b5f0397d195bf56cc9d&selectedTaskRun=EyoKZnq5TQyQziH1vlt4hQ.0

The former issue is bug 1731005. The latter is looks like known intermittent failure.

Depends on D125791

I have no idea how to make the test result stable because the intermittent
failure is caused by a race of IMEContentObserver's content query performend
at vsync and keypress event after the keydown event. Therefore, I try to
fix the root cause of the failure.

There are two paths reaching a public method of editor with pending
notifications. One is keypress event listener of the editor. The other is
execCommand related methods of Document. Therefore, we should make them
flush pending notifications before accessing editor, but the cost may be too
expensive. So we should consider whether we should flush pending notifications
or not as far as later.

Note that we cannot fix the beforeinput cases because flushing pending
notifications after dispatching beforeinput event may cause oranges. It'll
be fixed while I'm working on bug 1710784.

Depends on D125791

https://hg.mozilla.org/mozilla-central/rev/82f0527432d5