Closed MartB closed 2 years ago
MartB
commented
2 years ago Yep i can confirm after skipping over the avatar frames here: https://github.com/bepaald/signalbackup-tools/blob/c200d3d99cce19bf57ced2765e8d4ff69f15cb09/signalbackup/initfromfile.cc#L111 Got me all the other data back, now the groups / users seem to not have any avatars but i hope this will automagically fix itself.
Could be worth a shot to provide a --remove or ignore-avatars option.
bepaald
commented
2 years ago Hi thanks for this report!
I've pushed a fix for this, which automatically skips frames with corruption on write. This should have been default behavior, but was recently accidentally removed when I switched to the faster, less memory hungry, way of reading the backups. It should now simply skip single bad frames, while still being efficient, and automatically switch to full fixing mode when data corruption is more serious (i.e. bad data continues into the next frame).
One reason that this has gone unnoticed (I'm guessing) is because the Android app these days should actually be tolerant of this type of error, skipping the frame on import itself. But maybe it only does that with attachment data (and not avatars data)? Could you confirm that Signal refused to import the original backup?
If you have the time, I wouldn't mind if you ran the broken backup through the program again and let me know the output. I understand re-importing may be a hassle, so don't feel obligated. But, if you want to, I'd love to hear the results. If everything works, I suspect you will have all your avatars (except one) back. But I indeed think the missing ones will automagically reappear eventually.
Thanks!
MartB
commented
2 years ago @bepaald Sure thing as the avatars did not re-appear i might aswell try it again. The android app went through on the original but failed at the very last second with BAD MAC.
After restoring the "fixed" backup i made with the ugly hack from above the avatars are not coming back, so something is def. borked here. It tries to load an attachment but fails to do so and never tries to remove the entry from the database? or re-request it again.
Edit: There seems to be slightly more "borked" content in there:
signalbackup-tools (./signalbackup-tools) source version 20220218.171943 (OpenSSL)
IV: (hex:) 1a 99 59 d5 a2 b2 68 f1 aa b7 d9 70 ff 24 b7 aa (size: 16)
SALT: (hex:) 79 1c 81 6d aa 7d 7f 79 38 c9 ea 0a b2 6d 94 23 82 95 67 29 41 c4 38 ce 66 bc 5e 2f 29 c4 ad cf (size: 32)
BACKUPKEY: (hex:) 62 c3 77 0f 8c cb 10 b2 b8 5d 2c 28 c6 b7 fd 0a 9a a3 f4 0e d0 c8 99 58 85 ec 6d 42 43 56 4f de (size: 32)
CIPHERKEY: (hex:) fc e7 d3 8c f4 2b b9 b3 ac b3 4c 63 c7 18 6d 4e 12 c4 8c 53 e9 fa 01 42 e4 a8 d3 14 aa 1a cf 3a (size: 32)
MACKEY: (hex:) 92 3e f1 a0 75 4e 42 04 1e 8a 1e 86 4d 4a 05 07 50 09 57 7c 3c f7 06 41 79 0d 29 bb 6e 7c aa 87 (size: 32)
COUNTER: 446257621
Reading backup file...
FRAME 158847 (099.9%)...
WARNING: Bad MAC in frame: theirMac: (hex:) 94 40 ab 23 16 16 09 0a f2 c8
ourMac: (hex:) 4f 70 e6 0d 77 c9 09 e0 b3 01 cc 26 53 45 e6 69 b0 22 55 fc 72 3c b2 4d 3d ea 38 6f 4b dc e7 67
Failed to get valid frame from decoded data...
Encrypted data had failed verification (Bad MAC)
Starting bruteforcing offset to next valid frame... starting after: 4061736951
Checking offset 4140 bytes
GOT GOOD MAC AT OFFSET 4143 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 38 frames... YEAH! :)
Good frame: 158887 (SqlStatementFrame)
Frame number: 158887
Size: 90
Type: SQLSTATEMENT
- (statement: "INSERT INTO reaction VALUES (?,?,?,?,?,?,?)" (43 bytes)
- (uint64 parameter): "1545"
- (uint64 parameter): "17525"
- (uint64 parameter): "1"
- (uint64 parameter): "3"
- (string parameter): "😮"
- (uint64 parameter): "1626640518074"
- (uint64 parameter): "1626640519752"
Got frame, breaking
FRAME 160777 (100.0%)... Failed to read next frame (1518067352 bytes at filepos 4063678566)
Starting bruteforcing offset to next valid frame... starting after: 4063678566
Checking offset 258560 bytes
GOT GOOD MAC AT OFFSET 258568 BYTES!
Now let's try and find out how many frames we skipped to get here....
Checking if we skipped 2 frames... YEAH! :)
Good frame: 160780 (AvatarFrame)
Frame number: 160780
Size: 8
Type: AVATAR
- length : 33144 (8 bytes)
- recipient : 58 (2 bytes)
Got frame, breaking
FRAME 160781 (100.0%)... Read entire backup file...
done!
Exporting backup to 'fixed-signal-022-02-17-02-21-56.backup'
Writing HeaderFrame...
Writing DatabaseVersionFrame...
Writing SqlStatementFrame(s)...
Dealing with table 'part'... 4607/10435 entries...Warning: attachment data not found (rowid: 4805, uniqueid: 1626907075034)
Dealing with table 'part'... 4608/10435 entries...Warning: attachment data not found (rowid: 4806, uniqueid: 1626907099995)
Dealing with table 'part'... 4624/10435 entries...Warning: attachment data not found (rowid: 4822, uniqueid: 1626956499308)
Dealing with table 'part'... 4625/10435 entries...Warning: attachment data not found (rowid: 4823, uniqueid: 1626957855243)
Dealing with table 'part'... 4629/10435 entries...Warning: attachment data not found (rowid: 4827, uniqueid: 1626959138598)
Dealing with table 'part'... 4867/10435 entries...Warning: attachment data not found (rowid: 5081, uniqueid: 1627506750870)
Dealing with table 'part'... 5460/10435 entries...Warning: attachment data not found (rowid: 5702, uniqueid: 1629740252271)
Dealing with table 'part'... 9225/10435 entries...Warning: attachment data not found (rowid: 9699, uniqueid: 1641569273351)
Dealing with table 'part'... 10435/10435 entries...done
Dealing with table 'drafts'... 0/0 entries...
Dealing with table 'push'... 1/1 entries...done
Dealing with table 'groups'... 5/5 entries...done
Dealing with table 'recipient'... 57/57 entries...done
Dealing with table 'group_receipts'... 50566/50566 entries...done
Dealing with table 'sticker'... 334/334 entries...done
Dealing with table 'storage_key'... 0/0 entries...
Dealing with table 'mention'... 429/429 entries...done
Dealing with table 'remapped_recipients'... 1/1 entries...done
Dealing with table 'remapped_threads'... 0/0 entries...
Dealing with table 'payments'... 0/0 entries...
Dealing with table 'chat_colors'... 0/0 entries...
Dealing with table 'emoji_search'... 0/0 entries...
Dealing with table 'sender_key_shared'... 0/0 entries...
Dealing with table 'pending_retry_receipts'... 0/0 entries...
Dealing with table 'msl_payload'... 2587/2587 entries...done
Dealing with table 'msl_recipient'... 5649/5649 entries...done
Dealing with table 'msl_message'... 2881/2881 entries...done
Dealing with table 'thread'... 22/22 entries...done
Dealing with table 'mms'... 35439/35439 entries...done
Dealing with table 'sms'... 38067/38067 entries...done
Dealing with table 'avatar_picker'... 0/0 entries...
Dealing with table 'identities'... 17/17 entries...done
Dealing with table 'group_call_ring'... 0/0 entries...
Dealing with table 'sender_keys'... 0/0 entries...
Dealing with table 'reaction'... 3328/3328 entries...done
Dealing with table 'notification_profile'... 1/1 entries...done
Dealing with table 'notification_profile_schedule'... 1/1 entries...done
Dealing with table 'notification_profile_allowed_members'... 4/4 entries...done
Writing SharedPrefFrame(s)...
Writing KeyValueFrame(s)...
Writing Avatars...
WARNING: Bad MAC in attachmentdata: theirMac: (hex:) dc 9c 33 3a 9d 4b 85 55 0e 9b
ourMac: (hex:) 5d 4e 1e 31 f2 31 ba 30 c1 6b bc 50 6d 94 34 21 fd 9b e4 f4 81 85 69 85 f9 51 78 4c 92 61 5a 6b
WARNING : Corrupted data encountered. Skipping frame.
WARNING: Bad MAC in attachmentdata: theirMac: (hex:) 71 ca e5 b5 d4 7b e7 d3 c1 84
ourMac: (hex:) 20 03 9b 1b 68 e5 01 90 92 35 14 9c ae 4f ff da 64 e3 e6 a8 0c 1b 55 88 5b a1 6c 37 ba ca ef 20
WARNING : Corrupted data encountered. Skipping frame.
WARNING: Bad MAC in attachmentdata: theirMac: (hex:) 95 a8 6e 00 ac 8f f2 e8 1a d1
ourMac: (hex:) 3b c7 3e 62 d8 f9 f9 1c 75 30 ff 27 d0 fc d8 53 71 44 cc 33 27 30 bd 4b 8a 8c 59 e9 be 03 36 b5
WARNING : Corrupted data encountered. Skipping frame.
WARNING: Bad MAC in attachmentdata: theirMac: (hex:) 66 1c f9 21 eb 8a ed 63 22 d6
ourMac: (hex:) f9 de 4b 59 16 3a 5c 8c d4 3d 3b 2b 63 b1 d5 8a b3 46 96 d6 df dd a8 f2 ef 2c 33 72 9c 6d e1 d2
WARNING : Corrupted data encountered. Skipping frame.
Writing EndFrame...
Done!Actually im not sure it would change anything if i now re-imported that, as this just "skips" the frames only right? Something is telling signal that the avatar profile data is loaded and i kinda need to re-set this so it gets the correct parts again...
02-18 13:02:24.674 4872 4872 D BaseActivity: [MainActivity] onStart()
02-18 13:02:24.674 4872 4872 D LoggingFragment: [ConversationListFragmen] onStart()
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: null
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: java.io.IOException: No stream for: AttachmentId::(10914, 1644653043437)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at org.thoughtcrime.securesms.database.AttachmentDatabase.getAttachmentStream(AttachmentDatabase.java:208)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at org.thoughtcrime.securesms.mms.PartAuthority.getAttachmentStream(PartAuthority.java:73)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at org.thoughtcrime.securesms.mms.PartAuthority.getAttachmentThumbnailStream(PartAuthority.java:64)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at org.thoughtcrime.securesms.mms.DecryptableStreamLocalUriFetcher.loadResource(DecryptableStreamLocalUriFetcher.java:45)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at org.thoughtcrime.securesms.mms.DecryptableStreamLocalUriFetcher.loadResource(DecryptableStreamLocalUriFetcher.java:19)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at com.bumptech.glide.load.data.LocalUriFetcher.loadData(LocalUriFetcher.java:44)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at com.bumptech.glide.load.engine.SourceGenerator.startNextLoad(SourceGenerator.java:70)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at com.bumptech.glide.load.engine.SourceGenerator.startNext(SourceGenerator.java:63)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at com.bumptech.glide.load.engine.DecodeJob.runGenerators(DecodeJob.java:310)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at com.bumptech.glide.load.engine.DecodeJob.runWrapped(DecodeJob.java:279)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at com.bumptech.glide.load.engine.DecodeJob.run(DecodeJob.java:234)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at java.lang.Thread.run(Thread.java:920)
02-18 13:02:24.685 4872 28135 W DecryptableStreamLocalU: at com.bumptech.glide.load.engine.executor.GlideExecutor$DefaultThreadFactory$1.run(GlideExecutor.java:393)@bepaald Any idea which database magic is causing this to "remember" the attachment?
bepaald
commented
2 years ago Thanks for reporting back. Looking at the output it does seem like the program does what I wanted it to. And I can also see it successfully recovers from some corrupted frames earlier in the file. Just looking at the output, I would have guessed this was a good, working backup file.
I'm a bit confused about your last message, is that a log of the original fixed import, or the new fixed import? Does the app actually crash when you see this, or is it a caught and properly handled exception? What exactly are you doing when this exception occurs?
It looks to me like this exception is not about a missing avatar, but about a missing message attachment (AttachmentId::(10914, 1644653043437)). Attachments are identified by rowid and uniqueid (the latter is really just a timestamp), these values are stored in the 'part' table of the database. which for your backup seem to fit this range. What is strange however is
Unfortunately I'm not at home at the moment, so I can't really investigate thoroughly right now. But, I'd say, as long as the first fixed backup is no good anyway, try importing the new fixed backup and see if it makes a difference. Also, you could run signalbackup-tools [fixed input] [password] --runsqlquery "SELECT * FROM part WHERE _id = 10914 AND unique_id = 1644653043437", and see if there is indeed an entry for this attachment.
Something is telling signal that the avatar profile data is loaded
I would have to investigate, but I know there are things related to the profile (most notably 'signal_profile_avatar') in the 'recipient' table. Note also that profiles (and avatars) are not always immediately downloaded, I think that happens on some sort of timer.
When I get back home tomorrow, I will first remove some avatars from a backup to see if I can cause a crash (though I don't think so). And I'll think about this problem some more and hopefully think of some more things to try and fix this.
MartB
commented
2 years ago @bepaald thanks for taking the time to do some research.
I have to clarify that signal does not crash due to the avatars if removed, they just default display. The new backup most likely works but it would probably also cause the missing parts to be "stuck" in this java.io.Exception loop. Thats precisely the kind of thing we can try to fix / work around with some sql magic hopefully.
Imma try to take a look at the db / signals source later and see if i can find how to reset the profile / group icon state so it fetches it again.
* Executing query: SELECT * FROM part WHERE _id = 10914 AND unique_id = 1644653043437
(no results)Edit2:
From checking the signal source code i found two options upon import:
1) clearing signal_profile_avatar (setting it to NULL) or
2) invalidating the recipient id of the avatar (not possible if we just discard the frame)
only 1) seems to be worth a shot if the avatar frame is "broken" it has to be marked as such. Confirmed working for profiles, groups still have no icons tho.
Im going to try clearing avatar_id in groups and see what happens.
bepaald
commented
2 years ago Still not home and not investigated, but just off the top of my head:
Every contact and group has an entry in the 'recipient' table. In the recipient table exists a column 'last_profile_fetch'. I suspect this is just a timestamp, which is hooked to the timer that occasionally downloads profiles. Maybe - if you've not been successful already - try setting this to zero (UPDATE recipient SET last_profile_fetch = 0), so the app thinks the profile needs re-fetching. It is also possible (if I had designed this I would have made it so) that when the timer fires, it only downloads some key that shows whether the profile has actually changed instead of immediately downloading the entire thing, so there is probably some other value that needs clearing for this to work (if t works at all). We might need to look at the source to figure that out.
Well, I'm off to work. Good luck!
bepaald
commented
2 years ago Sorry for the delay. Have you tried anything, and did it work?
I prepared a backup with the avatars removed. This is a small backup, with only three recipients with an avatar (two groups and one individual). After some playing and clearing various entries in the database, the closest I got was using "UPDATE recipient SET last_profile_fetch = 0, signal_profile_avatar = NULL", and then restoring the backup. Clearing the _profilekey seemed to cause problems, and clearing anything in the groups table doesn't seem to help (in fact, all avatar-related fields in that table were already empty).
After restore, 2 of the three (one group and the individual) avatars immediately reappeared. The third did not (and still has not, this was yesterday). I do not know if there something weird that causes the last one to not appear, or if there is something weird that causes the other two to. So, you could try doing the same, maybe you will get lucky.
If it doesn't work, I'm out of ideas for now, but it should actually be fairly easy to import the avatar from a different (older, non-broken) backup if you have one. Let me know if we need to work on that.
Lastly, I can at least confirm that if the profile-avatar is changed, it will update anyway. So, depending on your relationship with the people in the group, you could also just ask someone to update it (and change it back if necessary).
MartB
commented
2 years ago Yeah i ran a similar sql query to clear the profile avatars, this ended up re-fetching okay. Group avatars indeed did not get re-fetched even after playing with the table, i got all the groups to manually change pictures though, so thats fine hehe
This issue can now be closed and kept as reference, as i assume its a pretty niche error. If you really wanted to you could add some quick "clear" avatar functionality if an avatar frame is corrupt, but i will leave that up to you :)
Thanks for this project and your continous effort @bepaald i really appreciate it! 🚀
bepaald
commented
2 years ago Yeah i ran a similar sql query to clear the profile avatars, this ended up re-fetching okay. Group avatars indeed did not get re-fetched even after playing with the table, i got all the groups to manually change pictures though, so thats fine hehe
Excellent
This issue can now be closed and kept as reference, as i assume its a pretty niche error. If you really wanted to you could add some quick "clear" avatar functionality if an avatar frame is corrupt, but i will leave that up to you :)
Yeah, I think that's not a bad idea, even if hardly anyone ever runs into this. I'm glad at least the program did what it was meant to (make an unrestorable backup restorable), but clearing the avatar data in the sqlite database would be a nice feature as long as I can determine automatically which contacts' data needs to be cleared. If I can't and users need to do it manually anyway, I think the runsqlquery option will suffice for this rare case. I'll put it somewhere in the to-do list.
Thanks for this project and your continous effort @bepaald i really appreciate it!
Thanks for your kind words. Happy to help!
Hey i tried to repair my backup file but it somehow fails to export with
If i use
--stoponbadmacHow can i still export the stuff thats "working" in this database?
I assume this is somehow related to avatar data being damaged?