rdiff-backup 1.1.2 testing - problems

classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

rdiff-backup 1.1.2 testing - problems

Kevin Horton
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




_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Ben Escoto
>>>>> Kevin Horton <[hidden email]>

>>>>> 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

_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki

attachment0 (196 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

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

>>>>>> Kevin Horton <[hidden email]>
>>>>>> 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




_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Ben Escoto
>>>>> Kevin Horton <[hidden email]>

>>>>> 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
@@ -166,7 +166,9 @@
                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

_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki

attachment0 (196 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Kevin Horton

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

>>>>>> Kevin Horton <[hidden email]>
>>>>>> 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




_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

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

> On 13 Nov 2005, at 11:54, Ben Escoto wrote:
>
>>>>>>> Kevin Horton <[hidden email]>
>>>>>>> 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




_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Kevin Horton
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 <[hidden email]>
>>>>>>>> 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




_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Ben Escoto
>>>>> Kevin Horton <[hidden email]>
>>>>> 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

_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki

attachment0 (196 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Kevin Horton
On 19 Nov 2005, at 24:21, Ben Escoto wrote:

>>>>>> Kevin Horton <[hidden email]>
>>>>>> 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.

I did a whole bunch of testing using the above gzip-python script.  
There is indeed a problem somewhere with large files.  I got a high  
failure rate with large (5.7 GB) files using fink's python 2.4.2 and  
also with Apple's stock python 2.3.5.  I will take this up in another  
forum.

I'm giving up on rdiff-backup for now, as it seems that there are  
python issues on OS X that make it unreliable for me.  I am prepared  
to help out with testing in my spare time, and I hope to be using  
rdiff-backup again someday.


Kevin Horton
Ottawa, Canada




_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Scott Lamb
In reply to this post by Ben Escoto
On 18 Nov 2005, at 21:21, Ben Escoto wrote:
> 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?

Yep.

$ ls -l 'Quicken Data.qdfm/Contents/Data File/rsrc'
-rw-rw----   1 slamb  slamb  1525662 Nov 25 12:10 Quicken Data.qdfm/
Contents/Data File/rsrc

I think it's unusual for resource forks to be this large - or even  
exist, on a modern system - but it will be true for any Quicken data  
file. (!@#$@# Intuit.)

--
Scott Lamb <http://www.slamb.org/>



_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Ben Escoto
In reply to this post by Kevin Horton
>>>>> Kevin Horton <[hidden email]>
>>>>> wrote the following on Sat, 26 Nov 2005 09:00:08 -0500
>
> I did a whole bunch of testing using the above gzip-python script.  
> There is indeed a problem somewhere with large files.  I got a high  
> failure rate with large (5.7 GB) files using fink's python 2.4.2 and  
> also with Apple's stock python 2.3.5.  I will take this up in another  
> forum.

Thanks for your testing---with the bugs we got I think the iffy gzip
support may be the only major issue remaining.  (Also I'm glad it's
not my responsibility this time :-))


--
Ben Escoto

_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki

attachment0 (196 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Kevin Horton
In reply to this post by Kevin Horton
On 26 Nov 2005, at 09:00, Kevin Horton wrote:

> On 19 Nov 2005, at 24:21, Ben Escoto wrote:
>
>>>>>>> Kevin Horton <[hidden email]>
>>>>>>> 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.
>
> I did a whole bunch of testing using the above gzip-python script.  
> There is indeed a problem somewhere with large files.  I got a high  
> failure rate with large (5.7 GB) files using fink's python 2.4.2  
> and also with Apple's stock python 2.3.5.  I will take this up in  
> another forum.
>
> I'm giving up on rdiff-backup for now, as it seems that there are  
> python issues on OS X that make it unreliable for me.  I am  
> prepared to help out with testing in my spare time, and I hope to  
> be using rdiff-backup again someday.

I eventually figured out that I had a bad stick of RAM.  It seemed to  
work fine most of the time, but it had one bit at one location that  
would stick if the machine was working hard.   One run of tests in  
memtest would pass, but if you put it on several rounds of successive  
tests it would start failing.  I pulled that bad stick out, and have  
been using rdiff-backup hard for the last week - no failures.  I also  
did a large number of tests using your gzip-python script on a 5.7GB  
file - no failures.

So, I will be happy to participate in any OS X related testing  
again.  I'm currently using rdiff-backup 1.1.4, installed via the  
fink packaging system, with no extra patches.

Kevin Horton
Ottawa, Canada




_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
Reply | Threaded
Open this post in threaded view
|

Re: rdiff-backup 1.1.2 testing - problems

Ben Escoto
>>>>> Kevin Horton <[hidden email]>

>>>>> wrote the following on Fri, 30 Dec 2005 14:42:32 -0500
>
> I eventually figured out that I had a bad stick of RAM.  It seemed to  
> work fine most of the time, but it had one bit at one location that  
> would stick if the machine was working hard.   One run of tests in  
> memtest would pass, but if you put it on several rounds of successive  
> tests it would start failing.  I pulled that bad stick out, and have  
> been using rdiff-backup hard for the last week - no failures.  I also  
> did a large number of tests using your gzip-python script on a 5.7GB  
> file - no failures.
Thanks for the update.  It's always nice to hear when problems
definitely aren't my fault :-)


--
Ben Escoto

_______________________________________________
rdiff-backup-users mailing list at [hidden email]
http://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki

attachment0 (196 bytes) Download Attachment