1705860 - Intermittent TEST-UNEXPECTED-TIMEOUT | dom/media/webrtc/tests/mochitests/identity/test_getIdentityAssertion.html | application timed out after 370 seconds with no output

Status: RESOLVED INCOMPLETE

(Core :: WebRTC: Audio/Video, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-04-17T02:48:48.635Z] 02:48:48     INFO - runtests.py | Waiting for browser...
[task 2021-04-17T02:48:48.673Z] 02:48:48     INFO - GECKO(4982) | 1618627728662	Marionette	DEBUG	Closed connection 1
[task 2021-04-17T02:48:49.011Z] 02:48:49     INFO - GECKO(4982) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-04-17T02:48:49.747Z] 02:48:49     INFO - GECKO(4982) | 1618627729742	Marionette	TRACE	[41] MarionetteEvents actor created for window id 6442450945
[task 2021-04-17T02:48:49.835Z] 02:48:49     INFO - GECKO(4982) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'
[task 2021-04-17T02:48:51.135Z] 02:48:51     INFO - SimpleTest START
[task 2021-04-17T02:48:51.191Z] 02:48:51     INFO - TEST-START | dom/media/webrtc/tests/mochitests/identity/test_getIdentityAssertion.html
[task 2021-04-17T02:55:01.211Z] 02:55:01     INFO - Buffered messages finished
[task 2021-04-17T02:55:01.212Z] 02:55:01    ERROR - TEST-UNEXPECTED-TIMEOUT | dom/media/webrtc/tests/mochitests/identity/test_getIdentityAssertion.html | application timed out after 370 seconds with no output
[task 2021-04-17T02:55:01.212Z] 02:55:01    ERROR - Force-terminating active process(es).
[task 2021-04-17T02:55:01.212Z] 02:55:01     INFO - Determining child pids from psutil...
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - [5122, 5152, 5200, 5225, 5149, 5068, 5044]
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - ==> process 4982 launched child process 4997
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - ==> process 4982 launched child process 5044
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - ==> process 4982 launched child process 5068
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - ==> process 4982 launched child process 5122
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - ==> process 4982 launched child process 5149
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - ==> process 4982 launched child process 5152
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - ==> process 4982 launched child process 5200
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - Found child pids: set([5152, 5122, 4997, 5225, 5068, 5200, 5044, 5149])
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - Failed to get child procs
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - Killing process: 5152
[task 2021-04-17T02:55:01.221Z] 02:55:01     INFO - TEST-INFO | started process screentopng
[task 2021-04-17T02:55:01.459Z] 02:55:01     INFO - TEST-INFO | screentopng: exit 0
[task 2021-04-17T02:55:01.459Z] 02:55:01     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:55:31.476Z] 02:55:31     INFO - failed to kill pid 5152 after 30s
[task 2021-04-17T02:55:31.477Z] 02:55:31     INFO - Killing process: 5122
[task 2021-04-17T02:55:31.477Z] 02:55:31     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:55:31.477Z] 02:55:31     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:56:01.497Z] 02:56:01     INFO - failed to kill pid 5122 after 30s
[task 2021-04-17T02:56:01.497Z] 02:56:01     INFO - Killing process: 4997
[task 2021-04-17T02:56:01.498Z] 02:56:01     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:56:01.498Z] 02:56:01     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:56:01.499Z] 02:56:01     INFO - Error: Failed to kill process 4997: psutil.NoSuchProcess no process found with pid 4997
[task 2021-04-17T02:56:01.500Z] 02:56:01     INFO - Killing process: 5225
[task 2021-04-17T02:56:01.501Z] 02:56:01     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:56:01.501Z] 02:56:01     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:56:31.518Z] 02:56:31     INFO - failed to kill pid 5225 after 30s
[task 2021-04-17T02:56:31.519Z] 02:56:31     INFO - Killing process: 5068
[task 2021-04-17T02:56:31.520Z] 02:56:31     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:56:31.521Z] 02:56:31     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:57:01.542Z] 02:57:01     INFO - failed to kill pid 5068 after 30s
[task 2021-04-17T02:57:01.544Z] 02:57:01     INFO - Killing process: 5200
[task 2021-04-17T02:57:01.544Z] 02:57:01     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:57:01.545Z] 02:57:01     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:57:31.564Z] 02:57:31     INFO - failed to kill pid 5200 after 30s
[task 2021-04-17T02:57:31.565Z] 02:57:31     INFO - Killing process: 5044
[task 2021-04-17T02:57:31.566Z] 02:57:31     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:57:31.567Z] 02:57:31     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:58:01.586Z] 02:58:01     INFO - failed to kill pid 5044 after 30s
[task 2021-04-17T02:58:01.587Z] 02:58:01     INFO - Killing process: 5149
[task 2021-04-17T02:58:01.587Z] 02:58:01     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:58:01.587Z] 02:58:01     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:58:31.606Z] 02:58:31     INFO - failed to kill pid 5149 after 30s
[task 2021-04-17T02:58:31.606Z] 02:58:31     INFO - Killing process: 4982
[task 2021-04-17T02:58:31.606Z] 02:58:31     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-17T02:58:31.606Z] 02:58:31     INFO - Can't trigger Breakpad, just killing process
[task 2021-04-17T02:59:01.628Z] 02:59:01     INFO - failed to kill pid 5200 after 30s
[task 2021-04-17T02:59:01.630Z] 02:59:01     INFO - failed to kill pid 4982 after 30s
[task 2021-04-17T02:59:01.630Z] 02:59:01     INFO - failed to kill pid 5044 after 30s
[task 2021-04-17T02:59:01.630Z] 02:59:01     INFO - failed to kill pid 5152 after 30s
[task 2021-04-17T02:59:01.631Z] 02:59:01     INFO - failed to kill pid 5122 after 30s
[task 2021-04-17T02:59:01.631Z] 02:59:01     INFO - failed to kill pid 5225 after 30s
[task 2021-04-17T02:59:01.631Z] 02:59:01     INFO - failed to kill pid 5068 after 30s
[task 2021-04-17T02:59:01.632Z] 02:59:01     INFO - failed to kill pid 5149 after 30s
[task 2021-04-17T02:59:31.650Z] 02:59:31  WARNING - failed to kill pid 4982 after 30s
[task 2021-04-17T03:16:11.673Z] 03:16:11     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/BDmMrrN-TUeAGfpKA8shXQ/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-17T03:16:11.682Z] 03:16:11    ERROR - timed out after 1000 seconds of no output
[task 2021-04-17T03:16:11.682Z] 03:16:11    ERROR - Return code: -15
[task 2021-04-17T03:16:11.683Z] 03:16:11    ERROR - No suite end message was emitted by this harness.
[task 2021-04-17T03:16:11.684Z] 03:16:11     INFO - TinderboxPrint: mochitest-mochitest-media<br/>273/0/0
[task 2021-04-17T03:16:11.684Z] 03:16:11    ERROR - # TBPL FAILURE #
[task 2021-04-17T03:16:11.685Z] 03:16:11  WARNING - setting return code to 2
[task 2021-04-17T03:16:11.685Z] 03:16:11    ERROR - The mochitest suite: mochitest-media ran with return status: FAILURE
[task 2021-04-17T03:16:11.685Z] 03:16:11     INFO - Running post-action listener: _package_coverage_data
[task 2021-04-17T03:16:11.685Z] 03:16:11     INFO - Running post-action listener: _resource_record_post_action
[task 2021-04-17T03:16:11.686Z] 03:16:11     INFO - Running post-action listener: process_java_coverage_data
[task 2021-04-17T03:16:11.686Z] 03:16:11     INFO - [mozharness: 2021-04-17 03:16:11.686199Z] Finished run-tests step (success)
[task 2021-04-17T03:16:11.686Z] 03:16:11     INFO - Running post-run listener: _resource_record_post_run
[task 2021-04-17T03:16:11.851Z] 03:16:11     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2021-04-17T03:16:11.856Z] 03:16:11     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"subtests": [{"name": "cpu_percent", "value": 24.345952287837335}, {"name": "io_write_bytes", "value": 2462240768}, {"name": "io.read_bytes", "value": 5521408}, {"name": "io_write_time", "value": 302056}, {"name": "io_read_time", "value": 40}], "extraOptions": ["e10s", "taskcluster-m5a.xlarge"], "name": "mochitest.mochitest-media.overall"}, {"subtests": [{"name": "time", "value": 0.02407693862915039}], "name": "mochitest.mochitest-media.start-pulseaudio"}, {"subtests": [{"name": "time", "value": 40.51619005203247}, {"name": "cpu_percent", "value": 25.283333333333335}], "name": "mochitest.mochitest-media.install"}, {"subtests": [{"name": "time", "value": 0.0002689361572265625}], "name": "mochitest.mochitest-media.stage-files"}, {"subtests": [{"name": "time", "value": 2519.5078930854797}, {"name": "cpu_percent", "value": 24.330206677265526}], "name": "mochitest.mochitest-media.run-tests"}]}
[task 2021-04-17T03:16:11.857Z] 03:16:11     INFO - Total resource usage - Wall time: 2560s; CPU: 24.0%; Read bytes: 5521408; Write bytes: 2462240768; Read time: 40; Write time: 302056
[task 2021-04-17T03:16:11.857Z] 03:16:11     INFO - TinderboxPrint: CPU usage<br/>24.3%
[task 2021-04-17T03:16:11.857Z] 03:16:11     INFO - TinderboxPrint: I/O read bytes / time<br/>5,521,408 / 40
[task 2021-04-17T03:16:11.857Z] 03:16:11     INFO - TinderboxPrint: I/O write bytes / time<br/>2,462,240,768 / 302,056
[task 2021-04-17T03:16:11.857Z] 03:16:11     INFO - TinderboxPrint: CPU idle<br/>7,705.1 (75.5%)
[task 2021-04-17T03:16:11.857Z] 03:16:11     INFO - TinderboxPrint: CPU system<br/>1,361.8 (13.3%)
[task 2021-04-17T03:16:11.858Z] 03:16:11     INFO - TinderboxPrint: CPU user<br/>1,124.9 (11.0%)
[task 2021-04-17T03:16:11.858Z] 03:16:11     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2021-04-17T03:16:11.859Z] 03:16:11     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-17T03:16:11.861Z] 03:16:11     INFO - install - Wall time: 41s; CPU: 25.0%; Read bytes: 0; Write bytes: 1391403008; Read time: 0; Write time: 158732
[task 2021-04-17T03:16:11.863Z] 03:16:11     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-17T03:16:11.888Z] 03:16:11     INFO - run-tests - Wall time: 2520s; CPU: 24.0%; Read bytes: 5521408; Write bytes: 801878016; Read time: 40; Write time: 103756
[task 2021-04-17T03:16:12.555Z] 03:16:12  WARNING - returning nonzero exit status 2
[task 2021-04-17T03:16:12.580Z] cleanup```

Comment 1

[Intermittent Failures Robot]

2 failures in 4255 pushes (0.0 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=1705860&startday=2021-04-12&endday=2021-04-18&tree=all

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform and build breakdown:

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

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

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

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

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

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

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