restic: Hash does not match id during prune

@fd0 is it useful for you if I complete the fix procedure? It seems it is really taking long.

Ah, yeah, it depends a lot on how large the broken blob is (and on your CPU, obviously). You don’t need to run it, it was just a quick test.

So, here comes my analysis, the prerequisites are:

• During backup, restic wrote a bunch of blobs into a file, appended an encrypted header and the length of the header, then saved the file to the backend with the SHA256 hash as the file name
• Reading back the data later, it has a different SHA256 hash
• Each blob as well as the header is encrypted and signed, so we can test each blob (and the header) for modification separately by checking the signature

From the test code’s output we know:

• restic can successfully read the header length and the header and decrypt it, so the header length and the header are both intact
• From the contents of the header we know how long the blobs in the file are, so we can read them one by one and check the signature
• Most blobs are intact, exactly one of them (for both repos discussed in this issue) does not verify, so it probably has been modified at some point somewhere
• The data before and after the bad blob is unmodified

In summary, for both repos, a part of a file was modified. The following observations assume that the modification has happened accidentally (i.e. not on purpose by an attacker).

The modification may have happened within restic or outside of it. What I’ve seen so far makes makes me think it’s very unlikely that the modification of the data has happened within restic. The reasoning is as follows:

• During backup, restic reads a blob from a file, hashes it, and if it is not yet stored in the repo, encrypts it and writes it to a temporary file which later is saved to the repo. If the modification happened before encryption, the signature would match, so it must have happened after encryption.
• For the name the file is saved as in the repo, restic calculates the SHA256 hash while it writes data to the file. If the modification has happened after encryption of the blob, but before it is written to the file (and the SHA256 hash is updated), the SHA256 hash would match. This is not the case, the hash is wrong, so it must have happened after writing it to the file.
• Therefore, I think the modification must have happened after restic was almost done with the file. When restic considers a file to be “full enough”, it’ll append the header, the header length, reads back the whole file and saves it to the repo. The modification could have happened after writing the data to the file, before (or during) saving it to the repo. At this point, restic is only streaming data from a file to a backend (e.g. over HTTP(s) or to another file), the program logic is rather simple.

I’m at a loss what happened here, and I’m sorry, but what I see from the result of the analysis makes me think it’s a fault outside of restic, i.e. harddisk, memory, or a network error. If it were a bug in restic (which is entirely possible!), then I would have expected it to appear much more often for the huge sets of data restic processes for various users (~1TB of data, with at most 600KB modified for @askielboe)…

For @carlonluca (repo mounted via CIFS from a server, stored on ext4 there), the modification may have been caused by the following issues:

• RAM on the source machine
• RAM on the CIFS server
• Storage device on the CIFS server
• Network error between source machine and server (I’m not sure if data transferred via CIFS is authenticated, maybe we can rule this one out)

For @askielboe (repo accessed via sftp, stored on a NAS):

• RAM on the source machine
• RAM on the NAS
• Storage device on the NAS

We can rule out a network error here because sftp is used through SSH, which authenticates data.

I’m not sure what to do next here. Ideally, I’d love to get the results of memtest86 for all machines involved… but that’ll be time-consuming and (in case of @askielboe’s NAS) maybe not even possible…

We can also try to examine the damage a bit more closely, by decrypting the broken blob while disregarding the signature. If it’s something from a file format that is readable without the context (or we can even find the source file on your machines), we would be able to see how many bytes have been modified and in which way exactly. I’m not sure if that helps.

So, what do you think? Is there anything I missed, or any conclusions I got wrong?

What are your thoughts on handling these cases in restic? Are there any meaningful paths that we could take to improve the user experience when repo data gets corrupted?

Oh yes, absolutely! restic needs to handle such cases a lot better. When the hash does not match for a file, this is just an indication that something is wrong, it should be clearly printed as such. Restic can then try to load and decrypt the individual blobs. For the blobs which could be successfully verified, restic can just use them. The others (which do not verify) should be discarded, that’s what we have the signature for. After all, they could have been modified by an attacker, and should be treated as such. This allows at least to salvage the unmodified parts of the file.

Then, restic prune should proceed, not including any broken blobs in the repository. This makes restic check complain that data is missing, but most of the time the original data is still there (like in your case) and the repository will just repair itself. Or users discard and forget the snapshots which reference the missing data.

We should definitely do 1) and 2), 3) is hard to do because I don’t have any idea what’s going on. It’d be great to have some feedback should you ever find out what’s going on with your hardware!

Hm, odd: The differences start at offset 0x646fa, the blob is unmodified again starting at offset 0x6c6fa, which means 32768 bytes are modified. That’s exactly 32KiB. The start offset is not a multiple of 32KiB though. XORing the bytes does not show any obvious pattern.

When we consider the position of the blob in the file in the repo, the faulty bytes start at offset 2701558+0x646fa = 3112944, which is also not a multiple of 32KiB. Oddly enough, that’s a multiple of 16, so the start offset in the file is 0x2f7ff0.

I’m thinking aloud here: For a memory (RAM) error that’s a rather surprising result, it could hint at storage problems. Maybe the file system on the NAS, or the underlying storage medium, uses 32KiB blocks? Even then, I would have expected the start offset to be a multiple of 32KiB…

Another thought: The usual transfer chunk size for data over sftp is also 32KiB…

It’d be great to have the same data from @carlonluca so we can compare it.

@askielboe can you check what the block size for the FS on the NAS is (for ext4 it’s either 1024 or 4096 for my systems)? You can either use tune2fs -l /dev/sda1 (or whatever the partition for the data is) or use stat -fc %s /path/to/mountpoint

I wanted to follow up on this thread to point others to a potential cause that affected me - a kernel bug affecting some builds before versions 5.3.15, 5.4.2, and 5.5 that can cause CPU register corruption. More details are available in my thread on the forum.

Please see https://github.com/restic/restic/issues/828#issuecomment-706186047 for updated instructions.

@n8henrie The debug-1999 branch been merged into master. It has gained the functionality to extract all intact parts of the damaged pack file, in the meantime. With that it’s actually possible to recover (well, actually replace) a damaged pack file. As I haven’t posted usage instructions here, here’s a complete walk-through:

• Build the latest master branch using go build -tags debug ./cmd/restic
• Run restic debug examine --extract-pack <id-of-broken-pack-file> to extract all blobs in the damaged pack file into the current folder (-> it’s best to use a temporary folder to reduce the chaos). The packfile must still be located in the proper place inside the repository, but it is not necessary for it to be contained in the repository index (i.e., there’s no need to run rebuild-index, please do not run that command right now) The option --try-repair can be used to try to repair a single bit flip, and --repair-byte tries to repair a full byte at once (but is also much slower). The examine command won’t modify the repository, so it’s safe to run even though it’s experimental code.
• From here on you can use a release version of restic if you feel safer with that.
• Move the damaged pack file out of the repository, create a backup of the index and run restic rebuild-index (which should work fairly when using the current master branch).
• Then run restic backup . in the folder which contains the extracted blobs. This let’s restic recover the blobs which were previously contained in the damaged pack file.
• Now with a bit of luck restic check --read-data should no longer report errors or only a few ones.
• If the (still) missing blobs are part of a file of which you still have the original, then run restic backup <original-file>, which will recover the missing blobs. (With restic before 0.10.0 you have to add the --force flag).

Apologies for the late reply, I’ve been away from the Internet for a while. The fixes for #2066 and #2068 have fixed the problems I’ve been seeing. I’ve pulled both those fixes into a local branch which also has the debug-1999 branch pulled into it.

Regarding the earlier comment, we don’t have a “malware protection gateway” sort of device, but we were indeed having some serious network issues, though we didn’t know that when I posted into this issue ticket. (It was a switching loop, where the “loop” was caused by several wifi APs.) That may have contributed to the problems we saw.

Here is my now working output:

$ ./restic --verbose prune
debug enabled
repository 1234abcd opened successfully, password is correct
counting files in repo
building new index for repo
[36:53:23] 100.00%  7778015 / 7778015 packs
repository contains 7778015 packs (97177051 blobs) with 35.961 TiB
processed 97177051 blobs: 2876930 duplicate blobs, 2.226 TiB duplicate
load all snapshots
find data that is still in use for 345 snapshots
...

Thanks a bunch for the help!

The discussion about how to handle these cases flows into a forum thread I made a while ago with an idea about restic offering a suggestion about what to do next, in case of an error: https://forum.restic.net/t/deterministic-output-of-restic-check-to-know-what-to-do-next/865?u=matt

The example there is for check, but I could see it happening for errors on any other command, too. I would be interested in implementing this if someone wanted to give me a pointer as to the best, centralized place to handle errors in this way.

To me these tests, along with your reasoning @fd0, seem to suggest that this is most likely a hardware issue, or at least an issue outside of restic.

What are your thoughts on handling these cases in restic? Are there any meaningful paths that we could take to improve the user experience when repo data gets corrupted?

A few thoughts/ideas:

1. Documentation: We could extend the error message somewhat to inform the user that they should check the consistency of their repository. Judging from the number of issues on this, there is a bit confusion about what a wrong object hash means. I’m not entirely sure if we’ve covered all cases of this, and can say anything definitive about it yet, but it seems that at least some of it could be hardware related - and warrant some action by the user to protect their backups.

2. Active recovery: Given that I managed to repair my repository by removing the broken pack, and let restic take care of the rest, would it be a viable option to let restic try to repair the repo by re-uploading bad blobs to the repo if the data is available? At least it would feel safer to let restic manipulate the repository, rather than having to modify the objects manually.

3. More tests: Run more tests to figure out what’s going on before we take action. If we had some way of reliable reproduction that would be helpful, but since it’s likely a hardware failure I guess that’s difficult.

In any case it would still be nice to have a way to recover from corrupted blobs using restic. I probably don’t currently know enough about the internals of restic to decide what the best approach is, but I’d like to help out if possible.

Ah, I’ve got something we can try: run the following on all Linux-based machines involved, then try again:

# echo 3 > /proc/sys/vm/drop_caches

This will clear all file system caches from memory, so the data needs to be re-read from disk. Then run sha256sum on the broken file in question, best would be on the machine which stores the file, or even better: run the test code again (without any --try-* options).

@carlonluca @askielboe I’ve pushed a new branch debug-1999 with extra code to find out what’s going on here.

Please pull the repo, then run git checkout debug-1999 and build restic with go run build.go -tags debug. Then you should have the restic debug examine command, it can be used like this (I’ve manually inserted an error into the file):

$ ./restic debug examine 8d83cae01cae47ec5dcf03dc2f2156ab40d8f65cc0cfa57971ed432fc1d0f608
repository ac7fd880 opened successfully, password is correct
examine 8d83cae01cae47ec5dcf03dc2f2156ab40d8f65cc0cfa57971ed432fc1d0f608
  file size is 1689865
    index 09ed6903:
      data blob e95f651fd16f8e8f6da57a890a442bb658902d20c02493f497673b0a79747268, offset 0     , raw length 1049556
      data blob 6161e68de39f8aa02a790d09750c7d79ef0c8b39c1ec978daad3332b9625558a, offset 1049556, raw length 640199
      file sizes match
      loading blob e95f651fd16f8e8f6da57a890a442bb658902d20c02493f497673b0a79747268 at 0 (length 1049556)
error decrypting blob: ciphertext verification failed
      loading blob 6161e68de39f8aa02a790d09750c7d79ef0c8b39c1ec978daad3332b9625558a at 1049556 (length 640199)
         successfully decrypted blob (length 640167), hash is 6161e68de39f8aa02a790d09750c7d79ef0c8b39c1ec978daad3332b9625558a
         IDs match
    index bf0435db does not contain the file
      data blob e95f651fd16f8e8f6da57a890a442bb658902d20c02493f497673b0a79747268, offset 0     , raw length 1049556
      data blob 6161e68de39f8aa02a790d09750c7d79ef0c8b39c1ec978daad3332b9625558a, offset 1049556, raw length 640199
      file sizes match

Please paste the output here! 😃

Thanks for the report, I’m sorry for the late reply.

Incomplete pack files are usually the result of restic being aborted (e.g. by pressing ^C) during a run of restic backup. It will then abort and not finalize the file, so it is too short to be valid, which is then detected early on.

This case (in contrast to the others) is a bit odd because CIFS is involved, which may or may not be the cause.

I have several ideas how we can try to drill down here. The core issue is that restic wrote data with the SHA256 hash of ad4b41a807[...], but when reading the data back it got data with the hash 2ac3712c12e[...]:

hash does not match id: want ad4b41a807fef9716a60f92f63334d3b28fd5a8a744a43069455fcd42f1db352, got 2ac3712c12e1b363c94fd6637fa8c09e8cffbc6d0bfc13699d83b8121e45c085

So, we need to find out what’s going on and where a (potential) bug in restic may be located.

I’d like you to do the following

• Run sha256sum on the file, report back the hash that is returned
• Paste the output of ls -al of the file
• Run the following commands to extract the information from the index files about the file in question:

restic list index | while read idxid; do \
         restic cat index $idxid | jq '.packs | map(select(.id | contains ("ad4b41a807fef9716a60f92f63334d3b28fd5a8a744a43069455fcd42f1db352")))'; \
done

Thanks!