Re: [rdiff-backup-users] 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 <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?

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