Original and backup do not match

[caek]

I've found a few files in a SuperDuper-generated backup that do not match the original. I haven't found an easy way to automate the checking of this (there's a lot of data), so I'm not sure how widespread across this problem is along the backup, but it certainly exists. I'm extremely concerned by this, as there are no errors in SuperDuper's log, and the Smart Copy completes successfully. The backup target is an encrypted, password-protected disk image on an external FW drive). There follows some Terminal output demonstrating this mismatch. I'd welcome any input. While I realise I can delete and regenerate the disk image, I'm reluctant to do so without establishing just what's gone wrong here.

Here's some examples of files which do not match:

otis:mike$ ls -al .aspell.conflrwxr-xr-x 1 mike mike 38 6 Nov 17:37 .aspell.conf -> Library/Preferences/cocoAspell/en.conf
otis:mike$ ls -al /Volumes/iBook\ Users\ Backup/Users/mike/.aspell.conf
lrwxr-xr-x 1 mike mike 38 29 Dec 21:29 /Volumes/iBook Users Backup/Users/mike/.aspell.conf -> Library/Preferences/cocoAspell/en.conf

(Note modification times differ. Not sure if this is a problem.)

otis:mike$ head .aspell.conf
# conf (string)
# main configuration file
# default: aspell.conf

# conf-dir (string)
# location of main configuration file
# default: <prefix:etc> = /usr/local/etc

# data-dir (string)
# location of language data files
otis:mike$ head /Volumes/iBook\ Users\ Backup/Users/mike/.aspell.conf
otis:mike$ [NO OUTPUT -- backup is a binary file!]
otis:mike$ diff .aspell.conf /Volumes/iBook\ Users\ Backup/Users/mike/.aspell.conf
Binary files .aspell.conf and /Volumes/iBook Users Backup/Users/mike/.aspell.conf differ


The backup of this directory of MP3s also does not match: files sizes an modification times match, but the content of all files (except, strangely, Track 6) differ, as shown by diff. Quicktime cannot open the files on the backup.

otis:mike$ ls -al /Users/Shared/Music/The\ Be\ Good\ Tanyas/Hello\ Love/
total 140200
drwxrwxrwx 16 mike wheel 544 21 Dec 01:40 .
drwxrwxrwx 7 mike wheel 238 11 Oct 16:33 ..
-rw-rw-rw- 1 mike wheel 6148 9 Dec 00:55 .DS_Store
-rw-r--r-- 1 mike wheel 5955712 9 Dec 00:57 01 Human Thing.mp3
-rw-r--r-- 1 mike wheel 6629504 9 Dec 00:57 02 For The Turnstiles.mp3
-rw-r--r-- 1 mike wheel 5197952 9 Dec 00:57 03 A Thousand Tiny Pieces.mp3
-rw-r--r-- 1 mike wheel 5130368 9 Dec 00:56 04 Ootischenia.mp3
-rw-r--r-- 1 mike wheel 4214912 9 Dec 00:57 05 A Little Blues.mp3
-rw-r--r-- 1 mike wheel 6807680 9 Dec 00:55 06 Scattered Leaves.mp3
-rw-r--r-- 1 mike wheel 6060160 9 Dec 00:57 07 Hello Love.mp3
-rw-r--r-- 1 mike wheel 5687424 9 Dec 00:57 08 Nobody Cares For Me.mp3
-rw-r--r-- 1 mike wheel 4532352 9 Dec 00:57 09 Out Of The Wilderness.mp3
-rw-r--r-- 1 mike wheel 5634176 9 Dec 00:57 10 Song For R..mp3
-rw-r--r-- 1 mike wheel 6578304 9 Dec 00:57 11 What Are They Doing In Heaven Today.mp3
-rw-r--r-- 1 mike wheel 3682432 9 Dec 00:55 12 Crow Waltz.mp3
-rw-r--r-- 1 mike wheel 5623936 9 Dec 00:44 13 When Doves Cry.mp3
otis:mike$ ls -al /Volumes/iBook\ Users\ Backup/Users/Shared/Music/The\ Be\ Good\ Tanyas/Hello\ Love/
total 140200
drwxrwxrwx 16 mike wheel 544 21 Dec 01:40 .
drwxrwxrwx 7 mike wheel 238 11 Oct 16:33 ..
-rw-rw-rw- 1 mike wheel 6148 9 Dec 00:55 .DS_Store
-rw-r--r-- 1 mike wheel 5955712 9 Dec 00:57 01 Human Thing.mp3
-rw-r--r-- 1 mike wheel 6629504 9 Dec 00:57 02 For The Turnstiles.mp3
-rw-r--r-- 1 mike wheel 5197952 9 Dec 00:57 03 A Thousand Tiny Pieces.mp3
-rw-r--r-- 1 mike wheel 5130368 9 Dec 00:56 04 Ootischenia.mp3
-rw-r--r-- 1 mike wheel 4214912 9 Dec 00:57 05 A Little Blues.mp3
-rw-r--r-- 1 mike wheel 6807680 9 Dec 00:55 06 Scattered Leaves.mp3
-rw-r--r-- 1 mike wheel 6060160 9 Dec 00:57 07 Hello Love.mp3
-rw-r--r-- 1 mike wheel 5687424 9 Dec 00:57 08 Nobody Cares For Me.mp3
-rw-r--r-- 1 mike wheel 4532352 9 Dec 00:57 09 Out Of The Wilderness.mp3
-rw-r--r-- 1 mike wheel 5634176 9 Dec 00:57 10 Song For R..mp3
-rw-r--r-- 1 mike wheel 6578304 9 Dec 00:57 11 What Are They Doing In Heaven Today.mp3
-rw-r--r-- 1 mike wheel 3682432 9 Dec 00:55 12 Crow Waltz.mp3
-rw-r--r-- 1 mike wheel 5623936 9 Dec 00:44 13 When Doves Cry.mp3
otis:mike$ diff /Users/Shared/Music/The\ Be\ Good\ Tanyas/Hello\ Love/ /Volumes/iBook\ Users\ Backup/Users/Shared/Music/The\ Be\ Good\ Tanyas/Hello\ Love/
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/01 Human Thing.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/01 Human Thing.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/02 For The Turnstiles.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/02 For The Turnstiles.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/03 A Thousand Tiny Pieces.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/03 A Thousand Tiny Pieces.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/04 Ootischenia.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/04 Ootischenia.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/05 A Little Blues.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/05 A Little Blues.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/07 Hello Love.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/07 Hello Love.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/08 Nobody Cares For Me.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/08 Nobody Cares For Me.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/09 Out Of The Wilderness.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/09 Out Of The Wilderness.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/10 Song For R..mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/10 Song For R..mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/11 What Are They Doing In Heaven Today.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/11 What Are They Doing In Heaven Today.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/12 Crow Waltz.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/12 Crow Waltz.mp3 differ
Binary files /Users/Shared/Music/The Be Good Tanyas/Hello Love/13 When Doves Cry.mp3 and /Volumes/iBook Users Backup/Users/Shared/Music/The Be Good Tanyas/Hello Love/13 When Doves Cry.mp3 differ

[dnanian]

I can't explain this, since we're using a standard system call to copy the data over, and I've never seen a file get copied in a way that didn't generate an error.

Please use the "Send to shirt pocket" button to send me the set of logs from this backup: I'd like to take a look.

[caek]

Originally Posted by dnanian

Please use the "Send to shirt pocket" button to send me the set of logs from this backup: I'd like to take a look.

Sent. Thanks for taking a look!

[trevyn]

That's funny, I just noticed something similar, with a text file.

The first 2.5k (exactly 2560 bytes) of the file was completely missing in the backup, and at the end, an extra 2560 bytes were appended. Most were null bytes, but in the middle of those was the spurious string "/Applications/SuperDuper!.app/Contents/Resources/Copy Scripts"

Figure that one out. Copy logs show nothing abnormal.

Now, the interesting part is that I kept that text file open in BBEdit for some time. Any changes were very minor, no large parts of text were moved around, etc.

So my theory is it may have something to do with files that are open when the copy is performed. If so, how can we address this? Corrupt backups are public enemy number one.

Another possibility: this drive has a small handful of unrecoverable IO errors; in order to get backups to succeed, I had to exclude four media files (unrelated to this text file) using a...yes...Copy Script. This text file has never had a problem for me in normal usage, but is it possible that the first 5 blocks were unreadable at some point, and when they became readable again, the data was never copied over? Kind of shooting in the dark here. Are the historical logs for scheduled backups kept past the last one?

[dnanian]

It's likely that the source file was damaged when we read it, but a subsequent write (which is typically done by writing a new file, deleting the old and renaming) was fine.

The actual file copy itself is done with a very well tested atomic OSX call that's relied upon by the entire system...

[dnanian]

(Open files also shouldn't matter terribly, as long as they're not being actively written. I've done thousands upon thousands of test runs on this stuff, and these things don't happen unless there's some kind of underlying failure going on -- memory, unflagged disk errors, etc -- and it certainly sounds like that's the case in this situation.)

[trevyn]

Originally Posted by dnanian

It's likely that the source file was damaged when we read it, but a subsequent write (which is typically done by writing a new file, deleting the old and renaming) was fine.

The actual file copy itself is done with a very well tested atomic OSX call that's relied upon by the entire system...

Maybe, but there's still a problem here in that a subsequent backup is not detecting the file as changed.

Also, I'm having trouble figuring out how "/Applications/SuperDuper!.app/Contents/Resources/Copy Scripts" could end up in any legitimate copy of the file, damaged or not.

[dnanian]

That's because the date, time, size and other attributes are correct. We do not compare the contents of the files.

The contents of memory could have had that string in it, as could the disk itself...

[trevyn]

It seems to me the most likely case might be a disk error that is not getting flagged properly. This absolutely should have thrown an error, and if I somehow missed that error in a log or failed copy status, it should be attempting the copy again each time it's scheduled, until it's done right, or keep throwing errors so I notice eventually.

[dnanian]

As I said, if the attributes are all correct than we won't re-copy.

[trevyn]

Right, but why are the attributes getting updated when the file copy is performed incorrectly? If there's garbage memory in my file, some CRC is not matching somewhere, and some error should be being thrown. i.e. there is a bug here. Maybe it's in the disk firmware, maybe it's in OS X, maybe it's in SuperDuper, I don't know, but this should not be happening.

[dnanian]

I agree with you, trevyn. But disks shouldn't fail either, and they do. When a system isn't performing properly - whether due to memory issues, disk failure, controller failures, etc - we can only work with what we have... and if an error isn't flagged, or is ignored, it's difficult to know what to do.

I've never seen anything similar to what you've experienced here, and as I've said I do thousands of tests. But if your system is corrupting data -- for whatever reason -- we'll be a victim of that corruption just like any other application might be.

Memory on a non-MacPro isn't ECC and doesn't have parity, so memory errors will not be caught by the system. And, if a drive fails to write but does not flag an error to us, there's no way for us to know, unless we were to checksum every source and destination file during every copy: something that would be prohibitively slow, expensive, would cause additional wear-and-tear, etc. And even that can't guarantee everything'll always work right (plus, an active system is always changing, so you'll have errors each and every time you ran).

We've worked very hard at this end to only use well-tested functions that leverage as much of Apple's work (and OSX) as possible. And, in our testing, these functions have been reliable. Where we've caught errors (such as missing metadata) we've made extensive efforts to supplement those calls (and this has been verified by third parties who have found us to be the most accurate copying engine). But we've never seen them mis-copy existing data, even once, in all our testing.

I'll do my best to try to reproduce the problem... but as I've said I've never seen anything like it before, so I'm not hopeful.

[caek]

For those of you keeping score, Dave and I have been unable to figure out the exact reason how these files got into the state where their contents differ but the attributes that SuperDuper checks are the same. As a not entirely satisfactory solution, I've nuked the backup and created a new one.