No thumbnails generated for OGG audio

[Fred Vkigg]

Setup:
  Core Music app
  BQ HD5
  OTA-7 15.04 r6
  Large collection of audio files in .ogg and .mp3 format on SD card
  Audio files tagged with Artist, Album titile, Track title etc.

Expected result:
  Album covers and Artist images are displayed in Music app

Actual result:
  Only mp3 audio files generate thumbnails. No Album of Artist thumbnails are generated for any OGG files

To test the situation I have
a) Cleared the thumbnailer failure cache
b) removed the whole thumbnail cache directory
c) Removed and reinsterted the SD card
d) Uninstallled and reinstalled the core Music app

Before the OTA-7 upgrade the thumbnails were shown for .ogg and .mp3 files

[James Henstridge (jamesh)]

Can you verify whether the files in question have embedded artwork or not?

[Michi Henning (michihenning)]

For the failing files, do they actually contain embedded artwork, or just the artist and album tags? If the latter, the artwork comes from the remote image server. If the server can't be reached or is temporarily out of action, you won't get a thumbnail. As of OTA-8, we retry once every few hours if the server cannot be reached so, once you have OTA-8, the situation should rectify itself automatically.

If your files *do* contain embedded artwork, could you please attach one of the failing files (with its original file name intact) so we can have a look?

[James Henstridge (jamesh)]

I just got some failures when loading artist artwork on a newly flashed phone image. I got the following in the log:

    thumbnailer-service: [10:09:49.548] Critical: common_fetch(): Request failed: "Error downloading https://dash.ubuntu.com/musicproxy/v1/artist-art?artist=Alt-J&album=An Awesome Wave&key=0f450aa882a6125ebcbfb3d7f7aa25bc - server replied: Proxy Error"
    thumbnailer-service: [10:09:49.550] Warning: "Handler::createFinished(): unity::ResourceException: RequestBase::thumbnail(): key = Alt-J\0An Awesome Wave\0artist:
        fetch() failed"
    thumbnailer-service: [10:09:49.551] "artist: Alt-J/An Awesome Wave (437,0): 7.798722 [q: 0.000003, d: 7.775611] sec (ERROR)"

This looks like a glitch with the online art service, and entering the URL into the browser manually seemed to give the expected art. After thumbnailer-service exited due to inactivity, I ran "restart unity8-dash", and it looks like the failure was cached:

    thumbnailer-service: [10:14:25.649] "artist: Alt-J/An Awesome Wave (437,0): 0.001276 sec (FAILED PREVIOUSLY)"

Clearing the cache and trying again from the command line didn't seem to help:

    $ thumbnailer-admin clear
    $ thumbnailer-admin get-artist "Alt-J" "An Awesome Wave"
    thumbnailer-admin: Handler::checkFinished(): no artwork for artist: Alt-J/An Awesome Wave (0,0): FAILED PREVIOUSLY

Shutting down the thumbnailer and blowing away ~/.cache/unity-thumbnailer did get me my art though.

[Fred Vkigg (fvkigg)]

No embedded images in to audio OGGs, just tags with artist etc.

I'm fairly sure the problem is just related to OGGs. I have 95% OGGs and 5% MP3s, but no OGGs get thumbnails. This seems unrelated to the secondary problem that the backend service not always delivering images.

To further investigate I intend to cut down my music archive to just a few well know OGGs and MP3s and capture the logs. I couple of questions to help me inverstigate:

> Shutting down the thumbnailer and blowing away ~/.cache/unity-thumbnailer did get me my art though.
How do you force the thumbnailer to shutdown?

Which logs are relevant, core.music or thumbnailer?

Is it possible to direct call the Webservice (through curl etc) to validate what results I should expect?

I'l try an confirm that this is not just the problem that the retry logic in OTA-8 will fix.

[Michi Henning (michihenning)]

The service exits after 30 seconds of idle time, or you can run

thumbnailer-admin shutdown

With OTA-8, to clear the failure cache *including* the network retry timeout, run

thumbnailer-admin clear f

Or, with OTA-7, you can physically delete the thumbnailer cache files.

You can use a browser to check whether the server has artwork:

https://dash.ubuntu.com/musicproxy/v1/artist-art?artist=Alt-J&album=AnAwesome%20Wave&key=0f450aa882a6125ebcbfb3d7f7aa25bc

You can follow what the thumbnailer is doing by running

tail -f ~phablet/.cache/upstart.dbus.log

[Michi Henning (michihenning)]

Fred, could you please attach one of the problem files? I really would like to have a look at how it is tagged.

[Fred Vkigg (fvkigg)]

OGG audio file attached. Rhythmbox shows following tags:
Title: A Whiter Shade of Pale
Artist: Annie Lennox
Album: Medusa

Album Artist is empty. I'm going to try if setting this helps the thumbnailer. This evening (UTC) I will cut down the music collection on the sdcard to just a few files, clear caches etc, so I can see what happing in the logs.

[Fred Vkigg (fvkigg)]

Just cut down to just a few files on the sdcard and managed to get a thumbnail hit on an OGG file. So you should not see a problem with the OGG gile I attached,
I'll expand the trials a little to see if I can actually find the failure mode. I normally have several thousand files! I'll try and get something more concrete to you before OTA-8 comes out!

[Michi Henning (michihenning)]

I'm pretty sure that there is nothing wrong with extraction from ogg files; we have tests for this. But, if most of these files do not contain artwork and you add an SD card with thousands of songs and run up the music app, the music app will send hundreds of requests to the thumbnailer. No problem, the thumbnailer queues them all up and patiently grinds through them. However, for each file without embedded artwork, the remote server has to deliver an image. This is slow. So slow that, in all likelihood, some of those requests will time out in the app because they will spend more than 30 seconds in the queue before the thumbnailer even sends the request for the image to the server. Again, no big deal. The server will reply eventually, and the thumbnailer will cache the image. But the calling music app may well get tired of waiting and show you the "no artwork" default image instead.

However, if you scroll around in a song list or the like, as soon as you move away from a missing thumbnail far enough and scroll back to it, the app will re-issue the request for the thumbnail. That second request will be answered instantly because, by now, the thumbnailer will have the image in the cache and deliver it in about a millisecond.

So, I'm wondering whether what you are seeing is simply due to the fact that a lot of files are added at once, and it simply takes quite a while to fetch the thumbnails for all of them?

The other possibility is that, at the time you tried, the remote server had a problem, in which case we back off and stop asking the server again for two hours. That's to avoid hammering the network needlessly and draining the battery.

[Fred Vkigg (fvkigg)]

Michi thanks for the feedback. Hopefully it will help me determine the root cause of the strang behaviour.

> I'm pretty sure that there is nothing wrong with extraction from ogg files
Agreed.

> So, I'm wondering whether what you are seeing is simply due to the fact that a lot of files are added at once, and it simply takes quite a while to fetch the thumbnails for all of them?

Indeed possible. I wondering if the large number (and possibly large size) was indirectly the cause. Possible one of the many an varied OGGs I have cause a thumbnailer crash or hang. I will investigate this later.

What is strange is that I previously I had no thumbnails on OGGs and a high proportion of thumbnails on the few MPs I have. I did a) Cleared the thumbnailer failure cache
b) removed the whole thumbnail cache directory
c) Removed and reinsterted the SD card
d) Uninstallled and reinstalled the core Music app

After each change I gave the music app/thumbnailer a day or two to get more thumbnails, scrolled about a lot, open and closed the music app. The convergent result at the end was always the same files (MPs) having thumbnails!

I will continue to investigate. Please do not feel you need to spend more time looking at test cases, it looks like the problem is related to my special circumstances.

I'm think of writing a patch for the music app so it understand a kind of .nomedia tag file so that it does not include my audio book library in my music library!

[Fred Vkigg (fvkigg)]

Further.. My cut down sd card with only music files is slowly covering to have a large percentage of Album and Artist art even on the OGG files

[Michi Henning (michihenning)]

Thanks for the update, Fred!

If one of the files causes a crash or hang during extraction, the thumbnailer is robust against that and will kill off the offending process. (We thumbnail out-of-process for audio and video precisely to guard against this issue.) But, if that happens, you should find an error message in ~/.cache/upstart/dbus.log. If you happen to be able to identify a file that causes this kind of problem, I'd be really keen to get my hands on a copy!

Alternatively, would it be possible for you to send us a copy of your SD card that shows the problem? I'm sure we could reimburse you for the cost. Basically, if we can't reproduce the issue, we are mostly stabbing around in the dark. Once we have a reproducible test case, it's typically just a matter of latching on and not letting go until we've hunted the problem down…

[Michi Henning (michihenning)]

I've confirmed that your file works just fine when I drop it onto the phone. We successful fetch both album and artist art for it.

I suspect that we need to focus on the fact that tons of files are being added all at once.

[Fred Vkigg (fvkigg)]

Thanks for the feedback. Sorry to respond so slowly.

I'm still still seeing a slow increase in thumbnails. I suspect it will not converge to a complete coverage!

I need to further analyse the logs. One possibility is that I see a lot of OOM killer activity when Music app is open. I need to check the memory usage of the associated processes when Music is running.
The BQ 5 seems chronicly short of RAM for the current touch releases!

I will wait to see if the retry changes in thumbnailer in OTA-8 effect the results. If still bad I can post an SD card.

[Michi Henning (michihenning)]

Fred, thanks for getting bad to us!

If the music app gets killed, it might be because it asks for more than it can eat. If it sends a large number of requests to the thumbnailer, and lots of requests get a cache hit, the thumbnailer will deliver close to a thousand images per second, which can eat a lot of memory.

I suspect that the retry in the thumbnailer is not going to fix this. This sounds more like a scalability issue outside of the thumbnailer to me.

The SD card option would be ideal. I thought about doing something with my own music library, but all of my songs have embedded cover art in them, and it would take me an eternity to strip out all the cover images. And, even then, I would have no guarantee that I can reproduce the problem.

[Michi Henning (michihenning)]

"Fred, thanks for getting bad to us!"

Bloody auto-correct. My apologies, that should have read "... getting back to us!"

[Michi Henning (michihenning)]

Fred, any change with OTA-8?

[Fred Vkigg (fvkigg)]

Hi Michi,

thanks for the interest!

The experience was interesting.

After the upgrade I went into the Music app. It was interesting to watch as all the entries dispersed in front of my eyes :-% After a few application restart the Music app simple crashed on startup. Quick solution to this was simply to uninstall and reinstall it so it started in a fresh state. I assume problems in the media scanner here.

After reinstall the thumnnailer churched away and over a time and managed to get about 50% thumbnail coverage (no correlation to .mp3 or .ogg format). Dbus logs showed quite a number of network error responses from the thumbnailer. On subsequent runs you see the corresponding FAILED PREVIOUSLY responses. Since there about 400 artists and 600 albums the behaviour seems reasonable assuming the backend server was not responding in time to all requests.

To speed things up I did a 'thumbnailer-admin clear f'. After a bit more thumbnailer churning it reached about 100% coverage of the albums and artists I would expect to be known.

So good so far, until yesterday.

Before giving you an update I open up the music app. To my surprise no thumbnails where shown (blank squares not grey heads or grey quavers). Looking at the dbus logs showed 10s timeouts and I think a crash report from thumbnailer. Annoyingly my pastebin upload of the dbus.log from the Logviewer app failed.

After a reboot the thumbnaiker started to pull new thumbnails from scratch. I not quite sure what trigger the thumbnailer to purge (or loose) its image cache.

Sorry for the lack of concrete information, I hope you enjoyed the story however. I look at geting a copy of the SD card for you if you like.

[Michi Henning (michihenning)]

Hi Fred, thank you for taking the time to help diagnose this!

> On subsequent runs you see the corresponding FAILED PREVIOUSLY responses. Since there about 400 artists and 600 albums the behaviour seems reasonable assuming the backend server was not responding in time to all requests.

Hmmm… We rate-limit the requests we send to the remote server such that there are never more than two requests in progress concurrently. So, nothing should ever time out at the HTTP level unless the server truly didn't respond. (We will not mistake a long wait time before we can send a request for a timeout.)

At any rate, the FAILED PREVIOUSLY log entries indicate that this was a genuine authoritative "no artwork available" response. Most likely, some of your songs are for artists and/or albums for which the remote server has no artwork. You can verify this by using curl:

curl "https://dash.ubuntu.com/musicproxy/v1/album-art?artist=nosuchartist&album=nosuchalbum&key=0f450aa882a6125ebcbfb3d7f7aa25bc" >/tmp/out

Replace "nosuchartist" and "nosuchalbum" with the (percent-escaped) details.

If you have a thumbnailer crash, I'd be keen to get my hands on it. Is there anything in /var/crash?

Not sure what's going on with the music app. It might be an unrelated issue.

The thumbnailer will not ever purge its cache, unless it detects database corruption, in which case it reinitialises the DB. But you would see definite trace in the log for that.

I'm afraid that the best way for us to move this forward would be for us to get our hands on your music collection. I'm looking at ways to create artificial test data for such stress testing too, but it's going to be tedious, and I want to make sure that we are getting a reproducible test case.

Could you drop me a line at <email address hidden> please? I'd love to get a copy of your flash card so we can nail this bug. Of course, I'll reimburse you for the cost.

Cheers,

Michi.

[Michi Henning (michihenning)]

OK, probably no need for the flash card, I think I have reproduced the problem.

I'm attaching an archive that contains 7000 MP3 files, in subdirs of 1000 files each. Each MP3 is one second of silence, with exactly two tags, album and artist. The tags were created from server trace files (thanks Facundo!); they all have corresponding artwork in 7digital.

Once mediascanner has done its thing, when I start the music app, I end up with lots of Bad Request responses from the server. Not sure why yet. But, the net effect is that we cache the failures and there are tons of "no artwork" icons shown in the music app.

[Michi Henning (michihenning)]

MP3 attachment.

[Michi Henning (michihenning)]

Actually, no entries in the failure cache. Instead, the first Bad Request response from the server means that we stop trying again for two hours.

[Fred Vkigg (fvkigg)]

Michi,

looks like your 7000 files are behaving similar to what I saw. When I get some time I shall see if with a clear cache I also get Bad Request responses.

Saldly nothing in /var/crash. I know where to look now!

Good luck. I shall monitor the bug in case you need more feedback/ beta testing.

Cheers.

[Michi Henning (michihenning)]

If you try with your own collection and scan the log, if you find a bad request followed by loads of "failed previously", we are dealing with the same issue. If not, I'd still like to get my hands on your collection, but let's hold off with that for now.

I'm working on a fix at the moment. The problem is caused by the music app asking for artist art with an empty artist tag, and asks for album art with an empty album tag. For those, the remote server returns a bad request response. In turn, that sends the thumbnailer into an error handling path where it it incorrectly concludes that the server has returned something silly that should not normally happen (such as an internal server error) and then stops trying to talk the server for two hours.

The ultimate cause of the problem is a poorly-designed Qt API that, for a 400 response, returns a totally unexpected and counter-intuitive error code.

I should have fix ready today, but it won't become available until OTA-9, I'm afraid.

In the mean time, if that is feasible, check whether you can find any songs in your collection with an empty artist or empty album field. Setting these empty fields to something non-empty should fix the problem (if the issue you are seeing is indeed the same one as for my test data set).

[Fred Vkigg (fvkigg)]

I certainly seeing the failure mode you suggest. The third lookup in this log has an empty artist. There are a variety of other responses after this including HIT, NO ARTWORK and FAILED PREVIOUSLY.

thumbnailer-service: [21:20:04.256] "album: Joan Baez/Queen of Hearts (512,512): 0.003812 sec (HIT)"
thumbnailer-service: [21:20:04.523] "artist: "Punchy" Anderson/ (512,512): 7.352634 [q: 4.818276, d: 0.586561] sec (NO ARTWORK)"
thumbnailer-service: [21:20:04.833] Critical: common_fetch(): Request failed: "Error downloading https://dash.ubuntu.com/musicproxy/v1/artist-art?artist=&album=Irish Whistle CD Edition&key=4e34a78d0ca246f81a7d0a892cc9fba8 - server replied: Bad Request"
thumbnailer-service: [21:20:04.834] Warning: "Handler::createFinished(): unity::ResourceException: RequestBase::thumbnail(): key = \0Irish Whistle CD Edition\0artist:
    fetch() failed"
thumbnailer-service: [21:20:04.837] "artist: /Irish Whistle CD Edition (512,512): 7.665484 [q: 5.403909, d: 0.268904] sec (ERROR)"
thumbnailer-service: [21:20:04.988] "artist: "Punchy" Anderson/I Need the Green -12" (512,512): 7.817587 [q: 5.084229, d: 0.703537] sec (NO ARTWORK)"
thumbnailer-service: [21:20:04.993] "album: Adrain Barker, Ben Stephenson/Undertones (512,512): 0.030632 sec (FAILED PREVIOUSLY)"
thumbnailer-service: [21:20:05.003] "thumbnail: /media/phablet/3133-3039/Audio/Music/Blowzabella/Compilation/Death In A Fen _ Bruton Town _ Our Captain Cried.mp3 (512,512): 0.006540 sec (HIT)"
thumbnailer-service: [21:20:05.010] "thumbnail: /media/phablet/3133-3039/Audio/Music/Blowzabella/Octomento/Tanteeka And Round The Corner.mp3 (512,512): 0.012198 sec (HIT)"
thumbnailer-service: [21:20:05.015] "album: Chorchester Söhre-Kaufunger Wald/Un as der Rebbe tanzt (512,512): 0.009069 sec (FAILED PREVIOUSLY)"
thumbnailer-service: [21:20:05.039] "album: Musik: Mische Spoliansky Text: Robert Gilbert/Schlager zum Erröten (512,512): 0.001048 sec (FAILED PREVIOUSLY)"
thumbnailer-service: [21:20:05.071] "album: Ashley Hutchings and others/Grandson of Morris On (512,512): 0.001352 sec (FAILED PREVIOUSLY)"
thumbnailer-service: [21:20:05.077] "album: Ashley Hutchings and others/Son of Morris On (512,512): 0.000895 sec (FAILED PREVIOUSLY)"
thumbnailer-service: [21:20:05.087] "album: The Jockey Morris Men/Five More Men (512,512): 0.000811 sec (FAILED PREVIOUSLY)"

[Michi Henning (michihenning)]

OK, that pretty much makes it clear that your problem matches the one exposed by my test data. The hits are from other requests that were in flight around the same time.

[Michi Henning (michihenning)]

The Bad Request response issue is definitely fixed by the linked branch. I'm seeing much more robust behavior now.

We still have an issue with the error back-off being too aggressive when an individual request to the server times out. I'll work on that and try to get this into OTA-9. We have a separate bug for that problem:

https://bugs.launchpad.net/ubuntu/+source/thumbnailer/+bug/1528105

[Michi Henning (michihenning)]

Fred, the fix for this will become available with OTA-9, maybe a week or two away. When you update, please run

thumbnailer-admin clear f

Otherwise, old failures will keep hanging around in the cache.

[Fred Vkigg (fvkigg)]

Great, Will give you feedback as soon as OTA-9 is available.

[Fred Vkigg (fvkigg)]

The fix works fine. Album and Artist thumbnails are being retrieved now even where there are empty tags. I have checked a few cases where I get no artwork in Music app, and they all correspond to where the webservice does not deliver a result.

Thanks for the work and the release!

[Michi Henning (michihenning)]

Thanks for the confirmation, Fred. Glad it works for you now!