Closed Bug 1266345 Opened 8 years ago Closed 6 years ago

Intermittent test_mediarecorder_principals.html | mediaRecorder.onerror must fire SecurityError

Categories

(Core :: Audio/Video: Recording, defect, P3)

Product:
Core
Component:
Audio/Video: Recording
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla62
Tracking Flags:
Tracking Status
firefox-esr60 --- fixed
firefox61 --- fixed
firefox62 --- fixed

People

(Reporter: cbook, Assigned: jib)

References

(
URL
)

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

MozReview Request: Bug 1266345 - disable test_mediarecorder_principals.html on linux 64
58 bytes, text/x-review-board-request
jesup
: review+
Details
Bug 1266345 - Let MediaRecorder ignore ended tracks.
59 bytes, text/x-review-board-request
bryce
: review+
RyanVM
: approval-mozilla-beta+
RyanVM
: approval-mozilla-esr60+
Details
Bug 1266345 - Re-enable test on linux64.
59 bytes, text/x-review-board-request
bryce
: review+
Details 
https://treeherder.mozilla.org/logviewer.html#?job_id=26277329&repo=mozilla-inbound

 06:20:22 INFO - 461 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.onerror must fire SecurityError
jib/mt: any idea why this is failing intermittently?
Rank: 25
Component: Audio/Video → Audio/Video: Recording
Flags: needinfo?(martin.thomson)
Flags: needinfo?(jib)
Priority: -- → P2
There are two tests in this file, both relying on partial http requests. The first one works fine, but the second one never redirects. The initial request from the second test [1] starts here (with v2_*):

> 06:20:17     INFO -  Received request for key = v2_11009232
> 06:20:17     INFO -  Response Content-Range = bytes 0-285309/285310
> 06:20:17     INFO -  Response Content-Length = 285310
> 06:20:20     INFO -  --DOCSHELL 0x7f34990eb800 == 3 [pid = 1883] [id = 75]
> 06:20:21     INFO -  TEST-INFO | started process screentopng
> 06:20:22     INFO -  TEST-INFO | screentopng: exit 0

Anyone know what "screentopng" is? If we see this again, I'd be curious to see if it's involved.

> 06:20:22     INFO -  455 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | A valid string reason is expected
> 06:20:22     INFO -  456 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | Reason cannot be empty
> 06:20:22     INFO -  457 INFO video.currentTime = 0.964463
> 06:20:22     INFO -  458 INFO video.currentTime = 1.977329

Gravity waves here, just looking at the times for the last two lines above. How is that possible, even accounting for rounding error? What's further odd is that these two lines seem to be from *from the first test*!

> 06:20:22     INFO -  459 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.start() must throw SecurityError
> 06:20:22     INFO -  460 INFO TEST-PASS | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.start() should not throw here
> 06:20:22     INFO -  461 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_principals.html | mediaRecorder.onerror must fire SecurityError

I thought I'd locked down the partial loader sufficiently in this test, but the seek.ogv file being operated on is only 4 seconds long after all, so I don't know if it's possible for things to be out of whack enough for this file to finish without any redirecting taking place. I suggest we keep an eye on it, and compare with future logs.

[1] http://mxr.mozilla.org/mozilla-central/source/dom/media/test/test_mediarecorder_principals.html?force=1#71
Flags: needinfo?(jib)
Sorry, just noticed the robot in comment 1.

Yeah the "screentopng" seems to be the culprit, whatever it is.

It shows up in the middle of this second test in every intermittent log. Linux x64 debug and asan only. Is there a way to move this thing away from this particular test, or just away in general?
(In reply to Jan-Ivar Bruaroey [:jib] from comment #4)
> Sorry, just noticed the robot in comment 1.
> 
> Yeah the "screentopng" seems to be the culprit, whatever it is.
> 
> It shows up in the middle of this second test in every intermittent log.
> Linux x64 debug and asan only. Is there a way to move this thing away from
> this particular test, or just away in general?

screentopng is a snapshot-the-screen thing run after a failure, that's not a cause, it's an effect.
Flags: needinfo?(jib)
Hmm that makes sense. Pity it throws off the logs so much, to the point of it looking like it happens a whole second before the failure is reported.
Flags: needinfo?(jib)
So the test is failing, because a SecurityError is not thrown within the 4 seconds of the file, because the rigged redirect from all subsequent partial requests isn't happening, because no partial requests apart from the initial one (v2_*) appear to be made by the HTMLMediaElement loader, which is odd, because the test directly ahead of it, loads the same file the same way, and it causes plenty of partial loads (v1_*), as can be seen in the log.

Is there some file caching specific to linux x64 going on, or other unique concurrency behaviors I should be aware of there? Timing wise, things seem to almost be overlapping here. Maybe breaking the two tests into different test files would help?
I'd be fine with disabling this test on linux x64 fwiw. Any takers?
Is the first request forcing a partial load?  That is, does the response include a short range no matter what?
Flags: needinfo?(martin.thomson)
Yes. Both tests work under the same media.cache_size of 192K. Using the log from comment 0 again:

> 06:20:15     INFO -  Received request for key = v1_11009232
> 06:20:15     INFO -  Response Content-Range = bytes 0-285309/285310
> 06:20:15     INFO -  Response Content-Length = 285310

Ironically, seek.ogv is so small (278K) that the initial request includes the entire file (we're probably below some minimum value), but with our tiny buffer, more requests are forthcoming:

> 06:20:15     INFO -  Received request for key = v1_11009232
> 06:20:15     INFO -  Redirecting to http://example.org/tests/dom/media/test/dynamic_redirect.sjs?nested&key=v1_11009232&res=seek.ogv

here's the second request and redirect,

> 06:20:15     INFO -  [Parent 1820] WARNING: NS_ENSURE_TRUE(mCacheEntry) failed: file /home/worker/workspace/build/src/netwerk/protocol/http/nsHttpChannel.cpp, line 4286
> 06:20:15     INFO -  Received request for key = v1_11009232
> 06:20:15     INFO -  Response Content-Range = bytes 32768-285309/285310
> 06:20:15     INFO -  Response Content-Length = 252542

and this is an actual partial request for a chunk of 246K (skipping the first 32K for some reason).

> 06:20:16     INFO -  Received request for key = v1_11009232
> 06:20:16     INFO -  Redirecting to http://example.org/tests/dom/media/test/dynamic_redirect.sjs?nested&key=v1_11009232&res=seek.ogv
> 06:20:16     INFO -  [Parent 1820] WARNING: NS_ENSURE_TRUE(mCacheEntry) failed: file /home/worker/workspace/build/src/netwerk/protocol/http/nsHttpChannel.cpp, line 4286
> 06:20:16     INFO -  Received request for key = v1_11009232
> 06:20:16     INFO -  Response Content-Range = bytes 285310-285310/285310
> 06:20:16     INFO -  Response Content-Length = 1
> 06:20:16     INFO -  [Child 1883] WARNING: NS_ENSURE_TRUE(aRangeStart < aRangeEnd) failed: file /home/worker/workspace/build/src/dom/media/MediaResource.cpp, line 352

And a bonus one where it's getting a byte past the end of the file, which looks like a fence-post error in HTMLMediaElement, but lets not chase that here.

> 06:20:17     INFO -  Received request for key = v2_11009232

And here's comes the second request.
There were no objections in the morning meeting to disabling this on linux x64 for now.
Assignee: nobody → jib
Comment on attachment 8747943 [details]
MozReview Request: Bug 1266345 - disable test_mediarecorder_principals.html on linux 64

https://reviewboard.mozilla.org/r/50081/#review46869
Attachment #8747943 - Flags: review?(rjesup) → review+
https://hg.mozilla.org/mozilla-central/rev/e4711157125b
Status: NEW → RESOLVED
Closed: 8 years ago
status-firefox49: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
Still happening.
Status: RESOLVED → REOPENED
status-firefox49: fixed → ---
Resolution: FIXED → ---
Target Milestone: mozilla49 → ---
Mass change P2->P3 to align with new Mozilla triage process.
Priority: P2 → P3
This is failing very frequently on ESR60 since the uplift of 1453127 to it :(. I also find it a bit comical that this has been skipped on Linux64 since 2016. Can you please take a look, Andreas?
status-firefox61: --- → affected
status-firefox62: --- → affected
status-firefox-esr60: --- → affected
Flags: needinfo?(apehrson)
I caught this in rr and the MediaRecorder error is due to there being 2 video tracks, and MediaRecorder doesn't support recording multiple tracks of the same type. [1]

However, one of the two tracks has already ended, so it can be safely ignored. That fixes it for me locally.


[1] https://searchfox.org/mozilla-central/rev/c621276fbdd9591f52009042d959b9e19b66d49f/dom/media/MediaRecorder.cpp#790
Flags: needinfo?(apehrson)
Comment on attachment 8984396 [details]
Bug 1266345 - Let MediaRecorder ignore ended tracks.

https://reviewboard.mozilla.org/r/250218/#review256544
Attachment #8984396 - Flags: review?(bvandyk) → review+
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/0bcaf31fab70
Let MediaRecorder ignore ended tracks. r=bryce
https://hg.mozilla.org/integration/autoland/rev/0e691269f2a0
Re-enable test on linux64. r=bryce
Comment on attachment 8984396 [details]
Bug 1266345 - Let MediaRecorder ignore ended tracks.

[Approval Request Comment]
If this is not a sec:{high,crit} bug, please state case for ESR consideration: Unblocks bug 1453127 from landing on esr60.
User impact if declined: See bug 1453127
Fix Landed on Version: 62
Risk to taking this patch (and alternatives if risky): Very low risk
String or UUID changes made by this patch: None

See https://wiki.mozilla.org/Release_Management/ESR_Landing_Process for more info.

Approval Request Comment
[Feature/Bug causing the regression]: bug 1208371
[User impact if declined]: An application could unexpectedly be unable to record a MediaStream. A workaround is simple but might not be obvious.
[Is this code covered by automated tests?]: Not explicitly, but it was caught by this intermittent.
[Has the fix been verified in Nightly?]: Not merged yet
[Needs manual test from QE? If yes, steps to reproduce]: No
[List of other uplifts needed for the feature/fix]: None
[Is the change risky?]: No
[Why is the change risky/not risky?]: Trivial fix
[String changes made/needed]: None
Attachment #8984396 - Flags: approval-mozilla-esr60?
Attachment #8984396 - Flags: approval-mozilla-beta?
Comment on attachment 8984396 [details]
Bug 1266345 - Let MediaRecorder ignore ended tracks.

mochitest-mda looks good on autoland, approving for 61.0b13 and ESR 60.1 to unblock the bug 1453127 from getting to the places it needs to be.
Attachment #8984396 - Flags: approval-mozilla-esr60?
Attachment #8984396 - Flags: approval-mozilla-esr60+
Attachment #8984396 - Flags: approval-mozilla-beta?
Attachment #8984396 - Flags: approval-mozilla-beta+
https://hg.mozilla.org/mozilla-central/rev/0bcaf31fab70
https://hg.mozilla.org/mozilla-central/rev/0e691269f2a0
Status: REOPENED → RESOLVED
Closed: 8 years ago → 6 years ago
status-firefox62: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: