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

[task 2020-10-09T12:03:13.542Z] 12:03:13     INFO - TEST-START | dom/base/test/useractivation/test_clipboard_editor.html
[task 2020-10-09T12:03:26.871Z] 12:03:26     INFO - TEST-INFO | started process screencapture
[task 2020-10-09T12:03:26.992Z] 12:03:26     INFO - TEST-INFO | screencapture: exit 0
[task 2020-10-09T12:03:26.992Z] 12:03:26     INFO - <snipped 6 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2020-10-09T12:03:26.992Z] 12:03:26     INFO - Buffered messages logged at 12:03:14
[task 2020-10-09T12:03:26.993Z] 12:03:26     INFO - Initializing clipboard with "waitForClipboard-known-value-0.2014797709281757"...
[task 2020-10-09T12:03:26.993Z] 12:03:26     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:26.993Z] 12:03:26     INFO - Buffered messages logged at 12:03:15
[task 2020-10-09T12:03:26.993Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.2014797709281757 
[task 2020-10-09T12:03:26.994Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 0 - 2 
[task 2020-10-09T12:03:26.994Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 0 - 2 
[task 2020-10-09T12:03:26.994Z] 12:03:26     INFO - Initializing clipboard with "waitForClipboard-known-value-0.571554504290182"...
[task 2020-10-09T12:03:26.994Z] 12:03:26     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:26.994Z] 12:03:26     INFO - Buffered messages logged at 12:03:16
[task 2020-10-09T12:03:26.995Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'text text' 
[task 2020-10-09T12:03:26.995Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 0 - 4 
[task 2020-10-09T12:03:26.995Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 0 - 4 
[task 2020-10-09T12:03:26.995Z] 12:03:26     INFO - Initializing clipboard with "waitForClipboard-known-value-0.160049676935494"...
[task 2020-10-09T12:03:26.995Z] 12:03:26     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:26.996Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'text text' 
[task 2020-10-09T12:03:26.996Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 0 - 6 
[task 2020-10-09T12:03:26.996Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 0 - 6 
[task 2020-10-09T12:03:26.996Z] 12:03:26     INFO - Initializing clipboard with "waitForClipboard-known-value-0.28162167164242924"...
[task 2020-10-09T12:03:26.997Z] 12:03:26     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:26.997Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.28162167164242924 
[task 2020-10-09T12:03:26.997Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 0 - 8 
[task 2020-10-09T12:03:26.997Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 0 - 8 
[task 2020-10-09T12:03:26.997Z] 12:03:26     INFO - Initializing clipboard with "waitForClipboard-known-value-0.12453862320072095"...
[task 2020-10-09T12:03:26.998Z] 12:03:26     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:26.998Z] 12:03:26     INFO - Buffered messages logged at 12:03:17
[task 2020-10-09T12:03:26.998Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.12453862320072095 
[task 2020-10-09T12:03:26.998Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 0 - 10 
[task 2020-10-09T12:03:26.998Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 0 - 10 
[task 2020-10-09T12:03:26.999Z] 12:03:26     INFO - Initializing clipboard with "waitForClipboard-known-value-0.5244679481055872"...
[task 2020-10-09T12:03:26.999Z] 12:03:26     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:26.999Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'textarea text' 
[task 2020-10-09T12:03:26.999Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 0 - 12 
[task 2020-10-09T12:03:26.999Z] 12:03:26     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 0 - 12 
[task 2020-10-09T12:03:27.000Z] 12:03:26     INFO - Initializing clipboard with "waitForClipboard-known-value-0.7165644368995802"...
[task 2020-10-09T12:03:27.000Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.000Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'textarea text' 
[task 2020-10-09T12:03:27.000Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 0 - 14 
[task 2020-10-09T12:03:27.000Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 0 - 14 
[task 2020-10-09T12:03:27.001Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.2181163892737623"...
[task 2020-10-09T12:03:27.001Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.001Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.2181163892737623 
[task 2020-10-09T12:03:27.001Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 0 - 15 
[task 2020-10-09T12:03:27.001Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 0 - 15 
[task 2020-10-09T12:03:27.001Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.8817212973972693"...
[task 2020-10-09T12:03:27.001Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - Buffered messages logged at 12:03:18
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.8817212973972693 
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 0 - 16 
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 0 - 16 
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.5633916543578131"...
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'contenteditable text' 
[task 2020-10-09T12:03:27.002Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 0 - 18 
[task 2020-10-09T12:03:27.003Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 0 - 18 
[task 2020-10-09T12:03:27.003Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.22997946778426048"...
[task 2020-10-09T12:03:27.003Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.009Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'contenteditable text' 
[task 2020-10-09T12:03:27.009Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 0 - 20 
[task 2020-10-09T12:03:27.009Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 0 - 20 
[task 2020-10-09T12:03:27.010Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.4857987374816608"...
[task 2020-10-09T12:03:27.010Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.010Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused copy invocation 0 - 1 - 0 
[task 2020-10-09T12:03:27.010Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'span text' 
[task 2020-10-09T12:03:27.010Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 1 - 1 
[task 2020-10-09T12:03:27.010Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 1 - 1 
[task 2020-10-09T12:03:27.010Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.6891436799085089"...
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused cut invocation 0 - 1 - 1 
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.6891436799085089 
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 1 - 2 
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 1 - 2 
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.2860865474841524"...
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.011Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused copy invocation 0 - 1 - 3 
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'text text' 
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 1 - 4 
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 1 - 4 
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.48498595253873766"...
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused cut invocation 0 - 1 - 5 
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'text text' 
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 1 - 6 
[task 2020-10-09T12:03:27.012Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 1 - 6 
[task 2020-10-09T12:03:27.013Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.34138331216054274"...
[task 2020-10-09T12:03:27.013Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.013Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused copy invocation 0 - 1 - 7 
[task 2020-10-09T12:03:27.013Z] 12:03:27     INFO - Buffered messages logged at 12:03:19
[task 2020-10-09T12:03:27.013Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.34138331216054274 
[task 2020-10-09T12:03:27.013Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 1 - 8 
[task 2020-10-09T12:03:27.013Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 1 - 8 
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.8825023036191956"...
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused cut invocation 0 - 1 - 9 
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.8825023036191956 
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback to run 0 - 1 - 10 
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback not to run 0 - 1 - 10 
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.7620710883159206"...
[task 2020-10-09T12:03:27.014Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.015Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused copy invocation 0 - 1 - 11 
[task 2020-10-09T12:03:27.015Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Clipboard has the given value: 'textarea text' 
[task 2020-10-09T12:03:27.015Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect cut callback not to run 0 - 1 - 12 
[task 2020-10-09T12:03:27.015Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Expect copy callback to run 0 - 1 - 12 
[task 2020-10-09T12:03:27.015Z] 12:03:27     INFO - Initializing clipboard with "waitForClipboard-known-value-0.5170680238228297"...
[task 2020-10-09T12:03:27.025Z] 12:03:27     INFO - Succeeded initializing clipboard, start requested things...
[task 2020-10-09T12:03:27.025Z] 12:03:27     INFO - TEST-PASS | dom/base/test/useractivation/test_clipboard_editor.html | Keydown caused cut invocation 0 - 1 - 13 
[task 2020-10-09T12:03:27.025Z] 12:03:27     INFO - Buffered messages finished
[task 2020-10-09T12:03:27.025Z] 12:03:27     INFO - TEST-UNEXPECTED-FAIL | dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.5170680238228297 ```

There have been 69 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures/bugdetails?startday=2021-01-01&endday=2021-01-08&tree=trunk&bug=1670233

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=326154124&repo=autoland&lineNumber=2351

Jens, could you assign this to someone?

Backed out changeset ed88b1f03a11 (Bug 1670233) for causing test_clipboard_noeditor.html to fail instead.

Backout link: https://hg.mozilla.org/integration/autoland/rev/1c24b564e9ebca0a1de676bedce8914efccbbbe1

Push with failures:
https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunning%2Cpending%2Crunnable&fromchange=51d688ae992bb4fc8a57e4c6df043a72dd884d32&searchStr=windows%2C7%2Copt%2Cmochitests%2Ctest-windows7-32%2Fopt-mochitest-plain-e10s%2C5&tochange=f91af44347aa4125dacb9933c683cf99ebb84761&selectedTaskRun=I0wCGRC-QGW8CfehxcPcFQ.0

https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&resultStatus=testfailed%2Cbusted%2Cexception%2Crunnable&fromchange=718fc13926e6e2350eedb1e807ac16e3e658e386&searchStr=linux%2C18.04%2Cx64%2Cwebrender%2Cdebug%2Cmochitests%2Cwith%2Cfission%2Cenabled%2Ctest-linux1804-64-qr%2Fdebug-mochitest-plain-fis-e10s%2C3&tochange=f91af44347aa4125dacb9933c683cf99ebb84761&selectedTaskRun=SawqGmjRQ5eVoicXp4rmdA.0

Failure log: https://treeherder.mozilla.org/logviewer?job_id=326376803&repo=autoland&lineNumber=2365

Disabling test_clipboard_editor.html caused test_clipboard_noeditor.html to fail in its place, meaning that there is an underlying reason that causes these tests to fail, so no point in disabling.

Backout merged to central: https://hg.mozilla.org/mozilla-central/rev/c6d819bd39daf86acd5e0c5bce5d74c2db8b8d64

These frequent fails (almost perma) are from Bug 1676966 - https://hg.mozilla.org/integration/autoland/rev/02d875d4f7d769cd03be3175490377dc600355fe
TH link: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&searchStr=windows%2C7%2Copt%2Cmochitests%2Ctest-windows7-32%2Fopt-mochitest-plain-e10s%2C5&tochange=02d875d4f7d769cd03be3175490377dc600355fe&fromchange=f38b3c4372aa9ab9650fcf4b94bf863f9bc44999&group_state=expanded&selectedTaskRun=FPDVwFKfTxOmz_QT7_ff0Q.0
Jonathan, please have a look over these. Thank you.

I expect an extra reflow triggered by async font fallback is upsetting the tests. We can just disable it for this test directory.

https://hg.mozilla.org/mozilla-central/rev/9588ccdb69f8

(In reply to Jonathan Kew (:jfkthame) from comment #24)

I expect an extra reflow triggered by async font fallback is upsetting the tests. We can just disable it for this test directory.

Is this a correct fix or just a mute for those failures?

It's a reasonable workaround, if the test is sensitive to an unpredictable extra reflow happening during the run. See https://groups.google.com/g/mozilla.dev.platform/c/VBh6oLm4EbQ for background.

Ideally, I guess tests would be immune to this, but in practice for tests that are interacting with events, selection, etc., it may be impractical to be entirely robust against this. The pref change simply ensures that any font fallback search required will complete synchronously (as has historically been the case) so that it will not result in triggering reflow at an indeterminate future time, which is what's tripping up some testcases.