1201070 - Make the tutorial more resilient to media errors

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::First Time Experience, defect)

Description

[:gerard-majax]

After investigating bug 1194979, it turns out the timeout were caused by the lack of error handling for at least two events:
 - abort
 - waiting

Adding those makes the test pass.

Comment 1

[:gerard-majax]

One PR with both, one with only abort:
https://treeherder.mozilla.org/#/jobs?repo=gaia&revision=70c2d901fce0e01c468ba6f00ee666c23790bbf4

Comment 2

[:gerard-majax]

(In reply to Alexandre LISSY :gerard-majax from comment #1)
> One PR with both, one with only abort:
> https://treeherder.mozilla.org/#/
> jobs?repo=gaia&revision=70c2d901fce0e01c468ba6f00ee666c23790bbf4

Handling only abort is enough :)

Comment 3

[GitHub Autolander Bot]

Attachment: [gaia] lissyx:bug1201070 > mozilla-b2g:master

Comment 4

[:gerard-majax]

To make it clear, this is mostly to make sure we have green test. The code should handle all error cases and "abort" was not. Yet, work should continue in bug 1199348 because we should not even get this "abort".

Comment 5

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8655996 [details] [review]
[gaia] lissyx:bug1201070 > mozilla-b2g:master

Thanks for tracking this down. This patch ends up registering overlapping 'abort' listeners in the case where src is already defined. It may be harmless in practice but I'd prefer to avoid further confusing and already obtuse block of code. I've got a patch that applies the same fix but avoids this case which I'll attach.

Comment 6

[GitHub Autolander Bot]

Attachment: [gaia] sfoster:ftu-tutorial-abort-bug-1201070 > mozilla-b2g:master

Comment 7

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8656171 [details] [review]
[gaia] sfoster:ftu-tutorial-abort-bug-1201070 > mozilla-b2g:master

Iterated a bit on your patch. I've run the unit tests on nightly and mulet and also checked on device and this seems pretty solid?

Comment 8

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8656171 [details] [review]
[gaia] sfoster:ftu-tutorial-abort-bug-1201070 > mozilla-b2g:master

Cancelling, new PR on its way

Comment 9

[Sam Foster [:sfoster] (he/him)]

Attachment: PR to update lissyx' patch

I've based my changes on top of attachment #8655996 [details] [review]. If you can merge these and update your PR we should be good to go - as long as try/mulet agrees

Comment 10

[:gerard-majax]

https://github.com/mozilla-b2g/gaia/pull/31670
https://treeherder.mozilla.org/#/jobs?repo=gaia&revision=81a485ec22af248e2036e235dc8bf5f0bcd854fb

Comment 11

[:gerard-majax]

(In reply to Sam Foster [:sfoster] from comment #9)
> Created attachment 8656257 [details] [review]
> PR to update lissyx' patch
> 
> I've based my changes on top of attachment #8655996 [details] [review]. If you can
> merge these and update your PR we should be good to go - as long as
> try/mulet agrees

That is failing worse.

Comment 12

[Sam Foster [:sfoster] (he/him)]

(In reply to Alexandre LISSY :gerard-majax from comment #11)
> That is failing worse.

I'm struggling to understand the difference in environments between running these tests locally on mulet, and on treeherder. I can apply the PR, run gaia-test and execute tutorial_test.js (or the whole #FTU suite), and it shows me that while the mp4 videos didn't load, this condition was handled and the tests pass. And yet that treeherder report says they all fail. Also, I don't see a significant functional difference between my patch and attachment #8655996 [details] [review] - I don't want to just land that without at least understanding whats going on there. 

I'll add a bunch of logging and try a new PR. I may also try waiting for the canplaythrough event, but its just shots in the dark at this point.

Comment 13

[GitHub Autolander Bot]

Attachment: [gaia] sfoster:mulet-tutorial > mozilla-b2g:master

Comment 14

[Sam Foster [:sfoster] (he/him)]

Ok, results are in from https://tools.taskcluster.net/task-inspector/#lfV-3JjnS_KUFT5rb3Vi9Q/2 and are interesting. I added listeners to log out all the media events (except progress which is v. noisy) I think this is the relevant snippet from the log: 

TEST-START | null | [ftu-test/unit/tutorial_test.js] Tutorial >  lifecycle start during init
TUTORIAL: setInitialStep
TUTORIAL: _loadMedia, no src, just calling onVideoUnloaded
TUTORIAL: _loadMedia, onVideoUnloaded for evt.type: undefined
TUTORIAL: _loadMedia, onVideoUnloaded, assigning src: /style/images/tutorial/VerticalScroll.mp4
TUTORIAL: media-event: emptied
TUTORIAL: media-event: loadstart
TUTORIAL: media-event: durationchange
TUTORIAL: media-event: loadedmetadata
TUTORIAL: media-event: loadeddata
TUTORIAL: media-event: canplay
### note that here we are apparently loading and playing the .mp4 just fine.  ###
TUTORIAL: _loadMedia, onMediaLoadOrError for evt.type: canplay
TUTORIAL: dispatching tutorialinitialized
TUTORIAL: media-event: suspend
TUTORIAL: media-event: play
TUTORIAL: media-event: playing
TUTORIAL: media-event: canplaythrough
TEST-PASS | null | [ftu-test/unit/tutorial_test.js] Tutorial >  lifecycle start during init
TEST-END | null | [ftu-test/unit/tutorial_test.js] Tutorial >  lifecycle start during init took 844 ms
### the test concludes, the video element is still playing that mp4 though..###
TEST-START | null | [ftu-test/unit/tutorial_test.js] Tutorial >  lifecycle start after init
TUTORIAL: setInitialStep
TUTORIAL: _loadMedia, removing src attribute
TUTORIAL: _loadMedia, calling load
### we unload the previous mp4 by removing src attribute and calling load()
TUTORIAL: media-event: abort
TUTORIAL: media-event: emptied
TUTORIAL: _loadMedia, onVideoUnloaded for evt.type: emptied
### the emptied event signals that went ok, and we're ready to assign a new src
TUTORIAL: _loadMedia, onVideoUnloaded, assigning src: /style/images/tutorial/VerticalScroll.mp4
TUTORIAL: media-event: emptied
TUTORIAL: media-event: loadstart
TUTORIAL: media-event: suspend
### not sure why we suspend here, and never recover. It all goes south from here ###
TEST-UNEXPECTED-FAIL | null | [ftu-test/unit/tutorial_test.js] Tutorial >  lifecycle start after init
Error: timeout of 10000ms exceeded
    at (anonymous) (app://ftu.gaiamobile.org/common/vendor/mocha/mocha.js:3680:14)

TEST-END | null | [ftu-test/unit/tutorial_test.js] Tutorial >  lifecycle start after init took 10002 ms

So the first test is able to load the video, we get the 'canplay' event, the test completes, all is good. The 2nd test seems to reset ok, but when it assigns the src again we get loadstart then suspend but it never resumes and canplay never happens so the test times-out and fails. Its not clear why.

I think the rest of the failures that follow are just indications that the <video> element is in a bad state and never recovers. For the purposes of this test it may make sense to re-create the element each time. But the load() call should be resetting all state, so it seems to me there's a legit video/mediaelement bug in there somewhere.

Comment 15

[Sam Foster [:sfoster] (he/him)]

I'm not ruling out mistakes in my code or test, but the logging in Comment #14 seems to point at the video element getting into a bad state. I'm not clear what I could be doing differently short of destroying and recreating the <video> each time I want to play something (and Im not confident that would fix this either.) do you have any pointers :jya? (See also discussion in bug 1199348 for context)

Comment 16

[GitHub Autolander Bot]

Attachment: [gaia] sfoster:ftu-tutorial-video-1201070 > mozilla-b2g:master

Comment 17

[Sam Foster [:sfoster] (he/him)]

Comment on attachment 8658816 [details] [review]
[gaia] sfoster:ftu-tutorial-video-1201070 > mozilla-b2g:master

The new PR which is just the FTU pieces, which harden the tutorial and its tests a bit. These should pass on b2g-desktop so I propose that (assuming they do pass) we land this and follow-up as necessary if there is more work to do to get tests passing on mulet, or we find out more about what's going on with the video/mediaelement behaviour

Comment 18

[Aus Lacroix [:aus]]

These changes were landed as part of bug 1199429 I believe. :) I've left the debug logging for these tests as they may still be fragile and will require further help... possibly soon but hopefully never. :)

Comment 19

[Sam Foster [:sfoster] (he/him)]

(In reply to Aus Lacroix [:aus] from comment #18)
> These changes were landed as part of bug 1199429 I believe. :) I've left the
> debug logging for these tests as they may still be fragile and will require
> further help... possibly soon but hopefully never. :)

I see :) Well lets at least file a bug to remove that extra logging - filed at bug 1203424. Fernando, consider this a heads-up I guess as it looks like that patch landed as a part of the b2g-desktop -> mulet transition. If you spot anything amiss we can follow-up or even backout if necessary.