Alissa（leave from Mozilla） Reporter
	Description • 9 years ago

[1.Description]:
[Flame KK v2.6&v2.5][Music]The Music Player can not work correctly by song list while user holds on the forward key until the second song is playing. 
Found time: 10:55
See attachment: FlameKK_v2.6 master.3gp & logcat_1055.txt

[2.Testing Steps]: 
1. Launch the Music app on the homescreen.
2. Play a song by the songs list.
3. Hold the forward key until the next song is playing.

[3.Expected Result]: 
3. The second song can play correctly.

[4.Actual Result]: 
3. The second song doesn't play and the play button does not work.

[5.Reproduction build]: 
Device: Aries kk v2.6 master (Unaffected)
Build ID               20151106003240
Gaia Revision          f39a7a827c0c0f48087ff3ead94f61ae22523919
Gaia Date              2015-11-05 18:52:32
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/dae6c2b8fef8a2f504baab5dae7ccd59d57a1d9d
Gecko Version          45.0a1
Device Name            aries
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.worker.20151105.231536
Firmware Date          Thu Nov  5 23:15:45 UTC 2015
Bootloader             s1       

Device: Flame KK v2.5(512m)(Affected):
Build ID               20151105004500
Gaia Revision          47da49f8206788d70d834c3a63d9245d50c89103
Gaia Date              2015-11-03 21:48:23
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g44_v2_5/rev/5c9fd135d4309239794126f1942d6e7aa8b3579c
Gecko Version          45.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20151105.043012
Firmware Date          Thu Nov  5 04:30:24 EST 2015
Firmware Version       v18D v4
Bootloader             L1TC000118D

                                                                    

Device: Flame kk v2.6 master 512mb(Affected)
Build ID               20151105150203
Gaia Revision          f39a7a827c0c0f48087ff3ead94f61ae22523919
Gaia Date              2015-11-05 18:52:32
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/dae6c2b8fef8a2f504baab5dae7ccd59d57a1d9d
Gecko Version          45.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20151105.182857
Firmware Date          Thu Nov  5 18:29:10 EST 2015
Firmware Version       v18D v4
Bootloader             L1TC000118D0

[6.Reproduction Frequency]: 
Always Recurrence,5/5

[7.TCID]: 
Free Test

	William Hsu [:whsu]
	Comment 2 • 9 years ago

Hi, Alissa,

NGA Music only?
Can it be reproduced on v2.2?

	Jim Porter (:squib)
	Comment 3 • 9 years ago

I think I figured out what this bug is about: if you fast-seek to the end of a song, the next song doesn't start playing automatically. However, it'll start once the screen turns off. Weird that it only happens on Flame. Maybe it's a recent regression? If we could get a regression range, that would help.

	Hema Koka [:hema]
	Comment 4 • 9 years ago

Triage 11/18: Blocking because of Broken functionality.

	Pi Wei Cheng [:piwei] (inactive)
	Comment 5 • 9 years ago

mozilla-inbound regression window:

Last Working
Device: Flame
BuildID: 20151027151832
Gaia: a26eadc5e1133d5112b6cbc10badbb7670a1090f
Gecko: 39a137bbfeee3f5e080a486ef0696674a5df2260
Version: 44.0a1
Firmware Version: v18D
User Agent: Mozilla/5.0 (Mobile; rv:44.0) Gecko/44.0 Firefox/44.0

First Broken
Device: Flame
BuildID: 20151027164732
Gaia: a26eadc5e1133d5112b6cbc10badbb7670a1090f
Gecko: 39af5c53fad65f5d3ea39581d60f4378b127f2e4
Version: 44.0a1
Firmware Version: v18D
User Agent: Mozilla/5.0 (Mobile; rv:44.0) Gecko/44.0 Firefox/44.0

Gaia is the same so it's a Gecko issue.

Gecko pushlog:
http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=39a137bbfeee3f5e080a486ef0696674a5df2260&tochange=39af5c53fad65f5d3ea39581d60f4378b127f2e4

Caused by changes made in Bug 1188887.

	Jayme Mercado [:JMercado] (Inactive 3/4/2016)
	Comment 6 • 9 years ago

Jean-Yves this issue seems to have been caused by the changes bug 1188887.  Can you please take a look?

	Jean-Yves Avenard [:jya]
	Comment 7 • 9 years ago

And once again, a case where having regression tests enabled on B2G would be of value!

The seek was changed to match the W3C spec. 
If something was relying on a broken behaviour to work, it's what needs to be fixed.

	Jean-Yves Avenard [:jya]
	Comment 8 • 9 years ago

Could you please point me where and how the seek is performed in the gaia code?

In particular how the songs list is handled and what is expected to make it start a new song.

	Hubert Figuiere [:hub]
	Comment 9 • 9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #7)
> And once again, a case where having regression tests enabled on B2G would be
> of value!

What needs to be done to have these tests on b2g?

	Jim Porter (:squib)
	Comment 10 • 9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #7)
> And once again, a case where having regression tests enabled on B2G would be
> of value!

Actually, our tests in Gaia have caught a few Gecko issues lately, too. It's also pretty hard to really test audio playback stuff in Gaia tests because our test machines have no audio hooked up. I've tried a few times to get audio playback tests working in Gaia, and it's never gone very well because our CI is fractally bad.
 
> The seek was changed to match the W3C spec. 
> If something was relying on a broken behaviour to work, it's what needs to
> be fixed.

As far as I can tell, we're not actually doing anything wrong. The biggest issue I see from Gecko is that we get multiple "ended" events for a given song if we update currentTime to the end of the file. We also end up with currentTime set to -0.00001 somehow, which happens immediately after we seek to the end of the track; even seeking to just *before* the end of the track causes that. That's probably bad.

All this happens before we try to load the next track, so readyState != HAVE_NOTHING. Nothing in your patches seem like they'd affect us, and I think we're obeying the part of the spec fixed in your bug anyway. My guess is that your patch just reveals some bustage elsewhere in Gecko.

	Jim Porter (:squib)
	Comment 11 • 9 years ago

Here are the most-relevant bits of code:

Seeking: https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.js#L158-L195
Setting up the <audio> element: https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.js#L109-L138

	Alissa（leave from Mozilla） Reporter
	Comment 12 • 9 years ago

Hi, William,

1.This bug can not repro on latest build of Flame KK 2.2 by the STR in Comment 0.

Actual results: The second song can play correctly.

Reproduce rate: 0/5

Device: Flame KK 2.2(Unaffected)
Build ID               20151117032501
Gaia Revision          885647d92208fb67574ced44004ab2f29d23cb45
Gaia Date              2015-10-07 13:05:24
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/e772f343b736
Gecko Version          37.0
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20151117.073435
Firmware Date          Tue Nov 17 07:34:46 EST 2015
Firmware Version       V18D V4
Bootloader             L1TC000118D0

2.The bug can also repro in OGA Music.

Actual results: The second song doesn't play and the play button does not work.

Reproduce rate: 5/5

Device:Flame kk v2.5 512mb (Affected)
Build ID               20151109004552
Gaia Revision          cf646c52bb947af28329b0a100df91d1b1f2a907
Gaia Date              2015-11-09 02:55:50
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g44_v2_5/rev/4eafef5b80f8985c94c4a067f130d37513e1a581
Gecko Version          44.0a2
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20151109.041411
Firmware Date          Mon Nov  9 04:14:26 EST 2015
Firmware Version        V18D V4
Bootloader             L1TC000118D0

	Jean-Yves Avenard [:jya]
	Comment 13 • 9 years ago

(In reply to Jim Porter (:squib) from comment #11)
> Here are the most-relevant bits of code:
> 
> Seeking:
> https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.
> js#L158-L195
> Setting up the <audio> element:
> https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.
> js#L109-L138

Thank you.

Are you calling seek(time) or startFastSeek() ?

So if I read properly there:
https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.js#L186

with startFastSeek, you seek to the current duration + 5.

Where do you manage jumping to the next song when reaching the end?

The commit that caused regression allowed to seek where we would otherwise have thrown an exception, there was no change in the seek behaviour otherwise. So can't see the causality. 

Would you have a way to test gaia and this particular audio playback in a normal browser? I don't have anything handy to debug otherwise and figure out what has changed.

(BTW, there's no point doing a "fast" seek with audio, fast seek only makes sense for video.)

	Jean-Yves Avenard [:jya]
	Comment 14 • 9 years ago

I wrote a quick mochitest that performs a fastSeek at duration+3

It tests that seeked event is fired, that ended has been fired and that currentTime == duration once seeked is fired.

the test passes. I can't fault anything there.

JY

	Jim Porter (:squib)
	Comment 15 • 9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #13)
> Are you calling seek(time) or startFastSeek() ?

startFastSeek is the public API, and seek is used internally.

> Where do you manage jumping to the next song when reaching the end?

This function is called from the onended event: https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.js#L92-L94

> The commit that caused regression allowed to seek where we would otherwise
> have thrown an exception, there was no change in the seek behaviour
> otherwise. So can't see the causality. 

Yeah, the behavior I see doesn't seem to be caused by your change, at least not in any obvious way.

> Would you have a way to test gaia and this particular audio playback in a
> normal browser? I don't have anything handy to debug otherwise and figure
> out what has changed.

Yeah, Justin knows how to do this. I'll ask him.

> (BTW, there's no point doing a "fast" seek with audio, fast seek only makes
> sense for video.)

That's what I thought.

(In reply to Jean-Yves Avenard [:jya] from comment #14)
> I wrote a quick mochitest that performs a fastSeek at duration+3
> 
> It tests that seeked event is fired, that ended has been fired and that
> currentTime == duration once seeked is fired.
> 
> the test passes. I can't fault anything there.

Apparently this bug only happens on some devices (broken on Flame, good on Aries), so I'm not surprised that it works on desktop. We more-or-less continually have problems with audio playback on real devices... maybe your change broke some assumptions in Flame-specific code? That stuff is black magic to me.

	Jim Porter (:squib)
	Comment 16 • 9 years ago

Justin: What incantations do I have to speak to make the Music app run in desktop? I've never tried to do that.

	Jean-Yves Avenard [:jya]
	Comment 17 • 9 years ago

starting to doubt the regression range.

If you revert commit http://hg.mozilla.org/integration/mozilla-inbound/rev/3c27972e56a7  and commit http://hg.mozilla.org/integration/mozilla-inbound/rev/faca58991660

recomping gecko, can you still reproduce the bug?

	Justin D'Arcangelo [:justindarc]
	Comment 18 • 9 years ago

(In reply to Jim Porter (:squib) from comment #16)
> Justin: What incantations do I have to speak to make the Music app run in
> desktop? I've never tried to do that.

We used to be able to do this before we switched out from dev_apps/ to apps/. However, in the process, we removed a DeviceStorage shim and we also have that build step now where we generate metadata_scripts.js. So, I don't think this will work out-of-the-box at the moment. But I'll investigate today to see if there's an easy workaround. So you know, previously, all you'd have to do was run `npm run serve` from the Music app directory and it would host the app on localhost:3000. But, like I said, we have an extra step in our build now that we've landed, and that would likely be an issue.

	Jim Porter (:squib)
	Comment 19 • 9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #17)
> starting to doubt the regression range.

I also doubt it because I have an old build sitting around here from October 2, and I still see the issue with it skipping over one song. It *plays* correctly, but fast-seeking to the end of song 1 then starts up song 3, so we're still getting two "ended" events.

	Jim Porter (:squib)
	Comment 20 • 9 years ago

So, there are actually (at least) two issues here:

1) Fast-seeking to the end of a song skips over a song (goes from track 1 to 3) because we see two "ended" events for a single track.
2) Fast-seeking while we're still loading a song(?) causes mozinterruptbegin to fire, but no mozinterruptend, meaning we can't play music anymore. This seems to resolve itself once the music app goes to the background.

I think (2) is what this bug is about, but I'd be unsurprised if we need to fix (1) first.

	Pi Wei Cheng [:piwei] (inactive)
	Comment 21 • 9 years ago

The regression window is for the original bug comment 0. I did notice it skipping tracks but as long as it continued to play, I counted that as 'working'. If I didn't do that I wouldn't have been able to find any window.

	Justin D'Arcangelo [:justindarc]
	Comment 22 • 9 years ago

Ok.. There are two issues here:

1.) We are getting 2 "ended" events which is causing the app to skip from song 1 to song 3 when fast-seeking (holding down the FFWD button)
2.) The app is appearing "stuck" with no audio when the above happens

So, for the first problem, I'm not entirely sure why we're getting 2 "ended" events, but this is certainly unexpected behavior coming from the <audio> element. However, the second problem is caused by a "mozinterruptbegin" event being thrown when we fast-seek past the end of the song.

Here is the order of events I'm seeing coming from the <audio> element along with the corresponding actions being taken by the user/app:

[action] Tap on "Song 1" to start playing it
[event] play
[event] mozinterruptbegin (immediately after "play")
[event] mozinterruptend   (immediately after "mozinterruptbegin")
[action] Press-and-hold FFWD ">|" button to fast-seek
[action] Continue fast-seeking past the end of "Song 1"
[event] pause             (immediately after seeking to the end of the song)
[event] ended             (immediately after "pause")
[event] ended             (immediately after first "ended")
[event] play              (immediately after second "ended")
[event] mozinterruptbegin (immediately after "play")

No "mozinterruptend" is seen after that. This is why the app stops playing audio and appears "stuck".

	Justin D'Arcangelo [:justindarc]
	Comment 24 • 9 years ago

Comment on attachment 8689673 [details] [review]
[gaia] justindarc:bug1222387 > mozilla-b2g:master

This patch fixes both issues I mentioned in Comment 22. However, we should not land this until we ensure that Gecko is behaving correctly.

	Jim Porter (:squib)
	Comment 25 • 9 years ago

Comment on attachment 8689673 [details] [review]
[gaia] justindarc:bug1222387 > mozilla-b2g:master

r=me, but only if we can't fix Gecko.

	Jim Porter (:squib)
	Comment 26 • 9 years ago

Comment on attachment 8689673 [details] [review]
[gaia] justindarc:bug1222387 > mozilla-b2g:master

Wait a second, I forgot one of the reasons I didn't want to do this. We'll have to update the UI as well so that the >| button isn't highlighted when we drop out of fast seek. Otherwise, it would be pretty confusing: the UI says you're fast-seeking, but you really aren't.

I don't think your patch does that.

	Jean-Yves Avenard [:jya]
	Comment 27 • 9 years ago

Just a thought, which could explain why bug 1188887 would cause a change of behaviour in your code.

What about it's a time / race issue (which would make it more visible on slower devices).

When holding the |> you seek in a loop.
Once you reach the end of the current song and get to the second song, seek is issued before the new audio is loaded. Previously that seek would have caused to throw an exception which you wouldn't have noticed. Now the seek is queued. If the next song uses VBR, it may not have a known duration yet, or a duration temporarily seen as < 5 as the file is loaded. The pending seek is now executed and as the music file is only partially loaded the seek position is greater than the calculated duration: reaches the end and causes ended to be fired and the next song to play.

So you don't get to see "ended" even twice for the same MP3 (which I can't see how it could ever happen), but once for the first song, then for the 2nd and you end up on the 3rd.

When you seek, and currentState is HAVE_NOTHING, the currentTime is the "official" time, which is the value you set to seek to.
If you seek to a negative time, and currentState is HAVE_NOTHING; currentTime may be negative too. I need to check on that. I can see on how it could be happening, the spec has nothing explicitly prevent currentTime to be negative when currentState is HAVE_NOTHING.

But regardless, what I believe you guys need to do, is to never start a new seek after the "ended" even is received until the new audio has been loaded and "loadedmetadata" event has been fired.
As the behaviour with MP3 which have a duration based on how much data has been loaded is unpredictable.

	Jim Porter (:squib)
	Comment 28 • 9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #27)
> So you don't get to see "ended" even twice for the same MP3 (which I can't
> see how it could ever happen), but once for the first song, then for the 2nd
> and you end up on the 3rd.

That's what I thought at first too, but the second "ended" event happens *before* we change the <audio> element's .src value. In any case, the double-"ended" bug happened before your patch landed, so your change didn't do anything there. It only caused an issue where "mozinterruptend" isn't fired when it should be (problem (2) in comment 20 and comment 22).

(In reply to Jean-Yves Avenard [:jya] from comment #27)
> But regardless, what I believe you guys need to do, is to never start a new
> seek after the "ended" even is received until the new audio has been loaded
> and "loadedmetadata" event has been fired.
> As the behaviour with MP3 which have a duration based on how much data has
> been loaded is unpredictable.

That seems to fix problem (2), but not problem (1).

	Jean-Yves Avenard [:jya]
	Comment 29 • 9 years ago

(In reply to Jim Porter (:squib) from comment #28)
> (In reply to Jean-Yves Avenard [:jya] from comment #27)
> > So you don't get to see "ended" even twice for the same MP3 (which I can't
> > see how it could ever happen), but once for the first song, then for the 2nd
> > and you end up on the 3rd.
> 
> That's what I thought at first too, but the second "ended" event happens
> *before* we change the <audio> element's .src value. In any case, the
> double-"ended" bug happened before your patch landed, so your change didn't
> do anything there. It only caused an issue where "mozinterruptend" isn't
> fired when it should be (problem (2) in comment 20 and comment 22).

I have no idea what those "mozinterrupted" events are.

The issue I described would happen even without bug 1188887 ; but 1188887 would make it more likely to be seen

> That seems to fix problem (2), but not problem (1).

I believe you're only seeing (1) because of (2), there's no two "ended" event per media element, unless you've seeked backward and play again.
You mentioned that you were seeing currentTime being close to duration() but not exactly. Rounding issues could cause that. So if you were in ended mode, seek to duration-0.0000001, you will get ended again.

For you seeing currentTime < 0 ; it can only happen if you are seeking to a negative duration.
If you read duration before loadedmetadata event (which you currently do), duration would be 0.

Can you trace the value passed to fastSeek() ? Fairly certain you will see negative values there

	Jim Porter (:squib)
	Comment 30 • 9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #29)
> I have no idea what those "mozinterrupted" events are.

"mozinterruptEND". They notify us that the audio channel blocking our <audio> element from playing has stopped and that we'll automatically resume.

> Can you trace the value passed to fastSeek() ? Fairly certain you will see
> negative values there

Sorry. :)

> about to seek to 159 endpoint.js:176:3
> seeked to 157.045464 endpoint.js:178:3
> event fired: timeupdate, currentTime = -0.000001 endpoint.js:91:5

Line 1 is the value we pass to fastSeek(). Line 2 is the value we get from currentTime immediately after fastSeek(). Line 3 is the currentTime from the next timeUpdate event we get.

> I believe you're only seeing (1) because of (2), there's no two "ended" event
> per media element, unless you've seeked backward and play again.

Well, that's what I'm seeing:

> event fired: ended, src = blob:app://music.gaiamobile.org/e6428344-dc92-4f23-bda2-0ea6d1a90c11 endpoint.js:96:5
> play(/sdcard1/Music/Poledouris, Basil/Conan the Barbarian OST/02 - Basil Poledouris - Riddle of Steel - Riders of Doom.mp3) endpoint.js:116:3
> event fired: timeupdate, currentTime = -0.000001 endpoint.js:91:5
> event fired: ended, src = blob:app://music.gaiamobile.org/e6428344-dc92-4f23-bda2-0ea6d1a90c11 endpoint.js:96:5
> play(/sdcard1/Music/Poledouris, Basil/Conan the Barbarian OST/03 - Basil Poledouris - Gift of Fury.mp3) endpoint.js:116:3
> about to seek to 4 endpoint.js:177:3
> seeked to 4 endpoint.js:179:3
> event fired: timeupdate, currentTime = 4 endpoint.js:91:5
> play(/sdcard1/Music/Poledouris, Basil/Conan the Barbarian OST/02 - Basil Poledouris - Riddle of Steel - Riders of Doom.mp3): about to set audio src endpoint.js:132:5
> about to seek to 5 endpoint.js:177:3
> seeked to 5 endpoint.js:179:3
> play(/sdcard1/Music/Poledouris, Basil/Conan the Barbarian OST/03 - Basil Poledouris - Gift of Fury.mp3): about to set audio src endpoint.js:132:5
> event fired: play endpoint.js:77:5

In the above, the play() function responds immediately to the "ended" event (see line 2), but doesn't update audio.src (line 9) until *after* two "ended" events have already been fired (lines 1 and 4). Note again that the currentTime from the timeupdate event (line 3) is -0.000001.

	Jean-Yves Avenard [:jya]
	Comment 31 • 9 years ago

JW, any ideas on how currentTime could ever possibly be negative???

A rounding issue I can understand, but how could it ever be negative?

Unless the MP3 OMXPlayer returns a first frame as != 0, so we substract that value and rounding makes it appear negative.

Likely my fix to TimeUnit I'm about to push for bug 1222866 would fix that.

	Jean-Yves Avenard [:jya]
	Comment 32 • 9 years ago

Could you apply patch 1 of bug 1222866 and see if that fixes the double "ended" event.

I have a strong conviction that it will. The conversion from seconds to useconds and back could yield a different number ; which would explain when seeking to the end, that you ended up being 1us before the end ; which would cause playback to start again only to immediately stop.

	JW Wang [:jwwang] [:jw_wang]
	Comment 33 • 9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #31)
> JW, any ideas on how currentTime could ever possibly be negative???

Searching around the code...

https://hg.mozilla.org/mozilla-central/file/a2f83cbe53ac4009afa4cb2b0b8f549289b23eeb/dom/html/HTMLMediaElement.cpp#l1411

HTMLMediaElement::CurrentTime() returns mDefaultPlaybackStartPosition which we don't check if aTime is negative when assigning it to mDefaultPlaybackStartPosition.

https://hg.mozilla.org/mozilla-central/file/a2f83cbe53ac4009afa4cb2b0b8f549289b23eeb/dom/html/HTMLMediaElement.cpp#l1504

	JW Wang [:jwwang] [:jw_wang]
	Comment 34 • 9 years ago

Btw, I write a mochitest to produce negative currentTime:

function startTest(test, token) {
  var type = getMajorMimeType(test.type);
  var v = document.createElement(type);
  v.token = token;
  manager.started(token);
  v.currentTime = -123;
  v.src = test.name;
  v._name = test.name;

  var events = ["suspend", "play", "canplay", "canplaythrough", "loadstart", "loadedmetadata",
                "loadeddata", "playing", "ended", "error", "stalled", "emptied", "abort",
                "waiting", "pause"];
  function logEvent(e) {
    var v = e.target;
    Log(e.target.token, "got " + e.type);
  }
  events.forEach(function(e) {
    v.addEventListener(e, logEvent, false);
  });

  v.ontimeupdate = function() {
    Log(v.token, "v.currentTime=" + v.currentTime);
  };
  v.play();
}


logs:
7 INFO [12:29:39.564] gizmo.mp4-0 got play
8 INFO [12:29:39.565] gizmo.mp4-0 got waiting
9 INFO [12:29:39.565] gizmo.mp4-0 got loadstart
10 INFO [12:29:39.853] gizmo.mp4-0 got suspend
11 INFO [12:29:39.855] gizmo.mp4-0 got loadedmetadata
12 INFO [12:29:39.866] gizmo.mp4-0 got loadeddata
13 INFO [12:29:39.867] gizmo.mp4-0 got canplay
14 INFO [12:29:39.868] gizmo.mp4-0 got playing
15 INFO [12:29:39.869] gizmo.mp4-0 got canplaythrough
16 INFO [12:29:39.994] gizmo.mp4-0 v.currentTime=-123
17 INFO [12:29:45.710] gizmo.mp4-0 v.currentTime=-123
18 INFO [12:29:45.711] gizmo.mp4-0 got pause
19 INFO [12:29:45.712] gizmo.mp4-0 v.currentTime=-123
20 INFO [12:29:45.713] gizmo.mp4-0 got ended

It is weird we got the 'ended' event but currentTime remains -123.

	Jean-Yves Avenard [:jya]
	Comment 35 • 9 years ago

Yes, and this can only happen if you started seeking and currentState is HAVE_NOTHING

I saw nothing in the spec stating that we shouldn't store something less than 0 there. Just that is currentState is HAVE_NOTHING then we do "then it must set the media element's default playback start position to the new value"

On getting: "on getting, return the media element's default playback start position, "

so you could set it to a negative value and get a negative value on reading.

Only once readyState is >= HAVE_METADATA will seek by started and "If the new playback position is less than the earliest possible position, let it be that position instead." where the value will be set to 0.

Having said that, here they don't appear to set currentTime to a negative value.

	Jean-Yves Avenard [:jya]
	Comment 36 • 9 years ago

(In reply to JW Wang [:jwwang] from comment #34)

> It is weird we got the 'ended' event but currentTime remains -123.

ohhhh... of course !

fix on the way

	JW Wang [:jwwang] [:jw_wang]
	Comment 39 • 9 years ago

Comment on attachment 8689919 [details] [diff] [review]
P2. Add mochitest for negative seek time.

Review of attachment 8689919 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/test/mochitest.ini
@@ +770,5 @@
>  [test_video_dimensions.html]
>  tags=capturestream
>  [test_resume.html]
>  skip-if = true # bug 1021673
> +[test_seek_negative.html ]

remove the space between 'html' and ']'.

::: dom/media/test/test_seek_negative.html
@@ +12,5 @@
> +
> +var manager = new MediaTestManager;
> +
> +function startTest(test, token) {
> + var type = getMajorMimeType(test.type);

Use 2-spaces indentation instead of one.

@@ +68,5 @@
> +}
> +
> +// Note: No need to set media test prefs, since we're using XHR to fetch
> +// media data.
> +SimpleTest.waitForExplicitFinish();

MediaTestManager has done this for you.

	Pulsebot
	Comment 40 • 9 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/4863ecb989c7
https://hg.mozilla.org/integration/mozilla-inbound/rev/a963aa713bbf

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 41 • 9 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/4863ecb989c7
https://hg.mozilla.org/mozilla-central/rev/a963aa713bbf

	Adam Alldredge [:AdamA][Inactive]
	Comment 42 • 9 years ago

This issue is still occurring in Flame 2.6.

Environmental Variables:
Device: Flame 2.6 [Full Flash][512mb]
BuildID: 20151123142444
Gaia: bae13c9ac6a91beecd7c94384e2aef25ed1a3214
Gecko: d3d286102ba7f8801e9dfe12d534f49554ba50c0
Gonk: 205ac4204bbbb2098a8046444acba551ba5dc75a
Version: 45.0a1 (2.6) 
Firmware Version: v18D
User Agent: Mozilla/5.0 (Mobile; rv:45.0) Gecko/45.0 Firefox/45.0

Result:
Fast forwarding to the next song skips the next song and the song after that will not play correctly.

	Jayme Mercado [:JMercado] (Inactive 3/4/2016)
	Comment 43 • 9 years ago

Jean-Yves and JW please see comment 42.

	Jim Porter (:squib)
	Comment 44 • 9 years ago

Cool, thanks for testing this again! I was going to check it out today, but you beat me to it.

I'm still not 100% sure why this is happening, though.

	Jean-Yves Avenard [:jya]
	Comment 45 • 9 years ago

The commit what I believe the only regression that could have happened following bug 1222866.

The only way you can have currentTime < 0 is if you seek to a negative value with readyState = HAVE_NOTHING.

There's no other possibility as currentTime is always reset to 0 after that.

That it's negative points to a JS issue, calling Seek (or fastSeek) before the element's src being set or as it's just been set.
No seek < 0 should be performed between the time src is set and the loadedmetadata event is fired.

	Jim Porter (:squib)
	Comment 46 • 9 years ago

I can check again, but the last two times I traced all the changes to the <audio> element, currentTime was somehow set to -0.000001 *before* we ever touched the src. If I log everything, we get a timeupdate event before setting src, and inspecting currentTime gives < 0. I assume this is all in the same thread, so I'm not getting any weird reordering?

	JW Wang [:jwwang] [:jw_wang]
	Comment 47 • 9 years ago

I am not sure how these patches fix the problem described in comment 27.

https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.js#L186
It appears to me you should stop the timer of faskSeek when reaching the end of the song.

	Jim Porter (:squib)
	Comment 48 • 9 years ago

(In reply to JW Wang [:jwwang] from comment #47)
> I am not sure how these patches fix the problem described in comment 27.
> 
> https://github.com/mozilla-b2g/gaia/blob/master/apps/music/js/endpoint.
> js#L186
> It appears to me you should stop the timer of faskSeek when reaching the end
> of the song.

That fixes (well, works around) this bug, but not the related bug 1226307. It also doesn't explain how we get a negative currentTime, since the music app never sets currentTime to a negative value, and :jya says it's impossible for that to happen.

The specific issue in this bug is as I said in comment 20: "Fast-seeking while we're still loading a song(?) causes mozinterruptbegin to fire, but no mozinterruptend, meaning we can't play music anymore. This seems to resolve itself once the music app goes to the background." While we can work around this by changing the behavior of our seeking code, there's probably still a Gecko bug here.

	JW Wang [:jwwang] [:jw_wang]
	Comment 49 • 9 years ago

I am kinda confused. Can you file another bugs so we can deal with only one issue in one bug?

1. This bug is fixed by the workaround, right?
2. negative currentTime is another issue.
3. mozinterruptend not fired which is yet another issue, right?

	Jim Porter (:squib)
	Comment 50 • 9 years ago

Based on comment 42, this bug is *not* fixed (although we can work around the problem in Gaia; see attachment 8689673 [details] [review]). I was using this bug to track (3) in your comment: mozinterruptend is not fired correctly. We could use this bug to land a workaround and file a new bug for the mozinterruptend issue; it's up to you.

Bug 1226307 is "the ended event is fired twice", which I think is actually the same issue as your point (2): currentTime can mysteriously end up negative.

	Justin D'Arcangelo [:justindarc]
	Comment 51 • 8 years ago

Not working on this. Unassigning myself.

	BMO Automation
	Comment 52 • 6 years ago

Firefox OS is not being worked on