Closed Bug 1704481 Opened 4 years ago Closed 3 years ago

Intermittent [tier2] TEST-UNEXPECTED-TIMEOUT | dom/media/webaudio/test/test_AudioBuffer.html | application timed out after 370 seconds with no output

Categories

(Core :: Web Audio, defect, P5)

defect

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=336180174&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QMUM1GF0Rz-VvLIody2Cbg/runs/0/artifacts/public/logs/live_backing.log


INFO - TEST-START | dom/media/webaudio/test/test_AudioBuffer.html
[task 2021-04-12T10:56:16.967Z] 10:56:16     INFO - Buffered messages finished
[task 2021-04-12T10:56:16.968Z] 10:56:16    ERROR - TEST-UNEXPECTED-TIMEOUT | dom/media/webaudio/test/test_AudioBuffer.html | application timed out after 370 seconds with no output
[task 2021-04-12T10:56:16.968Z] 10:56:16    ERROR - Force-terminating active process(es).
[task 2021-04-12T10:56:16.969Z] 10:56:16     INFO - Determining child pids from psutil...
[task 2021-04-12T10:56:16.971Z] 10:56:16     INFO - [3595, 3622, 3668, 3701, 3621, 3540, 3516]
[task 2021-04-12T10:56:16.972Z] 10:56:16     INFO - ==> process 3454 launched child process 3469
[task 2021-04-12T10:56:16.972Z] 10:56:16     INFO - ==> process 3454 launched child process 3516
[task 2021-04-12T10:56:16.973Z] 10:56:16     INFO - ==> process 3454 launched child process 3540
[task 2021-04-12T10:56:16.974Z] 10:56:16     INFO - ==> process 3454 launched child process 3595
[task 2021-04-12T10:56:16.974Z] 10:56:16     INFO - ==> process 3454 launched child process 3621
[task 2021-04-12T10:56:16.975Z] 10:56:16     INFO - ==> process 3454 launched child process 3622
[task 2021-04-12T10:56:16.975Z] 10:56:16     INFO - ==> process 3454 launched child process 3668
[task 2021-04-12T10:56:16.976Z] 10:56:16     INFO - Found child pids: set([3621, 3622, 3595, 3469, 3540, 3701, 3668, 3516])
[task 2021-04-12T10:56:16.976Z] 10:56:16     INFO - Failed to get child procs
[task 2021-04-12T10:56:16.977Z] 10:56:16     INFO - Killing process: 3621
[task 2021-04-12T10:56:16.977Z] 10:56:16     INFO - TEST-INFO | started process screentopng
[task 2021-04-12T10:56:17.283Z] 10:56:17     INFO - TEST-INFO | screentopng: exit 0
[task 2021-04-12T10:56:17.283Z] 10:56:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:56:47.310Z] 10:56:47     INFO - failed to kill pid 3621 after 30s
[task 2021-04-12T10:56:47.311Z] 10:56:47     INFO - Killing process: 3622
[task 2021-04-12T10:56:47.312Z] 10:56:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:56:47.312Z] 10:56:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:57:17.337Z] 10:57:17     INFO - failed to kill pid 3622 after 30s
[task 2021-04-12T10:57:17.337Z] 10:57:17     INFO - Killing process: 3595
[task 2021-04-12T10:57:17.338Z] 10:57:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:57:17.339Z] 10:57:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:57:47.362Z] 10:57:47     INFO - failed to kill pid 3595 after 30s
[task 2021-04-12T10:57:47.363Z] 10:57:47     INFO - Killing process: 3469
[task 2021-04-12T10:57:47.363Z] 10:57:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:57:47.363Z] 10:57:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:57:47.363Z] 10:57:47     INFO - Error: Failed to kill process 3469: psutil.NoSuchProcess no process found with pid 3469
[task 2021-04-12T10:57:47.364Z] 10:57:47     INFO - Killing process: 3540
[task 2021-04-12T10:57:47.364Z] 10:57:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:57:47.364Z] 10:57:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:58:17.381Z] 10:58:17     INFO - failed to kill pid 3540 after 30s
[task 2021-04-12T10:58:17.383Z] 10:58:17     INFO - Killing process: 3701
[task 2021-04-12T10:58:17.383Z] 10:58:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:58:17.384Z] 10:58:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:58:47.404Z] 10:58:47     INFO - failed to kill pid 3701 after 30s
[task 2021-04-12T10:58:47.404Z] 10:58:47     INFO - Killing process: 3668
[task 2021-04-12T10:58:47.404Z] 10:58:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:58:47.406Z] 10:58:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:59:17.430Z] 10:59:17     INFO - failed to kill pid 3668 after 30s
[task 2021-04-12T10:59:17.431Z] 10:59:17     INFO - Killing process: 3516
[task 2021-04-12T10:59:17.432Z] 10:59:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:59:17.433Z] 10:59:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T10:59:47.454Z] 10:59:47     INFO - failed to kill pid 3516 after 30s
[task 2021-04-12T10:59:47.455Z] 10:59:47     INFO - Killing process: 3454
[task 2021-04-12T10:59:47.455Z] 10:59:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-12T10:59:47.455Z] 10:59:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-12T11:00:17.479Z] 11:00:17     INFO - failed to kill pid 3701 after 30s
[task 2021-04-12T11:00:17.481Z] 11:00:17     INFO - failed to kill pid 3621 after 30s
[task 2021-04-12T11:00:17.482Z] 11:00:17     INFO - failed to kill pid 3595 after 30s
[task 2021-04-12T11:00:17.482Z] 11:00:17     INFO - failed to kill pid 3622 after 30s
[task 2021-04-12T11:00:17.482Z] 11:00:17     INFO - failed to kill pid 3516 after 30s
[task 2021-04-12T11:00:17.482Z] 11:00:17     INFO - failed to kill pid 3454 after 30s
[task 2021-04-12T11:00:17.482Z] 11:00:17     INFO - failed to kill pid 3540 after 30s
[task 2021-04-12T11:00:17.482Z] 11:00:17     INFO - failed to kill pid 3668 after 30s
[task 2021-04-12T11:00:47.491Z] 11:00:47  WARNING - failed to kill pid 3454 after 30s
[task 2021-04-12T11:17:27.533Z] 11:17:27     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/NYRwyoZiQtyAI5sCPloeXg/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-12T11:17:27.550Z] 11:17:27    ERROR - timed out after 1000 seconds of no output
[task 2021-04-12T11:17:27.550Z] 11:17:27    ERROR - Return code: -15
[task 2021-04-12T11:17:27.550Z] 11:17:27    ERROR - No suite end message was emitted by this harness.
[task 2021-04-12T11:17:27.551Z] 11:17:27     INFO - TinderboxPrint: mochitest-mochitest-media<br/>93/0/0
[task 2021-04-12T11:17:27.551Z] 11:17:27    ERROR - # TBPL FAILURE #
[task 2021-04-12T11:17:27.552Z] 11:17:27  WARNING - setting return code to 2
[task 2021-04-12T11:17:27.553Z] 11:17:27    ERROR - The mochitest suite: mochitest-media ran with return status: FAILURE
[task 2021-04-12T11:17:27.553Z] 11:17:27     INFO - Running post-action listener: _package_coverage_data
[task 2021-04-12T11:17:27.554Z] 11:17:27     INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-12T11:17:27.555Z] 11:17:27     INFO - Running post-action listener: process_java_coverage_data
[task 2021-04-12T11:17:27.556Z] 11:17:27     INFO - [mozharness: 2021-04-12 11:17:27.552064Z] Finished run-tests step (success)
[task 2021-04-12T11:17:27.557Z] 11:17:27     INFO - Running post-run listener: _resource_record_post_run
[task 2021-04-12T11:17:27.744Z] 11:17:27     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-04-12T11:17:27.752Z] 11:17:27     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 43.56020647583296}, {"name": "io_write_bytes", "value": 2325798912}, {"name": "io.read_bytes", "value": 0}, {"name": "io_write_time", "value": 282664}, {"name": "io_read_time", "value": 0}], "extraOptions": ["e10s", "taskcluster-m5a.xlarge"], "name": "mochitest.mochitest-media.overall"}, {"subtests": [{"name": "time", "value": 0.021691083908081055}], "name": "mochitest.mochitest-media.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 38.815810203552246}, {"name": "cpu_percent", "value": 25.229054054054053}], "name": "mochitest.mochitest-media.install"}, {"subtests": [{"name": "time", "value": 0.0002779960632324219}], "name": "mochitest.mochitest-media.stage-files"}, {"subtests": [{"name": "time", "value": 2094.850429058075}, {"name": "cpu_percent", "value": 43.90077676864247}], "name": "mochitest.mochitest-media.run-tests"}]}
[task 2021-04-12T11:17:27.752Z] 11:17:27     INFO - Total resource usage - Wall time: 2133s; CPU: 44.0%; Read bytes: 0; Write bytes: 2325798912; Read time: 0; Write time: 282664
[task 2021-04-12T11:17:27.752Z] 11:17:27     INFO - TinderboxPrint: CPU usage<br/>43.9%
[task 2021-04-12T11:17:27.753Z] 11:17:27     INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2021-04-12T11:17:27.754Z] 11:17:27     INFO - TinderboxPrint: I/O write bytes / time<br/>2,325,798,912 / 282,664
[task 2021-04-12T11:17:27.755Z] 11:17:27     INFO - TinderboxPrint: CPU idle<br/>4,781.2 (56.2%)
[task 2021-04-12T11:17:27.760Z] 11:17:27     INFO - TinderboxPrint: CPU system<br/>2,869.2 (33.7%)
[task 2021-04-12T11:17:27.761Z] 11:17:27     INFO - TinderboxPrint: CPU user<br/>844.1 (9.9%)
[task 2021-04-12T11:17:27.761Z] 11:17:27     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-04-12T11:17:27.762Z] 11:17:27     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-12T11:17:27.763Z] 11:17:27     INFO - install - Wall time: 39s; CPU: 25.0%; Read bytes: 0; Write bytes: 759324672; Read time: 0; Write time: 71724
[task 2021-04-12T11:17:27.763Z] 11:17:27     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-12T11:17:27.792Z] 11:17:27     INFO - run-tests - Wall time: 2095s; CPU: 44.0%; Read bytes: 0; Write bytes: 1293058048; Read time: 0; Write time: 171304
[task 2021-04-12T11:17:28.596Z] 11:17:28  WARNING - returning nonzero exit status 2
[task 2021-04-12T11:17:28.626Z] cleanup
[task 2021-04-12T11:17:28.626Z] + cleanup
[task 2021-04-12T11:17:28.626Z] + local rv=2
[task 2021-04-12T11:17:28.626Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-04-12T11:17:28.626Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-04-12T11:17:28.629Z] + '[' ']'
[task 2021-04-12T11:17:28.629Z] + true
[task 2021-04-12T11:17:28.629Z] + cleanup_xvfb
[task 2021-04-12T11:17:28.629Z] ++ pidof Xvfb
[task 2021-04-12T11:17:28.635Z] + local xvfb_pid=50
[task 2021-04-12T11:17:28.635Z] + local vnc=false
[task 2021-04-12T11:17:28.635Z] + local interactive=false
[task 2021-04-12T11:17:28.635Z] + '[' -n 50 ']'
[task 2021-04-12T11:17:28.654Z] + [[ false == false ]]
[task 2021-04-12T11:17:28.655Z] + [[ false == false ]]
[task 2021-04-12T11:17:28.655Z] + kill 50
[task 2021-04-12T11:17:28.655Z] + screen -XS xvfb quit
[task 2021-04-12T11:17:28.655Z] + exit 2
[taskcluster 2021-04-12 11:17:29.009Z] === Task Finished ===
[taskcluster 2021-04-12 11:17:33.091Z] Unsuccessful task run with exit code: 2 completed in 2265.612 seconds```
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.