Closed
Bug 1683585
Opened 5 years ago
Closed 5 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | dom/ipc/tests/browser_cancel_content_js.js | application timed out after 370 seconds with no output
Categories
(Core :: DOM: Content Processes, defect, P5)
Core
DOM: Content Processes
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=325080322&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BkcJJHgFTECPpvuZqui6vQ/runs/0/artifacts/public/logs/live_backing.log
INFO - TEST-START | dom/ipc/tests/browser_cancel_content_js.js
[task 2020-12-20T21:39:47.427Z] 21:39:47 INFO - GECKO(2708) | JavaScript warning: http://mochi.test:8888/browser/dom/ipc/tests/file_cancel_content_js.html, line 12: Script terminated by timeout at:
[task 2020-12-20T21:39:47.428Z] 21:39:47 INFO - GECKO(2708) | @http://mochi.test:8888/browser/dom/ipc/tests/file_cancel_content_js.html:12:16
[task 2020-12-20T21:39:48.378Z] 21:39:48 INFO - GECKO(2708) | ###!!! [Child][MessageChannel] Error: (msgtype=0x3A0116,name=PContent::Msg_AccumulateChildKeyedHistograms) Channel closing: too late to send/recv, messages will be lost
[task 2020-12-20T21:39:48.378Z] 21:39:48 INFO - GECKO(2708) | ###!!! [Child][MessageChannel] Error: (msgtype=0x3A011A,name=PContent::Msg_RecordDiscardedData) Channel closing: too late to send/recv, messages will be lost
[task 2020-12-20T21:45:58.382Z] 21:45:58 INFO - Buffered messages logged at 21:39:46
[task 2020-12-20T21:45:58.383Z] 21:45:58 INFO - Entering test bound
[task 2020-12-20T21:45:58.383Z] 21:45:58 INFO - Buffered messages logged at 21:39:47
[task 2020-12-20T21:45:58.384Z] 21:45:58 INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://mochi.test:8888/browser/dom/ipc/tests/file_cancel_content_js.html" line: 0}]
[task 2020-12-20T21:45:58.385Z] 21:45:58 INFO - navigating to http://mochi.test:8888/browser/dom/ipc/tests/ with cancel content JS enabled
[task 2020-12-20T21:45:58.385Z] 21:45:58 INFO - Console message: [JavaScript Warning: "Script terminated by timeout at:
[task 2020-12-20T21:45:58.385Z] 21:45:58 INFO - @http://mochi.test:8888/browser/dom/ipc/tests/file_cancel_content_js.html:12:16
[task 2020-12-20T21:45:58.385Z] 21:45:58 INFO - " {file: "http://mochi.test:8888/browser/dom/ipc/tests/file_cancel_content_js.html" line: 12}]
[task 2020-12-20T21:45:58.385Z] 21:45:58 INFO - Buffered messages finished
[task 2020-12-20T21:45:58.385Z] 21:45:58 ERROR - TEST-UNEXPECTED-TIMEOUT | dom/ipc/tests/browser_cancel_content_js.js | application timed out after 370 seconds with no output
[task 2020-12-20T21:45:58.385Z] 21:45:58 ERROR - Force-terminating active process(es).
[task 2020-12-20T21:45:58.385Z] 21:45:58 INFO - Determining child pids from psutil...
[task 2020-12-20T21:45:58.388Z] 21:45:58 INFO - [2781, 2863, 2806, 2928, 2895, 3018]
[task 2020-12-20T21:45:58.388Z] 21:45:58 INFO - ==> process 2708 launched child process 2723
[task 2020-12-20T21:45:58.388Z] 21:45:58 INFO - ==> process 2708 launched child process 2781
[task 2020-12-20T21:45:58.389Z] 21:45:58 INFO - ==> process 2708 launched child process 2806
[task 2020-12-20T21:45:58.390Z] 21:45:58 INFO - ==> process 2708 launched child process 2863
[task 2020-12-20T21:45:58.390Z] 21:45:58 INFO - ==> process 2708 launched child process 2895
[task 2020-12-20T21:45:58.390Z] 21:45:58 INFO - ==> process 2708 launched child process 2928
[task 2020-12-20T21:45:58.390Z] 21:45:58 INFO - ==> process 2708 launched child process 2965
[task 2020-12-20T21:45:58.391Z] 21:45:58 INFO - ==> process 2708 launched child process 2969
[task 2020-12-20T21:45:58.391Z] 21:45:58 INFO - Found child pids: set([2723, 3018, 2895, 2928, 2965, 2806, 2969, 2863, 2781])
[task 2020-12-20T21:45:58.391Z] 21:45:58 INFO - Failed to get child procs
[task 2020-12-20T21:45:58.391Z] 21:45:58 INFO - Killing process: 2723
[task 2020-12-20T21:45:58.394Z] 21:45:58 INFO - TEST-INFO | started process screentopng
[task 2020-12-20T21:45:58.631Z] 21:45:58 INFO - TEST-INFO | screentopng: exit 0
[task 2020-12-20T21:45:58.632Z] 21:45:58 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:45:58.632Z] 21:45:58 INFO - Error: Failed to kill process 2723: psutil.NoSuchProcess no process found with pid 2723
[task 2020-12-20T21:45:58.632Z] 21:45:58 INFO - Killing process: 3018
[task 2020-12-20T21:45:58.632Z] 21:45:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:45:58.632Z] 21:45:58 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:46:28.680Z] 21:46:28 INFO - failed to kill pid 3018 after 30s
[task 2020-12-20T21:46:28.680Z] 21:46:28 INFO - Killing process: 2895
[task 2020-12-20T21:46:28.681Z] 21:46:28 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:46:28.681Z] 21:46:28 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:46:58.723Z] 21:46:58 INFO - failed to kill pid 2895 after 30s
[task 2020-12-20T21:46:58.723Z] 21:46:58 INFO - Killing process: 2928
[task 2020-12-20T21:46:58.724Z] 21:46:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:46:58.724Z] 21:46:58 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:47:28.767Z] 21:47:28 INFO - failed to kill pid 2928 after 30s
[task 2020-12-20T21:47:28.767Z] 21:47:28 INFO - Killing process: 2965
[task 2020-12-20T21:47:28.767Z] 21:47:28 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:47:28.767Z] 21:47:28 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:47:28.768Z] 21:47:28 INFO - Error: Failed to kill process 2965: psutil.NoSuchProcess no process found with pid 2965
[task 2020-12-20T21:47:28.768Z] 21:47:28 INFO - Killing process: 2806
[task 2020-12-20T21:47:28.768Z] 21:47:28 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:47:28.768Z] 21:47:28 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:47:58.811Z] 21:47:58 INFO - failed to kill pid 2806 after 30s
[task 2020-12-20T21:47:58.811Z] 21:47:58 INFO - Killing process: 2969
[task 2020-12-20T21:47:58.811Z] 21:47:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:47:58.812Z] 21:47:58 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:47:58.812Z] 21:47:58 INFO - Error: Failed to kill process 2969: psutil.NoSuchProcess no process found with pid 2969
[task 2020-12-20T21:47:58.812Z] 21:47:58 INFO - Killing process: 2863
[task 2020-12-20T21:47:58.812Z] 21:47:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:47:58.813Z] 21:47:58 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:48:28.860Z] 21:48:28 INFO - failed to kill pid 2863 after 30s
[task 2020-12-20T21:48:28.860Z] 21:48:28 INFO - Killing process: 2781
[task 2020-12-20T21:48:28.860Z] 21:48:28 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:48:28.860Z] 21:48:28 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:48:58.907Z] 21:48:58 INFO - failed to kill pid 2781 after 30s
[task 2020-12-20T21:48:58.907Z] 21:48:58 INFO - Killing process: 2708
[task 2020-12-20T21:48:58.907Z] 21:48:58 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-12-20T21:48:58.908Z] 21:48:58 INFO - Can't trigger Breakpad, just killing process
[task 2020-12-20T21:49:28.922Z] 21:49:28 INFO - failed to kill pid 2863 after 30s
[task 2020-12-20T21:49:28.922Z] 21:49:28 INFO - failed to kill pid 2806 after 30s
[task 2020-12-20T21:49:28.922Z] 21:49:28 INFO - failed to kill pid 2928 after 30s
[task 2020-12-20T21:49:28.923Z] 21:49:28 INFO - failed to kill pid 2895 after 30s
[task 2020-12-20T21:49:28.923Z] 21:49:28 INFO - failed to kill pid 3018 after 30s
[task 2020-12-20T21:49:28.923Z] 21:49:28 INFO - failed to kill pid 2708 after 30s
[task 2020-12-20T21:49:28.923Z] 21:49:28 INFO - failed to kill pid 2781 after 30s
[task 2020-12-20T21:49:58.961Z] 21:49:58 WARNING - failed to kill pid 2708 after 30s
[task 2020-12-20T22:06:38.984Z] 22:06:38 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/worker/workspace/build/venv/bin/python', '-u', '/builds/worker/workspace/build/tests/mochitest/runtests.py', u'browser/base/content/test/about/browser.ini', u'browser/base/content/test/fullscreen/browser.ini', u'browser/base/content/test/sync/browser.ini', u'dom/ipc/tests/browser.ini', u'extensions/permissions/test/browser.ini', u'services/fxaccounts/tests/browser/browser.ini', u'toolkit/components/extensions/test/browser/browser.ini', u'toolkit/components/tooltiptext/tests/browser.ini', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--appname=/builds/worker/workspace/build/application/firefox/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', u'--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Jh6mjgY5RJqrwryWzUaSlw/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--setpref=webgl.force-enabled=true', '--quiet', '--log-raw=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--flavor=browser', '--chunk-by-runtime']
[task 2020-12-20T22:06:39.029Z] 22:06:39 ERROR - timed out after 1000 seconds of no output
[task 2020-12-20T22:06:39.030Z] 22:06:39 ERROR - Return code: -15
[task 2020-12-20T22:06:39.034Z] 22:06:39 ERROR - No suite end message was emitted by this harness.
[task 2020-12-20T22:06:39.034Z] 22:06:39 INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>46/0/0
[task 2020-12-20T22:06:39.035Z] 22:06:39 ERROR - # TBPL FAILURE #
[task 2020-12-20T22:06:39.035Z] 22:06:39 WARNING - setting return code to 2
[task 2020-12-20T22:06:39.035Z] 22:06:39 ERROR - The mochitest suite: mochitest-browser-chrome ran with return status: FAILURE
[task 2020-12-20T22:06:39.035Z] 22:06:39 INFO - Running post-action listener: _package_coverage_data
[task 2020-12-20T22:06:39.035Z] 22:06:39 INFO - Running post-action listener: _resource_record_post_action
[task 2020-12-20T22:06:39.035Z] 22:06:39 INFO - Running post-action listener: process_java_coverage_data
[task 2020-12-20T22:06:39.036Z] 22:06:39 INFO - [mozharness: 2020-12-20 22:06:39.035101Z] Finished run-tests step (success)
[task 2020-12-20T22:06:39.036Z] 22:06:39 INFO - Running post-run listener: _resource_record_post_run
[task 2020-12-20T22:06:39.247Z] 22:06:39 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 26.089563454198405}, {"name": "io_write_bytes", "value": 2386018304}, {"name": "io.read_bytes", "value": 704712704}, {"name": "io_write_time", "value": 275744}, {"name": "io_read_time", "value": 24424}], "extraOptions": ["e10s", "taskcluster-c5.xlarge"], "name": "mochitest.mochitest-browser-chrome.overall"}, {"subtests": [{"name": "time", "value": 0.018682003021240234}], "name": "mochitest.mochitest-browser-chrome.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 31.930579900741577}, {"name": "cpu_percent", "value": 25.175}], "name": "mochitest.mochitest-browser-chrome.install"}, {"subtests": [{"name": "time", "value": 0.0002338886260986328}], "name": "mochitest.mochitest-browser-chrome.stage-files"}, {"subtests": [{"name": "time", "value": 2066.6224188804626}, {"name": "cpu_percent", "value": 26.102676841085202}], "name": "mochitest.mochitest-browser-chrome.run-tests"}]}
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - Total resource usage - Wall time: 2098s; CPU: 26.0%; Read bytes: 704712704; Write bytes: 2386018304; Read time: 24424; Write time: 275744
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - TinderboxPrint: CPU usage<br/>26.1%
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - TinderboxPrint: I/O read bytes / time<br/>704,712,704 / 24,424
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - TinderboxPrint: I/O write bytes / time<br/>2,386,018,304 / 275,744
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - TinderboxPrint: CPU idle<br/>6,170.5 (73.7%)
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - TinderboxPrint: CPU system<br/>1,078.6 (12.9%)
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - TinderboxPrint: CPU user<br/>1,106.2 (13.2%)
[task 2020-12-20T22:06:39.251Z] 22:06:39 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2020-12-20T22:06:39.252Z] 22:06:39 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-12-20T22:06:39.254Z] 22:06:39 INFO - install - Wall time: 32s; CPU: 25.0%; Read bytes: 61440; Write bytes: 1308536832; Read time: 0; Write time: 130348
[task 2020-12-20T22:06:39.255Z] 22:06:39 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2020-12-20T22:06:39.269Z] 22:06:39 INFO - run-tests - Wall time: 2067s; CPU: 26.0%; Read bytes: 704630784; Write bytes: 808988672; Read time: 24424; Write time: 106844
[task 2020-12-20T22:06:39.607Z] 22:06:39 WARNING - returning nonzero exit status 2```
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•