Intermittent dom/media/test/test_mediarecorder_principals.html | mediaRecorder.start() must throw SecurityError

RESOLVED FIXED in Firefox 56

Status

()

defect
P1
normal
Rank:
19
RESOLVED FIXED
2 years ago
Last year

People

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

Tracking

({intermittent-failure})

unspecified
mozilla57
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox56 fixed, firefox57 fixed)

Details

(Whiteboard: [stockwell fixed])

Attachments

(3 attachments)

this picked up in failure rate in the last wee.  Starting on June 7th, we had a few failures, then by June 11th the failure rate was really high.  This is a debug only failure on non-e10s, primarily on windows 7/8.  There are 45+ failures in the last week.

a recent windows 7 failure:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-inbound&job_id=107579941&lineNumber=11150

shows this screenshot:
https://public-artifacts.taskcluster.net/bSCwFuEQRFu8PCt2Iqtfuw/0/public/test_info/mozilla-test-fail-screenshot_pxcooc.png

and this is the data in the log:
07:01:53     INFO -  405 INFO TEST-START | dom/media/test/test_mediarecorder_principals.html
07:01:53     INFO -  GECKO(3964) | ++DOMWINDOW == 24 (15719800) [pid = 3964] [serial = 341] [outer = 1B4C6800]
07:01:54     INFO -  GECKO(3964) | ++DOCSHELL 19777400 == 6 [pid = 3964] [id = {542f5abb-4c94-4540-8668-d9655d30c45c}]
07:01:54     INFO -  GECKO(3964) | ++DOMWINDOW == 25 (19777C00) [pid = 3964] [serial = 342] [outer = 00000000]
07:01:54     INFO -  GECKO(3964) | ++DOMWINDOW == 26 (19779C00) [pid = 3964] [serial = 343] [outer = 19777C00]
07:01:54     INFO -  Received request for key = v1_14896837
07:01:54     INFO -  Response Content-Range = bytes 0-285309/285310
07:01:54     INFO -  Response Content-Length = 285310
07:01:55     INFO -  GECKO(3964) | --DOMWINDOW == 25 (14A73000) [pid = 3964] [serial = 332] [outer = 00000000] [url = about:blank]
07:01:55     INFO -  GECKO(3964) | --DOMWINDOW == 24 (119E8400) [pid = 3964] [serial = 328] [outer = 00000000] [url = about:blank]
07:01:55     INFO -  GECKO(3964) | [3964] WARNING: file z:/build/build/src/ipc/chromium/src/base/message_loop.cc, line 280
07:01:55     INFO -  GECKO(3964) | [3964] WARNING: file z:/build/build/src/ipc/chromium/src/base/message_loop.cc, line 280
07:01:57     INFO -  [3932] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/toolkit/components/places/Database.cpp, line 727
07:01:57     INFO -  [3932] WARNING: NS_ENSURE_TRUE(mDB) failed: file z:/build/build/src/toolkit/components/places/nsNavHistory.cpp, line 315
07:01:57     INFO -  JavaScript error: resource://gre/modules/FormHistory.jsm, line 379: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]
07:01:57     INFO -  [3932] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file z:/build/build/src/toolkit/components/places/Database.cpp, line 727
07:01:57     INFO -  [3932] WARNING: NS_ENSURE_TRUE(mDB) failed: file z:/build/build/src/toolkit/components/places/nsNavHistory.cpp, line 315
07:01:57     INFO -  [3932] WARNING: NS_ENSURE_SUCCESS(rv, NS_ERROR_XPC_GS_RETURNED_FAILURE) failed with result 0x8007000E: file z:/build/build/src/js/xpconnect/src/XPCJSID.cpp, line 698
07:01:57     INFO -  [3932] WARNING: file z:/build/build/src/ipc/chromium/src/base/message_loop.cc, line 280
07:01:57     INFO -  [3932] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/dom/quota/ActorsParent.cpp, line 2617
07:01:57     INFO -  [3932] WARNING: 'NS_FAILED(rv)', file z:/build/build/src/dom/quota/ActorsParent.cpp, line 2780
07:01:57     INFO -  [3932] WARNING: '!quotaManager', file z:/build/build/src/dom/quota/ActorsParent.cpp, line 6326
07:01:57     INFO -  TEST-INFO | started process screenshot
07:01:57     INFO -  Received request for key = v2_14896837
07:01:57     INFO -  Response Content-Range = bytes 0-285309/285310
07:01:57     INFO -  Response Content-Length = 285310
07:01:57     INFO -  TEST-INFO | screenshot: exit 0
07:01:57     INFO -  Buffered messages logged at 07:01:54
07:01:57     INFO -  406 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | A valid string reason is expected
07:01:57     INFO -  407 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | Reason cannot be empty
07:01:57     INFO -  Buffered messages logged at 07:01:56
07:01:57     INFO -  408 INFO video.currentTime = 0.983
07:01:57     INFO -  Buffered messages logged at 07:01:57
07:01:57     INFO -  409 INFO video.currentTime = 1.965
07:01:57     INFO -  Buffered messages finished
07:01:57    ERROR -  410 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.start() must throw SecurityError
07:01:57     INFO -      testPrincipals/</</</<@dom/media/test/test_mediarecorder_principals.html:67:21
07:01:57     INFO -      promise callback*testPrincipals/</</<@dom/media/test/test_mediarecorder_principals.html:65:19
07:01:57     INFO -      promise callback*testPrincipals/</<@dom/media/test/test_mediarecorder_principals.html:62:14
07:01:57     INFO -      promise callback*testPrincipals/<@dom/media/test/test_mediarecorder_principals.html:57:12
07:01:57     INFO -      promise callback*testPrincipals@dom/media/test/test_mediarecorder_principals.html:46:10
07:01:57     INFO -      @dom/media/test/test_mediarecorder_principals.html:104:1
07:01:57     INFO -  GECKO(3964) | [3964] WARNING: file z:/build/build/src/ipc/chromium/src/base/message_loop.cc, line 280
07:01:57     INFO -  411 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.start() should not throw here
07:01:57     INFO -  GECKO(3964) | [3964] WARNING: file z:/build/build/src/ipc/chromium/src/base/message_loop.cc, line 280
07:01:57     INFO -  GECKO(3964) | [3964] WARNING: NS_ENSURE_TRUE(mCacheEntry) failed: file z:/build/build/src/netwerk/protocol/http/nsHttpChannel.cpp, line 5097
07:01:57     INFO -  Received request for key = v2_14896837
07:01:57     INFO -  Redirecting to http://example.org/tests/dom/media/test/dynamic_redirect.sjs?nested&key=v2_14896837&res=seek.ogv
07:01:57     INFO -  Received request for key = v2_14896837
07:01:57     INFO -  Response Content-Range = bytes 32768-285309/285310
07:01:57     INFO -  Response Content-Length = 252542
07:01:57     INFO -  412 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.onerror must fire SecurityError
07:01:57     INFO -  413 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.onstop must also have fired
07:01:57     INFO -  GECKO(3964) | MEMORY STAT | vsize 790MB | vsizeMaxContiguous 574MB | residentFast 176MB | heapAllocated 104MB
07:01:57     INFO -  414 INFO TEST-OK | dom/media/test/test_mediarecorder_principals.html | took 4012ms


:k17e, I see you are the triage owner, can you find someone from the audio/video: playback team to fix this in the next 2 weeks?
Flags: needinfo?(ajones)
Whiteboard: [stockwell needswork]
Do you want to figure this one out?
Component: Audio/Video: Playback → Audio/Video: Recording
Flags: needinfo?(ajones) → needinfo?(bvandyk)
Sure thing.
Assignee: nobody → bvandyk
Flags: needinfo?(bvandyk)
Rank: 19
Priority: -- → P1
Whiteboard: [stockwell needswork] → [stockwell unknown]
I think the way MediaCache works under the hood (and recent alterations) is leading to this being busted. I've been trying different prefs for the test, but can't get squash the intermittent failures yet. From having had a look the problem appears to be that:
- The test tries to set up a state where multiple requests will need to be made in order to retrieve a resource. The second request will alter the origin resulting in the desired sec error.
- At the moment the test can intermittently retrieve enough of the resource that a second request never need be made, so the sec error is never thrown, resulting in the test failing.

Good news is that this looks like a problem with the test rather than a failure in the recorder. Bad news is that I'm yet to find a way to patch the test, currently waiting on hearing back from people who know more about the MediaCache than I.
Comment on attachment 8888628 [details]
Bug 1371166 - Update media recorder principal test to behave more like MediaElement principal test.

https://reviewboard.mozilla.org/r/159642/#review165164

r=me with a green try-run before landing.

::: dom/media/test/test_mediarecorder_principals.html:34
(Diff revision 1)
> +// This test relies on that preloading the metadata then loading a sufficiently
> +// long video will result in two separate requests to load the resource. This

Is it green on all platforms? I'm a bit surprised as I recall basing this test on test_mixed_principals.html, and originally spending quite some time getting it to work the same way, ending up with the present way instead, as I for some reason wasn't getting two requests that way, at the time.

I'm a fan of end-to-end tests if at all possible, but this may be an example where it might be hard to maintain, so thanks for adding the comment.
Attachment #8888628 - Flags: review?(jib) → review+
Comment on attachment 8888629 [details]
Bug 1371166 - Drive by update to update var -> let in test.

https://reviewboard.mozilla.org/r/159644/#review165168
Attachment #8888629 - Flags: review?(jib) → review+
Pushed by bvandyk@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/736042ec645d
Update media recorder principal test to behave more like MediaElement principal test. r=jib
https://hg.mozilla.org/integration/autoland/rev/955998eefbe8
Drive by update to update var -> let in test. r=jib
Seems to be okay on try so have requested landing. Will try to keep an eye out for if we get any intermittent failures with new code. Agree that end to end tests are good, just not sure we can do so robustly in this case.
https://hg.mozilla.org/mozilla-central/rev/736042ec645d
https://hg.mozilla.org/mozilla-central/rev/955998eefbe8
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
I had to back these out because the test was permafailing like https://treeherder.mozilla.org/logviewer.html#?job_id=116767415&repo=autoland

https://hg.mozilla.org/mozilla-central/rev/bf4634a50775537b4e791b6d294a275b83737472
Status: RESOLVED → REOPENED
Flags: needinfo?(bvandyk)
Resolution: FIXED → ---
Target Milestone: mozilla56 → ---
Still looking at this, but it's a slow going as the issue appears to be windows 8 specific and I'm debugging via try.
Flags: needinfo?(bvandyk)
The updates to the tests may be impacted by bug 1386033, certainly the long timeouts rather than the videos playing through (which is still a failure case if we get no error) is being caused by the bug.
Depends on: 1386033
Comment on attachment 8897645 [details]
Bug 1371166 - Explicitly load videos via video.load to get a cross origin requests to take place.

https://reviewboard.mozilla.org/r/168904/#review174642
Attachment #8897645 - Flags: review?(jib) → review+
Pushed by bvandyk@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e177651cbe61
Update media recorder principal test to behave more like MediaElement principal test. r=jib
https://hg.mozilla.org/integration/autoland/rev/72f9ce682a28
Drive by update to update var -> let in test. r=jib
https://hg.mozilla.org/integration/autoland/rev/9fae68b13ef9
Explicitly load videos via video.load to get a cross origin requests to take place. r=jib
https://hg.mozilla.org/mozilla-central/rev/e177651cbe61
https://hg.mozilla.org/mozilla-central/rev/72f9ce682a28
https://hg.mozilla.org/mozilla-central/rev/9fae68b13ef9
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
You need to log in before you can comment on or make changes to this bug.