Closed Bug 1150322 Opened 9 years ago Closed 9 years ago

[Flame][Music]The time on the right side shows "---:--" and the whole progress bar is abnormally highlighted in blue on music playing screen.

Categories

(Firefox OS Graveyard :: Gaia::Music, defect)

ARM
Gonk (Firefox OS)
defect
Not set
normal

Tracking

(blocking-b2g:2.2+, firefox38 wontfix, firefox38.0.5 wontfix, firefox39 wontfix, firefox40 fixed, b2g-v2.1 unaffected, b2g-v2.2 verified, b2g-master verified)

RESOLVED FIXED
2.2 S12 (15may)
blocking-b2g 2.2+
Tracking Status
firefox38 --- wontfix
firefox38.0.5 --- wontfix
firefox39 --- wontfix
firefox40 --- fixed
b2g-v2.1 --- unaffected
b2g-v2.2 --- verified
b2g-master --- verified

People

(Reporter: lixia, Assigned: hub)

References

Details

(Keywords: regression)

Attachments

(11 files, 2 obsolete files)

228.88 KB, text/plain
Details
7.50 MB, video/mp4
Details
6.85 MB, application/zip
Details
8.49 MB, application/zip
Details
3.20 MB, application/zip
Details
3.68 KB, text/csv
Details
46 bytes, text/x-github-pull-request
dkuo
: review+
squib
: review+
Details | Review
52.85 KB, application/x-zip-compressed
Details
10.52 KB, text/plain
Details
3.28 KB, patch
sotaro
: review+
Details | Diff | Splinter Review
9.28 MB, video/mp4
Details
[1.Description]:
[Flame][v2.2&3.0][Music]When playing a song, tap Next button until it backs to songs list, then play one song again, but the time on the right side shows "---:--", and the whole progress bar is abnormally highlighted in blue on music playing screen.

Found time:21:23
Attach:music_time.mp4  and logcat_2123.txt.
Test files:"01 - goodbye&hello.zip" ,"01. 9 Crimes.zip" and "蒋婷 - 天山之春 [mqms].zip".

[2.Testing Steps]: 
1.Open Music app and tap Songs tab.
2.Select a song to play.
3.Tap "Next" button untl it backs to songs list screen.
4.Then select one song to continue to play.
5.Repeat step 3 & step 4.

[3.Expected Result]: 
5.The time on the right side shows normally, and the whole progress bar is normally highlighted, with only the left side of progress bar highlighted.

[4.Actual Result]: 
5.The song will play normally, but the time on the right shows "---:--", and thge progress bar is abnormally highlighted in blue.

[5.Reproduction build]: 
Device: Flame 2.2 build(Affected)
Build ID               20150401002624

Gaia Revision          8b3086ad3963f1707e2bee9094baccafffe161c4

Gaia Date              2015-03-31 21:48:06

Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/20b67213a047

Gecko Version          37.0

Device Name            flame

Firmware(Release)      4.4.2

Firmware(Incremental)  eng.cltbld.20150401.042225

Firmware Date          Wed Apr  1 04:22:36 EDT 2015

Bootloader             L1TC000118D0

Device: Flame 3.0 build(Affected)
Flame 3.0:
Build ID               20150401160204
Gaia Revision          4bb3a933bd805e8df1e11827cb247754c3565b0b
Gaia Date              2015-04-01 02:06:11
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/e044f4d172e2
Gecko Version          40.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150401.193001
Firmware Date          Wed Apr  1 19:30:12 EDT 2015
Bootloader             L1TC000118D0


[6.Reproduction Frequency]: 
occasionally Recurrence,3/20

[7.TCID]: 
Free Test
Attached file logcat_2123.txt
Attached video music_time.mp4
Attached file 01. 9 Crimes.zip
Hi, Shally,

Can it be reproduced with the latest v2.1 build?
Thanks.
Flags: needinfo?(lixia)
Hi William,

    I try to repro this bug by the same test files,but I can't repro this bug on latest Nightly Flame v2.1 (Rate:0/30).Thanks.

---------------------------------------------------------------------------------------------
Device: Flame 2.1 build(Unaffected)
Build ID               20150406001204
Gaia Revision          87e55a7ec688138812181747f690fd188d2a0668
Gaia Date              2015-04-03 21:43:01
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/747b6132c44d
Gecko Version          34.0
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150406.034925
Firmware Date          Mon Apr  6 03:49:36 EDT 2015
Bootloader             L1TC000118D0
Flags: needinfo?(lixia) → needinfo?(whsu)
A regression.

Basic functionality is broken.
blocking-b2g: --- → 2.2?
Flags: needinfo?(whsu)
Keywords: regression
QA Whiteboard: [MGSEI-Triage+]
Blocking for regression.

Hub, could you please take a look. Thanks!
Flags: needinfo?(hub)
blocking-b2g: 2.2? → 2.2+
Assignee: nobody → hub
Status: NEW → ASSIGNED
Flags: needinfo?(hub)
I see this happening too, on master. I don't know under which circumstances, but definitely happening.
For some reason we get audio.duration to be Infinity. Which according to the documentation mean that it is streamed...
To me it looks like a Gecko regression as we get fed the Audio element with an "infinite" duration. Will try to find a regression range.

I'm wondering if bug 1153895 isn't related to that as well. (just a hunch)
Bug 1153960 seems the same as this issue because the duration text also shows "---:--", though they are not exactly the same. I think Hub is on the right direction, those issues seems all caused by the audio element changes in gecko.
See Also: → 1153960
(In reply to Hubert Figuiere [:hub] from comment #12)
> To me it looks like a Gecko regression as we get fed the Audio element with
> an "infinite" duration. Will try to find a regression range.
> 
> I'm wondering if bug 1153895 isn't related to that as well. (just a hunch)

Actually bug 1153895 occurred at the beginning of this week, and now it's no longer reproducible for some reason, probably due to one of the backouts we did to close the smoketest blocker.  Seeing that this bug was reported in April 1st, it's sort of unlikely that Bug 1153895 are connected to it.
QA Contact: jmercado
Currently git bisect of Gecko lead to some unrelated code in AddonWatcher. Not exactly sure what's going on yet.
Bug 927349 seems to have caused this issue.

Mozilla-inbound Regression Window

Last Working 
Environmental Variables:
Device: Flame 2.2
BuildID: 20150104211243
Gaia: c2bf20d23851d5fda9f8f0ef0267db5f49152376
Gecko: b9f40d0310d5
Version: 37.0a1 (2.2) 
Firmware Version: v18D-1
User Agent: Mozilla/5.0 (Mobile; rv:37.0) Gecko/37.0 Firefox/37.0

First Broken 
Environmental Variables:
Device: Flame 2.2
BuildID: 20150105033543
Gaia: 4ceeff19086b2a2955f044ad923dcfa63a293de3
Gecko: b9ba4d717f8a
Version: 37.0a1 (2.2) 
Firmware Version: v18D-1
User Agent: Mozilla/5.0 (Mobile; rv:37.0) Gecko/37.0 Firefox/37.0

Last Working gaia / First Broken gecko - Issue DOES occur
Gaia: c2bf20d23851d5fda9f8f0ef0267db5f49152376
Gecko: b9ba4d717f8a

First Broken gaia / Last Working gecko - Issue does NOT occur
Gaia: 4ceeff19086b2a2955f044ad923dcfa63a293de3
Gecko: b9f40d0310d5

Gaia Pushlog: http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=b9f40d0310d5&tochange=b9ba4d717f8a
QA Whiteboard: [MGSEI-Triage+] → [MGSEI-Triage+][QAnalyst-Triage?]
Flags: needinfo?(ktucker)
Brian, can you take a look at this please? This might have been caused by the work done on bug 927349.
Blocks: 927349
QA Whiteboard: [MGSEI-Triage+][QAnalyst-Triage?] → [MGSEI-Triage+][QAnalyst-Triage+]
Flags: needinfo?(ktucker) → needinfo?(bbirtles)
I've had a look but I can't immediately see anything that could have caused this. I'll try to reproduce it locally but it's going to take me a while to get a test environment set up.

My best guess at this stage is there's some race surrounding when we read back the audio.duration and that something about bug 927349 affects the timing of some callbacks so that we hit that case more often.

Chris or Matt, what are the cases where audio.duration might return Infinity? (as per comment 11 and comment 12)
Flags: needinfo?(kinetik)
Flags: needinfo?(cpearce)
I can't seem to reproduce this on my Flame device with a trunk build. I see a but where the middle song regularly gets skipped (i.e. it jumps to the end then onto the next song), but that's all.
My bisecting found a different revision for something not related either.

It was 325b241b452d
changeset:   237320:325b241b452d
user:        David Rajchenbach-Teller <dteller@mozilla.com>
date:        Thu Apr 02 12:14:04 2015 +0200
summary:     Bug 1150432 - AddonWatcher assumes that totalCPOWTime is in milliseconds, while it is in microseconds;r=yoric

Another bisecting showed something even different. It is really weird. (all with the same version of gaia)
This issue was much easier to reproduce using only the 9 chimes audio file attached.  Hope that helps with reproduction and fixing this issue.
I can't reproduce this on a trunk build (trunk Gecko and trunk Gaia) even using the 9 Crimes audio file so I'm not sure I can help here.

It seems like we need a more accurate regression range first. Even if it does prove to be related to bug 927349, my best guess at this stage is an existing race condition exposed by the changes to timing introduced by that bug.
Flags: needinfo?(bbirtles)
Hub: have you tried adding logging to player_view.js to see what is actually happening here? When this bug appears, is the duration of the song actually being reported as infinite or is that just speculation?

When I look at updateSeekBar in player_view.js, I see that if isTouching somehow gets set to true, then durationchange events will be ignored. Since the seek region is quite near to the skip forward button, perhaps isTouching is being set somehow and is not reset when the app transitions back to the list of all songs?

We're running out of time. Even if there is a gecko regression causing this, we need to be working on a gaia workaround.  And it could well be that this is actually a gaia bug.
Flags: needinfo?(hub)
If you can reproduce this reliably, it would be easy to test whether commenting out that isTouching test makes the bug go away.  If so, then we need to figure out what is causing isTouching to be incorrectly set to true.
The "Infinite" value is given to me by the WebIDE debugger. And I added logging too to confirm the code path.

'itTouching' is a clue. I'll try that. It seemed ok to me.
Flags: needinfo?(hub)
On the gaia side we already do some stuff wrong, albeit in that case not the problem.

For example in "seekAudio"

  var startTime = this.audio.startTime;

This produce "undefined" as startTime isn't a known property of audio - and we pass that to this.setSeekBar().

To answer to comment 23 and comment 24, we hit this.seekAudio() from the event handler for "timeupdate". This is where this.audio.duration is 'Infinite'.
See Also: → 1149090
We receive ONE 'durationchange' event per sond and in that case audio.duration is Infinity.

Note that the handler is mostly the same as 'timeupdate' and we get this one regularly, still with the audio.duration set to Infinity.
I find this is easy to reproduce on master, using the attached audio files.  I can only reproduce it for the "9 Crimes" song, however, so possibly there is something special about that file.

I can also reproduce it by just starting at the tiles view, tapping on 9 crimes.  Then tapping on the 'previous song' button as needed to restart the song over and over until the bug occurs.  It happens pretty often.

Hub and Jayme: have either of you ever seen this bug occur with any song other than the attached 9 Crimes?
Flags: needinfo?(jmercado)
Flags: needinfo?(hub)
(In reply to David Flanagan [:djf] from comment #28)
> I find this is easy to reproduce on master, using the attached audio files. 
> I can only reproduce it for the "9 Crimes" song, however, so possibly there
> is something special about that file.
> 
> I can also reproduce it by just starting at the tiles view, tapping on 9
> crimes.  Then tapping on the 'previous song' button as needed to restart the
> song over and over until the bug occurs.  It happens pretty often.
> 
> Hub and Jayme: have either of you ever seen this bug occur with any song
> other than the attached 9 Crimes?

I could notice this bug on many different songs.
I was not able to understand why would it happen to some of them and not on others however. Or why sometimes and not always: I didn't tried to check if it was happening everytime on the same files.
Some thoughts on this bug:

1) If we can't find other music files that this happens for, it makes it less urgent to find a fix, and we might want to re-consider blocking.

2) Even if we can't find a fix to the underlying infinite duration bug, we should modify the way we draw the status bar in gaia, so that we use the current time (or the maximum currentTime value we've ever seen) as the max value for the status bar.  The user should be able to drag the thumb backwards to earlier parts of the song.  So even if we can't fix it completely, we can make the user experience better in gaia.

3) The fact that Jayme's bisection points to bug 927349 is interesting because that bug is about the timing of CSS animations and I just fixed another music bug 1148342 which was related to the failure to receive a transitionend event causing the music app to behave incorrectly. I wonder if there could be anything similar going on here.
I only managed to reproduce it once when not using the 9 crimes file and it took many attempts (more than 10 but I don't have the exact number written down anymore).
Flags: needinfo?(jmercado)
(In reply to Clément Lefèvre from comment #29)
> 
> I could notice this bug on many different songs.
> I was not able to understand why would it happen to some of them and not on
> others however. Or why sometimes and not always: I didn't tried to check if
> it was happening everytime on the same files.

Thanks. If there are any songs that you can attach (or email to me privately if there are copyright concerns) for testing that would be really helpful.  Have you ever seen this bug occur for songs that are not .mp3 files?  (And are you that this is the bug you were seeing and not bug 1148312 or one of its duplicates where we also displayed ---:-- along with "Unknown title"?)

Any more information you can provide here would be very helpful. Thanks!
Flags: needinfo?(clement.lefevre)
I've tried modifying player_view.js so that it creates a new audio element each time it switches to a new song, hoping that that might workaround the gecko issue, but it doesn't.

I notice that when the bug does not occur, the 9 crimes song reports a slightly different duration each time. That makes me think that this mp3 has some kind of variable bit rate thing going on, and the process of calculating the duration is somewhat non-deterministic. I'm not sure why that would be.  But I don't think I've seen that before with my .m4a audio files. I think their duration is always exactly the same to multiple decimal points.  For this file, I set a duration between about 223.9735 and 223.9742

Could that variability have anything to do with the bug, I wonder. Could the fact that it is within 3/100ths of a second of a whole number of seconds have anything to do with the bug? Just random guesses, of course. I've got no idea how the duration is computed for these files.

Does the device have special purpose hardware for decoding mp3s? Is that hardware computing the duration? Maybe there's a bug in the way that hardware interacts with the GPU? It seems to me that this bug is more likely to occur when there is a big animated transition going on then when there is a smaller transition.

At least the music plays. And we can fix the time bar to do something not so horrible when the duration is unknown.
A bit of a breakthrough: in player_view.js, if I take the content of setAudioSrc() and delay it by 1000ms with a setTimeout, then the bug does not occur anymore.  I don't know what this means, but I'd say it makes it more like that this bug does have something interaction with the CSS transitions that are going on.
Some thoughts on how we might work around this:

- We should look at the metadataloaded event and see if we have a non-zero, non-Infinite duration when that event arrives.  If so, we should store it and then use that value if it is followed by a durationchange event that sets the duration to Infinity.

- We could also try something where if we get a durationchange event with Infinity and we've only just started playing we could re-load the song and try again.  We'd want to be careful not to get into an infinite loop doing that, of course.

And if we don't want to have to work around it, it would be a good idea to create a simple web page or app that reproduces the infinite duration bug. That could help us determine whether it is necessary to have some kind of CSS transition going on at the same time to reproduce it.
IIRC the 'durationchange' event is sent for songs that use a variable bit rate encoding. It would be nice to know which, if any, of the zipped MP3 files attached to this bug use VBR and if that could have anything to do with this bug.

Anthony: is there anyone on your team who could help us with this 2.2 blocker bug? Why are we sometimes getting an infinite duration for this one attached '9 Crimes' song? See comment #18, for example.
Flags: needinfo?(ajones)
It sometime reproduces with the first track of "Pink Floyd" "The Division Bell". This is a rip from my CD done with iTunes a while ago. I used to reproduce almost all the time with it. Recently less, but still.
Flags: needinfo?(hub)
(In reply to David Flanagan [:djf] from comment #35)

> - We should look at the metadataloaded event and see if we have a non-zero,
> non-Infinite duration when that event arrives.  If so, we should store it
> and then use that value if it is followed by a durationchange event that
> sets the duration to Infinity.

I tried this, I also get Infinite duration on that event. If I'm not mistaken they are sent almost at the same time from Gecko in HTMLMediaElement::MetadataLoaded() but this one after duration change.
See around dom/html/HTMLMediaElement.cpp:3177
Using the 'file' command on the three mp3 files attached to this bug gives:

Audio file with ID3 version 2.3.0, contains: MPEG ADTS, layer III, v1, 320 kbps, 44.1 kHz, JntStereo

I don't really know anything about ADTS, but I know that the S is for streaming. So if these files were intended for streaming use, it seems less surprising that we'd get an infinite duration from one of them.

It still seems like there is a gecko bug, though.
(In reply to Hubert Figuiere [:hub] from comment #37)
> It sometime reproduces with the first track of "Pink Floyd" "The Division
> Bell". This is a rip from my CD done with iTunes a while ago. I used to
> reproduce almost all the time with it. Recently less, but still.

What's the file format? It it also ADTS by chance?
Flags: needinfo?(hub)
(In reply to David Flanagan [:djf] from comment #32)
> (In reply to Clément Lefèvre from comment #29)
> > 
> > I could notice this bug on many different songs.
> > I was not able to understand why would it happen to some of them and not on
> > others however. Or why sometimes and not always: I didn't tried to check if
> > it was happening everytime on the same files.
> 
> Thanks. If there are any songs that you can attach (or email to me privately
> if there are copyright concerns) for testing that would be really helpful. 
> Have you ever seen this bug occur for songs that are not .mp3 files?  (And
> are you that this is the bug you were seeing and not bug 1148312 or one of
> its duplicates where we also displayed ---:-- along with "Unknown title"?)
> 
> Any more information you can provide here would be very helpful. Thanks!

So, I listened mp3 files and flac on my Flame. I guess my mp3 are either CBR or VBR.
I still can't get what is causing this issue, and everytime I noticed it and tried to go to the previous/next track and then come back to the affected one, it did not reproduced.

I honnestly don't think your ADTS have something to deal with this and anyway the music I've on my phone clearly come from CD rips. I could try to see again tracks where I notice it and privately provide it to you if you still need it, or give you some media informations about it with tools.
Flags: needinfo?(clement.lefevre)
Hub has sent me a copy of his file that reproduces the bug. And it reproduces for me, too.

That file is another ADTS mp3:

Audio file with ID3 version 2.2.0, contains: MPEG ADTS, layer III, v1, 160 kbps, 44.1 kHz, JntStereo

The other two files attached to this bug are the same. But they don't have album art. The two files I've seen that do cause it to reproduce are MPEG ADTS files with album art. Maybe just co-incidence, but possibly worth checking on.
(In reply to David Flanagan [:djf] from comment #42)
> Hub has sent me a copy of his file that reproduces the bug. And it
> reproduces for me, too.
> 
> That file is another ADTS mp3:
> 
> Audio file with ID3 version 2.2.0, contains: MPEG ADTS, layer III, v1, 160
> kbps, 44.1 kHz, JntStereo
> 
> The other two files attached to this bug are the same. But they don't have
> album art. The two files I've seen that do cause it to reproduce are MPEG
> ADTS files with album art. Maybe just co-incidence, but possibly worth
> checking on.

So, here are what info can give me: 
> Audio file with ID3 version 2.3.0, contains: MPEG ADTS, layer III, v1, 320 kbps, 44.1 kHz, JntStereo
> Audio file with ID3 version 2.3.0, contains:
> Audio file with ID3 version 2.3.0, contains: MPEG ADTS, layer III, v1, 320 kbps, 48 kHz, JntStereo
> Audio file with ID3 version 2.3.0, contains: MPEG ADTS, layer III, v1, 128 kbps, 44.1 kHz, JntStereo
> Audio file with ID3 version 2.3.0, contains: MPEG ADTS, layer III, v1, 320 kbps, 44.1 kHz, Stereo
As you can see, these are variable things, but ADTS is almost always here. I still don't thing it have something to deal with the issue…but why not.
I didn't pasted the result for FLAC files as I didn't noticed yet this issue on them. I don't have lot of my FLAC files on the Flame though and could put more. Notice too that file command give wrong result with VBR file: 128kbps line isn't a 128kbps CBR file but a VBR one (I will never get those low CBR bitrates ;) )

I'll join right after a CSV file with a lot more complete informations. Note that it does not correspond to the files of the previous lines and that the only one album (not track) I'm 100% sure the issue happened to the 4th and 5th ones. It happened on others, but I can't tell which ones right now.
Attached file Invisor Comparison.csv
So, as explained in the previous comment, issue happened for sure on tracks from the 4th and 5th albums, but maybe not the same track. Anyway, it comes from the same rip, so same kind of files.

I can't tell fore sure if it happened on the other ones even if I know it happened on more files.
Hema: we're going to need platform help with this bug to find out why these media files sometimes return infinite durations. I've been unable to get needinfo responses from the media team in New Zealand. Could you try escalating this somehow or ask for help from the Taipei media team?
Flags: needinfo?(hkoka)
Here are some things I think we should be doing with this bug on the Gaia end:

1) modifying the way we display the time slider when we have an infinite duration. We can make that much less broken if we do. 

2) Based on comment #34 I want to investigate whether this bug still happens if we turn off all CSS animations in the music app.

3) try to produce a simpler test case for the platform team. Can we create a simple web page or app that demonstrates the same bug?

Hub: do yo want to take any of these three items?
(In reply to David Flanagan [:djf] from comment #46)

> 2) Based on comment #34 I want to investigate whether this bug still happens
> if we turn off all CSS animations in the music app.
> 
> 3) try to produce a simpler test case for the platform team. Can we create a
> simple web page or app that demonstrates the same bug?
> 
> Hub: do yo want to take any of these three items?

I can try to tackle 3 maybe 2 if we can't do 3.
Flags: needinfo?(hub)
Thanks, Hub.  I'll take number 1.

Here's something else that I think we should do for this bug:

4) We should find out of this bug reproduces on devices other than the Flame.
I should add that I found I had a 32 chapters of an audio book encoded as ADTS MP3 files. I can't reproduce the bug with any of them. Maybe because they have low bit rate?

Audio file with ID3 version 2.3.0, contains: MPEG ADTS, layer III, v2,  64 kbps, 24 kHz, Stereo
Actually, those audio book files say "layer III, v2". The files I've seen this reproduce on are both "layer III, v1"  Also the audio book files are "Stereo" instead of "JntStereo"
(In reply to David Flanagan [:djf] from comment #50)
> Actually, those audio book files say "layer III, v2". The files I've seen
> this reproduce on are both "layer III, v1"  Also the audio book files are
> "Stereo" instead of "JntStereo"

Anyway it really looks like file give really approximative and possibly wrong results, as I pointed out wiht the example of the 128kbps file. Maybe should you check the informations you can get with a more precise media analyzing program ?
(In reply to David Flanagan [:djf] from comment #48)
> Thanks, Hub.  I'll take number 1.
> 
> Here's something else that I think we should do for this bug:
> 
> 4) We should find out of this bug reproduces on devices other than the Flame.

What other devices are supported with master? Because I don't have many options.

I now have a sample app that doesn't even behave the same way between desktop and Flame....
(In reply to David Flanagan [:djf] from comment #46)
> Here are some things I think we should be doing with this bug on the Gaia
> end:
> 2) Based on comment #34 I want to investigate whether this bug still happens
> if we turn off all CSS animations in the music app.

I commented out all of the transition styles in music.css and I can no longer reproduce the bug.

Then, to double-check, I uncommented this line at music.css:296

  transition: transform 300ms ease;

I tested by starting at the tiles view and tapping on the "9 Crimes" song and then tapping again on the next song button to go back to the tiles view.  With the transition in the app, the bug would reproduce about half the time.  With the transition commented out, the bug never reproduced on more than 20 trials.

Milan: is there anyone on your team who could help investigate this weird (and 2.2+) interaction between CSS animations and the code that computes the duration of audio files?
Flags: needinfo?(milan)
Commenting out music.css:296 seems to prevent the bug. Just changing the transition length from 300ms to 0ms does not make it go away, however. It is harder to reproduce with a 0ms transition, but it still occurs sometimes.
(In reply to David Flanagan [:djf] from comment #53)
> ...
> Milan: is there anyone on your team who could help investigate this weird
> (and 2.2+) interaction between CSS animations and the code that computes the
> duration of audio files?

Not a usual combination :)  Perhaps Kats and/or Sotaro.
Flags: needinfo?(sotaro.ikeda.g)
Flags: needinfo?(milan)
Flags: needinfo?(bugmail.mozilla)
Comment on attachment 8597401 [details] [review]
[gaia] davidflanagan:bug1150322 > mozilla-b2g:master

This attachment is a minor workaround to make the music app slider a little less broken when this bug occurs. With this patch, when the song reports an infinite duration, we'll have the thumb flush against the end of the slider rather than flush against the start of the slider. And the user will be able to drag the thumb to go back to an earlier part of the song.

It doesn't fix the underlying issue, but if we can't get that fixed, at least this will make the symptoms less florid.

Dominic and/or Jim: could you review this please? Note that the music app has some code that seems to anticipate being used with music streams rather than with music files. This patch probably breaks that use case, but as far as I know we never do that, do we?  If the open activity is ever used to play a song from a URL rather than from a blob, this patch might cause trouble, but I don't know that code well enough to be sure.
Attachment #8597401 - Flags: review?(squibblyflabbetydoo)
Attachment #8597401 - Flags: review?(dkuo)
I can reproduce this bug on a nexus5-l running a nightly build from last week.
The audio element that the Music app uses is created in the index.html file, and is in the document tree, though it does have the hidden attribute.  Just in case the element itself was somehow being affected by the CSS transitions, I modified the app to use 'new Audio()' and never insert the element into the tree. But the bug still reproduces just the same.
Attached file reduced test case
The attached zip file holds a very simple webapp that reproduces this bug. Hopefully it will make it easier for someone to get to the bottom of it.

Unzip the file and then use WebIDE to push the audio-test app to your phone.
Unzip the '01. 9 Crimes.zip' file and push the .mp3 file it contains to your phone.

Run the audio-test app. Click on the file input element. It will take you to the music app to pick a song. Pick the 9 crimes file (it may have to scan for it the first time). Then click Done to go back to the audio-test app.

Now click the play button. You'll see audio controls animate on to the screen. If it shows a reasonable duration, then the bug did not occur. So click stop. Then try again.

For me, it usually reproduces quite easily, and I see the duration start off at infinity and then very quickly change so that the duration is almost always the same as the current time.

If I write an app where I give the audio element an ordinary URL for the song, then gecko streams it, and I'd expect this behavior where it doesn't know the duration. But here we've got a file and a blob:url, so gecko ought to know the duration. But some of the time it treats this blob url like a stream.

If you edit the test app to comment out the CSS transition in index.html the bug goes away.

If you edit the test app to remove the background image, the bug becomes harder to reproduce.
In case anyone is keeping score, back in comment #46 and 48, I set out four things we could do on the gaia end here:

1) Make the slider work better in the infinite duration case in case we can't actually fix this bug.  That is done, and a patch is attached.

2) Find out whether this depends on CSS animations. We found out that it does.

3) Create a reduced test case. Done, and attached.

4) Find out whether this bug reproduces on other hardware.  I've reproduced it on a Nexus 5 as well as the Flame. My reduced test case does not reproduce it on desktop.
Comment on attachment 8597401 [details] [review]
[gaia] davidflanagan:bug1150322 > mozilla-b2g:master

I'm hesitantly r+'ing this, but I'd rather we not land it in master if possible. If we do decide that something like this is necessary in the long term, I'd rather we update our MediaDB to store the duration with the metadata so we have an authoritative source for the information.

I'm not sure how hard that is to do in JS, but we might be able to parse the Xing headers for mp3 to do this (which we'll probably need to do anyway if we want gapless playback).
Attachment #8597401 - Flags: review?(squibblyflabbetydoo) → review+
I would add by the way that, even if you're talking about streaming possibilities, streaming does not always means that you don't now duration: on some file/streams you know them, on other (mostly live), you don't. Here for a .mp3 files, even if you stream it, you are able to know its duration (what does mplayer most of the time for example).
Probably is it doing it by using metadatas Jim Porter is pointing just right above.
Attached file gdb backtraces
I looked into this a bit and it looks like a race condition in the media decoder code. It doesn't really have anything to do with CSS animations except that it makes the race easier to trigger, but I can reproduce the problem even without the CSS animation using dflanagan's attached test app.

It seems like in the "good" case MediaDecoderStateMachine::SetDuration gets called before the MediaDecoderStateMachine::EnqueueLoadedMetadataEvent queues the MetadataLoaded call, but in the "bad" case it doesn't. It's going to be hard for me to go deeper without fully understanding the promise-based architecture of this code and mental model of what's supposed to be happening, but I'm attaching backtraces from gdb of both good and bad cases. Looking at the file history for MediaDecoderStateMachine.cpp bholley seems like the right person to look into this.
Flags: needinfo?(sotaro.ikeda.g)
Flags: needinfo?(kinetik)
Flags: needinfo?(hkoka)
Flags: needinfo?(cpearce)
Flags: needinfo?(bugmail.mozilla)
Flags: needinfo?(bobbyholley)
Flags: needinfo?(ajones)
Jim: thanks for the review. I don't understand why you don't want it on master. My goal with this patch wasn't to work around the bug but to handle it better if it does occur. I think that having the thumb at the end of the slider rather than the start, and allowing the user to seek backwards in this case are big wins, without any downside. I would have thought we'd want to land this even if the gecko bug gets fixed. What am I missing? Did I break something?

Also, since I wrote that patch, I've realized that there is some rtl-specific code that assumes that the duration is finite, so I think my patch needs to be revised to handle the infinite duration case in RTL locales.
Flags: needinfo?(squibblyflabbetydoo)
MDN says that stuff that actually has an infinite duration is a stream, and I'm pretty sure streams (e.g. internet radio) can't be seeked at all. Once Gecko is reporting durations correctly, either a) we'll never encounter infinite durations, so this will be dead code, or b) we'll be treating non-seekable streams as seekable. Since it sounds like this is a race condition that Gecko devs plan to fix, I'd just as soon not add another workaround to the music app in master. I guess I don't care super-strongly, though.

Longer-term, it might make sense to decide what to do with *actual* streams. Should we support them? In the music app? In the radio app?
Flags: needinfo?(squibblyflabbetydoo)
Comment on attachment 8597401 [details] [review]
[gaia] davidflanagan:bug1150322 > mozilla-b2g:master

If I recalled correctly, back to the time I implemented the seekAudio(), I did have some mp3 that made the audio.duration gets different values, like NaN and Infinity, and that's probably why I tried to wrote those if else-cases to handle them, but looks like gecko has changed the audio element's behavior, or a gecko regression because we never encountered that before.

David's patch should be able to prevent the cases we didn't consider before, then fix this bug, but I imagine there will be a very quick time showing the current time/text equals to duration time/text? at least we won't break the seek bar anymore and the basic function works.

But if it's possible, we should have gecko patch to fix this, or file a gecko followup then write another gaia patch to adjust the duration logic, or like Jim mentioned, to parse and save the duration from metadata though it should cause more effort to do it.
Attachment #8597401 - Flags: review?(dkuo) → review+
As of now I manage to reliably *crash* gecko with these samples. Not sure whether this is related or not.
(In reply to Hubert Figuiere [:hub] from comment #68)
> As of now I manage to reliably *crash* gecko with these samples. Not sure
> whether this is related or not.

Where does the crash happened? I saw crash with local build ROM when start music playback. My case was caused by AudioSink's name conflict. I created a patch as part of Bug 1158293.
(In reply to Sotaro Ikeda [:sotaro] from comment #69)

> Where does the crash happened? I saw crash with local build ROM when start
> music playback. My case was caused by AudioSink's name conflict. I created a
> patch as part of Bug 1158293.

Seems to be mostly the same thing. Skipping to next track. I have no headphones.
The more I think about it, the more I realize we need to store track length along with the rest of the metadata (in the long term, at least). This would let us show the duration of songs when we're looking at a track list from an album, among other things.

For the scrubber, we'd probably want to consider the track length as reported by Gecko as the "authoritative" value, but if it gave us something obviously-wrong like this, we could fall back to the database's recorded duration.

I'll start looking into how complex this is. I'm sure it won't land for 2.2, but it might be worthwhile for 3.0.
(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #64)
> It seems like in the "good" case MediaDecoderStateMachine::SetDuration gets
> called before the MediaDecoderStateMachine::EnqueueLoadedMetadataEvent
> queues the MetadataLoaded call, but in the "bad" case it doesn't.

EnqueueLoadedMetadataEvent happens after ReadMetadata returns. Your stack traces show MediaOmxReader::ReadMetadata performing the SetDuration call in the case that mOmxDecoder->GetDuration(&durationUs) gives a non-zero value:

https://hg.mozilla.org/mozilla-central/annotate/37d60e3b8be6/dom/media/omx/MediaOmxReader.cpp#l305

mOmxDecoder is of type |android::sp<android::OmxDecoder>|, which means that one of the device-y media people should look at this.
Flags: needinfo?(bobbyholley) → needinfo?(sotaro.ikeda.g)
This is not a gonk only problem. It is a general mp3's problem. On mp3 playback, we do not always get duration synchronously. Current gecko media framework try to get correct duration even on VBR mp3. If we want to get correct duration on vbr mp3, we need to check whole mp3 file to calculate the duration. But to check whole mp3 file during parsing metadata takes too long time. Therefore, it is checked asynchronously. So, there could be a case that mp3 duration does not get at MediaDecoderStateMachine::EnqueueLoadedMetadataEven().

By the way, android does not calculate the vbr mp3's duration correctly. It is for getting the duration synchronously. Therefore on gonk, vbr mp3 duration was not always correct. It was fixed by Bug 831224.

On gonk, "synchronous duration get" is done in MediaOmxReader::ReadMetadata(). But we might not get a valid duration here in mp3 case.
https://hg.mozilla.org/mozilla-central/annotate/37d60e3b8be6/dom/media/omx/MediaOmxReader.cpp#l293

If the duration did not get, MediaDecoder::UpdateEstimatedMediaDuration() updates the mp3's duration. On gonk it is called on the following.
https://dxr.mozilla.org/mozilla-central/source/dom/media/omx/MediaOmxReader.cpp#507
Flags: needinfo?(sotaro.ikeda.g)
(In reply to Sotaro Ikeda [:sotaro] from comment #73)
> This is not a gonk only problem. It is a general mp3's problem. On mp3
> playback, we do not always get duration synchronously. Current gecko media
> framework try to get correct duration even on VBR mp3. If we want to get
> correct duration on vbr mp3, we need to check whole mp3 file to calculate
> the duration.

I don't think that applies in this case, since one of the failing files (attachment 8587128 [details]) is a 320 kbps *CBR* MP3.
(In reply to Jim Porter (:squib) from comment #74)
> (In reply to Sotaro Ikeda [:sotaro] from comment #73)
> > This is not a gonk only problem. It is a general mp3's problem. On mp3
> > playback, we do not always get duration synchronously. Current gecko media
> > framework try to get correct duration even on VBR mp3. If we want to get
> > correct duration on vbr mp3, we need to check whole mp3 file to calculate
> > the duration.
> 
> I don't think that applies in this case, since one of the failing files
> (attachment 8587128 [details]) is a 320 kbps *CBR* MP3.

Current gecko media framework seems to handle same way between vbr mp3 and CBR mp3. I do not know the parser could differentiate between two.
edwin, can you answer comment 74?
Flags: needinfo?(edwin)
I thought the point of the 'durationchange' event was that during playback, when we had a better idea of what the duration would be, it could be sent with an updated duration.  I'm not seeing that ever happen in this bug, however. We get durationchange right before metadataloaded when duration is set to Infinity, then we never get another durationchange event again.

Could we fix that, perhaps?
Since it doesn't look like we're going to get a gecko fix by the FC deadline, I'm going to go ahead and land the partial workaround. The tests were green and both Jim and Dominic gave r+ to it.

First, I'll address the comments they left:

(In reply to Jim Porter (:squib) from comment #66)
> MDN says that stuff that actually has an infinite duration is a stream, and
> I'm pretty sure streams (e.g. internet radio) can't be seeked at all. Once
> Gecko is reporting durations correctly, either a) we'll never encounter
> infinite durations, so this will be dead code, or b) we'll be treating
> non-seekable streams as seekable. 

These are good points. If we want to start supporting non-seekable streams, we'll have to add code that turns off the fast-forward and rewind functionality for those streams. Right now, those buttons still work for this fake infinite duration case, and my patch doesn't change that. All it does is put the thumb on the more useful side of the slider. We know that the current code doesn't handle inifinite durations correctly. This patch makes it a little better. Eventually we may want to replace it whth something correct. And even if it ends up being dead code, one isFinite() call is a pretty small price to pay for insurance against gecko regressions in the future.

Since it sounds like this is a race
> condition that Gecko devs plan to fix, I'd just as soon not add another
> workaround to the music app in master. I guess I don't care super-strongly,
> though.

Since you're don't have a really strong opinion here, I'm going to land on master and the request uplift, because that is the easier path to take to get the fix in.

(In reply to Dominic Kuo [:dkuo] from comment #67)
> Comment on attachment 8597401 [details] [review]
> [gaia] davidflanagan:bug1150322 > mozilla-b2g:master
> 
> If I recalled correctly, back to the time I implemented the seekAudio(), I
> did have some mp3 that made the audio.duration gets different values, like
> NaN and Infinity, and that's probably why I tried to wrote those if
> else-cases to handle them, but looks like gecko has changed the audio
> element's behavior, or a gecko regression because we never encountered that
> before.

I agree that something has changed. Hub pointed out on github (and earlier in this bug, I think) that audio.startTime does not exist. I really thought that it did exist and was used for live streams. That was part of the reason that I modified your existing code as much as I did in the patch.

> David's patch should be able to prevent the cases we didn't consider before,
> then fix this bug, but I imagine there will be a very quick time showing the
> current time/text equals to duration time/text? at least we won't break the
> seek bar anymore and the basic function works.

I was worried at first that the patch would start off a new song showing the duration of the last song because of the Math.max() call, but that doesn't happen because we always call setSeekBar(0,0,0) at the start of a new song. So I think this is okay.

We all agree that this still needs a fix in gecko, so we don't want to close this bug.

The gaia tree is closed, so I can't land the patch directly. I'll set checkin-needed so that autolander will land it, and we may need to reopen the bug once it does that.
Keywords: checkin-needed
Whiteboard: [keep open]
https://github.com/mozilla-b2g/gaia/pull/29719

Autolander could not land the pull request due to not having collaborator rights. This is possibly due to a tree closure. Please check the tree status and request checkin again once the tree is open.
Comment on attachment 8597401 [details] [review]
[gaia] davidflanagan:bug1150322 > mozilla-b2g:master

This patch does not fix the bug but it is a partial workaround that minimizes the symptoms that the user sees. I'd prefer a gecko fix, but if we can't have that, I think we should get this gaia patch in before the FC deadline.

Note that this has been reviewed and has passing tests, but has not landed on master yet because of today's Gaia tree closure.

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): unknown gecko regression, we think

[User impact] if declined: certain mp3 songs report an inifinite duration and the music app does a bad job of displaying the seek bar in that case. Music still plays correctly, though

[Testing completed]: yes

[Risk to taking this patch] (and alternatives if risky): not very risky

[String changes made]: none
Attachment #8597401 - Flags: approval-gaia-v2.2?(bbajaj)
Landed the partial workaround to master: https://github.com/mozilla-b2g/gaia/commit/b813864f8365322ff7efded51ea768c4474b1d4c

This does not resolve the bug, just mimimizes the symptoms, so leaving the bug open for a real solution.
Attached patch 1150322.patchSplinter Review
Flags: needinfo?(edwin)
Attachment #8599658 - Flags: review?(sotaro.ikeda.g)
(In reply to David Flanagan [:djf] from comment #78)
> I thought the point of the 'durationchange' event was that during playback,
> when we had a better idea of what the duration would be, it could be sent
> with an updated duration.  I'm not seeing that ever happen in this bug,
> however. We get durationchange right before metadataloaded when duration is
> set to Infinity, then we never get another durationchange event again.
> 
> Could we fix that, perhaps?

I am going to check about it.
Waiting for Sotaro's review to see if Edwin's patch is ok. 

:djf, if that works out then we don't need the work around, correct? Or do you still recommend landing it?
(In reply to Sotaro Ikeda [:sotaro] from comment #84)
> (In reply to David Flanagan [:djf] from comment #78)
> > I thought the point of the 'durationchange' event was that during playback,
> > when we had a better idea of what the duration would be, it could be sent
> > with an updated duration.  I'm not seeing that ever happen in this bug,
> > however. We get durationchange right before metadataloaded when duration is
> > set to Infinity, then we never get another durationchange event again.
> > 
> > Could we fix that, perhaps?

Handling of MediaOmxReader::mUseParserDuration seems not correct. If mp3 parser does not parse a frame yet in MediaOmxReader::ReadMetadata(), the mUseParserDuration is not set true. It blocks to update a duration MediaOmxReader::NotifyDataArrived().
The patch seems to fix the problem for me.
(In reply to Sotaro Ikeda [:sotaro] from comment #87)
> Created attachment 8599974 [details] [diff] [review]
> patch - Change mUseParserDuration handling
> 
> The patch seems to fix the problem for me.

This seems a regression of Bug 1039901.
Attachment #8599974 - Flags: review?(edwin)
(In reply to bhavana bajaj [:bajaj] from comment #85)
> Waiting for Sotaro's review to see if Edwin's patch is ok. 
> 
> :djf, if that works out then we don't need the work around, correct? Or do
> you still recommend landing it?

If either Sotaro's or Edwin's patch fixes this bug, then we don't need to uplift the gaia patch.

If any similar bugs were to be found however, (for different audio formats, e.g.) we'd be in better shape if we had uplifted the gaia patch. I'm not sure how to balance the risks and benefits here. We do know that the current gaia code in 2.2 is incorrect and the patch improves it. But the change is not strictly necessary.
Comment on attachment 8599974 [details] [diff] [review]
patch - Change mUseParserDuration handling

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

I'd rather get rid of mUseParserDuration since it seems totally redundant, but not super fussed either way.
Attachment #8599974 - Flags: review?(edwin) → review+
(In reply to Edwin Flores [:eflores] [:edwin] from comment #90)
> Comment on attachment 8599974 [details] [diff] [review]
> patch - Change mUseParserDuration handling
> 
> Review of attachment 8599974 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'd rather get rid of mUseParserDuration since it seems totally redundant,
> but not super fussed either way.

Yeah, it seems better.
Apply the comment. Carry "r=edwin".
Attachment #8599974 - Attachment is obsolete: true
Attachment #8600353 - Flags: review+
(In reply to David Flanagan [:djf] from comment #89)
> (In reply to bhavana bajaj [:bajaj] from comment #85)
> > Waiting for Sotaro's review to see if Edwin's patch is ok. 
> > 
> > :djf, if that works out then we don't need the work around, correct? Or do
> > you still recommend landing it?
> 
> If either Sotaro's or Edwin's patch fixes this bug, then we don't need to
> uplift the gaia patch.
Thanks, holding-off on gaia approval to take edwin's patch. No-jun, can you please help tets this one once the patch lands on m-c. Thanks!
> 
> If any similar bugs were to be found however, (for different audio formats,
> e.g.) we'd be in better shape if we had uplifted the gaia patch. I'm not
> sure how to balance the risks and benefits here. We do know that the current
> gaia code in 2.2 is incorrect and the patch improves it. But the change is
> not strictly necessary.
Flags: needinfo?(npark)
Attachment #8600353 - Attachment is obsolete: true
Comment on attachment 8599658 [details] [diff] [review]
1150322.patch

Sorry, I did not checked your patch. Your path is better than mine:-)
Attachment #8599658 - Flags: review?(sotaro.ikeda.g) → review+
attachment 8599658 [details] [diff] [review] seems to fix the problem on my device.
By the way, mUseParserDuration was also existed in GStreamerReader.
No-Jun,

In comment #93, Bhavana asks you to test on master. Note, though, that my gaia patch did land on master, so the symptoms of the bug are now different on master than they are on 2.2.  If the song duration comes out as infinite, on master you'll see the thumb against the right side of the slider with the duration updating every second as the song plays.  On 2.2 you'll still see what this bug describes a blue bar and duration listed as ---:--. Hopefully with the patch, you won't see the bug at all on master, however.
I tested with the fixes in on gaia master and I could no longer reproduced. This is good news.
I also tested with today's master, and in all instances the right side was decrementing correctly as the song played.
Flags: needinfo?(npark)
Thanks for testing, I'll wait for Edwin to request uplift here for the gecko patch. Meanwhile, clearing the gaia approval as that needn't land on 2.2.
Attachment #8597401 - Flags: approval-gaia-v2.2?(bbajaj) → approval-gaia-v2.2-
Flags: needinfo?(edwin)
Comment on attachment 8599658 [details] [diff] [review]
1150322.patch

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): MP3FrameParser
User impact if declined: Wrong or missing MP3 durations on B2G
Testing completed: Yes
Risk to taking this patch (and alternatives if risky): Low
String or UUID changes made by this patch: None
Flags: needinfo?(edwin)
Attachment #8599658 - Flags: approval-mozilla-b2g37?
Marking as fixed as patched landed on central
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Comment on attachment 8599658 [details] [diff] [review]
1150322.patch

Given QA already verify on master.
Attachment #8599658 - Flags: approval-mozilla-b2g37? → approval-mozilla-b2g37+
Whiteboard: [keep open]
Target Milestone: --- → 2.2 S12 (15may)
This bug has been verified as pass on latest Nightly build of Flame v3.0 by the STR in Comment 0.

Actual results: The time on the right/left side shows normally(ex: "00:01", "-03:42"),and the progress bar also displays normally.The played part of the song is highlighted in blue.
See attachment: verified_v3.0.mp4
Reproduce rate: 0/40


Device: Flame v3.0 build(Pass)
Build ID               20150511160205
Gaia Revision          6089234ace8b294a8feef064387604bae16254e3
Gaia Date              2015-05-10 13:57:12
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/502e1a5e722f
Gecko Version          41.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150511.193556
Firmware Date          Mon May 11 19:36:04 EDT 2015
Bootloader             L1TC000118D0
Attached video verified_v3.0.mp4
This bug has been verified as pass on latest Nightly build of Flame v2.2 by the STR in Comment 0.

Actual results: The time on the right/left side shows normally(ex: "00:01", "-03:42"),and the progress bar also displays normally.The played part of the song is highlighted in blue.

See above attachment: verified_v3.0.mp4
Reproduce rate: 0/40

Device: Flame v2.2 build(Pass)
Build ID               20150512002502
Gaia Revision          c4c1bf443f2b01c2ba918780510fd4c639a3c360
Gaia Date              2015-05-11 14:12:24
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/70782f19acbf
Gecko Version          37.0
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150512.041644
Firmware Date          Tue May 12 04:16:55 EDT 2015
Bootloader             L1TC000118D0
Update the version in Comment 109:

Device: Flame v2.2 build(Pass)
Build ID               20150512162502
Gaia Revision          e048df68f6f4853b5826a8816e143d95258149de
Gaia Date              2015-05-12 19:10:26
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/9edadb35caca
Gecko Version          37.0
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150512.202452
Firmware Date          Tue May 12 20:25:03 EDT 2015
Bootloader             L1TC000118D0
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: