1747395 - Intermittent [tier 2] dom/media/test/test_eme_createMediaKeys_iframes.html | Test timed out. -

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - TEST-PASS | dom/media/test/test_eme_createMediaKeys_iframes.html | Media keys should still exist after the load 
[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - add_task | Leaving test 
[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - add_task | Entering test 
[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - Starting different origin iframe, using src attribute, wait for onload test
[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - Buffered messages logged at 12:23:24
[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - iframe loaded
[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - Buffered messages finished
[task 2021-12-23T12:28:36.812Z] 12:28:36     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_createMediaKeys_iframes.html | Test timed out. - 
[task 2021-12-23T12:28:37.636Z] 12:28:37     INFO - GECKO(9235) | MEMORY STAT | vsize 20974670MB | residentFast 648MB
[task 2021-12-23T12:29:06.627Z] 12:29:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:29:06.628Z] 12:29:06     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_createMediaKeys_iframes.html | Test timed out. - 
[task 2021-12-23T12:29:07.628Z] 12:29:07    ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-12-23T12:29:07.633Z] 12:29:07     INFO - TEST-UNEXPECTED-ERROR | dom/media/test/test_eme_createMediaKeys_iframes.html | called finish() multiple times
[task 2021-12-23T12:29:07.634Z] 12:29:07     INFO - TEST-INFO took 345645ms
[task 2021-12-23T12:29:36.628Z] 12:29:36     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:29:36.629Z] 12:29:36     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_createMediaKeys_iframes.html | Test timed out. - 
[task 2021-12-23T12:29:37.629Z] 12:29:37    ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-12-23T12:29:37.632Z] 12:29:37     INFO - TEST-UNEXPECTED-ERROR | dom/media/test/test_eme_createMediaKeys_iframes.html | called finish() multiple times
[task 2021-12-23T12:29:37.632Z] 12:29:37     INFO - TEST-INFO 
[task 2021-12-23T12:30:06.630Z] 12:30:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:30:06.630Z] 12:30:06     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_createMediaKeys_iframes.html | Test timed out. - 
[task 2021-12-23T12:30:06.632Z] 12:30:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:30:06.632Z] 12:30:06     INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. - 
[task 2021-12-23T12:30:06.632Z] 12:30:06     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:30:06.633Z] 12:30:06     INFO - TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 30 remaining tests. - 
[task 2021-12-23T12:30:07.631Z] 12:30:07    ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-12-23T12:30:07.634Z] 12:30:07     INFO - TEST-UNEXPECTED-ERROR | (SimpleTest/TestRunner.js) | called finish() multiple times
[task 2021-12-23T12:30:07.634Z] 12:30:07     INFO - TEST-INFO 
[task 2021-12-23T12:36:17.654Z] 12:36:17     INFO - Buffered messages finished
[task 2021-12-23T12:36:17.655Z] 12:36:17    ERROR - TEST-UNEXPECTED-TIMEOUT | (SimpleTest/TestRunner.js) (finished) | application timed out after 370 seconds with no output
[task 2021-12-23T12:36:17.655Z] 12:36:17    ERROR - Force-terminating active process(es).
[task 2021-12-23T12:36:17.655Z] 12:36:17     INFO - Determining child pids from psutil...
[task 2021-12-23T12:36:17.660Z] 12:36:17     INFO - [9312, 9335, 9337, 9395, 9431, 9468, 9498, 9611]
[task 2021-12-23T12:36:17.660Z] 12:36:17     INFO - ==> process 9235 launched child process 9251
[task 2021-12-23T12:36:17.664Z] 12:36:17     INFO - ==> process 9235 launched child process 9312
[task 2021-12-23T12:36:17.664Z] 12:36:17     INFO - ==> process 9235 launched child process 9334
[task 2021-12-23T12:36:17.665Z] 12:36:17     INFO - ==> process 9235 launched child process 9335
[task 2021-12-23T12:36:17.665Z] 12:36:17     INFO - ==> process 9235 launched child process 9337
[task 2021-12-23T12:36:17.667Z] 12:36:17     INFO - ==> process 9235 launched child process 9395
[task 2021-12-23T12:36:17.667Z] 12:36:17     INFO - ==> process 9235 launched child process 9431
[task 2021-12-23T12:36:17.671Z] 12:36:17     INFO - ==> process 9235 launched child process 9468
[task 2021-12-23T12:36:17.672Z] 12:36:17     INFO - ==> process 9235 launched child process 9498
[task 2021-12-23T12:36:17.672Z] 12:36:17     INFO - ==> process 9235 launched child process 9505
[task 2021-12-23T12:36:17.672Z] 12:36:17     INFO - ==> process 9235 launched child process 9518
[task 2021-12-23T12:36:17.673Z] 12:36:17     INFO - ==> process 9235 launched child process 9600
[task 2021-12-23T12:36:17.673Z] 12:36:17     INFO - ==> process 9235 launched child process 9611
[task 2021-12-23T12:36:17.673Z] 12:36:17     INFO - Found child pids: {9312, 9505, 9600, 9251, 9611, 9518, 9395, 9334, 9431, 9337, 9498, 9468, 9335}
[task 2021-12-23T12:36:17.673Z] 12:36:17     INFO - Failed to get child procs
[task 2021-12-23T12:36:17.673Z] 12:36:17     INFO - Killing process: 9312
[task 2021-12-23T12:36:17.673Z] 12:36:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:36:17.673Z] 12:36:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:36:47.709Z] 12:36:47     INFO - failed to kill pid 9312 after 30s
[task 2021-12-23T12:36:47.710Z] 12:36:47     INFO - Killing process: 9505
[task 2021-12-23T12:36:47.710Z] 12:36:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:36:47.710Z] 12:36:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:36:47.711Z] 12:36:47     INFO - Error: Failed to kill process 9505: psutil.NoSuchProcess no process found with pid 9505
[task 2021-12-23T12:36:47.711Z] 12:36:47     INFO - Killing process: 9600
[task 2021-12-23T12:36:47.711Z] 12:36:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:36:47.711Z] 12:36:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:36:47.712Z] 12:36:47     INFO - Error: Failed to kill process 9600: psutil.NoSuchProcess no process found with pid 9600
[task 2021-12-23T12:36:47.712Z] 12:36:47     INFO - Killing process: 9251
[task 2021-12-23T12:36:47.712Z] 12:36:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:36:47.712Z] 12:36:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:36:47.713Z] 12:36:47     INFO - Error: Failed to kill process 9251: psutil.NoSuchProcess no process found with pid 9251
[task 2021-12-23T12:36:47.713Z] 12:36:47     INFO - Killing process: 9611
[task 2021-12-23T12:36:47.713Z] 12:36:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:36:47.713Z] 12:36:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - failed to kill pid 9611 after 30s
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - Killing process: 9518
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - Error: Failed to kill process 9518: psutil.NoSuchProcess no process found with pid 9518
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - Killing process: 9395
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:37:17.755Z] 12:37:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:37:47.798Z] 12:37:47     INFO - failed to kill pid 9395 after 30s
[task 2021-12-23T12:37:47.798Z] 12:37:47     INFO - Killing process: 9334
[task 2021-12-23T12:37:47.799Z] 12:37:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:37:47.800Z] 12:37:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:37:47.800Z] 12:37:47     INFO - Error: Failed to kill process 9334: psutil.NoSuchProcess no process found with pid 9334
[task 2021-12-23T12:37:47.801Z] 12:37:47     INFO - Killing process: 9431
[task 2021-12-23T12:37:47.801Z] 12:37:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:37:47.802Z] 12:37:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:38:17.843Z] 12:38:17     INFO - failed to kill pid 9431 after 30s
[task 2021-12-23T12:38:17.843Z] 12:38:17     INFO - Killing process: 9337
[task 2021-12-23T12:38:17.843Z] 12:38:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:38:17.844Z] 12:38:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:38:47.894Z] 12:38:47     INFO - failed to kill pid 9337 after 30s
[task 2021-12-23T12:38:47.894Z] 12:38:47     INFO - Killing process: 9498
[task 2021-12-23T12:38:47.894Z] 12:38:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:38:47.894Z] 12:38:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:39:17.942Z] 12:39:17     INFO - failed to kill pid 9498 after 30s
[task 2021-12-23T12:39:17.944Z] 12:39:17     INFO - Killing process: 9468
[task 2021-12-23T12:39:17.945Z] 12:39:17     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:39:17.946Z] 12:39:17     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:39:47.990Z] 12:39:47     INFO - failed to kill pid 9468 after 30s
[task 2021-12-23T12:39:47.990Z] 12:39:47     INFO - Killing process: 9335
[task 2021-12-23T12:39:47.990Z] 12:39:47     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:39:47.990Z] 12:39:47     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:40:18.037Z] 12:40:18     INFO - failed to kill pid 9335 after 30s
[task 2021-12-23T12:40:18.038Z] 12:40:18     INFO - Killing process: 9235
[task 2021-12-23T12:40:18.039Z] 12:40:18     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-23T12:40:18.039Z] 12:40:18     INFO - Can't trigger Breakpad, just killing process
[task 2021-12-23T12:40:48.066Z] 12:40:48     INFO - psutil found pid 9235 dead
[task 2021-12-23T12:40:48.067Z] 12:40:48     INFO - failed to kill pid 9312 after 30s
[task 2021-12-23T12:40:48.067Z] 12:40:48     INFO - failed to kill pid 9395 after 30s
[task 2021-12-23T12:40:48.068Z] 12:40:48     INFO - failed to kill pid 9611 after 30s
[task 2021-12-23T12:40:48.069Z] 12:40:48     INFO - failed to kill pid 9335 after 30s
[task 2021-12-23T12:40:48.069Z] 12:40:48     INFO - failed to kill pid 9468 after 30s
[task 2021-12-23T12:40:48.070Z] 12:40:48     INFO - failed to kill pid 9498 after 30s
[task 2021-12-23T12:40:48.071Z] 12:40:48     INFO - failed to kill pid 9337 after 30s
[task 2021-12-23T12:40:48.071Z] 12:40:48     INFO - failed to kill pid 9431 after 30s
[task 2021-12-23T12:40:48.072Z] 12:40:48     INFO - psutil found pid 9235 dead
[task 2021-12-23T12:40:48.073Z] 12:40:48     INFO - TEST-INFO | Main app process: exit 0

Comment 1

[Intermittent Failures Robot]

1 failures in 2286 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-asan-qr: 1
  • opt: 1

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1747395&startday=2022-01-03&endday=2022-01-09&tree=all

Comment 3

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

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