Exoplayer: Crash: DownloadManager Assertion fails for STATE_DOWNLOADING

[avalanchas]

Issue description

In our project, we currently see a crash in the exoplayer DownloadManager, when starting the download of a Podcast Episode. Let me give you the crash snippet and my suspicions first, more details below

Fatal Exception: java.lang.NullPointerException
       at com.google.android.exoplayer2.util.Assertions.checkNotNull(Assertions.java:5)
       at com.google.android.exoplayer2.offline.DownloadManager$InternalHandler.syncTasks(DownloadManager.java:57)
       at com.google.android.exoplayer2.offline.DownloadManager$InternalHandler.initialize(DownloadManager.java:83)
       at com.google.android.exoplayer2.offline.DownloadManager$InternalHandler.handleMessage(DownloadManager.java:98)
       at android.os.Handler.dispatchMessage(Handler.java:108)
       at android.os.Looper.loop(Looper.java:166)
       at android.os.HandlerThread.run(HandlerThread.java:65)

After accounting for Proguard, that's this line:

It is very hard to reproduce and does not happen often. At the moment I suspect a threading issue, I suspect that the two variables...

private final ArrayList<Download> downloads;
private final HashMap<String, Task> activeTasks;

... need to be declared volatile. Why? Because I managed to write a bit of reflection code that accesses those variables when the crash occurs, and today the Google Play Pre-Lanch report encountered the crash and it printed:
did it work?? -> downloads=[[]], activeTasks=[{}]
But how could the downloads list be empty? This crash happens inside a loop that iterates over that very list.

Reproduction steps

^{Still working on reproduction steps. We have about 10 users and this happens about once per week. I will update this ticket as soon as I can}
This is a video from the pre-launch report:
https://drive.google.com/file/d/1rPwRBqij7BKr6JPspsy7XLcjQNBWQC-M/view?usp=sharing
As you can see the crash happens immediately upon clicking the download button (so when adding a new download). And it also appears to me like the click on download happens almost exactly when another download is finished (which could explain the empty download and activeTasks lists that I saw above)

Link to test content

^{Still working on test content. At the moment it seems this can happen with any URL that is downloaded}

A full bug report captured from the device

I have not been able to get my hand on a device right after it happened. In the beginning we saw it once or twice on a developer phone but did not consider it important and failed to give it any attention. But this ticket is now my main focus and as I said above I will update this page with any details I'll find, hopefully a bug report soon. For now I can only attach the full logcat of the Pre-Launch Report. The crash happens at 10-04 07:31:49.632, the UnsupportedOperationException is the one I throw to hint that the UncaughtExceptionHandler from the snippet linked above has caught the error
logcat.txt

Version of ExoPlayer being used

Seen in: 2.10.4, 2.10.7, 2.11.1

Device(s) and version(s) of Android being used

Huawei Mate 10 Lite, Android 8.0
Google Pixel 3, Android 10
Google Pixel 2, Android 9
Google Pixel, Android 7.1 in Pre-Launch Report Emulator

More Code

This is how I start the download

DownloadRequest request = new DownloadRequest(downloadData.getId(), DownloadRequest.TYPE_PROGRESSIVE, playlistData.getUri(), Collections.emptyList(), null, ByteArrayUtil.toCustomDownloadArray(downloadData));
DownloadService.sendAddDownload(mContext, EpisodeDownloadService.class, request, true);

This is my DownloadManager Implementation

@Provides
@FeatureScope
DownloadManager provideDownloadManager(DownloadTracker tracker, Cache cache, DataSource.Factory factory,
        DatabaseProvider databaseProvider, PreferenceDomain preferences) {
    DownloadManager downloadManager = new DownloadManager(mAppContext, databaseProvider, cache, factory);
    downloadManager.addListener(tracker);
    downloadManager.setRequirements(preferences.isMeteredDownloadAllowed() ? new Requirements(Requirements.NETWORK) : new Requirements(Requirements.NETWORK_UNMETERED));
    return downloadManager;
}

As I said I cannot reproduce it, or prove it in the demo app. Sorry for that. But I would be deeply grateful for any input and promise to update with more info as best I can, I hope you can see from my efforts above that I wish I could do more than just dump a stacktrace here and ask for your help

[christosts]

Hi @avalanchas,

thank you for submitting details of the bug. I'd appreciate if you can provide more details on what your app does, and a bug report or logcat when the error happens (here or by mail at [email protected] with this issue's number on the subject). Please see analysis and questions below.

Looking the code, the fields

private final ArrayList<Download> downloads;
private final HashMap<String, Task> activeTasks;

in InternalHandler seem to be accessed only by the class itself and only by internal handler thread: the two fields are referenced only from InternalHandler's private methods and these methods are only invoked by InternalHandler.handleMessage(). Therefore I am not sure it is a race condition issue. (Note: even if it turns out to be a synchronization issue, volatile will not work in this case, the fields are final, we would need to synchronize reading and writing from/to those containers).

According to the stack trace you provided, the crash occurs during InternalHandler.initialize() (code), which in turn is enqueued by the DownloadManager constructor here. It looks like the downloads ArrayList contains entries in STATE_DOWNLOADING but a corresponding task is not inside the activeTasks map. Since this is happening within InternalHandler.initialize(), I wonder if there is an issue here where InternalHandler.initialize() might add entries inside downloads but not in activeTasks. Therefore, my investigation would lean towards what the WritableDownloadIndex downloadIndex actually returns when downloadIndex.getDownloads() is called here.

Are you using the DefaultDownloadIndex? Can you please inspect if there are downloads in STATE_DOWNLOADING persisted in the DefaultDownloadIndex that are returned when downloadIndex.getDownloads() is called from InternalHandler.initialize()? Can you observe if there is a usage pattern, e.g. close the app while downloading and then restart the app, which might cause the downloadIndex to contain incomplete downloads?

I understand that this does not align with your findings with the reflective code, where both downloads and activeTasks are empty. But because, as you said "the crash occurs while iterating over downloads, so how can downloads be empty?", I'm inclined to leave this finding aside for a while until we verify what's happening with the question above.

[christosts]

Hi @avalanchas,

I investigated this further to see if it is possible to add downloads with state STATE_DOWNLOADING from InternalHandler.initialize(). The code does make sure to change the state from STATE_DOWNLOADING to state STATE_QUEUED before it loads the database here and I have been able to reproduce the issue.

Can you please provide further details on your app usage, and specifically if

• you see the error happening after an app shutdown and restart
• are you using multiple instances of DownloadManager or ExoPlayer?

[avalanchas]

Just letting you know that I read your answers with gratitude and am thoroughly investigating in the meantime, please don't take my silence as ignoring this, I'm just not the fastest coder :D

[avalanchas]

Hi Christos, thank you so much for your input. Your comment about where the call originates, the InternalHandler.initialize() hints and the volatile are absolutely correct. And yes, the latter I should've figured out myself, and hell yeah I do hope it's not a race condition, it just looked like one to me at first glance.

No, I'm not using the DefaultDownloadIndex. Going by this I was implementing with a DatabaseProvider (new ExoDatabaseProvider(mContext)). Is that risky, should I change that and code closer along the demo app?

As to your questions:

• no the crash happens during app usage and does not require closing and reopening the app, it can happen from the beginning as far as I can tell (again, this would all be easier if I could already reproduce it. If you have further ideas for reproduction steps I could try I would appreciate that a lot)
• We dagger inject singleton instances of both these dependencies. The @FeatureScope you saw above depends on a Component that is Singleton, same goes for the Exoplayer. But that's a good idea, it would lead to trouble if that were the case, so to make sure I took this advice and added a print of the DownloadManager to the crash

So I looked at the lists closer again, and did some breakpoint debugging on the syncTasks method, but as before, I can never get it to enter the loop when the list is empty, and I can never see the activeTasks as empty when the loop is entered. I added some details (video from Play Console) to the OP above, and I'll keep investigating

[christosts]

Hi Patrick,

when you say

No, I'm not using the DefaultDownloadIndex.

I understand that you are passing your own implementation of a WritableDownloadIndex in the DownloadManager constructor, is that right?

In that case, I would check your implementation of the WritableDownloadIndex and specifically if the method setDownloadingStatesToQueued() works correctly. This method is called inside InternalHandler.initialize() just before loading the database. After calling this method, you should have no downloads in STATE_DOWNLOADING.

Can you please verify that?

[avalanchas]

Hi Christos, no, I don't have my own implementation, I use the other constructor for the DownloadManager at the moment, as you can see in the code above, not using a WritableDownloadIndex but instead a DatabaseProvider:

@Provides
@Singleton
DatabaseProvider provideDatabaseProvider() {
  return new ExoDatabaseProvider(mContext);
}
...
@Provides
@FeatureScope
DownloadManager provideDownloadManager(DownloadTracker tracker, Cache cache, DataSource.Factory factory,
        DatabaseProvider databaseProvider, PreferenceDomain preferences) {
DownloadManager downloadManager = new DownloadManager(mAppContext, databaseProvider, cache, factory);
...
}

I'll check today if I can find some more documentation on the difference between these two approaches, because I'm definitely not above changing that if you say using an index is better/safer?

[christosts]

Alright, thanks for clarifying that.

In order to verify one possible cause of your bug, can you please do the following: debug (just add a print/log) what the downloads list contains after these lines inside InternalHandler.initialize() are executed. At this point, the downloads list should NOT contain any entry with state STATE_DOWNLOADING, so make sure you check each download's state. If the crash occurs (with the same stack trace), please report to this ticket the state of each download inside the downloads list.

The stack trace you submitted in the ticket description suggests that InternalHandler.initialize() loads the database and there are downloads in STATE_DOWNLOADING. However, the code takes care of that, and before loading the database makes sure that any download in STATE_DOWNLOADING is first converted to STATE_QUEUED. Your submitted stack trace suggests that the code failed to do the conversion, and I would like to verify that first.

[ojw28]

@avalanchas - Please could you take a look at the request above? Thanks!

[avalanchas]

Yes sorry I absolutely did that, there was just nothing of substance to add here, sorry I didn't answer! When I debug the code with these lines in mind then yeah, the downloads and the states are set as expected. I mean... if that wasn't the case then I would have a nice, reproducible crash, that I could pinpoint much more precisely :(
All I can say at the moment is that it happened again recently, and here's the stacktrace:

 FATAL EXCEPTION: DownloadManager file i/o
Process: de.radio.android, PID: 29005
java.lang.NullPointerException
    at com.google.android.exoplayer2.util.Assertions.checkNotNull(Assertions.java:111)
    at com.google.android.exoplayer2.offline.DownloadManager$InternalHandler.syncTasks(DownloadManager.java:872)
    at com.google.android.exoplayer2.offline.DownloadManager$InternalHandler.initialize(DownloadManager.java:709)
    at com.google.android.exoplayer2.offline.DownloadManager$InternalHandler.handleMessage(DownloadManager.java:630)
    at android.os.Handler.dispatchMessage(Handler.java:105)
    at android.os.Looper.loop(Looper.java:164)
    at android.os.HandlerThread.run(HandlerThread.java:65)

But that's about it. I think we'll just have to wait until we're in production in about 1-2 weeks until we see the real impact and can gather some more logs (I had the idea to put some Crashlytics logs in only today unfortunately... -.- So next time I'll maybe have more info)

[Kamil-H]

I would like to just inform that I'm also facing this problem. Occasionally I'm getting exactly the same crash.

[avalanchas]

Ok so let me give a small status update: Our app is now live and we see this problem in about 0.5% of our users sessions - around 20 times in the last 3 days. I can now also prove that there are indeed situations, where the downloads list has an object in it (which is why the for-loop starts rolling) but the activeTasks array has none (which then causes the non-null assertion crash)

D/CrashlyticsCore Caught Crash -> downloadManager=[com.google.android.exoplayer2.offline.DownloadManager@f7ea035], downloads=[[com.google.android.exoplayer2.offline.Download@bb88cca]], activeTasks=[{}]

^{For Info where this log comes from check my OP, the "bit of reflection code" that I linked to}
So in the near-term future I will be focussing on the concurrent execution idea again, and I'll really have to make 100% sure that I only have one instance of the DownloadManager, maybe my Dagger config is really bad or something...

[ojw28]

As a status update from our side: We did find an app internally that was seeing a similar issue, but we're fairly confident they were violating the one-instance-of-DownloadManager rule to be causing this.

Did you manage to validate that you really do only have one instance? I'm not sure there's anything actionable for us to do here, seeing as no-one else has reported the same problem and we don't have reproduction steps.

[avalanchas]

That's a good reminder and thank you very very much for keeping up with this. I have actually found such a problem quite recently (my Dagger setup was severely lacking), but it's not rolled out to the users yet. I will report back on this in about 2 weeks!

[google-oss-bot]

Hey @avalanchas. We need more information to resolve this issue but there hasn't been an update in 14 weekdays. I'm marking the issue as stale and if there are no new updates in the next 7 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[google-oss-bot]

Since there haven't been any recent updates here, I am going to close this issue.

@avalanchas if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.

[avalanchas]

Hi Team, hi @google-oss-bot ;) Here's my long-overdue update on this. The fix has been released for about a month now, and I have not seen the crash even once since then. I will therefore conclude that this bug is indeed caused by multiple DownloadManagers existing and accessing the same resources at the same time

For anybody else coming across this I can only recommend

• check instance creation for DownloadManager, DownloadService and the like
• check dependency injections setup if you have it, remember that @Singleton will do nothing for you if you have multiple modules or variable scopes, because each of which will get a "singleton" object for ITS respective needs
• Check my first post for some advice on logging, maybe extend that log by a hash of the instances you're monitoring

@christosts thank you so much