search

bepaald / signalbackup-tools

Tool to work with Signal Backup files.
GNU General Public License v3.0
790 stars 38 forks source link

Crash when importing generated backup. Negative array size. #145

Closed bepaald closed 1 year ago

bepaald commented 1 year ago 
          Hi @bepaald ,

let me thank you first for the great tool, the decrypting and the xport to HTML work perfectly. I just bought you a Ko-fi. 😉 Unfortunately I am experiencing similar Issues importing conversations from the desktop client. 😅 The export to HTML works pretty well and all chats look fine.
I am using Signal desktop for Windows (version 6.30.2) and the Signal Android app (version 6.32.5). The ADB errors stack trace seem to differ a bit from the one @luturnai had posted:

2023-09-20 09:13:06.832  6084-10896 AndroidRuntime          org.thoughtcrime.securesms           E  FATAL EXCEPTION: AsyncTask #5
                                                                                                    Process: org.thoughtcrime.securesms, PID: 6084
                                                                                                    java.lang.RuntimeException: An error occurred while executing doInBackground()
                                                                                                        at android.os.AsyncTask$3.done(AsyncTask.java:355)
                                                                                                        at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:383)
                                                                                                        at java.util.concurrent.FutureTask.setException(FutureTask.java:252)
                                                                                                        at java.util.concurrent.FutureTask.run(FutureTask.java:271)
                                                                                                        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:246)
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.processTask(ThreadPoolExecutor.java:1187)
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
                                                                                                        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
                                                                                                        at java.lang.Thread.run(Thread.java:784)
                                                                                                    Caused by: java.lang.NegativeArraySizeException: -235780801
                                                                                                        at org.thoughtcrime.securesms.backup.BackupRecordInputStream.readFrame(BackupRecordInputStream.java:164)
                                                                                                        at org.thoughtcrime.securesms.backup.BackupRecordInputStream.readFrame(BackupRecordInputStream.java:92)
                                                                                                        at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:93)
                                                                                                        at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:71)
                                                                                                        at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:292)
                                                                                                        at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:282)
                                                                                                        at android.os.AsyncTask$2.call(AsyncTask.java:334)
                                                                                                        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
                                                                                                        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:246) 
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.processTask(ThreadPoolExecutor.java:1187) 
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152) 
                                                                                                        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
                                                                                                        at java.lang.Thread.run(Thread.java:784) 
2023-09-20 09:13:06.838  6084-10896 SignalUncaughtException org.thoughtcrime.securesms           E  
                                                                                                    java.lang.RuntimeException: An error occurred while executing doInBackground()
                                                                                                        at android.os.AsyncTask$3.done(AsyncTask.java:355)
                                                                                                        at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:383)
                                                                                                        at java.util.concurrent.FutureTask.setException(FutureTask.java:252)
                                                                                                        at java.util.concurrent.FutureTask.run(FutureTask.java:271)
                                                                                                        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:246)
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.processTask(ThreadPoolExecutor.java:1187)
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
                                                                                                        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
                                                                                                        at java.lang.Thread.run(Thread.java:784)
                                                                                                    Caused by: java.lang.NegativeArraySizeException: -235780801
                                                                                                        at org.thoughtcrime.securesms.backup.BackupRecordInputStream.readFrame(BackupRecordInputStream.java:164)
                                                                                                        at org.thoughtcrime.securesms.backup.BackupRecordInputStream.readFrame(BackupRecordInputStream.java:92)
                                                                                                        at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:93)
                                                                                                        at org.thoughtcrime.securesms.backup.FullBackupImporter.importFile(FullBackupImporter.java:71)
                                                                                                        at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:292)
                                                                                                        at org.thoughtcrime.securesms.registration.fragments.RestoreBackupFragment$2.doInBackground(RestoreBackupFragment.java:282)
                                                                                                        at android.os.AsyncTask$2.call(AsyncTask.java:334)
                                                                                                        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
                                                                                                        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:246) 
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.processTask(ThreadPoolExecutor.java:1187) 
                                                                                                        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152) 
                                                                                                        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
                                                                                                        at java.lang.Thread.run(Thread.java:784)

Also the Timestamp of the generated backup seems to be broken. The start of the unix epoch is displayed as the backup date in the Android app: image

Originally posted by @BernwardWeigand in https://github.com/bepaald/signalbackup-tools/issues/143#issuecomment-1727156750

bepaald commented 1 year ago

So, first of all, thank you very much for the Ko-fi, it is very much appreciated.

Looking at some of the problems here, I feel like the backup file did not arrive on your phone intact. It may have been corrupted by a bug in this program, but also by other factors during writing or copying.

Note, the missing timestamp on the file also indicates it was not fully successfully written at some point: it is not missing due to anything in this program, it is up to your OS to set/copy the timestamps when creating or copying files (though it should not have any effect on restoring). A few questions:

If the file as generated by this program and the one on your phone are bit-identical, it seems this program failed to write a valid backup file.

Thanks!

BernwardWeigand commented 1 year ago

You are welcome 😄 Thank you again!

Here are the answers for the questions:

  1. The files are of the same size and the md5 sum is also identical after copying the Backup to the phone.
  2. The output seems to be fine: 
    
signalbackup-tools (<path-to-executable>) source version 20230919.220525 (OpenSSL)
IV: (hex:) <hex-numbers> (size: 16)
SALT: (hex:)  <hex-numbers> (size: 32)
BACKUPKEY: (hex:)  <hex-numbers> (size: 32)
CIPHERKEY: (hex:)  <hex-numbers> (size: 32)
MACKEY: (hex:)  <hex-numbers> (size: 32)
BACKUPFILE VERSION: 1
COUNTER: 2951928291
Reading backup file...
FRAME 1483 (100.0%)... Read entire backup file...

done! Database version: 206

I also ran it on the backup which I created freshly without any chats from the phone and it also did not show any errors as above.
3. The output after running the command had several warning but no errors:

signalbackup-tools () source version 20230919.220525 (OpenSSL) IV: (hex:) (size: 16) SALT: (hex:) (size: 32) BACKUPKEY: (hex:) (size: 32) CIPHERKEY: (hex:) (size: 32) MACKEY: (hex:) (size: 32) BACKUPFILE VERSION: 1 COUNTER: 2951928291 Reading backup file... FRAME 57564 (100.0%)... Read entire backup file...

done! Database version: 206 Trying to match conversation (1/33) (type: private) Warning: Failed to find matching thread for conversation, creating. (id: 641a84ac-db8d-4134-a4ef-e664b3a319a8)

Exporting backup to 'my-signal.backup' Writing HeaderFrame... Writing DatabaseVersionFrame... Writing SqlStatementFrame(s)... Dealing with table 'avatar_picker'... 0/0 entries... Dealing with table 'recipient'... 399/399 entries...done Dealing with table 'thread'... 35/35 entries...done Dealing with table 'message'... 47975/47975 entries...done Dealing with table 'call'... 0/0 entries... Dealing with table 'call_link'... 0/0 entries... Dealing with table 'cds'... 382/382 entries...done Dealing with table 'chat_colors'... 0/0 entries... Dealing with table 'distribution_list'... 1/1 entries...done Dealing with table 'distribution_list_member'... 0/0 entries... Dealing with table 'donation_receipt'... 0/0 entries... Dealing with table 'drafts'... 0/0 entries... Dealing with table 'emoji_search'... 0/0 entries... Dealing with table 'groups'... 8/8 entries...done Dealing with table 'group_membership'... 47/47 entries...done Dealing with table 'group_receipts'... 2075/2075 entries...done Dealing with table 'identities'... 48/48 entries...done Dealing with table 'kyber_prekey'... 202/202 entries...done Dealing with table 'mention'... 62/62 entries...done Dealing with table 'msl_payload'... 0/0 entries... Dealing with table 'msl_message'... 0/0 entries... Dealing with table 'msl_recipient'... 0/0 entries... Dealing with table 'notification_profile'... 0/0 entries... Dealing with table 'notification_profile_allowed_members'... 0/0 entries... Dealing with table 'notification_profile_schedule'... 0/0 entries... Dealing with table 'part'... 2635/2635 entries...done Dealing with table 'payments'... 0/0 entries... Dealing with table 'pending_pni_signature_message'... 0/0 entries... Dealing with table 'pending_retry_receipts'... 0/0 entries... Dealing with table 'reaction'... 749/749 entries...done Dealing with table 'remapped_recipients'... 0/0 entries... Dealing with table 'remapped_threads'... 0/0 entries... Dealing with table 'remote_megaphone'... 0/0 entries... Dealing with table 'sender_key_shared'... 0/0 entries... Dealing with table 'sender_keys'... 0/0 entries... Dealing with table 'sticker'... 78/78 entries...done Dealing with table 'storage_key'... 6/6 entries...done Dealing with table 'story_sends'... 0/0 entries... Writing SharedPrefFrame(s)... Writing KeyValueFrame(s)... Writing Avatars... Writing EndFrame... Done!

bepaald commented 1 year ago

Hi! Hm... I'm slightly confused at this point. The error you are seeing (as shown by adb) points to a problem not in the database itself but in the decryption of it. So it seems this tool is writing bad encrypted data, even though it can still decrypt it itself....

I need to think about what could be going wrong here, but just a few quick questions:

  1. The output seems to be fine:

I assume this is the output from the "backup which I created freshly without any chats"? Because looking at the framecount it doesn't look like the 1.8GB file you attempt to restore. Also, the file you are importing into has a higher framecount — even before the import — than that (as seen in question 3).

  1. The output after running the command had several warning but no errors:

Yeah I see nothing too strange here. So at the end of this process you have 'my-signal.backup'. Is this the 1.8GB file that's still read properly by this program? Could you look at the file properties of that file? Does it have timestamps (other than 1970)? How are you transferring the file to your phone (directly through cable, via a USB thumb drive, wireless...), maybe you can find out at what point the file loses its timestamp?

I need to think about this a bit, it's a weird one. I may have more questions later.

Thanks!

bepaald commented 1 year ago

About how far into the restore process does this crash occur by the way, does it happen almost immediately, or after some messages were restored? If it happens quickly, before you see the message counter going up, this actually looks like an incorrect passphrase, are you sure you are using the correct one and aren't mistyping it?

BernwardWeigand commented 1 year ago

It seems that the passphrase was entered correctly it starts restoring the Backup up to more than 55k messages before the app is crashing: Screenshot_20230921_213855_org thoughtcrime securesms

I transfered the file via a normal USB cable connection to my phone. The properties seem to be fine. The modification date of the file also cooresponds to the one on my machine.

Perhaps some additional information about my phone helps you. It is a relatively old Huawei phone, running Android 9, for which I could not find a proper updated ROM yet😅: Screenshot_20230921_215706

Just one more thing:

I assume this is the output from the "backup which I created freshly without any chats"? Because looking at the framecount it doesn't look like the 1.8GB file you attempt to restore. Also, the file you are importing into has a higher framecount — even before the import — than that (as seen in question 3).

I double checked it and realized that I accidentally switched the frame counts. 🙈 I messed it up when I removed the Open SSL data from the CLI-output. The one of the backup that I got from my phone directly after entering the PIN to my signal account is of course lower. The backup from the phone just has around 10 MB. The higher frame count was after I had imported the 1.8 GB from my desktop machine.

bepaald commented 1 year ago

Thanks. To be honest, I'm really at a loss with this one. A little info:

The backup file is made up of frames, each frame is prepended with 4 bytes that hold the length of the next frame. So the program (this one, or Signal) reads 4 bytes, which say 'the next frame is 126 bytes long', then it reads 126 bytes and processes the frame. This repeats until the backup file is completely read.

What the error you are seeing is saying:

Caused by: java.lang.NegativeArraySizeException: -235780801
at org.thoughtcrime.securesms.backup.BackupRecordInputStream.readFrame(BackupRecordInputStream.java:164)

is that the next frame has a negative length (-235780801 bytes), which is of course impossible.

So the question is, why is this framesize incorrect?

  1. This tool is miscalculating the framesize and actually writing -235780801.
  2. The framesize is calculated properly, but encrypted incorrectly, causing to be interpreted -235780801 when decrypting the bad data.
  3. The framesize of the preceding frame is actually incorrect, causing the program to read some random, mid-frame bytes as if it was the size of the next frame.

To me, none of these options seem really likely. Option 3 is actually nearly impossible (I simplified the backup file description above, there are also checksums involved that would catch that, and at the very least show a different error). With options 1 and 2, the backup file should be just as unreadable by this tool as by Signal. Also, especially with option 2, I would have expected this problem to show up before.

Still, as long as I can't think of a 4th option, I'll try to investigate these. If I could reproduce the problem here, things would be a bit easier, but as it is, I'm afraid I need to keep asking you for additional information, I apologize for that.

Could you, when you find the time:

  1. Update this tool.
  2. Re-do the import, this time setting a new password on the outputfile and capturing a verbose log of the process: signalbackup-tools [input] [passphrase] --importfromdesktop -o [output] -op 000001111122222333334444455555 --no-showprogress --verbose > SBT.log. Note, due to the output-redirection (> SBT.log) it might seem that nothing is happening, but it should be running.
  3. At this point, maybe calculate the hash of the new output, just to be safe. Copy it to your phone, and calculate the hash there as well.
  4. Restore it, with adb running. I'm curious to see if the error is exactly the same (including the same incorrect size -235780801).
  5. Send me the SBT.log file. It will be large, but it should compress well. Apart from the 2nd - 6th line (with the mackey and such) there should not be sensitive information in there, but you could check and delete if you want. And you could send it directly by email if you don't trust it to post it here. I'm mostly interested in the last part of the log (starting at Exporting backup to [...]).

I'm hoping this will give me some more info on where to look for the problem.

There is another thing I'd like to try later: in a previous version of the backupfile-format, the framesize marker was not encrypted. I think this format is still supported by Signal, so if I write some custom code I could probably force your new backup file to be written in the old format. This way, either the problem would be gone (if the problem was the encryption of the framesize), or it's still there, but because it's not encrypted, it might be possible to actually find the problematic frame and see if there is anything special about it. I'll try to get a custom version working this weekend.

Sorry for the trouble, I haven't had such a mysterious bug in a long time, I'm afraid it's going to take a little time. I hope we can get to the bottom of it. Thanks!

bepaald commented 1 year ago

Before doing all the things mentioned above, I thought of something. I asked earlier whether the generated backup file would still decode properly with this tool (and it seems it does), but I had forgotten that attachment (and avatar) data is not actually decrypted unless the program needs it. So just to be sure, could you run signalbackup-tools [input-with-desktop-merged] [passphrase] -o [some_directory/]? Does it still finish ok? (you can delete the some_directory folder afterwards).

Also, you mentioned the HTML output of the merged backup looks fine. Could you maybe double check the index.html page, specifically all the user avatars? Are any missing that do have an avatar on the Desktop? Thanks!

bepaald commented 1 year ago

In another issue, I found and fixed a bug in setting profile avatars from the Desktop database. There is a chance that this issue is related. Both issues dealt with --importfromdesktop and your problem also occurs late in the backup restoration (~55k frames in) which is where I would expect the Avatars to be. Other symptoms were different though. I wouldn't say the chance of this being fixed is big, but it's certainly not impossible.

Give it a try, whenever you have the time. Thanks!

BernwardWeigand commented 1 year ago

Again thanks to you!


- Regarding the avatars: They were displayed correctly and none is missing in the all the time in all versions of your tool that I tried.
- Regarding the decryption of the Backup it seems to decrypt correctly (no errors in the CLI output), but I honestly I am not 100% sure how the output should look like:
![image](https://github.com/bepaald/signalbackup-tools/assets/26571395/ce172edf-f748-4054-b965-733d46225acf)
bepaald commented 1 year ago

Regarding the SBT-File: I sent it to you via Mail. Unfortunately the App is still crashing. I also send you the entire ADB output. But now it seems to crash with a different exception:

Ok, that's quite interesting. I think the real error actually happens on the preceding frame:

2023-09-24 22:10:59.071  8493-8632  FullBackupImporter   pid-8493  W  Bad MAC for attachment 1646420142476! Can't restore it.

I think this bad mac happens because at this point the importer is already reading the wrong bytes, after which it reads the wrong 4 bytes as the next frame length. Previously it read a negative value, now it's reading 639278224 bytes (aka 609MB, which is much too large for any frame) and your phone runs out of memory.

I'm still not quite sure why it would read a different value this time than last time, and why this tool doesn't run in to the same problem.

In the ADB output we now get and attachment id: 1646420142476, so I tried to write some custom code to print information about this attachment as it gets added, encrypted and written. For me, it's difficult to test this code, so I hope it works and provides some new clues. Please run this with --importfromdesktop and -o/--output, no need for verbose. I'd be interested in all the output, there shouldn't be any sensitive information in there, apart from possibly a filename (which you can remove). signalbackup-tools_win_custom.zip

Some things you might be able to check out:

Sorry for all the questions, I'm still trying to figure out what's going on. I do think we're getting closer to finding out what the problem is.

BernwardWeigand commented 1 year ago

I just gave it a quick run and it gave me that output:

unq_id: 1646420142476
numatt: 1
isprev: 0
rowid : 13307
isquot: 0
stick : 0
AMD: 0
 === Row 1/1 ===
            path : <path-to-the-file>
    content_type : application/octet-stream
            size : 0
   sticker_emoji : (NULL)
  sticker_packid : (NULL)
      sticker_id : (NULL)
       file_name : <filename>
upload_timestamp : 0
           flags : 0
         pending : 0
      cdn_number : 0
Inserted part, new id: 2461
Placed attachment in list:
Frame number: 0
        Size: 0
        Type: ATTACHMENT
         - row id          : 2461 (8 bytes)
         - attachment id   : 1646420142476 (8 bytes)
         - length          : 0 (8 bytes)

and

 === Row 1/1 ===
                   _id : 2461
                   mid : 12848
                   seq : 0
                    ct : application/octet-stream
                  name : (NULL)
                 chset : (NULL)
                    cd : (NULL)
                    fn : (NULL)
                   cid : (NULL)
                    cl : (NULL)
                 ctt_s : (NULL)
                 ctt_t : (NULL)
             encrypted : (NULL)
          pending_push : 0
                 _data : (NULL)
             data_size : 0
             file_name : <filename>
             unique_id : 1646420142476
                digest : (NULL)
     fast_preflight_id : (NULL)
            voice_note : 0
            borderless : 0
             video_gif : 0
           data_random : (NULL)
                 quote : 0
                 width : 0
                height : 0
               caption : (NULL)
       sticker_pack_id : (NULL)
      sticker_pack_key : (NULL)
            sticker_id : -1
         sticker_emoji : (NULL)
             data_hash :
             blur_hash : (NULL)
  transform_properties : (NULL)
         transfer_file : (NULL)
         display_order : 0
      upload_timestamp : 0
            cdn_number : 0
incremental_mac_digest : (NULL)

Edit: I just added placeholders for the file itself

BernwardWeigand commented 1 year ago

The file itself seems to be corrupted. I am not able to open it and it has a size 0 bytes on my desktop machine. So I may just delete the message in which I got the file?

BernwardWeigand commented 1 year ago

After I did a full backup of the desktop files I deleted the message in which I received the corrupted file in the conversation via the desktop app. The I could almost an import in the app. But unfortunately after the backup restore when I entered my PIN the App just crashed again. I will send you the ADB output of the crash. I hope this will help you to understand the Issue a bit better.

bepaald commented 1 year ago

I just gave it a quick run and it gave me that output:

Ok, good, I guess that sort of explains it. I will just have the import skip 0 byte files. As far as I know Signal Android doesn't support them anyway (when I send myself one and check the database its always ~130 bytes or something like that). *

The file itself seems to be corrupted. I am not able to open it and it has a size 0 bytes on my desktop machine. So I may just delete the message in which I got the file?

Yes, I would have thought this would work.

I will send you the ADB output of the crash. I hope this will help you to understand the Issue a bit better.

I'm sad this hasn't completely fixed it. I'm not sure about the error in your log now, I've seen it once before (#124) but I never found out what was causing it exactly. I'll think about it again.

I am curious about the thousands of 

D  [deleteAttachment] attachmentId: AttachmentId::(2588, 1649085799422)
I  [deleteAttachmentOnDisk] No other strong uses of this attachment. Safe to delete. /data/user/0/org.thoughtcrime.securesms/app_parts/part3173453225303398684.mms AttachmentId::(2588, 1649085799422)
I  [deleteAttachmentOnDisk] Deleted attachment file. /data/user/0/org.thoughtcrime.securesms/app_parts/part3173453225303398684.mms AttachmentId::(2588, 1649085799422)

in that log. As far as I can tell, after a backup restore Signal will 'clean up' the database by deleting all messages that do not belong to an existing thread and then delete all attachments that do not belong to existing messages. The function that does that is called runPostBackupRestoreTasks, and it's on the last line of this function that the program crashes. From the part of the log you sent me, it seems that many attachments are deleted (and so, many messages before it). Could you maybe check a couple of those attachments (the numbers mentioned in the log correspond to the [N] and [ID] as before). Do they belong to existing messages in existing threads in Signal Desktop (and the html output of this tool)?

Is there more to the ADB log, preferably from 'Starting restore backup'? If you run this tool with signalbackup-tools [input] [passphrase] --importfromdesktop --runsqlquery "SELECT count(*) FROM message WHERE thread_id NOT IN (SELECT DISTINCT _id FROM thread)" --runsqlquery "SELECT count(*) FROM part WHERE mid NOT IN (SELECT DISTINCT _id FROM message)", what are the last lines of output?

Thanks!

*EDIT Note for future self. I think Signal Android might actually support 0 byte files, but just not read them from the backup and not write any hash for them. I did write the hash for them (I skip that for non-existing files, not for existing files even if 0 bytes), causing Android to read the first bytes of the hash as the size of next frame.

bepaald commented 1 year ago

I've found out why Signal was deleting all the newly inserted messages and pushed a fix. I'm not sure if this has any effect on the crash (I'm hoping it does), but either way you'll need to recreate the backup. So maybe (update and) try again?

Thanks!

BernwardWeigand commented 1 year ago

Sorry again for the delay. I have been a bit busy the last days. But now I gave it another try again. Unfortunately the new version is crashing. Here is the output of the signalbackup-tools [input] [passphrase] --importfromdesktop --runsqlquery "SELECT count(*) FROM message WHERE thread_id NOT IN (SELECT DISTINCT _id FROM thread)" --runsqlquery "SELECT count(*) FROM part WHERE mid NOT IN (SELECT DISTINCT _id FROM message)" run as well as the "normal" --importfromdesktop without an SQL-Query:

signalbackup-tools (<path-to-executable>) source version 20230926.132549 (Win)
BACKUPFILE VERSION: 1
BACKUPFILE SIZE: 174397153
COUNTER: 2905044603
Reading backup file...
FRAME 7593 (100.0%)... Read entire backup file...

done!
Database version: 206
Trying to match conversation (1/33) (type: private)
 - Importing 271 messages into thread._id 10
Trying to match conversation (2/33) (type: private)
 - Importing 1 messages into thread._id 11
Trying to match conversation (3/33) (type: private)
 - Importing 4 messages into thread._id 12
Trying to match conversation (4/33) (type: private)
 - Importing 50 messages into thread._id 13
Trying to match conversation (5/33) (type: private)
 - Importing 8 messages into thread._id 14
Trying to match conversation (6/33) (type: private)
 - Importing 9 messages into thread._id 15
Trying to match conversation (7/33) (type: private)
 - Importing 4168 messages into thread._id 16
Getting value of field 'size' (idx 2). Value as string:
Type: Dn Requested type: x
terminate called after throwing an instance of 'std::bad_any_cast'
  what():  bad any_cast
bepaald commented 1 year ago

Sorry again for the delay. I have been a bit busy the last days.

No worries, always take all the time you need of course.

Unfortunately the new version is crashing.

Hm, slightly unexpected, I do in a few places assume the size is an integer type without actually checking, but I don't see how that's only a problem now, and not before. Anyway, it's hopefully fixed now. Sorry about that.

BernwardWeigand commented 1 year ago

Thank you a lot for the quick fix. Now your tool runs without Problems. But unfortunately the restore process in signal is not working. It passes the import process up to the point where I get the verification SMS and them it crashes. The HTML export still seems fine I sent you the ADB of the ouput via mail again.
The output of signalbackup-tools [input] [passphrase] --importfromdesktop --runsqlquery "SELECT count(*) FROM message WHERE thread_id NOT IN (SELECT DISTINCT _id FROM thread)" --runsqlquery "SELECT count(*) FROM part WHERE mid NOT IN (SELECT DISTINCT _id FROM message)" is:

signalbackup-tools (<path-to-the-tool>) source version 20230928.135342 (Win)
BACKUPFILE VERSION: 1
BACKUPFILE SIZE: 174397153
COUNTER: 2905044603
Reading backup file...
FRAME 7593 (100.0%)... Read entire backup file...

done!
Database version: 206
Trying to match conversation (1/33) (type: private)
 - Importing 271 messages into thread._id 10
Trying to match conversation (2/33) (type: private)
 - Importing 1 messages into thread._id 11
Trying to match conversation (3/33) (type: private)
 - Importing 4 messages into thread._id 12
Trying to match conversation (4/33) (type: private)
 - Importing 50 messages into thread._id 13
Trying to match conversation (5/33) (type: private)
 - Importing 8 messages into thread._id 14
Trying to match conversation (6/33) (type: private)
 - Importing 9 messages into thread._id 15
Trying to match conversation (7/33) (type: private)
 - Importing 4168 messages into thread._id 16
Trying to match conversation (8/33) (type: private)
 - Importing 43 messages into thread._id 17
Trying to match conversation (9/33) (type: private)
 - Importing 39640 messages into thread._id 18
Trying to match conversation (10/33) (type: private)
 - Importing 7 messages into thread._id 19
Trying to match conversation (11/33) (type: private)
 - Importing 7 messages into thread._id 20
Trying to match conversation (12/33) (type: private)
 - Importing 54 messages into thread._id 21
Trying to match conversation (13/33) (type: group)
 - Importing 55 messages into thread._id 4
Warning: Unsupported message type 'group-v2-change'. Skipping... (this warning will be shown only once)
Trying to match conversation (14/33) (type: group)
 - Importing 3 messages into thread._id 5
Trying to match conversation (15/33) (type: private)
 - Importing 26 messages into thread._id 22
Trying to match conversation (16/33) (type: private)
 - Importing 26 messages into thread._id 23
Trying to match conversation (17/33) (type: private)
 - Importing 39 messages into thread._id 24
Trying to match conversation (18/33) (type: private)
 - Importing 63 messages into thread._id 25
Trying to match conversation (19/33) (type: private)
 - Importing 18 messages into thread._id 26
Trying to match conversation (20/33) (type: private)
 - Importing 113 messages into thread._id 27
Trying to match conversation (21/33) (type: private)
 - Importing 12 messages into thread._id 28
Trying to match conversation (22/33) (type: private)
 - Importing 55 messages into thread._id 29
Trying to match conversation (23/33) (type: group)
 - Importing 199 messages into thread._id 6
Trying to match conversation (24/33) (type: private)
 - Importing 101 messages into thread._id 30
Trying to match conversation (25/33) (type: private)
 - Importing 45 messages into thread._id 31
Trying to match conversation (26/33) (type: group)
 - Importing 1642 messages into thread._id 2
Trying to match conversation (27/33) (type: private)
 - Importing 21 messages into thread._id 32
Trying to match conversation (28/33) (type: group)
 - Importing 25 messages into thread._id 7
Trying to match conversation (29/33) (type: private)
 - Importing 28 messages into thread._id 33
Trying to match conversation (30/33) (type: group)
 - Importing 80 messages into thread._id 3
Trying to match conversation (31/33) (type: private)
 - Importing 37 messages into thread._id 34
Trying to match conversation (32/33) (type: group)
 - Importing 1147 messages into thread._id 1
Trying to match conversation (33/33) (type: private)
 - Importing 2 messages into thread._id 35
Warning: Profile data empty. Not updating recipient.
Warning: Failed to update profile data.
Warning: Profile data empty. Not updating recipient.
Warning: Failed to update profile data.
reorderMmsSmsIds
updateThreadsEntries
  Dealing with thread id: 10, 18, 16, 26, 32, 25, 35, 27, 30, 21, 33, 17, 15, 31, 19, 34, 13, 28, 29, 14, 12, 22, 11, 23, 20, 24, 1, 2
Checking foreign key constraints... ok
Checking database integrity (full)... ok
 * Executing query: SELECT count(*) FROM message WHERE thread_id NOT IN (SELECT DISTINCT _id FROM thread)
count(*)
0
 * Executing query: SELECT count(*) FROM part WHERE mid NOT IN (SELECT DISTINCT _id FROM message)
count(*)
0
BernwardWeigand commented 1 year ago

I was wrong! The app crashes but the process is still running. After a short time this message appeared and most of my old messages started popping up in the app: image I will redo the process with running ADB and send you the file again.

BernwardWeigand commented 1 year ago

Hm. The push notification did not disappear but also no further messages ( but around 70% were back as far as I can see) appeared after a longer time. After the next started Signal this message was displayed: image When I press the submit button, it just displays for almost a second "Could not upload logs" (ADB is also incoming).

bepaald commented 1 year ago

Hm, ok so I have to admit I'm now completely out of ideas. I need to let this sit in my brain a bit to see if I come up with any theories. As far as i can tell from the logs, the restore went fine, I see no errors in that part. The debug log was apparently not created, the error in that log just says it's 0 bytes long (but I don't know why).

The crash in you got when the verification SMS arrives, comes from here: https://github.com/signalapp/Signal-Android/blob/1d052e7c1b8b4774dc6b1adafbd1455e9e528158/app/src/main/java/org/thoughtcrime/securesms/database/RecipientTable.kt#L989C13-L989C27

In this line, a profile is being updated by something like _'Set the name of the recipient with storageid XYZ to John', and then it is asserted that one profile was updated. In this case the assertion fails because apparently no recipient with storage_id XYZ exists. (I'm not sure why this needs to be asserted and result in a fatal error, but what do I know.) But my code, and certainly the --importfromdesktop function, does not touch the storage_id's, it barely even touches the recipient table at all, so I don't understand it. As far as I know, all the recipients and their storage_id's are already in the input file and should be in the output file unchanged. You could test this by running signalbackup-tools [input] [passphrase] --runsqlquery "SELECT * FROM recipient ORDER BY storage_service_id ASC" on the backup file before and after importing from desktop and checking if the output is the same (but it will probably be a lot of output).

I will create another custom version that really does not alter the recipient table, but I'm not sure why that would help this case. edit Here it is: signalbackup-tools_win_custom.zip

A couple of questions (though this time not really with a clear purpose, I'm just hoping something will give me an idea):

Hopefully I'll come up with something to try in a little while.

BernwardWeigand commented 1 year ago

Thanks again for the custom executable I gave it a try and I did not have any errors in the process and in the ADB log. Now almost all of my messages are restored.😀😀😀 Regarding your questions:

BernwardWeigand commented 1 year ago

Unfortunately I do not have another phone for testing at the moment Perhaps it is possible to do that in the mid of the month. 😅

BernwardWeigand commented 1 year ago

I am very happy with the state now my backup restore now, after I saw through my conversations in detail. So It is fine for me if you would like to close the issue, but if I may help you with some other testing I can do that.
I was thinking about the backup restore process and I remember that I left the phone on the charging cable during the restore process. So it maybe supports your hypothesis of the DeadlockDetector. In the current ADB output there was just one such event triggered by signal:

10-01 15:44:00.245 19822 19897 D MemoryTracker: Used memory has decreased from 22635016 (21,59 MiB) to 13790032 (13,15 MiB)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: Found a long block! Blocked for at least 5000 ms.
10-01 15:44:00.263 19822 19896 W DeadlockDetector: -- [1816] signal-KeyValueStore | TIMED_WAITING
10-01 15:44:00.263 19822 19896 W DeadlockDetector: java.lang.Object.wait(Native Method)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: java.lang.Thread.parkFor$(Thread.java:2163)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: sun.misc.Unsafe.park(Unsafe.java:358)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:230)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: net.zetetic.database.sqlcipher.SQLiteConnectionPool.waitForConnection(SQLiteConnectionPool.java:681)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: net.zetetic.database.sqlcipher.SQLiteConnectionPool.acquireConnection(SQLiteConnectionPool.java:359)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: net.zetetic.database.sqlcipher.SQLiteSession.acquireConnection(SQLiteSession.java:929)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: net.zetetic.database.sqlcipher.SQLiteSession.beginTransactionUnchecked(SQLiteSession.java:314)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: net.zetetic.database.sqlcipher.SQLiteSession.beginTransaction(SQLiteSession.java:302)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: net.zetetic.database.sqlcipher.SQLiteDatabase.beginTransaction(SQLiteDatabase.java:555)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: net.zetetic.database.sqlcipher.SQLiteDatabase.beginTransaction(SQLiteDatabase.java:426)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: org.thoughtcrime.securesms.database.KeyValueDatabase.writeDataSet(KeyValueDatabase.java:145)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: org.thoughtcrime.securesms.keyvalue.KeyValueStore.lambda$write$0(KeyValueStore.java:146)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: org.thoughtcrime.securesms.keyvalue.KeyValueStore.$r8$lambda$wULmmd1-PmtZ-SnjAVLz5yExi4k(KeyValueStore.java:0)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: org.thoughtcrime.securesms.keyvalue.KeyValueStore$$ExternalSyntheticLambda0.run(R8$$SyntheticClass:0)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: java.util.concurrent.ThreadPoolExecutor.processTask(ThreadPoolExecutor.java:1187)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: java.lang.Thread.run(Thread.java:784)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: org.signal.core.util.concurrent.SignalExecutors$1.run(SignalExecutors.java:32)
10-01 15:44:00.263 19822 19896 W DeadlockDetector: 
10-01 15:44:00.263 19822 19896 W DeadlockDetector: 
10-01 15:44:00.379 32591 32653 V avrcp-Avrcp: Send track changed

If you would like to see through the entire ADB output I can send it to you.

bepaald commented 1 year ago

I did not have any errors in the process and in the ADB log. Now almost all of my messages are restored.

Excellent, I'd say this is probably solved then. Though I'll probably never be 100% certain what was wrong at the end here. I did fix at least two actual bugs in this issue (0 byte attachments and setting the new 'active' flag on threads), so thank you for reporting. You've been very helpful in helping me track down the problems you encountered.

I am very happy with the state now my backup restore now, after I saw through my conversations in detail. So It is fine for me if you would like to close the issue, but if I may help you with some other testing I can do that.

Thank you for the offer. If I do come up with anything I'll be sure to contact you. Of course, you should also feel free to message me if you need anything, either here or in a new issue. Other than that: if you're happy I'm happy. So I'll indeed close this issue for now.

Thanks again for reporting! Cheers!