#592 Hash is different from the reference hash

[doe65]

It seems that 'hash is different from the reference hash' is a long lasting bug in Areca. I've met this few times. I overcome this by redoing full backup. Note that there are also other same issues that were reported with this message. As this is nasty scratch I would love to find this solved. I was trying to hunt down this bug but without any luck. Below are my thoughs about this bug. Maybe some developer or Aventin will be able to solve this or will give me a helping hand how to track bug down.

I have such backups done by Areca. All are done with delta mode and zip64 and transaction points (from the newest to the oldest).
1) incremental backup, backup checked, 2016.02, ERROR invalid hash
2) full backup, backup checked, 2015.09, no file B within backup
3) full backup, backup checked, 2015.08, no file B within backup
here file B is deleted
4) incremental backup, backup NOT CHECKED, 2015.06, file B exists, no change (so no backup)
5) full backup, backup checked, 2015.02, file B exists, back up
6) incremental backup, backup checked, 2015.02, file B exists, no change (so no backup)
7) incremental backup, backup checked, 2015.01, file B exists, no change (so no backup)
8) full backup, backup checked, 2014.12, file B back up

Now... the problem is that trying to do incremental backup (step 1) I receive this exception:

16-02-13 21:06 - WARNING - .IdeaIC14/config/plugins/extensions.xml was not properly recovered : its hash (74732428ec575989d2a1c78964e44330616faa55) is different from the reference hash (2ea02e398e2dd079437a738c078e988c57973f9c). Simulation flag set to ON - file : /tmp/tmp-root/chk0/.IdeaIC14/config/plugins/extensions.xml
16-02-13 21:06 - WARNING - .macromedia/Flash_Player/macromedia.com/support/flashplayer/sys/#static.oognet.pl/settings.sol was not properly recovered : its hash (5ab9236edeebcb8db2d53f6f15e098102f588789) is different from the reference hash (d0e26306d8ac0f3d90cf89b9128d54071a0dcb27). Simulation flag set to ON - file : /tmp/tmp-root/chk0/.macromedia/Flash_Player/macromedia.com/support/flashplayer/sys/#static.oognet.pl/settings.sol
16-02-13 21:06 - WARNING - file A was not properly recovered : its hash (5ab9236edeebcb8db2d53f6f15e098102f588789) is different from the reference hash (f98d0c48bedc44d37656d7c938beb5a091908fb7). Simulation flag set to ON - file : /tmp/tmp-root/chk0/file A
16-02-13 21:06 - WARNING - file B was not properly recovered : its hash (5ab9236edeebcb8db2d53f6f15e098102f588789) is different from the reference hash (14f40ee0aec297422c0087db64da8e0f670059cc). Simulation flag set to ON - file : /tmp/tmp-root/chk0/file B

1) This seems definitly like bug as in step 2 (full backup) 'file B' didn't exists in previous backup so backup in step 1 should be quite easy as it doesn't have to calculate delta increments.
2) It's interesting that same hash number (5ab9236edeebcb8db2d53f6f15e098102f588789) exists for 3 different files. Maybe it's kind of hash collision?
3) I put some system out to dump hashSequence for 'file B'. This is what I get:

seq is : [HashSequence - 
Bucket8=[SimilarEntrySet - Element0=[HashSequenceEntry - Q=42980073 - F=20 - P=0 - S=1024]] - 
Bucket2526=[SimilarEntrySet - Element0=[HashSequenceEntry - Q=33175731 - F=20 - P=1 - S=1024]] - 
Bucket4680=[SimilarEntrySet - Element0=[HashSequenceEntry - Q=58965924 - F=20 - P=3 - S=1024]] - 
Bucket9358=[SimilarEntrySet - Element0=[HashSequenceEntry - Q=24076193 - F=20 - P=4 - S=170]] - 
Bucket9373=[SimilarEntrySet - Element0=[HashSequenceEntry - Q=64194271 - F=20 - P=2 - S=1024]]]

Can't say if this is valid or not but Bucket9358 has some very low 'S' parameter.

4) I try to reproduce this bug on same file with this schema:
- create file B,
- full backup,
- incremental backup,
- delete file B,
- full backup,
- full backup,
- create file B,
- increment backup
But this worked as expected. So can't reproduce the problem.

5) Please note that in step 4 I didn't checked the backup. So propably the error comes from that step. If I've turn off validation in that step so it's a high chance that backup could not be done because of same validation hash error that occured in the past. I can't say now, I don't remember. That however should not cause the problem as later that file is deleted, so even if there was a problem, it should not cause faulty backup of newly added file.

6) Looking at archive_dir/date_data/hash for 'file B' I found there's correct value for that file but it's not used by areca? So what's that for? Is it the hash from the original file that is dumped at backup stage? So even if original file will be changed during the backup (so it's hash will be different than the one in that hash file), then verify hash stage can be done correctly?

7) It seems that Areca extract that invalid hash from archive_dir/date/file B where the first part of that file is:
- signature if this is all file or delta file,
- hash number (?),
- file name
- file content

8) Maybe I don't understand file format from point 7? If someone could also dump some word what's the format of the file from point no 7? It's little strange for me. I would expect that validation should look like this:
- restore all file,
- count hash number of restored file,
- count hash number of original file,
- validate if hash numbers are equal.

But it seems that validation looks like this:
- get file in dir: 'archive_dir/date/file
- omit signature (new, delta?),
- take a hashnumber
- count hash number of original file,
- validate if hash numbers are equal.

9) Looking at code I found multiple iterations per integer index. I believe those should be replaced with iterating over collections to protect from going over max-integer value.

10) There's also lot of StringBuffer which can be safely replaced with more efficiency StringBuilder. I can prepare fix for this if Aventin is OK with that.

[aventin]

First of all, thanks for this very comprehensive bug report

This bug is indeed a real nightmare to investigate because I never managed to reproduce it, although it has been reported by many users. All I was able to do was to add diagnostic informations so one of the users could one day report more detailed context informations (which you did :) )

Before getting more into the details, there is some misunderstanding that needs to be clarified : the "hash codes" we are talking about have nothing to do with the data stored for delta backup : both features are completely independant (archive verification must be also available for non-delta setups), so AFAIK the problem does not lie in the "HashSequences" objects, but rather in the verification feature itself.

About your point 8 : there are two use cases for "archive verification" :
1) The user has performed a recovery, and wants to check that the recovered files are identical to the original ones : in that case, Areca simply recovers the files, then reads them, compute a HashCode from their content and compares it to the hashCode that was stored in the "hash" file (ie the hashCode of the original file)
2) The user has performed a backup, and wants to check its archive. We could handle this case exactly like use case 1 : recover all files, compute their hashCode and check them against the original ones. This approach (which was implemented in the early versions of Areca) would be inefficient because it would use a lot of storage space, while all we want is to compute recovered HashCodes.
On the other side, we really want to execute the exact same code as in a recovery (that's the only way to make sure that Areca will be able to recover the archive), so we don't really want to write dedicated code to compute HashCodes on the fly and bypass the recovery code in Areca.
So the approach that was choosen was to add a proxy class that intercepts the file writing operations, and write their hashCode instead of their full content. (see the "ContentHashFileSystemDriver" class)
So the steps of backup verification are : first, activate the proxy so the files are not really written to the disk, then perform a 'classical' archive recovery, and then read the recovered files to retrieve their hashCode and check them against the original ones (stored in the "Hash" file). This ensures that little storage space is used for verification (because we only store hash codes) and that we use the exact same code that will be used for recovery (except for the 'proxy' part, of course)

To get back to the bug: the interresting point in your post is that "settings.sol", "file A" and "file B" share the same recovered hashCode. The only reason that could explain that is that their content is identical (for instance, if fileA and fileB are copies of settings.sol) ... is it the case ?

[aventin]

Another thing : when you say "Looking at archive_dir/date_data/hash for 'file B' I found there's correct value ", what value did you found exactly ? According to the log you posted, it should be "14f40ee0aec297422c0087db64da8e0f670059cc"

[HULLIN Pascal]

I continue this thread since I had also the same phenomena on a Windows 2008 R2. I use the VSS plugin.
As far I understand, aventin has some difficulties to track the problem since he could not reproduce it. How luck he is ;-)
On my side, I face this problem on a regular basis but I haven't been able to trigger it on demand when there is none present. I'm not a java developper but if it could help to track this bug, I propose to run some 'debug' version on my server and forward the result to aventin for investigation.
Currently, the last night target backup returned to me this this error... So if I do nothing, the next backup will show the same problem...

Waiting to your feedback and have a nice day.

[HULLIN Pascal]

Hi,

As expected, I had the same hash error during the backup last night. That's a good point for the debug process. Since I want to go further on this problem, I did today the following :
first I have tried to reproduce the problem on a target that only contains the directory with the set of files in error. Here, it is a single directory but notice that all files in error are shortcut files. The problem is NOT related to shortcut files because I already had it on more regular files.

1 - I duplicated the target and changed only the source path to that directory, then I run the archive process. Bad luck, this completed without error but it did a full backup and not an incremental backup. That's normal but it is a difference. I did many archive on this reduced target -> no error.
I restored these files on another place compared manually the checksum of the original files and the restored files. These shortcut files are identical. I used the cvif.exe -md5 command to produce the hash. There is a difference : The original name of the shortcut is in french but the restore shortcut name is in english ! Explorer doesn't translate on fly. It is an 'explorer' problem since a 'dir' command gives the english file name in both cases.
-> This means that there is a difference between full and reduce target (or full and incremental archive) that makes some random result. So it is not useful.

2 - I run the full target archive, but this time I disabled the final check to get a archive file. It ran OK
3 - I run an archive check to be sure that I got the hash error... and I get the all hash errors as last night. But this time it didn't delete the archive.
4 - I restored only the directory with these files in error on another location. I get of course warning message about theses files.
5 - I compared restored files against original files. Some of them are smaller than original and windows didn't recognised them as shortcut (completely broken). All hash warning files in the log are completely broken. The others have the same size, windows recognises them as valid shortcut and have the same md5 hash.
-> There is data corruption either during the archive OR during the restore process and the 'hash' check detect nicely this corruption. Do you have a good idea to determine if the problem occurs during backup or during restore ? in other word how can I rebuild the file from the archive without using Areca ?

As I said in my last post, I can run a troubleshooting version of Areca to spot the bug. I have a configuration where this problem happens. It is a chance to get rid of this long term bug. ;-)

[A Person]

Are there any news about this recovery verification issue? It makes this software completely unusable due to how important the verifications are, and it's scary how someone may realize it too late after becoming dependant on this backup tool.

My error also mentions the well known hash of 5ab9236edeebcb8db2d53f6f15e098102f588789, and it happened in a use-case where I had a .exe file, then made another backup with the file deleted, and after any amount of intermediate backups, returned the same file back and attempted to create a new backup. By the way, this seems to happen specifically under delta && incremental backups.

[SystemDotExit]

I don't think Aventin supports this anymore and no one has picked up the responsibility.

Unless he responds soon to a lot of unanswered support requests, it may be time to start planning a migration of backup tools to something else supported.

Shame really as Areca has all the perfect features and functions many of us require!