Image loading blocks the main thread

[hacker1024]

Describe the bug
The main thread is blocked when the plugin loads a new image for the notification.

To Reproduce
This can be observed easily if you turn off wifi/mobile data and add a new MediaItem. The network request takes a while to time out, and the app is unresponsive while it does.

Expected behavior
The image loading should be entirely asynchronous.

Runtime Environment (please complete the following information):

• Device: Xiaomi POCOPHONE F1
• Android version: 9.0 (Pixel Experience CAF ROM)

[hacker1024]

Actually, this only seems to happen 10% of the time. It's weird.

[ryanheise]

Unfortunately when I tried to implement this asynchronously a few months ago I hit a bug in the Flutter engine (see the comments in the Java method AudioService.preloadArtwork. So for now that's an option which is off by default.

Probably this same Flutter engine bug is responsible for the behaviour you observed when the network is down. Basically, even if I asynchronously start a thread that sleeps for 20 seconds and theoretically doesn't block anything else, Flutter's platform channels will be blocked for those 20 seconds. I don't even know how that works so it's a big mystery. I've reported it to Ben Konyi although it doesn't sound like anything has been done to address it so I might go and post an issue on the Flutter Engine github page.

[ryanheise]

I tried turning off wifi/mobile and while I couldn't reproduce one of those 10% thread blocking occasions, I did get the following stack trace which I'm pasting here for the benefit of my future self when I continue looking at this issue later.

W/System.err(28260): java.net.UnknownHostException: Unable to resolve host "XXXXXXXXXX": No address associated with hostname
W/System.err(28260): 	at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:111)
W/System.err(28260): 	at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:90)
W/System.err(28260): 	at java.net.InetAddress.getAllByName(InetAddress.java:787)
W/System.err(28260): 	at com.android.okhttp.Dns$1.lookup(Dns.java:39)
W/System.err(28260): 	at com.android.okhttp.internal.http.RouteSelector.resetNextInetSocketAddress(RouteSelector.java:175)
W/System.err(28260): 	at com.android.okhttp.internal.http.RouteSelector.nextProxy(RouteSelector.java:141)
W/System.err(28260): 	at com.android.okhttp.internal.http.RouteSelector.next(RouteSelector.java:83)
W/System.err(28260): 	at com.android.okhttp.internal.http.StreamAllocation.findConnection(StreamAllocation.java:174)
W/System.err(28260): 	at com.android.okhttp.internal.http.StreamAllocation.findHealthyConnection(StreamAllocation.java:126)
W/System.err(28260): 	at com.android.okhttp.internal.http.StreamAllocation.newStream(StreamAllocation.java:95)
W/System.err(28260): 	at com.android.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:281)
W/System.err(28260): 	at com.android.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:224)
W/System.err(28260): 	at com.android.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:472)
W/System.err(28260): 	at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:418)
W/System.err(28260): 	at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getInputStream(HttpURLConnectionImpl.java:249)
W/System.err(28260): 	at com.android.okhttp.internal.huc.DelegatingHttpsURLConnection.getInputStream(DelegatingHttpsURLConnection.java:210)
W/System.err(28260): 	at com.android.okhttp.internal.huc.HttpsURLConnectionImpl.getInputStream(Unknown Source:0)
W/System.err(28260): 	at com.ryanheise.audioservice.AudioService.loadArtBitmap(AudioService.java:415)
W/System.err(28260): 	at com.ryanheise.audioservice.AudioService$2.run(AudioService.java:388)

[ryanheise]

Good fortune has led me to accidentally encounter this bug out in the wild. I was walking through a dodgy wifi area when I got an ANR. Indeed, this is not the flutter engine bug I referred to above (after all, they fixed that), it is a bug in the plugin.

After later analysing the ANR dump, I noticed that the main thread was blocked within AudioService, and after reviewing the synchronized blocks, I believe I found the issue. Any code that updates the media metadata with an art URI is synchronized to preserve the integrity of the bitmap cache. setMetadata is synchronized because it can be called both on the main thread in response to a client request, and also on a background thread after image loading has complete. But the rule is that no method on the main thread should block. If a client calls setMetadata while a background image load is in progress, it will block and wait for that to finish first. This is obviously bad and will cause an ANR if the image takes longer than 5 seconds to load, which is the case I ran into when walking through the dodgy wifi area.

It was also reproducible in that I went back to the same area the next day and reproduced the ANR. On my second visit, I also tested my theory by switching off WIFI, and suddenly the app unblocked itself and continued playing the next track.

To hopefully solve this, I've modified the code so that setMetadata is not synchronized, and now only ever gets invoked on the main thread. When image loading in the background completes, it posts a new Runnable on the main looper to call setMetadata so that requests to set metadata are processed serially, but also without blocking the main thread. All synchronisation is now done off the main thread.

The fix is in the latest commit, although it hasn't been tested yet. I'll do some testing over the next few days.

[ryanheise]

Seems to work and is now published in 0.6.1.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs, or use StackOverflow if you need help with audio_service.