Closed Bug 1651652 Opened 5 years ago Closed 4 years ago

Intermittent browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js | Test timed out -

Categories

(WebExtensions :: Untriaged, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


[task 2020-07-09T10:22:36.665Z] 10:22:36 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js
[task 2020-07-09T10:22:36.711Z] 10:22:36 INFO - GECKO(1642) | [Parent 1642, Main Thread] WARNING: Need BrowserChild to get the nativeWindow from!: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp, line 1086
[task 2020-07-09T10:22:36.711Z] 10:22:36 INFO - GECKO(1642) | [Child 1644: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x12072bc00 == 22 [pid = 1644] [id = {6599924c-542b-0b40-8060-ffa9d03618b1}]
[task 2020-07-09T10:22:36.711Z] 10:22:36 INFO - GECKO(1642) | [Child 1644: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 100 (0x14a99f650) [pid = 1644] [serial = 1625] [outer = 0x0]
[task 2020-07-09T10:22:36.711Z] 10:22:36 INFO - GECKO(1642) | [Child 1644: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 101 (0x147d4b000) [pid = 1644] [serial = 1626] [outer = 0x14a99f650]
[task 2020-07-09T10:22:36.730Z] 10:22:36 INFO - GECKO(1642) | [Child 1644, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp, line 2633
[task 2020-07-09T10:22:36.739Z] 10:22:36 INFO - GECKO(1642) | [Child 1644: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 102 (0x147d54800) [pid = 1644] [serial = 1627] [outer = 0x14a99f650]
[task 2020-07-09T10:22:36.813Z] 10:22:36 INFO - GECKO(1642) | [Child 1645: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x14024a400 == 2 [pid = 1645] [id = {0afc66a9-7d70-c248-9956-79527dabb94d}]

[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js | port should be disconnected without errors - Expected: null, Actual: null -
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - Console message: [JavaScript Error: "TypeError: can't access property "permanentKey", browser is undefined" {file: "resource:///modules/ContentCrashHandlers.jsm" line: 50}]
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - get@resource:///modules/ContentCrashHandlers.jsm:50:9
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - onAboutTabCrashedUnload@resource:///modules/ContentCrashHandlers.jsm:556:35
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - removeCrashedPage@resource:///actors/AboutTabCrashedParent.jsm:75:21
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - didDestroy@resource:///actors/AboutTabCrashedParent.jsm:22:10
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO -
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - Buffered messages logged at 10:22:39
[task 2020-07-09T10:24:06.901Z] 10:24:06 INFO - Leaving test bound connect_from_tab_to_bg_and_crash_tab
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - Entering test bound connect_from_bg_to_tab_and_crash_tab
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - Extension loaded
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - Console message: Warning: attempting to write 21412 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js | expected message - Expected: contentscript_ready, Actual: contentscript_ready -
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - TEST-PASS | browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js | expected port - Expected: bg_to_tab, Actual: bg_to_tab -
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - Buffered messages finished
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js | Test timed out -
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js | Extension left running at test shutdown -
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - Stack trace:
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - chrome://mochikit/content/browser-test.js:test_ok:1299
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:117
[task 2020-07-09T10:24:06.902Z] 10:24:06 INFO - chrome://mochikit/content/browser-test.js:nextTest:550
[task 2020-07-09T10:24:06.903Z] 10:24:06 INFO - GECKO(1642) | [Child 1644: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x140197c00 == 4 [pid = 1644] [id = {ca55f2a2-c5bf-e245-9922-6096b9221cba}] [url = moz-extension://e70791ab-f4ed-8249-b142-04a30d2e4ac4/_generated_background_page.html]
[task 2020-07-09T10:24:14.880Z] 10:24:14 INFO - Console message: [JavaScript Error: "Timeout while waiting for extension child to shutdown: "Generated extension" (ID: {1688fade-3368-a748-b433-e2c14f08a74b}, moz-extension://e70791ab-f4ed-8249-b142-04a30d2e4ac4/)" {file: "resource://gre/modules/Extension.jsm" line: 2666}]
[task 2020-07-09T10:24:14.880Z] 10:24:14 INFO - shutdown@resource://gre/modules/Extension.jsm:2666:10
[task 2020-07-09T10:24:14.880Z] 10:24:14 INFO -
[task 2020-07-09T10:24:15.364Z] 10:24:15 INFO - GECKO(1642) | [Child 1644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (0x107519b70) [pid = 1644] [serial = 1628] [outer = 0x0] [url = moz-extension://e70791ab-f4ed-8249-b142-04a30d2e4ac4/_generated_background_page.html]
[task 2020-07-09T10:24:19.497Z] 10:24:19 INFO - GECKO(1642) | [Child 1644: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (0x147d53800) [pid = 1644] [serial = 1630] [outer = 0x0] [url = moz-extension://e70791ab-f4ed-8249-b142-04a30d2e4ac4/_generated_background_page.html]
[task 2020-07-09T10:30:29.498Z] 10:30:29 INFO - Buffered messages finished
[task 2020-07-09T10:30:29.498Z] 10:30:29 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_port_disconnect_on_crash.js | application timed out after 370 seconds with no output
[task 2020-07-09T10:30:29.498Z] 10:30:29 ERROR - Force-terminating active process(es).
[task 2020-07-09T10:30:29.498Z] 10:30:29 INFO - Determining child pids from psutil...
[task 2020-07-09T10:30:29.499Z] 10:30:29 INFO - [1647, 1644, 1646, 1648, 1652, 1666]
[task 2020-07-09T10:30:29.499Z] 10:30:29 INFO - ==> process 1642 launched child process 1644
[task 2020-07-09T10:30:29.499Z] 10:30:29 INFO - ==> process 1642 launched child process 1645
[task 2020-07-09T10:30:29.499Z] 10:30:29 INFO - ==> process 1642 launched child process 1646
[task 2020-07-09T10:30:29.499Z] 10:30:29 INFO - ==> process 1642 launched child process 1647
[task 2020-07-09T10:30:29.500Z] 10:30:29 INFO - ==> process 1642 launched child process 1648
[task 2020-07-09T10:30:29.500Z] 10:30:29 INFO - ==> process 1642 launched child process 1652
[task 2020-07-09T10:30:29.500Z] 10:30:29 INFO - ==> process 1642 launched child process 1666
[task 2020-07-09T10:30:29.500Z] 10:30:29 INFO - ==> process 1642 launched child process 1701
[task 2020-07-09T10:30:29.501Z] 10:30:29 INFO - Found child pids: set([1666, 1701, 1644, 1645, 1646, 1647, 1648, 1652])
[task 2020-07-09T10:30:29.501Z] 10:30:29 INFO - Failed to get child procs
[task 2020-07-09T10:30:29.501Z] 10:30:29 INFO - Killing process: 1666
[task 2020-07-09T10:30:29.501Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.502Z] 10:30:29 INFO - Killing process: 1701
[task 2020-07-09T10:30:29.502Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.502Z] 10:30:29 INFO - Can't trigger Breakpad, process no longer exists
[task 2020-07-09T10:30:29.502Z] 10:30:29 INFO - Killing process: 1644
[task 2020-07-09T10:30:29.502Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.503Z] 10:30:29 INFO - Killing process: 1645
[task 2020-07-09T10:30:29.503Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.503Z] 10:30:29 INFO - Can't trigger Breakpad, process no longer exists
[task 2020-07-09T10:30:29.503Z] 10:30:29 INFO - Killing process: 1646
[task 2020-07-09T10:30:29.504Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.504Z] 10:30:29 INFO - Killing process: 1647
[task 2020-07-09T10:30:29.504Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.504Z] 10:30:29 INFO - Killing process: 1648
[task 2020-07-09T10:30:29.504Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.505Z] 10:30:29 INFO - Killing process: 1652
[task 2020-07-09T10:30:29.505Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.505Z] 10:30:29 INFO - Killing process: 1642
[task 2020-07-09T10:30:29.505Z] 10:30:29 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-09T10:30:29.682Z] 10:30:29 INFO - psutil found pid 1642 dead
[task 2020-07-09T10:47:09.847Z] 10:47:09 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/Users/cltbld/tasks/task_1594286150/build/venv/bin/python', '-u', '/Users/cltbld/tasks/task_1594286150/build/tests/mochitest/runtests.py', u'browser/components/extensions/test/browser/browser.ini', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--appname=/Users/cltbld/tasks/task_1594286150/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=/Users/cltbld/tasks/task_1594286150/build/symbols', '--certificate-path=tests/certs', '--quiet', '--log-raw=/Users/cltbld/tasks/task_1594286150/build/blobber_upload_dir/mochitest-browser-chrome_raw.log', '--log-errorsummary=/Users/cltbld/tasks/task_1594286150/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/Users/cltbld/tasks/task_1594286150/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime']
[task 2020-07-09T10:47:09.907Z] 10:47:09 ERROR - timed out after 1000 seconds of no output
[task 2020-07-09T10:47:09.907Z] 10:47:09 ERROR - Return code: -15
[task 2020-07-09T10:47:09.908Z] 10:47:09 ERROR - Got 2 unexpected statuses
[task 2020-07-09T10:47:09.908Z] 10:47:09 ERROR - No suite end message was emitted by this harness.
[task 2020-07-09T10:47:09.908Z] 10:47:09 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>125/<em class="testfail">2</em>/0
[task 2020-07-09T10:47:09.908Z] 10:47:09 ERROR - # TBPL FAILURE #
[task 2020-07-09T10:47:09.908Z] 10:47:09 WARNING - setting return code to 2

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