Restore fails with "Invalid data - SHA1 hash mismatch"

Bug #487720 reported by Andrew Fister on 2009-11-24
200
This bug affects 38 people
Affects Status Importance Assigned to Milestone
Duplicity
Medium
Unassigned
Déjà Dup
Critical
Unassigned
duplicity (Ubuntu)
Undecided
Unassigned
Lucid
Undecided
Unassigned
Maverick
Undecided
Unassigned
Natty
Undecided
Unassigned

Bug Description

When restoring a backup, one might see an error like:

Invalid data - SHA1 hash mismatch:
Calculated hash: 0b2bc4c2fb98b36f9891f9172f909d70ab5662e9
Manifest hash: 11cd330357618de52e4e5361a6e63b09ee951ae2

This can happen when a volume file was not completely written to the backend before duplicity was interrupted (say, shutting down the machine or whatever). When duplicity resumes the backup next run, it will start with the next volume. The half-complete volume file will sit on the backend and cause this error later when restoring.

You can manually recover from this by either restoring from your older backup sets or by restoring individual files that don't happen to be in the corrupted volume.

== To Reproduce ==

See attachment https://bugs.launchpad.net/ubuntu/+source/duplicity/+bug/487720/+attachment/2159465/+files/test.sh for a test script tor reproduce the problem.

== Ubuntu SRU Justification ==

This is a serious data loss problem for users, which won't be noticed until they try to restore. With Ubuntu 11.10 including Deja Dup, some users may think to back up their data first then upgrade, and may accidentally create corrupted backups.

Andrew Fister (andrewfister) wrote :
Michael Terry (mterry) wrote :

Ken, do you know what's going on here? Is this a case of a bad/stale archive-dir?

Andrew, could you post the manifest file here. I'd like to see if the failed backup caused something strange in the manifest. Just use the "add an attachment" link below. If it ends in .gpg, you'll need to decrypt it before posting. Thanks.

Andrew Fister (andrewfister) wrote :
Andrew Fister (andrewfister) wrote :

Took a while to get the log. I'll get the manifest now.

Andrew Fister (andrewfister) wrote :

Here is the manifest.

OK, I'm confused now! The log says you had just processed Volume 557, so you should be working on 558, yet the manifest hash in the error message matches the volume at 625 and the calculated hash does not match anything in the manifest at all.

I don't see how this is possible. You say the backup failed and then you restarted. Do you have the log from that?

Andrew Fister (andrewfister) wrote :

Sorry, I must have wonked something from the error message that I typed in my description of the bug. The error message in the log should have the correct hashes. Were you looking at those?

I don't have the log from the backup that I did. I know why it failed, though.

Basically, when you're doing a backup to a remote location(ssh) and then the computer suspends, the backup will keep going just fine if you resume the machine after a short time. However, if you wait too long, I think the server will sever the connection automatically. (As a side note, annoyingly, Ubuntu does not check for a timed out connection and unmount the connection in nautilus upon resume) Upon resuming the client from suspend, deja-dup/duplicity attempts to continue the backup, and then fails because the connection has timed out. So, that's how the backup failed. When I manually ran the backup again through Deja-Dup, it found the unfinished backup, scanned through the files to the current file being backed up, and continued as normal. This is how the backup got finished.

Andrew Fister (andrewfister) wrote :

The manifest hash in the log appears to match to Volume 625 in the manifest file. Not sure what that means...

Andrew Fister (andrewfister) wrote :

I fixed the hashes in my original description, so it should match now. Again, sorry about that.

description: updated
Changed in duplicity:
status: New → In Progress
importance: Undecided → Medium
assignee: nobody → Kenneth Loafman (kenneth-loafman)
Andrew Fister (andrewfister) wrote :

Is a workaround so that I can get this backup restored fully? It's rather important.

Changed in deja-dup:
status: New → In Progress
Matthew Twomey (mtwomey) wrote :

Is this maybe an issue with Duplicity not resuming an interrupted transfer properly? Andrew is archive volume 625 roughly the same file size (give or take a bit) as the others?

Andrew Fister (andrewfister) wrote :

Well, most of the surrounding volumes are 10mb. Volume 625 in particular is 3.1mb. I don't know if that's significant, but it seems an irregular size compared to the surrounding volumes.

Andrew Fister (andrewfister) wrote :

Actually, all of the surrounding volumes for that backup are 10mb. I assume this is a break point where the backup failed or something? Is there a way to manually bridge this gap so I can get this backup restored?

If a transfer failed, then there should be either no file on the remote end, or there should be a .part file, or something to differentiate it from a normally transferred file. This looks like a partial transfer. Does it have the correct name?

Andrew Fister (andrewfister) wrote :

There are no .part files in the backup directory.

I have generated a file list of the relevant files from the backup at issue. I'll attach it as a file, since it's long.

https://bugs.launchpad.net/duplicity/+bug/491971 is a related bug. Not sure at this point, but it may be a duplicate.

Changed in duplicity:
milestone: none → 0.6.07
Matthew Twomey (mtwomey) wrote :

This is exactly what I'm seeing in bug 491971. The transfer is interrupted and the file which was being transferred when the interruption occurred still remains out there with nothing to differentiate it from the other files. I don't believe openssh uses .part files or any form of temporary filename during transfers. So when Duplicity resumes, it sees that file and thinks it transferred ok and begins with the next file.

Andrew Fister (andrewfister) wrote :

That seems like exactly what happened.

Andrew Fister (andrewfister) wrote :

I was able to restore the files with this command:

duplicity restore --force --archive-dir ~/archive --tempdir /home/andrew/tmp --restore-time 2009/11/12 file:///media/disk/rachel/backup/tadpole ~/Pics

Even without the --force, it gets further(almost all the way done) than when I tried restoring just the Pictures directory with Deja Dup. I'm not sure why that is, but I thought it might be helpful to report it :-)

Matthew Twomey (mtwomey) wrote :

Did you end up restoring from a different backup? Just curious because of the --restore-time specification. Also - are you able to tell if all the files that were supposed to be in volume 625 were restored? When I had this issue, I was missing half the files in the archive volume which was interrupted.

Andrew Fister (andrewfister) wrote :

My original backup was done with Deja Dup, the front end to duplicity, restoring the same backup. I needed this one specifically, because after that date, the files I needed were removed from the client drive. In fact, it's the only backup that has the files I needed. One difference is that I specified a particular directory to be restored in Deja Dup, and that only restored a third of the directory I wanted. When I ran duplicity directly I decided not to specify a directory, and it got through most of the backup. If I don't have --force, it does crash with the error I report in the title of my bug report, but it was right near the end of the entire backup this time.

Matthew Twomey (mtwomey) wrote :

Got it, so possibly the files you needed weren't in volume 625 I would assume..

Changed in duplicity:
milestone: 0.6.07 → 0.6.08
Changed in duplicity:
milestone: 0.6.08 → 0.6.09
Tom Helner (duffman) wrote :

I have found that after getting this SHA1 hash mismatch error adding "--restore-time <any_timestamp>" to my command results in a successful recovery. It makes no difference if the restore-time is correct or not.

$ duplicity restore --file-to-restore duplicity_backup/test_file scp://<USER>@<BACKUP_HOST>//home/backup /tmp/test_file
Errors out with:
Invalid data - SHA1 hash mismatch:
Calculated hash: 2baf388b6e2e783a8c4321cdfbd2b0224f523790
Manifest hash: b12b24b7d87f51f681672abc2f1dc003b4fa2b55

But both of these commands work:
$ duplicity restore --file-to-restore duplicity_backup/test_file --restore-time 2010/06/16 scp://<USER>@<BACKUP_HOST>//home/backup /tmp/test_file
$ duplicity restore --file-to-restore duplicity_backup/test_file --restore-time 2000/01/01 scp://<USER>@<BACKUP_HOST>//home/backup /tmp/test_file

This is with duplicity 0.6.08b on Ubuntu 10.04

This bug and it's duplicate, https://bugs.launchpad.net/duplicity/+bug/491971, show one common thread. A partial ssh transfer is left in place on the remote, which causes duplicity to think that it has a full backup volume there. Most of the other transfers create a temp file or a .part file or use some other mechanism to distinguish partial from complete. It looks like ssh does not.

Is there a workaround to recover the data? I have the same problem having backed up my home director prior to giving a laptop back to my former employer. It's hopefully all there, but I can only access a small part of it.

Glen Fullmer (gfullmer-yahoo) wrote :

The workaround for me was as per the suggestion to use:

 --restore-time yyyy/mm/dd

 It might be related to a restarted backup as I restarted it again after the failure.

Martin Pool (mbp) wrote :

I also see this (or something a lot like it) when restoring from S3. It consistently fails at the same point.

Writing presentations/karl-lp-slides/.bzr/repository/pack-names of type reg
Writing presentations/karl-lp-slides/.bzr/repository/packs of type dir
Making directory /home/mbp/restore2/presentations/karl-lp-slides/.bzr/repository/packs
Writing presentations/karl-lp-slides/.bzr/repository/packs/333f31809d404f88307e43ab55aba6b6.pack of type reg
Deleting /tmp/duplicity-nZZdPB-tempdir/mktemp-G1Aa_U-107
Processed volume 104 of 119
Downloading s3+http://mbp.lithe.dy.sourcefrog.net//duplicity-full.20101017T064647Z.vol74.difftar.gpg
Invalid data - SHA1 hash mismatch:
Calculated hash: 0f562b0a57965ccde134263ebee44b8c07e630aa
Manifest hash: bfa0dc7844e1e565b8b34487e5832687d734cb9e

From my understanding of S3, I would not expect it to ever show just a partial file in place: uploads should appear atomically. However, I might be wrong, or there might be something in boto that causes this to happen.

Adding the current date to -t does not fix the problem. I'm going to try setting -t back to before the last increment.

Martin Pool (mbp) wrote :

If this is connected to resuming an interrupted backup, is there a way to tell duplicity to never do that, and instead to always start from scratch?

For now there is no way to keep it from doing a restart from the command line except by forcing a full, or by running 'duplicity cleanup --force'. Either way, a cleanup would have to be done eventually.

Changed in duplicity:
milestone: 0.6.09 → none
Daniel T. (pterion) wrote :

Can one make duplicity to utilize filepart protocol as does e.g. WinSCP, so that the file will have the extension .filepart or similar while it's being downloaded and renamed only when it's upload completes?

Michael Otto (michael-astrapi) wrote :

the same problem (SHA1 hash mismatch) on my nas (wd mybook):

create backup from nas -> restore in nas -> mismatch
create backup from ubuntu (10.10) -> restore on nas -> OK
create backup from nas -> restore on ubuntu (10.10) -> mismatch

means: the upload to my ftpserver failed, not the restore!

Michael Otto (michael-astrapi) wrote :

On my nas, i run 'duplicity -v 9 source file:///target', comes the error 'GPG process 30608 terminated before wait()' after 'AsyncScheduler ...'. The files sigtar.gpg and manifest.gpg ar 0 KB.

Hi!

I met the same problem on NAS Synology DS410 and I fixed it by modifying the source code of duplicity in order to use MD5 hash system instead of SHA1.

For this, I edited the following files:
- src/gpg.py
- src/manifest.py
- duplicity

I'm attaching the edited files on this message.

Actually, I still don't know the source of the problem, put it shows that it could be useful for duplicity adding an option to choose the hash method.

Patrick Allemann (pallemann) wrote :

Hi,

I have encountered the same issue - If a backup was interrupted, a file is being left over in the loval cache preventing a restore until the cashe is flushed ot the file is manually deleted. A detail which is a bit more critical about this issue is that the file that was being backupped at the time of the interruption seems to be hashed in the signature file and will not be backupped in any of the following inc-runs. I was able to test is by creating a large file (couple of hundred MBs) being backupped. After an initial full backup I modified the file and ran an incremental backup pulling out the network during the backup. Re-starting the incremental backup showed that nothing had to be uploaded - the modified file was therefore never fully uploaded to the server.

This might create a hole in your backup...

I have encountered the same issue while backing up a large dataset to a local disc, using the file:// protocol.
(duplicity 0.6.10). I must say it scares me a little. Does the file:// protocol use ssh internally?

Kieran Hogg (xerosis) wrote :

Just to add to this bug, I'm now seeing this with a backup over smb://. I resumed my initial backup and now restoring ANY file is giving this error.

Michael Terry (mterry) on 2011-06-06
Changed in deja-dup:
importance: Undecided → Critical
status: In Progress → Confirmed
Michael Terry (mterry) wrote :

Here's a test script to reliably trigger the bug. It basically interrupts a backup and replaces the last volume with junk (ala interrupting a backup when it's writing the last volume). It's a forced trigger of the bug (i.e. it doesn't recreate it naturally as doing so would be racy).

This bug can be hit with the gio backend (i.e. any remote server through Deja Dup), the local backend (file://), and apparently the s3 backend? Possibly others too.

I have a hacky fix for this, which is to just always redo the last block when restarting a backup. We're talking about the best approach on the mailing list.

Changed in duplicity:
milestone: none → 0.6.14
assignee: Kenneth Loafman (kenneth-loafman) → nobody
status: In Progress → Fix Committed
Michael Terry (mterry) on 2011-06-14
Changed in deja-dup:
status: Confirmed → Invalid
Changed in duplicity:
status: Fix Committed → Fix Released
Manolis Kapernaros (kapcom01) wrote :

Hello, I filed a new bug https://bugs.launchpad.net/duplicity/+bug/826389
Maybe its a duplicate of this this one. If it is can you help me apply the fix? I am in a hurry restoring my files..
Thanks.

Manolis Kapernaros (kapcom01) wrote :

I downloaded Duplicity 0.6.14 source and installed it but nothing changed...

Michael Terry (mterry) on 2011-08-16
Changed in duplicity (Ubuntu):
status: New → Fix Released
Michael Terry (mterry) wrote :

I'm going to prepare an SRU for Ubuntu for this, since it can silently corrupt your backup. I'll update the description shortly with SRU justifications. Ken, hope you don't mind the noise, it just made sense for me to use the same bug since all the history is here.

Michael Terry (mterry) on 2011-08-16
description: updated
Changed in duplicity (Ubuntu Lucid):
status: New → Confirmed
Changed in duplicity (Ubuntu Maverick):
status: New → Confirmed
Changed in duplicity (Ubuntu Natty):
status: New → Confirmed
Michael Terry (mterry) wrote :

I've uploaded packages for lucid, maverick, and natty to -proposed.

Hello Andrew, or anyone else affected,

Accepted duplicity into natty-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

Changed in duplicity (Ubuntu Natty):
status: Confirmed → Fix Committed
tags: added: verification-needed
Changed in duplicity (Ubuntu Maverick):
status: Confirmed → Fix Committed
Clint Byrum (clint-fewbar) wrote :

Hello Andrew, or anyone else affected,

Accepted duplicity into maverick-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

Changed in duplicity (Ubuntu Lucid):
status: Confirmed → Fix Committed
Clint Byrum (clint-fewbar) wrote :

Hello Andrew, or anyone else affected,

Accepted duplicity into lucid-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

Mike O'Donnell (mikeodonnell) wrote :

Hello Michael Terry

I ran your test in my lucid system after enabling duplicity-proposed and found no errors. I still have Lucid's Duplicity with no PPA.

Michael Terry (mterry) on 2011-09-15
tags: added: verification-done
removed: verification-needed
Clint Byrum (clint-fewbar) wrote :

Hi everybody, I'm setting the bug back to verification-needed .. while it was verified on lucid, it also needs to be independently verified on maverick and natty still.

tags: added: verification-done-lucid verification-needed
removed: verification-done
Martin Pitt (pitti) wrote :

@Clint: I added back v-done. If a bug has both -needed and -done, it'll appear in purple on sru-report. That means ubuntu-sru has to manually check which releases can go to -updates and which not, but that way we avoid blocking on e. g. maverick verification for the lucid update.

tags: added: verification-done
Miklos Juhasz (mjuhasz) wrote :

I have tested duplicity from Natty Proposed Repository and it did fix the bug. Works fine.

I ran: https://bugs.launchpad.net/ubuntu/+source/duplicity/+bug/487720/+attachment/2159465/+files/test.sh
and got the message: Yay! We didn't hit the bug!

Before the upgrade of duplicity from the proposed repository I ran the same test and I got the message: Guh! We hit the bug!
so I was able to reproduce the bug.

Martin Pitt (pitti) on 2011-09-29
tags: added: verification-done-natty
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package duplicity - 0.6.13-0ubuntu1.1

---------------
duplicity (0.6.13-0ubuntu1.1) natty-proposed; urgency=low

  * debian/patches/06shamismatch.dpatch:
    - Fix possible backup corruption bug when resuming backups
      LP: #487720
 -- Michael Terry <email address hidden> Tue, 16 Aug 2011 13:37:37 -0400

Changed in duplicity (Ubuntu Natty):
status: Fix Committed → Fix Released
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package duplicity - 0.6.08b-0ubuntu2.1

---------------
duplicity (0.6.08b-0ubuntu2.1) lucid-proposed; urgency=low

  * debian/patches/04dontrestoresameblock.dpatch:
    - Fix possible backup corruption bug when resuming backups
      LP: #613244
  * debian/patches/06shamismatch.dpatch:
    - Fix another possible backup corruption bug when resuming backups
      LP: #487720
 -- Michael Terry <email address hidden> Tue, 16 Aug 2011 14:15:12 -0400

Changed in duplicity (Ubuntu Lucid):
status: Fix Committed → Fix Released
Martin Pitt (pitti) on 2011-09-29
tags: removed: verification-done
Michael Terry (mterry) wrote :

I thought I'd write a little HOWTO on recovering from this bug, in case people hit it from using versions that aren't fixed. It won't be able to restore all original files, but you can restore most.

The central issue is that one or several of the backup volumes will be corrupted and likely not the correct size. So the first step is to identify which ones. The second step will be to restore everything *but* the files that are supposed to be in that volume.

Step 1: Identify corrupted volumes

A) Find your manifest file. If you did not encrypt your backup, it will end in ".manifest". If you did, it will end in ".manifest.gpg" and you will first have to run "gpg --decrypt MANIFESTFILE" to decrypt it.

B) Search for the provided "Manifest hash" in the error message. It will be a string like "11cd330357618de52e4e5361a6e63b09ee951ae2". This will show you which volume is corrupted.

C) In this same volume block, you can see "StartingPath" and "EndPath". This is the range of files that are supposed to be in that volume. You won't be able to get these back. :-/

Step 2: Restoring all other files

D) Using Deja Dup, you can restore many files at once by using either the "lost files" method [1] or the "revert files" method [2]. Make sure you avoid trying to restore any file that you found to be inside a corrupted volume.

[1] http://live.gnome.org/DejaDup/Help/Restore/LostFile
[2] http://live.gnome.org/DejaDup/Help/Restore/Revert

Manolis Kapernaros (kapcom01) wrote :

hello, i have an old corrupted backup and i decided to restore everything i can into a separate folder. I ran: duplicity restore file:///path/to/backup /target/folder and the restore began. After a while it failed with the following message:

Invalid data - SHA1 hash mismatch for file:
 duplicity-full.20110808T175923Z.vol246.difftar.gpg
 Calculated hash: 7d96fd9b424f777e795c40f29f0cc88c7d87ec3d
 Manifest hash: a102c548ef930c7a928f9519dbc5ea5f59441ebb

So, how can I exclude the corrupted volume with duplicity command?

tomx (tom-xitio) wrote :

I ran into the same problem. duplicity version 0.6.15 (might have been 0.6.14 when doing the backup).
I used backintime for years until december 2011, found deja dup, and deleted the plain backup after a successful backup with deja dup.
What a mistake.

After an update the system broke and was not bootable.
No problem, as i assumed the backup was there.

I ran into the SHA1 mismatch issue. I have 699 .difftar.pgp files out of which 7 could not be processed with duplicity.
I tried out the instructions from https://live.gnome.org/DejaDup/Help/Restore/WorstCase (Thanks for those MichaelTerry!) and was relieved when I saw the folders reappearing.

Micheal's instructions take you to the point where the files are spread onto two folders multivol_snapshot and snapshot , the first one containing one folder per file, which then contains 64kb parts of the actual file.

As I wanted to restore as much - and as good - as possible, I looked for scripts that do the 'cat' automatically .

I found 2 or 3 scipts, and I tested the one from here
https://gist.github.com/1365425
on the 70GB of original data. One run takes several hours.

It creates the files, but something goes wrong.
Lets say an Image was spread on 4 blocks. If I want to view that image, half of it looks ok, the rest ist missing. Or the image looks picassofied. Funny, at times if
*it just wasn't the only backup of past 10 years*
This person describes a similar behavior.
https://bugs.launchpad.net/duplicity/+bug/713832/comments/1

I don't mind loosing business docs, even if not all of them are in the companies data centre.
I don't mind loosing many hundreds of source code files, I am sure I can redo that.
But the pictures?

So obviously the question is: Is there a chance to reassemble the blocks in a way that the resulting jpeg files are not corrupted?
Or alternatively: Does anyone know a data curation solution that detects such corruptions?

Possibly the data is present, at least for 70,80,(95?) % and it is the recombining of the blocks that creates the problem.
Truly, any help and hints appreciated.

papukaija (papukaija) wrote :

Please open a new question for your issue. Thanks.

ubby (kostas-sytske) wrote :

I also have this bug agean:
Invalid data - SHA1 hash mismatch for file:
 duplicity-inc.20111106T102651Z.to.20111213T090632Z.vol9.difftar.gz
 Calculated hash: 4bdbd1f52c07593da62c276e0aa343d8ff3b555f
 Manifest hash: 5d9e6492392576d22baf0eeac67d88e04cf23495
 I am using Ubuntu 11.10 64 bit with Deja Dup.

The backups are made with Ubuntu 11.10 32 bit.

Rainshoots (astyh83) wrote :

I have the same problem.

Invalid data - SHA1 hash mismatch for file:
duplicity-inc.20140424T053227Z.to.20140508T021212Z.vol51.difftar.gz
Calculated hash: e28fd59e70f82bb126eb76b0c76b807cc03f5b27
Manifest hash: 38e4dd60b6aac680493f03d8c8a3145474d45907

I could not fall back to a previous backup because one tar.gz file was missing.

Could someone please help out with this? I just did a clean install of Trusty because upgrade failed. Now I can only get 50% of my files back.

Most importantly, I have been working on Zotero for weeks and it stopped working.

Database upgrade error

[Exception... "Component returned failure code: 0x8052000b (NS_ERROR_FILE_CORRUPTED) [mozIStorageConnection.executeSimpleSQL]" nsresult: "0x8052000b (NS_ERROR_FILE_CORRUPTED)" location: "JS frame :: chrome://zotero/content/xpcom/db.js :: Zotero.DBConnection.prototype.query :: line 149" data: no] [QUERY: DELETE FROM itemTypeFieldsCombined] [ERROR: database disk image is malformed]

Rolf Leggewie (r0lf) wrote :

maverick has seen the end of its life and is no longer receiving any updates. Marking the maverick task for this ticket as "Won't Fix".

Changed in duplicity (Ubuntu Maverick):
status: Fix Committed → Won't Fix
The Great Gazauga (eanbowman) wrote :

This is absolutely still an issue in the latest versions of Ubuntu.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers