search

signalapp / Signal-Android

A private messenger for Android.
https://signal.org
GNU Affero General Public License v3.0
25.66k stars 6.16k forks source link

Backup Failed #12404

Closed zjabri closed 1 year ago

zjabri commented 2 years ago

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

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

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$AM6NnZmduQ5oDS8tZY51D7UmE(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 commented 2 years ago

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

zjabri commented 2 years ago

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

cody-signal commented 2 years ago

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

zjabri commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

Thanks, looking into it.

cody-signal commented 2 years ago

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

mauriceKA commented 2 years ago

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

mdontu commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

waaamb commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

simonbru commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

mdecker commented 2 years ago

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

gkft commented 2 years ago

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

KoljaFrahm commented 2 years ago

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

waaamb commented 2 years ago

Mine are in /storage/emulated/0/Signal

My backup completed this morning on 5.48.3 👍🏻

gkft commented 2 years ago

My backup also completed successfully after upgrading to 5.48.3. :+1:

cloudyafternoon commented 2 years ago

My backup also completed successfully after upgrading to 5.48.3. 👍 Same for me. Thanks!

KoljaFrahm commented 2 years ago

My backup also completed successfully after upgrading to 5.48.3. 👍 Same for me. Thanks!

Same for me!

mdontu commented 2 years ago

I am still seeing the issue with Signal 5.48.3.

alex-signal commented 2 years ago

@mdontu Could you please post a new debug log for 5.48.3?

M0ssTee commented 2 years ago

I also still have the issue in 5.48.3. https://debuglogs.org/android/5.48.3/605d08c72aa3df4640d88414f7ba0c558e414c88830a0cca141938df7eb65eaa

thewholelifetolearn commented 2 years ago

I'm having the same issue. Since the 17th of August, all backups are failing. It started with 5.46.6 and it still does with the last version (5.48.3).

You can find the logs on: https://debuglogs.org/android/5.48.3/f60926627d3dabf280f66a12829333c7c5f17be932396f2c7c259a7469abc0d8

PS: since the backups are failing, the temporary files are not deleted!!

janejuenyang commented 2 years ago

Another set of logs to help with the debugging. I'm on 5.48.3 but the backups haven't worked for me since Aug 20.

https://debuglogs.org/android/5.48.3/a196eeb0490d83c2647f37fed5571f558ad55685306b0b760ea8b36611ca78d7

mdontu commented 2 years ago

@mdontu Could you please post a new debug log for 5.48.3?

https://debuglogs.org/android/5.48.3/260a750f81aa98b6411114dc82273d526aca82d779a7b10e9c29366b47353180

cody-signal commented 2 years ago

Hi folks, thanks for all the logs. We are looking into the issue. We made changes to verify a backup file and that is showing us some limitations with Android's scoped storage system and how we are interacting with it. Hope to have a fix in soon.

dcgomez commented 2 years ago

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.

itsjustarumour commented 2 years ago

Still getting this on Version 5.49.4. Like OP, backups stopped working on Aug 18.

thewholelifetolearn commented 2 years ago

As @itsjustarumour said, the backups are not working with the new version 5.49.4. Ad the failed backups are not deleted either!

mikefonnesbeck commented 2 years ago

I am having a similar issue since August 18, 2022. If I try and perform a backup of my chat in Signal, it will get to about 80% then the app crashes. My last successful backup was August 18, 2022. Manual backup crashes every time. I have tried rebooting, updating Signal, nothing works. I see in the DEBUG log a Parcel exception when creating the backup. I have submitted my log and also emailed Signal Support but have gotten nothing.

Please help if you can?

-M

PeterPilley commented 2 years ago

Hi is there any update in this issue. It's getting really annoying having to delete the backup files to free up space.

PeterPilley commented 2 years ago

Hi is there any update in this issue. It's getting really annoying having to delete the backup files to free up space.

Also, just noticed if I go into settings -> chats then try to use the chat backups option signal crashes.

hslh commented 2 years ago

Same here, except that for me opening 'settings -> chats -> Chat backups' does work. This is on version 5.51.7

mikefonnesbeck commented 2 years ago

Hi is there any update in this issue. It's getting really annoying having to delete the backup files to free up space.

Also, just noticed if I go into settings -> chats then try to use the chat backups option signal crashes.

Yes --- this is what is happening to me. Backups are not working & cause crashing. If I go into SETTINGS | CHATS | CHATS BACKUP and do a manual backup, Signal crashes. I am also on version 5.51.7

greyson-signal commented 2 years ago

Hi there, just to be clear, submitting a log does not make it immediately visible to us. You have to send us the link :) If people are experiencing a crash, please take a debuglog and post the link in this thread. Thanks!

r-eule commented 2 years ago

Hi, my signal backups are also not working since Aug-19. No App-Update could change that (now vers. 5.51.7). I have also the problem that the failed backups are not deleted. The backup-location is on the internal sd-card in the standard download folder.

my debug-log: https://debuglogs.org/android/5.51.7/353c1d28ead19286a4ff9bced4224de89204e65eeead2297e77f23209c8cb0c3

What can I do to restore the backup functionality?

Best regards, Rene

mikefonnesbeck commented 2 years ago

Hi there, just to be clear, submitting a log does not make it immediately visible to us. You have to send us the link :) If people are experiencing a crash, please take a debuglog and post the link in this thread. Thanks!

Hi @greyson-signal thank you so much.

Here is my debug log : https://debuglogs.org/android/5.51.7/74de20bed77e8a453a625e740729f0fe591be5761bb7a765991afd90cec97dc3