1702503 - Intermittent dom/media/webspeech/synth/test/test_global_queue.html | Test timed out.

Status: RESOLVED INCOMPLETE

(Core :: Web Speech, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=335152100&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ADQrEO9JRkGI4vFI2EZ3WA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-04-01T13:12:28.304Z] 13:12:28     INFO - TEST-OK | dom/media/webspeech/synth/test/test_bfcache.html | took 3093ms
[task 2021-04-01T13:12:28.481Z] 13:12:28     INFO - TEST-START | dom/media/webspeech/synth/test/test_global_queue.html
[task 2021-04-01T13:17:55.222Z] 13:17:55     INFO - TEST-INFO | started process screentopng
[task 2021-04-01T13:17:55.431Z] 13:17:55     INFO - TEST-INFO | screentopng: exit 0
[task 2021-04-01T13:17:55.432Z] 13:17:55     INFO - TEST-UNEXPECTED-FAIL | dom/media/webspeech/synth/test/test_global_queue.html | Test timed out. 
[task 2021-04-01T13:17:55.432Z] 13:17:55     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-04-01T13:17:55.432Z] 13:17:55     INFO -     reportError@SimpleTest/TestRunner.js:147:24
[task 2021-04-01T13:17:55.432Z] 13:17:55     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:18
[task 2021-04-01T13:17:56.263Z] 13:17:56     INFO - GECKO(2905) | MEMORY STAT | vsize 130550459MB | residentFast 512MB
[task 2021-04-01T13:18:25.224Z] 13:18:25     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:18:25.225Z] 13:18:25     INFO - TEST-UNEXPECTED-FAIL | dom/media/webspeech/synth/test/test_global_queue.html | Test timed out. 
[task 2021-04-01T13:18:25.225Z] 13:18:25     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-04-01T13:18:25.225Z] 13:18:25     INFO -     reportError@SimpleTest/TestRunner.js:147:24
[task 2021-04-01T13:18:25.225Z] 13:18:25     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:18
[task 2021-04-01T13:18:26.229Z] 13:18:26    ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-04-01T13:18:26.245Z] 13:18:26     INFO - TEST-UNEXPECTED-ERROR | dom/media/webspeech/synth/test/test_global_queue.html | called finish() multiple times
[task 2021-04-01T13:18:26.245Z] 13:18:26     INFO - TEST-INFO took 357766ms
[task 2021-04-01T13:18:55.231Z] 13:18:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:18:55.231Z] 13:18:55     INFO - TEST-UNEXPECTED-FAIL | dom/media/webspeech/synth/test/test_global_queue.html | Test timed out. 
[task 2021-04-01T13:18:55.231Z] 13:18:55     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-04-01T13:18:55.231Z] 13:18:55     INFO -     reportError@SimpleTest/TestRunner.js:147:24
[task 2021-04-01T13:18:55.232Z] 13:18:55     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:18
[task 2021-04-01T13:18:56.231Z] 13:18:56    ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-04-01T13:18:56.247Z] 13:18:56     INFO - TEST-UNEXPECTED-ERROR | dom/media/webspeech/synth/test/test_global_queue.html | called finish() multiple times
[task 2021-04-01T13:18:56.247Z] 13:18:56     INFO - TEST-INFO 
[task 2021-04-01T13:19:25.235Z] 13:19:25     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:19:25.235Z] 13:19:25     INFO - TEST-UNEXPECTED-FAIL | dom/media/webspeech/synth/test/test_global_queue.html | Test timed out. 
[task 2021-04-01T13:19:25.235Z] 13:19:25     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-04-01T13:19:25.235Z] 13:19:25     INFO -     reportError@SimpleTest/TestRunner.js:147:24
[task 2021-04-01T13:19:25.235Z] 13:19:25     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:170:18
[task 2021-04-01T13:19:25.235Z] 13:19:25     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO -     reportError@SimpleTest/TestRunner.js:147:24
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:178:20
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 10 remaining tests. 
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO -     reportError@SimpleTest/TestRunner.js:147:24
[task 2021-04-01T13:19:25.236Z] 13:19:25     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:183:20
[task 2021-04-01T13:19:26.236Z] 13:19:26    ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-04-01T13:19:26.252Z] 13:19:26     INFO - TEST-UNEXPECTED-ERROR | (SimpleTest/TestRunner.js) | called finish() multiple times
[task 2021-04-01T13:19:26.252Z] 13:19:26     INFO - TEST-INFO 
[task 2021-04-01T13:25:36.257Z] 13:25:36     INFO - Buffered messages finished
[task 2021-04-01T13:25:36.258Z] 13:25:36    ERROR - TEST-UNEXPECTED-TIMEOUT | (SimpleTest/TestRunner.js) (finished) | application timed out after 370 seconds with no output
[task 2021-04-01T13:25:36.259Z] 13:25:36    ERROR - Force-terminating active process(es).
[task 2021-04-01T13:25:36.260Z] 13:25:36     INFO - Determining child pids from psutil...
[task 2021-04-01T13:25:36.265Z] 13:25:36     INFO - [3078, 3129, 3158, 3162, 3079, 2972, 2996, 3052]
[task 2021-04-01T13:25:36.266Z] 13:25:36     INFO - ==> process 2905 launched child process 2920
[task 2021-04-01T13:25:36.266Z] 13:25:36     INFO - ==> process 2905 launched child process 2972
[task 2021-04-01T13:25:36.267Z] 13:25:36     INFO - ==> process 2905 launched child process 2996
[task 2021-04-01T13:25:36.268Z] 13:25:36     INFO - ==> process 2905 launched child process 3052
[task 2021-04-01T13:25:36.268Z] 13:25:36     INFO - ==> process 2905 launched child process 3078
[task 2021-04-01T13:25:36.269Z] 13:25:36     INFO - ==> process 2905 launched child process 3079
[task 2021-04-01T13:25:36.270Z] 13:25:36     INFO - ==> process 2905 launched child process 3129
[task 2021-04-01T13:25:36.271Z] 13:25:36     INFO - ==> process 2905 launched child process 3158
[task 2021-04-01T13:25:36.271Z] 13:25:36     INFO - Found child pids: set([3078, 3079, 2920, 3052, 2996, 3158, 3129, 3162, 2972])
[task 2021-04-01T13:25:36.272Z] 13:25:36     INFO - Failed to get child procs
[task 2021-04-01T13:25:36.273Z] 13:25:36     INFO - Killing process: 3078
[task 2021-04-01T13:25:36.273Z] 13:25:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:25:36.274Z] 13:25:36     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:26:06.321Z] 13:26:06     INFO - failed to kill pid 3078 after 30s
[task 2021-04-01T13:26:06.322Z] 13:26:06     INFO - Killing process: 3079
[task 2021-04-01T13:26:06.322Z] 13:26:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:26:06.322Z] 13:26:06     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - failed to kill pid 3079 after 30s
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - Killing process: 2920
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - Error: Failed to kill process 2920: psutil.NoSuchProcess no process found with pid 2920
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - Killing process: 3052
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:26:36.336Z] 13:26:36     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:27:06.384Z] 13:27:06     INFO - failed to kill pid 3052 after 30s
[task 2021-04-01T13:27:06.385Z] 13:27:06     INFO - Killing process: 2996
[task 2021-04-01T13:27:06.385Z] 13:27:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:27:06.386Z] 13:27:06     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:27:36.394Z] 13:27:36     INFO - failed to kill pid 2996 after 30s
[task 2021-04-01T13:27:36.396Z] 13:27:36     INFO - Killing process: 3158
[task 2021-04-01T13:27:36.396Z] 13:27:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:27:36.396Z] 13:27:36     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:28:06.444Z] 13:28:06     INFO - failed to kill pid 3158 after 30s
[task 2021-04-01T13:28:06.444Z] 13:28:06     INFO - Killing process: 3129
[task 2021-04-01T13:28:06.444Z] 13:28:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:28:06.444Z] 13:28:06     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:28:36.491Z] 13:28:36     INFO - failed to kill pid 3129 after 30s
[task 2021-04-01T13:28:36.492Z] 13:28:36     INFO - Killing process: 3162
[task 2021-04-01T13:28:36.492Z] 13:28:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:28:36.493Z] 13:28:36     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:29:06.541Z] 13:29:06     INFO - failed to kill pid 3162 after 30s
[task 2021-04-01T13:29:06.541Z] 13:29:06     INFO - Killing process: 2972
[task 2021-04-01T13:29:06.542Z] 13:29:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:29:06.542Z] 13:29:06     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:29:36.592Z] 13:29:36     INFO - failed to kill pid 2972 after 30s
[task 2021-04-01T13:29:36.592Z] 13:29:36     INFO - Killing process: 2905
[task 2021-04-01T13:29:36.592Z] 13:29:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-01T13:29:36.592Z] 13:29:36     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-01T13:30:06.613Z] 13:30:06     INFO - failed to kill pid 3079 after 30s
[task 2021-04-01T13:30:06.614Z] 13:30:06     INFO - failed to kill pid 3158 after 30s
[task 2021-04-01T13:30:06.615Z] 13:30:06     INFO - failed to kill pid 3078 after 30s
[task 2021-04-01T13:30:06.615Z] 13:30:06     INFO - failed to kill pid 3162 after 30s
[task 2021-04-01T13:30:06.615Z] 13:30:06     INFO - failed to kill pid 2972 after 30s
[task 2021-04-01T13:30:06.615Z] 13:30:06     INFO - failed to kill pid 3052 after 30s
[task 2021-04-01T13:30:06.615Z] 13:30:06     INFO - failed to kill pid 2996 after 30s
[task 2021-04-01T13:30:06.615Z] 13:30:06     INFO - failed to kill pid 2905 after 30s
[task 2021-04-01T13:30:06.616Z] 13:30:06     INFO - failed to kill pid 3129 after 30s
[task 2021-04-01T13:30:36.654Z] 13:30:36  WARNING - failed to kill pid 2905 after 30s
[task 2021-04-01T13:47:16.679Z] 13:47:16     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/autoplay/test/mochitest/mochitest.ini', u'dom/media/webspeech/synth/test/mochitest.ini', u'dom/media/webspeech/synth/test/startup/mochitest.ini', u'dom/media/webvtt/test/mochitest/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/ZGdamKrVQyibYR02-sMhhw/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-01T13:47:16.711Z] 13:47:16    ERROR - timed out after 1000 seconds of no output
[task 2021-04-01T13:47:16.711Z] 13:47:16    ERROR - Return code: -15
[task 2021-04-01T13:47:16.713Z] 13:47:16    ERROR - Got 9 unexpected statuses
[task 2021-04-01T13:47:16.713Z] 13:47:16    ERROR - No suite end message was emitted by this harness.
[task 2021-04-01T13:47:16.714Z] 13:47:16     INFO - TinderboxPrint: mochitest-mochitest-media<br/>17/<em class="testfail">9</em>/0
[task 2021-04-01T13:47:16.714Z] 13:47:16    ERROR - # TBPL FAILURE #
[task 2021-04-01T13:47:16.714Z] 13:47:16  WARNING - setting return code to 2
[task 2021-04-01T13:47:16.714Z] 13:47:16    ERROR - The mochitest suite: mochitest-media ran with return status: FAILURE
[task 2021-04-01T13:47:16.714Z] 13:47:16     INFO - Running post-action listener: _package_coverage_data
[task 2021-04-01T13:47:16.714Z] 13:47:16     INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-01T13:47:16.714Z] 13:47:16     INFO - Running post-action listener: process_java_coverage_data
[task 2021-04-01T13:47:16.714Z] 13:47:16     INFO - [mozharness: 2021-04-01 13:47:16.713903Z] Finished run-tests step (success)
[task 2021-04-01T13:47:16.714Z] 13:47:16     INFO - Running post-run listener: _resource_record_post_run
[task 2021-04-01T13:47:16.838Z] 13:47:16     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-04-01T13:47:16.842Z] 13:47:16     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 24.01239705244907}, {"name": "io_write_bytes", "value": 2200649728}, {"name": "io.read_bytes", "value": 65536}, {"name": "io_write_time", "value": 330636}, {"name": "io_read_time", "value": 4}], "extraOptions": ["e10s", "taskcluster-m5.xlarge"], "name": "mochitest.mochitest-media.overall"}, {"subtests": [{"name": "time", "value": 0.017127037048339844}], "name": "mochitest.mochitest-media.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 34.76439809799194}, {"name": "cpu_percent", "value": 25.203030303030303}], "name": "mochitest.mochitest-media.install"}, {"subtests": [{"name": "time", "value": 0.00022101402282714844}], "name": "mochitest.mochitest-media.stage-files"}, {"subtests": [{"name": "time", "value": 2274.609007835388}, {"name": "cpu_percent", "value": 23.99326584507043}], "name": "mochitest.mochitest-media.run-tests"}]}
[task 2021-04-01T13:47:16.843Z] 13:47:16     INFO - Total resource usage - Wall time: 2309s; CPU: 24.0%; Read bytes: 65536; Write bytes: 2200649728; Read time: 4; Write time: 330636
[task 2021-04-01T13:47:16.843Z] 13:47:16     INFO - TinderboxPrint: CPU usage<br/>24.0%
[task 2021-04-01T13:47:16.843Z] 13:47:16     INFO - TinderboxPrint: I/O read bytes / time<br/>65,536 / 4
[task 2021-04-01T13:47:16.843Z] 13:47:16     INFO - TinderboxPrint: I/O write bytes / time<br/>2,200,649,728 / 330,636
[task 2021-04-01T13:47:16.843Z] 13:47:16     INFO - TinderboxPrint: CPU idle<br/>6,989.4 (75.8%)
[task 2021-04-01T13:47:16.843Z] 13:47:16     INFO - TinderboxPrint: CPU system<br/>1,390.1 (15.1%)
[task 2021-04-01T13:47:16.844Z] 13:47:16     INFO - TinderboxPrint: CPU user<br/>826.3 (9.0%)
[task 2021-04-01T13:47:16.844Z] 13:47:16     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-04-01T13:47:16.844Z] 13:47:16     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-01T13:47:16.846Z] 13:47:16     INFO - install - Wall time: 35s; CPU: 25.0%; Read bytes: 0; Write bytes: 304095232; Read time: 0; Write time: 35464
[task 2021-04-01T13:47:16.847Z] 13:47:16     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-01T13:47:16.864Z] 13:47:16     INFO - run-tests - Wall time: 2275s; CPU: 24.0%; Read bytes: 65536; Write bytes: 1583816704; Read time: 4; Write time: 252008
[task 2021-04-01T13:47:17.262Z] 13:47:17  WARNING - returning nonzero exit status 2
[task 2021-04-01T13:47:17.286Z] cleanup
[task 2021-04-01T13:47:17.286Z] + cleanup
[task 2021-04-01T13:47:17.286Z] + local rv=2
[task 2021-04-01T13:47:17.286Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2021-04-01T13:47:17.286Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2021-04-01T13:47:17.287Z] + '[' ']'
[task 2021-04-01T13:47:17.288Z] + true
[task 2021-04-01T13:47:17.288Z] + cleanup_xvfb
[task 2021-04-01T13:47:17.288Z] ++ pidof Xvfb
[task 2021-04-01T13:47:17.292Z] + local xvfb_pid=50
[task 2021-04-01T13:47:17.292Z] + local vnc=false
[task 2021-04-01T13:47:17.292Z] + local interactive=false
[task 2021-04-01T13:47:17.292Z] + '[' -n 50 ']'
[task 2021-04-01T13:47:17.292Z] + [[ false == false ]]
[task 2021-04-01T13:47:17.292Z] + [[ false == false ]]
[task 2021-04-01T13:47:17.293Z] + kill 50
[task 2021-04-01T13:47:17.293Z] + screen -XS xvfb quit
[task 2021-04-01T13:47:17.303Z] + exit 2
[taskcluster 2021-04-01 13:47:17.657Z] === Task Finished ===
[taskcluster 2021-04-01 13:47:19.080Z] Unsuccessful task run with exit code: 2 completed in 2547.278 seconds```

Comment 1

[Intermittent Failures Robot]

2 failures in 3125 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• linux1804-64-tsan: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1702503&startday=2021-03-29&endday=2021-04-04&tree=all

Comment 2

[Intermittent Failures Robot]

3 failures in 3854 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2
• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-tsan: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1702503&startday=2021-04-05&endday=2021-04-11&tree=all

Comment 3

[Intermittent Failures Robot]

1 failures in 4255 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1702503&startday=2021-04-12&endday=2021-04-18&tree=all

Comment 4

[BugBot [:suhaib / :marco]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.