1747644 - Intermittent TEST-UNEXPECTED-TIMEOUT | dom/media/test/browser/browser_encrypted_play_time_telemetry.js | application timed out after 370 seconds with no output

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

[task 2021-12-26T12:08:54.772Z] 12:08:54     INFO - TEST-PASS | dom/media/test/browser/browser_encrypted_play_time_telemetry.js | Should have a play time greater than zero - 
[task 2021-12-26T12:08:54.772Z] 12:08:54     INFO - Leaving test bound testChangingFromEncryptedToUnencrypted
[task 2021-12-26T12:08:54.772Z] 12:08:54     INFO - Entering test bound testChangingFromEncryptedToUnencryptedAndClearingMediaKeys
[task 2021-12-26T12:08:54.772Z] 12:08:54     INFO - Buffered messages finished
[task 2021-12-26T12:08:54.773Z] 12:08:54    ERROR - TEST-UNEXPECTED-TIMEOUT | dom/media/test/browser/browser_encrypted_play_time_telemetry.js | application timed out after 370 seconds with no output
[task 2021-12-26T12:08:54.773Z] 12:08:54    ERROR - Force-terminating active process(es).
[task 2021-12-26T12:08:54.774Z] 12:08:54     INFO - Determining child pids from psutil...
[task 2021-12-26T12:08:54.774Z] 12:08:54     INFO - [8956]
[task 2021-12-26T12:08:54.774Z] 12:08:54     INFO - ==> process 8956 launched child process 1216 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.0.1697592057\1988394378" -parentBuildID 20211226101207 -prefsHandle 2160 -prefMapHandle 2152 -prefsLen 1 -prefMapSize 257252 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 2216 28611defb48 gpu)
[task 2021-12-26T12:08:54.775Z] 12:08:54     INFO - ==> process 8956 launched child process 1484 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.1.1372023326\1825568148" -childID 1 -isForBrowser -prefsHandle 2876 -prefMapHandle 2872 -prefsLen 1790 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 2884 28615c58448 tab)
[task 2021-12-26T12:08:54.776Z] 12:08:54     INFO - ==> process 8956 launched child process 4176 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.3.1128702356\1878288787" -childID 2 -isForBrowser -prefsHandle 3260 -prefMapHandle 3228 -prefsLen 1969 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 3244 28617e7df48 tab)
[task 2021-12-26T12:08:54.777Z] 12:08:54     INFO - ==> process 8956 launched child process 8204 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.5.1522363686\1297468484" -childID 3 -isForBrowser -prefsHandle 3412 -prefMapHandle 3408 -prefsLen 2009 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 3396 2860586b948 tab)
[task 2021-12-26T12:08:54.777Z] 12:08:54     INFO - ==> process 8956 launched child process 8580 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.8.1477893700\416606051" -childID 4 -isForBrowser -prefsHandle 4184 -prefMapHandle 4180 -prefsLen 9617 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 3956 2861a3eb848 tab)
[task 2021-12-26T12:08:54.778Z] 12:08:54     INFO - ==> process 8956 launched child process 6736 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.10.755220449\1489412765" -childID 5 -isForBrowser -prefsHandle 4308 -prefMapHandle 3612 -prefsLen 9785 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 4364 2861a3ea948 tab)
[task 2021-12-26T12:08:54.779Z] 12:08:54     INFO - ==> process 8956 launched child process 7764 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.12.112978628\1060229248" -childID 6 -isForBrowser -prefsHandle 4160 -prefMapHandle 4348 -prefsLen 10287 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 4660 28605869e48 tab)
[task 2021-12-26T12:08:54.779Z] 12:08:54     INFO - ==> process 8956 launched child process 4196 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.14.214056207\107635567" -childID 7 -isForBrowser -prefsHandle 4824 -prefMapHandle 4844 -prefsLen 10555 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 5008 28605867948 tab)
[task 2021-12-26T12:08:54.780Z] 12:08:54     INFO - ==> process 8956 launched child process 1508 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.15.67727727\1820663781" -childID 8 -isForBrowser -prefsHandle 4836 -prefMapHandle 4840 -prefsLen 10555 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 4168 2861aa46e48 tab)
[task 2021-12-26T12:08:54.781Z] 12:08:54     INFO - ==> process 8956 launched child process 6956 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.18.1832112103\1430759796" -parentBuildID 20211226101207 -prefsHandle 4984 -prefMapHandle 5288 -prefsLen 10727 -prefMapSize 257252 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 5384 2861dd55748 rdd)
[task 2021-12-26T12:08:54.782Z] 12:08:54     INFO - ==> process 8956 launched child process 4220 ("Z:\task_164051681795493\build\application\firefox\plugin-container.exe" --channel="8956.19.1137934556\1549050548" "Z:\task_164051681795493\build\application\firefox\gmp-clearkey\0.1" -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 4980 2861dd54e48 gmplugin)
[task 2021-12-26T12:08:54.782Z] 12:08:54     INFO - ==> process 8956 launched child process 3636 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.23.1716837391\893355064" -childID 9 -isForBrowser -prefsHandle 5392 -prefMapHandle 5648 -prefsLen 10727 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 5652 2861dd56948 tab)
[task 2021-12-26T12:08:54.783Z] 12:08:54     INFO - ==> process 8956 launched child process 7952 ("Z:\task_164051681795493\build\application\firefox\plugin-container.exe" --channel="8956.27.544762994\673237227" "Z:\task_164051681795493\build\application\firefox\gmp-clearkey\0.1" -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 5588 2861b22f848 gmplugin)
[task 2021-12-26T12:08:54.783Z] 12:08:54     INFO - ==> process 8956 launched child process 7712 ("Z:\task_164051681795493\build\application\firefox\firefox.exe" -contentproc --channel="8956.32.1067695371\1787635772" -childID 10 -isForBrowser -prefsHandle 5016 -prefMapHandle 5020 -prefsLen 10727 -prefMapSize 257252 -jsInitHandle 1332 -jsInitLen 280572 -parentBuildID 20211226101207 -appDir "Z:\task_164051681795493\build\application\firefox\browser" - 8956 "\\.\pipe\gecko-crash-server-pipe.8956" 5436 28605874548 tab)
[task 2021-12-26T12:08:54.784Z] 12:08:54     INFO - Found child pids: {1216, 7712, 8580, 4196, 1508, 8204, 1484, 6956, 4176, 6736, 4220, 7952, 7764, 3636, 8956}
[task 2021-12-26T12:08:54.784Z] 12:08:54     INFO - Failed to get child procs
[task 2021-12-26T12:08:54.784Z] 12:08:54     INFO - Killing process: 1216
[task 2021-12-26T12:08:54.788Z] 12:08:54     INFO - TEST-INFO | started process screenshot
[task 2021-12-26T12:08:54.846Z] 12:08:54     INFO - TEST-INFO | screenshot: exit 0
[task 2021-12-26T12:08:54.850Z] 12:08:54     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\02124aff-494e-4e41-ad97-b9165428cf67.dmp for [1216]
[task 2021-12-26T12:08:54.946Z] 12:08:54     INFO - Killing process: 7712
[task 2021-12-26T12:08:54.961Z] 12:08:54     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:54.961Z] 12:08:54     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\b8196e63-df75-4bce-8b2a-84e345cb369f.dmp for [7712]
[task 2021-12-26T12:08:55.015Z] 12:08:55     INFO - Killing process: 8580
[task 2021-12-26T12:08:55.020Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.020Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\acc79704-98c1-4a70-be0e-a84cd008532b.dmp for [8580]
[task 2021-12-26T12:08:55.064Z] 12:08:55     INFO - Killing process: 4196
[task 2021-12-26T12:08:55.073Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.073Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\c2c32e11-498a-4a84-8615-e20daaa662c8.dmp for [4196]
[task 2021-12-26T12:08:55.074Z] 12:08:55  WARNING - mozcrash unable to get handle for pid 4196: 87
[task 2021-12-26T12:08:55.074Z] 12:08:55  WARNING - mozcrash kill_pid(): unable to get handle for pid 4196: 87
[task 2021-12-26T12:08:55.074Z] 12:08:55     INFO - Killing process: 1508
[task 2021-12-26T12:08:55.075Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.075Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\2d93885b-d052-4b35-973e-11e30c1cc2b0.dmp for [1508]
[task 2021-12-26T12:08:55.131Z] 12:08:55     INFO - Killing process: 8204
[task 2021-12-26T12:08:55.133Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.133Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\7c416a76-556c-4cbf-b9d1-d2bcbe7c9224.dmp for [8204]
[task 2021-12-26T12:08:55.178Z] 12:08:55     INFO - Killing process: 1484
[task 2021-12-26T12:08:55.187Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.187Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\f929aef3-ae29-4378-9df6-1fad4e2df718.dmp for [1484]
[task 2021-12-26T12:08:55.188Z] 12:08:55  WARNING - mozcrash unable to get handle for pid 1484: 87
[task 2021-12-26T12:08:55.188Z] 12:08:55  WARNING - mozcrash kill_pid(): unable to get handle for pid 1484: 87
[task 2021-12-26T12:08:55.188Z] 12:08:55     INFO - Killing process: 6956
[task 2021-12-26T12:08:55.189Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.189Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\e239a1e4-3853-4610-a51c-7a9774704650.dmp for [6956]
[task 2021-12-26T12:08:55.231Z] 12:08:55     INFO - Killing process: 4176
[task 2021-12-26T12:08:55.234Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.234Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\9bc95a40-0828-44f9-b06c-3edf4eb03168.dmp for [4176]
[task 2021-12-26T12:08:55.279Z] 12:08:55     INFO - Killing process: 6736
[task 2021-12-26T12:08:55.284Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.284Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\217353ba-b236-4090-8e21-f98821bb97bf.dmp for [6736]
[task 2021-12-26T12:08:55.331Z] 12:08:55     INFO - Killing process: 4220
[task 2021-12-26T12:08:55.334Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.334Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\a1df0aff-3761-40bc-8faa-c28e45f389ab.dmp for [4220]
[task 2021-12-26T12:08:55.335Z] 12:08:55  WARNING - mozcrash unable to get handle for pid 4220: 87
[task 2021-12-26T12:08:55.335Z] 12:08:55  WARNING - mozcrash kill_pid(): unable to get handle for pid 4220: 87
[task 2021-12-26T12:08:55.335Z] 12:08:55     INFO - Killing process: 7952
[task 2021-12-26T12:08:55.335Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.336Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\d947e278-50b2-4b21-b48d-a4597b3c7060.dmp for [7952]
[task 2021-12-26T12:08:55.336Z] 12:08:55  WARNING - mozcrash unable to get handle for pid 7952: 87
[task 2021-12-26T12:08:55.337Z] 12:08:55  WARNING - mozcrash kill_pid(): unable to get handle for pid 7952: 87
[task 2021-12-26T12:08:55.337Z] 12:08:55     INFO - Killing process: 7764
[task 2021-12-26T12:08:55.337Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.338Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\fde7f9b3-2bdc-45b4-94b1-511a66862d2f.dmp for [7764]
[task 2021-12-26T12:08:55.338Z] 12:08:55  WARNING - mozcrash unable to get handle for pid 7764: 87
[task 2021-12-26T12:08:55.338Z] 12:08:55  WARNING - mozcrash kill_pid(): unable to get handle for pid 7764: 87
[task 2021-12-26T12:08:55.338Z] 12:08:55     INFO - Killing process: 3636
[task 2021-12-26T12:08:55.339Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.339Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\8fc0a755-83a5-47e1-ad66-89a1826e2475.dmp for [3636]
[task 2021-12-26T12:08:55.367Z] 12:08:55     INFO - Killing process: 8956
[task 2021-12-26T12:08:55.382Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.382Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\7f95cd03-8603-437a-8161-86d7a4428037.dmp for [8956]
[task 2021-12-26T12:08:55.516Z] 12:08:55     INFO - Killing process: 8624
[task 2021-12-26T12:08:55.528Z] 12:08:55     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-26T12:08:55.528Z] 12:08:55     INFO - mozcrash Writing a dump to C:\Users\task_164051681795493\AppData\Local\Temp\tmpitcxvyd2.mozrunner\minidumps\454a157b-3917-4e42-bd80-37787d9274a5.dmp for [8624]
[task 2021-12-26T12:08:55.530Z] 12:08:55  WARNING - mozcrash unable to dump minidump file for pid 8624: -2147024597
[task 2021-12-26T12:08:55.530Z] 12:08:55  WARNING - mozcrash kill_pid(): unable to terminate pid 8624: 5
[task 2021-12-26T12:08:55.532Z] 12:08:55     INFO - psutil found pid 8624 dead
[task 2021-12-26T12:08:55.532Z] 12:08:55     INFO - TEST-INFO | Main app process: exit 1
[task 2021-12-26T12:08:55.532Z] 12:08:55     INFO - Buffered messages finished
[task 2021-12-26T12:08:55.533Z] 12:08:55    ERROR - TEST-UNEXPECTED-FAIL | dom/media/test/browser/browser_encrypted_play_time_telemetry.js | application terminated with exit code 1
[task 2021-12-26T12:08:55.533Z] 12:08:55     INFO - runtests.py | Application ran for: 0:06:19.129630
[task 2021-12-26T12:08:55.533Z] 12:08:55     INFO - zombiecheck | Reading PID log: C:\Users\task_164051681795493\AppData\Local\Temp\tmp8h01bg40pidlog

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:

• windows10-64-2004-qr: 1
  • opt: 1

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

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1747644&startday=2021-12-27&endday=2022-01-02&tree=all

Comment 3

[BugBot [:suhaib / :marco]]

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