1403307 - Intermittent dom/media/test/test_mediarecorder_pause_resume_video.html | Last frame should be green

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: wkocher [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=133374373&repo=autoland

https://archive.mozilla.org/pub/firefox/tinderbox-builds/autoland-win64-debug/autoland_win10_64-debug_test-mochitest-media-e10s-bm111-tests1-windows-build102.txt.gz

Comment 1

[Intermittent Failures Robot]

29 failures in 195 pushes (0.149 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 16
* mozilla-inbound: 10
* mozilla-central: 3

Platform breakdown:
* windows10-64: 18
* macosx64-stylo-disabled: 5
* osx-10-10: 4
* linux64-stylo-disabled: 1
* linux32-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-09-28&endday=2017-09-28&tree=all

Comment 2

[Intermittent Failures Robot]

25 failures in 163 pushes (0.153 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 11
* autoland: 9
* mozilla-central: 4
* try: 1

Platform breakdown:
* windows10-64: 15
* osx-10-10: 5
* macosx64-stylo-disabled: 3
* linux64-qr: 1
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-09-29&endday=2017-09-29&tree=all

Comment 3

[Intermittent Failures Robot]

96 failures in 885 pushes (0.108 failures/push) were associated with this bug in the last 7 days. 

This is the #16 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 50
* mozilla-inbound: 29
* mozilla-central: 14
* try: 3

Platform breakdown:
* windows10-64: 62
* osx-10-10: 15
* macosx64-stylo-disabled: 11
* linux32-stylo-disabled: 3
* linux32: 3
* linux64-stylo-disabled: 1
* linux64-qr: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-09-25&endday=2017-10-01&tree=all

Comment 4

[Intermittent Failures Robot]

22 failures in 144 pushes (0.153 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 15
* mozilla-inbound: 4
* mozilla-central: 3

Platform breakdown:
* windows10-64: 16
* osx-10-10: 2
* macosx64-stylo-disabled: 2
* linux32: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-10-02&endday=2017-10-02&tree=all

Comment 5

[Intermittent Failures Robot]

22 failures in 173 pushes (0.127 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 18
* mozilla-inbound: 2
* try: 1
* mozilla-central: 1

Platform breakdown:
* windows10-64: 9
* osx-10-10: 6
* macosx64-stylo-disabled: 3
* linux32: 2
* linux64-stylo-disabled: 1
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-10-03&endday=2017-10-03&tree=all

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

this is failing at a very high failure rate, 135 failures in the last week alone- all on debug, but a variety of platforms.

here is a recent windows10 log:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=134865118&lineNumber=10087

and related text from the log:
03:24:40     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Media recorder should be paused 
03:24:40     INFO - Drawing color 0,0,255,1
03:24:40     INFO - Buffered messages logged at 03:24:38
03:24:40     INFO - Drawing color 0,255,0,1
03:24:40     INFO - Buffered messages logged at 03:24:39
03:24:40     INFO - Got 'dataavailable' event
03:24:40     INFO - Got 'stop' event
03:24:40     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Media recorder should be incative after stop 
03:24:40     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Expected 1 dataavailable event 
03:24:40     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Should have gotten a data blob 
03:24:40     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | video element should be same size as canvas once metadata is loaded 
03:24:40     INFO - Buffered messages finished
03:24:40     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_pause_resume_video.html | Last frame should be green 
03:24:40     INFO -     startTest/mediaRecorder.onstop/video.onended@dom/media/test/test_mediarecorder_pause_resume_video.html:104:7
03:24:40     INFO -     EventHandlerNonNull*startTest/mediaRecorder.onstop@dom/media/test/test_mediarecorder_pause_resume_video.html:103:5
03:24:40     INFO -     EventHandlerNonNull*startTest@dom/media/test/test_mediarecorder_pause_resume_video.html:81:3
03:24:40     INFO -     @dom/media/test/test_mediarecorder_pause_resume_video.html:125:1
03:24:40     INFO - GECKO(1416) | MEMORY STAT | vsize 1700MB | vsizeMaxContiguous 132540028MB | residentFast 109MB | heapAllocated 21MB
03:24:40     INFO - TEST-OK | dom/media/test/test_mediarecorder_pause_resume_video.html | took 4255ms


:jib, I see you are the triage owner for av:recording, can you help prioritize this bug and get this in the queue for the right person to look at it?

Comment 7

[Intermittent Failures Robot]

95 failures in 824 pushes (0.115 failures/push) were associated with this bug in the last 7 days. 

This is the #20 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* autoland: 51
* mozilla-inbound: 26
* mozilla-central: 10
* try: 8

Platform breakdown:
* windows10-64: 43
* osx-10-10: 22
* macosx64-stylo-disabled: 9
* linux32: 6
* linux64: 5
* linux64-stylo-disabled: 3
* windows10-64-stylo-disabled: 2
* linux64-qr: 2
* linux32-stylo-disabled: 2
* linux64-ccov: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-10-02&endday=2017-10-08&tree=all

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/f8a337cc1e67
Disable dom/media/test/test_mediarecorder_pause_resume_video.html on debug for frequent failures. r=me, a=test-only

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

please remember to re-enable this test when working on it.

Comment 10

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/f8a337cc1e67

Comment 11

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Bryce, this is a new test you added in bug 1354457. Please take a look. We should turn off the test temporarily if there's not a quick fix, then we can lower priority if needed.

Comment 12

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

I suspect this is a regression due to bug 1296531 landing based on the dates involved. I can repro locally, but it's fairly intermittent.

Rough test schedule:
- Draw red
- Record (red)
- Pause
- Draw blue
- Draw green
- Resume (green)
- Stop

The screenshots indicate the last frame of the video is red, which means the recorder hasn't resumed and captured any of the green frames. Don't know why yet, will continue to look.

Comment 13

[Andreas Pehrson [:pehrsons]]

If you adjust the timing of drawing green vs resume() (i.e., increase the nr of rAFs in between, say 72 instead of 62), does that affect the result?

Comment 14

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Hard to be sure due to the intermittence (100s of iterations without failures for values I know can fail), but here are some results we me changing the resume value (while leaving draw green at 60):
62 (default): can repro
63: can repro
64: can repro
65+: haven't been able to repro

If I change the value of when we draw green to 30 or 50 I'm unable to repro at all across a range of resume values.

Due to the intermittence I'd talk these with some big grains of salt, but hopefully it's more useful than no data.

Comment 15

[Andreas Pehrson [:pehrsons]]

Clearly there's a larger than anticipated delay between drawing a frame (it should be captured at the end of requestAnimationFrame()), until it gets into MSG (on the next MSG iteration in NotifyPull()) and further all the way through MediaRecorder (the encoder TaskQueue basically).

Some logging that would be useful would be when a new frame arrives to the TaskQueue vs Resume(); when a new frame is handled by the TaskQueue vs Resume(); and when we forward mLastChunk to the encoder on end-of-stream.

Comment 16

[Intermittent Failures Robot]

23 failures in 947 pushes (0.024 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 12
* mozilla-inbound: 5
* mozilla-central: 4
* try: 2

Platform breakdown:
* linux64: 9
* macosx64-stylo-disabled: 5
* windows10-64: 3
* osx-10-10: 3
* linux64-qr: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-10-09&endday=2017-10-15&tree=all

Comment 17

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Could you elaborate on what you think is going on with the pause and resume and the delays. I would have thought if we're seeing delays in delivery of frames then shifting the resume to take place later would not alleviate the issue.

Questions to help clarify my understanding and allow me to look at/add appropriate logs: by the time requestAnimationFrame has run draw(), the color of the canvas will be stable, as will the state of the recorder? How does/should this interact with the MSG and drivers? Do we have any guarantees that drivers don't tick during JS execution (I believe not)?

The MSG performs a pull on the data from the canvas (via NotifyPull)? This data is used by SetCurrentFrames (MSG thread) and sent to AppendVideoSegment (MediaRecorder thread), further down the MSG processing pipeline this data is again processed by NotifyQueuedChanges (MSG thread) and sent to AdvanceCurrentTime (MediaRecorder thread), which we use to null queued data when suspended? As above, is there any sync here between the main thread and these? Does the MSG need to hit mainthread to pull form the canvas?

Chrome seem to do some syncing to make sure their recorder and canvas are synced (this pen is an extreme example: https://codepen.io/SingingTree/full/eGZdQX/). I need to investigate what happens if we're doing drawing with workers. Despite that the regression concerns me, I wonder also if this test is entirely sane given what I've learnt since first writing it.

Comment 18

[Andreas Pehrson [:pehrsons]]

When we draw() in the requestAnimationFrame() callback, there's not really an async step until the capture happens. It happens late during the RefreshDriver Tick on main thread (rAF happens earlier).

However, when we capture a frame (let's call this A), we don't immediately append it to the captured track, [1].

It takes until the next MSG iteration's NotifyPull() to append the new frame, [2] (let's call this B).
(note that in the long term this will change to append immediately -- we need to get rid of the notion of a duration from video chunks first, and preferably some locking from AppendToTrack. But doing this should help your codepen with sync.)

When this AppendToTrack() happens, MediaRecorder receives the new frame immediately (since it uses a direct track listener) and dispatches the frame to VideoTrackEncoder::AppendVideoSegment() on the encoder thread, [3] (let's call this C)

As far as races go, a frame takes this path:
A - MainThread
B - MSG thread
C - Encoder thread

While Resume() takes this path:
MediaRecorder::Resume() - MainThread
TrackEncoder::Resume() - Encoder thread

B is the difference here, and B is dependent on audio callbacks for the current output device (when audio is present in the MSG, or on a timer if there's no audio -- we try to keep iterations to 10ms, [4]). Since you managed to get rid of the intermittent behavior by only changing timing of draw() or Resume(), I assume the race is somehow between B and Resume(), and not between B and Stop().

As the next step I'd look for anomalies in the timing between B and Resume() as they come in on the encoder thread (wherever you can repro). If you see a pattern there it should be simple to reproduce in a gtest and if needed debug that with RR.

VideoTrackEncoder::AdvanceCurrentTime might be interesting to log too, since it also reads mSuspended, and it tells you how long the MSG iterations are.



[1] http://searchfox.org/mozilla-central/rev/40b456626e2d0409b7034768b4d9526fc7235ea4/dom/media/CanvasCaptureMediaStream.cpp#208
[2] http://searchfox.org/mozilla-central/rev/40b456626e2d0409b7034768b4d9526fc7235ea4/dom/media/CanvasCaptureMediaStream.cpp#65
[3] http://searchfox.org/mozilla-central/rev/40b456626e2d0409b7034768b4d9526fc7235ea4/dom/media/encoder/TrackEncoder.cpp#453
[4] http://searchfox.org/mozilla-central/rev/40b456626e2d0409b7034768b4d9526fc7235ea4/dom/media/GraphDriver.h#38

Comment 19

[Intermittent Failures Robot]

6 failures in 864 pushes (0.007 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* mozilla-inbound: 1
* mozilla-central: 1

Platform breakdown:
* linux64: 5
* macosx64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-10-16&endday=2017-10-22&tree=all

Comment 20

[Intermittent Failures Robot]

8 failures in 912 pushes (0.009 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 5
* mozilla-inbound: 3

Platform breakdown:
* linux64: 7
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-10-23&endday=2017-10-29&tree=all

Comment 21

[Intermittent Failures Robot]

21 failures in 857 pushes (0.025 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 12
* mozilla-inbound: 8
* try: 1

Platform breakdown:
* linux64: 20
* linux64-qr: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-10-30&endday=2017-11-05&tree=all

Comment 22

[Intermittent Failures Robot]

14 failures in 849 pushes (0.016 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* mozilla-inbound: 4
* mozilla-central: 4

Platform breakdown:
* linux64: 14

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-11-06&endday=2017-11-12&tree=all

Comment 23

[Intermittent Failures Robot]

16 failures in 762 pushes (0.021 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 8
* autoland: 6
* mozilla-central: 2

Platform breakdown:
* linux64: 16

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-11-13&endday=2017-11-19&tree=all

Comment 24

[Intermittent Failures Robot]

19 failures in 744 pushes (0.026 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 8
* autoland: 8
* mozilla-central: 2
* mozilla-beta: 1

Platform breakdown:
* linux64: 19

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-11-20&endday=2017-11-26&tree=all

Comment 25

[Intermittent Failures Robot]

11 failures in 792 pushes (0.014 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* mozilla-inbound: 4
* mozilla-central: 1

Platform breakdown:
* linux64: 11

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-11-27&endday=2017-12-03&tree=all

Comment 26

[Intermittent Failures Robot]

20 failures in 889 pushes (0.022 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 10
* mozilla-inbound: 9
* mozilla-central: 1

Platform breakdown:
* linux64: 20

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-04&endday=2017-12-10&tree=all

Comment 27

[Intermittent Failures Robot]

9 failures in 423 pushes (0.021 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 4
* mozilla-inbound: 3
* mozilla-central: 2

Platform breakdown:
* linux64: 7
* linux64-qr: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-11&endday=2017-12-17&tree=all

Comment 28

[Intermittent Failures Robot]

18 failures in 97 pushes (0.186 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 7
* autoland: 7
* mozilla-central: 3
* mozilla-beta: 1

Platform breakdown:
* linux64: 18

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-18&endday=2017-12-18&tree=all

Comment 29

[Intermittent Failures Robot]

18 failures in 108 pushes (0.167 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 8
* autoland: 8
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux64: 18

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-20&endday=2017-12-20&tree=all

Comment 30

[Geoff Brown [:gbrown]]

All current failures are linux/asan. There was an increase in failure frequency around Dec 18.

Comment 31

[Intermittent Failures Robot]

23 failures in 170 pushes (0.135 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* autoland: 15
* mozilla-inbound: 6
* try: 1
* mozilla-central: 1

Platform breakdown:
* linux64: 23

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-21&endday=2017-12-21&tree=all

Comment 32

[Intermittent Failures Robot]

22 failures in 50 pushes (0.44 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 19
* autoland: 2
* mozilla-central: 1

Platform breakdown:
* linux64: 21
* linux64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-22&endday=2017-12-22&tree=all

Comment 33

[Intermittent Failures Robot]

98 failures in 590 pushes (0.166 failures/push) were associated with this bug in the last 7 days. 

This is the #5 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* mozilla-inbound: 45
* autoland: 39
* mozilla-central: 10
* try: 3
* mozilla-beta: 1

Platform breakdown:
* linux64: 97
* linux64-stylo-disabled: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-18&endday=2017-12-24&tree=all

Comment 34

[Tiberius Oros[:tiberius_oros]]

There have been 34 failures in the last week.
This is failing on Linux x64 / asan, with a single exception on linux64-stylo-disabled / opt.

Here is a recent log file:
https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=153534459&lineNumber=10999

and a snippet with the failure:

[task 2017-12-28T22:41:41.898Z] 22:41:41     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Media recorder should be incative after stop 
10995
[task 2017-12-28T22:41:41.899Z] 22:41:41     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Expected 1 dataavailable event 
10996
[task 2017-12-28T22:41:41.900Z] 22:41:41     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Should have gotten a data blob 
10997
[task 2017-12-28T22:41:41.900Z] 22:41:41     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | video element should be same size as canvas once metadata is loaded 
10998
[task 2017-12-28T22:41:41.903Z] 22:41:41     INFO - Buffered messages finished
10999
[task 2017-12-28T22:41:41.904Z] 22:41:41     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_pause_resume_video.html | Last frame should be green 
11000
[task 2017-12-28T22:41:41.904Z] 22:41:41     INFO -     startTest/mediaRecorder.onstop/video.onended@dom/media/test/test_mediarecorder_pause_resume_video.html:104:7
11001
[task 2017-12-28T22:41:41.904Z] 22:41:41     INFO -     EventHandlerNonNull*startTest/mediaRecorder.onstop@dom/media/test/test_mediarecorder_pause_resume_video.html:103:5
11002
[task 2017-12-28T22:41:41.904Z] 22:41:41     INFO -     EventHandlerNonNull*startTest@dom/media/test/test_mediarecorder_pause_resume_video.html:81:3
11003
[task 2017-12-28T22:41:41.904Z] 22:41:41     INFO -     @dom/media/test/test_mediarecorder_pause_resume_video.html:125:1
11004
[task 2017-12-28T22:41:41.904Z] 22:41:41     INFO - GECKO(1754) | MEMORY STAT | vsize 20973779MB | residentFast 1200MB
11005
[task 2017-12-28T22:41:41.905Z] 22:41:41     INFO - TEST-OK | dom/media/test/test_mediarecorder_pause_resume_video.html | took 4300ms

Comment 35

[Intermittent Failures Robot]

10 failures in 147 pushes (0.068 failures/push) were associated with this bug in the last 7 days. 

This is the #27 most frequent failure this week.   

Repository breakdown:
* mozilla-central: 4
* autoland: 4
* mozilla-inbound: 2

Platform breakdown:
* linux64: 10

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2017-12-25&endday=2017-12-31&tree=all

Comment 36

[Arthur Iakab [arthur_iakab]]

This has failed 42 times in the last 7 days. It occurred only on Linux x64 platform affecting asan build type.
Failing test suite: only on opt-mochitest-media-e10s.

Link to a recent log: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=153630587&lineNumber=11024

Part of that log:

[task 2017-12-30T23:07:28.139Z] 23:07:28     INFO - Got 'dataavailable' event
11018
[task 2017-12-30T23:07:28.139Z] 23:07:28     INFO - Got 'stop' event
11019
[task 2017-12-30T23:07:28.140Z] 23:07:28     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Media recorder should be incative after stop 
11020
[task 2017-12-30T23:07:28.141Z] 23:07:28     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Expected 1 dataavailable event 
11021
[task 2017-12-30T23:07:28.142Z] 23:07:28     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | Should have gotten a data blob 
11022
[task 2017-12-30T23:07:28.143Z] 23:07:28     INFO - TEST-PASS | dom/media/test/test_mediarecorder_pause_resume_video.html | video element should be same size as canvas once metadata is loaded 
11023
[task 2017-12-30T23:07:28.143Z] 23:07:28     INFO - Buffered messages finished
11024
[task 2017-12-30T23:07:28.143Z] 23:07:28     INFO - TEST-UNEXPECTED-FAIL | dom/media/test/test_mediarecorder_pause_resume_video.html | Last frame should be green 
11025
[task 2017-12-30T23:07:28.144Z] 23:07:28     INFO -     startTest/mediaRecorder.onstop/video.onended@dom/media/test/test_mediarecorder_pause_resume_video.html:104:7
11026
[task 2017-12-30T23:07:28.145Z] 23:07:28     INFO -     EventHandlerNonNull*startTest/mediaRecorder.onstop@dom/media/test/test_mediarecorder_pause_resume_video.html:103:5
11027
[task 2017-12-30T23:07:28.145Z] 23:07:28     INFO -     EventHandlerNonNull*startTest@dom/media/test/test_mediarecorder_pause_resume_video.html:81:3
11028
[task 2017-12-30T23:07:28.145Z] 23:07:28     INFO -     @dom/media/test/test_mediarecorder_pause_resume_video.html:125:1
11029
[task 2017-12-30T23:07:28.146Z] 23:07:28     INFO - GECKO(1639) | MEMORY STAT | vsize 20973777MB | residentFast 905MB
11030
[task 2017-12-30T23:07:28.146Z] 23:07:28     INFO - TEST-OK | dom/media/test/test_mediarecorder_pause_resume_video.html | took 4301ms
11031
[task 2017-12-30T23:07:28.147Z] 23:07:28     INFO - TEST-START | dom/media/test/test_mediarecorder_playback_can_repeat.html
11032
[task 2017-12-30T23:07:28.296Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Shutdown: decoder=0x61600044d080 state machine=0x61d000633880
11033
[task 2017-12-30T23:07:28.298Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Enter: state machine=0x6020003f6950 reader=0x60d00001cb50
11034
[task 2017-12-30T23:07:28.299Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Shutdown: reader=0x61e000048c80 shutdown demuxer=0x6020005a3150
11035
[task 2017-12-30T23:07:28.300Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Shutdown: pool=0x60400030ab90 count=1
11036
[task 2017-12-30T23:07:28.301Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] operator(): pool=0x60400030ab90 shutdown=true count=0
11037
[task 2017-12-30T23:07:28.301Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] TearDownDecoders: reader=0x61e000048c80 shut down audio task queue
11038
[task 2017-12-30T23:07:28.302Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] TearDownDecoders: reader=0x61e000048c80 shut down video task queue
11039
[task 2017-12-30T23:07:28.303Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] FinishShutdown: state machine=0x61d000633880
11040
[task 2017-12-30T23:07:28.304Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Unregister: decoder=0x61600044d080, count=1
11041
[task 2017-12-30T23:07:28.999Z] 23:07:28     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Register: decoder=0x616000501680, count=2
11042
[task 2017-12-30T23:07:30.111Z] 23:07:30     INFO - GECKO(1639) | MEMORY STAT | vsize 20973770MB | residentFast 889MB
11043
[task 2017-12-30T23:07:30.128Z] 23:07:30     INFO - TEST-OK | dom/media/test/test_mediarecorder_playback_can_repeat.html | took 2428ms
11044
[task 2017-12-30T23:07:30.188Z] 23:07:30     INFO - TEST-START | dom/media/test/test_mediarecorder_record_4ch_audiocontext.html
11045
[task 2017-12-30T23:07:30.254Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Shutdown: decoder=0x616000209480 state machine=0x61d000c61680
11046
[task 2017-12-30T23:07:30.255Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Enter: state machine=0x602000613670 reader=0x60d00025b590
11047
[task 2017-12-30T23:07:30.255Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Shutdown: reader=0x61e000085880 shutdown demuxer=0x602000629c90
11048
[task 2017-12-30T23:07:30.256Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Shutdown: pool=0x6040001fc390 count=1
11049
[task 2017-12-30T23:07:30.256Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] operator(): pool=0x6040001fc390 shutdown=true count=0
11050
[task 2017-12-30T23:07:30.256Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] TearDownDecoders: reader=0x61e000085880 shut down audio task queue
11051
[task 2017-12-30T23:07:30.257Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] TearDownDecoders: reader=0x61e000085880 shut down video task queue
11052
[task 2017-12-30T23:07:30.259Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] FinishShutdown: state machine=0x61d000c61680
11053
[task 2017-12-30T23:07:30.260Z] 23:07:30     INFO - GECKO(1639) | [DEBUG SHUTDOWN] Unregister: decoder=0x616000209480, count=1
11054
[task 2017-12-30T23:07:31.478Z] 23:07:31     INFO - GECKO(1639) | MEMORY STAT | vsize 20973795MB | residentFast 901MB
11055
[task 2017-12-30T23:07:31.494Z] 23:07:31     INFO - TEST-OK | dom/media/test/test_mediarecorder_record_4ch_audiocontext.html | took 1302ms
11056
[task 2017-12-30T23:07:31.559Z] 23:07:31     INFO - TEST-START | dom/media/test/test_mediarecorder_record_addtracked_stream.html

Comment 37

[Arthur Iakab [arthur_iakab]]

jib: do you have any updates on this?

Comment 38

[Intermittent Failures Robot]

17 failures in 119 pushes (0.143 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 7
* autoland: 7
* try: 3

Platform breakdown:
* linux64: 17

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2018-01-05&endday=2018-01-05&tree=all

Comment 39

[Intermittent Failures Robot]

53 failures in 462 pushes (0.115 failures/push) were associated with this bug in the last 7 days. 

This is the #12 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **  

Repository breakdown:
* autoland: 23
* mozilla-inbound: 21
* try: 5
* mozilla-central: 4

Platform breakdown:
* linux64: 53

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2018-01-01&endday=2018-01-07&tree=all

Comment 40

[Jan-Ivar Bruaroey [:jib] (needinfo? me)]

Attachment: Bug 1403307 - Disable dom/media/test/test_mediarecorder_pause_resume_video.html on linux64 as well for frequent failures.

Review commit: https://reviewboard.mozilla.org/r/211180/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/211180/

Comment 41

[Bryce Seager van Dyk [:bryce] (he/him) - Not reading bugmail]

Comment on attachment 8940916 [details]
Bug 1403307 - Disable dom/media/test/test_mediarecorder_pause_resume_video.html on linux64 as well for frequent failures.

https://reviewboard.mozilla.org/r/211180/#review217084

Comment 42

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ee54a2ff9373
Disable dom/media/test/test_mediarecorder_pause_resume_video.html on linux64 as well for frequent failures. r=bryce

Comment 43

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/ee54a2ff9373

Comment 44

[Intermittent Failures Robot]

19 failures in 788 pushes (0.024 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 9
* try: 7
* autoland: 2
* mozilla-central: 1

Platform breakdown:
* linux64: 19

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2018-01-08&endday=2018-01-14&tree=all

Comment 45

[Intermittent Failures Robot]

1 failures in 657 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-beta: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2018-01-15&endday=2018-01-21&tree=all

Comment 46

[Intermittent Failures Robot]

1 failures in 701 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* try: 1

Platform breakdown:
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2018-01-22&endday=2018-01-28&tree=all

Comment 47

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1
* autoland: 1

Platform breakdown:
* linux32-stylo-disabled: 1
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2018-01-29&endday=2018-02-04&tree=all

Comment 48

[Intermittent Failures Robot]

1 failures in 831 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-beta: 1

Platform breakdown:
* linux32-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1403307&startday=2018-02-26&endday=2018-03-04&tree=all

Comment 49

[Andreas Pehrson [:pehrsons]]

I've debugged a case of this intermittent, and what happens is that the last (green) frame hits the underrun path in [1].

The only way we can append the same frame again is then to wait 1 second, but we reach EOS before that happens.

I need to look at why exactly we hit the underrun path here, and check whether some logic is flawed.



[1] https://searchfox.org/mozilla-central/rev/ce9ff94ffed34dc17ec0bfa406156d489eaa8ee1/dom/media/encoder/TrackEncoder.cpp#769

Comment 50

[Andrei Ciure[:aciure]]

This issue is still occurring:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-classifiedState=unclassified&fromchange=093b3a6f608998cc9d1fb66d68445bf2e30e84df&autoclassify=&selectedJob=178132384&filter-searchStr=Linux+x64+asan+Mochitests+with+e10s+test-linux64-asan%2Fopt-mochitest-media-e10s-1+M-e10s%28mda1%29

https://treeherder.mozilla.org/logviewer.html#?job_id=178132384&repo=mozilla-inbound

Comment 51

[Intermittent Failures Robot]

1 failures in 660 pushes (0.002 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* linux64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1403307&startday=2018-05-07&endday=2018-05-13&tree=trunk