Backup Failed #12404

zjabri · 2022-08-19T14:20:06Z

Let's begin with a checklist: Replace the empty checkboxes [ ] below with checked ones [x] accordingly. -->

[x ] I have searched open and closed issues for duplicates
[ x] I am submitting a bug report for existing functionality that does not work as intended
[ x] I have read https://github.com/signalapp/Signal-Android/wiki/Submitting-useful-bug-reports
[x ] This isn't a feature request or a discussion topic

Bug description

Since yesterday I am unable to make chat backups anymore, every time I try it stops on 20.3% with a notification (backup failed tap to manage backups).

Steps to reproduce

settings-chats-chats backup-create backup+failed on 20.3%.

Device info

Oneplus 7 pro

Android 12 (Crdroid 8.8)
Signal version: 5.46.6

Link to debug log

08-19 09:45:43.762 17173 17173 W DocumentFile: Failed query: java.lang.IllegalArgumentException: Failed to determine if primary:Signal Backups/.backup********----37.tmp is child of primary:Signal Backups: java.io.FileNotFoundException: Missing file for primary:Signal Backups/.backup----37.tmp at /storage/emulated/0/Signal Backups/.backup----**********37.tmp
08-19 09:45:43.770 17173 17173 E EventBus: Could not dispatch event: class org.thoughtcrime.securesms.backup.BackupEvent to subscribing class class org.thoughtcrime.securesms.preferences.BackupsPreferenceFragment
08-19 09:45:43.770 17173 17173 E EventBus: java.lang.NullPointerException: Attempt to invoke virtual method 'boolean java.lang.String.endsWith(java.lang.String)' on a null object reference
08-19 09:45:43.770 17173 17173 E EventBus: at org.thoughtcrime.securesms.util.BackupUtil.getAllBackupsNewestFirstApi29(BackupUtil.java:155)
08-19 09:45:43.770 17173 17173 E EventBus: at org.thoughtcrime.securesms.util.BackupUtil.getAllBackupsNewestFirst(BackupUtil.java:131)
08-19 09:45:43.770 17173 17173 E EventBus: at org.thoughtcrime.securesms.util.BackupUtil.getLatestBackup(BackupUtil.java:71)
08-19 09:45:43.770 17173 17173 E EventBus: at org.thoughtcrime.securesms.util.BackupUtil.getLastBackupTime(BackupUtil.java:42)
08-19 09:45:43.770 17173 17173 E EventBus: at org.thoughtcrime.securesms.preferences.BackupsPreferenceFragment.setBackupSummary(BackupsPreferenceFragment.java:169)
08-19 09:45:43.770 17173 17173 E EventBus: at org.thoughtcrime.securesms.preferences.BackupsPreferenceFragment.onEvent(BackupsPreferenceFragment.java:148)
08-19 09:45:43.770 17173 17173 E EventBus: at java.lang.reflect.Method.invoke(Native Method)
08-19 09:45:43.770 17173 17173 E EventBus: at org.greenrobot.eventbus.EventBus.invokeSubscriber(EventBus.java:485)
08-19 09:45:43.770 17173 17173 E EventBus: at org.greenrobot.eventbus.EventBus.invokeSubscriber(EventBus.java:479)
08-19 09:45:43.770 17173 17173 E EventBus: at org.greenrobot.eventbus.HandlerPoster.handleMessage(HandlerPoster.java:67)
08-19 09:45:43.770 17173 17173 E EventBus: at android.os.Handler.dispatchMessage(Handler.java:106)
08-19 09:45:43.770 17173 17173 E EventBus: at android.os.Looper.loopOnce(Looper.java:201)
08-19 09:45:43.770 17173 17173 E EventBus: at android.os.Looper.loop(Looper.java:288)
08-19 09:45:43.770 17173 17173 E EventBus: at android.app.ActivityThread.main(ActivityThread.java:7833)
08-19 09:45:43.770 17173 17173 E EventBus: at java.lang.reflect.Method.invoke(Native Method)
08-19 09:45:43.770 17173 17173 E EventBus: at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
08-19 09:45:43.770 17173 17173 E EventBus: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1003)
08-19 09:45:43.876 17173 17300 W LocalBackupJobApi29: Backup failed. Deleted temp file
08-19 09:45:43.879 17173 17300 I GenericForegroundServic: Stopping foreground service id=0
08-19 09:45:43.881 17173 17173 I GenericForegroundServic: handleStop()
08-19 09:45:43.881 17173 17173 I GenericForegroundServic: Last request. Ending foreground service.
08-19 09:45:43.881 17173 17300 W BaseJob : [JOB::a6b00639-bf3b-466c-8a53-57afe1807b82][LocalBackupJobApi29] Encountered a failing exception. (Time Since Submission: 112302 ms, Lifespan: Immortal, Run Attempt: 1/3, Queue: LOCAL_BACKUP)
08-19 09:45:43.881 17173 17300 W BaseJob : java.io.IOException: Prematurely reached end of stream!
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.crypto.ModernDecryptingPartInputStream.readFully(ModernDecryptingPartInputStream.java:78)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.crypto.ModernDecryptingPartInputStream.createFor(ModernDecryptingPartInputStream.java:64)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.crypto.ModernDecryptingPartInputStream.createFor(ModernDecryptingPartInputStream.java:28)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.openAttachmentStream(FullBackupExporter.java:435)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.calculateVeryOldStreamLength(FullBackupExporter.java:419)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.exportAttachment(FullBackupExporter.java:374)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.lambda$internalExport$5(FullBackupExporter.java:175)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.$r8$lambda$AM__6NnZmduQ5oDS8tZY51D7UmE(Unknown Source:0)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter$$ExternalSyntheticLambda6.postProcess(Unknown Source:8)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.exportTable(FullBackupExporter.java:346)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.internalExport(FullBackupExporter.java:175)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.backup.FullBackupExporter.export(FullBackupExporter.java:123)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.jobs.LocalBackupJobApi29.onRun(LocalBackupJobApi29.java:118)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:32)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
08-19 09:45:43.881 17173 17300 W BaseJob : at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)
08-19 09:45:43.882 17173 17300 W JobRunner: [JOB::a6b00639-bf3b-466c-8a53-57afe1807b82][LocalBackupJobApi29][2] Job failed. (Time Since Submission: 112303 ms, Lifespan: Immortal, Run Attempt: 1/3, Queue: LOCAL_BACKUP)
08-19 09:47:23.205 17173 17173 D BaseActivity: [AppSettingsActivity] onStart()
08-19 09:47:23.208 17173 17173 I ApplicationContext: App is now visible.
08-19 09:47:23.208 17173 17173 D FrameRateTracker: Beginning frame rate tracking. Screen refresh rate: 90.00 hz, or 11.11 ms per frame.
08-19 09:47:23.208 17173 17173 D DeadlockDetector: Beginning deadlock monitoring.
08-19 09:47:23.209 17173 17173 D ApplicationContext: onStart() took 1 ms
08-19 09:47:23.209 17173 17257 I FeatureFlags: Skipping remote config refresh. Refreshed 3729019 ms ago.
08-19 09:47:23.209 17173 17257 I RetrieveProfileJob: Too soon to refresh. Did the last refresh 42792384 ms ago.
08-19 09:47:23.211 17173 17260 D IncomingMessageObserver: Network: true, Foreground: true, FCM: true, Stay open requests: [], Censored: false, Registered: true, Proxy: false
08-19 09:47:23.211 17173 17260 I IncomingMessageObserver: Making websocket connection....
08-19 09:47:23.211 17173 17260 I WebSocketConnection: [normal:42632444] connect()

Thank you for help

cody-signal · 2022-08-19T14:36:46Z

Looks like it's struggling on an attachment. Any wonky recent attachments?

zjabri · 2022-08-19T14:39:57Z

Thank you Cody, I did delete all big ones...

cody-signal · 2022-08-19T14:43:35Z

How long ago was that? Curious if some are still being cleaned up/deleted and that's causing the backup job to choke.

zjabri · 2022-08-19T14:47:17Z

It started yesterday, all was good til yesterday, I wonder if the latest version is causing that, I tried everything, deleted old backups, disabled backups, enabled again and again, disabled permissions and enabled again with no success, but I wonder why exactly the same % every time 20.3 % it fails. It started happening before deleting attachments.

gkft · 2022-08-19T20:30:43Z

I can confirm since the update from version 5.45.6 to version 5.46.6 my backup fails as well (I did not receive any multimedia messages since the last successful backup with the previous version three days ago). debuglog

[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: Error during backup!
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: java.io.IOException: File too short
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.crypto.ClassicDecryptingPartInputStream.createFor(ClassicDecryptingPartInputStream.java:53)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.openAttachmentStream(FullBackupExporter.java:437)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.calculateVeryOldStreamLength(FullBackupExporter.java:419)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.exportAttachment(FullBackupExporter.java:374)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.lambda$internalExport$5(FullBackupExporter.java:175)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.$r8$lambda$AM__6NnZmduQ5oDS8tZY51D7UmE(Unknown Source:0)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter$$ExternalSyntheticLambda6.postProcess(Unknown Source:8)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.exportTable(FullBackupExporter.java:346)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.internalExport(FullBackupExporter.java:175)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.export(FullBackupExporter.java:123)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.jobs.LocalBackupJobApi29.onRun(LocalBackupJobApi29.java:118)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:32)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 	at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)
[5.46.6] [1064 ] 2022-08-19 22:23:40.092 GMT+02:00 W LocalBackupJobApi29: 
[5.46.6] [1064 ] 2022-08-19 22:23:47.669 GMT+02:00 W LocalBackupJobApi29: Backup failed. Deleted temp file
[5.46.6] [1064 ] 2022-08-19 22:23:47.670 GMT+02:00 I GenericForegroundServic: Stopping foreground service id=1
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: [JOB::54d186e3-16e6-40de-82fc-be6bcdc431d2][LocalBackupJobApi29] Encountered a failing exception. (Time Since Submission: 76686857 ms, Lifespan: Immortal, Run Attempt: 1/3, Queue: __LOCAL_BACKUP__)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: java.io.IOException: File too short
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.crypto.ClassicDecryptingPartInputStream.createFor(ClassicDecryptingPartInputStream.java:53)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.openAttachmentStream(FullBackupExporter.java:437)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.calculateVeryOldStreamLength(FullBackupExporter.java:419)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.exportAttachment(FullBackupExporter.java:374)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.lambda$internalExport$5(FullBackupExporter.java:175)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.$r8$lambda$AM__6NnZmduQ5oDS8tZY51D7UmE(Unknown Source:0)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter$$ExternalSyntheticLambda6.postProcess(Unknown Source:8)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.exportTable(FullBackupExporter.java:346)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.internalExport(FullBackupExporter.java:175)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.export(FullBackupExporter.java:123)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.jobs.LocalBackupJobApi29.onRun(LocalBackupJobApi29.java:118)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:32)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
[5.46.6] [1064 ] 2022-08-19 22:23:47.671 GMT+02:00 W BaseJob: 	at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)

Maybe one of those:

git log --pretty=oneline --abbrev-commit v5.45.6..v5.46.6 | grep -i backup
41a7560e7 Do not fail backup when missing attachments.
ac8a972c6 Do not fail backup creation when sticker files are missing.
019025ab8 Improve backup creation exception messaging to user.
cfebd0eeb Verify backup can be decrypted as part of creation flow.

zjabri · 2022-08-19T20:50:27Z

Yes, since the last update. I tried everything ...
The fix for me was the following:
I had a backup before the issue started on the cloud.
Stop signal app, clear cache and data, open signal and restore from that backup.

Now I can do backups as usual.
I could wait for a fix in the next signal version, but I wanted to try the restore and it did work.

gkft · 2022-08-19T21:02:14Z

I just compared our logs mine is lacking the Missing file for primary: part the rest is looking similar. Unfortunately, restoring a backup may not be the way to go for some users, as they probably don't even have one.

theraser · 2022-08-20T06:56:00Z

I can confirm the issue and got the same error as gkft. It worked fine until 2-3 days, got Signal 5.46.5

mdecker · 2022-08-20T15:28:58Z

I can confirm as well. Same error message in debug log, happening since update to 5.46.6 two days ago. Using Android 11.

cody-signal · 2022-08-22T14:03:29Z

Thanks, looking into it.

cody-signal · 2022-08-22T14:04:26Z

For those that are encountering the issue, please include a debuglog.

mauriceKA · 2022-08-22T14:50:57Z

I have the same problem since a few days. Here is my debug log
https://debuglogs.org/android/5.46.6/a0bca472ab4ad8210918f940f01446dc2715714748c245827629cadc130ed4d5

mdontu · 2022-08-22T19:36:10Z

I believe I have the same issue. Debug log.

I don't know if exceptions like the following play a role:

08-22 21:50:44.629 15681 15767 W DocumentsContract: Failed to rename document
08-22 21:50:44.629 15681 15767 W DocumentsContract: java.lang.IllegalStateException: Downloaded file doesn't exist anymore: 0 {
08-22 21:50:44.629 15681 15767 W DocumentsContract:    _id=40902
08-22 21:50:44.629 15681 15767 W DocumentsContract:    local_filename=/storage/emulated/0/Download/.backup907f6f5c-eac0-4f6c-8ab2-a17c54e98456.tmp
08-22 21:50:44.629 15681 15767 W DocumentsContract:    mediaprovider_uri=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    destination=6
08-22 21:50:44.629 15681 15767 W DocumentsContract:    title=.backup907f6f5c-eac0-4f6c-8ab2-a17c54e98456.tmp
08-22 21:50:44.629 15681 15767 W DocumentsContract:    description=.backup907f6f5c-eac0-4f6c-8ab2-a17c54e98456.tmp
08-22 21:50:44.629 15681 15767 W DocumentsContract:    uri=non-dwnldmngr-download-dont-retry2download
08-22 21:50:44.629 15681 15767 W DocumentsContract:    status=200
08-22 21:50:44.629 15681 15767 W DocumentsContract:    hint=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    media_type=application/octet-stream
08-22 21:50:44.629 15681 15767 W DocumentsContract:    total_size=2790477975
08-22 21:50:44.629 15681 15767 W DocumentsContract:    last_modified_timestamp=1661194232909
08-22 21:50:44.629 15681 15767 W DocumentsContract:    bytes_so_far=0
08-22 21:50:44.629 15681 15767 W DocumentsContract:    allow_write=1
08-22 21:50:44.629 15681 15767 W DocumentsContract:    notificationpackage=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    dd_primaryMimeType=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    dd_fileName=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    dd_vendor=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    dd_description=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    dd_contentSize=0
08-22 21:50:44.629 15681 15767 W DocumentsContract:    dd_objUrl=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    dd_majorVersion=null
08-22 21:50:44.629 15681 15767 W DocumentsContract:    range_start=0
08-22 21:50:44.629 15681 15767 W DocumentsContract:    range_end=0
08-22 21:50:44.629 15681 15767 W DocumentsContract:    range_first_end=0
08-22 21:50:44.629 15681 15767 W DocumentsContract:    local_uri=file:///storage/emulated/0/Download/.backup907f6f5c-eac0-4f6c-8ab2-a17c54e98456.tmp
08-22 21:50:44.629 15681 15767 W DocumentsContract:    reason=placeholder
08-22 21:50:44.629 15681 15767 W DocumentsContract: }
08-22 21:50:44.629 15681 15767 W DocumentsContract: 
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.os.Parcel.createExceptionOrNull(Parcel.java:2445)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.os.Parcel.createException(Parcel.java:2421)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.os.Parcel.readException(Parcel.java:2404)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.database.DatabaseUtils.readExceptionFromParcel(DatabaseUtils.java:190)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.database.DatabaseUtils.readExceptionFromParcel(DatabaseUtils.java:142)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.content.ContentProviderProxy.call(ContentProviderNative.java:732)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.content.ContentResolver.call(ContentResolver.java:2457)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at android.provider.DocumentsContract.renameDocument(DocumentsContract.java:1451)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at androidx.documentfile.provider.TreeDocumentFile.renameTo(TreeDocumentFile.java:179)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at org.thoughtcrime.securesms.jobs.LocalBackupJobApi29.onRun(LocalBackupJobApi29.java:133)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:32)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
08-22 21:50:44.629 15681 15767 W DocumentsContract:     at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)
08-22 21:50:44.629 15681 15767 W LocalBackupJobApi29: Failed to rename temp file
08-22 21:50:44.629 15681 15767 W LocalBackupJobApi29: Error during backup!
08-22 21:50:44.629 15681 15767 W LocalBackupJobApi29: java.io.IOException: Renaming temporary backup file failed!
08-22 21:50:44.629 15681 15767 W LocalBackupJobApi29:   at org.thoughtcrime.securesms.jobs.LocalBackupJobApi29.onRun(LocalBackupJobApi29.java:135)
08-22 21:50:44.629 15681 15767 W LocalBackupJobApi29:   at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:32)
08-22 21:50:44.629 15681 15767 W LocalBackupJobApi29:   at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
08-22 21:50:44.629 15681 15767 W LocalBackupJobApi29:   at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)

waaamb · 2022-08-23T04:31:32Z

I'm having a similar issue that started after I updated to 5.46.6. I just updated to 5.47.0 and still the same.

Android 12 on Pixel 6 Pro.

https://debuglogs.org/android/5.47.0/39f510fc9cdfc4731ad88d752abef06abe02849a4add09c1037697ca4427a516

Skyr · 2022-08-23T11:05:21Z

Same issue since probably 10 days or so. Currently on 5.46.6. Lots of "Needed size calculation" messages before the stack trace, if this is relevant...

[5.46.6] [1528 ] 2022-08-23 11:56:04.394 GMT+02:00 W FullBackupExporter: Needed size calculation! Manual: 181487 File: 181524  DB: 181487 ID: AttachmentId::(289, 1487408815117)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: Error during backup!
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: java.io.IOException: File too short
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.crypto.ClassicDecryptingPartInputStream.createFor(ClassicDecryptingPartInputStream.java:53)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.openAttachmentStream(FullBackupExporter.java:437)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.calculateVeryOldStreamLength(FullBackupExporter.java:419)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.exportAttachment(FullBackupExporter.java:374)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.lambda$internalExport$5(FullBackupExporter.java:175)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.$r8$lambda$AM__6NnZmduQ5oDS8tZY51D7UmE(Unknown Source:0)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter$$ExternalSyntheticLambda6.postProcess(Unknown Source:8)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.exportTable(FullBackupExporter.java:346)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.internalExport(FullBackupExporter.java:175)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.backup.FullBackupExporter.export(FullBackupExporter.java:109)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.jobs.LocalBackupJob.onRun(LocalBackupJob.java:125)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:32)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 	at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)
[5.46.6] [1528 ] 2022-08-23 11:56:04.421 GMT+02:00 W LocalBackupJob: 
[5.46.6] [1528 ] 2022-08-23 11:56:05.010 GMT+02:00 W LocalBackupJob: Backup failed. Deleted temp file

cody-signal · 2022-08-23T15:11:45Z

Thanks for the additional reports. Looks like there's two issues being reported. One (needed size calculation) has a clear fix and will be addressed in an upcoming release. The other is less clear. Can folks respond with where they are storing their backups? As in, are they being stored in internal storage, external, on device, etc.?

mdontu-bd · 2022-08-23T15:29:55Z

I store mine on internal storage (Downloads, ~150GiB available).

waaamb · 2022-08-23T17:28:52Z

Can folks respond with where they are storing their backups? As in, are they being stored in internal storage, external, on device, etc.?

Mine are in /storage/emulated/0/Signal

mauriceKA · 2022-08-24T05:48:54Z

Mine is on /storage/emulated/0/Signal/Backups - and there is no way to change it. Tapping on the folder display does not bring up any dialog. This is internal storage.
If I could, I would put my backups on my SD card, which is /storage/0000-0000
That would be more practical as it would migrating to a new device more easy.

mdecker · 2022-08-24T13:35:30Z

Mine are on internal storage, but in a custom non-default location, namely /storage/emulated/0/Backup/Signal (~200GB free space)

fresh debug log here: https://debuglogs.org/android/5.46.7/38f382a773aeca0badca4d521ef008d20b1319f9dbbe689b55e3b51bc216d1a7

nickersonm · 2022-08-24T14:02:12Z

I have also been encountering this for the last week or so: as soon as I place my phone on the charger, Signal tries and immediately fails to create a backup. Attempted manual backups also fail immediately.

Debug log after manually triggering a backup: https://debuglogs.org/android/5.46.6/663dd6e83eb1aaeddb531b7a7396108a7ae0ac45ae1565022ca972aa3de1fe40

As @mauriceKA mentioned, I also cannot change my backup location. It is currently /storage/emulated/0/Signal/Backups.

gkft · 2022-08-26T14:15:33Z

Hi @cody-signal so the java.io.IOException: File too short is thrown due to the flawed size calculation?

simonbru · 2022-08-28T08:40:38Z

I have had the same issue for 1-2 weeks: Failed backup with the "File too short" exception.

In the media section, I noticed that I had a lot of broken media from 2014-2015. They had no thumbnails, could not be displayed nor exported.

The backup feature started to work again right after deleting these broken media.

M0ssTee · 2022-08-28T12:53:36Z

I have a similar issue of not being able to back up. Similarly, I am unable to select the backup folder location. My last backup was Aug. 20th. I am currently on version 5.47.3. Debug logs.

nickersonm · 2022-08-28T14:07:16Z

Thanks for mentioning that, @simonbru - inspecting my media revealed several broken older media files, and removing them restored backup functionality.

mdecker · 2022-08-29T15:38:02Z

Indeed, some of the oldest stored media seems to have been broken. After removal the backup started working again.

gkft · 2022-08-29T16:59:50Z

The old media problem seems to be fixed with 05c16e4, so it should not be necessary to search all chats for wonky attachments.

KoljaFrahm · 2022-08-30T12:01:47Z

I have the same problem. I deleted some old media files, but that didn't help. Can anyone help?

waaamb · 2022-08-30T13:09:55Z

Mine are in /storage/emulated/0/Signal

My backup completed this morning on 5.48.3 👍🏻

gkft · 2022-09-01T08:42:46Z

My backup also completed successfully after upgrading to 5.48.3. 👍

mr-brunes · 2022-10-23T09:18:29Z

Another notification of "Backup failed" at 08:59.

I dutifully "tap to manage backuips" and there's nothing to indicate any issues.
I tap "Create backup"(Last backup was Sat) and it seems to create it successfuly (well I glanced away and it now says "Last backup: Now" . Head scratched.

https://debuglogs.org/android/5.53.5/e25c2ab8962f543dea61c78ebebc6967499d392d57323eace8721a8ef6ec7ee8
The only thing that jumps out to me as a layman is:
"Unable to start foreground service ...
Caused by: android.app.ForegroundServiceStartNotAllowedException: startForegroundService() not allowed due to mAllowStartForeground false: service org.thoughtcrime.securesms/.service.GenericForegroundService"

dcgomez · 2022-10-24T18:06:47Z

Worth noting the temporary backup files created during crash are not deleted during the backup failure. I've had to delete multiple 2+ GB working files as one is left each time the backup fails.

Coming back to thread to note that the referenced solution above worked for me and it seems to be resolved.

Steps taken:

Moved last good backup from Downloads folder to Documents folder
Went into Chats > Backups and disabled (I did the above step because I was worried about losing my last backup with the warning there)
Reenabled Backups in Documents folder (wrote down pass phrase)
Manually triggered backup (success! no crash! no left-over file!)
Deleted last old original backup from August

r-eule · 2022-10-24T19:13:07Z

Hi.
Finally I was able to try change the backup location as suggested.
It worked like the previous poster (dcgomez) described it.
The manually triggered backup worked without problem.

The UI is really not good at this point.

Thank you @greyson-signal and @cody-signal for looking in the debug-log and finally providing a solution.

PeterPilley · 2022-10-24T19:23:07Z

Hi just added a new debug log https://debuglogs.org/android/5.52.5/cafede2fbb53cb3908c790bcef6c0e4f45e02a5d2fc03c9a65627953de3ee929

Looking through I can see an error popping up regularly for LiveRecipient.

I have read through the other posts and tried to clear out any old backups, still have the same issue

mr-brunes · 2022-10-25T08:54:11Z

Another backup failed notification this morning, but manual backup appears to work fine.
https://debuglogs.org/android/5.53.5/a7af9dac014678384268392023e7311cfa82541d12b6ec223ca0bf0d5ea13d74

cody-signal · 2022-10-25T15:00:41Z

@PeterPilley try using a different directory for your backups. Some folks have had permissions issues with Downloads.

@mr-brunes Yeah, so the problem is we aren't getting the right conditions to run in the background like we should, and so it fails. But when you start with us already in the foreground via the UI, it'll work. We'll have a tweak out for this shortly.

PeterPilley · 2022-10-25T19:08:46Z

@PeterPilley try using a different directory for your backups. Some folks have had permissions issues with Downloads.

@mr-brunes Yeah, so the problem is we aren't getting the right conditions to run in the background like we should, and so it fails. But when you start with us already in the foreground via the UI, it'll work. We'll have a tweak out for this shortly.

@cody-signal I can't do that unfortunately. If I click chat backups under settings the app crashes. Do I need to reinstall

mr-brunes · 2022-10-25T19:14:40Z

@cody-signal that's good to know!

andrepd · 2022-10-28T16:13:07Z

Hi, I am facing the same error on Signal 5.47.3, with "Backup failed / Tap to manage backups."

The backup process hangs at ~4.0%.
This corresponds to when the backup process has created a file approx ~8GB big. My Signal data is 11.7GB and my free space is 28GB.
This happens when I turn on backups, and also when I request a backup manually by clicking Create backup
This happens when I chose Signal/Backups (existing), or a folder Sig (newly created).

Any updates? I see that some users have had success by changing the backup directory but I had no luck there.

Debug log (let me know if you need more than this)

schnappyMG · 2022-12-13T11:04:10Z

100% working (for me) also look: dcgomez

#12404 (comment)

cody-signal · 2022-12-13T14:57:40Z

@andrepd are you still experiencing this issue? Can you send me an updated debuglog link?

schnappyMG · 2022-12-13T16:54:24Z

Hi, the trick was to change the directory. In the same folder (DOWNLAD) it no longer worked. (Delete backup and create new one failed) Now I save the Backup in Dokuments and IT works. attached the log where it works again. https://debuglo.txt <https://drive.google.com/file/d/1GafQjHh6RVYfHbwZngXYz2hoiaD9UMJZ/view?usp=drivesdk> schnappy Cody Henthorne ***@***.***> schrieb am Di., 13. Dez. 2022, 15:57:

…

@andrepd <https://github.com/andrepd> are you still experiencing this issue? Can you send me an updated debuglog link? — Reply to this email directly, view it on GitHub <#12404 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/A4XB6COHJ6IWNT5J4RXVB4DWNCFHDANCNFSM57A5CHPA> . You are receiving this because you commented.Message ID: ***@***.***>

minosimo · 2022-12-23T17:21:03Z

Hello, I am having a similar issue on 6.5.6. I have tried enabling backups several times on different folders on my SD card. My phone does not have enough free internal storage to store a backup, so I have been unable to test that.

The backup gets to 100%, is checked for a little while, then the notification appears saying the backup failed. I have attached a debug log.
signal-log-1671716424073.zip

minosimo · 2023-01-30T14:49:38Z

I found a similar thread where an SD card formatted as fat32 was causing the issue.

I am fairly sure I was using exfat on my sd card before, but after formatting it again (as exfat), backups started working so who knows.

DorskFR · 2023-03-06T22:05:21Z

I have a maybe similar issue:

https://debuglogs.org/android/6.12.5/c5d5f83caf3527a4d27ae8979e728088fb0c2b70ee02768ec156cfdc14cafb2f

it's probably been one year I cannot backup.

I see a file read IO Error without further description in the logs which does not allow me to find which files might be problematic and delete them.

In total, if successful the backup would probably be 10-15Gb and internal storage free space is not an issue.

TriniKat13 · 2023-03-12T13:36:14Z

I have been having the same problem since about mid-August 2022. Backup used to be stored on my device.

https://debuglogs.org/android/6.13.6/931cca10ad974a78f46b0b1866689ab8988d538b43eadaf14eb6ce6198418840

Currently on version 6.13.6

stale · 2023-05-11T20:42:55Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

cody-signal · 2023-05-12T12:40:48Z

@TriniKat13 your backup is failing when trying to rename the file. Have you tried using a custom folder instead of a default primary? It seems using folders like Document or Download can cause problems.

TriniKat13 · 2023-05-12T14:14:42Z

Thanks, Cody. Are you able to provide some instructions on how to do that? Kathie

…

On Fri, May 12, 2023 at 8:41 AM Cody Henthorne ***@***.***> wrote: @TriniKat13 <https://github.com/TriniKat13> your backup is failing when trying to rename the file. Have you tried using a custom folder instead of a default primary? It seems using folders like Document or Download can cause problems. — Reply to this email directly, view it on GitHub <#12404 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/A6OBTLYZDORKNZ4ZULY7NB3XFYVV3ANCNFSM57A5CHPA> . You are receiving this because you were mentioned.Message ID: ***@***.***>

cody-signal · 2023-05-12T16:00:23Z

You can go into Settings->Chats->Backup and then disable and re-enable backups to pick a new folder (I know, not great). Make sure to record the new password that is generated.

TriniKat13 · 2023-05-12T16:10:42Z

Thank you - it worked!!! I really appreciate your time. Have a great day. Kathie

…

On Fri, May 12, 2023 at 12:00 PM Cody Henthorne ***@***.***> wrote: You can go into Settings->Chats->Backup and then disable and re-enable backups to pick a new folder (I know, not great). Make sure to record the new password that is generated. — Reply to this email directly, view it on GitHub <#12404 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/A6OBTL6OMP4ZPEX42UCXWEDXFZNCJANCNFSM57A5CHPA> . You are receiving this because you were mentioned.Message ID: ***@***.***>

stale · 2023-07-11T19:28:42Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

stale · 2023-07-19T20:31:10Z

This issue has been closed due to inactivity.

daanijel · 2024-01-15T07:03:31Z

I lost my chats and it costed me a week to find this page on GitHub. Could this solution, give Documents folder as backup folder, be added to the FAQ of Signal app?

stale bot added the wontfix label May 11, 2023

stale bot removed the wontfix label May 12, 2023

stale bot added the wontfix label Jul 11, 2023

stale bot closed this as completed Jul 19, 2023

moltowin mentioned this issue Feb 4, 2024

Backup failes every time at the same percentage #13402

Open

steelowheel mentioned this issue Feb 12, 2024

Chat backups doesn't produce a backup file #13418

Open

4 tasks

Backup Failed #12404

Backup Failed #12404

Comments

zjabri commented Aug 19, 2022

Bug description

Steps to reproduce

Device info

Link to debug log

cody-signal commented Aug 19, 2022

zjabri commented Aug 19, 2022

cody-signal commented Aug 19, 2022

zjabri commented Aug 19, 2022

gkft commented Aug 19, 2022 • edited Loading

zjabri commented Aug 19, 2022

gkft commented Aug 19, 2022 • edited Loading

theraser commented Aug 20, 2022

mdecker commented Aug 20, 2022 • edited Loading

cody-signal commented Aug 22, 2022

cody-signal commented Aug 22, 2022 • edited Loading

mauriceKA commented Aug 22, 2022 • edited Loading

mdontu commented Aug 22, 2022

waaamb commented Aug 23, 2022

Skyr commented Aug 23, 2022

cody-signal commented Aug 23, 2022

mdontu-bd commented Aug 23, 2022

waaamb commented Aug 23, 2022 • edited Loading

mauriceKA commented Aug 24, 2022 • edited Loading

mdecker commented Aug 24, 2022 • edited Loading

nickersonm commented Aug 24, 2022

gkft commented Aug 26, 2022

simonbru commented Aug 28, 2022

M0ssTee commented Aug 28, 2022

nickersonm commented Aug 28, 2022

mdecker commented Aug 29, 2022

gkft commented Aug 29, 2022

KoljaFrahm commented Aug 30, 2022 • edited Loading

waaamb commented Aug 30, 2022

gkft commented Sep 1, 2022

mr-brunes commented Oct 23, 2022

dcgomez commented Oct 24, 2022

r-eule commented Oct 24, 2022 • edited Loading

PeterPilley commented Oct 24, 2022

mr-brunes commented Oct 25, 2022

cody-signal commented Oct 25, 2022

PeterPilley commented Oct 25, 2022

mr-brunes commented Oct 25, 2022

andrepd commented Oct 28, 2022

schnappyMG commented Dec 13, 2022

cody-signal commented Dec 13, 2022

schnappyMG commented Dec 13, 2022 via email

minosimo commented Dec 23, 2022

minosimo commented Jan 30, 2023

DorskFR commented Mar 6, 2023

TriniKat13 commented Mar 12, 2023

stale bot commented May 11, 2023

cody-signal commented May 12, 2023

TriniKat13 commented May 12, 2023 via email

cody-signal commented May 12, 2023

TriniKat13 commented May 12, 2023 via email

stale bot commented Jul 11, 2023

stale bot commented Jul 19, 2023

daanijel commented Jan 15, 2024

gkft commented Aug 19, 2022 •

edited

Loading

gkft commented Aug 19, 2022 •

edited

Loading

mdecker commented Aug 20, 2022 •

edited

Loading

cody-signal commented Aug 22, 2022 •

edited

Loading

mauriceKA commented Aug 22, 2022 •

edited

Loading

waaamb commented Aug 23, 2022 •

edited

Loading

mauriceKA commented Aug 24, 2022 •

edited

Loading

mdecker commented Aug 24, 2022 •

edited

Loading

KoljaFrahm commented Aug 30, 2022 •

edited

Loading

r-eule commented Oct 24, 2022 •

edited

Loading