Closed
Bug 1707579
Opened 4 years ago
Closed 4 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | dom/media/mediasession/test/test_setactionhandler.html | application timed out after 370 seconds with no output
Categories
(Core :: Audio/Video, defect, P5)
Core
Audio/Video
Tracking
()
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=337730279&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SHnhtG_wSlql03esXqUkfA/runs/0/artifacts/public/logs/live_backing.log
[task 2021-04-26T13:25:12.717Z] 13:25:12 INFO - TEST-START | dom/media/mediasession/test/test_setactionhandler.html
[task 2021-04-26T13:31:22.727Z] 13:31:22 INFO - Buffered messages finished
[task 2021-04-26T13:31:22.728Z] 13:31:22 ERROR - TEST-UNEXPECTED-TIMEOUT | dom/media/mediasession/test/test_setactionhandler.html | application timed out after 370 seconds with no output
[task 2021-04-26T13:31:22.728Z] 13:31:22 ERROR - Force-terminating active process(es).
[task 2021-04-26T13:31:22.728Z] 13:31:22 INFO - Determining child pids from psutil...
[task 2021-04-26T13:31:22.736Z] 13:31:22 INFO - [1641, 1665, 1719, 1823, 1753, 1747, 1798, 1830]
[task 2021-04-26T13:31:22.736Z] 13:31:22 INFO - ==> process 1574 launched child process 1589
[task 2021-04-26T13:31:22.736Z] 13:31:22 INFO - ==> process 1574 launched child process 1641
[task 2021-04-26T13:31:22.736Z] 13:31:22 INFO - ==> process 1574 launched child process 1665
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - ==> process 1574 launched child process 1719
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - ==> process 1574 launched child process 1747
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - ==> process 1574 launched child process 1753
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - ==> process 1574 launched child process 1798
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - ==> process 1574 launched child process 1823
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - Found child pids: set([1665, 1830, 1798, 1641, 1747, 1589, 1719, 1753, 1823])
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - Failed to get child procs
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - Killing process: 1665
[task 2021-04-26T13:31:22.737Z] 13:31:22 INFO - TEST-INFO | started process screentopng
[task 2021-04-26T13:31:22.981Z] 13:31:22 INFO - TEST-INFO | screentopng: exit 0
[task 2021-04-26T13:31:22.981Z] 13:31:22 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:31:52.988Z] 13:31:52 INFO - failed to kill pid 1665 after 30s
[task 2021-04-26T13:31:52.988Z] 13:31:52 INFO - Killing process: 1830
[task 2021-04-26T13:31:52.989Z] 13:31:52 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:31:52.989Z] 13:31:52 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:32:23.039Z] 13:32:23 INFO - failed to kill pid 1830 after 30s
[task 2021-04-26T13:32:23.047Z] 13:32:23 INFO - Killing process: 1798
[task 2021-04-26T13:32:23.047Z] 13:32:23 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:32:23.048Z] 13:32:23 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:32:53.079Z] 13:32:53 INFO - failed to kill pid 1798 after 30s
[task 2021-04-26T13:32:53.080Z] 13:32:53 INFO - Killing process: 1641
[task 2021-04-26T13:32:53.081Z] 13:32:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:32:53.081Z] 13:32:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:33:23.131Z] 13:33:23 INFO - failed to kill pid 1641 after 30s
[task 2021-04-26T13:33:23.131Z] 13:33:23 INFO - Killing process: 1747
[task 2021-04-26T13:33:23.131Z] 13:33:23 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:33:23.132Z] 13:33:23 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:33:53.136Z] 13:33:53 INFO - failed to kill pid 1747 after 30s
[task 2021-04-26T13:33:53.136Z] 13:33:53 INFO - Killing process: 1589
[task 2021-04-26T13:33:53.136Z] 13:33:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:33:53.136Z] 13:33:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:33:53.136Z] 13:33:53 INFO - Error: Failed to kill process 1589: psutil.NoSuchProcess no process found with pid 1589
[task 2021-04-26T13:33:53.137Z] 13:33:53 INFO - Killing process: 1719
[task 2021-04-26T13:33:53.137Z] 13:33:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:33:53.137Z] 13:33:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:34:23.187Z] 13:34:23 INFO - failed to kill pid 1719 after 30s
[task 2021-04-26T13:34:23.187Z] 13:34:23 INFO - Killing process: 1753
[task 2021-04-26T13:34:23.187Z] 13:34:23 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:34:23.187Z] 13:34:23 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:34:53.223Z] 13:34:53 INFO - failed to kill pid 1753 after 30s
[task 2021-04-26T13:34:53.223Z] 13:34:53 INFO - Killing process: 1823
[task 2021-04-26T13:34:53.223Z] 13:34:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:34:53.224Z] 13:34:53 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:35:23.231Z] 13:35:23 INFO - failed to kill pid 1823 after 30s
[task 2021-04-26T13:35:23.233Z] 13:35:23 INFO - Killing process: 1574
[task 2021-04-26T13:35:23.233Z] 13:35:23 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-26T13:35:23.234Z] 13:35:23 INFO - Can't trigger Breakpad, just killing process
[task 2021-04-26T13:35:53.262Z] 13:35:53 INFO - failed to kill pid 1747 after 30s
[task 2021-04-26T13:35:53.262Z] 13:35:53 INFO - failed to kill pid 1719 after 30s
[task 2021-04-26T13:35:53.262Z] 13:35:53 INFO - failed to kill pid 1753 after 30s
[task 2021-04-26T13:35:53.262Z] 13:35:53 INFO - failed to kill pid 1574 after 30s
[task 2021-04-26T13:35:53.262Z] 13:35:53 INFO - failed to kill pid 1641 after 30s
[task 2021-04-26T13:35:53.263Z] 13:35:53 INFO - failed to kill pid 1830 after 30s
[task 2021-04-26T13:35:53.263Z] 13:35:53 INFO - failed to kill pid 1823 after 30s
[task 2021-04-26T13:35:53.263Z] 13:35:53 INFO - failed to kill pid 1798 after 30s
[task 2021-04-26T13:35:53.263Z] 13:35:53 INFO - failed to kill pid 1665 after 30s
[task 2021-04-26T13:36:23.270Z] 13:36:23 WARNING - failed to kill pid 1574 after 30s
[task 2021-04-26T13:53:03.304Z] 13:53:03 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'dom/media/mediasession/test/mochitest.ini', u'dom/media/mediasource/test/mochitest.ini', u'dom/media/webaudio/test/blink/mochitest.ini', u'dom/media/webaudio/test/mochitest.ini', u'dom/media/webrtc/tests/mochitests/identity/mochitest.ini', u'dom/media/webspeech/recognition/test/mochitest.ini', '--setpref=webgl.out-of-process=false', '--setpref=fission.autostart=true', '--setpref=dom.serviceWorkers.parent_intercept=true', '--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/C7JWH6UASQ2QGQ5NzzFArA/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-media_raw.log', '--log-errorsummary=/builds/worker/workspace/build/blobber_upload_dir/mochitest-media_errorsummary.log', '--use-test-media-devices', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/builds/worker/workspace/build', '--log-raw=-', '--subsuite=media']
[task 2021-04-26T13:53:03.349Z] 13:53:03 ERROR - timed out after 1000 seconds of no output
[task 2021-04-26T13:53:03.349Z] 13:53:03 ERROR - Return code: -15
[task 2021-04-26T13:53:03.350Z] 13:53:03 ERROR - No suite end message was emitted by this harness.
[task 2021-04-26T13:53:03.350Z] 13:53:03 INFO - TinderboxPrint: mochitest-mochitest-media<br/>12/0/0
[task 2021-04-26T13:53:03.350Z] 13:53:03 ERROR - # TBPL FAILURE #
[task 2021-04-26T13:53:03.351Z] 13:53:03 WARNING - setting return code to 2
[task 2021-04-26T13:53:03.351Z] 13:53:03 ERROR - The mochitest suite: mochitest-media ran with return status: FAILURE
[task 2021-04-26T13:53:03.351Z] 13:53:03 INFO - Running post-action listener: _package_coverage_data
[task 2021-04-26T13:53:03.351Z] 13:53:03 INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-26T13:53:03.351Z] 13:53:03 INFO - Running post-action listener: process_java_coverage_data
[task 2021-04-26T13:53:03.351Z] 13:53:03 INFO - [mozharness: 2021-04-26 13:53:03.351793Z] Finished run-tests step (success)
[task 2021-04-26T13:53:03.352Z] 13:53:03 INFO - Running post-run listener: _resource_record_post_run
[task 2021-04-26T13:53:03.470Z] 13:53:03 INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-04-26T13:53:03.474Z] 13:53:03 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 21.707198499711474}, {"name": "io_write_bytes", "value": 2064080896}, {"name": "io.read_bytes", "value": 8192}, {"name": "io_write_time", "value": 240728}, {"name": "io_read_time", "value": 4}], "extraOptions": ["e10s", "taskcluster-m5d.xlarge"], "name": "mochitest.mochitest-media.overall"}, {"subtests": [{"name": "time", "value": 0.017281055450439453}], "name": "mochitest.mochitest-media.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 37.30171585083008}, {"name": "cpu_percent", "value": 25.222916666666666}], "name": "mochitest.mochitest-media.install"}, {"subtests": [{"name": "time", "value": 0.0002429485321044922}], "name": "mochitest.mochitest-media.stage-files"}, {"subtests": [{"name": "time", "value": 1697.4135959148407}, {"name": "cpu_percent", "value": 21.627374631268424}], "name": "mochitest.mochitest-media.run-tests"}]}
[task 2021-04-26T13:53:03.474Z] 13:53:03 INFO - Total resource usage - Wall time: 1735s; CPU: 22.0%; Read bytes: 8192; Write bytes: 2064080896; Read time: 4; Write time: 240728
[task 2021-04-26T13:53:03.474Z] 13:53:03 INFO - TinderboxPrint: CPU usage<br/>21.6%
[task 2021-04-26T13:53:03.475Z] 13:53:03 INFO - TinderboxPrint: I/O read bytes / time<br/>8,192 / 4
[task 2021-04-26T13:53:03.475Z] 13:53:03 INFO - TinderboxPrint: I/O write bytes / time<br/>2,064,080,896 / 240,728
[task 2021-04-26T13:53:03.475Z] 13:53:03 INFO - TinderboxPrint: CPU idle<br/>5,412.8 (78.2%)
[task 2021-04-26T13:53:03.475Z] 13:53:03 INFO - TinderboxPrint: CPU system<br/>1,055.9 (15.2%)
[task 2021-04-26T13:53:03.475Z] 13:53:03 INFO - TinderboxPrint: CPU user<br/>450.0 (6.5%)
[task 2021-04-26T13:53:03.475Z] 13:53:03 INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-04-26T13:53:03.476Z] 13:53:03 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-04-26T13:53:03.478Z] 13:53:03 INFO - install - Wall time: 37s; CPU: 25.0%; Read bytes: 0; Write bytes: 1739227136; Read time: 0; Write time: 220836
[task 2021-04-26T13:53:03.478Z] 13:53:03 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-04-26T13:53:03.492Z] 13:53:03 INFO - run-tests - Wall time: 1697s; CPU: 22.0%; Read bytes: 8192; Write bytes: 322551808; Read time: 4; Write time: 19668
[task 2021-04-26T13:53:03.816Z] 13:53:03 WARNING - returning nonzero exit status 2
[task 2021-04-26T13:53:03.841Z] cleanup
[task 2021-04-26T13:53:03.842Z] + cleanup
[task 2021-04-26T13:53:03.842Z] + local rv=2
[task 2021-04-26T13:53:03.842Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-04-26T13:53:03.842Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-04-26T13:53:03.843Z] + '[' ']'
[task 2021-04-26T13:53:03.844Z] + true
[task 2021-04-26T13:53:03.844Z] + cleanup_xvfb
[task 2021-04-26T13:53:03.844Z] ++ pidof Xvfb
[task 2021-04-26T13:53:03.848Z] + local xvfb_pid=50
[task 2021-04-26T13:53:03.848Z] + local vnc=false
[task 2021-04-26T13:53:03.848Z] + local interactive=false
[task 2021-04-26T13:53:03.848Z] + '[' -n 50 ']'
[task 2021-04-26T13:53:03.848Z] + [[ false == false ]]
[task 2021-04-26T13:53:03.848Z] + [[ false == false ]]
[task 2021-04-26T13:53:03.848Z] + kill 50
[task 2021-04-26T13:53:03.848Z] + screen -XS xvfb quit
[task 2021-04-26T13:53:03.851Z] + exit 2
[taskcluster 2021-04-26 13:53:04.211Z] === Task Finished ===
[taskcluster 2021-04-26 13:53:08.408Z] Unsuccessful task run with exit code: 2 completed in 1836.02 seconds```
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•4 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•