Closed Bug 1688858 Opened 4 years ago Closed 3 years ago

Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | application timed out after 370 seconds with no output

Categories

(WebExtensions :: General, defect, P5)

Product:
WebExtensions
Component:
General
Type:
defect

Tracking

(firefox-esr78 unaffected, firefox84 unaffected, firefox85 unaffected, firefox86 unaffected, firefox87 affected)

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
firefox-esr78 --- unaffected
firefox84 --- unaffected
firefox85 --- unaffected
firefox86 --- unaffected
firefox87 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

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

[task 2021-01-26T11:00:38.154Z] 11:00:38     INFO - TEST-START | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html
[task 2021-01-26T11:00:38.297Z] 11:00:38     INFO - GECKO(17199) | 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_async_clipboard.html" line: 0}]
[task 2021-01-26T11:00:38.762Z] 11:00:38     INFO - GECKO(17199) | Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://example.com” on “http://mochi.test:8888”."]
[task 2021-01-26T11:00:39.020Z] 11:00:39     INFO - GECKO(17199) | Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://example.com” on “http://mochi.test:8888”."]
[task 2021-01-26T11:00:39.258Z] 11:00:39     INFO - GECKO(17199) | Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://example.com” on “http://mochi.test:8888”."]
[task 2021-01-26T11:00:39.637Z] 11:00:39     INFO - GECKO(17199) | Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://example.com” on “http://mochi.test:8888”."]
[task 2021-01-26T11:00:39.876Z] 11:00:39     INFO - GECKO(17199) | Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://example.com” on “http://mochi.test:8888”."]
[task 2021-01-26T11:00:40.241Z] 11:00:40     INFO - GECKO(17199) | Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://example.com” on “http://mochi.test:8888”."]
[task 2021-01-26T11:00:40.607Z] 11:00:40     INFO - GECKO(17199) | Console message: [JavaScript Warning: "Storage access automatically granted for origin “https://example.com” on “http://mochi.test:8888”."]
[task 2021-01-26T11:00:40.732Z] 11:00:40     INFO - GECKO(17199) | [CodeCoverage] Requested flush for 17199.
[task 2021-01-26T11:00:40.995Z] 11:00:40     INFO - GECKO(17199) | [CodeCoverage] flush completed.
[task 2021-01-26T11:00:41.889Z] 11:00:41     INFO - GECKO(17199) | [CodeCoverage] JS flush completed.
[task 2021-01-26T11:00:41.889Z] 11:00:41     INFO - GECKO(17199) | [CodeCoverage] Requested flush for 17341.
[task 2021-01-26T11:00:41.889Z] 11:00:41     INFO - GECKO(17199) | [CodeCoverage] Requested flush for 17264.
[task 2021-01-26T11:00:41.889Z] 11:00:41     INFO - GECKO(17199) | [CodeCoverage] Requested flush for 17376.
[task 2021-01-26T11:00:41.889Z] 11:00:41     INFO - GECKO(17199) | [CodeCoverage] Requested flush for 17257.
[task 2021-01-26T11:00:42.154Z] 11:00:42     INFO - GECKO(17199) | [CodeCoverage] flush completed.
[task 2021-01-26T11:00:42.270Z] 11:00:42     INFO - GECKO(17199) | [CodeCoverage] JS flush completed.
[task 2021-01-26T11:00:42.528Z] 11:00:42     INFO - GECKO(17199) | [CodeCoverage] flush completed.
[task 2021-01-26T11:00:42.596Z] 11:00:42     INFO - GECKO(17199) | [CodeCoverage] JS flush completed.
[task 2021-01-26T11:00:42.865Z] 11:00:42     INFO - GECKO(17199) | [CodeCoverage] flush completed.
[task 2021-01-26T11:00:42.885Z] 11:00:42     INFO - GECKO(17199) | [CodeCoverage] JS flush completed.
[task 2021-01-26T11:00:43.148Z] 11:00:43     INFO - GECKO(17199) | [CodeCoverage] flush completed.
[task 2021-01-26T11:00:43.249Z] 11:00:43     INFO - GECKO(17199) | [CodeCoverage] JS flush completed.
[task 2021-01-26T11:00:43.249Z] 11:00:43     INFO - GECKO(17199) | JavaScript error: resource://testing-common/PerTestCoverageUtils.jsm, line 76: NS_ERROR_FILE_DIR_NOT_EMPTY: Component returned failure code: 0x80520014 (NS_ERROR_FILE_DIR_NOT_EMPTY) [nsIFile.moveTo]
[task 2021-01-26T11:06:53.252Z] 11:06:53     INFO - Buffered messages logged at 11:00:38
[task 2021-01-26T11:06:53.252Z] 11:06:53     INFO - add_task | Entering test setup
[task 2021-01-26T11:06:53.252Z] 11:06:53     INFO - add_task | Leaving test setup
[task 2021-01-26T11:06:53.256Z] 11:06:53     INFO - add_task | Entering test test_background_async_clipboard_no_permissions
[task 2021-01-26T11:06:53.257Z] 11:06:53     INFO - Extension loaded
[task 2021-01-26T11:06:53.257Z] 11:06:53     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | Promise rejected, expecting rejection to match null, got undefined: Read should be denied without permission 
[task 2021-01-26T11:06:53.257Z] 11:06:53     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | Promise rejected, expecting rejection to match null, got "Clipboard write was blocked due to lack of user activation.": Write should be denied without permission 
[task 2021-01-26T11:06:53.257Z] 11:06:53     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | Promise rejected, expecting rejection to match null, got "Clipboard write was blocked due to lack of user activation.": WriteText should be denied without permission 
[task 2021-01-26T11:06:53.257Z] 11:06:53     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | Promise rejected, expecting rejection to match null, got undefined: ReadText should be denied without permission 
<...>
[task 2021-01-26T11:06:53.263Z] 11:06:53     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | ReadText successfully read correct thing from an empty clipboard 
[task 2021-01-26T11:06:53.263Z] 11:06:53     INFO - add_task | Leaving test test_contentscript_clipboard_nocontents_readtext
[task 2021-01-26T11:06:53.263Z] 11:06:53     INFO - add_task | Entering test test_contentscript_clipboard_nocontents_read
[task 2021-01-26T11:06:53.263Z] 11:06:53     INFO - Initializing clipboard with "waitForClipboard-known-value-0.15239319728682443"...
[task 2021-01-26T11:06:53.264Z] 11:06:53     INFO - Succeeded initializing clipboard, start requested things...
[task 2021-01-26T11:06:53.264Z] 11:06:53     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | Clipboard has the given value: '' 
[task 2021-01-26T11:06:53.264Z] 11:06:53     INFO - Extension loaded
[task 2021-01-26T11:06:53.264Z] 11:06:53     INFO - TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | Read promise successfully resolved 
[task 2021-01-26T11:06:53.264Z] 11:06:53     INFO - add_task | Leaving test test_contentscript_clipboard_nocontents_read
[task 2021-01-26T11:06:53.264Z] 11:06:53     INFO - Buffered messages finished
[task 2021-01-26T11:06:53.265Z] 11:06:53    ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | application timed out after 370 seconds with no output
[task 2021-01-26T11:06:53.265Z] 11:06:53    ERROR - Force-terminating active process(es).
[task 2021-01-26T11:06:53.265Z] 11:06:53     INFO - Determining child pids from psutil...
[task 2021-01-26T11:06:53.273Z] 11:06:53     INFO - [17341, 17376, 17257, 17264]
[task 2021-01-26T11:06:53.273Z] 11:06:53     INFO - ==> process 17199 launched child process 17221
[task 2021-01-26T11:06:53.273Z] 11:06:53     INFO - ==> process 17199 launched child process 17257
[task 2021-01-26T11:06:53.273Z] 11:06:53     INFO - ==> process 17199 launched child process 17264
[task 2021-01-26T11:06:53.273Z] 11:06:53     INFO - ==> process 17199 launched child process 17341
[task 2021-01-26T11:06:53.274Z] 11:06:53     INFO - ==> process 17199 launched child process 17376
[task 2021-01-26T11:06:53.275Z] 11:06:53     INFO - Found child pids: set([17376, 17257, 17341, 17264, 17221])
[task 2021-01-26T11:06:53.275Z] 11:06:53     INFO - Failed to get child procs
[task 2021-01-26T11:06:53.275Z] 11:06:53     INFO - Killing process: 17376```

2 failures for the test coverage config, can you take a look?

status-firefox84: --- → unaffected
status-firefox85: --- → unaffected
status-firefox86: --- → unaffected
status-firefox87: --- → affected
status-firefox-esr78: --- → unaffected
Flags: needinfo?(evilpies)
Keywords: regression
Regressed by: 1619947
Has Regression Range: --- → yes

Sadly that log isn't very useful, but I think I have a lead. I've ran the test in verify mode and found an (pre-existing) issue.

Flags: needinfo?(evilpies)
Assignee: nobody → evilpies

And now it doesn't reproduce anymore. Fun.

Maybe this was just a fluke. Closing for now.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=337257121&repo=mozilla-central&lineNumber=10579

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Assignee: evilpies → nobody

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=371572289&repo=mozilla-central

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 4 years ago → 3 years ago
Resolution: --- → INCOMPLETE

This is failing on tier 2: https://treeherder.mozilla.org/logviewer?job_id=379426993&repo=mozilla-central&lineNumber=15900

Summary: Intermittent TC TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | application timed out after 370 seconds with no output → Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/mochitest/test_ext_async_clipboard.html | application timed out after 370 seconds with no output

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=379426993&repo=mozilla-central

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.