Closed Bug 1747171 Opened 2 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | browser/components/contextualidentity/test/browser/browser_eme.js | application timed out after 370 seconds with no output

Categories

(Core :: DOM: Security, defect, P5)

Product:
Core
Component:
DOM: Security
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
97 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox95 --- unaffected
firefox96 --- unaffected
firefox97 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: karlt)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [domsecurity-intermittent])

Attachments

(1 file)

Bug 1747171 don't hold mutex while spinning nested event loop r?peterv
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2021-12-21T23:56:38.094Z] 23:56:38     INFO - TEST-START | browser/components/contextualidentity/test/browser/browser_eme.js
[task 2021-12-21T23:56:46.356Z] 23:56:46     INFO - GECKO(5788) | ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-12-22T00:02:56.364Z] 00:02:56     INFO - Buffered messages logged at 23:56:38
[task 2021-12-22T00:02:56.366Z] 00:02:56     INFO - Entering test bound setup
[task 2021-12-22T00:02:56.367Z] 00:02:56     INFO - Leaving test bound setup
[task 2021-12-22T00:02:56.367Z] 00:02:56     INFO - Entering test bound test
[task 2021-12-22T00:02:56.368Z] 00:02:56     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use <!DOCTYPE html>." {file: "http://example.com/browser/browser/components/contextualidentity/test/browser/empty_file.html" line: 0}]
[task 2021-12-22T00:02:56.369Z] 00:02:56     INFO - Console message: [JavaScript Warning: "Using Encrypted Media Extensions at http://example.com/browser/browser/components/contextualidentity/test/browser/empty_file.html on an insecure (i.e. non-HTTPS) context is deprecated and will soon be removed. You should consider switching to a secure origin such as HTTPS." {file: "chrome://mochitests/content/browser/browser/components/contextualidentity/test/browser/browser_eme.js" line: 121}]
[task 2021-12-22T00:02:56.370Z] 00:02:56     INFO - Console message: MediaKeySystemAccess::GetKeySystemStatus(org.w3.clearkey) result=available msg=''
[task 2021-12-22T00:02:56.371Z] 00:02:56     INFO - Console message: [JavaScript Warning: "Calling navigator.requestMediaKeySystemAccess() (at http://example.com/browser/browser/components/contextualidentity/test/browser/empty_file.html) passing a candidate MediaKeySystemConfiguration containing audioCapabilities or videoCapabilities without a contentType with a codecs string is deprecated and will soon become unsupported." {file: "http://example.com/browser/browser/components/contextualidentity/test/browser/empty_file.html" line: 0}]
[task 2021-12-22T00:02:56.372Z] 00:02:56     INFO - TEST-PASS | browser/components/contextualidentity/test/browser/browser_eme.js | One media key has been added. - 1 == 1 - 
[task 2021-12-22T00:02:56.372Z] 00:02:56     INFO - TEST-PASS | browser/components/contextualidentity/test/browser/browser_eme.js | The key Id of the default container is correct. - 
[task 2021-12-22T00:02:56.373Z] 00:02:56     INFO - Console message: [JavaScript Warning: "This page is in Quirks Mode. Page layout may be impacted. For Standards Mode use <!DOCTYPE html>." {file: "http://example.com/browser/browser/components/contextualidentity/test/browser/empty_file.html" line: 0}]
[task 2021-12-22T00:02:56.374Z] 00:02:56     INFO - Console message: [JavaScript Warning: "Using Encrypted Media Extensions at http://example.com/browser/browser/components/contextualidentity/test/browser/empty_file.html on an insecure (i.e. non-HTTPS) context is deprecated and will soon be removed. You should consider switching to a secure origin such as HTTPS." {file: "chrome://mochitests/content/browser/browser/components/contextualidentity/test/browser/browser_eme.js" line: 190}]
[task 2021-12-22T00:02:56.374Z] 00:02:56     INFO - Console message: MediaKeySystemAccess::GetKeySystemStatus(org.w3.clearkey) result=available msg=''
[task 2021-12-22T00:02:56.375Z] 00:02:56     INFO - Buffered messages finished
[task 2021-12-22T00:02:56.375Z] 00:02:56    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/contextualidentity/test/browser/browser_eme.js | application timed out after 370 seconds with no output
[task 2021-12-22T00:02:56.376Z] 00:02:56    ERROR - Force-terminating active process(es).
[task 2021-12-22T00:02:56.376Z] 00:02:56     INFO - Determining child pids from psutil...
[task 2021-12-22T00:02:56.376Z] 00:02:56     INFO - [2988]
[task 2021-12-22T00:02:56.377Z] 00:02:56     INFO - ==> process 2988 launched child process 2352 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.0.697502379\334596671" -parentBuildID 20211221220806 -prefsHandle 2160 -prefMapHandle 2152 -prefsLen 1 -prefMapSize 257126 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 2216 1ce12df5648 gpu)
[task 2021-12-22T00:02:56.378Z] 00:02:56     INFO - ==> process 2988 launched child process 7072 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.1.58661417\181158913" -childID 1 -isForBrowser -prefsHandle 2872 -prefMapHandle 2868 -prefsLen 1858 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 2892 1ce177ca048 tab)
[task 2021-12-22T00:02:56.379Z] 00:02:56     INFO - ==> process 2988 launched child process 824 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.3.1955112025\1130177962" -childID 2 -isForBrowser -prefsHandle 2120 -prefMapHandle 3300 -prefsLen 2037 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 2088 1ce18fad848 tab)
[task 2021-12-22T00:02:56.380Z] 00:02:56     INFO - ==> process 2988 launched child process 7148 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.5.251162401\1914214208" -childID 3 -isForBrowser -prefsHandle 3472 -prefMapHandle 3476 -prefsLen 2077 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 3540 1ce1319f648 tab)
[task 2021-12-22T00:02:56.380Z] 00:02:56     INFO - ==> process 2988 launched child process 8536 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.8.1796389536\737665785" -childID 4 -isForBrowser -prefsHandle 4172 -prefMapHandle 4168 -prefsLen 10381 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 4136 1ce1b6c5e48 tab)
[task 2021-12-22T00:02:56.381Z] 00:02:56     INFO - ==> process 2988 launched child process 9200 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.9.1878730869\777394875" -childID 5 -isForBrowser -prefsHandle 4196 -prefMapHandle 4208 -prefsLen 10381 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 4220 1ce1d44a748 tab)
[task 2021-12-22T00:02:56.382Z] 00:02:56     INFO - ==> process 2988 launched child process 6700 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.12.1493810428\1479317481" -childID 6 -isForBrowser -prefsHandle 4476 -prefMapHandle 4460 -prefsLen 10409 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 4632 1ce1d44aa48 tab)
[task 2021-12-22T00:02:56.383Z] 00:02:56     INFO - ==> process 2988 launched child process 7064 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.14.1386688151\950723669" -childID 7 -isForBrowser -prefsHandle 4852 -prefMapHandle 1532 -prefsLen 10623 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 4896 1ce06965b48 tab)
[task 2021-12-22T00:02:56.384Z] 00:02:56     INFO - ==> process 2988 launched child process 616 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.15.438332622\1783899141" -childID 8 -isForBrowser -prefsHandle 3020 -prefMapHandle 4744 -prefsLen 10623 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 5056 1ce1d97ba48 tab)
[task 2021-12-22T00:02:56.385Z] 00:02:56     INFO - ==> process 2988 launched child process 8016 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.17.1203664564\1697486008" -childID 9 -isForBrowser -prefsHandle 5156 -prefMapHandle 5160 -prefsLen 10623 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 5144 1ce1eed8848 tab)
[task 2021-12-22T00:02:56.386Z] 00:02:56     INFO - ==> process 2988 launched child process 6520 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.23.2086465771\944863685" -childID 10 -isForBrowser -prefsHandle 5472 -prefMapHandle 5952 -prefsLen 10873 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 5856 1ce06965b48 tab)
[task 2021-12-22T00:02:56.387Z] 00:02:56     INFO - ==> process 2988 launched child process 3004 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.25.1284834709\1898404286" -childID 11 -isForBrowser -prefsHandle 5376 -prefMapHandle 5276 -prefsLen 10873 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 6000 1ce23a92748 tab)
[task 2021-12-22T00:02:56.387Z] 00:02:56     INFO - ==> process 2988 launched child process 8136 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.27.1964101577\1994090604" -childID 12 -isForBrowser -prefsHandle 5288 -prefMapHandle 5252 -prefsLen 10873 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 5312 1ce1fab8148 tab)
[task 2021-12-22T00:02:56.388Z] 00:02:56     INFO - ==> process 2988 launched child process 5800 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.32.1067386416\75974936" -childID 13 -isForBrowser -prefsHandle 5588 -prefMapHandle 5012 -prefsLen 10873 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 5220 1ce1fab7548 tab)
[task 2021-12-22T00:02:56.389Z] 00:02:56     INFO - ==> process 2988 launched child process 1452 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.34.22620955\906445171" -childID 14 -isForBrowser -prefsHandle 5332 -prefMapHandle 5304 -prefsLen 10960 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 5356 1ce1fab9648 tab)
[task 2021-12-22T00:02:56.390Z] 00:02:56     INFO - ==> process 2988 launched child process 5716 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.36.454417241\1767424899" -childID 15 -isForBrowser -prefsHandle 5152 -prefMapHandle 6080 -prefsLen 10960 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 4916 1ce1fab8148 tab)
[task 2021-12-22T00:02:56.391Z] 00:02:56     INFO - ==> process 2988 launched child process 3428 ("Z:\task_164012882916998\build\application\firefox\plugin-container.exe" --channel="2988.38.1434144644\232445322" "Z:\task_164012882916998\build\application\firefox\gmp-clearkey\0.1" -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 5108 1ce16ff3b48 gmplugin)
[task 2021-12-22T00:02:56.391Z] 00:02:56     INFO - ==> process 2988 launched child process 6788 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.39.924038915\339102939" -childID 16 -isForBrowser -prefsHandle 4936 -prefMapHandle 5292 -prefsLen 10960 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 4896 1ce16ff3548 tab)
[task 2021-12-22T00:02:56.392Z] 00:02:56     INFO - ==> process 2988 launched child process 8576 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.40.449141875\619348443" -childID 17 -isForBrowser -prefsHandle 6204 -prefMapHandle 6208 -prefsLen 10960 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 6296 1ce167fb848 tab)
[task 2021-12-22T00:02:56.393Z] 00:02:56     INFO - ==> process 2988 launched child process 6484 ("Z:\task_164012882916998\build\application\firefox\firefox.exe" -contentproc --channel="2988.44.1357101925\1377038463" -childID 18 -isForBrowser -prefsHandle 6268 -prefMapHandle 6320 -prefsLen 10960 -prefMapSize 257126 -jsInitHandle 1316 -jsInitLen 280572 -parentBuildID 20211221220806 -appDir "Z:\task_164012882916998\build\application\firefox\browser" - 2988 "\\.\pipe\gecko-crash-server-pipe.2988" 6252 1ce16ff5648 tab)
[task 2021-12-22T00:02:56.394Z] 00:02:56     INFO - Found child pids: {8576, 6788, 7064, 7072, 5800, 2988, 6700, 1452, 2352, 824, 3004, 8136, 8016, 5716, 6484, 8536, 3428, 616, 7148, 9200, 6520}
[task 2021-12-22T00:02:56.394Z] 00:02:56     INFO - Failed to get child procs
[task 2021-12-22T00:02:56.394Z] 00:02:56     INFO - Killing process: 8576
task 2021-12-22T00:02:56.401Z] 00:02:56     INFO - TEST-INFO | started process screenshot
[task 2021-12-22T00:02:56.464Z] 00:02:56     INFO - TEST-INFO | screenshot: exit 0
[task 2021-12-22T00:02:56.477Z] 00:02:56     INFO - mozcrash Writing a dump to C:\Users\task_164012882916998\AppData\Local\Temp\tmpkm7wfzqv.mozrunner\minidumps\3da19103-8280-4738-9f1d-21d3c72ee692.dmp for [8576]
[task 2021-12-22T00:02:56.549Z] 00:02:56     INFO - Killing process: 6788
[task 2021-12-22T00:02:56.557Z] 00:02:56     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-22T00:02:56.557Z] 00:02:56     INFO - mozcrash Writing a dump to C:\Users\task_164012882916998\AppData\Local\Temp\tmpkm7wfzqv.mozrunner\minidumps\2192c32a-ddf9-4762-9497-c4d37cb6d290.dmp for [6788]
[task 2021-12-22T00:02:56.617Z] 00:02:56     INFO - Killing process: 7064
[task 2021-12-22T00:02:56.617Z] 00:02:56     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-22T00:02:56.618Z] 00:02:56     INFO - mozcrash Writing a dump to C:\Users\task_164012882916998\AppData\Local\Temp\tmpkm7wfzqv.mozrunner\minidumps\fe66a4cf-558c-4fd1-83bc-8f93071cfc52.dmp for [7064]
[task 2021-12-22T00:02:56.618Z] 00:02:56  WARNING - mozcrash unable to get handle for pid 7064: 87
[task 2021-12-22T00:02:56.618Z] 00:02:56  WARNING - mozcrash kill_pid(): unable to get handle for pid 7064: 87
[task 2021-12-22T00:02:56.619Z] 00:02:56     INFO - Killing process: 7072
[task 2021-12-22T00:02:56.619Z] 00:02:56     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-12-22T00:02:56.620Z] 00:02:56     INFO - mozcrash Writing a dump to C:\Users\task_164012882916998\AppData\Local\Temp\tmpkm7wfzqv.mozrunner\minidumps\147752e3-775f-424b-a4b0-3e169c3e1fa6.dmp for [7072]
[task 2021-12-22T00:02:56.620Z] 00:02:56  WARNING - mozcrash unable to get handle for pid 7072: 87
[task 2021-12-22T00:02:56.620Z] 00:02:56  WARNING - mozcrash kill_pid(): unable to get handle for pid 7072: 87

Karl, do you have an idea what started these EME failures (Bryce is away for some time)?

status-firefox95: --- → unaffected
status-firefox96: --- → unaffected
status-firefox97: --- → affected
status-firefox-esr91: --- → unaffected
Flags: needinfo?(karlt)
See Also: → 1747188

Regression from https://hg.mozilla.org/mozilla-central/rev/c8e8cfd5f9d8#l4.415
Can gmp->mMutex be released after the GetThreadLocked() call?

In https://treeherder.mozilla.org/logviewer?job_id=362124941&repo=autoland&lineNumber=4024, for example:

  1. On the main thread, GMPServiceParent::Create() spins the event loop with GeckoMediaPluginServiceParent::mMutex held.
  2. While processing tasks in the nested event loop, ContentParent::LaunchSubprocessResolve() calls GeckoMediaPluginServiceParent::UpdateContentProcessGMPCapabilities(), which waits for GeckoMediaPluginServiceParent::mMutex.
Flags: needinfo?(karlt)
Regressed by: 1746907
Has Regression Range: --- → yes
Keywords: regression
Flags: needinfo?(rjesup)
Summary: Intermittent [Tier 2] TEST-UNEXPECTED-TIMEOUT | browser/components/contextualidentity/test/browser/browser_eme.js | application timed out after 370 seconds with no output → Intermittent TEST-UNEXPECTED-TIMEOUT | browser/components/contextualidentity/test/browser/browser_eme.js | application timed out after 370 seconds with no output
Assignee: nobody → karlt
Status: NEW → ASSIGNED

(In reply to Karl Tomlinson (:karlt) from comment #3)

Can gmp->mMutex be released after the GetThreadLocked() call?

The change to ServiceUserCreated() expects the lock to be held across GMPServiceParent construction.

Flags: needinfo?(rjesup)

This reverts an unnecessary broadening of Mutex acquisition from
https://hg.mozilla.org/mozilla-central/rev/c8e8cfd5f9d8#l4.415
and also removes an unnecessary debug-only lock that was added and might have
caused a difference in behavior between debug and optimized builds.

The main-thread-only access of mShuttingDown is now asserted instead of
protected by the mutex.

I r+'d karl's patch, thanks!

Pushed by ktomlinson@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/70e8c739dd2d
don't hold mutex while spinning nested event loop r=jesup

https://hg.mozilla.org/mozilla-central/rev/70e8c739dd2d

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
status-firefox97: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → 97 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: