Closed Bug 1670233 Opened 4 years ago Closed 4 years ago

Intermittent dom/base/test/useractivation/test_clipboard_editor.html | Timed out while polling clipboard for requested data, got: waitForClipboard-known-value-0.5170680238228297

Categories

(Core :: DOM: Core & HTML, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
86 Branch
Tracking Status
firefox86 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell unknown])

Attachments

(2 files)

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 ```
Flags: needinfo?(jstutte)
Assignee: nobody → apavel
Status: NEW → ASSIGNED
Assignee: apavel → nobody
Status: ASSIGNED → NEW
Assignee: nobody → apavel
Status: NEW → ASSIGNED
Pushed by rmaries@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/ed88b1f03a11 disable test_clipboard_editor.html on linux64-qr and win7 r=intermittent-reviewers,jmaher DONTBUILD
Keywords: leave-open
Whiteboard: [stockwell needswork:owner] → [stockwell needswork:owner][stockwell disabled]
Keywords: leave-open
Whiteboard: [stockwell needswork:owner][stockwell disabled] → [stockwell needswork:owner]
Backout by btara@mozilla.com: https://hg.mozilla.org/mozilla-central/rev/c6d819bd39da Backed out changeset ed88b1f03a11 for causing test_clipboard_noeditor.html to fail instead.
Has Regression Range: --- → yes
Keywords: regression

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

Flags: needinfo?(jfkthame)
Pushed by jkew@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/9588ccdb69f8 Disable async font fallback in useractivation test directory. r=intermittent-reviewers,jmaher
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 86 Branch

(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?

Flags: needinfo?(jstutte) → needinfo?(jfkthame)

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.

Flags: needinfo?(jfkthame)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: