Signal-android: App crashes after restoring backup from previous version

[taturati]

The app crashes after automatic restore of encrypted backup from 4.19.3 in 4.20.4. Then it crashes immediately after each attempt to start it.

Steps to reproduce:

• Backup data in 4.19.3 installed from play store through Settings->chats and media->create backup (and wait for the backup process to complete),
• unistall the app
• switch to beta testing in play store
• install beta version (4.20.4), let it to restore data from backup
• app crashes.

Device: Samsung SM-J330F
Android version: 7.0
Signal version: 4.20.4

Debug log can't be created for obvious reasons.

My guess (without actually looking into the code):
The app is not validating restored data and handles exceptions poorly, so when restoring process goes wrong, the app just crashes without reporting any error to the user and then it keeps crashing and crashing..

[Mofas45]

i want

[heydabop]

Also happening to me

Steps to reproduce

• Open Signal (4.20.5) on phone 1
• Go to Settings -> Chats and Media -> "Create Backup"
• Copy Backup to Phone 2
• Launch Signal (for first time) on Phone 2
• Grant permissions, start restore, enter password

Actual result: App crashes on message 1

Device(s) info
Device: Google Pixel 2 XL
Android version: Stock Android P DP2
Signal version: 4.20.5

Can't submit a debug log but here's the exception I'm getting
net.sqlcipher.database.SQLiteDatabaseCorruptException: error code 11: database disk image is malformed
Being thrown from somewhere in FullBackupImporter.importFile(). Looks like the statement being executed is INSERT INTO sms VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?), and it's the first insert into sms.

UPDATE: Looks like it's failing on this.native_execute(); in SQLiteStatement.execute(). Could be my NDK environment, though the Play Store version also crashes on import

[florath]

Same here.

Device(s) info
Device: Samsung Galaxy A5 2017 (SM-A520F)
Android version: LineageOS 14.1 (Build: 2018-05-30).
Signal version: 4.20.5

Backup was created with Signal Version 4.20.5.
Try to restore with latest 4.19 and 4.20.5 - both run into the same error.

Found the following logs - looks to be at least a similar exception as reported by heydabop.

05-31 12:26:32.812 28636 29201 E Database: Calling error handler for corrupt database (detected) /data/user/0/org.thoughtcrime.securesms/databases/signal.db
05-31 12:26:32.812 28636 29201 E DefaultDatabaseErrorHandler: Corruption reported by sqlite on database, deleting: /data/user/0/org.thoughtcrime.securesms/databases/signal.db
05-31 12:26:32.812 28636 29201 E DefaultDatabaseErrorHandler: Database object for corrupted database is already open, closing
05-31 12:26:32.821 28636 29201 E DefaultDatabaseErrorHandler: deleting the database file: /data/user/0/org.thoughtcrime.securesms/databases/signal.db
05-31 12:26:32.823 28636 29201 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #5
05-31 12:26:32.823 28636 29201 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 28636
05-31 12:26:32.823 28636 29201 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at android.os.AsyncTask$3.done(AsyncTask.java:325)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:242)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:243)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:761)
05-31 12:26:32.823 28636 29201 E AndroidRuntime: Caused by: java.lang.IllegalStateException: database not open
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at net.sqlcipher.database.SQLiteDatabase.endTransaction(SQLiteDatabase.java:736)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:79)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:372)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:364)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at android.os.AsyncTask$2.call(AsyncTask.java:305)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:237)
05-31 12:26:32.823 28636 29201 E AndroidRuntime:    ... 4 more
05-31 12:26:32.825  4284  5909 W ActivityManager:   Force finishing activity org.thoughtcrime.securesms/.RegistrationActivity

[AlfonsoMuskedunder]

I receive the exact same error as @florath. I'd just like to add that backups used to work just fine on the same device before SD functionality was implemented.

(Backup was created and failed to import in Signal 4.20.5; OS is LineageOS 7.1.2; device is a Moto G4 Play.)

[synonym24]

Getting the same messages in logcat as @florath and @AlfonsoMuskedunder:

Device: Huawei P9 (EVA-L09)
Build: EVA-L09C432B502
Android version: 7.0
Signal version: 4.20.5

06-01 02:06:59.757 13730 13730 I         : power log dlsym ok
06-01 02:06:59.760 13730 13730 I art     : Reinit property: dalvik.vm.checkjni= false
06-01 02:06:59.827 13730 13730 I MultiDex: VM with version 2.1.0 has multidex support
06-01 02:06:59.827 13730 13730 I MultiDex: Installing application
06-01 02:06:59.827 13730 13730 I MultiDex: VM has multidex support, MultiDex support library is disabled.
06-01 02:06:59.842 13730 13730 W PartProvider: onCreate()
06-01 02:06:59.947 13730 13730 W PersistentAlarmManagerListener: class org.thoughtcrime.securesms.service.RotateSignedPreKeyListener scheduling for: 1527984419947
06-01 02:06:59.949 13730 13730 W PersistentAlarmManagerListener: class org.thoughtcrime.securesms.service.DirectoryRefreshListener scheduling for: 1527854819949
06-01 02:06:59.956 13730 13730 I org.webrtc.Logging: NativeLibrary: Loading native library.
06-01 02:06:59.956 13730 13730 I org.webrtc.Logging: NativeLibrary: Loading library: jingle_peerconnection_so
06-01 02:06:59.968 13730 13730 I HwCust  : Constructor found for class android.app.HwCustActivityImpl
06-01 02:06:59.974 13730 13730 I HwCust  : Constructor found for class android.app.HwCustHwWallpaperManagerImpl
06-01 02:06:59.978 13730 13730 W PassphraseRequiredActionBarActivity: onCreate(null)
06-01 02:06:59.992 13730 13730 W PassphraseRequiredActionBarActivity: routeApplicationState(), state: 1
06-01 02:07:00.007 13730 13730 W art     : Before Android 4.1, method android.graphics.PorterDuffColorFilter android.support.graphics.drawable.VectorDrawableCompat.updateTintFilter(android.graphics.PorterDuffColorFilter, android.content.res.ColorStateList, android.graphics.PorterDuff$Mode) would have incorrectly overridden the package-private method in android.graphics.drawable.Drawable
06-01 02:07:00.054 13730 13730 W VRSystemServiceManager: vr service is not alive
06-01 02:07:00.055 13730 13730 I HwSecImmHelper: mSecurityInputMethodService is null
06-01 02:07:00.058 13730 13730 I HwPointEventFilter: support AFT
06-01 02:07:00.090 13730 13761 I OpenGLRenderer: Initialized EGL, version 1.4
06-01 02:07:00.096 13730 13761 W linker  : /vendor/lib/libhwuibp.so: unused DT entry: type 0xf arg 0xeb5
06-01 02:07:00.235 13730 13730 W KeyCachingService: onCreate()
06-01 02:07:00.331 13730 13730 W service : Broadcasting new secret...
06-01 02:07:00.331 13730 13730 I SendBroadcastPermission: action:org.thoughtcrime.securesms.service.action.NEW_KEY_EVENT, mPermissionType:0
06-01 02:07:00.333 13730 13730 W KeyCachingService: onStartCommand, null
06-01 02:07:00.335 13730 13776 W MmsSmsDatabase: Executing query: SELECT _id, unique_row_id, body, type, thread_id, address, address_device_id, subject, date_sent, date_received, m_type, msg_box, status, part_count, ct_l, tr_id, m_size, exp, st, delivery_receipt_count, read_receipt_count, mismatched_identities, network_failures, subscription_id, expires_in, expire_started, notified, transport_type, attachment_json, quote_id, quote_author, quote_body, quote_attachment, shared_contacts FROM (SELECT DISTINCT date_sent AS date_sent, date AS date_received, _id, 'SMS::' || _id || '::' || date_sent AS unique_row_id, NULL AS attachment_json, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, delivery_receipt_count, read_receipt_count, mismatched_identities, subscription_id, expires_in, expire_started, notified, NULL AS network_failures, 'sms' AS transport_type, NULL AS quote_id, NULL AS quote_author, NULL AS quote_body, NULL AS quote_attachment, NULL AS shared_contacts FROM sms WHERE (read = 0 AND notified = 0) UNION ALL SELECT DISTINCT date AS date_sent, date_received AS date_received, mms._id AS _id, 'MMS::' || mms._id || '::' || date AS unique_row_id, json_group_array(json_object('_id', part._id, 'unique_id', part.unique_id, 'mid', part.mid,'data_size', part.data_size, 'file_name', part.file_name, '_data', part._data, 'thumbnail', part.thumbnail, 'ct', part.ct, 'cl', part.cl, 'fast_preflight_id', part.fast_preflight_id, 'voice_note', part.voice_note, 'width', part.width, 'height', part.height, 'quote', part.quote, 'cd', part.cd, 'name', part.name, 'pending_push', part.pending_push)) AS attachment_json, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, delivery_receipt_count, read_receipt_count, mismatched_identities, subscription_id, expires_in, expire_started, notified, network_failures, 'mms' AS transport_type, quote_id, quote_author, quote_body, quote_attachment, shared_contacts FROM mms LEFT OUTER JOIN part ON part.mid = mms._id WHERE (read = 0 AND notified = 0) GROUP BY mms._id ORDER BY date_received ASC)
06-01 02:07:00.337 13730 13730 W service : Broadcasting new secret...
06-01 02:07:00.337 13730 13730 I SendBroadcastPermission: action:org.thoughtcrime.securesms.service.action.NEW_KEY_EVENT, mPermissionType:0
06-01 02:07:00.340 13730 13777 W MmsSmsDatabase: Executing query: SELECT _id, unique_row_id, body, type, thread_id, address, address_device_id, subject, date_sent, date_received, m_type, msg_box, status, part_count, ct_l, tr_id, m_size, exp, st, delivery_receipt_count, read_receipt_count, mismatched_identities, network_failures, subscription_id, expires_in, expire_started, notified, transport_type, attachment_json, quote_id, quote_author, quote_body, quote_attachment, shared_contacts FROM (SELECT DISTINCT date_sent AS date_sent, date AS date_received, _id, 'SMS::' || _id || '::' || date_sent AS unique_row_id, NULL AS attachment_json, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, delivery_receipt_count, read_receipt_count, mismatched_identities, subscription_id, expires_in, expire_started, notified, NULL AS network_failures, 'sms' AS transport_type, NULL AS quote_id, NULL AS quote_author, NULL AS quote_body, NULL AS quote_attachment, NULL AS shared_contacts FROM sms WHERE (read = 0 AND notified = 0) UNION ALL SELECT DISTINCT date AS date_sent, date_received AS date_received, mms._id AS _id, 'MMS::' || mms._id || '::' || date AS unique_row_id, json_group_array(json_object('_id', part._id, 'unique_id', part.unique_id, 'mid', part.mid,'data_size', part.data_size, 'file_name', part.file_name, '_data', part._data, 'thumbnail', part.thumbnail, 'ct', part.ct, 'cl', part.cl, 'fast_preflight_id', part.fast_preflight_id, 'voice_note', part.voice_note, 'width', part.width, 'height', part.height, 'quote', part.quote, 'cd', part.cd, 'name', part.name, 'pending_push', part.pending_push)) AS attachment_json, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, delivery_receipt_count, read_receipt_count, mismatched_identities, subscription_id, expires_in, expire_started, notified, network_failures, 'mms' AS transport_type, quote_id, quote_author, quote_body, quote_attachment, shared_contacts FROM mms LEFT OUTER JOIN part ON part.mid = mms._id WHERE (read = 0 AND notified = 0) GROUP BY mms._id ORDER BY date_received ASC)
06-01 02:07:00.370 13730 13730 W PassphraseRequiredActionBarActivity: onCreate(null)
06-01 02:07:00.370 13730 13730 W PassphraseRequiredActionBarActivity: routeApplicationState(), state: 4
06-01 02:07:00.612 13730 13730 W VRSystemServi06-01 02:07:06.823 13730 13735 I art     : After code cache collection, code=7KB, data=31KB
06-01 02:07:06.823 13730 13735 I art     : Increasing code cache capacity to 128KB
06-01 02:07:06.824 13730 13730 W VRSystemServiceManager: vr service is not alive
06-01 02:07:06.825 13730 13730 W VRSystemServiceManager: vr service is not alive
06-01 02:07:06.826 13730 13730 I HwPointEventFilter: support AFT
06-01 02:07:14.850 13730 13730 I HwSecImmHelper: mSecurityInputMethodService is null
06-01 02:07:39.685 13730 13730 I HwSecImmHelper: mSecurityInputMethodService is null
06-01 02:07:39.733 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.733 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.733 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:39.734 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.734 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.734 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:39.752 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:40.661 13730 13797 E Database: Calling error handler for corrupt database (detected) /data/user/0/org.thoughtcrime.securesms/databases/signal.db
06-01 02:07:40.661 13730 13797 E DefaultDatabaseErrorHandler: Corruption reported by sqlite on database, deleting: /data/user/0/org.thoughtcrime.securesms/databases/signal.db
06-01 02:07:40.661 13730 13797 E DefaultDatabaseErrorHandler: Database object for corrupted database is already open, closing
06-01 02:07:40.666 13730 13797 E DefaultDatabaseErrorHandler: deleting the database file: /data/user/0/org.thoughtcrime.securesms/databases/signal.db
06-01 02:07:40.668 13730 13797 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #5
06-01 02:07:40.668 13730 13797 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 13730
06-01 02:07:40.668 13730 13797 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at android.os.AsyncTask$3.done(AsyncTask.java:330)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.run(FutureTask.java:242)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:255)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.lang.Thread.run(Thread.java:776)
06-01 02:07:40.668 13730 13797 E AndroidRuntime: Caused by: java.lang.IllegalStateException: database not open
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at net.sqlcipher.database.SQLiteDatabase.endTransaction(SQLiteDatabase.java:737)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:79)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:372)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:364)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at android.os.AsyncTask$2.call(AsyncTask.java:316)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  ... 4 more
06-01 02:07:40.700 13730 13797 I Process : Sending signal. PID: 13730 SIG: 9
06-01 02:07:40.801  1180  2021 I MediaProcessHandler: processOp opType: 1, uid: 10187, pid: 13730
06-01 02:07:40.801  1180  2021 W MediaProcessHandler: remove target not exist, maybe the UI process: uid: 10187, pid: 13730ceManager: vr service is not alive
06-01 02:07:00.612 13730 13730 W VRSystemServiceManager: vr service is not alive
06-01 02:07:00.613 13730 13730 I HwPointEventFilter: support AFT 
06-01 02:07:00.666 13730 13730 W PassphraseRequiredActionBarActivity: onDestroy()
06-01 02:07:00.909 13730 13730 W PassphraseRequiredActionBarActivity: onDestroy()
06-01 02:07:06.687 13730 13730 I hwaps   : JNI_OnLoad
06-01 02:07:06.823 13730 13735 I art     : Do partial code cache collection, code=7KB, data=31KB
06-01 02:07:06.823 13730 13735 I art     : After code cache collection, code=7KB, data=31KB
06-01 02:07:06.823 13730 13735 I art     : Increasing code cache capacity to 128KB
06-01 02:07:06.824 13730 13730 W VRSystemServiceManager: vr service is not alive
06-01 02:07:06.825 13730 13730 W VRSystemServiceManager: vr service is not alive
06-01 02:07:06.826 13730 13730 I HwPointEventFilter: support AFT
06-01 02:07:14.850 13730 13730 I HwSecImmHelper: mSecurityInputMethodService is null
06-01 02:07:39.685 13730 13730 I HwSecImmHelper: mSecurityInputMethodService is null
06-01 02:07:39.733 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.733 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.733 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:39.734 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.734 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.734 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:39.752 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: beginBatchEdit on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: finishComposingText on inactive InputConnection
06-01 02:07:39.753 13730 13730 W IInputConnectionWrapper: endBatchEdit on inactive InputConnection
06-01 02:07:40.661 13730 13797 E Database: Calling error handler for corrupt database (detected) /data/user/0/org.thoughtcrime.securesms/databases/signal.db
06-01 02:07:40.661 13730 13797 E DefaultDatabaseErrorHandler: Corruption reported by sqlite on database, deleting: /data/user/0/org.thoughtcrime.securesms/databases/signal.db
06-01 02:07:40.661 13730 13797 E DefaultDatabaseErrorHandler: Database object for corrupted database is already open, closing
06-01 02:07:40.666 13730 13797 E DefaultDatabaseErrorHandler: deleting the database file: /data/user/0/org.thoughtcrime.securesms/databases/signal.db
06-01 02:07:40.668 13730 13797 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #5
06-01 02:07:40.668 13730 13797 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 13730
06-01 02:07:40.668 13730 13797 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at android.os.AsyncTask$3.done(AsyncTask.java:330)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.run(FutureTask.java:242)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:255)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.lang.Thread.run(Thread.java:776)
06-01 02:07:40.668 13730 13797 E AndroidRuntime: Caused by: java.lang.IllegalStateException: database not open
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at net.sqlcipher.database.SQLiteDatabase.endTransaction(SQLiteDatabase.java:737)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:79)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:372)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:364)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at android.os.AsyncTask$2.call(AsyncTask.java:316)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  at java.util.concurrent.FutureTask.run(FutureTask.java:237)
06-01 02:07:40.668 13730 13797 E AndroidRuntime:  ... 4 more
06-01 02:07:40.700 13730 13797 I Process : Sending signal. PID: 13730 SIG: 9
06-01 02:07:40.801  1180  2021 I MediaProcessHandler: processOp opType: 1, uid: 10187, pid: 13730
06-01 02:07:40.801  1180  2021 W MediaProcessHandler: remove target not exist, maybe the UI process: uid: 10187, pid: 13730

[pajowu]

after some debugging I got it working. The problem seems to be caused by the "CREATE TRIGGER" commands added in database version 9 (commit 0449647cf90156e0e7f62f66727e50b4f3de58bb) for the search feature. If the commands are skipped when importing the backup, it works fine.

[nextgen-networks]

Had also massive errors restoring old backups made with Signal 4.20.2 / 4.20.4 / 4.20.5 even withing fresh installed Signal 4.20.5 - no chance to get it working.

My workaround:

• removal from beta group
• installation of Signal 4.19.3
• import Signal messages (worked for me also with signal backup created with 4.20.2)

Developers:
Please put extra focus on test of backup / restore - this feature is absolute essential!

Thanks for all the hard work on this great app!

[greyson-signal]

There was an issue in the backup restoration flow that flubbed when migrating to schemas with new tables. Sorry! We'll be putting extra focus on ensuring the stability of backup & restore in the future.

[greyson-signal]

@taturati @heydabop @AlfonsoMuskedunder @florath @synonym24 @nextgen-networks @pajowu

The 4.20.6 beta is rolling out now. I took special care to ensure that backups made on previous 4.20.x versions should work now on 4.20.6. If you're able and willing, try restoring from your backup again and let me know if you're having any problems.

Thank you all for being beta testers!

[synonym24]

Tried today restoring the previously failed restore of the backup created with version 4.20.5.
I can confirm that, at least in my case, the restore with the version 4.20.6 was successful.

[heydabop]

Was able restore without issue. Thanks for all the hard work!

[tux2sa]

On my side is not posible to run after Upgrade from 4.16.9 to the new version without carsh as i desciped in #7866

[tux2sa]

here is the log about the crash:

6-07 16:40:23.573 19839 19839 W service : Broadcasting new secret... 06-07 16:40:23.574 2326 2366 W BroadcastQueue: Skipping deliver [background] BroadcastRecord{f0e4bbd u0 org.thoughtcrime.securesms.service.action.NEW_KEY_EVENT} to ReceiverList{5d4a4ee 19839 org.thoughtcrime.securesms/10146/u0 remote:c13269}: process crashing 06-07 16:40:23.575 19839 19839 W KeyCachingService: onStartCommand, null 06-07 16:40:23.575 19839 19839 W PassphraseRequiredActionBarActivity: onPause() 06-07 16:40:23.581 2326 2364 I WindowManager: Failed to capture screenshot of Token{5f8b143 ActivityRecord{5b916f2 u0 org.thoughtcrime.securesms/.RoutingActivity t3468 f}} appWin=Window{7cc9ad8 u0 Starting org.thoughtcrime.securesms} drawState=4 06-07 16:40:23.586 19839 19882 W MmsSmsDatabase: Executing query: SELECT _id, unique_row_id, body, type, thread_id, address, address_device_id, subject, date_sent, date_received, m_type, msg_box, status, part_count, ct_l, tr_id, m_size, exp, st, delivery_receipt_count, read_receipt_count, mismatched_identities, network_failures, subscription_id, expires_in, expire_started, notified, transport_type, attachment_json, quote_id, quote_author, quote_body, quote_attachment, shared_contacts FROM (SELECT DISTINCT date_sent AS date_sent, date AS date_received, _id, 'SMS::' || _id || '::' || date_sent AS unique_row_id, NULL AS attachment_json, body, read, thread_id, type, address, address_device_id, subject, NULL AS m_type, NULL AS msg_box, status, NULL AS part_count, NULL AS ct_l, NULL AS tr_id, NULL AS m_size, NULL AS exp, NULL AS st, delivery_receipt_count, read_receipt_count, mismatched_identities, subscription_id, expires_in, expire_started, notified, NULL AS network_failures, 'sms' AS transport_type, NULL AS quote_id, NULL AS quote_author, NULL AS quote_body, NULL AS quote_attachment, NULL AS shared_contacts FROM sms WHERE (read = 0 AND notified = 0) UNION ALL SELECT DISTINCT date AS date_sent, date_received AS date_received, mms._id AS _id, 'MMS::' || mms._id || '::' || date AS unique_row_id, json_group_array(json_object('_id', part._id, 'unique_id', part.unique_id, 'mid', part.mid,'data_size', part.data_size, 'file_name', part.file_name, '_data', part._data, 'thumbnail', part.thumbnail, 'ct', part.ct, 'cl', part.cl, 'fast_preflight_id', part.fast_preflight_id, 'voice_note', part.voice_note, 'width', part.width, 'height', part.height, 'quote', part.quote, 'cd', part.cd, 'name', part.name, 'pending_push', part.pending_push)) AS attachment_json, body, read, thread_id, NULL AS type, address, address_device_id, NULL AS subject, m_type, msg_box, NULL AS status, part_count, ct_l, tr_id, m_size, exp, st, delivery_receipt_count, read_receipt_count, mismatched_identities, subscription_id, expires_in, expire_started, notified, network_failures, 'mms' AS transport_type, quote_id, quote_author, quote_body, quote_attachment, shared_contacts FROM mms LEFT OUTER JOIN part ON part.mid = mms._id WHERE (read = 0 AND notified = 0) GROUP BY mms._id ORDER BY date_received ASC) 06-07 16:40:23.593 19839 19839 W KeyCachingService: onStartCommand, org.thoughtcrime.securesms.service.action.ACTIVITY_START_EVENT 06-07 16:40:23.593 19839 19839 W KeyCachingService: Incrementing activity count... 06-07 16:40:23.613 19839 19886 I art : Alloc concurrent mark sweep GC freed 1388(123KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 9MB/16MB, paused 972us total 48.805ms 06-07 16:40:23.613 19839 19886 I art : Forcing collection of SoftReferences for 778MB allocation 06-07 16:40:23.614 19839 19886 I art : Starting a blocking GC Alloc 06-07 16:40:23.658 19839 19886 I art : Alloc concurrent mark sweep GC freed 2486(101KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 9MB/16MB, paused 571us total 44.143ms 06-07 16:40:23.658 19839 19886 W art : Throwing OutOfMemoryError "Failed to allocate a 815909458 byte allocation with 6922064 free bytes and 502MB until OOM" 06-07 16:40:23.658 19839 19886 I art : Starting a blocking GC Alloc 06-07 16:40:23.658 19839 19886 I art : Starting a blocking GC Alloc 06-07 16:40:23.665 19839 19886 I art : Alloc sticky concurrent mark sweep GC freed 1349(44KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 9MB/16MB, paused 578us total 6.432ms 06-07 16:40:23.666 19839 19886 I art : Starting a blocking GC Alloc 06-07 16:40:23.666 2326 2366 W BroadcastQueue: Skipping deliver [background] BroadcastRecord{30025f u-1 android.net.conn.CONNECTIVITY_CHANGE} to ReceiverList{a58e6b9 19839 org.thoughtcrime.securesms/10146/u0 remote:7078080}: process crashing 06-07 16:40:23.670 19839 19893 W MessageRetrievalService: Waiting for websocket state change.... 06-07 16:40:23.672 19839 19893 W MessageRetrievalService: Network requirement: false, active activities: 0, push pending: 0, gcm disabled: true 06-07 16:40:23.680 19839 19839 W MessageRetrievalService: Active Count: 1 06-07 16:40:23.681 19839 19893 W MessageRetrievalService: Network requirement: false, active activities: 1, push pending: 0, gcm disabled: true 06-07 16:40:23.712 19839 19886 I art : Alloc partial concurrent mark sweep GC freed 742(39KB) AllocSpace objects, 0(0B) LOS objects, 39% free, 9MB/16MB, paused 3.479ms total 45.405ms 06-07 16:40:23.712 19839 19886 I art : Starting a blocking GC Alloc 06-07 16:40:23.734 19839 19839 W KeyCachingService: onStartCommand, org.thoughtcrime.securesms.service.action.ACTIVITY_STOP_EVENT 06-07 16:40:23.734 19839 19839 W KeyCachingService: Decrementing activity count... 06-07 16:40:23.735 19839 19839 W MessageRetrievalService: Active Count: 0 06-07 16:40:23.738 19839 19893 W MessageRetrievalService: Network requirement: false, active activities: 0, push pending: 0, gcm disabled: true 06-07 16:40:23.765 19839 19886 I art : Alloc concurrent mark sweep GC freed 389(25KB) AllocSpace objects, 0(0B) LOS objects, 39% free, 9MB/16MB, paused 5.916ms total 51.494ms 06-07 16:40:23.765 19839 19886 I art : Forcing collection of SoftReferences for 778MB allocation 06-07 16:40:23.765 19839 19886 I art : Starting a blocking GC Alloc 06-07 16:40:23.810 19839 19886 I art : Alloc concurrent mark sweep GC freed 98(6KB) AllocSpace objects, 0(0B) LOS objects, 40% free, 9MB/16MB, paused 442us total 44.365ms 06-07 16:40:23.810 19839 19886 W art : Throwing OutOfMemoryError "Failed to allocate a 815909458 byte allocation with 6911450 free bytes and 502MB until OOM" 06-07 16:40:23.814 19839 19886 I Process : Sending signal. PID: 19839 SIG: 9 06-07 16:40:23.836 2326 3683 I ActivityManager: Process org.thoughtcrime.securesms (pid 19839) has died 06-07 16:40:23.836 2326 3704 D GraphicsStats: Buffer count: 9 06-07 16:40:23.836 2326 3683 D ActivityManager: cleanUpApplicationRecord -- 19839 06-07 16:40:23.837 2326 3683 W ActivityManager: Scheduling restart of crashed service org.thoughtcrime.securesms/.service.MessageRetrievalService in 1000ms 06-07 16:40:23.837 2326 3683 W ActivityManager: Scheduling restart of crashed service org.thoughtcrime.securesms/.service.KeyCachingService in 11000ms 06-07 16:40:23.840 2326 2580 W InputDispatcher: channel 'e370714 org.thoughtcrime.securesms/org.thoughtcrime.securesms.RoutingActivity (server)' ~ Consumer closed input channel or an error occurred. events=0x9 06-07 16:40:23.840 2326 2580 E InputDispatcher: channel 'e370714 org.thoughtcrime.securesms/org.thoughtcrime.securesms.RoutingActivity (server)' ~ Channel is unrecoverably broken and will be disposed! 06-07 16:40:23.843 2326 3158 I WindowManager: WIN DEATH: Window{e370714 u0 org.thoughtcrime.securesms/org.thoughtcrime.securesms.RoutingActivity} 06-07 16:40:23.843 2326 3158 W InputDispatcher: Attempted to unregister already unregistered input channel 'e370714 org.thoughtcrime.securesms/org.thoughtcrime.securesms.RoutingActivity (server)' 06-07 16:40:23.860 2326 10446 W ActivityManager: Ignoring remove of inactive process: ProcessRecord{43c08f3 0:org.thoughtcrime.securesms/u0a146} 06-07 16:40:24.018 2326 2373 W AppOps : Finishing op nesting under-run: uid 1000 pkg android code 24 time=0 duration=0 nesting=0 06-07 16:40:24.470 281 476 E ThermalEngine: [GPU_MON] 11 percent. Current Sampling Time is 1 sec 06-07 16:40:24.849 2326 2366 I ActivityManager: Start proc 19899:org.thoughtcrime.securesms/u0a146 for service org.thoughtcrime.securesms/.service.MessageRetrievalService 06-07 16:40:24.935 19899 19899 I MultiDex: VM with version 2.1.0 has multidex support 06-07 16:40:24.935 19899 19899 I MultiDex: Installing application 06-07 16:40:24.936 19899 19899 I MultiDex: VM has multidex support, MultiDex support library is disabled. 06-07 16:40:24.959 19899 19899 W PartProvider: onCreate() 06-07 16:40:25.147 19899 19899 W PersistentAlarmManagerListener: class org.thoughtcrime.securesms.service.RotateSignedPreKeyListener scheduling for: 1528579752983 06-07 16:40:25.150 19899 19899 W PersistentAlarmManagerListener: class org.thoughtcrime.securesms.service.DirectoryRefreshListener scheduling for: 1528450152986 06-07 16:40:25.163 19899 19899 I org.webrtc.Logging: NativeLibrary: Loading native library. 06-07 16:40:25.163 19899 19899 I org.webrtc.Logging: NativeLibrary: Loading library: jingle_peerconnection_so 06-07 16:40:25.171 19899 19923 W SQLCipherOpenHelper: Upgrading database: 1, 9 06-07 16:40:25.177 19899 19899 D JVM : JVM::Initialize@[tid=19899] 06-07 16:40:25.178 19899 19899 D JVM : JVM::JVM@[tid=19899] 06-07 16:40:25.178 19899 19899 D JVM : LoadClasses 06-07 16:40:25.178 19899 19899 D JVM : name: org/webrtc/voiceengine/BuildInfo 06-07 16:40:25.178 19899 19899 D JVM : name: org/webrtc/voiceengine/WebRtcAudioManager 06-07 16:40:25.178 19899 19899 D JVM : name: org/webrtc/voiceengine/WebRtcAudioRecord 06-07 16:40:25.178 19899 19899 D JVM : name: org/webrtc/voiceengine/WebRtcAudioTrack 06-07 16:40:25.187 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363189 06-07 16:40:25.190 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363191 06-07 16:40:25.191 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363193 06-07 16:40:25.192 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363194 06-07 16:40:25.195 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363196 06-07 16:40:25.196 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363198 06-07 16:40:25.197 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363200 06-07 16:40:25.198 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363201 06-07 16:40:25.204 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363202 06-07 16:40:25.205 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363203 06-07 16:40:25.206 19899 19923 W PreKeyMigrationHelper: Migrated one-time prekey: 2363204 06-07 16:40:25.206 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.206 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.242 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.268 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.295 19899 19923 I art : Forcing collection of SoftReferences for 778MB allocation 06-07 16:40:25.295 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.317 19899 19923 W art : Throwing OutOfMemoryError "Failed to allocate a 815909458 byte allocation with 2554394 free bytes and 504MB until OOM" 06-07 16:40:25.319 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.319 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.325 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.342 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.371 19899 19923 I art : Forcing collection of SoftReferences for 778MB allocation 06-07 16:40:25.371 19899 19923 I art : Starting a blocking GC Alloc 06-07 16:40:25.396 19899 19923 I art : Starting a blocking GC HomogeneousSpaceCompact 06-07 16:40:25.429 19899 19923 W art : Throwing OutOfMemoryError "Failed to allocate a 815909458 byte allocation with 2559629 free bytes and 504MB until OOM" 06-07 16:40:25.436 19899 19923 E AndroidRuntime: FATAL EXCEPTION: pool-3-thread-1 06-07 16:40:25.436 19899 19923 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 19899 06-07 16:40:25.436 19899 19923 E AndroidRuntime: java.lang.OutOfMemoryError: Failed to allocate a 815909458 byte allocation with 2559629 free bytes and 504MB until OOM 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at org.thoughtcrime.securesms.database.helpers.PreKeyMigrationHelper.readBlob(PreKeyMigrationHelper.java:190) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at org.thoughtcrime.securesms.database.helpers.PreKeyMigrationHelper.loadSerializedRecord(PreKeyMigrationHelper.java:158) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at org.thoughtcrime.securesms.database.helpers.PreKeyMigrationHelper.migratePreKeys(PreKeyMigrationHelper.java:46) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at org.thoughtcrime.securesms.database.helpers.SQLCipherOpenHelper.onUpgrade(SQLCipherOpenHelper.java:141) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at net.sqlcipher.database.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:173) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at net.sqlcipher.database.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:227) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at net.sqlcipher.database.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:214) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at org.thoughtcrime.securesms.database.helpers.SQLCipherOpenHelper.getReadableDatabase(SQLCipherOpenHelper.java:224) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at org.thoughtcrime.securesms.database.SmsDatabase.getExpirationStartedMessages(SmsDatabase.java:668) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at org.thoughtcrime.securesms.service.ExpiringMessageManager$LoadTask.run(ExpiringMessageManager.java:57) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607) 06-07 16:40:25.436 19899 19923 E AndroidRuntime: at java.lang.Thread.run(Thread.java:761) 06-07 16:40:25.448 2326 2366 W BroadcastQueue: Skipping deliver [background] BroadcastRecord{ff914e3 u-1 android.net.conn.CONNECTIVITY_CHANGE} to ReceiverList{3406c9d 19899 org.thoughtcrime.securesms/10146/u0 remote:c0b9f74}: process crashing 06-07 16:40:25.449 19899 19930 W MessageRetrievalService: Waiting for websocket state change.... 06-07 16:40:25.453 19899 19930 W MessageRetrievalService: Network requirement: false, active activities: 0, push pending: 0, gcm disabled: true

[johanw666]

Restore still crashes with 4.20.6 on a Sony Xperia Z3 compact, Android 6.0.1:

06-08 01:06:02.718 W/RegistrationActivity(21262): java.io.IOException: Bad MAC
06-08 01:06:02.718 W/RegistrationActivity(21262):   at org.thoughtcrime.securesms.backup.FullBackupImporter$BackupRecordInputStream.readFrame(FullBackupImporter.java:284)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at org.thoughtcrime.securesms.backup.FullBackupImporter$BackupRecordInputStream.readFrame(FullBackupImporter.java:216)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:73)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:372)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at org.thoughtcrime.securesms.RegistrationActivity$2.doInBackground(RegistrationActivity.java:364)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at android.os.AsyncTask$2.call(AsyncTask.java:295)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at java.util.concurrent.FutureTask.run(FutureTask.java:237)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:234)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
06-08 01:06:02.718 W/RegistrationActivity(21262):   at java.lang.Thread.run(Thread.java:818)

[greyson-signal]

@tux2sa Looks like you're experiencing a different kind of issue, specifically an OOM error. I'm going to copy your stack trace to the other ticket and re-open it.

[greyson-signal]

@johanw666 Looks like you're experiencing a separate issue as well. Do you mind opening a separate ticket with information about which version your backup is from?

[florath]

I was able to restore a backup using 4.20.6.
Thanks for the fast fix!