[Question] Extremely corrupted backup file

[strugee]

I have a Signal backup that cannot be restored in the Signal app. I've built signalbackup-tools and tried to use it to repair the broken backup, but the tool seems to have hit a lot of corruption. In https://github.com/bepaald/signalbackup-tools/issues/17#issuecomment-724243153, this description:

It's from a phone that initially had not enough space to perform a backup but at some point it seemed that enough space was available and the backup finished correctly.

sounds exactly like me. So, my question is twofold: am I encountering the same problem as #17, where somehow part of the backup file is a copy of the earlier part, and if not, is there a way to restore my data? If the answer to the first question is yes, I'll be reporting that bug to Signal upstream as that really seems related to the disk space issue.

I'm on revision f3db27438a3b442dc9bbce43455eec457599bb6e. I don't have access to the original device (I'm in this situation because I accidentally factory reset my phone while flashing Google factory images today), but I do have access to several years worth of Signal backups. At least some of these are known-good, although the known-good ones are probably pretty old. I also have access to a Signal Desktop installation that was originally linked to the installation that generated the backup. I did not test this backup in any way prior to today, a mistake which I will not be making in the future ;)

Examination of server backups show that the file has not been corrupted since being uploaded to my personal Nextcloud. I believe but am not sure that Nextcloud mobile verifies checksums when uploading, so likely the file was corrupted before it ever made it onto the network.

The VM I was running it in seems to have crashed just before the tool finished, but I already have 12 GB of logs... I'm wondering if that will be enough to determine whether the repeated data problem has occurred :sweat_smile: if so, I could email you a link. Or if you want to give me a script or something to just run on it locally I can make that happen too.

[bepaald]

Hi!

So, my question is twofold: am I encountering the same problem as #17, where somehow part of the backup file is a copy of the earlier part, and if not, is there a way to restore my data?

Well, that would be interesting, I always thought the problem in #17 was odd, and it would be good to have more info on it (though I'm sorry this happened to you of course). I've added some quick functions to check if you are having the same problem.

I've broken a backup in a (hopefully) similar way, normal operation gives output like this:

$ ./signalbackup-tools broken.backup [password]
signalbackup-tools (./signalbackup-tools) source version 20210628.222742 (OpenSSL)
IV: (hex:) 82 1d 49 4b e[....] (size: 16)
SALT: (hex:) 68 26 0e 36 7b 4[....]  (size: 32)
BACKUPKEY: (hex:) e7 6b ea 9f 7[....] (size: 32)
CIPHERKEY: (hex:) 0e 7c ea 6e b[....] (size: 32)
MACKEY: (hex:) 1a c3 32 49 80 57 e0 5[....] (size: 32)
COUNTER: 2182957387
Reading backup file...
FRAME 62104 (017.8%)... 
WARNING: Bad MAC in attachmentdata: theirMac: (hex:) ee 3b 61 d5 0c 88 82 f2 ca 7e
                                      ourMac: (hex:) 5b aa 46 fc 40 05 3f bd 82 e9 67 0b 1e f7 55 ee 13 4e e3 ac cf dc 7e 15 b4 74 03 36 b7 34 0c fa

WARNING: Bad MAC in frame, trying to print frame info:
Frame number: 62105
        Size: 15
        Type: ATTACHMENT
         - row id          : 1010 (8 bytes)
         - attachment id   : 1518716486494 (8 bytes)
         - length          : 44227460 (8 bytes)
         - attachment      : (hex:) 00 00 00 18 66 74 79 70 6d 70 34 32 00 00 00 00 69 73 6f 6d 6d 70 34 32 00 ... (44227460 bytes total)
Frame is attachment, it belongs to entry in the 'part' table of the database:
 - _id : 1010
 - mid : 1131
 - seq : 0
 - ct : video/mp4
 - name : (NULL)
 - chset : (NULL)
 - cd : (NULL)
 - fn : (NULL)
 - cid : (NULL)
 - cl : (NULL)
 - ctt_s : (NULL)
 - ctt_t : (NULL)
 - encrypted : (NULL)
 - pending_push : 0
 - _data : /data/user/0/org.thoughtcrime.securesms/app_parts/part6947972982379084307.mms
 - data_size : 44227460
 - file_name : (NULL)
 - thumbnail : (NULL)
 - aspect_ratio : 2
 - unique_id : 1518716486494
 - digest : (NULL)
 - fast_preflight_id : -2974854916947713723
 - voice_note : 0
 - data_random : (hex:) 8d a9 73 76 f5 5d 44 e8 ef 67 f9 f5 91 0a 46 17 83 e4 7b 05 9e cc 9d ea 61 14 a0 da 74 03 27 09
 - thumbnail_random : (NULL)
 - width : 0
 - height : 0
 - quote : 0
 - caption : (NULL)
 - sticker_pack_id : (NULL)
 - sticker_pack_key : (NULL)
 - sticker_id : -1
 - data_hash : (NULL)
 - blur_hash : (NULL)
 - transform_properties : (NULL)
 - transfer_file : (NULL)
 - display_order : 0
 - upload_timestamp : 0
 - cdn_number : 0
 - borderless : 0
 - sticker_emoji : (NULL)
 - video_gif : 0

Which belongs to entry in 'mms' table:
 - _id : 1131
 - thread_id : 10
 - date : 2018-02-15 18:41:26 +0100 (1518716486463)
 - date_received : 2018-02-15 18:41:26 +0100 (1518716486485)
 - msg_box : 10485783
 - read : 1
 - m_id : (NULL)
 - sub : (NULL)
 - sub_cs : (NULL)
 - body : (NULL)
 - part_count : 1
 - ct_t : (NULL)
 - ct_l : (NULL)
 - address : 2
 - address_device_id : (NULL)
 - exp : (NULL)
 - m_cls : (NULL)
 - m_type : 128
 - v : (NULL)
 - m_size : (NULL)
 - pri : (NULL)
 - rr : (NULL)
 - rpt_a : (NULL)
 - resp_st : (NULL)
 - st : (NULL)
 - tr_id : (NULL)
 - retr_st : (NULL)
 - retr_txt : (NULL)
 - retr_txt_cs : (NULL)
 - read_status : (NULL)
 - ct_cls : (NULL)
 - resp_txt : (NULL)
 - d_tm : (NULL)
 - delivery_receipt_count : 1
 - mismatched_identities : (NULL)
 - network_failures : (NULL)
 - d_rpt : (NULL)
 - subscription_id : -1
 - expires_in : 0
 - expire_started : 0
 - notified : 0
 - read_receipt_count : 0
 - quote_id : 0
 - quote_author : (NULL)
 - quote_body : (NULL)
 - quote_attachment : -1
 - shared_contacts : (NULL)
 - quote_missing : 0
 - unidentified : 0
 - previews : (NULL)
 - reveal_duration : 0
 - reveal_start_time : 0
 - reactions : (NULL)
 - reactions_unread : 0
 - reactions_last_seen : -1
 - date_server : -1
 - remote_deleted : 0
 - quote_mentions : (NULL)
 - mentions_self : 0
 - notified_timestamp : 0
 - viewed_receipt_count : 0
 - server_guid : (NULL)
Trying to dump decoded attachment to file 'attachment_1131.bin'
FRAME 62105 (018.5%)... Failed to read next frame (2365904350 bytes at filepos 1108100821)
Starting bruteforcing offset to next valid frame... starting after: 1108100821
Checking offset 944130 bytes
GOT GOOD MAC AT OFFSET 944139 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 94413 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 944570 bytes
GOT GOOD MAC AT OFFSET 944571 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 94457 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 1140570 bytes^C

So, the first important thing is, does the program keep finding good MAC's ('GOT GOOD MAC AT OFFSET xxx BYTES!', indicating a possible valid frame)? But then fail to decode it ('No valid frame found at maximum frameskip for this offset...')? This pattern, like the last 11 lines of the above output, should be visible in your 12 GB (😲) log. Or, just run the program again and cancel ^C a few seconds after the first bad mac error.

If yes, then please try the following:

• Note at which file-position the program fails to read a valid frame. Indicated by the line 'Failed to read next frame (yyy bytes at filepos xxx)'. In the above example, the file position is 1108100821.
• Note when it first finds a (potential) valid frame (got good mac). In the above example 944139.
• Then run the tool with signalbackup-tools file.backup passphrase --strugee filepos+offset

With my example this shows:

$ ./signalbackup-tools broken.backup [password] --strugee $((1108100821+944139))
signalbackup-tools (./signalbackup-tools) source version 20210628.222742 (OpenSSL))
TEMP FUNCTION (#37)
IV: (hex:) 82 1d 49 4b e[....] (size: 16)
SALT: (hex:) 68 26 0e 36 7b 4[....]  (size: 32)
BACKUPKEY: (hex:) e7 6b ea 9f 7[....] (size: 32)
CIPHERKEY: (hex:) 0e 7c ea 6e b[....] (size: 32)
MACKEY: (hex:) 1a c3 32 49 80 57 e0 5[....] (size: 32)
COUNTER: 2182957387
Getting frame at filepos: 1109044960

GOT GOOD MAC AT OFFSET 0 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 60146 frames... YEAH! :)
Good frame: 60146 (SqlStatementFrame)
COUNTER: 2183017533
Frame number: 60146
        Size: 415
        Type: SQLSTATEMENT
         - (statement: "INSERT INTO part VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)" (109 bytes)
         - (uint64 parameter): "21"
         - (uint64 parameter): "45"
         - (uint64 parameter): "0"
         - (string parameter): "image/jpeg"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (string parameter): "/data/user/0/org.thoughtcrime.securesms/app_parts/part3275461812830375248.mms"
         - (uint64 parameter): "3646978"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "1486374622900"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (binary parameter): "(hex:) 3d 53 73 91 f6 b8 24 5b 84 d1 2b a4 cf da dc 56 c5 12 0c 73 ca 2b be 70 e8 30 e0 21 02 b4 88 d3"
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "18446744073709551615"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
$

If you get a valid frame at this point, ('Checking if we skipped xxx frames... YEAH! :)'), then I'd say you are having the exact same issue. Also note the framenumber (in my case 60146) and compare it to the last correct framenumber in the first run (62105) and realize it has run backwards, which should be impossible.

if you find you are having the exact same issue, I can write some more code to get the precise offsets where things start repeating so you can show the repetition in your bug report without having to refer to my tool: any hexviewer will then show the duplication.

If you think you are having different problems, I'd happily take a look at your log (though please truncate it to about 10 MB). Though I must warn that either way, if the program isn't able to fix the backup automatically we are probably going to have to deal with recovering as much as possible with the help of older (working) backups. This was successfully done once in #32, though we should first try to find out where exactly your broken backup stops (if the error happens in the beginning of the file it may not contain messages newer than your last good backup).

To find the last working good backup you can run with --stoponbadmac. The program should then finish with 'Failed to open backup' or with 'done.' depending on the success. You could of course script this if you need to test a lot of backups, in which case I'd recommend adding --no-showprogress to keep the output a bit smaller and more readable.

Let me know how this all goes and we can see what to do next. Also, please forgive me if I ever don't reply for a few days, sometimes I'm busy.

[strugee]

Well, that would be interesting, I always thought the problem in #17 was odd, and it would be good to have more info on it (though I'm sorry this happened to you of course).

Heh, thanks. I appreciate your help tracking down the problem!

So, the first important thing is, does the program keep finding good MAC's ('GOT GOOD MAC AT OFFSET xxx BYTES!', indicating a possible valid frame)? But then fail to decode it ('No valid frame found at maximum frameskip for this offset...')? This pattern, like the last 11 lines of the above output, should be visible in your 12 GB (:astonished:) log. Or, just run the program again and cancel ^C a few seconds after the first bad mac error.

I should clarify that the original backup file was 12GB, so I'm not surprised the log is 12GB too. It's pretty annoying though... I can't even search for things in less because it fails to allocate memory in my environment :sweat_smile:

In any case, yes, it seems that after a while what you're describing occurs (I had to use ripgrep instead of GNU grep because GNU grep also ran out of memory):

$ rg -FC 10 'No valid frame found at maximum frameskip' signalbackup-tools-verbose-2021-06-29-22-01-15.log | head -50
Trying to dump decoded attachment to file 'attachment_-1.bin'
FRAME 1678759 (001.0%)... 
Getting frame at filepos: 117726413 (COUNTER: 454850731)
Framelength: 2071527424
Failed to read next frame (2071527424 bytes at filepos 117726413)
Starting bruteforcing offset to next valid frame... starting after: 117726413

GOT GOOD MAC AT OFFSET 2 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 0 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 550 bytes
GOT GOOD MAC AT OFFSET 553 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 55 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 1120 bytes
GOT GOOD MAC AT OFFSET 1123 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 112 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 1680 bytes
GOT GOOD MAC AT OFFSET 1685 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 168 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 2220 bytes
GOT GOOD MAC AT OFFSET 2223 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 222 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 2780 bytes
GOT GOOD MAC AT OFFSET 2787 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 278 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 3330 bytes
GOT GOOD MAC AT OFFSET 3330 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 333 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 3900 bytes
GOT GOOD MAC AT OFFSET 3909 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 390 frames... nope! :(
No valid frame found at maximum frameskip for this offset...
Checking offset 4380 bytes
GOT GOOD MAC AT OFFSET 4385 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 438 frames... nope! :(

However, sometimes I get GOT GOOD MAC messages without corresponding No valid frame found messages:

$ rg -FC 10 'GOT GOOD MAC AT OFFSET' signalbackup-tools-verbose-2021-06-29-22-01-15.log | head -50
 - notified_timestamp : 0
 - viewed_receipt_count : 0
 - server_guid : (NULL)
Trying to dump decoded attachment to file 'attachment_13654.bin'
FRAME 380049 (007.9%)... 
Getting frame at filepos: 974090549 (COUNTER: 453552008)
Framelength: 0
Failed to read next frame (0 bytes at filepos 974090549)
Starting bruteforcing offset to next valid frame... starting after: 974090549
Checking offset 125954510 bytes
GOT GOOD MAC AT OFFSET 125954518 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 1074 frames... YEAH! :)
Good frame: 381124 (SqlStatementFrame)
Frame number: 381124
        Size: 476
        Type: SQLSTATEMENT
         - (statement: "INSERT INTO part VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)" (109 bytes)
         - (uint64 parameter): "2035"
         - (uint64 parameter): "15746"
         - (uint64 parameter): "0"
--
 - notified_timestamp : 0
 - viewed_receipt_count : 0
 - server_guid : (NULL)
Trying to dump decoded attachment to file 'attachment_15746.bin'
FRAME 381125 (008.9%)... 
Getting frame at filepos: 1100593513 (COUNTER: 453553085)
Framelength: 0
Failed to read next frame (0 bytes at filepos 1100593513)
Starting bruteforcing offset to next valid frame... starting after: 1100593513
Checking offset 576710 bytes
GOT GOOD MAC AT OFFSET 576711 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 3 frames... YEAH! :)
Good frame: 381129 (SqlStatementFrame)
Frame number: 381129
        Size: 476
        Type: SQLSTATEMENT
         - (statement: "INSERT INTO part VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)" (109 bytes)
         - (uint64 parameter): "2037"
         - (uint64 parameter): "15748"
         - (uint64 parameter): "0"
--
 - notified_timestamp : 0
 - viewed_receipt_count : 0
 - server_guid : (NULL)
Trying to dump decoded attachment to file 'attachment_15749.bin'
FRAME 381132 (008.9%)... 
Getting frame at filepos: 1102213471 (COUNTER: 453553094)

Which Failed to read next frame message should I pay attention to when using the --strugee flag? The ones accompanied by No valid frame found messages? Or any of them?

Also, please forgive me if I ever don't reply for a few days, sometimes I'm busy.

No worries, same. Sorry for the delay here; I'm also somewhat busy and the system I've been running your tool on is different than the system I'm using day-to-day these days so I need to find a good time to boot into it :P

[strugee]

A few other things: first, I ended up restoring from an old backup. So at this point I'm just trying to fill in more historical messages but I have a working Signal, so I'm not in a rush or anything like that.

Second, one strange thing I noticed:

$ rg -FC 10 'theirMac: (hex:) 00 00 00 00 00 00 00 00 00 00' signalbackup-tools-verbose-2021-06-29-22-01-15.log
Framelength: 455
Calculated mac: (hex:) d2 5a 73 e0 e0 91 60 b9 64 69 22 e3 09 0c 85 b1 58 0e 80 3d 06 18 bd f2 0d 2d 20 55 0c db 84 83
Mac in file   : (hex:) d2 5a 73 e0 e0 91 60 b9 64 69
FRAME 380048 (007.9%)... 
Getting frame at filepos: 973259177 (COUNTER: 453552006)
Framelength: 26
Calculated mac: (hex:) 69 65 fb 3d b8 ef 59 84 25 d3 87 e7 42 3b 58 82 de 85 38 1b 40 6d 17 90 0d 97 4c 30 e1 a4 df 43
Mac in file   : (hex:) 69 65 fb 3d b8 ef 59 84 25 d3
Getting attachment at file pos 974090549 (size: 831332)

WARNING: Bad MAC in attachmentdata: theirMac: (hex:) 00 00 00 00 00 00 00 00 00 00
                                      ourMac: (hex:) 3a fa b6 71 73 86 a0 5f 09 2c a1 96 54 44 b4 98 1a bb f9 11 32 2d 5b 63 e9 f1 d7 b2 f9 d5 9e 9a

WARNING: Bad MAC in frame, trying to print frame info:
Frame number: 380049
        Size: 14
        Type: ATTACHMENT
         - row id          : 1522 (8 bytes)
         - attachment id   : 1506114769650 (8 bytes)
         - length          : 831332 (8 bytes)
         - attachment      : (hex:) ff d8 ff e0 00 10 4a 46 49 46 00 01 01 01 00 48 00 48 00 00 ff e1 8d 32 45 ... (831332 bytes total)
--
         - (uint64 parameter): "0"

Got frame, breaking
FRAME 381124 (008.9%)... 
Getting frame at filepos: 1100045560 (COUNTER: 453553083)
Framelength: 26
Calculated mac: (hex:) fa 78 4b 1a d0 7d e6 d5 ec 35 07 ac c7 29 1d 23 18 ca 11 06 9a 5f 73 44 d4 26 f9 cf ac e0 d0 c3
Mac in file   : (hex:) fa 78 4b 1a d0 7d e6 d5 ec 35
Getting attachment at file pos 1100593513 (size: 547913)

WARNING: Bad MAC in attachmentdata: theirMac: (hex:) 00 00 00 00 00 00 00 00 00 00
                                      ourMac: (hex:) 10 58 4d f5 f3 d4 ab 56 b5 4e 11 1b b8 1e fc e9 d7 4e fc 8d 0f fa 86 88 1e 55 3c bf e0 80 81 48

WARNING: Bad MAC in frame, trying to print frame info:
Frame number: 381125
        Size: 14
        Type: ATTACHMENT
         - row id          : 2035 (8 bytes)
         - attachment id   : 1539395272241 (8 bytes)
         - length          : 547913 (8 bytes)
         - attachment      : (hex:) ff d8 ff e0 00 10 4a 46 49 46 00 01 01 00 00 01 00 01 00 00 ff db 00 43 00 ... (547913 bytes total)
--
Framelength: 489
Calculated mac: (hex:) b2 06 85 22 72 5f 33 b4 0a 09 c5 01 9a 02 52 c2 99 ce 1c a7 86 d6 65 a2 f8 23 a8 da b6 cd 4a d6
Mac in file   : (hex:) b2 06 85 22 72 5f 33 b4 0a 09
FRAME 381131 (008.9%)... 
Getting frame at filepos: 1101717711 (COUNTER: 453553092)
Framelength: 26
Calculated mac: (hex:) f4 13 4c 68 3c 73 9c 02 33 f9 82 5e 3f 01 62 fa 6a 41 4e 6a 44 7d e2 ee 58 d7 83 c4 51 e0 ae 3e
Mac in file   : (hex:) f4 13 4c 68 3c 73 9c 02 33 f9
Getting attachment at file pos 1102213471 (size: 495720)

WARNING: Bad MAC in attachmentdata: theirMac: (hex:) 00 00 00 00 00 00 00 00 00 00
                                      ourMac: (hex:) 98 c3 ff f0 fe d6 e5 c8 d2 7d 32 b8 3f 90 83 ec cc f9 15 12 26 f5 19 98 9f 97 1f 60 cb 17 1c ab

WARNING: Bad MAC in frame, trying to print frame info:
Frame number: 381132
        Size: 14
        Type: ATTACHMENT
         - row id          : 2038 (8 bytes)
         - attachment id   : 1539395280436 (8 bytes)
         - length          : 495720 (8 bytes)
         - attachment      : (hex:) ff d8 ff e0 00 10 4a 46 49 46 00 01 01 00 00 01 00 01 00 00 ff db 00 43 00 ... (495720 bytes total)
--
Framelength: 431
Calculated mac: (hex:) 38 0f 09 4e 57 69 7b 5c 9a cd c0 92 49 f1 aa 54 7e 7a b7 e4 fc 72 4a 01 a7 34 e6 f5 46 6b ee 24
Mac in file   : (hex:) 38 0f 09 4e 57 69 7b 5c 9a cd
FRAME 381434 (009.2%)... 
Getting frame at filepos: 1138807501 (COUNTER: 453553404)
Framelength: 26
Calculated mac: (hex:) 31 7a 9e 91 44 fd ec 0d 3b ee 4e 9e ff 82 6a e6 9e 4f 96 17 88 5c 73 f5 8e 31 f9 8e 73 ac bd 3b
Mac in file   : (hex:) 31 7a 9e 91 44 fd ec 0d 3b ee
Getting attachment at file pos 1139043891 (size: 236350)

WARNING: Bad MAC in attachmentdata: theirMac: (hex:) 00 00 00 00 00 00 00 00 00 00
                                      ourMac: (hex:) d5 37 a5 0d 44 0b ed 82 34 c8 90 c3 02 6e cf 08 db 9b a6 74 28 87 71 d9 3d 59 6c f5 99 70 70 32

WARNING: Bad MAC in frame, trying to print frame info:
Frame number: 381435
        Size: 14
        Type: ATTACHMENT
         - row id          : 2142 (8 bytes)
         - attachment id   : 1540217354627 (8 bytes)
         - length          : 236350 (8 bytes)
         - attachment      : (hex:) ff d8 ff e0 00 10 4a 46 49 46 00 01 01 00 00 01 00 01 00 00 ff db 00 43 00 ... (236350 bytes total)

Some attachments report a null MAC. Seems like that couldn't be a coincidence?

[bepaald]

In any case, yes, it seems that after a while what you're describing occurs (I had to use ripgrep instead of GNU grep because GNU grep also ran out of memory):

Yeah that at least looks like the same problem indeed(, however...)

However, sometimes I get GOT GOOD MAC messages without corresponding No valid frame found messages:

Not really sure how to explain this one. It was a big problem in the original issue, I always just assumed a valid MAC meant a valid frame, but that is not true and I do a lot of frame validation now. Also, just looking at the bits of the frame in the output, they definitely look legit. One important thing I notice, is that the counter (and framenumber) is actually lower at this point in your log, at 7.9% in the file than where the first error is reported, at 1%. Right before the first problem I see

FRAME 1678759 (001.0%)...
Getting frame at filepos: 117726413 (COUNTER: 454850731)

Then, when good frames are found again, it's

Good frame: 381124 (SqlStatementFrame)

And a counter around 453552008. This program does not actually ever decrease the counter/framenumber. So I can't guess how this is happening, unless the counter has actually wrapped and is finding earlier (=repeated) frames that appear later in the file. I'd need to think about that, but first:

Which Failed to read next frame message should I pay attention to when using the --strugee flag? The ones accompanied by No valid frame found messages? Or any of them?

I'd say run --strugee 117726415 or --strugee 117726966 (or both) (that is 117726413 + 2 and + 533) and let me know the results.

A few other things: first, I ended up restoring from an old backup. So at this point I'm just trying to fill in more historical messages but I have a working Signal, so I'm not in a rush or anything like that.

Ok, that's good. I hope you didn't have to use too old a backup. Usually, as I've said before, I think importing the messages into an existing, working backup shouldn't be too big of a problem. Backup files usually break somewhere in the attachment data (statistically, because 99% of most backup files is attachment data) and all the messages are in the beginning of the file (before the corruption). BUT as of my latest backup, the order of the sqlite tables seems to have changed (probably because of this commit in which the message table are deleted and recreated to fix a bug). If the message tables are located after the attachment data, so after the failure point in your backup, there may not be any messages in the file to recover. We would need to check that (I mean, I would have to write something to check for that).

Some attachments report a null MAC. Seems like that couldn't be a coincidence?

No, that is just about impossible I think. Note that this is the MAC that is read from the backup file, so actual zeros have been written by the app. The actual attachment data is there (the program calculates ourMac from that) and seems to be fine: - attachment : (hex:) ff d8 ff e0 [...], FFD8FFE0 is a jpeg file signature. So actual zeros are written to the backup file where they shouldn't be. I also noticed this in your earlier post where I see

Framelength: 0
Failed to read next frame (0 bytes at filepos 1100593513)

The framelength, like the MAC, is a raw, unencrypted value in the backup file. Obviously it can not be zero. How or why the app has written zeros I do not know. Either it is a bug in the app, or a bug in Android dealing with filewrites on full storage.

Anyway, try the strugee option first, and I'll try to get something written to see if any message data exists in the backup before the corruption occurs. I hope to be able to do that before Friday, otherwise it'll be next week because I'm out for the weekend.

[strugee]

Sounds great, no rush. I'll report back when I get a chance to run this.

[bepaald]

Ok, two things:

1. I was thinking about the decreasing counter in your log. Maybe you could (rip)grep for "FRAME 381124", see if it was actually found before as well? I'm not sure how much (if any) information about that frame is then printed, but maybe we can already see the repetition in there.

2. I've added a second function to see what messages are in the good part of your database. Run with --strugee2 and inspect the output. Examples:

[~/programming/signalbackup-tools] $ ./signalbackup-tools ~/PHONE/signal-2021-06-01-14-34-32.backup (password) --strugee2
Target "signalbackup-tools" is up to date, nothing to do.
signalbackup-tools (./signalbackup-tools) source version 20210730.230437 (OpenSSL)
TEMP FUNCTION 2 (#37)
[...]
Read entire backup file...
Tables present in backup:
sms
mms
part
thread
identities
groups
group_receipts
sticker
recipient
remapped_recipients
mention
Last message: INSERT INTO mms VALUES (5117,15,1622530623620,1622530629821,10485780,1,NULL,NULL,NULL,NULL,1,NULL,'','11',NULL,NULL,NULL,132,NULL,NULL,NULL,NULL,NULL,NULL,1,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,0,NULL,NULL,NULL,-1,0,0,0,0,0,NULL,NULL,-1,NULL,0,1,NULL,0,0,NULL,0,1622532975797,1622530626444,0,NULL,0,1622530630497,0,'0242b487-ad89-4e7f-9ca3-c164fe2504e9')

Note, this was a backup from June, the important tables (sms and mms) are right at the start here. On a backup from July:

signalbackup-tools (./signalbackup-tools) source version 20210730.230437 (OpenSSL)
TEMP FUNCTION 2 (#37)
[...]
Tables present in backup:
part
identities
groups
group_receipts
sticker
recipient
remapped_recipients
mention
thread
mms
sms
Last message: INSERT INTO sms VALUES (56636,24,27,1,NULL,1627578150028,1627578150028,-1,NULL,1,-1,10485783,NULL,1,NULL,'OK!',NULL,NULL,-1,0,0,0,0,1,NULL,0,-1,0,0,NULL)

As you see, the mms and sms tables are now at the end, if this backup was broken during the part-table, there would be no useful information in the file.

Note I was too lazy to actually parse the date of the last message. You'll see some numbers around 1627578150028, which is the timestamp of the message in milliseconds since UNIX epoch, so (on linux) date -d @1627578150 will give you a readable date. If you think about posting the output here, inspect that last line carefully, it will also contain the message body (in my case 'OK!').

[strugee]

Got a chance to rebuild and run with --strugee:

--strugee 117726415

TEMP FUNCTION (#37)
<key material omitted>
COUNTER: 453170439
Getting frame at filepos: 117726415


GOT GOOD MAC AT OFFSET 0 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 10855 frames... YEAH! :)
Good frame: 10855 (DatabaseVersionFrame)
COUNTER: 453181294
Frame number: 10855
        Size: 20
        Type: DATABASEVERSION
         - Version: 2720875916

--strugee 117726966

TEMP FUNCTION (#37)
<key material omitted>
COUNTER: 453170439
Getting frame at filepos: 117726966

GOT GOOD MAC AT OFFSET 0 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 339406 frames... YEAH! :)
Good frame: 339406 (SqlStatementFrame)
COUNTER: 453509845
Frame number: 339406
        Size: 553
        Type: SQLSTATEMENT
         - (statement: "INSERT INTO mms VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)" (148 bytes)
         - (uint64 parameter): "42855"
         - (uint64 parameter): "648"
         - (uint64 parameter): "1591140396508"
         - (uint64 parameter): "1591140396541"
         - (uint64 parameter): "23"
         - (uint64 parameter): "1"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (string parameter): "<plaintext message omitted>"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (string parameter): "836"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "128"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "18446744073709551615"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "18446744073709551615"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (uint64 parameter): "18446744073709551615"
         - (uint64 parameter): "18446744073709551615"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (uint64 parameter): "0"
         - (bool parameter)  : "true" (value: "1")

[strugee]

1. I was thinking about the decreasing counter in your log. Maybe you could (rip)grep for "FRAME 381124", see if it was actually found before as well?

Nope, just the one occurrence apparently.

2. I've added a second function to see what messages are in the good part of your database. Run with --strugee2 and inspect the output. Examples:

Veeeery interesting. Running with --strugee2 (without --verbose) produces the following output:

signalbackup-tools (./signalbackup-tools) source version 20210809.171715 (OpenSSL)
TEMP FUNCTION 2 (#37)
<key material omitted>
COUNTER: 453170439
Failed to read next frame (0 bytes at filepos 974090549)
Tables present in backup:
sms
mms
part (probably incomplete)
Last message: INSERT INTO mms VALUES (81222,579,1625012798763,1625012798793,10485783,1,NULL,NULL,NULL,'<plaintext message omitted>',0,NULL,NULL,'690',NULL,NULL,NULL,128,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,NULL,1,NULL,NULL,NULL,-1,0,0,0,0,1625011732815,'690','<plaintext message being replied to omitted>',-1,0,NULL,1,NULL,0,0,NULL,0,-1,-1,0,NULL,0,0,0,NULL)

The backup is from June 29th, 2021, which matches the timestamp in this row. Also clearly generated before https://github.com/signalapp/Signal-Android/commit/83086a5a2b8cae3ac40dea75d8c9533457a31858#diff-f9caa7b5d9e2dbdff5f21d16ca6f4aac7e10fd27c4f8608723c83a8d5cf7eec2 was committed upstream.

[bepaald]

Got a chance to rebuild and run with --strugee:

Thanks. That's interesting, I think it's doubling messages indeed. Not 100% sure though, that first frame looks a bit suspect (the 'DatabaseVersionFrame' is always the first frame, but obviously the actual version number is not a real version). The frame after that looks completely legit though. I'll write something up to check for the actual doubling as soon as I have some time.

Veeeery interesting. Running with --strugee2 (without --verbose) produces the following output: [...] The backup is from June 29th, 2021, which matches the timestamp in this row. Also clearly generated before signalapp/Signal-Android@83086a5#diff-f9caa7b5d9e2dbdff5f21d16ca6f4aac7e10fd27c4f8608723c83a8d5cf7eec2 was committed upstream.

That is very good news! That means all your messages are intact, only some attachments will be unrecoverable. I've already written a function to import them into an older backup (as long as that older backup has existing threads for the messages). It will be quite a process though:

• The function assumes a cropped backup, so you'd need to delete the broken part from the backup. From your first post I'm guessing $ truncate 1063873360 [brokenbackup] should do the trick. (do this on a copy if you want to keep the original!) (also, after cropping you could check with --strugee2 that I calculated that number correctly, output should be the same)
• The function assumes the intact backup is older (does not contain any messages that are not in the broken backup, in this case, since the commit we mentioned above, the newer file would be incompatible anyway because of the database format change). So use the original one you imported a week or so ago, not a newly exported one.
• Then run the program as follows signalbackup-tools [completebackup] [pwd] --sleepyh34d [truncatedbackup],[pwd] -o [output] (second pwd is optional if it's the same as the first). This should hopefully create a backup which is as close as possible in contents as the brokenbackup would have been if it wasn't broken. The option is called sleepyh34d because it was written for his issue, you might want to read a few of the messages in that thread for more info, starting here: https://github.com/bepaald/signalbackup-tools/issues/32#issuecomment-818597082
• Now, at this point, you should be able to import this backup and inspect it thoroughly (before you do this, export a fresh backup of your current installation and save it). If it seems to be okay, you could merge the newest messages (ones you got since 8 or so days ago). To do this, export the fixed backup again (to get it up to the same databaseversion). Then, to prevent having many messages (that are in both databases) doubled, you will probably want to crop the 'backup_with_latest_messages' first. To do this, first call --listthreads on the fixed backup, it will give timestamps for the first and last messages in the database, then use the 'Max date' to crop the other backup signalbackup-tools [backup_with_latest_messages] [pwd] --croptodates [MAXDATE]-9999999999999 -o [cropped_to_just_the_newest_messages]
• Then import the newest messages into it: signalbackup-tools [newly_exported_fixed_backup] [pwd] --importthreads all --source [cropped_to_just_the_newest_messages] --sourcepassword [pwd] -o [merged_output].

Something like that. Sorry that's quite an involved process, I hope I managed to write that in a way it makes sense. It should pretty much work, though it has only been done once before (see the other issue I linked), and in that case the final merge did not require cropping since they used a fresh install while waiting for the fix.

[bepaald]

Sorry, maybe hold off on the --sleepyh34d option above. I thought tonight that I might be able to slightly improve it for your situation specifically. Give me a few days to look it over closely and possibly make some adjustments.

[bepaald]

I'll write something up to check for the actual doubling as soon as I have some time.

Well, I at least got around to this. If you run with --strugee3 117726966, hopefully you'll see the file position where duplication happens. From my own example:

 $ ./signalbackup-tools broken [pwd] --strugee3 $((1108100821+944139))
signalbackup-tools (./signalbackup-tools) source version 20210809.171715 (OpenSSL)
TEMP FUNCTION (#37)
[...]
200 bytes at file position 36351712: 
(hex:) 00 00 01 ac 1f f3 59 4a 61 12 ce 82 4f 86 ff d7 ec 2e 1e 60 03 fd f2 b4 28 a6 87 d4 52 1a fd 01 27 a5 7f 1d 37 10 cb de 88 7d c0 55 b8 1a 47 ff ed dd 80 3f 0f 10 65 6a f1 9b e1 d3 7e 25 de cd 92 4a fd 80 48 97 56 cd 56 7c b5 c4 b5 46 69 56 29 fd c4 8b f8 b1 4e 18 2c 39 ec 15 b9 04 6e 2f 3d 16 ae 2c 13 1e dc 47 ab 79 d3 64 ce 90 69 a6 aa a0 2e fc 64 9a c7 10 f2 10 e2 3d 4e e1 c1 7f 51 73 8b 24 f4 fa d8 44 40 93 d1 07 df fc 19 d6 c1 40 84 81 8a b5 b5 cf ca 5f 3a 59 c3 13 96 81 c6 8c 15 2f 5f 7d 3e 24 9f ff 3d bb cf b5 d5 fa e5 20 e5 00 a9 e6 bd f4 e4 82 f3 30 c9 cc ae f7 99 7c f1 2b 60 f3 03 6a
200 bytes at file position 1109044960: 
(hex:) 00 00 01 ac 1f f3 59 4a 61 12 ce 82 4f 86 ff d7 ec 2e 1e 60 03 fd f2 b4 28 a6 87 d4 52 1a fd 01 27 a5 7f 1d 37 10 cb de 88 7d c0 55 b8 1a 47 ff ed dd 80 3f 0f 10 65 6a f1 9b e1 d3 7e 25 de cd 92 4a fd 80 48 97 56 cd 56 7c b5 c4 b5 46 69 56 29 fd c4 8b f8 b1 4e 18 2c 39 ec 15 b9 04 6e 2f 3d 16 ae 2c 13 1e dc 47 ab 79 d3 64 ce 90 69 a6 aa a0 2e fc 64 9a c7 10 f2 10 e2 3d 4e e1 c1 7f 51 73 8b 24 f4 fa d8 44 40 93 d1 07 df fc 19 d6 c1 40 84 81 8a b5 b5 cf ca 5f 3a 59 c3 13 96 81 c6 8c 15 2f 5f 7d 3e 24 9f ff 3d bb cf b5 d5 fa e5 20 e5 00 a9 e6 bd f4 e4 82 f3 30 c9 cc ae f7 99 7c f1 2b 60 f3 03 6a

It just prints the first 200 bytes from the location found (if a location is found), but a larger part of the file may be duplicated, the important part would be the position, you should be able to compare with any number of tools that the file is indeed (partly) duplicated.

Been a bit busy, but I'll get around to more work this weekend I hope.

[bepaald]

Sorry, maybe hold off on the --sleepyh34d option above. I thought tonight that I might be able to slightly improve it for your situation specifically. Give me a few days to look it over closely and possibly make some adjustments.

This is done. Although untested. But I'm hopeful it will do the trick.

[bepaald]

I assume this is done/no longer relevant. Not sure if all the custom function I write for this issue still work with current database versions. Feel free to open a new issue if necessary.