Re: [rdiff-backup-users] 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 <address@hidden>
> > > > > > > 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