[rdiff-backup-users] RE: strange traceback

[Sacerdoti, Federico]

Sorry for the inundation, but I have more data on this problem. I
renamed the logfiles, and now I see another issue: the 'increments'
state is corrupted. The regression logic seems to be broken.

Thanks,
Federico

Previous backup seems to have failed, regressing destination now.
Traceback (most recent call last):
  File "/usr/bin/rdiff-backup", line 23, in ?
    rdiff_backup.Main.Main(sys.argv[1:])
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line
285, in Main
    take_action(rps)
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line
255, in take_action
    elif action == "backup": Backup(rps[0], rps[1])
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line
305, in Backup
    backup.Mirror_and_increment(rpin, rpout, incdir)
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py", line
51, in Mirror_and_increment
    DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py", line
229, in patch_and_increment
    ITR(diff.index, diff)
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/rorpiter.py",
line 285, in __call__
    last_branch.fast_process(*args)
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py", line
623, in fast_process
    inc.fsync_with_dir() # Write inc before rp changed
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/rpath.py", line
1081, in fsync_with_dir
    if Globals.fsync_directories: self.get_parent_rp().fsync()
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/rpath.py", line
1068, in fsync
    if not fp: self.conn.rpath.RPath.fsync_local(self)
  File "/usr/lib64/python2.3/site-packages/rdiff_backup/rpath.py", line
1074, in fsync_local
    fd = os.open(self.path, os.O_RDONLY)
OSError: [Errno 13] Permission denied:
'/backup/drdsb01/drdsa01/rdiff-backup-data/increments/klepeisj/Desmond2/
suPAR_NCI/ATTN1102/prod_xp_snap2_400K/indiv_pdbs/mmgbsa_run_drda0280_10'
Exception exceptions.TypeError: "'NoneType' object is not callable" in
<bound method GzipFile.__del__ of <gzip open file
'/backup/drdsb01/drdsa01/rdiff-backup-data/file_statistics.2006-11-06T11
:29:31-05:00.data.gz', mode 'wb' at 0x2aaaade2b9d0 0x2aaaaf18e710>>
ignored
Exception exceptions.TypeError: "'NoneType' object is not callable" in
<bound method GzipFile.__del__ of <gzip open file
'/backup/drdsb01/drdsa01/rdiff-backup-data/error_log.2006-11-06T11:29:31
-05:00.data.gz', mode 'wb' at 0x2aaaad9f5500 0x2aaaada01e60>> ignored
Exception exceptions.TypeError: "'NoneType' object is not callable" in
<bound method GzipFile.__del__ of <gzip open file
'/backup/drdsb01/drdsa01/rdiff-backup-data/mirror_metadata.2006-11-06T11
:29:31-05:00.snapshot.gz', mode 'wb' at 0x2aaaada06570 0x2aaaaf18e8c0>>
ignored
error - exceptions.Exception: backup:rc=256

> _____________________________________________ 
> From:         Sacerdoti, Federico  
> Sent: Monday, November 06, 2006 11:30 AM
> To:   Sacerdoti, Federico; 'address@hidden'
> Subject:      RE: strange traceback
> 
> Here is a nicer traceback of the problem. Perhaps the old logs should
> be renamed before the regression is attempted?
> 
> Thanks,
> Federico
> 
> Previous backup seems to have failed, regressing destination now.
> Traceback (most recent call last):
>   File "/usr/bin/rdiff-backup", line 23, in ?
>     rdiff_backup.Main.Main(sys.argv[1:])
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line
> 285, in Main
>     take_action(rps)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line
> 255, in take_action
>     elif action == "backup": Backup(rps[0], rps[1])
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line
> 305, in Backup
>     backup.Mirror_and_increment(rpin, rpout, incdir)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py",
> line 51, in Mirror_and_increment
>     DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py",
> line 229, in patch_and_increment
>     ITR(diff.index, diff)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/rorpiter.py",
> line 285, in __call__
>     last_branch.fast_process(*args)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py",
> line 617, in fast_process
>     if self.patch_to_temp(rp, diff_rorp, tf):
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py",
> line 511, in patch_to_temp
>     (diff_rorp, new)) == 0: return 0
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/robust.py",
> line 39, in check_common_error
>     if error_handler: return error_handler(exc, *args)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/robust.py",
> line 71, in error_handler
>     log.ErrorLog.write_if_open(error_type, rp, exc)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line
> 253, in write_if_open
>     if cls.isopen(): cls.write(error_type, rp, exc)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line
> 234, in write
>     Log(s, 2)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line
> 119, in __call__
>     if verbosity <= self.verbosity: self.log_to_file(message)
>   File "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line
> 128, in log_to_file
>     self.logfp.flush()
> IOError: [Errno 13] Permission denied
> Exception exceptions.TypeError: "'NoneType' object is not callable" in
> <bound method GzipFile.__del__ of <gzip open file
> '/backup/drdsb01/drdsa01/rdiff-backup-data/file_statistics.2006-11-06T
> 10:39:18-05:00.data.gz', mode 'wb' at 0x2aaaade2b9d0 0x2aaaaf1b9440>>
> ignored
> Exception exceptions.TypeError: "'NoneType' object is not callable" in
> <bound method GzipFile.__del__ of <gzip open file
> '/backup/drdsb01/drdsa01/rdiff-backup-data/error_log.2006-11-06T10:39:
> 18-05:00.data.gz', mode 'wb' at 0x2aaaad9f5500 0x2aaaaab387a0>>
> ignored
> Exception exceptions.TypeError: "'NoneType' object is not callable" in
> <bound method GzipFile.__del__ of <gzip open file
> '/backup/drdsb01/drdsa01/rdiff-backup-data/mirror_metadata.2006-11-06T
> 10:39:18-05:00.snapshot.gz', mode 'wb' at 0x2aaaada06570
> 0x2aaaaf1b9cf8>> ignored
> error - exceptions.Exception: backup:rc=256
> 
>       _____________________________________________ 
>       From:   Sacerdoti, Federico  
>       Sent:   Monday, November 06, 2006 10:52 AM
>       To:     'address@hidden'
>       Subject:        strange traceback
> 
>       Hi,
> 
>       I am using rdiff-backup sucessfully to backup very large NAS
> servers (~3TB each). The setup is one primary nas, one secondary nas.
> 
>       I use the "local" method of rdiff backup, where I mount the
> secondary's volume on the primary via NFS, then tell rdiff-backup to
> use the mountpoint as the destination.
> 
>       Things have been humming along as expected for several weeks,
> until last night. My nightly rdiff-backup script emails errors if
> rdiff-backup returns non-zero. All 5 of my NAS primary servers emailed
> this traceback:
> 
>       (I apologize for the loss of newlines). Note these are
> indepedant servers and the tracebacks are identical. It is possible we
> experienced a network partition between the primary and backup last
> night.
> 
>       Thanks,
>       Federico
>       D. E. Shaw Research LLC
> 
>       rdiff-backup:did not succeed: 
> 
>        Previous backup seems to have failed, regressing destination
> now. Traceback (most recent call last): File "/usr/bin/rdiff-backup",
> line 23, in u rdiff_backup.Main.Main(sys.argv[1:]) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line 285,
> in Main take_action(rps) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line 255,
> in take_action elif action == "backup": Backup(rps[0], rps[1]) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/Main.py", line 305,
> in Backup backup.Mirror_and_increment(rpin, rpout, incdir) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py", line 51,
> in Mirror_and_increment DestS.patch_and_increment(dest_rpath,
> source_diffiter, inc_rpath) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py", line 229,
> in patch_and_increment ITR(diff.index, diff) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/rorpiter.py", line
> 285, in __call__ last_branch.fast_process(*args) File
> "/usr/lib64/python2.3/sit
>        e-packages/rdiff_backup/backup.py", line 617, in fast_process
> if self.patch_to_temp(rp, diff_rorp, tf): File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/backup.py", line 515,
> in patch_to_temp Rdiff.patch_local, (basis_rp, diff_rorp, new)) == 0:
> return 0 File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/robust.py", line 39,
> in check_common_error if error_handler: return error_handler(exc,
> *args) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/robust.py", line 71,
> in error_handler log.ErrorLog.write_if_open(error_type, rp, exc) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line 253, in
> write_if_open if cls.isopen(): cls.write(error_type, rp, exc) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line 234, in
> write Log(s, 2) File
> "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line 119, in
> __call__ if verbosity <= self.verbosity: self.log_to_file(message)
> File "/usr/lib64/python2.3/site-packages/rdiff_backup/log.py", line 1
>        28, in log_to_file self.logfp.flush() IOError: [Errno 13]
> Permission denied Exception exceptions.TypeError: "'NoneType' object
> is not callable" in <bound method GzipFile.__del__ of <gzip open file
> '/backup/drdsb04/drdsa04/rdiff-backup-data/file_statistics.2006-11-06T
> 04:02:17-05:00.data.gz', mode 'wb' at 0x2aaaaafea340 0x2aaaac1ac680>>
> ignored Exception exceptions.TypeError: "'NoneType' object is not
> callable" in <bound method GzipFile.__del__ of <gzip open file
> '/backup/drdsb04/drdsa04/rdiff-backup-data/error_log.2006-11-06T04:02:
> 17-05:00.data.gz', mode 'wb' at 0x2aaaaabac420 0x2aaaac1ad830>>
> ignored Exception exceptions.TypeError: "'NoneType' object is not
> callable" in <bound method GzipFile.__del__ of <gzip open file
> '/backup/drdsb04/drdsa04/rdiff-backup-data/mirror_metadata.2006-11-06T
> 04:02:17-05:00.snapshot.gz', mode 'wb' at 0x2aaaaafea110
> 0x2aaaac1acfc8>> ignored error - exceptions.Exception: backup:rc=256
>