Backup Central

I added the carbonfile patch, built v1.1.2, and did some testing.

I created a full backup, with carbonfile enabled. I restored a large
directory, and the carbonfile info seemed to restore correctly.

There was some earlier discussion about the performance impact of
adding SHA hashes - the time to do a full backup was perhaps slightly
shorter than with v1.1.0, so I have no complaints. Looking at the
CPU useage, I don't think my machine is CPU bound most of the time
(dual G4, 1.42 Ghz).

Rdiff-backup 1.1.2 worked great to make a new backup, but I can't get
it to add an increment. I've tried twice, and both times it failed.
I watched it after the first failure, and it do revert the backup.

The first failure ended with:

Regular copying ('screenlog.0',) to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup.tmp.226
Writing file object to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup.tmp.226
Copying attributes from ('screenlog.0',) to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup.tmp.226
Writing resource fork to ('rdiff-backup.tmp.226',)
Writing carbon data to ('rdiff-backup.tmp.226',)
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup.tmp.226 to 1131300680
Incrementing mirror file /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/screenlog.0
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/increments/screenlog.0.2005-11-06T09:56:15-05:00.missing
Renaming /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup.tmp.226 to /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
screenlog.0
Copying attributes from () to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile to
1131299084
Writing mirror_metadata diff
Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 230, in patch_and_increment
cls.CCPP.close()
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 446, in close
metadata.ManagerObj.ConvertMetaToDiff()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 593, in ConvertMetaToDiff
for diff_rorp in self.get_diffiter(new_iter, old_iter):
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 555, in get_diffiter
for new_rorp, old_rorp in rorpiter.Collate2Iters(new_iter,
old_iter):
File "/sw/lib/python2.4/site-packages/rdiff_backup/rorpiter.py",
line 92, in Collate2Iters
try: relem1 = riter1.next()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 260, in iterate
for record in self.iterate_records():
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 269, in iterate_records
next_pos = self.get_next_pos()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 252, in get_next_pos
newbuf = self.fileobj.read(self.blocksize)
File "/sw/lib/python2.4/gzip.py", line 225, in read
self._read(readsize)
File "/sw/lib/python2.4/gzip.py", line 290, in _read
self._read_eof()
File "/sw/lib/python2.4/gzip.py", line 309, in _read_eof
raise IOError, "CRC check failed"
IOError: CRC check failed
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/file_statistics.
2005-11-06T12:44:53-05:00.data.gz', mode 'wb' at 0x79f8d8 0x7b75d0>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/error_log.
2005-11-06T12:44:53-05:00.data.gz', mode 'wb' at 0x79f6e0 0x7b4df0>>
ignored


===============================
I tried again, and it started like:

sudo rdiff-backup -v7 --carbonfile --print-statistics --exclude-
globbing-filelist /rdiff-backup_exclude_list /Users/kwh /Volumes/
Ext_BU/Users/kwh/rdiffbu_112_carbonfile

Unable to import module xattr.
Extended attributes not supported on filesystem at /Users/kwh
Unable to import module posix1e from pylibacl package.
ACLs not supported on filesystem at /Users/kwh
-----------------------------------------------------------------
Detected abilities for source (read only) file system:
Access control lists Off
Extended attributes Off
Case sensitivity Off
Mac OS X style resource forks On
Mac OS X Finder information On
-----------------------------------------------------------------
Making directory /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/rdiff-backup.tmp.0
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/5-_ a.
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/5-_ a.
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/:\ ·Ñâ
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/:\ ·Ñâ
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/A
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/a
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/foo
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/foo
Making directory /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/rdiff-backup.tmp.0/hl
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/hardlinked_file1
Hard linking /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/hl/hardlinked_file2 to /Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/rdiff-backup.tmp.0/
hardlinked_file1
Unable to import module xattr.
Extended attributes not supported on filesystem at /Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/rdiff-backup.tmp.0
Unable to import module posix1e from pylibacl package.
ACLs not supported on filesystem at /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup-data/rdiff-backup.tmp.0
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/dir_inc_check
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/dir_inc_check
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/regfile
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/regfile
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/high_perms
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0/high_perms
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/rdiff-backup.tmp.0
Removing directory /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/rdiff-backup.tmp.0
-----------------------------------------------------------------
Detected abilities for destination (read/write) file system:
Ownership changing On
Hard linking On
fsync() directories On
Directory inc permissions On
High-bit permissions On
Extended filenames On
Access control lists Off
Extended attributes Off
Case sensitivity Off
Mac OS X style resource forks On
Mac OS X Finder information On
-----------------------------------------------------------------
Previous backup seems to have failed, regressing destination now.
Regressing to Sun Nov 6 09:56:15 2005
Deleting old diff at /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/error_log.2005-11-06T12:44:53-05:00.data.gz
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/error_log.2005-11-06T12:44:53-05:00.data.gz
Deleting old diff at /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/file_statistics.2005-11-06T12:44:53-05:00.data.gz
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/file_statistics.2005-11-06T12:44:53-05:00.data.gz
Deleting old diff at /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/mirror_metadata.2005-11-06T12:44:53-05:00.snapshot.gz
Deleting /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/mirror_metadata.2005-11-06T12:44:53-05:00.snapshot.gz
Regressing file .DS_Store


And it ended like:


Copying attributes from ('screenlog.0',) to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup.tmp.320
Writing resource fork to ('rdiff-backup.tmp.320',)
Writing carbon data to ('rdiff-backup.tmp.320',)
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup.tmp.320 to 1131309524
Incrementing mirror file /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/screenlog.0
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/increments/screenlog.0.2005-11-06T09:56:15-05:00.missing
Renaming /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup.tmp.320 to /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
screenlog.0
Copying attributes from () to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile to
1131306058
Writing mirror_metadata diff
Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 230, in patch_and_increment
cls.CCPP.close()
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 446, in close
metadata.ManagerObj.ConvertMetaToDiff()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 590, in ConvertMetaToDiff
diff_writer = self.get_meta_writer('diff', oldrp.getinctime())
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 511, in get_meta_writer
typestr, time)
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 503, in _writer_helper
assert not rp.lstat(), "File %s already exists!" % (rp.path,)
AssertionError: File /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/mirror_metadata.2005-11-06T09:56:15-05:00.diff.gz
already exists!
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/file_statistics.
2005-11-06T14:40:45-05:00.data.gz', mode 'wb' at 0x79f890 0x7b49b8>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/error_log.
2005-11-06T14:40:45-05:00.data.gz', mode 'wb' at 0x79f728 0x7b4698>>
ignored

=========================

I noted that both these attempts failed on screenlog.0. I was using
screen to create a logfile of the terminal output, so this file would
be continually changing. I added it to the excluded files list, and
tried again. The third attempt failed like:


Incrementing mirror file /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup_1.1.2_incremental_bu_fail1.txt
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/increments/rdiff-backup_1.1.2_incremental_bu_fail1.txt.
2005-11-06T09:56:15-05:00.missing
Renaming /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup.tmp.354 to /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup_1.1.2_incremental_bu_fail1.txt
Processing changed file rdiff-backup_1.1.2_incremental_bu_fail2.txt
Regular copying ('rdiff-backup_1.1.2_incremental_bu_fail2.txt',) to /
Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-backup.tmp.355
Writing file object to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup.tmp.355
Copying attributes from ('rdiff-
backup_1.1.2_incremental_bu_fail2.txt',) to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup.tmp.355
Writing resource fork to ('rdiff-backup.tmp.355',)
Writing carbon data to ('rdiff-backup.tmp.355',)
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup.tmp.355 to 1131310004
Incrementing mirror file /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/rdiff-backup_1.1.2_incremental_bu_fail2.txt
Touching /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup-data/increments/rdiff-backup_1.1.2_incremental_bu_fail2.txt.
2005-11-06T09:56:15-05:00.missing
Renaming /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/rdiff-
backup.tmp.355 to /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup_1.1.2_incremental_bu_fail2.txt
Copying attributes from () to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile to
1131310570
Writing mirror_metadata diff
Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 230, in patch_and_increment
cls.CCPP.close()
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 446, in close
metadata.ManagerObj.ConvertMetaToDiff()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 590, in ConvertMetaToDiff
diff_writer = self.get_meta_writer('diff', oldrp.getinctime())
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 511, in get_meta_writer
typestr, time)
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 503, in _writer_helper
assert not rp.lstat(), "File %s already exists!" % (rp.path,)
AssertionError: File /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/mirror_metadata.2005-11-06T09:56:15-05:00.diff.gz
already exists!
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/file_statistics.
2005-11-06T15:56:19-05:00.data.gz', mode 'wb' at 0x79f8d8 0x7b49b8>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/error_log.
2005-11-06T15:56:19-05:00.data.gz', mode 'wb' at 0x79f728 0x7b4738>>
ignored

It seems to strange to be a coincidence that the file that had failed
this time (rdiff-backup_1.1.2_incremental_bu_fail2.txt) was the
renamed screenlog.0 file that had caused the problem the first time.
I moved this file where it wouldn't be backed up, and tried again. I
was starting to wonder whether my use of screen could somehow be
causing my problems, so I didn't use it this time. rdiff-backup
regressed the last failed backup, then failed as:

Writing resource fork to ('Library', 'Syndication',
'Database3.2005-11-06T09:56:15-05:00.diff.gz')
Writing carbon data to ('Library', 'Syndication',
'Database3.2005-11-06T09:56:15-05:00.diff.gz')
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/increments/Library/Syndication/
Database3.2005-11-06T09:56:15-05:00.diff.gz to 1131291807
Renaming /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/Library/
Syndication/rdiff-backup.tmp.389 to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/Library/Syndication/Database3
Copying attributes from ('Library', 'Syndication') to /Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/Library/Syndication
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
Library/Syndication to 1131320605
Copying attributes from ('Library',) to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/Library
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
Library to 1123261449
Copying attributes from () to /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile
Setting time of /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile to
1131318339
Writing mirror_metadata diff
Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 230, in patch_and_increment
cls.CCPP.close()
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 446, in close
metadata.ManagerObj.ConvertMetaToDiff()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 590, in ConvertMetaToDiff
diff_writer = self.get_meta_writer('diff', oldrp.getinctime())
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 511, in get_meta_writer
typestr, time)
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 503, in _writer_helper
assert not rp.lstat(), "File %s already exists!" % (rp.path,)
AssertionError: File /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/mirror_metadata.2005-11-06T09:56:15-05:00.diff.gz
already exists!
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/file_statistics.
2005-11-06T18:03:21-05:00.data.gz', mode 'wb' at 0x79f848 0x7b4990>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
Users/kwh/rdiffbu_112_carbonfile/rdiff-backup-data/error_log.
2005-11-06T18:03:21-05:00.data.gz', mode 'wb' at 0x79f6e0 0x7b4670>>
ignored

I'll be heading on the road on Monday, and won't be be able to do any
more testing until Friday.

Thanks for all your work to try to get this working on OS X.

Kevin Horton
Ottawa, Canada

Kevin Horton <khorton01 < at > rogers.com>
wrote the following on Sun, 6 Nov 2005 19:24:24 -0500

Rdiff-backup 1.1.2 worked great to make a new backup, but I can't get
it to add an increment. I've tried twice, and both times it failed.
I watched it after the first failure, and it do revert the backup.

The first failure ended with:
File "/sw/lib/python2.4/gzip.py", line 309, in _read_eof
raise IOError, "CRC check failed"
IOError: CRC check failed

Hmm I have no idea about this. It seems rdiff-backup is writing
corrupt mirror_metadata files even when the session succeeds.
(Earlier I thought they might have gotten corrupted in some crash
somehow, but it seems to be an unrelated problem.)

Offhand the only thing I can think of is a bug in python's gzip
library. Can you try making a very simple rdiff-backup repository on
any relevant computers? Try something like:

mkdir input
cat /dev/null > input/file
rdiff-backup input output
touch input/file
rdiff-backup input output

If that works, try a slightly bigger volume, and see if you notice a
pattern. If that doesn't work, I could write a very simple gzip
python test, and we would know it's not rdiff-backup's problem.

AssertionError: File /Volumes/Ext_BU/Users/kwh/rdiffbu_112_carbonfile/
rdiff-backup-data/mirror_metadata.2005-11-06T09:56:15-05:00.diff.gz
already exists!

The new hash related regress code is forgetting to delete a file,
This patch should fix that, but won't fix the main problem:

http://savannah.nongnu.org/cgi-bin/viewcvs/rdiff-backup/rdiff-backup/rdiff_backup/regress.py.diff?r2=1.16&r1=1.15&diff_format=u


--
Ben Escoto

On 12 Nov 2005, at 24:14, Ben Escoto wrote:

Kevin Horton <khorton01 < at > rogers.com>
wrote the following on Sun, 6 Nov 2005 19:24:24 -0500

Rdiff-backup 1.1.2 worked great to make a new backup, but I can't get
it to add an increment. I've tried twice, and both times it failed.
I watched it after the first failure, and it do revert the backup.

The first failure ended with:
File "/sw/lib/python2.4/gzip.py", line 309, in _read_eof
raise IOError, "CRC check failed"
IOError: CRC check failed

Hmm I have no idea about this. It seems rdiff-backup is writing
corrupt mirror_metadata files even when the session succeeds.
(Earlier I thought they might have gotten corrupted in some crash
somehow, but it seems to be an unrelated problem.)

Offhand the only thing I can think of is a bug in python's gzip
library. Can you try making a very simple rdiff-backup repository on
any relevant computers? Try something like:

mkdir input
cat /dev/null > input/file
rdiff-backup input output
touch input/file
rdiff-backup input output

If that works, try a slightly bigger volume, and see if you notice a
pattern. If that doesn't work, I could write a very simple gzip
python test, and we would know it's not rdiff-backup's problem.

AssertionError: File /Volumes/Ext_BU/Users/kwh/
rdiffbu_112_carbonfile/
rdiff-backup-data/mirror_metadata.2005-11-06T09:56:15-05:00.diff.gz
already exists!

The new hash related regress code is forgetting to delete a file,
This patch should fix that, but won't fix the main problem:

http://savannah.nongnu.org/cgi-bin/viewcvs/rdiff-backup/rdiff-
backup/rdiff_backup/regress.py.diff?r2=1.16&r1=1.15&diff_format=u

I added the above patch, then did some tests, starting with a small
directory to backup, and adding a bunch of files after each
successful backup. I've finally gotten a failure, and it looks
different than any I remember from before, so I'm reporting it now
(TypeError: Non-hexadecimal digit found).

The failure happened when backing up about 4.1 GB of stuff. Before
that, I had gradually worked up from a single file to about 100 MB.
I'll repeat using smaller increments between 100 MB and 4GB to see if
there is a pattern with size. I'll save the old input and output
directories, in case there is any info you need from them.

====================================

I was using the following command line:
sudo rdiff-backup -v7 --carbonfile --print-statistics --exclude-
globbing-filelist /rdiff-backup_exclude_list /input /Volumes/Ext_BU/
output

The failure looked like:

Incrementing mirror file /Volumes/Ext_BU/output/Documents/Documents/
washing machine/PA080001.jpg
Touching /Volumes/Ext_BU/output/rdiff-backup-data/increments/
Documents/Documents/washing machine/PA080001.jpg.
2005-11-13T07:24:36-05:00.missing
Renaming /Volumes/Ext_BU/output/Documents/Documents/washing machine/
rdiff-backup.tmp.29107 to /Volumes/Ext_BU/output/Documents/Documents/
washing machine/PA080001.jpg
Processing changed file Documents/Documents/washing machine/PA080004.jpg
Regular copying ('Documents', 'Documents', 'washing machine',
'PA080004.jpg') to /Volumes/Ext_BU/output/Documents/Documents/washing
machine/rdiff-backup.tmp.29108
Writing file object to /Volumes/Ext_BU/output/Documents/Documents/
washing machine/rdiff-backup.tmp.29108
Copying attributes from ('Documents', 'Documents', 'washing machine',
'PA080004.jpg') to /Volumes/Ext_BU/output/Documents/Documents/washing
machine/rdiff-backup.tmp.29108
Writing resource fork to ('Documents', 'Documents', 'washing
machine', 'rdiff-backup.tmp.29108')
Writing carbon data to ('Documents', 'Documents', 'washing machine',
'rdiff-backup.tmp.29108')
Setting time of /Volumes/Ext_BU/output/Documents/Documents/washing
machine/rdiff-backup.tmp.29108 to 1065905658
Incrementing mirror file /Volumes/Ext_BU/output/Documents/Documents/
washing machine/PA080004.jpg
Touching /Volumes/Ext_BU/output/rdiff-backup-data/increments/
Documents/Documents/washing machine/PA080004.jpg.
2005-11-13T07:24:36-05:00.missing
Renaming /Volumes/Ext_BU/output/Documents/Documents/washing machine/
rdiff-backup.tmp.29108 to /Volumes/Ext_BU/output/Documents/Documents/
washing machine/PA080004.jpg
Copying attributes from ('Documents', 'Documents', 'washing machine')
to /Volumes/Ext_BU/output/Documents/Documents/washing machine
Setting time of /Volumes/Ext_BU/output/Documents/Documents/washing
machine to 1065905658
Copying attributes from ('Documents', 'Documents') to /Volumes/Ext_BU/
output/Documents/Documents
Setting time of /Volumes/Ext_BU/output/Documents/Documents to 1131886341
Copying attributes from ('Documents',) to /Volumes/Ext_BU/output/
Documents
Setting time of /Volumes/Ext_BU/output/Documents to 1131886108
Copying attributes from () to /Volumes/Ext_BU/output
Setting time of /Volumes/Ext_BU/output to 1131886041
Writing mirror_metadata diff
Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 230, in patch_and_increment
cls.CCPP.close()
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 446, in close
metadata.ManagerObj.ConvertMetaToDiff()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 593, in ConvertMetaToDiff
for diff_rorp in self.get_diffiter(new_iter, old_iter):
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 555, in get_diffiter
for new_rorp, old_rorp in rorpiter.Collate2Iters(new_iter,
old_iter):
File "/sw/lib/python2.4/site-packages/rdiff_backup/rorpiter.py",
line 92, in Collate2Iters
try: relem1 = riter1.next()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 261, in iterate
try: yield self.record_to_object(record)
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 169, in Record2RORP
else: data_dict['resourcefork'] = binascii.unhexlify(data)
TypeError: Non-hexadecimal digit found
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
output/rdiff-backup-data/file_statistics.
2005-11-13T08:03:13-05:00.data.gz', mode 'wb' at 0x79fad0 0x1205080>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/Ext_BU/
output/rdiff-backup-data/error_log.
2005-11-13T08:03:13-05:00.data.gz', mode 'wb' at 0x3892f0 0x7b17b0>>
ignored


Kevin Horton
Ottawa, Canada

Kevin Horton <khorton01 < at > rogers.com>
wrote the following on Sun, 13 Nov 2005 08:39:19 -0500

I added the above patch, then did some tests, starting with a small
directory to backup, and adding a bunch of files after each
successful backup. I've finally gotten a failure, and it looks
different than any I remember from before, so I'm reporting it now
(TypeError: Non-hexadecimal digit found).

Writing mirror_metadata diff
...
TypeError: Non-hexadecimal digit found

This is another error reading the metadata file. In the
rdiff-backup-data directory there should be two mirror_metadata
snapshots, and some diffs. One of the diffs should be only half
written, but the two snapshots should be intact. Do they validate
correctly with gzip -t and look normal at the end if you just view
them? If so, try:

zcat mirror_metadata.<time>.snapshot.gz | grep ResourceFork

to see the resource fork lines. Anything weird there? All the lines
should look like one of these two:

ResourceFork None
ResourceFork <hex data>

If there are too many lines to look through manually easily, you could
use this logging patch, so you can see what data it's having a problem
with.

--- metadata.py 2005-11-05 21:24:33.000000000 -0600
+++ metadata.py.new 2005-11-13 10:52:18.000000000 -0600
< at > < at > -166,7 +166,9 < at > < at >
elif field == "Size": data_dict['size'] = long(data)
elif field == "ResourceFork":
if data == "None": data_dict['resourcefork'] = ""
- else: data_dict['resourcefork'] = binascii.unhexlify(data)
+ else:
+ log.Log("Resource fork data: %s" % (data,), 5)
+ data_dict['resourcefork'] = binascii.unhexlify(data)
elif field == "CarbonFile":
if data == "None": data_dict['carbonfile'] = None
else: data_dict['carbonfile'] = string2carbonfile(data)


--
Ben Escoto

On 13 Nov 2005, at 11:54, Ben Escoto wrote:

Kevin Horton <khorton01 < at > rogers.com>
wrote the following on Sun, 13 Nov 2005 08:39:19 -0500

I added the above patch, then did some tests, starting with a small
directory to backup, and adding a bunch of files after each
successful backup. I've finally gotten a failure, and it looks
different than any I remember from before, so I'm reporting it now
(TypeError: Non-hexadecimal digit found).

Writing mirror_metadata diff
...
TypeError: Non-hexadecimal digit found

This is another error reading the metadata file. In the
rdiff-backup-data directory there should be two mirror_metadata
snapshots, and some diffs. One of the diffs should be only half
written, but the two snapshots should be intact. Do they validate
correctly with gzip -t and look normal at the end if you just view
them? If so, try:

zcat mirror_metadata.<time>.snapshot.gz | grep ResourceFork

to see the resource fork lines. Anything weird there? All the lines
should look like one of these two:

ResourceFork None
ResourceFork <hex data>

If there are too many lines to look through manually easily, you could
use this logging patch, so you can see what data it's having a problem
with.

<-- patch snipped -->

There are actually three mirror_metadata snapshots. The first two
are OK with gzip -t and zcat, but the last one is corrupted (and huge
- 81 Megs).

The ResourceFork lines in the first two look normal, but the third
one is so big that I can't really look at (251 Meg of ResourceFork
lines). I'll add the logging patch and try again with the original
input directory.

Kevin Horton
Ottawa, Canada

On 13 Nov 2005, at 12:57, Kevin Horton wrote:

On 13 Nov 2005, at 11:54, Ben Escoto wrote:

Kevin Horton <khorton01 < at > rogers.com>
wrote the following on Sun, 13 Nov 2005 08:39:19 -0500

I added the above patch, then did some tests, starting with a small
directory to backup, and adding a bunch of files after each
successful backup. I've finally gotten a failure, and it looks
different than any I remember from before, so I'm reporting it now
(TypeError: Non-hexadecimal digit found).

Writing mirror_metadata diff
...
TypeError: Non-hexadecimal digit found

This is another error reading the metadata file. In the
rdiff-backup-data directory there should be two mirror_metadata
snapshots, and some diffs. One of the diffs should be only half
written, but the two snapshots should be intact. Do they validate
correctly with gzip -t and look normal at the end if you just view
them? If so, try:

zcat mirror_metadata.<time>.snapshot.gz | grep ResourceFork

to see the resource fork lines. Anything weird there? All the lines
should look like one of these two:

ResourceFork None
ResourceFork <hex data>

If there are too many lines to look through manually easily, you
could
use this logging patch, so you can see what data it's having a
problem
with.

<-- patch snipped -->

There are actually three mirror_metadata snapshots. The first two
are OK with gzip -t and zcat, but the last one is corrupted (and
huge - 81 Megs).

The ResourceFork lines in the first two look normal, but the third
one is so big that I can't really look at (251 Meg of ResourceFork
lines). I'll add the logging patch and try again with the original
input directory.


I've lost count of how many different backups I've tried in the last
two days, adding more files for each incremental backup, without a
failure until tonight. I did have two cases where the Terminal
program crashed, taking the rdiff-backup process with it. I'd never
had a crash of Terminal.app before. I guessed that the problem was
the screen buffer eventually got too big (I had changed the default
10,000 line buffer to unlimited, so as to not miss anything
important). I changed the buffer back to 10,000 lines, and no more
crashes of Terminal.app.

I had reported a previous rdiff-backup failure, before the logging
patch. I redid the same input directory with no failure, and kept on
adding stuff to it without a failure, until I finally ran out of room
on that drive. So, I did a full backup of my Home directory, and
then two or three incremental backups. I finally got a failure
tonight. The failure ends with:

Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 226, in patch_and_increment
for diff in rorpiter.FillInIter(source_diffiter, dest_rpath):
File "/sw/lib/python2.4/site-packages/rdiff_backup/rorpiter.py",
line 177, in FillInIter
for rp in rpiter:
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 103, in get_diffs
for dest_sig in dest_sigiter:
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 166, in get_sigs
for src_rorp, dest_rorp in cls.CCPP:
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 306, in next
source_rorp, dest_rorp = self.iter.next()
File "/sw/lib/python2.4/site-packages/rdiff_backup/rorpiter.py",
line 100, in Collate2Iters
try: relem2 = riter2.next()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 263, in iterate
try: yield self.record_to_object(record)
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 171, in Record2RORP
data_dict['resourcefork'] = binascii.unhexlify(data)
TypeError: Non-hexadecimal digit found
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/file_statistics.
2005-11-14T19:38:13-05:00.data.gz', mode 'wb' at 0x79f8d8 0x7b67b0>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/error_log.
2005-11-14T19:38:13-05:00.data.gz', mode 'wb' at 0x79f578 0x7b34b8>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/mirror_metadata.
2005-11-14T19:38:13-05:00.snapshot.gz', mode 'wb' at 0x79f920
0x7b67d8>> ignored

Before that, there is just an unending line of hex stuff. I scrolled
all the way back to the top of the screen buffer, and it is all just
one long line of hex, with untold thousands of characters. Anything
interesting scrolled of the top of the buffer. I guess I should
start using "screen" again, to take advantage of its logging. Or
maybe "tee".

The error_log in the rdiff-backup-data directory shows:

# zcat error_log.2005-11-14T19:38:13-05:00.data.gz
UpdateError Desktop/RV_Stuff/POH archive/graphs/all-3.gp Updated
mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/RV_Stuff/POH
archive/graphs/rdiff-backup.tmp.4 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/cg_chart-4.gp Updated
mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/RV_Stuff/POH
archive/graphs/rdiff-backup.tmp.5 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/data/cg_chart-2.txt
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/data/rdiff-backup.tmp.6 does not match
source
UpdateError Desktop/RV_Stuff/POH archive/graphs/data/g-chart-2.txt
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/data/rdiff-backup.tmp.7 does not match
source
UpdateError Desktop/RV_Stuff/POH archive/graphs/data/wb-moment-
chart-2.txt Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/
Desktop/RV_Stuff/POH archive/graphs/data/rdiff-backup.tmp.8 does not
match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/g-chart-1.gp Updated
mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/RV_Stuff/POH
archive/graphs/rdiff-backup.tmp.9 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/wb-cg-chart-4.gp
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/rdiff-backup.tmp.10 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/wb-moment-chart-3.gp
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/rdiff-backup.tmp.11 does not match source

zcat: error_log.2005-11-14T19:38:13-05:00.data.gz: unexpected end of
file

Does that failure output tell any useful clues? What other useful
info can I provide?


Kevin Horton
Ottawa, Canada

On 14 Nov 2005, at 20:23, Kevin Horton wrote:

On 13 Nov 2005, at 12:57, Kevin Horton wrote:

On 13 Nov 2005, at 11:54, Ben Escoto wrote:

Kevin Horton <khorton01 < at > rogers.com>
wrote the following on Sun, 13 Nov 2005 08:39:19 -0500

I added the above patch, then did some tests, starting with a small
directory to backup, and adding a bunch of files after each
successful backup. I've finally gotten a failure, and it looks
different than any I remember from before, so I'm reporting it now
(TypeError: Non-hexadecimal digit found).

Writing mirror_metadata diff
...
TypeError: Non-hexadecimal digit found

This is another error reading the metadata file. In the
rdiff-backup-data directory there should be two mirror_metadata
snapshots, and some diffs. One of the diffs should be only half
written, but the two snapshots should be intact. Do they validate
correctly with gzip -t and look normal at the end if you just view
them? If so, try:

zcat mirror_metadata.<time>.snapshot.gz | grep ResourceFork

to see the resource fork lines. Anything weird there? All the
lines
should look like one of these two:

ResourceFork None
ResourceFork <hex data>

If there are too many lines to look through manually easily, you
could
use this logging patch, so you can see what data it's having a
problem
with.

<-- patch snipped -->

There are actually three mirror_metadata snapshots. The first two
are OK with gzip -t and zcat, but the last one is corrupted (and
huge - 81 Megs).

The ResourceFork lines in the first two look normal, but the third
one is so big that I can't really look at (251 Meg of ResourceFork
lines). I'll add the logging patch and try again with the
original input directory.


I've lost count of how many different backups I've tried in the
last two days, adding more files for each incremental backup,
without a failure until tonight. I did have two cases where the
Terminal program crashed, taking the rdiff-backup process with it.
I'd never had a crash of Terminal.app before. I guessed that the
problem was the screen buffer eventually got too big (I had changed
the default 10,000 line buffer to unlimited, so as to not miss
anything important). I changed the buffer back to 10,000 lines,
and no more crashes of Terminal.app.

I had reported a previous rdiff-backup failure, before the logging
patch. I redid the same input directory with no failure, and kept
on adding stuff to it without a failure, until I finally ran out of
room on that drive. So, I did a full backup of my Home directory,
and then two or three incremental backups. I finally got a failure
tonight. The failure ends with:

Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 226, in patch_and_increment
for diff in rorpiter.FillInIter(source_diffiter, dest_rpath):
File "/sw/lib/python2.4/site-packages/rdiff_backup/rorpiter.py",
line 177, in FillInIter
for rp in rpiter:
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 103, in get_diffs
for dest_sig in dest_sigiter:
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 166, in get_sigs
for src_rorp, dest_rorp in cls.CCPP:
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 306, in next
source_rorp, dest_rorp = self.iter.next()
File "/sw/lib/python2.4/site-packages/rdiff_backup/rorpiter.py",
line 100, in Collate2Iters
try: relem2 = riter2.next()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 263, in iterate
try: yield self.record_to_object(record)
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 171, in Record2RORP
data_dict['resourcefork'] = binascii.unhexlify(data)
TypeError: Non-hexadecimal digit found
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/file_statistics.
2005-11-14T19:38:13-05:00.data.gz', mode 'wb' at 0x79f8d8
0x7b67b0>> ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/error_log.
2005-11-14T19:38:13-05:00.data.gz', mode 'wb' at 0x79f578
0x7b34b8>> ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/mirror_metadata.
2005-11-14T19:38:13-05:00.snapshot.gz', mode 'wb' at 0x79f920
0x7b67d8>> ignored

Before that, there is just an unending line of hex stuff. I
scrolled all the way back to the top of the screen buffer, and it
is all just one long line of hex, with untold thousands of
characters. Anything interesting scrolled of the top of the
buffer. I guess I should start using "screen" again, to take
advantage of its logging. Or maybe "tee".

The error_log in the rdiff-backup-data directory shows:

# zcat error_log.2005-11-14T19:38:13-05:00.data.gz
UpdateError Desktop/RV_Stuff/POH archive/graphs/all-3.gp Updated
mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/RV_Stuff/
POH archive/graphs/rdiff-backup.tmp.4 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/cg_chart-4.gp
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/rdiff-backup.tmp.5 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/data/cg_chart-2.txt
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/data/rdiff-backup.tmp.6 does not match
source
UpdateError Desktop/RV_Stuff/POH archive/graphs/data/g-chart-2.txt
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/data/rdiff-backup.tmp.7 does not match
source
UpdateError Desktop/RV_Stuff/POH archive/graphs/data/wb-moment-
chart-2.txt Updated mirror temp file /Volumes/Maxtor_300/bu/
PowerMac/Desktop/RV_Stuff/POH archive/graphs/data/rdiff-backup.tmp.
8 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/g-chart-1.gp
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/rdiff-backup.tmp.9 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/wb-cg-chart-4.gp
Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/Desktop/
RV_Stuff/POH archive/graphs/rdiff-backup.tmp.10 does not match source
UpdateError Desktop/RV_Stuff/POH archive/graphs/wb-moment-
chart-3.gp Updated mirror temp file /Volumes/Maxtor_300/bu/PowerMac/
Desktop/RV_Stuff/POH archive/graphs/rdiff-backup.tmp.11 does not
match source

zcat: error_log.2005-11-14T19:38:13-05:00.data.gz: unexpected end
of file

Does that failure output tell any useful clues? What other useful
info can I provide?


Well, I got another failure, this time while logging the whole
session with screen. I have the whole 1.2 GB session log, but have
no idea what to look for. The failure ends with:

Traceback (most recent call last):
File "/sw/bin/rdiff-backup", line 23, in ?
rdiff_backup.Main.Main(sys.argv[1:])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
303, in Main
take_action(rps)
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
272, in take_action
elif action == "backup": Backup(rps[0], rps[1])
File "/sw/lib/python2.4/site-packages/rdiff_backup/Main.py", line
323, in Backup
backup.Mirror_and_increment(rpin, rpout, incdir)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 51, in Mirror_and_increment
DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 230, in patch_and_increment
cls.CCPP.close()
File "/sw/lib/python2.4/site-packages/rdiff_backup/backup.py",
line 446, in close
metadata.ManagerObj.ConvertMetaToDiff()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 595, in ConvertMetaToDiff
for diff_rorp in self.get_diffiter(new_iter, old_iter):
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 557, in get_diffiter
for new_rorp, old_rorp in rorpiter.Collate2Iters(new_iter,
old_iter):
File "/sw/lib/python2.4/site-packages/rdiff_backup/rorpiter.py",
line 92, in Collate2Iters
try: relem1 = riter1.next()
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 263, in iterate
try: yield self.record_to_object(record)
File "/sw/lib/python2.4/site-packages/rdiff_backup/metadata.py",
line 171, in Record2RORP
data_dict['resourcefork'] = binascii.unhexlify(data)
TypeError: Non-hexadecimal digit found
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/file_statistics.
2005-11-15T16:05:46-05:00.data.gz', mode 'wb' at 0x7af968 0x7c6a80>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable"
in <bound method GzipFile.__del__ of <gzip open file '/Volumes/
Maxtor_300/bu/PowerMac/rdiff-backup-data/error_log.
2005-11-15T16:05:46-05:00.data.gz', mode 'wb' at 0x7af578 0x7c34b8>>
ignored

Before this failure traceback, I only see Resource fork data lines,
with hex data. Very, very, very long lines. The last Resource fork
line just above the traceback is about 1,800,000 characters long. Is
this expected?

Kevin


Kevin Horton
Ottawa, Canada

Kevin Horton <khorton01 < at > rogers.com>
wrote the following on Tue, 15 Nov 2005 20:39:49 -0500

Hmm, I don't really know what could be the problem. My one thought is
that there might be a problem with python's gzip on your system. I've
written a little gzip script on your system, you can download it at:

https://savannah.nongnu.org/bugs/download.php?item_id=15006&item_file_id=3111

Once saved you can:

chmod 755 gzip-python
./gzip-python <file>

and it will work a bit like gzip, writing a compressed version of
<file> to <file>.gz. So I'd be interested to see if you can compress
files (including large files, like 4GB+ files) that decompress to the
correct original files.

Before this failure traceback, I only see Resource fork data lines,
with hex data. Very, very, very long lines. The last Resource fork
line just above the traceback is about 1,800,000 characters long. Is
this expected?

I guess it depends on the size of the resource fork. I forget how big
resource forks are supposed to be, but there was a discussion a long
time ago when they were added, and whoever added them apparently
thought that they would be small enough to put in the mirror_metadata
file. Isn't there some quick way on Mac OS to tell how long a file's
resource fork is?

This resource fork error may also be a symptom of a corrupted
mirror_metadata file, so you may want to use --no-resource-forks when
testing, until the mirror_metadata problem gets fixed.


--
Ben Escoto