Problems and crashes with local music collection

[Michi Henning]

We have just made a change to the thumbnailer that provides a 12x speed-up for extracting cover art from local music files with embedded artwork. I'm seeing serious problems with the song list in the music app with this new thumbnailer. I have tried very hard to find fault with what the thumbnailer is doing, but I don't think we are to blame. I need help getting to the bottom of this; I can't debug it myself. But I'm fairly confident that either the music app or the implementation of song list widget is doing something wrong.

I've attached an archive that contains 1000 songs, each of which has embedded cover art. (It's the same boring image for all of them.)

I'm seeing the problem on Mako, rc-proposed, build 359, which includes the new music app, I believe.

The modified thumbnailer is available in silo 31. Please let me know when you no longer need the silo, so I can release it again. (We are really short on silos at the moment; it might be best to grab the vivid arm debs from the silo.)

To reproduce the problem, install the silo, then:

- Kill the music app
- Clear out the Music folder
- untar the song collection into the Music folder
- run "thumbnailer-admin clear" to empty the caches
- monitor the device with top and wait for the media scanner to finish indexing
- Start the music app and go to the song list

I'm seeing really weird behavior. Initially, the song list flickers a few times, redrawing itself each time. After a few seconds, it settles down. Now start scrolling slowly. It might work for some distance but, after a few songs, the song list is reset to the top (first song) and redraws itself.

Now scroll down again, quickly. Again, the song list resets to the top.

Each time this happens, the song list is populated with a bunch of extra songs. Each time I scroll down, it works fine for the region that was cached previously, and then things blow up as soon as the scroll moves into the as-yet unexplored part.

Looking at the thumbnailer, I'm not seeing anything unusual. We deliver thumbnails as we should. But I notice that, for some reason, while scrolling in the song list, the music app also sends requests for artist art to the thumbnailer? Why? There is no artist in sight.

Some of the songs in the collection have an empty artist field and the thumbnailer returns an error for that (because asking for artist art without an artist doesn't make sense). But there can be other errors, such as errors returned by the remote server.

It looks like the song list resetting is related to the error return from the thumbnailer. Every time the thumbnailer reports that something could not be extracted, the song list misbehaves.

If the already-thumbnailed list gets too long, you can run

thumbnailer-admin clear

to empty caches. (There doesn't ever seem to be a problem in the region of the list that has been cached already.)

I'm also getting occasional crashes from the music app while trying all this. And, every now and then, I find a message such as

DelegateModel::cancel(): index out of range 34 0

in the music app log. (I have no idea whether that is related.)

I'd really appreciate if someone can look at this urgently. We want to land the improved thumbnailer but, while things are in this state, we can't. As best as I can tell, the problem might be related to incorrect error handling when the ThumbnailerImageResponse returns a request with status "invalid", either in the music app, or somewhere in the qml machinery.

[Michi Henning (michihenning)]

Adding thumbnailer and unity8-dash because I don't know which is the guilty party...

[Victor Thompson (vthompson)]

I can reproduce what you are seeing.

I see a lot of the following in the log:

Thumbnailer: RequestImpl::dbusCallFinished(): D-Bus error: DBusInterface::GetArtistArt(): /: unity::InvalidArgumentException: Thumbnailer::get_artist_art(): artist is empty
ThumbnailerImageResponse::dbusCallFinished(): D-Bus error: "Thumbnailer: RequestImpl::dbusCallFinished(): D-Bus error:DBusInterface::GetArtistArt(): /: unity::InvalidArgumentException: Thumbnailer::get_artist_art(): artist is empty

I also see the refreshes happening in views where the artist name isn't blank. For instance, it refreshes/redraws when I click on a valid Artist in the Artists tab. This would seem to suggest that it isn't just one component misbehaving.

When I run with just my modest music library I also experience the same redraw in the Songs tab, so I suspect it'd be problematic for most users.

[Michi Henning (michihenning)]

Great, thanks for double-checking.

The log messages are expected. They simply indicate that something didn't work when trying to get a thumbnail. It's not clear to me who is to blame here. As far as the thumbnailer is concerned, it receives an error indication from the server and returns an image response indicating that the request failed.

[Michi Henning (michihenning)]

Besides the core issue with the song list, why does the music app ask for *artist* art when I'm in the song list?

[Albert Astals Cid (aacid)]

Why is the dash added to a bug of the music app? How would the dash be involved in here?

[Victor Thompson (vthompson)]

For the Songs tab, the music app uses the art property provided by Mediascanner2. Therefore the image url that is requested is in the form: "image://thumbnailer/file:///home/phablet/Music/short-songs-with-artwork/
140.mp3"

So the app shouldn't be specifically asking for the artist artwork.

Could this issue be an ms2 problem?

[Michi Henning (michihenning)]

This my ignorance at work. What's the right project for a problem that is potentially caused the qml infrastructure applications use? Isn't the song list some pre-canned component? At least the image provider would be, I imagine?

[Albert Astals Cid (aacid)]

 - What's the right project for a problem that is potentially caused the qml infrastructure applications use?
The ubuntu-ui-toolkit? Qt?

- Isn't the song list some pre-canned component?
No idea, never had a look at the music-app code.

 - At least the image provider would be, I imagine?
You mean the thumbnailer?

[Michi Henning (michihenning)]

No, I meant whatever UI component consumes the image that comes out of the thumbnailer's image provider if successful, and the error when not successful.

Forgive me, but I know nothing about how all the UI stuff works. If I've assigned this to the wrong project, could you please re-assign to the one that's right? I don't know which one that might be.

[Victor Thompson (vthompson)]

Here's a very minimal app that exhibits the same issue: lp:~vthompson/+junk/test-songs/

To run just push to device and run qmlscene:

adb push test-songs.qml /home/phablet
phablet-shell
qmlscene ~/test-songs.qml --desktop_file_hint=/usr/share/click/preinstalled/com.ubuntu.music/current/com.ubuntu.music_music.desktop

[Albert Astals Cid (aacid)]

I don't know either, as we already discussed this on IRC yesterday, unity8 is not involved and someone that knows how the music-app code works needs to investigate it.

[Michi Henning (michihenning)]

Victor, with my limited qml knowledge, this seems to suggest that there is a problem with ListView?

[Victor Thompson (vthompson)]

I would assume it's an issue either with ms2 or thumbnailer's support for the image provider for image://thumbnailer/.

[Michi Henning (michihenning)]

I had a bit of a tinker with your simplified example, thanks for that!

The reset of the list happens each and every time we return an error from the thumbnailer. This is new; with the previous thumbnailer, you never saw any errors because the thumbnailer delivered a fallback image when something went wrong.

This behavior is going away (currently in silo 45), and the music app needs to handle errors for thumbnails that cannot be produced and provide its own fallback art in this case.

I know next to nothing about qml but, from reading some of the docs, it looks like you can delegate the image loading to a Loader that returns default art when something goes wrong.

[James Henstridge (jamesh)]

I simplified Victor's test program to the following:

http://paste.ubuntu.com/14991178/

Removing SortFilterModel gets rid of the flicker on start, but I still see the ListView reset to the start when scrolling through the results. All Image.source values are "image://thumbnailer/...", so the artist or album values shouldn't matter.

[Michi Henning (michihenning)]

Attached is a smaller set of test songs. None of these have an empty artist or album tag, and all of them contain cover art. The problem still shows up with your test qml, Victor.

None of these songs produce errors, so we can rule out the error handling as the culprit.

What I'm seeing is that the list resets to the beginning whenever there is a miss on the cache. It's easy to see this by following the thumbnailer log and scrolling down very slowly. Things work exactly up to the point where the first miss is encountered.

But, whether we have a miss or a hit at the service end makes no difference to the client, other than the amount of time it takes for the request to complete. (Hits and misses are indistinguishable to the client). I've verified that we are returning the correct image data on the client side after both hits and and misses.

I wonder whether there is a collation problem of some kind, or whether it is possible for the association of which request goes with what list item to get messed up somehow?

[Michi Henning (michihenning)]

Problem is caused by libtaglib. It helpfully opens the file for read-write, and it is impossible to open for read-only without jumping through unbelievable hoops :-(

Mediascanner2 has an inotify watch for IN_CLOSE_WRITE. Every time the thumbnailer made a new thumbnail, the media scanner concludes that the file has been modified. In turn, that causes a model update, which ends up re-drawing the list.

It is questionable whether re-displaying the list re-positioned at the first song is the correct behavior; it would seem more appropriate to re-display at the current view position, if possible. But that's a separate, unrelated issue.

James has modified the media scanner to check the modification time when getting an IN_CLOSE_WRITE. Opening and closing for writing doesn't update mtime unless there is an intervening call to write(2). I've verified that this fixes the problem on the phone.

[Launchpad Janitor (janitor)]

This bug was fixed in the package mediascanner2 - 0.111+16.04.20160225-0ubuntu1

---------------
mediascanner2 (0.111+16.04.20160225-0ubuntu1) xenial; urgency=medium

  [ James Henstridge ]
  * Batch index updates during the initial scan in 10 second intervals
    (the same rate as invalidation notifications go out). This greatly
    reduces the IO overhead on initial startup, and is fairly safe now
    we have out of process metadata extraction.
  * Don't emit the InvalidateResults signal if a file was opened for
    writing and then closed, but not actually modified (LP: #1542175)
  * Favour the EXIF DateTimeOriginal tag over DateTime when extracting
    metadata from photos. (LP: #1468585)
  * Use taglib to extract metadata from Vorbis, Opus, Flac, MP3 and MP4
    audio files. Other formats will fall back to the existing GStreamer
    code path. (LP: #1536832)

  [ CI Train Bot ]
  * debian/libmediascanner-2.0-3.symbols: update to released version.

 -- James Henstridge <email address hidden> Thu, 25 Feb 2016 01:53:33 +0000