Intermittent test_mediarecorder_principals.html | mediaRecorder.onerror must fire SecurityError

RESOLVED FIXED in Firefox -esr60

Status

()

P3
normal
Rank:
25
RESOLVED FIXED
3 years ago
10 months ago

People

(Reporter: cbook, Assigned: jib)

Tracking

({intermittent-failure})

unspecified
mozilla62
intermittent-failure
Points:
---
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox-esr60 fixed, firefox61 fixed, firefox62 fixed)

Details

(URL)

Attachments

(3 attachments)

(Reporter)

Description

3 years ago
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
Comment hidden (Intermittent Failures Robot)
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.
Comment hidden (Intermittent Failures Robot)
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+
(Reporter)

Comment 16

3 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/e4711157125b
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox49: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
Still happening.
Status: RESOLVED → REOPENED
status-firefox49: fixed → ---
Resolution: FIXED → ---
Target Milestone: mozilla49 → ---
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Mass change P2->P3 to align with new Mozilla triage process.
Priority: P2 → P3
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
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)
Comment hidden (Intermittent Failures Robot)
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 hidden (mozreview-request)
Comment hidden (mozreview-request)

Comment 50

10 months ago
mozreview-review
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+

Comment 51

10 months ago
mozreview-review
Comment on attachment 8984397 [details]
Bug 1266345 - Re-enable test on linux64.

https://reviewboard.mozilla.org/r/250220/#review256546
Attachment #8984397 - Flags: review?(bvandyk) → review+

Comment 53

10 months ago
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?
Blocks: 1208371
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+

Comment 58

10 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/0bcaf31fab70
https://hg.mozilla.org/mozilla-central/rev/0e691269f2a0
Status: REOPENED → RESOLVED
Last Resolved: 3 years ago10 months ago
status-firefox62: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla62
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.