Files stay stuck in `DELETED` state

[giladgotman]

We are in a process of migration from v1 to v2. While testing v2, we encounter that after using the delete function, some files stay in DELETED state - forever. We can see those files in the internal db of the library using stetho. Once a file reaches this state we can basically do nothing. We can't delete it and we can't try to re-download it because its id already exists.

I believe the problem occurs once the operation of trying to physically delete the file fails.

1. Are you familiar with such a problem?
2. Is there a way to clear the deleted files or retry to physically delete them?

[Mecharyry]

Hi @giladgotman, let me see if I can help you.

I've not seen that particular issue before I have to say. Would you be able to provide a reproducible example?

I believe this could be an issue though, from what I remember we don't perform any checks on whether a download has actually been deleted. Yes, here it is https://github.com/novoda/download-manager/blob/release/library/src/main/java/com/novoda/downloadmanager/PathBasedFilePersistence.java#L83-L99

@giladgotman would you be able to attach the logger to your application using:

DownloadManagerBuilder
                .withLogHandle(new DemoLogHandle())

If you could try and look for a debug log matching String.format("File or Directory: %s deleted: %s", absoluteFilePath.path(), deleted); we can confirm this is the location and patch it for you.

[giladgotman]

Thanks for the prompt response @Mecharyry.

I have found a scenario to reproduce it. I discovered that we were doing downloadManager.submitAllStoredDownloads after calling downloadManager.download and after downloadManager.delete by mistake.

I added this calls to the sample app and was able to reproduce it. If you use the sample app, and pressStart downloading and then repeatedly press the Delete all button, eventually you should be able to reproduce it. I also changed the number of batch downloads to 18 instead of 2. Of course this is not a proper way of using the library but its a good way to reproduce the problem and find the root cause. Even after I stopped calling the submitAllStoredDownloads I've noticed the same problem one time. (not sure about the scenario though).

I have attached my modified SampleApp code. I have only modified the MainActivity class. demo.zip

Here is the log:

2018-10-23 11:42:21.906 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:21.994 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file batch_id_1http://ipv4.download.thinkbroadband.com/10MB.zip with status QUEUED 
2018-10-23 11:42:22.001 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for batch_id_1 
2018-10-23 11:42:22.066 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.068 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 4 
2018-10-23 11:42:22.145 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.153 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 5 
2018-10-23 11:42:22.237 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.240 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 6 
2018-10-23 11:42:22.468 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.470 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 9 
2018-10-23 11:42:22.545 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.548 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 10 
2018-10-23 11:42:22.630 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.633 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 11 
2018-10-23 11:42:22.713 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.716 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 12 
2018-10-23 11:42:22.809 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.816 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 13 
2018-10-23 11:42:22.886 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.891 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 14 
2018-10-23 11:42:22.958 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:22.961 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 15 
2018-10-23 11:42:23.054 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:23.057 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 16 
2018-10-23 11:42:23.128 2716-2785/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-1-thread-1][(DownloadsFilePersistence.java:41).persistSync]  failure to persist sync file file_id_1 with status QUEUED 
2018-10-23 11:42:23.130 2716-2757/com.novoda.downloadmanager.demo.simple E/DownloadManagerDemo: [pool-2-thread-1][(DownloadsBatchPersistence.java:189).lambda$updateStatusAsync$3$DownloadsBatchPersistence]  could not update batch status QUEUED failed for BATCH 17 
2018-10-23 11:42:33.503 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 4/foo/bar/5mb.zip4 deleted: true 
2018-10-23 11:42:33.506 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 5/foo/bar/5mb.zip5 deleted: true 
2018-10-23 11:42:33.508 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 6/foo/bar/5mb.zip6 deleted: true 
2018-10-23 11:42:33.513 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 10/foo/bar/5mb.zip10 deleted: true 
2018-10-23 11:42:33.516 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 11/foo/bar/5mb.zip11 deleted: true 
2018-10-23 11:42:33.518 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 12/foo/bar/5mb.zip12 deleted: true 
2018-10-23 11:42:33.521 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 13/foo/bar/5mb.zip13 deleted: true 
2018-10-23 11:42:33.523 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 14/foo/bar/5mb.zip14 deleted: true 
2018-10-23 11:42:33.526 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 15/foo/bar/5mb.zip15 deleted: true 
2018-10-23 11:42:33.529 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 16/foo/bar/5mb.zip16 deleted: true 
2018-10-23 11:42:33.532 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 17/foo/bar/5mb.zip17 deleted: true 
2018-10-23 11:42:37.321 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/batch_id_1/foo/bar/5mb.zip deleted: true 
2018-10-23 11:42:37.323 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/batch_id_1/10MB.zip deleted: true 
2018-10-23 11:42:37.832 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 4/foo/bar/5mb.zip4 deleted: true 
2018-10-23 11:42:54.351 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 5/foo/bar/5mb.zip5 deleted: true 
2018-10-23 11:42:55.465 2716-2716/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 6/foo/bar/5mb.zip6 deleted: true 

And here is screen shot of stetho:

[giladgotman]

here is another log with verbose level: (using batch 2 filter. batch 2 is the one that got stuck in DELETED)

2018-10-23 12:02:48.056 11065-11065/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [main][(LiteDownloadManager.java:83).download]  abort download batch LiteDownloadBatchId{id='BATCH 2'} will not download as exists already in the running batches map 
2018-10-23 12:02:48.440 11065-11065/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [main][(DownloadBatch.java:318).delete]  delete request for batch BATCH 2, status DELETING, should be deleting 
2018-10-23 12:02:48.441 11065-11065/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [main][(DownloadFile.java:173).delete]  mark file as deleted for batchId: BATCH 2 
2018-10-23 12:02:48.451 11065-11065/com.novoda.downloadmanager.demo.simple D/DownloadManagerDemo: [main][(PathBasedFilePersistence.java:98).delete]  PathBasedFilePersistence File or Directory: /data/user/0/com.novoda.downloadmanager.demo.simple/files/downloads/BATCH 2/foo/bar/5mb.zip2 deleted: true 
2018-10-23 12:02:48.452 11065-11065/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [main][(DownloadBatch.java:328).delete]  delete async paused or downloaded batch BATCH 2 
2018-10-23 12:02:48.453 11065-11065/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [main][(DownloadBatch.java:336).delete]  delete request for batch end BATCH 2, status: DELETING, should be deleting 
2018-10-23 12:02:48.473 11065-11137/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [pool-2-thread-1][(DownloadBatch.java:330).lambda$delete$0$DownloadBatch]  delete paused or downloaded mark as deleted: BATCH 2 
2018-10-23 12:02:48.571 11065-11395/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [pool-1-thread-1][(DownloadBatchStatusFilter.java:22).shouldFilterOut]  Passes filter. ID: BATCH 2 Status: DELETED 
2018-10-23 12:02:48.574 11065-11395/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [pool-1-thread-1][(LiteDownloadManagerDownloader.java:114).lambda$downloadBatchCallback$2$LiteDownloadManagerDownloader]  batch BATCH 2 is finally deleted, removing it from the map 
2018-10-23 12:02:48.766 11065-11065/com.novoda.downloadmanager.demo.simple I/ggg: notificationDisplayState batch idLiteDownloadBatchId{id='BATCH 2'}
2018-10-23 12:02:48.766 11065-11065/com.novoda.downloadmanager.demo.simple I/ggg: customNotificationFrom batch idLiteDownloadBatchId{id='BATCH 2'}
2018-10-23 12:02:50.461 11065-11409/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [pool-3-thread-1][(DownloadBatch.java:56).download]  start sync download BATCH 2, status DELETED 
2018-10-23 12:02:50.462 11065-11409/com.novoda.downloadmanager.demo.simple V/DownloadManagerDemo: [pool-3-thread-1][(DownloadBatch.java:59).download]  abort starting download BATCH 2, status DELETED 

[Mecharyry]

Thanks @giladgotman for all of the information! I'll try and take a look at this as soon as I am able and provide a fix. I'll try and keep you updated as I work on it.