search

signalapp / Signal-Android

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

Signal crashes at db migration V191_UniqueMessageMigrationV2.kt with "SQLiteLog: (267) statement aborts at 10: [...]" #13034

Open derMart opened 1 year ago

derMart commented 1 year ago

Bug description

As title says, upgrading vom v6.14.x to v6.24.3.0-JW, see also log below. Although this is happening on JW fork, this is very certain not anything related to that fork. See also https://github.com/signalapp/Signal-Android/issues/12410 where something similar happened on an older upgrade. It seems something fundamentally is broken with the db migration code. The "SQLiteLog: (267) statement aborts at 10:" is also very interesting, but I can't figure out what the error is (maybe the log is cutoff here?)

Steps to reproduce

logcat

06-26 22:57:47.746 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_read_and_notified_and_thread_id_index
06-26 22:57:47.765 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_type_index
06-26 22:57:47.784 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_date_sent_index
06-26 22:57:47.811 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_date_server_index
06-26 22:57:47.828 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_thread_date_index
06-26 22:57:47.850 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_reactions_unread_index
06-26 22:57:47.863 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_story_type_index
06-26 22:57:47.876 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_parent_story_id_index
06-26 22:57:47.888 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_exported_index
06-26 22:57:47.901 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_id_type_payment_transactions_index
06-26 22:57:47.904 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS mms_thread_story_parent_story_scheduled_date_index
06-26 22:57:47.930 25251 25321 D V185_MessageRecipientsA: Executing: DROP trigger IF EXISTS message_ai
06-26 22:57:47.932 25251 25321 D V185_MessageRecipientsA: Executing: DROP trigger IF EXISTS message_ad
06-26 22:57:47.933 25251 25321 D V185_MessageRecipientsA: Executing: DROP trigger IF EXISTS message_au
06-26 22:57:47.934 25251 25321 D V185_MessageRecipientsA: Executing: DROP index IF EXISTS message_quote_id_quote_author_scheduled_date_index
06-26 22:57:47.950 25251 25321 D V185_MessageRecipientsA: Executing: DROP trigger IF EXISTS msl_message_delete
06-26 22:57:49.058 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_read_and_notified_and_thread_id_index ON "message"(read, notified, thread_id)
06-26 22:57:49.369 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_type_index ON "message" (type)
06-26 22:57:49.569 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_date_sent_from_to_thread_index ON message (date_sent, from_recipient_id, to_recipient_id, thread_id)
06-26 22:57:49.770 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_date_server_index ON "message" (date_server)
06-26 22:57:49.966 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_thread_date_index ON "message" (thread_id, date_received)
06-26 22:57:50.207 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_reactions_unread_index ON "message" (reactions_unread)
06-26 22:57:50.387 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_story_type_index ON "message" (story_type)
06-26 22:57:50.571  2025  2025 D VideoCall_LowBattery: disconnectVideoCalls on low battery
06-26 22:57:50.571  2025  2025 D VideoCall_LowBattery: disconnectVideoCalls 
06-26 22:57:50.572 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_parent_story_id_index ON "message" (parent_story_id)
06-26 22:57:50.572   797   797 D lights.sony: setLight : Type::BATTERY
06-26 22:57:50.573   797   797 D lights.sony: set_speaker_light_locked mode 1 colorRGB=4294901760 onMS=125 offMS=2875 result: 1
06-26 22:57:50.744 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_exported_index ON "message" (exported)
06-26 22:57:51.042 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_id_type_payment_transactions_index ON "message" (_id, type) WHERE type & 12884901888 != 0
06-26 22:57:51.135 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_thread_story_parent_story_scheduled_date_latest_revision_id_index ON message (thread_id, date_received, story_type, parent_story_id, scheduled_date, latest_revision_id)
06-26 22:57:51.451 25251 25321 D V185_MessageRecipientsA: Executing: CREATE TRIGGER message_ai AFTER INSERT ON message BEGIN
06-26 22:57:51.451 25251 25321 D V185_MessageRecipientsA:         INSERT INTO message_fts(rowid, body, thread_id) VALUES (new._id, new.body, new.thread_id);
06-26 22:57:51.451 25251 25321 D V185_MessageRecipientsA:       END
06-26 22:57:51.454 25251 25321 D V185_MessageRecipientsA: Executing: CREATE TRIGGER message_ad AFTER DELETE ON message BEGIN
06-26 22:57:51.454 25251 25321 D V185_MessageRecipientsA:         INSERT INTO message_fts(message_fts, rowid, body, thread_id) VALUES ('delete', old._id, old.body, old.thread_id);
06-26 22:57:51.454 25251 25321 D V185_MessageRecipientsA:       END
06-26 22:57:51.458 25251 25321 D V185_MessageRecipientsA: Executing: CREATE TRIGGER message_au AFTER UPDATE ON message BEGIN
06-26 22:57:51.458 25251 25321 D V185_MessageRecipientsA:         INSERT INTO message_fts(message_fts, rowid, body, thread_id) VALUES('delete', old._id, old.body, old.thread_id);
06-26 22:57:51.458 25251 25321 D V185_MessageRecipientsA:         INSERT INTO message_fts(rowid, body, thread_id) VALUES (new._id, new.body, new.thread_id);
06-26 22:57:51.458 25251 25321 D V185_MessageRecipientsA:       END
06-26 22:57:51.462 25251 25321 D V185_MessageRecipientsA: Executing: CREATE INDEX message_quote_id_quote_author_scheduled_date_index ON message (quote_id, quote_author, scheduled_date)
06-26 22:57:51.711 25251 25321 D V185_MessageRecipientsA: Executing: CREATE TRIGGER msl_message_delete AFTER DELETE ON message 
06-26 22:57:51.711 25251 25321 D V185_MessageRecipientsA:         BEGIN 
06-26 22:57:51.711 25251 25321 D V185_MessageRecipientsA:           DELETE FROM msl_payload WHERE _id IN (SELECT payload_id FROM msl_message WHERE message_id = old._id);
06-26 22:57:51.711 25251 25321 D V185_MessageRecipientsA:         END
06-26 22:57:51.900 25251 25321 D V185_MessageRecipientsA: [migration] get-self: 29  drop-dependents: 214  create-table: 3  copy-data: 648  update-data: 262  drop-old-table: 176  rename-table: 15  recreate-dependents: 2658  fk-check: 186  total: 4191
06-26 22:57:53.555 25251 25321 D V186_ForeignKeyIndicesM: [migration] original_message_id: 211  latest_revision_id: 191  from_recipient_id: 218  to_recipient_id: 216  reaction_author: 10  message_fix: 271  analyze: 518  total: 1635
06-26 22:57:53.576 25251 25321 D V187_MoreForeignKeyInde: [migration] call_link: 4  call_peer: 1  dlist_member: 2  msl_payload: 10  total: 17
06-26 22:57:53.602 25251 25321 I V188_FixMessageRecipien: Already performed the migration! No need to do this.
06-26 22:57:53.817 25251 25321 E SQLiteLog: (267) statement aborts at 10: [WITH needs_update AS (
06-26 22:57:53.817 25251 25321 E SQLiteLog:         SELECT
06-26 22:57:53.817 25251 25321 E SQLiteLog:           _id
06-26 22:57:53.817 25251 25321 E SQLiteLog:         FROM
06-26 22:57:53.817 25251 25321 E SQLiteLog:           message M
06-26 22:57:53.817 25251 25321 E SQLiteLog:         WHERE
06-26 22:57:53.817 25251 25321 E SQLiteLog:           (
06-26 22:57:53.817 25251 25321 E SQLiteLog:             type & 262144 != 0
06-26 22:57:53.817 25251 25321 E SQLiteLog:             OR type & 268435456 != 0
06-26 22:57:53.817 25251 25321 E SQLiteLog:      
06-26 22:57:55.578   797   797 D lights.sony: setLight : Type::BATTERY
06-26 22:57:55.578  2025  2025 D VideoCall_LowBattery: disconnectVideoCalls on low battery
06-26 22:57:55.578  2025  2025 D VideoCall_LowBattery: disconnectVideoCalls 
06-26 22:57:55.578   797   797 D lights.sony: set_speaker_light_locked mode 1 colorRGB=4294901760 onMS=125 offMS=2875 result: 1
06-26 22:57:56.262 25251 25321 W crime.securesm: JNI critical lock held for 202.939ms on Thread[28,tid=25321,Runnable,Thread*=0x7b147e0000,peer=0x12f83800,"signal-bounded-1"]
06-26 22:57:56.472 25251 25321 W crime.securesm: JNI critical lock held for 199.148ms on Thread[28,tid=25321,Runnable,Thread*=0x7b147e0000,peer=0x12f83800,"signal-bounded-1"]
06-26 22:57:56.477 25251 25321 E SqlCipherErrorHandler: Database 'signal.db' corrupted!
06-26 22:57:56.478 25251 25321 E SqlCipherErrorHandler: [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null
06-26 22:57:56.478 25251 25321 E SqlCipherErrorHandler: Diagnostic results:
06-26 22:57:56.478 25251 25321 E SqlCipherErrorHandler:   ===== PRAGMA integrity_check (same-connection) =====
06-26 22:57:56.478 25251 25321 E SqlCipherErrorHandler: ok
06-26 22:57:56.478 25251 25321 E SqlCipherErrorHandler: 
06-26 22:57:56.478 25251 25321 E SqlCipherErrorHandler: ===== PRAGMA cipher_integrity_check (same-connection) =====
06-26 22:57:56.478 25251 25321 E SqlCipherErrorHandler: 
06-26 22:57:56.489 25251 25321 W SearchTable: [fullyResetTables] Dropping tables and triggers...
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler: Failed to clear full text search index.
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler: java.lang.IllegalStateException: getDatabase called recursively
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:318)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:278)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.getSignalWritableDatabase(SignalDatabase.kt:204)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.DatabaseTable.getWritableDatabase(DatabaseTable.java:91)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SearchTable.fullyResetTables(SearchTable.kt:236)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.attemptToClearFullTextSearchIndex(SqlCipherErrorHandler.kt:149)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:38)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:43)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:237)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:403)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:302)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.getRawReadableDatabase(SignalDatabase.kt:195)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase$Companion.hasTable(SignalDatabase.kt:311)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.hasTable(Unknown Source:2)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.JobDatabase.dropTableIfPresent(JobDatabase.java:377)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.JobDatabase.lambda$onOpen$0$org-thoughtcrime-securesms-database-JobDatabase(JobDatabase.java:148)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.JobDatabase$$ExternalSyntheticLambda7.run(Unknown Source:2)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at java.lang.Thread.run(Thread.java:919)
06-26 22:57:56.494 25251 25321 W SqlCipherErrorHandler:     at org.signal.core.util.concurrent.SignalExecutors$NumberedThreadFactory$1.run(SignalExecutors.java:109)
06-26 22:57:56.533 25251 25323 W crime.securesm: Long monitor contention with owner signal-bounded-1 (25321) at int net.zetetic.database.sqlcipher.SQLiteConnection.nativeExecuteForChangedRowCount(long, long)(SQLiteConnection.java:-2) waiters=0 in net.zetetic.database.sqlcipher.SQLiteDatabase net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase() for 16.520s
06-26 22:57:56.538 25251 25321 E AndroidRuntime: FATAL EXCEPTION: signal-bounded-1
06-26 22:57:56.538 25251 25321 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 25251
06-26 22:57:56.538 25251 25321 E AndroidRuntime: org.thoughtcrime.securesms.database.SqlCipherErrorHandler$DatabaseCorruptedError_BothChecksPass
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:39)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:43)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:237)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:403)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:302)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase.getRawReadableDatabase(SignalDatabase.kt:195)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase$Companion.hasTable(SignalDatabase.kt:311)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase.hasTable(Unknown Source:2)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.JobDatabase.dropTableIfPresent(JobDatabase.java:377)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.JobDatabase.lambda$onOpen$0$org-thoughtcrime-securesms-database-JobDatabase(JobDatabase.java:148)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.thoughtcrime.securesms.database.JobDatabase$$ExternalSyntheticLambda7.run(Unknown Source:2)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:919)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at org.signal.core.util.concurrent.SignalExecutors$NumberedThreadFactory$1.run(SignalExecutors.java:109)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at [[ ↑↑ Original Trace ↑↑ ]].(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at [[ ↓↓ Inferred Trace ↓↓ ]].(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at Database 'signal.db' corrupted!.(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null.(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at Diagnostics results:.(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at  ===== PRAGMA integrity_check (same-connection) =====.(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at ok.(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at .(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at ===== PRAGMA cipher_integrity_check (same-connection) =====.(:0)
06-26 22:57:56.538 25251 25321 E AndroidRuntime:    at .(:0)
06-26 22:57:56.540 25251 25323 I SQLiteConnection: Database keying operation returned:0
06-26 22:57:56.540 25251 25321 E SignalUncaughtException: 
06-26 22:57:56.540 25251 25321 E SignalUncaughtException: org.thoughtcrime.securesms.database.SqlCipherErrorHandler$DatabaseCorruptedError_BothChecksPass
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:39)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:43)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:237)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:403)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:302)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase.getRawReadableDatabase(SignalDatabase.kt:195)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase$Companion.hasTable(SignalDatabase.kt:311)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase.hasTable(Unknown Source:2)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.JobDatabase.dropTableIfPresent(JobDatabase.java:377)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.JobDatabase.lambda$onOpen$0$org-thoughtcrime-securesms-database-JobDatabase(JobDatabase.java:148)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.JobDatabase$$ExternalSyntheticLambda7.run(Unknown Source:2)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at java.lang.Thread.run(Thread.java:919)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at org.signal.core.util.concurrent.SignalExecutors$NumberedThreadFactory$1.run(SignalExecutors.java:109)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at [[ ↑↑ Original Trace ↑↑ ]].(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at [[ ↓↓ Inferred Trace ↓↓ ]].(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at Database 'signal.db' corrupted!.(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null.(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at Diagnostics results:.(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at  ===== PRAGMA integrity_check (same-connection) =====.(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at ok.(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at .(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at ===== PRAGMA cipher_integrity_check (same-connection) =====.(:0)
06-26 22:57:56.540 25251 25321 E SignalUncaughtException:   at .(:0)
06-26 22:57:56.548 25251 25336 D StorageSyncHelper: Scheduling a sync. Last sync was 12925113 ms ago.
derMart commented 1 year ago

This might also be an import / export problem. I have made stock encrypted backups before the upgrade. Now as upgrade did not work, I cleaned the app data, deinstalled the app and tried an import of a previously exported backup. Tried v6.24.3.0-JW as well as the stock v6.22.8 (git tag). Both crash, with the latter I get:

06-27 09:51:35.734  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_read_and_notified_and_thread_id_index
06-27 09:51:35.740  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_type_index
06-27 09:51:35.747  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_date_sent_index
06-27 09:51:35.758  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_date_server_index
06-27 09:51:35.764  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_thread_date_index
06-27 09:51:35.773  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_reactions_unread_index
06-27 09:51:35.778  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_story_type_index
06-27 09:51:35.783  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_parent_story_id_index
06-27 09:51:35.787  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_exported_index
06-27 09:51:35.794  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_id_type_payment_transactions_index
06-27 09:51:35.795  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_thread_story_parent_story_scheduled_date_index
06-27 09:51:35.805  5959  6034 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS message_ai
06-27 09:51:35.805  5959  6034 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS message_ad
06-27 09:51:35.805  5959  6034 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS message_au
06-27 09:51:35.806  5959  6034 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS message_quote_id_quote_author_scheduled_date_index
06-27 09:51:35.812  5959  6034 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS msl_message_delete
06-27 09:51:36.260  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_read_and_notified_and_thread_id_index ON "message"(read, notified, thread_id)
06-27 09:51:36.358  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_type_index ON "message" (type)
06-27 09:51:36.427  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_date_sent_from_to_thread_index ON message (date_sent, from_recipient_id, to_recipient_id, thread_id)
06-27 09:51:36.502  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_date_server_index ON "message" (date_server)
06-27 09:51:36.570  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_thread_date_index ON "message" (thread_id, date_received)
06-27 09:51:36.652  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_reactions_unread_index ON "message" (reactions_unread)
06-27 09:51:36.719  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_story_type_index ON "message" (story_type)
06-27 09:51:36.787  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_parent_story_id_index ON "message" (parent_story_id)
06-27 09:51:36.856  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_exported_index ON "message" (exported)
06-27 09:51:36.924  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_id_type_payment_transactions_index ON "message" (_id, type) WHERE type & 12884901888 != 0
06-27 09:51:36.958  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_thread_story_parent_story_scheduled_date_latest_revision_id_index ON message (thread_id, date_received, story_type, parent_story_id, scheduled_date, latest_revision_id)
06-27 09:51:37.065  5959  6034 D V188_FixMessageRecipien: Executing: CREATE TRIGGER message_ai AFTER INSERT ON message BEGIN
06-27 09:51:37.065  5959  6034 D V188_FixMessageRecipien:         INSERT INTO message_fts(rowid, body, thread_id) VALUES (new._id, new.body, new.thread_id);
06-27 09:51:37.065  5959  6034 D V188_FixMessageRecipien:       END
06-27 09:51:37.065  5959  6034 D V188_FixMessageRecipien: Executing: CREATE TRIGGER message_ad AFTER DELETE ON message BEGIN
06-27 09:51:37.065  5959  6034 D V188_FixMessageRecipien:         INSERT INTO message_fts(message_fts, rowid, body, thread_id) VALUES ('delete', old._id, old.body, old.thread_id);
06-27 09:51:37.065  5959  6034 D V188_FixMessageRecipien:       END
06-27 09:51:37.066  5959  6034 D V188_FixMessageRecipien: Executing: CREATE TRIGGER message_au AFTER UPDATE ON message BEGIN
06-27 09:51:37.066  5959  6034 D V188_FixMessageRecipien:         INSERT INTO message_fts(message_fts, rowid, body, thread_id) VALUES('delete', old._id, old.body, old.thread_id);
06-27 09:51:37.066  5959  6034 D V188_FixMessageRecipien:         INSERT INTO message_fts(rowid, body, thread_id) VALUES (new._id, new.body, new.thread_id);
06-27 09:51:37.066  5959  6034 D V188_FixMessageRecipien:       END
06-27 09:51:37.066  5959  6034 D V188_FixMessageRecipien: Executing: CREATE INDEX message_quote_id_quote_author_scheduled_date_index ON message (quote_id, quote_author, scheduled_date)
06-27 09:51:37.159  5959  6034 D V188_FixMessageRecipien: Executing: CREATE TRIGGER msl_message_delete AFTER DELETE ON message 
06-27 09:51:37.159  5959  6034 D V188_FixMessageRecipien:         BEGIN 
06-27 09:51:37.159  5959  6034 D V188_FixMessageRecipien:           DELETE FROM msl_payload WHERE _id IN (SELECT payload_id FROM msl_message WHERE message_id = old._id);
06-27 09:51:37.159  5959  6034 D V188_FixMessageRecipien:         END
06-27 09:51:37.602  5959  6034 D V188_FixMessageRecipien: [migration] get-self: 22  drop-dependents: 80  create-table: 1  copy-data: 246  update-data: 122  drop-old-table: 73  rename-table: 5  recreate-dependents: 901  v186-indexes: 381  fk-check: 61  total: 1892
06-27 09:51:37.661  5959  6034 E SQLiteLog: (267) statement aborts at 10: [WITH needs_update AS (
06-27 09:51:37.661  5959  6034 E SQLiteLog:         SELECT
06-27 09:51:37.661  5959  6034 E SQLiteLog:           _id
06-27 09:51:37.661  5959  6034 E SQLiteLog:         FROM
06-27 09:51:37.661  5959  6034 E SQLiteLog:           message M
06-27 09:51:37.661  5959  6034 E SQLiteLog:         WHERE
06-27 09:51:37.661  5959  6034 E SQLiteLog:           (
06-27 09:51:37.661  5959  6034 E SQLiteLog:             type & 262144 != 0
06-27 09:51:37.661  5959  6034 E SQLiteLog:             OR type & 268435456 != 0
06-27 09:51:37.661  5959  6034 E SQLiteLog:      
06-27 09:51:38.579  5959  6034 W crime.securesm: JNI critical lock held for 56.899ms on Thread[50,tid=6034,Runnable,Thread*=0x71081d6400,peer=0x13a00000,"AsyncTask #1"]
06-27 09:51:38.636  5959  6034 W crime.securesm: JNI critical lock held for 56.337ms on Thread[50,tid=6034,Runnable,Thread*=0x71081d6400,peer=0x13a00000,"AsyncTask #1"]
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: Database 'signal.db' corrupted!
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: Diagnostic results:
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler:   ===== PRAGMA integrity_check (same-connection) =====
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: ok
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: 
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: ===== PRAGMA cipher_integrity_check (same-connection) =====
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: 
06-27 09:51:38.639  5959  6034 W SearchTable: [fullyResetTables] Dropping tables and triggers...
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler: Failed to clear full text search index.
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler: android.database.sqlite.SQLiteException: Cannot execute this statement because it might modify the database but the connection is read-only.
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteConnection.throwIfStatementForbidden(SQLiteConnection.java:1061)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteConnection.executeForChangedRowCount(SQLiteConnection.java:765)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteSession.executeForChangedRowCount(SQLiteSession.java:758)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:71)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase.lambda$execSQL$17$org-thoughtcrime-securesms-database-SQLiteDatabase(SQLiteDatabase.java:406)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase$$ExternalSyntheticLambda14.run(Unknown Source:4)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase.traceSql(SQLiteDatabase.java:86)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase.execSQL(SQLiteDatabase.java:406)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SearchTable.fullyResetTables(SearchTable.kt:241)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.attemptToClearFullTextSearchIndex(SqlCipherErrorHandler.kt:149)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:38)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:43)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:236)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase$Companion.runPostBackupRestoreTasks(SignalDatabase.kt:287)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.runPostBackupRestoreTasks(Unknown Source:2)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:294)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:279)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at android.os.AsyncTask$3.call(AsyncTask.java:378)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:289)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-27 09:51:38.643  5959  6034 W SqlCipherErrorHandler:     at java.lang.Thread.run(Thread.java:919)
--------- beginning of crash
06-27 09:51:38.645  5959  6034 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #1
06-27 09:51:38.645  5959  6034 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 5959
06-27 09:51:38.645  5959  6034 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at android.os.AsyncTask$4.done(AsyncTask.java:399)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:383)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.FutureTask.setException(FutureTask.java:252)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:271)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:289)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:919)
06-27 09:51:38.645  5959  6034 E AndroidRuntime: Caused by: org.thoughtcrime.securesms.database.SqlCipherErrorHandler$DatabaseCorruptedError_BothChecksPass
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:39)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:43)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:236)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase$Companion.runPostBackupRestoreTasks(SignalDatabase.kt:287)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase.runPostBackupRestoreTasks(Unknown Source:2)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:294)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:279)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at android.os.AsyncTask$3.call(AsyncTask.java:378)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:289)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:919)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at [[ ↑↑ Original Trace ↑↑ ]].(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at [[ ↓↓ Inferred Trace ↓↓ ]].(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at Database 'signal.db' corrupted!.(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null.(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at Diagnostics results:.(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at  ===== PRAGMA integrity_check (same-connection) =====.(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at ok.(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at .(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at ===== PRAGMA cipher_integrity_check (same-connection) =====.(:0)
06-27 09:51:38.645  5959  6034 E AndroidRuntime:    at .(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException: 
06-27 09:51:38.646  5959  6034 E SignalUncaughtException: java.lang.RuntimeException: An error occurred while executing doInBackground()
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at android.os.AsyncTask$4.done(AsyncTask.java:399)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:383)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.FutureTask.setException(FutureTask.java:252)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.FutureTask.run(FutureTask.java:271)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:289)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.lang.Thread.run(Thread.java:919)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException: Caused by: org.thoughtcrime.securesms.database.SqlCipherErrorHandler$DatabaseCorruptedError_BothChecksPass
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:39)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:43)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:236)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase$Companion.runPostBackupRestoreTasks(SignalDatabase.kt:287)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase.runPostBackupRestoreTasks(Unknown Source:2)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:294)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:279)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at android.os.AsyncTask$3.call(AsyncTask.java:378)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.FutureTask.run(FutureTask.java:266)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:289)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at java.lang.Thread.run(Thread.java:919)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at [[ ↑↑ Original Trace ↑↑ ]].(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at [[ ↓↓ Inferred Trace ↓↓ ]].(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at Database 'signal.db' corrupted!.(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null.(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at Diagnostics results:.(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at  ===== PRAGMA integrity_check (same-connection) =====.(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at ok.(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at .(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at ===== PRAGMA cipher_integrity_check (same-connection) =====.(:0)
06-27 09:51:38.646  5959  6034 E SignalUncaughtException:   at .(:0)
06-27 09:51:38.671  5959  6034 I JobManager: Successfully flushed.

Will now try stock v6.14.5

derMart commented 1 year ago

Ok import in stock v6.14.5 is working. So definitively not a corrupted backup but a migration bug. Trying to bisect a bit.

derMart commented 1 year ago

This seems to be a problem inside V191_UniqueMessageMigrationV2.kt: https://github.com/signalapp/Signal-Android/blob/6cc8e87d46f82092dee3d474fe8294cdc4760624/app/src/main/java/org/thoughtcrime/securesms/database/helpers/migration/V191_UniqueMessageMigrationV2.kt#L43-L74

Related to that commit https://github.com/signalapp/Signal-Android/commit/9ba2724d0a36a01660edf8f229ff7c78cb9376c9 V191 seems to be a replacement for V190 migration, which was also buggy. @greyson-signal Do you have any clue what might be the cause of this issue here? Issue possibly related to this output coming from V191:

06-27 09:51:37.661  5959  6034 E SQLiteLog: (267) statement aborts at 10: [WITH needs_update AS (
06-27 09:51:37.661  5959  6034 E SQLiteLog:         SELECT
06-27 09:51:37.661  5959  6034 E SQLiteLog:           _id
06-27 09:51:37.661  5959  6034 E SQLiteLog:         FROM
06-27 09:51:37.661  5959  6034 E SQLiteLog:           message M
06-27 09:51:37.661  5959  6034 E SQLiteLog:         WHERE
06-27 09:51:37.661  5959  6034 E SQLiteLog:           (
06-27 09:51:37.661  5959  6034 E SQLiteLog:             type & 262144 != 0
06-27 09:51:37.661  5959  6034 E SQLiteLog:             OR type & 268435456 != 0
06-27 09:51:37.661  5959  6034 E SQLiteLog:

EDIT: Might this be some timing / operation pending issues? (https://stackoverflow.com/questions/35219579/sqlite-statement-aborts-database-locked-in-android-app)

derMart commented 1 year ago

Wrapping my head around this issue...

06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: Database 'signal.db' corrupted!
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: Diagnostic results:
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler:   ===== PRAGMA integrity_check (same-connection) =====
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler: ok
06-27 09:51:38.637  5959  6034 E SqlCipherErrorHandler:

At first it seems the database is corrupt when running V191 sql statement, but PRAGMA integrity_check returns ok. I extracted the raw sqlite database from the backup I am trying to restore via the excellent and very useful tool signalbackup-tools. Opens fine in sqlite explorer, no issues looking at tables etc. Also running PRAGMA integrity_check there is ok. So the db trying to be imported is ok, but while running an sql query on that db it gets corrupted ... ? This is starting to smell like a problem in SQLChipher or even the underlying sqlite library, which would both be devastating.

It gets even funnier, if I try to import the very same backup into 3 versions of Signal. v6.14.4 -> everything ok v6.16.2:

06-30 15:18:20.749   721   721 I QNS     : QNS: requested charging params: current: 650, voltage: 4350
06-30 15:18:20.773 20317 20397 D V166_ThreadAndMessageFo: [migration] thread-dupes: 3  thread-schema: 15  sms-dangling: 50  mms-dangling: 12  sms-schema: 586  mms-schema: 287  total: 953
06-30 15:18:21.914 20317 20397 D V168_SingleMessageTable: [migration] next-id: 1  drop-triggers: 28  drop-mms-indexes: 18  copy-sms: 158  drop-sms: 78  rebuild-indexes: 834  update-reactions: 5  update-msl: 4  total: 1126
06-30 15:18:21.953 20317 20397 D V171_ThreadForeignKeyFi: [migration] thread-dupes: 2  thread-schema: 14  total: 16
06-30 15:18:22.261 20317 20397 I V181_ThreadTableForeign: Deleted 0 threads.
06-30 15:18:22.261 20317 20397 W V181_ThreadTableForeign: No threads deleted. Finishing early.
06-30 15:18:22.261 20317 20397 D V181_ThreadTableForeign: [deletes] threads: 1  
06-30 15:18:23.133 20317 20397 I SignalDatabase: Upgrade complete. Took 3439 ms.
06-30 15:18:23.135 20317 20397 W crime.securesm: Accessing hidden method Lsun/misc/Unsafe;->getObject(Ljava/lang/Object;J)Ljava/lang/Object; (greylist, linking, allowed)
06-30 15:18:23.242 20317 20397 W SearchTable: [fullyResetTables] Dropping tables and triggers...
06-30 15:18:23.246 20317 20397 W SearchTable: [fullyResetTables] Recreating table...
06-30 15:18:23.248 20317 20397 W SearchTable: [fullyResetTables] Recreating triggers...
06-30 15:18:23.250 20317 20397 W crime.securesm: Accessing hidden method Lsun/misc/Unsafe;->compareAndSwapObject(Ljava/lang/Object;JLjava/lang/Object;Ljava/lang/Object;)Z (greylist, linking, allowed)
06-30 15:18:23.256 20317 20397 I Job     : [JOB::eaa52fd1-dfe4-4bad-9936-a3bc320e8796][RebuildMessageSearchIndexJob] onSubmit() (Time Since Submission: 6 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: RebuildMessageSearchIndex)
06-30 15:18:23.256 20317 20397 W SearchTable: [fullyResetTables] Done. Index will be rebuilt asynchronously)
06-30 15:18:23.258 20317 20369 I JobSchedulerScheduler: JobScheduler enqueue of  (0)
06-30 15:18:23.261 20317 20382 I JobRunner: [JOB::eaa52fd1-dfe4-4bad-9936-a3bc320e8796][RebuildMessageSearchIndexJob][3] Running job. (Time Since Submission: 10 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: RebuildMessageSearchIndex)
06-30 15:18:23.263 20317 20317 I JobSchedulerScheduler: Waking due to job: 0
06-30 15:18:23.265 20317 20382 I SearchTable: Re-indexing. Operating on ID's 1-40433 in steps of 10000.
06-30 15:18:23.265 20317 20382 I SearchTable: Reindexing ID's [1, 10001)
06-30 15:18:23.267 20317 20382 E BaseJob : Encountered a fatal exception. Crash imminent.
06-30 15:18:23.267 20317 20382 E BaseJob : java.lang.IllegalStateException: attempt to re-open an already-closed object: SQLiteDatabase: /data/user/0/org.thoughtcrime.securesms/databases/signal.db
06-30 15:18:23.267 20317 20382 E BaseJob :  at net.zetetic.database.sqlcipher.SQLiteClosable.acquireReference(SQLiteClosable.java:59)
06-30 15:18:23.267 20317 20382 E BaseJob :  at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1977)
06-30 15:18:23.267 20317 20382 E BaseJob :  at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1901)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.database.SQLiteDatabase.lambda$execSQL$17$org-thoughtcrime-securesms-database-SQLiteDatabase(SQLiteDatabase.java:405)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.database.SQLiteDatabase$$ExternalSyntheticLambda14.run(Unknown Source:4)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.database.SQLiteDatabase.traceSql(SQLiteDatabase.java:86)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.database.SQLiteDatabase.execSQL(SQLiteDatabase.java:405)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.database.SearchTable.rebuildIndex(SearchTable.kt:142)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.database.SearchTable.rebuildIndex$default(SearchTable.kt:135)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.jobs.RebuildMessageSearchIndexJob.onRun(RebuildMessageSearchIndexJob.kt:34)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.jobs.BaseJob.run(BaseJob.java:31)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:86)
06-30 15:18:23.267 20317 20382 E BaseJob :  at org.thoughtcrime.securesms.jobmanager.JobRunner.run(JobRunner.java:49)
06-30 15:18:23.268 20317 20382 E JobRunner: [JOB::eaa52fd1-dfe4-4bad-9936-a3bc320e8796][RebuildMessageSearchIndexJob][3] Job failed with a fatal exception. Crash imminent. (Time Since Submission: 17 ms, Lifespan: Immortal, Run Attempt: 1/1, Queue: RebuildMessageSearchIndex)

So here, V171 runs through, but one of the index rebuilders is complaining after the import, that the db somehow was closed.

v6.20.0:

06-30 12:26:36.397 16854 16934 D V166_ThreadAndMessageFo: [migration] thread-dupes: 1  thread-schema: 15  sms-dangling: 52  mms-dangling: 13  sms-schema: 621  mms-schema: 411  total: 1113
06-30 12:26:37.594 16854 16934 D V168_SingleMessageTable: [migration] next-id: 1  drop-triggers: 28  drop-mms-indexes: 20  copy-sms: 201  drop-sms: 76  rebuild-indexes: 846  update-reactions: 6  update-msl: 4  total: 1182
06-30 12:26:40.174 16854 16934 E SQLiteLog: (267) statement aborts at 10: [DROP TABLE thread] database disk image is malformed
06-30 12:26:40.926 16854 16934 W crime.securesm: JNI critical lock held for 58.111ms on Thread[54,tid=16934,Runnable,Thread*=0x73d5eb9800,peer=0x139c41b0,"AsyncTask #2"]
06-30 12:26:40.958  2025  2025 D VideoCall_LowBattery: disconnectVideoCalls on low battery
06-30 12:26:40.958  2025  2025 D VideoCall_LowBattery: disconnectVideoCalls 
06-30 12:26:40.959   788   788 D lights.sony: setLight : Type::BATTERY
06-30 12:26:40.960   788   788 D lights.sony: set_speaker_light_locked mode 0 colorRGB=4294967040 onMS=0 offMS=0 result: 1
06-30 12:26:40.985 16854 16934 W crime.securesm: JNI critical lock held for 56.391ms on Thread[54,tid=16934,Runnable,Thread*=0x73d5eb9800,peer=0x139c41b0,"AsyncTask #2"]
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler: Database 'signal.db' corrupted!
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler: [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler: Diagnostic results:
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler:   ===== PRAGMA integrity_check (same-connection) =====
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler: ok
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler: 
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler: ===== PRAGMA cipher_integrity_check (same-connection) =====
06-30 12:26:40.986 16854 16934 E SqlCipherErrorHandler:

Here, V171 is not running through. How can this happen?

What also puzzles me is that the export I got is from v6.14.x-JW. This should have DB version 180, but it hasn't. It is 157. Is it possible that exports do somehow not write the correct DB version out?

derMart commented 1 year ago

I was able to get the import working in v6.16.2 by reducing the size of the backup, replacing image/video attachments with placeholders. Although this is totally unrelated to the exceptions, as the db basically stays the same (attachments are stored separately as files, not inside the sqlite db) it went through.

I bisected down the problem regarding V171 (at least) to occur with v6.19.0, in v6.18.4 the import finishes without errors. Still clueless what could cause these issues, seems more and more to be related to SqlCipher IMHO...

GraphiteSprite commented 1 year ago

Did any of the versions you used work with your original backup file, or did you only get it working using the edited backup exported from signalbackup-tools ? I'm having a similar issue; crashed after trying to update, now won't restore from backup. Would you mind pointing to where to find a safe apk of the older version that worked for you as I'd be grateful to try that as an interim measure as well :pray:

GraphiteSprite commented 1 year ago

I have version 6.24.4 and got this in the log when I was able to produce one:


 --------- beginning of crash
06-30 06:34:12.390 13800 13960 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #2
06-30 06:34:12.390 13800 13960 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 13800
06-30 06:34:12.390 13800 13960 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at android.os.AsyncTask$4.done(AsyncTask.java:415)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:381)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at java.util.concurrent.FutureTask.setException(FutureTask.java:250)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:269)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:305)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:1012)
06-30 06:34:12.390 13800 13960 E AndroidRuntime: Caused by: java.lang.IllegalStateException: Foreign Key Constraints cannot be enabled or disabled while there are transactions in progress.  Finish all transactions and release all active database connections first.
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteConnectionPool.reconfigure(SQLiteConnectionPool.java:291)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.setForeignKeyConstraintsEnabled(SQLiteDatabase.java:2177)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:123)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:71)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:292)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:282)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at android.os.AsyncTask$3.call(AsyncTask.java:394)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:264)
06-30 06:34:12.390 13800 13960 E AndroidRuntime:    ... 4 more
06-30 06:34:12.391 13800 13960 E SignalUncaughtException: java.lang.RuntimeException: An error occurred while executing doInBackground()
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at android.os.AsyncTask$4.done(AsyncTask.java:415)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:381)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at java.util.concurrent.FutureTask.setException(FutureTask.java:250)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at java.util.concurrent.FutureTask.run(FutureTask.java:269)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:305)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at java.lang.Thread.run(Thread.java:1012)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException: Caused by: java.lang.IllegalStateException: Foreign Key Constraints cannot be enabled or disabled while there are transactions in progress.  Finish all transactions and release all active database connections first.
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteConnectionPool.reconfigure(SQLiteConnectionPool.java:291)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.setForeignKeyConstraintsEnabled(SQLiteDatabase.java:2177)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:123)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:71)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:292)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:282)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at android.os.AsyncTask$3.call(AsyncTask.java:394)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   at java.util.concurrent.FutureTask.run(FutureTask.java:264)
06-30 06:34:12.391 13800 13960 E SignalUncaughtException:   ... 4 more`

Is this issue similar to the one mentioned here: https://github.com/signalapp/Signal-Android/issues/12992

or is it different?

derMart commented 1 year ago

@GraphiteSprite My comment above (https://github.com/signalapp/Signal-Android/issues/13034#issuecomment-1614852940) I have run the tests on the phone with the original backup files. So yes, I have tested it working until v6.14.4. Up to v6.18.4 it works at least with the replaced attachments.

As for your issue, it looks similar to https://github.com/signalapp/Signal-Android/issues/12992, so it might be good to discuss your instance of the problem there, as this is also still an open issue and to not mix supposedly unrelated issues.

simmac commented 1 year ago

I'm experiencing the same issue, both on a Nokia 7 Plus running Android 10 and a Pixel 6a running Android 13.

This also occurs when restoring an old backup file (original and "fixed" by signalbackup-tools)

clark-signal commented 1 year ago

Are you able to reproduce on 6.26.2 (or 6.25.5)

zoickx commented 1 year ago

Same issue here, trying to restore an old backup (unfortunately not sure which version of Signal exactly, but it will have been around 6.4 by date).

Importing into Signal 6.26.4.

Running the file through signalbackup-tools does not help.

Logcat:

07-27 12:12:24.079 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_read_and_notified_and_thread_id_index
07-27 12:12:24.092 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_type_index
07-27 12:12:24.108 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_date_sent_index
07-27 12:12:24.129 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_date_server_index
07-27 12:12:24.142 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_thread_date_index
07-27 12:12:24.161 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_reactions_unread_index
07-27 12:12:24.173 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_story_type_index
07-27 12:12:24.184 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_parent_story_id_index
07-27 12:12:24.195 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_exported_index
07-27 12:12:24.207 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_id_type_payment_transactions_index
07-27 12:12:24.207 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS mms_thread_story_parent_story_scheduled_date_index
07-27 12:12:24.228 25869 25972 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS message_ai
07-27 12:12:24.228 25869 25972 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS message_ad
07-27 12:12:24.229 25869 25972 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS message_au
07-27 12:12:24.229 25869 25972 D V188_FixMessageRecipien: Executing: DROP index IF EXISTS message_quote_id_quote_author_scheduled_date_index
07-27 12:12:24.242 25869 25972 D V188_FixMessageRecipien: Executing: DROP trigger IF EXISTS msl_message_delete
07-27 12:12:25.216 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_read_and_notified_and_thread_id_index ON "message"(read, notified, thread_id)
07-27 12:12:25.412 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_type_index ON "message" (type)
07-27 12:12:25.580 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_date_sent_from_to_thread_index ON message (date_sent, from_recipient_id, to_recipient_id, thread_id)
07-27 12:12:25.763 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_date_server_index ON "message" (date_server)
07-27 12:12:25.914 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_thread_date_index ON "message" (thread_id, date_received)
07-27 12:12:26.122 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_reactions_unread_index ON "message" (reactions_unread)
07-27 12:12:26.255 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_story_type_index ON "message" (story_type)
07-27 12:12:26.390 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_parent_story_id_index ON "message" (parent_story_id)
07-27 12:12:26.527 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_exported_index ON "message" (exported)
07-27 12:12:26.654 25869 25956 D MemoryTracker: Used memory has decreased from 92535200 (88.25 MiB) to 79614368 (75.93 MiB)
07-27 12:12:26.665 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_id_type_payment_transactions_index ON "message" (_id, type) WHERE type & 12884901888 != 0
07-27 12:12:26.726 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_thread_story_parent_story_scheduled_date_latest_revision_id_index ON message (thread_id, date_received, story_type, parent_story_id, scheduled_date, latest_revision_id)
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien: Executing: CREATE TRIGGER message_ai AFTER INSERT ON message BEGIN
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien:         INSERT INTO message_fts(rowid, body, thread_id) VALUES (new._id, new.body, new.thread_id);
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien:       END
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien: Executing: CREATE TRIGGER message_ad AFTER DELETE ON message BEGIN
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien:         INSERT INTO message_fts(message_fts, rowid, body, thread_id) VALUES ('delete', old._id, old.body, old.thread_id);
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien:       END
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien: Executing: CREATE TRIGGER message_au AFTER UPDATE ON message BEGIN
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien:         INSERT INTO message_fts(message_fts, rowid, body, thread_id) VALUES('delete', old._id, old.body, old.thread_id);
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien:         INSERT INTO message_fts(rowid, body, thread_id) VALUES (new._id, new.body, new.thread_id);
07-27 12:12:27.002 25869 25972 D V188_FixMessageRecipien:       END
07-27 12:12:27.003 25869 25972 D V188_FixMessageRecipien: Executing: CREATE INDEX message_quote_id_quote_author_scheduled_date_index ON message (quote_id, quote_author, scheduled_date)
07-27 12:12:27.228 25869 25972 D V188_FixMessageRecipien: Executing: CREATE TRIGGER msl_message_delete AFTER DELETE ON message 
07-27 12:12:27.228 25869 25972 D V188_FixMessageRecipien:         BEGIN 
07-27 12:12:27.228 25869 25972 D V188_FixMessageRecipien:           DELETE FROM msl_payload WHERE _id IN (SELECT payload_id FROM msl_message WHERE message_id = old._id);
07-27 12:12:27.228 25869 25972 D V188_FixMessageRecipien:         END
07-27 12:12:27.670 25869 25869 D LoggingFragment: [RestoreBackupFragment] onStop()
07-27 12:12:27.672 25869 25869 D LoggingFragment: [EnterPhoneNumberFragmen] onCreate()
07-27 12:12:27.720 25869 25869 W InputMethodManager: Ignoring showSoftInput() as view=com.google.android.material.textfield.TextInputEditText{678cb9c VFED..CL. .F....I. 0,0-0,0} is not served.
07-27 12:12:27.720 25869 25869 D LoggingFragment: [EnterPhoneNumberFragmen] onStart()
07-27 12:12:27.756 25869 25869 I AssistStructure: Flattened final assist data: 3368 bytes, containing 1 windows, 23 views
07-27 12:12:27.880 25869 25869 D LoggingFragment: [RestoreBackupFragment] onDestroy()
07-27 12:12:28.180 25869 25972 D V188_FixMessageRecipien: [migration] get-self: 27  drop-dependents: 164  create-table: 0  copy-data: 531  update-data: 298  drop-old-table: 141  rename-table: 3  recreate-dependents: 2014  v186-indexes: 857  fk-check: 94  total: 4129
07-27 12:12:28.256 25869 25972 E SQLiteLog: (267) statement aborts at 10: [WITH needs_update AS (
07-27 12:12:28.256 25869 25972 E SQLiteLog:         SELECT
07-27 12:12:28.256 25869 25972 E SQLiteLog:           _id
07-27 12:12:28.256 25869 25972 E SQLiteLog:         FROM
07-27 12:12:28.256 25869 25972 E SQLiteLog:           message M
07-27 12:12:28.256 25869 25972 E SQLiteLog:         WHERE
07-27 12:12:28.256 25869 25972 E SQLiteLog:           (
07-27 12:12:28.256 25869 25972 E SQLiteLog:             type & 262144 != 0
07-27 12:12:28.256 25869 25972 E SQLiteLog:             OR type & 268435456 != 0
07-27 12:12:28.256 25869 25972 E SQLiteLog:      
07-27 12:12:29.552 25869 25869 D InputMethodManager: showSoftInput() view=com.google.android.material.textfield.TextInputEditText{678cb9c VFED..CL. .F.P.... 0,0-902,195 aid=1073741860} flags=0 reason=SHOW_SOFT_INPUT
07-27 12:12:29.608 25869 25869 D InsetsController: show(ime(), fromIme=true)
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler: Database 'signal.db' corrupted!
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler: [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler: Diagnostic results:
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler:   ===== PRAGMA integrity_check (same-connection) =====
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler: ok
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler: 
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler: ===== PRAGMA cipher_integrity_check (same-connection) =====
07-27 12:12:30.528 25869 25972 E SqlCipherErrorHandler: 
07-27 12:12:30.530 25869 25972 W SearchTable: [fullyResetTables] Dropping tables and triggers...
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler: Failed to clear full text search index.
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler: android.database.sqlite.SQLiteException: Cannot execute this statement because it might modify the database but the connection is read-only.
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteConnection.throwIfStatementForbidden(SQLiteConnection.java:1061)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteConnection.executeForChangedRowCount(SQLiteConnection.java:765)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteSession.executeForChangedRowCount(SQLiteSession.java:758)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:71)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase.lambda$execSQL$17(SQLiteDatabase.java:406)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase.$r8$lambda$s4XtpDmp0hr2or-DcGqtIyQgI2k(SQLiteDatabase.java:0)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase$$ExternalSyntheticLambda22.run(R8$$SyntheticClass:0)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase.traceSql(SQLiteDatabase.java:86)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SQLiteDatabase.execSQL(SQLiteDatabase.java:406)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SearchTable.fullyResetTables(SearchTable.kt:243)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.attemptToClearFullTextSearchIndex(SqlCipherErrorHandler.kt:150)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:39)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:44)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:238)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase$Companion.runPostBackupRestoreTasks(SignalDatabase.kt:287)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.database.SignalDatabase.runPostBackupRestoreTasks(SignalDatabase.kt:0)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:298)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:282)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at android.os.AsyncTask$3.call(AsyncTask.java:394)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at java.util.concurrent.FutureTask.run(FutureTask.java:264)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:305)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
07-27 12:12:30.534 25869 25972 W SqlCipherErrorHandler:     at java.lang.Thread.run(Thread.java:1012)
07-27 12:12:30.534 25869 25972 I JobManager: onConstraintMet(DataRestoreConstraint)
--------- beginning of crash
07-27 12:12:30.535 25869 25972 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #2
07-27 12:12:30.535 25869 25972 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 25869
07-27 12:12:30.535 25869 25972 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at android.os.AsyncTask$4.done(AsyncTask.java:415)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:381)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.FutureTask.setException(FutureTask.java:250)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:269)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:305)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:1012)
07-27 12:12:30.535 25869 25972 E AndroidRuntime: Caused by: org.thoughtcrime.securesms.database.SqlCipherErrorHandler$DatabaseCorruptedError_BothChecksPass
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:40)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:44)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:238)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase$Companion.runPostBackupRestoreTasks(SignalDatabase.kt:287)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.database.SignalDatabase.runPostBackupRestoreTasks(SignalDatabase.kt:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:298)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:282)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at android.os.AsyncTask$3.call(AsyncTask.java:394)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.FutureTask.run(FutureTask.java:264)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:305)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at java.lang.Thread.run(Thread.java:1012)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at [[ ↑↑ Original Trace ↑↑ ]].(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at [[ ↓↓ Inferred Trace ↓↓ ]].(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at Database 'signal.db' corrupted!.(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null.(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at Diagnostics results:.(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at  ===== PRAGMA integrity_check (same-connection) =====.(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at ok.(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at .(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at ===== PRAGMA cipher_integrity_check (same-connection) =====.(:0)
07-27 12:12:30.535 25869 25972 E AndroidRuntime:    at .(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException: java.lang.RuntimeException: An error occurred while executing doInBackground()
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at android.os.AsyncTask$4.done(AsyncTask.java:415)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:381)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.FutureTask.setException(FutureTask.java:250)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.FutureTask.run(FutureTask.java:269)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:305)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.lang.Thread.run(Thread.java:1012)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException: Caused by: org.thoughtcrime.securesms.database.SqlCipherErrorHandler$DatabaseCorruptedError_BothChecksPass
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SqlCipherErrorHandler.onCorruption(SqlCipherErrorHandler.kt:40)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.onCorruption(SQLiteDatabase.java:348)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteProgram.onCorruption(SQLiteProgram.java:117)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteStatement.executeUpdateDelete(SQLiteStatement.java:74)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.executeSql(SQLiteDatabase.java:1993)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at net.zetetic.database.sqlcipher.SQLiteDatabase.execSQL(SQLiteDatabase.java:1900)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.helpers.migration.V191_UniqueMessageMigrationV2.migrate(V191_UniqueMessageMigrationV2.kt:44)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:238)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:170)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase$Companion.runPostBackupRestoreTasks(SignalDatabase.kt:287)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.database.SignalDatabase.runPostBackupRestoreTasks(SignalDatabase.kt:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:298)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:282)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at android.os.AsyncTask$3.call(AsyncTask.java:394)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.FutureTask.run(FutureTask.java:264)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:305)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1137)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:637)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at java.lang.Thread.run(Thread.java:1012)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at [[ ↑↑ Original Trace ↑↑ ]].(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at [[ ↓↓ Inferred Trace ↓↓ ]].(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at Database 'signal.db' corrupted!.(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null.(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at Diagnostics results:.(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at  ===== PRAGMA integrity_check (same-connection) =====.(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at ok.(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at .(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at ===== PRAGMA cipher_integrity_check (same-connection) =====.(:0)
07-27 12:12:30.535 25869 25972 E SignalUncaughtException:   at .(:0)
07-27 12:12:30.561 25869 25972 I JobManager: Successfully flushed.
07-27 12:12:30.592 25869 25972 I Process : Sending signal. PID: 25869 SIG: 9
stale[bot] commented 11 months ago

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.

derMart commented 11 months ago

Issue is of course still existing and has not been fixed. Please do not close this ticket until it is done.

safisynai commented 11 months ago

I can confirm this issue is still present in version 6.34.5. The backup I'm trying to restore is quite old (from late 2020), but my passphrase is definitely correct and the backup is uncorrupted as signalbackup-tools can read the old backup without issue; it's only Signal itself that crashes when trying to restore this backup. Unpacking then repacking the backup with signalbackup-tools also does not help - Signal still crashes shortly after finishing the import.

Downgrading to an older (6.14.5) version allows the backup to be restored successfully, but registration subsequently fails with a DeprecatedVersionException.

Debug log: signal-log-1696041624334.zip

cody-signal commented 11 months ago

Thanks for the extra details @safisynai it's something we're still tracking, but difficult to trace down cause without a local reproduction.

safisynai commented 11 months ago

Thank you for your response, @cody-signal. Is there any further information I can provide from my end that could help in reproducing the issue?

aesrentai commented 7 months ago

I just hit this issue myself and it's causing me a LOT of grief. Can confirm present on the most recent release of signal (6.46) from the Play Store. I personally hit this issue when trying to restore a backup created from an old version of signal (5.51 I believe) and signal crashes sometime between instantly and 10 seconds after reading the backup.

I would be willing to send this backup to the signal developers if it would be helpful in diagnosing this issue.

I can also confirm that using an older version of the app succeeds, but registration fails as the version is deprecated

nicholas-signal commented 7 months ago

I personally hit this issue when trying to restore a backup created from an old version of signal (5.51 I believe) and signal crashes sometime between instantly and 10 seconds after reading the backup.

Our backup format has evolved a lot since 5.51. There exist tools out there for manipulating backups that might help you in this case.

If you upload a debuglog of the crash, we can take a look. You should be able to relaunch Signal after the backup-reading-crash and capture+upload a debug log from the registration flow: https://support.signal.org/hc/en-us/articles/360007318591-Debug-Logs-and-Crash-Reports#android_debug

ichthyosaurus commented 7 months ago

I just hit this issue myself and it's causing me a LOT of grief.

Same here. I hit the issue when trying to import a backup created with version 6.8.3.

The backup I'm trying to restore is quite old (from late 2020), but my passphrase is definitely correct and the backup is uncorrupted as signalbackup-tools can read the old backup without issue; it's only Signal itself that crashes when trying to restore this backup. Unpacking then repacking the backup with signalbackup-tools also does not help - Signal still crashes shortly after finishing the import.

I tried this as well, and the backup file seems fine: extracting the database with signalbackup-tools works but even rebuilding the file doesn't help. Signal always crashes.

nh2 commented 5 months ago

I have the same issue, different versions:

Restoring the backup succeeds, but afterwards starting Signal causes the app to crash immediately.

Posting adb logcat of the signal process:

``` 03-15 05:23:08.108 27294 27294 I crime.securesms: Using CollectorTypeCC GC. 03-15 05:23:08.112 27294 27294 E crime.securesms: Not starting debugger since process cannot load the jdwp agent. 03-15 05:23:08.129 27294 27294 D CompatibilityChangeReporter: Compat change id reported: 171979766; UID 10255; state: ENABLED 03-15 05:23:08.129 27294 27294 D CompatibilityChangeReporter: Compat change id reported: 242716250; UID 10255; state: DISABLED 03-15 05:23:08.134 27294 27294 D nativeloader: Configuring clns-4 for other apk /system/framework/org.apache.http.legacy.jar. target_sdk_version=33, uses_libraries=ALL, library_path=/data/app/~~_SXO4NjRAEQJZ2b1PbKDbw==/org.thoughtcrime.securesms-5-E2ZD3wJU7kY84C70bt3g==/lib/arm64:/data/app/~~_SXO4NjRAEQJZ2b1PbKDbw==/org.thoughtcrime.securesms-5-E2ZD3wJU7kY84C70bt3g==/base.apk!/lib/arm64-v8a, permitted_path=/data:/mnt/expand:/data/user/0/org.thoughtcrime.securesms 03-15 05:23:08.387 27294 27294 D nativeloader: Configuring clns-5 for other apk /data/app/~~_SXO4NjRAEQJZ2b1PbKDbw==/org.thoughtcrime.securesms-5-E2ZD3wJU7kY84C70bt3g==/base.apk. target_sdk_version=33, uses_libraries=, library_path=/data/app/~~_SXO4NjRAEQJZ2b1PbKDbw==/org.thoughtcrime.securesms-5-E2ZD3wJU7kY84C70bt3g==/lib/arm64:/data/app/~~_SXO4NjRAEQJZ2b1PbKDbw==/org.thoughtcrime.securesms-5-E2ZD3wJU7kY84C70bt3g==/base.apk!/lib/arm64-v8a, permitted_path=/data:/mnt/expand:/data/user/0/org.thoughtcrime.securesms 03-15 05:23:08.394 27294 27294 V GraphicsEnvironment: Currently set values for: 03-15 05:23:08.395 27294 27294 V GraphicsEnvironment: angle_gl_driver_selection_pkgs=[] 03-15 05:23:08.395 27294 27294 V GraphicsEnvironment: angle_gl_driver_selection_values=[] 03-15 05:23:08.395 27294 27294 V GraphicsEnvironment: ANGLE GameManagerService for org.thoughtcrime.securesms: false 03-15 05:23:08.395 27294 27294 V GraphicsEnvironment: Neither updatable production driver nor prerelease driver is supported. 03-15 05:23:08.395 27294 27294 V GraphicsEnvironment: org.thoughtcrime.securesms is not listed in per-application setting 03-15 05:23:08.401 27294 27294 I MultiDex: Installing application 03-15 05:23:08.401 27294 27294 I MultiDex: VM has multidex support, MultiDex support library is disabled. 03-15 05:23:08.401 27294 27294 I MultiDex: VM with version 2.1.0 has multidex support 03-15 05:23:08.404 27294 27294 D CompatibilityChangeReporter: Compat change id reported: 183155436; UID 10255; state: ENABLED 03-15 05:23:08.406 27294 27294 I FirebaseApp: Device unlocked: initializing all Firebase APIs for app [DEFAULT] 03-15 05:23:08.409 27294 27294 I FirebaseInitProvider: FirebaseApp initialization successful 03-15 05:23:08.414 27294 27294 D CompatibilityChangeReporter: Compat change id reported: 263076149; UID 10255; state: DISABLED 03-15 05:23:08.452 27294 27294 I ApplicationContext: onCreate() 03-15 05:23:08.454 27294 27294 I ApplicationContext: Installed AesGcmProvider: 1 03-15 05:23:08.456 27294 27294 V NativeCrypto: Registering org/conscrypt/NativeCrypto's 288 native methods... 03-15 05:23:08.460 27294 27294 I ApplicationContext: Installed Conscrypt provider: 2 03-15 05:23:08.461 27294 27317 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.463 27294 27317 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.469 27294 27294 D ApplicationMigrations: Not an update. Skipping. 03-15 05:23:08.469 27294 27321 D JobManager: Starting initialization: Thread[signal-JobManager,5,main] 03-15 05:23:08.470 27294 27294 I IncomingMessageObserver: Initializing! (108952237) 03-15 05:23:08.472 27294 27322 I IncomingMessageObserver: Waiting for websocket state change.... 03-15 05:23:08.473 27294 27321 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.474 27294 27294 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.484 27294 27294 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.485 27294 27294 I KeyValueDatabase: onOpen() 03-15 05:23:08.495 27294 27294 D CachedInflater: Clearing view cache. 03-15 05:23:08.495 27294 27294 D DynamicTheme: Setting to follow system expecting: 32 03-15 05:23:08.496 27294 27294 I FeatureFlags: init() {} 03-15 05:23:08.497 27294 27294 D CallManager: Loading ringrtc library 03-15 05:23:08.497 27294 27324 D NetworkConnectionListen: ConnectivityManager.NetworkCallback onAvailable() 03-15 05:23:08.498 27294 27324 D NetworkConnectionListen: ConnectivityManager.NetworkCallback onBlockedStatusChanged() 03-15 05:23:08.499 27294 27325 D BlobProvider: No attachment drafts exist. Skipping. 03-15 05:23:08.499 27294 27325 I BlobProvider: Initialized. 03-15 05:23:08.500 27294 27294 I CallManager: CallManager.initialize(): (release build, field trials = WebRTC-Audio-OpusSetSignalVoiceWithDtx/Enabled/) 03-15 05:23:08.500 27294 27294 I org.webrtc.Logging: NativeLibrary: Loading native library: jingle_peerconnection_so 03-15 05:23:08.501 27294 27294 I CallManager: CallManager.initialize() returned 03-15 05:23:08.504 27294 27294 D ApplicationContext: onCreate() took 88 ms 03-15 05:23:08.504 27294 27294 D AppStartup: [init] sqlcipher-init: 34, logging: 1, anr-detector: 1, security-provider: 7, crash-handling: 0, rx-init: 0, event-bus: 0, app-dependencies: 0, scrubber: 0, first-launch: 0, app-migrations: 9, lifecycle-observer: 0, message-retriever: 25, dynamic-theme: 1, proxy-init: 0, blob-provider: 1, feature-flags: 0, ring-rtc: 4, glide: 0, schedule-non-blocking: 2, total: 86 03-15 05:23:08.505 27294 27323 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at java.lang.Thread.run(Thread.java:1012) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at org.signal.core.util.concurrent.SignalExecutors$NumberedThreadFactory$1.run(SignalExecutors.java:109) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at org.thoughtcrime.securesms.ApplicationContext$$ExternalSyntheticLambda11.run(R8$$SyntheticClass:0) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at org.thoughtcrime.securesms.ApplicationContext.$r8$lambda$j9SYVZNI3aEbrOx6jxBWYL046uc(ApplicationContext.java:0) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at org.thoughtcrime.securesms.ApplicationContext.lambda$onCreate$9(ApplicationContext.java:180) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: at org.thoughtcrime.securesms.registration.RegistrationUtil.maybeMarkRegistrationComplete(RegistrationUtil.java:44) 03-15 05:23:08.505 27294 27327 I RegistrationUtil: java.lang.Throwable 03-15 05:23:08.505 27294 27327 I RegistrationUtil: Registration is not yet complete. 03-15 05:23:08.506 27294 27321 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.507 27294 27322 D IncomingMessageObserver: [Does Not Need Connection] Network: true, Foreground: false, Time Since Last Interaction: 2 ms (within limit), FCM: true, Stay open requests: [], Registered: false, Proxy: false, Force websocket: false 03-15 05:23:08.508 27294 27328 I PreKeysSyncJob: Some signed/last-resort prekeys aren't registered yet. Enqueuing a job. ACI: false PNI: false 03-15 05:23:08.510 27294 27322 D IncomingMessageObserver: [Does Not Need Connection] Network: true, Foreground: false, Time Since Last Interaction: 37 ms (within limit), FCM: true, Stay open requests: [], Registered: false, Proxy: false, Force websocket: false 03-15 05:23:08.511 27294 27327 I PersistentAlarmManagerL: [RotateSignedPreKeyListener] onReceive(signal.ACTION_SCHEDULE) 03-15 05:23:08.511 27294 27328 I JobManager: Waiting for initialization... 03-15 05:23:08.512 27294 27327 D CompatibilityChangeReporter: Compat change id reported: 160794467; UID 10255; state: ENABLED 03-15 05:23:08.513 27294 27327 I PersistentAlarmManagerL: [RotateSignedPreKeyListener] scheduling alarm for: 1710636015272 03-15 05:23:08.514 27294 27327 I PersistentAlarmManagerL: [DirectoryRefreshListener] onReceive(signal.ACTION_SCHEDULE) 03-15 05:23:08.516 27294 27327 I PersistentAlarmManagerL: [DirectoryRefreshListener] scheduling alarm for: 1710636015288 03-15 05:23:08.518 27294 27327 I PersistentAlarmManagerL: [LocalBackupListener] onReceive(signal.ACTION_SCHEDULE) 03-15 05:23:08.523 27294 27321 I JobDatabase: onOpen() 03-15 05:23:08.527 27294 27294 W crime.securesms: Accessing hidden field Ljava/util/Collections$SynchronizedCollection;->mutex:Ljava/lang/Object; (max-target-o, reflection, denied) 03-15 05:23:08.527 27294 27294 W crime.securesms: Accessing hidden method Ljava/util/Collections$SynchronizedCollection;->(Ljava/util/Collection;Ljava/lang/Object;)V (max-target-o, reflection, denied) 03-15 05:23:08.527 27294 27294 W crime.securesms: Accessing hidden method Ljava/util/Collections$SynchronizedSet;->(Ljava/util/Set;Ljava/lang/Object;)V (max-target-o, reflection, denied) 03-15 05:23:08.527 27294 27327 I PersistentAlarmManagerL: [LocalBackupListener] scheduling exact alarm for: 1710554700000 hasManagerPermission: false 03-15 05:23:08.527 27294 27327 W PersistentAlarmManagerL: [LocalBackupListener] Unable to schedule exact alarm, falling back to inexact alarm, scheduling alarm for: 1710554700000 03-15 05:23:08.529 27294 27327 I PersistentAlarmManagerL: [RotateSenderCertificateListener] onReceive(signal.ACTION_SCHEDULE) 03-15 05:23:08.530 27294 27327 I PersistentAlarmManagerL: [RotateSenderCertificateListener] scheduling alarm for: 1710549615541 03-15 05:23:08.531 27294 27294 D AppCompatDelegate: Checking for metadata for AppLocalesMetadataHolderService : Service not found 03-15 05:23:08.533 27294 27327 I RoutineMessageFetchRece: Alarm scheduled to repeat at interval 21600000 03-15 05:23:08.534 27294 27323 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.541 27294 27294 I AppStartup: Received first critical render event. 03-15 05:23:08.544 27294 27294 D CachedInflater: Clearing view cache. 03-15 05:23:08.544 27294 27294 D DynamicTheme: Previous night mode has changed previous: 0 now: 32 03-15 05:23:08.546 27294 27294 D PassphraseRequiredActiv: routeApplicationState(), state: 4 03-15 05:23:08.547 27294 27318 D LogDatabase: [trim] keepers-size: 3, binary-search: 75, delete: 1, total: 79 03-15 05:23:08.548 27294 27323 I SignalDatabase: Upgrading database: 190, 219 03-15 05:23:08.550 27294 27323 I SignalDatabaseMigration: Running migration for version 191: V191_UniqueMessageMigrationV2. Foreign keys: false 03-15 05:23:08.556 27294 27321 D JobManager: Initialized 03-15 05:23:08.557 27294 27328 I JobManager: Initialization complete. 03-15 05:23:08.560 27294 27328 D StorageSyncHelper: Registration still ongoing. Ignore sync request. 03-15 05:23:08.560 27294 27328 D StorageSyncHelper: Scheduling a sync. Last sync was 1710476588560 ms ago. 03-15 05:23:08.560 27294 27328 I Job : [JOB::857005f7-8fbd-465d-8fee-d26e040c997a][PreKeysSyncJob] onSubmit() (Time Since Submission: 49 ms, Lifespan: 2592000000 ms, Run Attempt: 1/Unlimited, Queue: PreKeysSyncJob) 03-15 05:23:08.564 27294 27323 E SQLiteLog: 03-15 05:23:08.564 27294 27323 E SQLiteLog: OR type & 268435456 != 0 03-15 05:23:08.564 27294 27323 E SQLiteLog: type & 262144 != 0 03-15 05:23:08.564 27294 27323 E SQLiteLog: ( 03-15 05:23:08.564 27294 27323 E SQLiteLog: _id 03-15 05:23:08.564 27294 27323 E SQLiteLog: message M 03-15 05:23:08.564 27294 27323 E SQLiteLog: FROM 03-15 05:23:08.564 27294 27323 E SQLiteLog: SELECT 03-15 05:23:08.564 27294 27323 E SQLiteLog: WHERE 03-15 05:23:08.564 27294 27323 E SQLiteLog: (267) statement aborts at 10: [WITH needs_update AS ( 03-15 05:23:08.564 27294 27339 I JobRunner: [JOB::f189af8f-43a6-4ef2-a8ea-98e55ec24515][RebuildMessageSearchIndexJob][2] Running job. (Time Since Submission: 187613 ms, Lifespan: Immortal, Run Attempt: 1/3, Queue: RebuildMessageSearchIndex) 03-15 05:23:08.566 27294 27340 I JobRunner: [JOB::857005f7-8fbd-465d-8fee-d26e040c997a][PreKeysSyncJob][3] Running job. (Time Since Submission: 9 ms, Lifespan: 2592000000 ms, Run Attempt: 1/Unlimited, Queue: PreKeysSyncJob) 03-15 05:23:08.570 27294 27294 D BaseActivity: [MainActivity] onCreate() 03-15 05:23:08.572 27294 27340 W PreKeysSyncJob: [JOB::857005f7-8fbd-465d-8fee-d26e040c997a][PreKeysSyncJob] Not yet registered (Time Since Submission: 15 ms, Lifespan: 2592000000 ms, Run Attempt: 1/Unlimited, Queue: PreKeysSyncJob) 03-15 05:23:08.574 27294 27340 I JobRunner: [JOB::857005f7-8fbd-465d-8fee-d26e040c997a][PreKeysSyncJob][3] Job finished with result SUCCESS in 8 ms. (Time Since Submission: 17 ms, Lifespan: 2592000000 ms, Run Attempt: 1/Unlimited, Queue: PreKeysSyncJob) 03-15 05:23:08.578 27294 27294 I AppStartup: First render has finished. Cold Start: 162 ms, Render Time: 37 ms 03-15 05:23:08.578 27294 27328 D EmojiFiles: Verifying all name files exist. 03-15 05:23:08.579 27294 27328 D EmojiFiles: All names exist? true 03-15 05:23:08.581 27294 27315 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.592 27294 27315 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.593 27294 27294 I JobManager: onConstraintMet(NetworkConstraintObserv) 03-15 05:23:08.601 27294 27294 I JobSchedulerScheduler: Waking due to job: -1733499378 03-15 05:23:08.602 27294 27294 I JobSchedulerScheduler: Waking due to job: 0 03-15 05:23:08.611 27294 27315 D LocalMetrics: [cold-start-other] total: 161 | application-create: 88, start-activity: 37, render: 37 03-15 05:23:08.639 27294 27294 D LoggingFragment: [WelcomeFragment] onCreate() 03-15 05:23:08.642 27294 27294 D SmsRetrieverReceiver: Registering SMS retriever receiver 03-15 05:23:08.667 27294 27328 D CompatibilityChangeReporter: Compat change id reported: 247079863; UID 10255; state: DISABLED 03-15 05:23:08.679 27294 27294 D CompatibilityChangeReporter: Compat change id reported: 210923482; UID 10255; state: ENABLED 03-15 05:23:08.702 27294 27294 D LoggingFragment: [WelcomeFragment] onStart() 03-15 05:23:08.704 27294 27294 I ApplicationContext: App is now visible. 03-15 05:23:08.705 27294 27294 D FrameRateTracker: Beginning frame rate tracking. Screen refresh rate: 60.00 hz, or 16.67 ms per frame. 03-15 05:23:08.707 27294 27294 D DeadlockDetector: Beginning deadlock monitoring. 03-15 05:23:08.707 27294 27345 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.709 27294 27294 D ApplicationContext: onStart() took 4 ms 03-15 05:23:08.714 27294 27322 D IncomingMessageObserver: [Does Not Need Connection] Network: true, Foreground: true, Time Since Last Interaction: N/A, FCM: true, Stay open requests: [], Registered: false, Proxy: false, Force websocket: false 03-15 05:23:08.716 27294 27345 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:08.719 27294 27345 I MegaphoneDatabase: onOpen() 03-15 05:23:08.720 27294 27294 D CompatibilityChangeReporter: Compat change id reported: 237531167; UID 10255; state: DISABLED 03-15 05:23:08.724 27294 27349 W Parcel : Expecting binder but got null! 03-15 05:23:08.728 27294 27294 D IncomingMessageObserver: Background service started. 03-15 05:23:08.728 27294 27294 V DeviceToDeviceTransferS: onCreate 03-15 05:23:08.731 27294 27294 I WifiDirect: Nearby Wifi permission required 03-15 05:23:08.732 27294 27294 I DeviceToDeviceTransferS: Shutdown 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: Build Config : S P 10.0.4 AArch64 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: Build Date : 11/30/20 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: Local Branch : promo490_3_Google 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: OpenGL ES Shader Compiler Version: EV031.31.04.01 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: QUALCOMM build : 85da404, I46ff5fc46f 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: Reconstruct Branch : 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: Remote Branch : 03-15 05:23:08.750 27294 27334 I AdrenoGLES-0: Remote Branch : 03-15 05:23:08.751 27294 27334 I AdrenoGLES-0: Driver Path : /vendor/lib64/egl/libGLESv2_adreno.so 03-15 05:23:08.757 27294 27334 I AdrenoGLES-0: PFP: 0x016ee190, ME: 0x00000000 03-15 05:23:08.760 27294 27334 W AdrenoUtils: : Failed to read chip ID from gpu_model. Fallback to use the GSL path 03-15 05:23:08.760 27294 27334 W AdrenoUtils: : Failed to open /sys/class/kgsl/kgsl-3d0/gpu_model 03-15 05:23:08.768 27294 27334 E OpenGLRenderer: Unable to match the desired swap behavior. 03-15 05:23:08.785 27294 27294 V DeviceToDeviceTransferS: onDestroy 03-15 05:23:08.807 27294 27294 D BaseActivity: [MainActivity] onDestroy() 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: ===== PRAGMA integrity_check (same-connection) ===== 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: ===== PRAGMA cipher_integrity_check (same-connection) ===== 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: Database 'signal.db' corrupted! 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: Diagnostic results: 03-15 05:23:08.944 27294 27323 E SqlCipherErrorHandler: ok 03-15 05:23:08.944 27294 27323 W SearchTable: [fullyResetTables] Dropping tables and triggers... 03-15 05:23:08.958 27294 27323 W SearchTable: [fullyResetTables] Recreating table... 03-15 05:23:08.960 27294 27323 W SearchTable: [fullyResetTables] Recreating triggers... 03-15 05:23:08.965 27294 27323 I Job : [JOB::df43b773-1bb9-40f3-927c-d5bbf57e4136][RebuildMessageSearchIndexJob] onSubmit() (Time Since Submission: 2 ms, Lifespan: Immortal, Run Attempt: 1/3, Queue: RebuildMessageSearchIndex) 03-15 05:23:08.965 27294 27323 W SearchTable: [fullyResetTables] Done. Index will be rebuilt asynchronously) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at java.lang.Thread.run(Thread.java:1012) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at net.zetetic.database.sqlcipher.SQLiteDatabase.endTransaction(SQLiteDatabase.java:572) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:403) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:302) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at net.zetetic.database.sqlcipher.SQLiteSession.endTransaction(SQLiteSession.java:402) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at net.zetetic.database.sqlcipher.SQLiteSession.throwIfNoTransaction(SQLiteSession.java:950) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.signal.core.util.concurrent.SignalExecutors$NumberedThreadFactory$1.run(SignalExecutors.java:109) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.signal.core.util.SQLiteDatabaseExtensionsKt.withinTransaction(SQLiteDatabaseExtensions.kt:24) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:176) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.KeyValueDatabase$$ExternalSyntheticLambda0.run(R8$$SyntheticClass:0) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.KeyValueDatabase.$r8$lambda$jefACyoHK4h3lvPI5zn7iBuWxuI(KeyValueDatabase.java:0) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.KeyValueDatabase.lambda$onOpen$0(KeyValueDatabase.java:99) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.SignalDatabase$Companion.hasTable(SignalDatabase.kt:305) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.SignalDatabase.getRawReadableDatabase(SignalDatabase.kt:189) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.SignalDatabase.hasTable(SignalDatabase.kt:0) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:168) 03-15 05:23:08.970 27294 27323 E AndroidRuntime: FATAL EXCEPTION: signal-bounded-0 03-15 05:23:08.970 27294 27323 E AndroidRuntime: java.lang.IllegalStateException: Cannot perform this operation because there is no current transaction. 03-15 05:23:08.970 27294 27323 E AndroidRuntime: Process: org.thoughtcrime.securesms, PID: 27294 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at java.lang.Thread.run(Thread.java:1012) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:644) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at net.zetetic.database.sqlcipher.SQLiteDatabase.endTransaction(SQLiteDatabase.java:572) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:403) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:302) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at net.zetetic.database.sqlcipher.SQLiteSession.endTransaction(SQLiteSession.java:402) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at net.zetetic.database.sqlcipher.SQLiteSession.throwIfNoTransaction(SQLiteSession.java:950) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.signal.core.util.concurrent.SignalExecutors$NumberedThreadFactory$1.run(SignalExecutors.java:109) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.signal.core.util.SQLiteDatabaseExtensionsKt.withinTransaction(SQLiteDatabaseExtensions.kt:24) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.helpers.SignalDatabaseMigrations.migrate(SignalDatabaseMigrations.kt:176) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.KeyValueDatabase$$ExternalSyntheticLambda0.run(R8$$SyntheticClass:0) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.KeyValueDatabase.$r8$lambda$jefACyoHK4h3lvPI5zn7iBuWxuI(KeyValueDatabase.java:0) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.KeyValueDatabase.lambda$onOpen$0(KeyValueDatabase.java:99) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.SignalDatabase$Companion.hasTable(SignalDatabase.kt:305) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.SignalDatabase.getRawReadableDatabase(SignalDatabase.kt:189) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.SignalDatabase.hasTable(SignalDatabase.kt:0) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: at org.thoughtcrime.securesms.database.SignalDatabase.onUpgrade(SignalDatabase.kt:168) 03-15 05:23:08.971 27294 27323 E SignalUncaughtException: java.lang.IllegalStateException: Cannot perform this operation because there is no current transaction. 03-15 05:23:08.971 27294 27325 W crime.securesms: Long monitor contention with owner signal-bounded-0 (27323) at net.zetetic.database.sqlcipher.SQLiteDatabase net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase()(SQLiteOpenHelper.java:303) waiters=0 in net.zetetic.database.sqlcipher.SQLiteDatabase net.zetetic.database.sqlcipher.SQLiteOpenHelper.getReadableDatabase() for 467ms 03-15 05:23:08.985 27294 27323 I JobManager: Successfully flushed. 03-15 05:23:08.992 27294 27325 I SQLiteConnection: Database keying operation returned:0 03-15 05:23:09.008 27294 27323 I Process : Sending signal. PID: 27294 SIG: 9 03-15 05:23:09.075 1066 1066 I Zygote : Process 27294 exited due to signal 9 (Killed) 03-15 05:23:09.084 1730 1983 I libprocessgroup: Successfully killed process cgroup uid 10255 pid 27294 in 0ms 03-15 05:23:09.737 1730 7346 I Process : Sending signal. PID: 27294 SIG: 9 ```

Excerpt from that:

E SqlCipherErrorHandler: [sqlite] FullCode: 267 | ErrorCode: 11 | ExtendedErrorCode: 1 | Message: database disk image is malformed | ExtraMessage: null
E SqlCipherErrorHandler: Database 'signal.db' corrupted!
nh2 commented 5 months ago

Does Signal have any test in a test suite that checks that old backups work?

nh2 commented 5 months ago

where to find a safe apk of the older version that worked for you as I'd be grateful to try that as an interim measure as well

I'd like know that as well.

I picked version 6.5.6 from apkmirror.com now, imported the 6.5.6 backup there. This prompted me for my phone number, but showed an error popup that it could not connect to the "service" (presumably the Signal phone number verification service).

So I upgraded again to the latest Play Store version 7.0.2; the next app start showed an "Updating ..." screen, but immediately after that the app is back to perma-crashing on each open.

Using WiFi device-to-device transfer from the old device with 6.5.6 from which the backup comes, to the new device with 7.0.2, the same issue happens: Transfer completes, and the 7.0.2 app is perma-crashing on startup.

This is quite frustrating:

Every time I try the Signal backup functionality, it fails completely. 3 years ago it lost me a lot of data. Today again, it seems my 25000 messages are at risk.

nh2 commented 5 months ago

Using WiFi device-to-device transfer from the old device with 6.5.6 from which the backup comes, to the new device with 7.0.2, the same issue happens: Transfer completes, and the 7.0.2 app is perma-crashing on startup.

Uh, after doing this, signal on the old device doesn't even start any more either: It shows

Complete registration on your new device

Your Signal account has been transferred to your new device, but you must complete registration on it to continue. Signal will be inactive on ... [here the message is cut off vertically, and scrolling is impossible, so I can't read the rest]

The only button is Done and that closes the app.

This seems like a bad workflow to me: Making the old data inaccessible when there's no guarantee or check that the new device could actually successfully use the data.

If backup restoration is known to be broken for years, wouldn't it be better to be a bit more conservative in the transfer feature?

nh2 commented 5 months ago

I managed to migrate the data via the following upgrade path across versions, downloaded from apkmirror.com:

I picked these versions arbitrarily. The idea was that maybe DB migrations only work from recent previous versions, so I went in small version steps. I have not tried to minimise the number of steps.

I installed 6.5.6, imported the backup, and then for each version in the list, I installed it, started Signal, clicked myself through the "Restore from backup file" procedure, all the way to the phone number verification step. For most versions the phone number verification request submission would fail with an error about not being able to connect to the network; only for the latest version did this succeed for me. The latest version prompted for my Signal PIN, which I skipped. Then my data showed up as migrated successfully.

I hope this helps others with the same problem, and maybe the info above can also help Signal devs figure out how to fix the problem that old backups do not restore correctly.

ichthyosaurus commented 5 months ago

Thank you! @nh2 It actually works!

Here's what I did:

My backup was from version 6.8.3 (database v171), so I started with the last version that was found to be ok in this thread (@derMart in https://github.com/signalapp/Signal-Android/issues/13034#issuecomment-1614852940).

I used Molly instead of Signal proper because it's easy to download directly: https://github.com/mollyim/mollyim-android/releases

I installed 6.14.5, imported the backup, and attempted to register (which failed as expected). I then went through my APKs, installed the next version, opened the app, waited a bit for good measure, closed it again, and continued with step 1. Apparently it's not necessary to go through the import process after the first attempt. I tried it a few times along the way, and it didn't ask for my passphrase after selecting the backup file. Instead, it jumped to the registration page immediately.

After installing the latest version (7.0.2), I restored the backup, it didn't ask for my passphrase, and I registered my number. Note that registration failed with Molly-FOSS - only after installing the googlified version it worked. Also note that registration took a lot of patience, many tries without any error feedback, and many captchas - but in the end it worked.

It then forced me to set a PIN (which is a problem because of https://github.com/signalapp/Signal-Android/issues/13458 / https://github.com/mollyim/mollyim-android/issues/293). After registration, all my chats showed up, and I installed Molly-v7.0.2-1-FOSS.apk over Molly-v7.0.2-1.apk again.

There were a few issues though:

My path:

I'm glad it finally worked but it's an ordeal. To be honest, having no backup system would almost be better than having a broken one. Maybe it would make sense to show a big warning when creating a backup: "backups are not intended as backups but only as a vehicle for transferring your data to a new phone in the very near future"...

runderwo commented 2 weeks ago

I was unable to restore a backup made on Android v7.12.0 (in February of this year) with v7.14.1 (current) - the app claimed it was reading hundreds of thousands of messages (while the actual count was ~80k) and then crashed. The same result occurred in multiple attempts. The solution was to build and install the old version that generated the backup, restore the backup with it and then install the new version to migrate the already imported database. Very puzzling how there can be so much drift in such a small delta in clock time and minor version.