Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=458679601&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/diT0oYx_Ra2t-scBRrZVbA/runs/0/artifacts/public/logs/live_backing.log
[task 2024-05-17T21:35:03.297Z] 21:35:03 INFO - TEST-START | dom/media/test/test_complete_length.html
[task 2024-05-17T21:35:04.428Z] 21:35:04 INFO - GECKO(3324) | JavaScript error: https://example.com/tests/dom/media/test/test_complete_length.html, line 27: ReferenceError: add_task is not defined
[task 2024-05-17T21:35:32.157Z] 21:35:32 INFO - GECKO(3324) | 2024-05-17 21:35:32.156 firefox[3324:39398] Persistent UI failed to open file file:///Users/cltbld/Library/Saved%20Application%20State/org.mozilla.nightly.savedState/window_1.data: No such file or directory (2)
[task 2024-05-17T21:41:42.226Z] 21:41:42 INFO - TEST-UNEXPECTED-TIMEOUT | dom/media/test/test_complete_length.html | application timed out after 370 seconds with no output
[task 2024-05-17T21:41:42.226Z] 21:41:42 INFO - TEST-INFO took 398704ms
[task 2024-05-17T21:41:42.226Z] 21:41:42 INFO - Buffered messages finished
[task 2024-05-17T21:41:42.227Z] 21:41:42 WARNING - Force-terminating active process(es).
[task 2024-05-17T21:41:42.227Z] 21:41:42 INFO - Determining child pids from psutil...
[task 2024-05-17T21:41:42.228Z] 21:41:42 INFO - [3325, 3328, 3330, 3331, 3332, 3333, 3334]
[task 2024-05-17T21:41:42.228Z] 21:41:42 INFO - ==> process 3324 launched child process 3325
[task 2024-05-17T21:41:42.228Z] 21:41:42 INFO - ==> process 3324 launched child process 3327
[task 2024-05-17T21:41:42.228Z] 21:41:42 INFO - ==> process 3324 launched child process 3328
[task 2024-05-17T21:41:42.228Z] 21:41:42 INFO - ==> process 3324 launched child process 3330
[task 2024-05-17T21:41:42.228Z] 21:41:42 INFO - ==> process 3324 launched child process 3331
[task 2024-05-17T21:41:42.228Z] 21:41:42 INFO - ==> process 3324 launched child process 3332
[task 2024-05-17T21:41:42.229Z] 21:41:42 INFO - ==> process 3324 launched child process 3333
[task 2024-05-17T21:41:42.229Z] 21:41:42 INFO - ==> process 3324 launched child process 3334
[task 2024-05-17T21:41:42.229Z] 21:41:42 INFO - Found child pids: {3328, 3330, 3331, 3332, 3333, 3334, 3325, 3327}
[task 2024-05-17T21:41:42.229Z] 21:41:42 INFO - Failed to get child procs
[task 2024-05-17T21:41:42.229Z] 21:41:42 INFO - Killing process: 3328
[task 2024-05-17T21:41:42.229Z] 21:41:42 INFO - TEST-INFO | started process screencapture
[task 2024-05-17T21:41:42.356Z] 21:41:42 INFO - TEST-INFO | screencapture: exit 0
[task 2024-05-17T21:41:42.356Z] 21:41:42 INFO - Killing process: 3330
[task 2024-05-17T21:41:42.356Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.357Z] 21:41:42 INFO - Killing process: 3331
[task 2024-05-17T21:41:42.357Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.357Z] 21:41:42 INFO - Killing process: 3332
[task 2024-05-17T21:41:42.357Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.357Z] 21:41:42 INFO - Killing process: 3333
[task 2024-05-17T21:41:42.357Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.357Z] 21:41:42 INFO - Killing process: 3334
[task 2024-05-17T21:41:42.358Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.358Z] 21:41:42 INFO - Killing process: 3325
[task 2024-05-17T21:41:42.358Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.358Z] 21:41:42 INFO - Killing process: 3327
[task 2024-05-17T21:41:42.358Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.358Z] 21:41:42 INFO - Can't trigger Breakpad, process no longer exists
[task 2024-05-17T21:41:42.358Z] 21:41:42 INFO - Killing process: 3324
[task 2024-05-17T21:41:42.359Z] 21:41:42 INFO - Not taking screenshot here: see the one that was previously logged
[task 2024-05-17T21:41:42.459Z] 21:41:42 INFO - psutil found pid 3324 dead
[task 2024-05-17T21:58:22.602Z] 21:58:22 INFO - Automation Error: mozharness timed out after 1000 seconds running ['/opt/worker/tasks/task_171598056109172/build/venv/bin/python', '-u', '/opt/worker/tasks/task_171598056109172/build/tests/mochitest/runtests.py', 'dom/media/autoplay/test/mochitest/mochitest.toml', 'dom/media/mediasession/test/mochitest.toml', 'dom/media/mediasource/test/mochitest.toml', 'dom/media/mediasource/test/mochitest_compat.toml', 'dom/media/test/mochitest.toml', 'dom/media/test/mochitest_background_video.toml', 'dom/media/test/mochitest_bugs.toml', 'dom/media/test/mochitest_compat.toml', 'dom/media/test/mochitest_eme.toml', 'dom/media/test/mochitest_eme_compat.toml', 'dom/media/test/mochitest_media_engine.toml', 'dom/media/test/mochitest_media_recorder.toml', 'dom/media/test/mochitest_seek.toml', 'dom/media/test/mochitest_stream.toml', 'dom/media/webaudio/test/blink/mochitest.toml', 'dom/media/webaudio/test/mochitest.toml', 'dom/media/webaudio/test/mochitest_audio.toml', 'dom/media/webaudio/test/mochitest_bugs.toml', 'dom/media/webaudio/test/mochitest_media.toml', 'dom/media/webcodecs/test/mochitest.toml', 'dom/media/webrtc/tests/mochitests/identity/mochitest.toml', 'dom/media/webrtc/tests/mochitests/mochitest.toml', 'dom/media/webrtc/tests/mochitests/mochitest_datachannel.toml', 'dom/media/webrtc/tests/mochitests/mochitest_getusermedia.toml', 'dom/media/webrtc/tests/mochitests/mochitest_peerconnection.toml', 'dom/media/webspeech/recognition/test/mochitest.toml', 'dom/media/webspeech/synth/test/mochitest.toml', 'dom/media/webspeech/synth/test/startup/mochitest.toml', 'dom/media/webvtt/test/mochitest/mochitest.toml', 'ipc/glue/test/browser/mochitest_audio_off.toml', 'ipc/glue/test/browser/mochitest_audio_on.toml', '--setpref=layout.css.stylo-threads=4', '--setpref=webgl.out-of-process=false', '--setpref=security.sandbox.content.headless=false', '--setpref=webgl.out-of-process=true', '--setpref=security.sandbox.content.headless=true', '--setpref=media.peerconnection.mtransport_process=false', '--setpref=network.process.enabled=false', '--setpref=layers.d3d11.enable-blacklist=false', '--appname=/opt/worker/tasks/task_171598056109172/build/application/Firefox Nightly.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fu3sj5YoSKOM_pnnV2cu0w/artifacts/public/build/target.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--quiet', '--log-errorsummary=/opt/worker/tasks/task_171598056109172/build/blobber_upload_dir/mochitest-media_errorsummary.log', '--screenshot-on-fail', '--cleanup-crashes', '--marionette-startup-timeout=180', '--sandbox-read-whitelist=/opt/worker/tasks/task_171598056109172/build', '--log-raw=-', '--subsuite=media']
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Return code: -9
[task 2024-05-17T21:58:22.603Z] 21:58:22 WARNING - Got 1 unexpected statuses
[task 2024-05-17T21:58:22.603Z] 21:58:22 ERROR - No suite end message was emitted by this harness.
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - TinderboxPrint: mochitest-mochitest-media<br/>183/<em class="testfail">1</em>/0
[task 2024-05-17T21:58:22.603Z] 21:58:22 WARNING - setting return code to 2
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - The mochitest suite: mochitest-media ran with return status: FAILURE
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Running post-action listener: _package_coverage_data
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Running post-action listener: _resource_record_post_action
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Running post-action listener: process_java_coverage_data
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - [mozharness: 2024-05-17 21:58:22.603858Z] Finished run-tests step (success)
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - [mozharness: 2024-05-17 21:58:22.603874Z] Running uninstall step.
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Running pre-action listener: _resource_record_pre_action
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Running main action method: uninstall
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Skipping uninstall for non-MSIX test
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Running post-action listener: _resource_record_post_action
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - [mozharness: 2024-05-17 21:58:22.603932Z] Finished uninstall step (success)
[task 2024-05-17T21:58:22.603Z] 21:58:22 INFO - Running post-run listener: _resource_record_post_run
[task 2024-05-17T21:58:22.809Z] 21:58:22 INFO - instance_metadata.json not found; unable to determine instance type
[task 2024-05-17T21:58:22.818Z] 21:58:22 INFO - Validating Perfherder data against /opt/worker/tasks/task_171598056109172/mozharness/external_tools/performance-artifact-schema.json
[task 2024-05-17T21:58:22.819Z] 21:58:22 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-media.overall", "extraOptions": ["e10s", "buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 14.848891525568686}, {"name": "io_write_bytes", "value": 951345152}, {"name": "io.read_bytes", "value": 318627840}, {"name": "io_write_time", "value": 1726}, {"name": "io_read_time", "value": 5329}]}, {"name": "mochitest.mochitest-media.start-pulseaudio", "subtests": [{"name": "time", "value": 9.658299995862762e-05}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-media.install", "subtests": [{"name": "time", "value": 21.236286124999992}, {"name": "cpu_percent", "value": 13.18381696428572}]}, {"name": "mochitest.mochitest-media.stage-files", "subtests": [{"name": "time", "value": 0.00013770800001111638}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-media.run-tests", "subtests": [{"name": "time", "value": 1893.3144533749996}, {"name": "cpu_percent", "value": 14.86239096640471}]}, {"name": "mochitest.mochitest-media.uninstall", "subtests": [{"name": "time", "value": 3.841700026896433e-05}, {"name": "cpu_percent", "value": 0}]}]}
[task 2024-05-17T21:58:22.819Z] 21:58:22 INFO - Total resource usage - Wall time: 1915s; CPU: Can't collect data; Read bytes: 318627840; Write bytes: 951345152; Read time: 5329; Write time: 1726
[task 2024-05-17T21:58:22.819Z] 21:58:22 INFO - TinderboxPrint: I/O read bytes / time<br/>318,627,840 / 5,329
[task 2024-05-17T21:58:22.819Z] 21:58:22 INFO - TinderboxPrint: I/O write bytes / time<br/>951,345,152 / 1,726
[task 2024-05-17T21:58:22.819Z] 21:58:22 INFO - TinderboxPrint: CPU idle<br/>13,111.8 (85.6%)
[task 2024-05-17T21:58:22.819Z] 21:58:22 INFO - TinderboxPrint: CPU user<br/>2,057.8 (13.4%)
[task 2024-05-17T21:58:22.819Z] 21:58:22 INFO - TinderboxPrint: Swap in / out<br/>882,999,296 / 0
[task 2024-05-17T21:58:22.820Z] 21:58:22 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-05-17T21:58:22.822Z] 21:58:22 INFO - install - Wall time: 21s; CPU: 13%; Read bytes: 509597696; Write bytes: 506335232; Read time: 18238; Write time: 405
[task 2024-05-17T21:58:22.823Z] 21:58:22 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-05-17T21:58:22.854Z] 21:58:22 INFO - run-tests - Wall time: 1893s; CPU: 15%; Read bytes: 308322304; Write bytes: 444977152; Read time: 5105; Write time: 1321
[task 2024-05-17T21:58:22.856Z] 21:58:22 INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-05-17T21:58:23.896Z] 21:58:23 WARNING - returning nonzero exit status 2
[taskcluster 2024-05-17T21:58:23.961Z] Exit Code: 2
[taskcluster 2024-05-17T21:58:23.961Z] User Time: 4m2.535279s
[taskcluster 2024-05-17T21:58:23.961Z] Kernel Time: 24.742762s
[taskcluster 2024-05-17T21:58:23.961Z] Wall Time: 32m58.575486s
[taskcluster 2024-05-17T21:58:23.961Z] Result: FAILED
[taskcluster 2024-05-17T21:58:23.961Z] === Task Finished ===
[taskcluster 2024-05-17T21:58:23.961Z] Task Duration: 32m58.580711s
Description
•