1726085 - Intermittent toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | Timed out while polling clipboard for initialized data, got: dummy string to copy

Status: NEW

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-08-17T02:48:53.697Z] 02:48:53     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_canvas_resistFingerprinting.html | took 96ms
[task 2021-08-17T02:48:53.704Z] 02:48:53     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html
[task 2021-08-17T02:48:53.716Z] 02:48:53     INFO - GECKO(2936) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_clipboard.html" line: 0}]
[task 2021-08-17T02:48:53.734Z] 02:48:53     INFO - GECKO(2936) | Console message: [JavaScript Warning: "document.execCommand(cut/copy) was denied because it was not called from inside a short running user-generated event handler." {file: "moz-extension://6d169405-2344-4c65-a886-bffaa4328364/%7B154eee07-456b-40b5-95c9-51c488c3b54a%7D.js" line: 9}]
[task 2021-08-17T02:48:53.920Z] 02:48:53     INFO - GECKO(2936) | Console message: [JavaScript Warning: "document.execCommand(cut/copy) was denied because it was not called from inside a short running user-generated event handler." {file: "moz-extension://a4723fed-e04f-469b-9d80-760f50ac88d1/shared.js" line: 9}]
[task 2021-08-17T02:49:42.453Z] 02:49:42     INFO - TEST-INFO | started process screenshot
[task 2021-08-17T02:49:42.522Z] 02:49:42     INFO - TEST-INFO | screenshot: exit 0
[task 2021-08-17T02:49:42.533Z] 02:49:42     INFO - Buffered messages logged at 02:48:53
[task 2021-08-17T02:49:42.533Z] 02:49:42     INFO - add_task | Entering test test_background_clipboard_permissions
[task 2021-08-17T02:49:42.534Z] 02:49:42     INFO - Extension loaded
[task 2021-08-17T02:49:42.534Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | copy should be denied without permission - Expected: false, Actual: false 
[task 2021-08-17T02:49:42.535Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | paste should be denied without permission - Expected: false, Actual: false 
[task 2021-08-17T02:49:42.535Z] 02:49:42     INFO - add_task | Leaving test test_background_clipboard_permissions
[task 2021-08-17T02:49:42.536Z] 02:49:42     INFO - add_task | Entering test test_background_clipboard_copy
[task 2021-08-17T02:49:42.536Z] 02:49:42     INFO - Extension loaded
[task 2021-08-17T02:49:42.537Z] 02:49:42     INFO - Initializing clipboard with "waitForClipboard-known-value-0.1687713838712479"...
[task 2021-08-17T02:49:42.538Z] 02:49:42     INFO - Succeeded initializing clipboard, start requested things...
[task 2021-08-17T02:49:42.539Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | copy should be allowed with permission - Expected: true, Actual: true 
[task 2021-08-17T02:49:42.540Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | Clipboard has the given value: 'dummy string to copy' 
[task 2021-08-17T02:49:42.540Z] 02:49:42     INFO - add_task | Leaving test test_background_clipboard_copy
[task 2021-08-17T02:49:42.541Z] 02:49:42     INFO - add_task | Entering test test_contentscript_clipboard_permissions
[task 2021-08-17T02:49:42.541Z] 02:49:42     INFO - Extension loaded
[task 2021-08-17T02:49:42.542Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | copy should be denied without permission - Expected: false, Actual: false 
[task 2021-08-17T02:49:42.542Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | paste should be denied without permission - Expected: false, Actual: false 
[task 2021-08-17T02:49:42.543Z] 02:49:42     INFO - add_task | Leaving test test_contentscript_clipboard_permissions
[task 2021-08-17T02:49:42.543Z] 02:49:42     INFO - add_task | Entering test test_contentscript_clipboard_copy
[task 2021-08-17T02:49:42.544Z] 02:49:42     INFO - Extension loaded
[task 2021-08-17T02:49:42.544Z] 02:49:42     INFO - Initializing clipboard with "waitForClipboard-known-value-0.2909440704452163"...
[task 2021-08-17T02:49:42.545Z] 02:49:42     INFO - Buffered messages finished
[task 2021-08-17T02:49:42.546Z] 02:49:42     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | Timed out while polling clipboard for initialized data, got: dummy string to copy 
[task 2021-08-17T02:49:42.546Z] 02:49:42     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-08-17T02:49:42.546Z] 02:49:42     INFO -     putAndVerify@SimpleTest/SimpleTest.js:1215:16
[task 2021-08-17T02:49:42.546Z] 02:49:42     INFO - add_task | Leaving test test_contentscript_clipboard_copy
[task 2021-08-17T02:49:42.547Z] 02:49:42     INFO - add_task | Entering test test_contentscript_clipboard_paste
[task 2021-08-17T02:49:42.547Z] 02:49:42     INFO - Extension loaded
[task 2021-08-17T02:49:42.548Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | the correct string was pasted 
[task 2021-08-17T02:49:42.548Z] 02:49:42     INFO - add_task | Leaving test test_contentscript_clipboard_paste
[task 2021-08-17T02:49:42.549Z] 02:49:42     INFO - add_task | Entering test test_background_clipboard_paste
[task 2021-08-17T02:49:42.549Z] 02:49:42     INFO - Extension loaded
[task 2021-08-17T02:49:42.561Z] 02:49:42     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | the correct string was pasted 
[task 2021-08-17T02:49:42.581Z] 02:49:42     INFO - add_task | Leaving test test_background_clipboard_paste
[task 2021-08-17T02:49:42.590Z] 02:49:42     INFO - GECKO(2936) | MEMORY STAT | vsize 2103754MB | vsizeMaxContiguous 67378173MB | residentFast 70MB | heapAllocated 9MB
[task 2021-08-17T02:49:42.594Z] 02:49:42     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_clipboard.html | took 48889ms
[task 2021-08-17T02:49:42.607Z] 02:49:42     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_clipboard_image.html
[task 2021-08-17T02:49:42.622Z] 02:49:42     INFO - GECKO(2936) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_clipboard_image.html" line: 0}]
[task 2021-08-17T02:49:42.785Z] 02:49:42     INFO - GECKO(2936) | MEMORY STAT | vsize 2103753MB | vsizeMaxContiguous 67378173MB | residentFast 70MB | heapAllocated 9MB
[task 2021-08-17T02:49:42.790Z] 02:49:42     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_clipboard_image.html | took 181ms
[task 2021-08-17T02:49:42.802Z] 02:49:42     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_contentscript_about_blank.html
[task 2021-08-17T02:49:42.970Z] 02:49:42     INFO - GECKO(2936) | MEMORY STAT | vsize 2103754MB | vsizeMaxContiguous 67378173MB | residentFast 73MB | heapAllocated 13MB
[task 2021-08-17T02:49:42.980Z] 02:49:42     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_contentscript_about_blank.html | took 176ms
[task 2021-08-17T02:49:42.993Z] 02:49:42     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_contentscript_activeTab.html
[task 2021-08-17T02:49:42.999Z] 02:49:42     INFO - GECKO(2936) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_contentscript_activeTab.html" line: 0}]
[task 2021-08-17T02:49:43.787Z] 02:49:43     INFO - GECKO(2936) | MEMORY STAT | vsize 2103754MB | vsizeMaxContiguous 67378173MB | residentFast 72MB | heapAllocated 10MB
[task 2021-08-17T02:49:43.794Z] 02:49:43     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_contentscript_activeTab.html | took 797ms
[task 2021-08-17T02:49:43.801Z] 02:49:43     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_contentscript_cache.html
[task 2021-08-17T02:49:43.828Z] 02:49:43     INFO - GECKO(2936) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_contentscript_cache.html" line: 0}]
[task 2021-08-17T02:49:46.962Z] 02:49:46     INFO - GECKO(2936) | MEMORY STAT | vsize 2103752MB | vsizeMaxContiguous 67378173MB | residentFast 67MB | heapAllocated 7MB
[task 2021-08-17T02:49:46.975Z] 02:49:46     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_contentscript_cache.html | took 3175ms
[task 2021-08-17T02:49:46.987Z] 02:49:46     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_contentscript_canvas.html
[task 2021-08-17T02:49:47.001Z] 02:49:47     INFO - GECKO(2936) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_contentscript_canvas.html" line: 0}]
[task 2021-08-17T02:49:47.047Z] 02:49:47     INFO - GECKO(2936) | Console message: [JavaScript Warning: "Storage access automatically granted for origin https://example.org on http://mochi.test:8888."]
[task 2021-08-17T02:49:47.079Z] 02:49:47     INFO - GECKO(2936) | Console message: [JavaScript Warning: "Use of drawWindow method from CanvasRenderingContext2D is deprecated. Use tabs.captureTab extensions API instead https://developer.mozilla.org/docs/Mozilla/Add-ons/WebExtensions/API/tabs/captureTab" {file: "moz-extension://0dabb7fc-f1af-4c96-aff8-d0a07d56bb21/content_script.js" line: 5}]
[task 2021-08-17T02:49:47.194Z] 02:49:47     INFO - GECKO(2936) | Console message: [JavaScript Warning: "Storage access automatically granted for origin https://example.org on http://mochi.test:8888."]
[task 2021-08-17T02:49:47.233Z] 02:49:47     INFO - GECKO(2936) | MEMORY STAT | vsize 2103752MB | vsizeMaxContiguous 67378173MB | residentFast 72MB | heapAllocated 11MB
[task 2021-08-17T02:49:47.249Z] 02:49:47     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_contentscript_canvas.html | took 261ms
[task 2021-08-17T02:49:47.255Z] 02:49:47     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_contentscript_devtools_metadata.html
[task 2021-08-17T02:49:47.268Z] 02:49:47     INFO - GECKO(2936) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_contentscript_devtools_metadata.html" line: 0}]
[task 2021-08-17T02:49:47.335Z] 02:49:47     INFO - GECKO(2936) | MEMORY STAT | vsize 2103753MB | vsizeMaxContiguous 67378173MB | residentFast 73MB | heapAllocated 12MB
[task 2021-08-17T02:49:47.343Z] 02:49:47     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_contentscript_devtools_metadata.html | took 90ms
[task 2021-08-17T02:49:47.359Z] 02:49:47     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html
[task 2021-08-17T02:49:47.366Z] 02:49:47     INFO - GECKO(2936) | Console message: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html" line: 0}]
[task 2021-08-17T02:49:47.408Z] 02:49:47     INFO - GECKO(2936) | Console message: [JavaScript Warning: "Storage access automatically granted for origin http://example.org on http://mochi.test:8888."]
[task 2021-08-17T02:49:47.448Z] 02:49:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-08-17T02:49:47.449Z] 02:49:47     INFO - Buffered messages logged at 02:49:47
[task 2021-08-17T02:49:47.450Z] 02:49:47     INFO - add_task | Entering test test_content_script_cross_origin_frame
[task 2021-08-17T02:49:47.451Z] 02:49:47     INFO - Load first extension
[task 2021-08-17T02:49:47.451Z] 02:49:47     INFO - Extension loaded
[task 2021-08-17T02:49:47.452Z] 02:49:47     INFO - Load a page, test content scripts in new frame with extension loaded
[task 2021-08-17T02:49:47.453Z] 02:49:47     INFO - Buffered messages finished
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | CS can access page DOM - Expected: 
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO - 
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO - Sample text
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO - 
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO - 
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO - 
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO - , Actual: Sample text 
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-08-17T02:49:47.454Z] 02:49:47     INFO -     testHandler@SimpleTest/ExtensionTestUtils.js:68:18
[task 2021-08-17T02:49:47.455Z] 02:49:47     INFO -     testResult@SimpleTest/ExtensionTestUtils.js:82:18
[task 2021-08-17T02:49:47.455Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | undefined - Expected: 1.0, Actual: 1.0 
[task 2021-08-17T02:49:47.456Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | undefined - Expected: Generated extension, Actual: Generated extension 
[task 2021-08-17T02:49:47.457Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | sender frameId is ok 
[task 2021-08-17T02:49:47.457Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | url is ok 
[task 2021-08-17T02:49:47.459Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | CS runs in a shared Sandbox - Expected: 357, Actual: 357 
[task 2021-08-17T02:49:47.461Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | Promise rejected, expecting rejection to match /does is not defined/, got "does is not defined": Got the expected rejection from tabs.executeScript 
[task 2021-08-17T02:49:47.463Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | Promise rejected, expecting rejection to match /Script .* result is non-structured-clonable data/, got "Script '<anonymous code>' result is non-structured-clonable data": Got the expected rejection from tabs.executeScript 
[task 2021-08-17T02:49:47.464Z] 02:49:47     INFO - content script received tabs.sendMessage
[task 2021-08-17T02:49:47.466Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | Got correct response - Expected: 21, Actual: 21 
[task 2021-08-17T02:49:47.466Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | undefined assertion name 
[task 2021-08-17T02:49:47.468Z] 02:49:47     INFO - Load second extension, test content scripts in existing frame
[task 2021-08-17T02:49:47.469Z] 02:49:47     INFO - Extension loaded
[task 2021-08-17T02:49:47.481Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | CS can access page DOM - Expected: Sample text, Actual: Sample text 
[task 2021-08-17T02:49:47.483Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | undefined - Expected: 1.0, Actual: 1.0 
[task 2021-08-17T02:49:47.484Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | undefined - Expected: Generated extension, Actual: Generated extension 
[task 2021-08-17T02:49:47.492Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | sender frameId is ok 
[task 2021-08-17T02:49:47.493Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | url is ok 
[task 2021-08-17T02:49:47.495Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | CS runs in a shared Sandbox - Expected: 357, Actual: 357 
[task 2021-08-17T02:49:47.497Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | Promise rejected, expecting rejection to match /does is not defined/, got "does is not defined": Got the expected rejection from tabs.executeScript 
[task 2021-08-17T02:49:47.498Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | Promise rejected, expecting rejection to match /Script .* result is non-structured-clonable data/, got "Script '<anonymous code>' result is non-structured-clonable data": Got the expected rejection from tabs.executeScript 
[task 2021-08-17T02:49:47.499Z] 02:49:47     INFO - content script received tabs.sendMessage
[task 2021-08-17T02:49:47.500Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | Got correct response - Expected: 21, Actual: 21 
[task 2021-08-17T02:49:47.500Z] 02:49:47     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | undefined assertion name 
[task 2021-08-17T02:49:47.514Z] 02:49:47     INFO - add_task | Leaving test test_content_script_cross_origin_frame
[task 2021-08-17T02:49:47.519Z] 02:49:47     INFO - GECKO(2936) | MEMORY STAT | vsize 2103752MB | vsizeMaxContiguous 67378173MB | residentFast 73MB | heapAllocated 12MB
[task 2021-08-17T02:49:47.525Z] 02:49:47     INFO - TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_contentscript_fission_frame.html | took 161ms
[task 2021-08-17T02:49:47.532Z] 02:49:47     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_contentscript_incognito.html

Comment 1

[Intermittent Failures Robot]

1 failures in 2899 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1

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

Comment 2

[Mirko Brodesser (:mbrodesser-Igalia)]

0 failures last week. Presumably this was fixed with bug 1726269.