[rdiff-backup-users] regression error with 0.11.4

[ruttmannn]

Hi!

The backup system here is in an error state, that was caused by
interupting a running rdiff-backup by hitting CTRL-C.  When trying
another backup run, it says correctly, that the last backup did fail
and enters regression mode. Sadly regression fails.

So I started digging into this error condition and would like to
present the results and discuss the next step before doing the next
step, possibly destroying the hole backup system and killing hundreds
of innocent people.

This is what I found out so far:

The regression terminates with this error messages:

######## terminal dump start ####

Thu Aug  7 14:06:54 2003  Regressing file usr/share/automake-1.6/COPYING
Thu Aug  7 14:06:55 2003  Sending back exception  of type 
exceptions.AssertionError:
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/connection.py", 
line 313, in answer_request
    result = apply(eval(request.function_string), argument_list)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/regress.py", line 
68, in Regress
    for rf in iterate_meta_rfs(mirror_rp, inc_rpath): ITR(rf.index, rf)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/rorpiter.py", line 
275, in __call__
    last_branch.fast_process(*args)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/regress.py", line 
211, in fast_process
    if rf.metadata_rorp.isreg(): self.restore_orig_regfile(rf)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/regress.py", line 
236, in restore_orig_regfile
    rf.mirror_rp.write_from_fileobj(rf.get_restore_fp())
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/restore.py", line 
374, in get_restore_fp
    assert self.relevant_incs[-1].isreg()

Thu Aug  7 14:06:55 2003  Server sending (0):
Thu Aug  7 13:57:00 2003  Client received (0):
Traceback (most recent call last):
  File "/usr/local/bin/rdiff-backup", line 24, in ?
    rdiff_backup.Main.Main(sys.argv[1:])
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/Main.py", line 236, 
in Main
    take_action(rps)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/Main.py", line 210, 
in take_action
    elif action == "backup": Backup(rps[0], rps[1])
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/Main.py", line 246, 
in Backup
    backup_init_dirs(rpin, rpout)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/Main.py", line 278, 
in backup_init_dirs
    checkdest_if_necessary(rpout)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/Main.py", line 608, 
in checkdest_if_necessary
    dest_rp.conn.regress.Regress(dest_rp)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/connection.py", 
line 424, in __call__
    return apply(self.connection.reval, (self.name,) + args)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/connection.py", 
line 346, in reval
    if isinstance(result, Exception): raise result
AssertionError
Traceback (most recent call last):
  File "/usr/local/bin/rdiff-backup", line 24, in ?
    rdiff_backup.Main.Main(sys.argv[1:])
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/Main.py", line 236, 
in Main
    take_action(rps)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/Main.py", line 208, 
in take_action
    connection.PipeConnection(sys.stdin, sys.stdout).Server()
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/connection.py", 
line 331, in Server
    self.get_response(-1)
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/connection.py", 
line 293, in get_response
    try: req_num, object = self._get()
  File "/usr/local/lib/python2.2/site-packages/rdiff_backup/connection.py", 
line 216, in _get
    raise ConnectionReadError("Truncated header string (problem "
rdiff_backup.connection.ConnectionReadError: Truncated header string (problem 
probably originated remotely)

######## terminal dump end ######

I tried a few things, like copying the automake-1.6/COPYING file
manually, after reading the mailing list archive, that this error
might be related to missing files. This did not help. 

I was thinking about upgrading to V12, but finally took a look at the
mirror metadata files and this looks like the real problem to me. As
you can see, the metadata file of the last backup is smaller than the
previous metadata files. As the host didn't change much, all metadata
files should be nearly of equal size.

But see yourself:

######## terminal dump start ####

-rw-------    1 root     root            0 Jul 15 20:31 
current_mirror.2003-07-15T20:21:28+02:00.data
-rw-------    1 root     root            0 Jul 18 11:19 
current_mirror.2003-07-18T11:09:46+02:00.data
-rw-------    1 root     root          346 Apr 13 05:18 
error_log.2003-04-12T14:51:37+02:00.data.gz
-rw-------    1 root     root          308 May  5 04:27 
error_log.2003-05-04T19:51:45+02:00.data.gz
-rw-------    1 root     root          306 Jun 17 04:12 
error_log.2003-06-16T23:40:49+02:00.data.gz
-rw-------    1 root     root          472 Jun 22 16:27 
error_log.2003-06-22T13:14:48+02:00.data.gz
-rw-------    1 root     root          264 Jun 25 23:44 
error_log.2003-06-25T20:31:33+02:00.data.gz
-rw-------    1 root     root          233 Jun 26 12:26 
error_log.2003-06-26T09:31:22+02:00.data.gz
-rw-------    1 root     root          245 Jun 27 15:45 
error_log.2003-06-27T12:50:00+02:00.data.gz
-rw-------    1 root     root          235 Jul  1 12:40 
error_log.2003-07-01T09:22:04+02:00.data.gz
-rw-------    1 root     root          255 Jul  6 00:35 
error_log.2003-07-05T18:55:00+02:00.data.gz
-rw-------    1 root     root          289 Jul  6 22:33 
error_log.2003-07-06T18:35:40+02:00.data.gz
-rw-------    1 root     root          204 Jul 16 00:27 
error_log.2003-07-15T20:21:28+02:00.data.gz
-rw-------    1 root     root           90 Jul 18 13:50 
error_log.2003-07-18T11:09:46+02:00.data.gz
-rw-------    1 root     root      5956603 Apr 13 05:18 
file_statistics.2003-04-12T14:51:37+02:00.data.gz
-rw-------    1 root     root      3615444 May  5 04:27 
file_statistics.2003-05-04T19:51:45+02:00.data.gz
-rw-------    1 root     root      3358861 Jun 17 04:12 
file_statistics.2003-06-16T23:40:49+02:00.data.gz
-rw-------    1 root     root      3344272 Jun 22 16:27 
file_statistics.2003-06-22T13:14:48+02:00.data.gz
-rw-------    1 root     root      3347925 Jun 25 23:44 
file_statistics.2003-06-25T20:31:33+02:00.data.gz
-rw-------    1 root     root      3337158 Jun 26 12:26 
file_statistics.2003-06-26T09:31:22+02:00.data.gz
-rw-------    1 root     root      3337806 Jun 27 15:45 
file_statistics.2003-06-27T12:50:00+02:00.data.gz
-rw-------    1 root     root      3337892 Jul  1 12:40 
file_statistics.2003-07-01T09:22:04+02:00.data.gz
-rw-------    1 root     root      3347150 Jul  6 00:35 
file_statistics.2003-07-05T18:55:00+02:00.data.gz
-rw-------    1 root     root      3387360 Jul  6 22:33 
file_statistics.2003-07-06T18:35:40+02:00.data.gz
-rw-------    1 root     root      3416378 Jul 16 00:27 
file_statistics.2003-07-15T20:21:28+02:00.data.gz
-rw-------    1 root     root      1150976 Jul 18 13:50 
file_statistics.2003-07-18T11:09:46+02:00.data.gz
drwx------   18 root     root         5792 Jul 18 14:20 increments
-rwxr-xr-x    1 root     root            0 May 24  2002 
increments.2003-04-12T14:51:37+02:00.dir
-rwxr-xr-x    1 root     root            0 May  1 13:51 
increments.2003-05-04T19:51:45+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-06-16T23:40:49+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-06-22T13:14:48+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-06-25T20:31:33+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-06-26T09:31:22+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-06-27T12:50:00+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-07-01T09:22:04+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-07-05T18:55:00+02:00.dir
-rwxr-xr-x    1 root     root            0 May  5 21:23 
increments.2003-07-06T18:35:40+02:00.dir
-rwxr-xr-x    1 root     root            0 Jul  6 18:37 
increments.2003-07-15T20:21:28+02:00.dir
-rw-------    1 root     root      3968243 Apr 13 05:18 
mirror_metadata.2003-04-12T14:51:37+02:00.snapshot.gz
-rw-------    1 root     root      3903060 May  5 04:27 
mirror_metadata.2003-05-04T19:51:45+02:00.snapshot.gz
-rw-------    1 root     root      3909509 Jun 17 04:12 
mirror_metadata.2003-06-16T23:40:49+02:00.snapshot.gz
-rw-------    1 root     root      3909007 Jun 22 16:27 
mirror_metadata.2003-06-22T13:14:48+02:00.snapshot.gz
-rw-------    1 root     root      3907597 Jun 25 23:44 
mirror_metadata.2003-06-25T20:31:33+02:00.snapshot.gz
-rw-------    1 root     root      3907621 Jun 26 12:26 
mirror_metadata.2003-06-26T09:31:22+02:00.snapshot.gz
-rw-------    1 root     root      3907945 Jun 27 15:45 
mirror_metadata.2003-06-27T12:50:00+02:00.snapshot.gz
-rw-------    1 root     root      3908018 Jul  1 12:40 
mirror_metadata.2003-07-01T09:22:04+02:00.snapshot.gz
-rw-------    1 root     root      3908951 Jul  6 00:35 
mirror_metadata.2003-07-05T18:55:00+02:00.snapshot.gz
-rw-------    1 root     root      3972698 Jul  6 22:33 
mirror_metadata.2003-07-06T18:35:40+02:00.snapshot.gz
-rw-------    1 root     root      3937036 Jul 16 00:27 
mirror_metadata.2003-07-15T20:21:28+02:00.snapshot.gz
-rw-------    1 root     root      1339454 Jul 18 13:50 
mirror_metadata.2003-07-18T11:09:46+02:00.snapshot.gz
-rw-------    1 root     root         2692 Jul 16 09:16 restore.log
-rw-------    1 root     root          575 Apr 13 05:18 
session_statistics.2003-04-12T14:51:37+02:00.data
-rw-------    1 root     root          582 May  5 04:27 
session_statistics.2003-05-04T19:51:45+02:00.data
-rw-------    1 root     root          577 Jun 17 04:12 
session_statistics.2003-06-16T23:40:49+02:00.data
-rw-------    1 root     root          566 Jun 22 16:27 
session_statistics.2003-06-22T13:14:48+02:00.data
-rw-------    1 root     root          568 Jun 25 23:44 
session_statistics.2003-06-25T20:31:33+02:00.data
-rw-------    1 root     root          544 Jun 26 12:26 
session_statistics.2003-06-26T09:31:22+02:00.data
-rw-------    1 root     root          558 Jun 27 15:45 
session_statistics.2003-06-27T12:50:00+02:00.data
-rw-------    1 root     root          556 Jul  1 12:40 
session_statistics.2003-07-01T09:22:04+02:00.data
-rw-------    1 root     root          570 Jul  6 00:35 
session_statistics.2003-07-05T18:55:00+02:00.data
-rw-------    1 root     root          568 Jul  6 22:33 
session_statistics.2003-07-06T18:35:40+02:00.data
-rw-------    1 root     root          577 Jul 16 00:27 
session_statistics.2003-07-15T20:21:28+02:00.data

 # gzip -d -c mirror_metadata.2003-07-06T18\:35\:40+02\:00.snapshot.gz | wc
2715675 5455409 54203158

 # gzip -d -c mirror_metadata.2003-07-15T20\:21\:28+02\:00.snapshot.gz | wc
2696014 5416099 53797413

 # gzip -d -c mirror_metadata.2003-07-18T11\:09\:46+02\:00.snapshot.gz | wc
 944324 1892190 18295248

 # gzip -d -c error_log.2003-07-15T20\:21\:28+02\:00.data.gz | wc
      1      11     131

 # gzip -d -c error_log.2003-07-18T11\:09\:46+02\:00.data.gz | wc
gzip: error_log.2003-07-18T11:09:46+02:00.data.gz: unexpected end of file
      0       0       0

 # gzip -d -c file_statistics.2003-07-15T20\:21\:28+02\:00.data.gz | wc
 391935 1971932 26629348

 # gzip -d -c file_statistics.2003-07-18T11\:09\:46+02\:00.data.gz | wc
 136302  681547 8567496

######## terminal dump end ######

Notice, that gzip doesn't complain about corrupted compressed data, so
it must have correctly closed the file.

So I think the mirror metadata file is corrupted. What to do now?
Deleting it? Magic command line switch to rdiff-backup?

BTW: After copying the automake-1.6/COPYING file manually and running
rdiff-backup, it was gone. This is okay, because in the last backup it
didn't exist, there is a .missing file in the incremental directory.

It seems to me, that automake-1.6/COPYING is not related to the
problem, it's just the last file that is processes normally before
running into troubles, because of the corrupted metadata file.

rdiff 0.11.4
librsync 0.9.5.1
Suse Linux 7.1
python 2.2

thanks for any help
john

-- 
"They that can give up essential liberty to obtain a little temporary
safety deserve neither liberty nor safety." - Benjamin Franklin, 1759.