1171202 - Music app doesn't update its database (e.g. shows tile for a podcast that I've deleted from the device), if NPR Intelligence Squared podcast mp3 is present, with logcat showing "Error: index greater than buffer size" and "Error: MediaDB is not ready"

Status: VERIFIED FIXED

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

Description

[Daniel Holbert [:dholbert]]

Yesterday I loaded 3 new podcast files (mp3s) onto my Sony Xperia Z3C. The next time I opened the music app, it had some trouble scanning them -- as I recall, it spun forever while processing the first podcast. I eventually killed it and reopened it, and the music app then let me play that one podcast (but it didn't recognize that there were any other media files on the device).

I've now deleted that podcast, but the Music player still shows it as being the only playable thing (even though it's gone).

When I start up the music app, here's my logcat:
{

06-03 14:24:43.991 W/Music   ( 7066): [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "jar:file:///system/b2g/omni.ja!/components/DirectoryProvider.js" line: 81}]
06-03 14:24:44.151 W/Music   ( 7066): [JavaScript Warning: "mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create" {file: "app://customizer.gaiamobile.org/js/addon-concat.js" line: 23}]
06-03 14:24:44.181 I/Music   ( 7066): Content JS LOG: Injected addon-concat.js 
06-03 14:24:44.181 I/Music   ( 7066):     at <anonymous> (app://customizer.gaiamobile.org/js/addon-concat.js:7262:1)
06-03 14:24:44.291 I/Music   ( 7066): Content JS LOG: Injected components-concat.js 
06-03 14:24:44.291 I/Music   ( 7066):     at <anonymous> (app://customizer.gaiamobile.org/js/components-concat.js:15411:1)
06-03 14:24:44.581 I/Music   ( 7066): Content JS LOG: [Customizer] Injecting into app://music.gaiamobile.org/manifest.webapp 
06-03 14:24:44.581 I/Music   ( 7066):     at initialize/request.onsuccess (app://customizer.gaiamobile.org/js/addon-concat.js:7231:5)
06-03 14:24:44.591 I/Music   ( 7066): Content JS LOG: Sending HTTP request check to Customizer Launcher 
06-03 14:24:44.591 I/Music   ( 7066):     at MainController.prototype._checkOpenFromLauncher (app://customizer.gaiamobile.org/js/addon-concat.js:6159:5)
06-03 14:24:44.591 I/Music   ( 7066): Content JS LOG: [Customizer] Initialized MainController [object Object] 
06-03 14:24:44.591 I/Music   ( 7066):     at MainController (app://customizer.gaiamobile.org/js/addon-concat.js:6055:5)
06-03 14:24:44.631 W/Music   ( 7066): [JavaScript Warning: "Cross-Origin Request Blocked: The Same Origin Policy disallows reading the remote resource at http://localhost:3215/request. (Reason: CORS request failed)."]
06-03 14:24:44.911 E/Music   ( 7066): [JavaScript Error: "Error: index greater than buffer size" {file: "app://music.gaiamobile.org/js/metadata_scripts.js" line: 6}]
06-03 14:24:49.631 I/Gecko   ( 7174): ###################################### forms.js loaded
06-03 14:24:49.641 I/Gecko   ( 7174): ############################### browserElementPanning.js loaded
06-03 14:24:49.641 I/Gecko   ( 7174): ###################################### BrowserElementCopyPaste.js loaded
06-03 14:24:49.651 I/Gecko   ( 7174): ######################## BrowserElementChildPreload.js loaded
06-03 14:24:49.781 I/(Preallocated app)( 7174): PAC file installed from data: URI
06-03 14:24:58.401 E/Music   ( 7066): [JavaScript Error: "Error: MediaDB is not ready. State: enumerable" {file: "app://music.gaiamobile.org/gaia_build_defer_index.js" line: 337}]
}

Comment 1

[Daniel Holbert [:dholbert]]

I'm running an up-to-date Firefox OS 3.0 build, dogfood update-channel.

Comment 2

[Daniel Holbert [:dholbert]]

I'm happy to let someone take a look at this on my phone, or run some diagnostic commands myself to poke around in the app, to see if there's any information that can be gleaned. (See also adb logcat output in comment 0.)

In the meantime, this means my phone is useless for listening to audio files :-/  hence, adding "dogfood" keyword.

Comment 3

[Doug Sherk (:drs) (inactive)]

Jim, could you take a look at this please?

Comment 4

[Jim Porter (:squib)]

If Daniel posts a sample file that reproduces the issue, sure.

Comment 5

[Daniel Holbert [:dholbert]]

The file that triggered this for me was:
http://traffic.libsyn.com/hippiesympathizer/Confronting_the_evil_of_our_era_Climate.mp3

(I have no idea if this reliably reproduces the issue, or if I just hit a random race condition and it happened to be with this file. My music app's database seems to have been corrupted somehow; not sure how it happened.)

Comment 6

[Jim Porter (:squib)]

It might help if you could run WebIDE and get the full stack trace for this line:

06-03 14:24:44.911 E/Music   ( 7066): [JavaScript Error: "Error: index greater than buffer size" {file: "app://music.gaiamobile.org/js/metadata_scripts.js" line: 6}]

There's almost no way that's coming from the ID3 parser, since the ID3 parser catches errors like that and just skips the file. Do you have any MP4 or FLAC files? (This includes MP4 videos and .3gp files.)

Comment 7

[Daniel Holbert [:dholbert]]

(In reply to Jim Porter (:squib) from comment #6)
> It might help if you could run WebIDE and get the full stack trace for this
> line:

It looks like we can't usefully set breakpoints during app-startup, in the WebIDE debugger; I filed bug 1172114 on this. So, I don't think I can help with this part. :-/

> There's almost no way that's coming from the ID3 parser, since the ID3
> parser catches errors like that and just skips the file. Do you have any MP4
> or FLAC files? (This includes MP4 videos and .3gp files.)

I do have some .3gp files (videos recorded using the phone itself), in the DCIM/100MZLLA directory. Should I try deleting those?

Comment 8

[Jim Porter (:squib)]

(In reply to Daniel Holbert [:dholbert] from comment #7)
> I do have some .3gp files (videos recorded using the phone itself), in the
> DCIM/100MZLLA directory. Should I try deleting those?

If they're from the camera app, they should be ok, but it couldn't hurt to try removing them.

Comment 9

[Daniel Holbert [:dholbert]]

Yayy, that did it!  I moved my DCIM/100MZLLA folder off of the device, and now the music app renders as "Please load songs onto the memory card" (correctly reflecting that there are currently no mp3s on the device, rather than showing a blank tile for a previously-deleted mp3).

Would it help if I tried copying 3gp files back over, one at a time, to find out which one breaks stuff, and then send that breaking 3gp to you for further analysis/investigation?

Comment 10

[Jim Porter (:squib)]

(In reply to Daniel Holbert [:dholbert] from comment #9)
> Would it help if I tried copying 3gp files back over, one at a time, to find
> out which one breaks stuff, and then send that breaking 3gp to you for
> further analysis/investigation?

That would help very much indeed. I'm guessing that some part of the MP4 metadata parser is throwing an exception that we aren't catching.

Comment 11

[Jim Porter (:squib)]

Oh, and you can email me at <first initial><last name>@mozilla.com if you don't want to post the file to the bug. (My Bugzilla email is just for bugspam.)

Comment 12

[Daniel Holbert [:dholbert]]

Actually, I'm now hitting the "index greater than buffer size" problem with a particular NPR Intelligence Squared podcast mp3 file, whenever I try to copy podcasts back onto the device. Other podcasts copy & scan fine; but if I copy this particular NPR podcast file, the rescan operation fails, and the music app doesn't update its rendering.

I mailed this file to squib.

Comment 13

[Daniel Holbert [:dholbert]]

(Further testing with 3gp files and that NPR mp3 file, it now seems that my 3gp files are all fine; with all of them back on the device, I can add/remove mp3 files and the music app updates its tile-grid correctly. But if I have the NPR mp3 file on the device, then the grid fails to update after files are added/removed, and I see the "index greater than buffer size" error each time I start the music app.

For reference, the NPR mp3 file's md5sum & filename are:
 6c5bb35d38209a9c286455904bd54698  npr_411414499.mp3

Comment 14

[Daniel Holbert [:dholbert]]

The mp3 file is also available here:
 http://podcastdownload.npr.org/anon.npr-podcasts/podcast/510184/411414499/npr_411414499.mp3

I verified that a freshly-downloaded version of that file will also trigger this issue.

(My freshly downloaded file has a different md5sum (289105fd57c6592cf12c03b44c15a684) than comment 13, possibly due to edits that NPR made after initially posting the file.  But whatever the differences are between the two versions of this file, they don't seem to be relevant to this bug; both versions trigger it on my device.)

Comment 15

[Jim Porter (:squib)]

Attachment: Fix it

David: I know you're pretty busy with 2.2 blockers, but this should be an easy patch to review. All I did (aside from tests and some whitespace/doc fixes) was to add a couple of try blocks in the appropriate places.

Comment 16

[Jim Porter (:squib)]

Comment on attachment 8616295 [details] [review]
Fix it

[Approval Request Comment]
[Bug caused by] (feature/regressing bug #): N/A
[User impact] if declined: Putting broken mp3 files on a phone can cause the music app to be unable to scan for new files.
[Testing completed]: Unit tests provided in the patch
[Risk to taking this patch] (and alternatives if risky): Very low risk. This just adds some error-handling.
[String changes made]: None

Comment 17

[David Flanagan [:djf]]

Comment on attachment 8616295 [details] [review]
Fix it

I did not test this code myself, but it looks good to me.

I support the uplift request. If it is not too late, it would be good to get this change into 2.2

Comment 18

[Josh Cheng [:josh]]

Approving and requesting QA verify on 2.2 when patch landed there.

Comment 19

[Ryan VanderMeulen [:RyanVM]]

In the future, please include a link to the revision when a patch lands.

Master: https://github.com/mozilla-b2g/gaia/commit/fc27d9f5d58ae6f65a644150d15b9a0f01dadec4

Also, this needs rebasing for v2.2 uplift.

Comment 20

[Jim Porter (:squib)]

Attachment: Patch for 2.2

Here's the 2.2 uplift patch. I'm not forwarding the r+ yet until I see a green try run.

Comment 21

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8616975 [details] [review]
Patch for 2.2

This shows Gu failures on the Gaia Try run.
https://treeherder.mozilla.org/logviewer.html#?job_id=1331367&repo=gaia

Comment 22

[Jim Porter (:squib)]

Should be fixed. I had to remove some features since I doubt we can uplift bug 1122374 for 2.2 (it's huge).

Comment 23

[Jim Porter (:squib)]

Comment on attachment 8616975 [details] [review]
Patch for 2.2

Ok, tests look good. Passing forward r+.

Comment 24

[Verson Xiong (Leave from Mozilla)]

Attachment: verify_master.mp4

This bug has been verified as "pass" on latest build of Flame master,Nexus5 master.

STR
1.Connect PC and DUT via MTP mode.
2.Open music app.
3.Check music tile.
4.Loaded the issue file of comment 14 to DUT.
5.Check music tile.
6.Perform some operations on mp3 file(add/remove).
7.Check music tile.

Actually result(5,7): music app updates its database.
Reproduce rate: 0/10
See attachment: verify_master.mp4

Device: Flame master build(pass)
Build ID               20150609081832
Gaia Revision          06edb0f8db7c2f45cde54401a8593663059861a4
Gaia Date              2015-06-08 14:29:09
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/239c59921129
Gecko Version          37.0
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150609.122002
Firmware Date          Tue Jun  9 12:20:13 EDT 2015
Bootloader             L1TC000118D0

Device: Nexus5 master build(pass)
Build ID               20150609081840
Gaia Revision          ea27c4ed5b6083c9e21d233d4804372ac4d5d353
Gaia Date              2015-06-08 03:06:41
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/e10e2e8d8bf2
Gecko Version          41.0a1
Device Name            hammerhead
Firmware(Release)      5.1
Firmware(Incremental)  eng.cltbld.20150609.121002
Firmware Date          Tue Jun  9 12:10:19 EDT 2015
Bootloader             HHZ11k

Comment 25

[Ryan VanderMeulen [:RyanVM]]

v2.2: https://github.com/mozilla-b2g/gaia/commit/90ac4339c3c8411bff153bb41900bc4f6e000022

Comment 26

[Verson Xiong (Leave from Mozilla)]

Attachment: verify_2.2.3gp

Hi Daniel ,

This bug has been verified as "pass" on latest build of Flame 2.2,Nexus5 2.2.
In STR 7: these files can be recognized, but the npr_411414499.mp3 in STR 5 can't be recognized on v2.2, while it can be recognized by v2.0/v2.1/v3.0. For this problem on v2.2, could I file a new bug for tracking?

STR
1.Connect PC and DUT via MTP mode.
2.Open music app.
3.Check music tile.
4.Loaded the issue file of comment 14 to DUT.
5.Check music tile.
6.Perform some operations on mp3 file(add/remove).
7.Check music tile.

Actually result(7): music app updates its database.
Reproduce rate: 0/10
See attachment: verify_2.2.3gp

Verify environment:
Device:Flame 2.2(pass)
Build ID               20150611162501
Gaia Revision          cfceba16e48ede3defee24be93637a0fa291c494
Gaia Date              2015-06-11 22:10:18
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/3478f3c355c2
Gecko Version          37.0
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150611.195621
Firmware Date          Thu Jun 11 19:56:31 EDT 2015
Bootloader             L1TC000118D0

Device:N5_2.2(pass)
Build ID               20150611162501
Gaia Revision          cfceba16e48ede3defee24be93637a0fa291c494
Gaia Date              2015-06-11 22:10:18
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/3478f3c355c2
Gecko Version          37.0
Device Name            hammerhead
Firmware(Release)      5.1
Firmware(Incremental)  eng.cltbld.20150611.195436
Firmware Date          Thu Jun 11 19:54:51 EDT 2015
Bootloader             HHZ12f

Comment 27

[Daniel Holbert [:dholbert]]

(In reply to Verson from comment #26)
> the npr_411414499.mp3 in STR 5
> can't be recognized on v2.2, while it can be recognized by v2.0/v2.1/v3.0.
> For this problem on v2.2, could I file a new bug for tracking?

Sure, if you think it's a different issue from this bug. (I'm not sure I entirely understand the issue so I'm not sure.) Please CC :squib, if you do file a new bug.

> This bug has been verified as "pass" on latest build of Flame 2.2,Nexus5 2.2.

(Just to clarify what "pass" means here, given the remaining issue you mentioned -- so are you saying this one NPR file isn't recognized, but the music database will still be updated correctly to show other files that have been added/removed?)

Comment 28

[Jim Porter (:squib)]

(In reply to Daniel Holbert [:dholbert] from comment #27)
> (In reply to Verson from comment #26)
> > the npr_411414499.mp3 in STR 5
> > can't be recognized on v2.2, while it can be recognized by v2.0/v2.1/v3.0.
> > For this problem on v2.2, could I file a new bug for tracking?
> 
> Sure, if you think it's a different issue from this bug. (I'm not sure I
> entirely understand the issue so I'm not sure.) Please CC :squib, if you do
> file a new bug.

It's not a new issue. Because 2.2 is missing bug 1122374, we can't fall back to parsing ID3v1 tags, so all we can do is skip the invalid file. Unfortunately, bug 1122374 is too large to uplift, so I don't expect 2.2 will see any further improvements (especially since we passed the code complete deadline).

Comment 29

[Daniel Holbert [:dholbert]]

Ah, that makes sense.  Verson, sounds like everything is working in the way we expect it to, then; no need to file a new bug.