[rdiff-backup-users] exceptions.AssertionError: problem (long, verbose, detailed)

[Dan Parrish]

I don't think I'm alone with this problem, or one similar to it.  I've
dug through much of the archives and seen several posts from people
having similar problems, but I've not seen a good explanation/workaround.

Anyway, I'm setting up rdiff-backup on 4 different machines.  One of
these machines (kahn) is the target for backups (remote, over internet)
of the other 3 machines (which are all on a LAN at home).  All of the 3
client machines are successfully (I'm guessing) backing up to the remote
machine (kahn) via ssh with hostkey auth.  However, all 3 of these
machines (substance, lycaeum, and deathandtaxes) are failing to recover
successfully from kahn.

All 4 machines are similar in system layout and configuration.  They all
run the same version of python (2.3.3), rdiff-backup (0.12.6), openssh 
(openssh-3.7.1_p2) and all run gentoo linux on reiserfs filesystems.

I have successfully backed up /etc for all three machines locally to
another directory on each client computer and have successfully restored
locally as well.  I always run into problems when running it over the
network.  I have tested it via ssh to the other machines and even to
localhost.  ALL of these tests are producing similar errors.  The
particular file in question changes from machine to machine, but is
always the same for each individual client.  IOW, the same file fails
for lycaeum whether it backs it up to kahn, deathandtaxes, or even to
lycaeum itself.

As I mentioned before, I'm using 0.12.6, but I have tried out 0.13.3 
with the same results (just a bit more verbose feedback).

Ok, now that I've described my problem, here's some stdout (sorry about
the auto-wrapping of my email client):

address@hidden:~/temptest]$ rdiff-backup -v8 -r now
address@hidden::/usr/local/storage/dan/backup/lycaeum/etc pull
Executing ssh -C address@hidden rdiff-backup --server
Registering connection 1
Using mirror root directory /usr/local/storage/dan/backup/lycaeum/etc
Starting restore of /usr/local/storage/dan/backup/lycaeum/etc to pull as
it was as of Sun Feb  1 12:05:54 2004.
Processing changed file .
Making directory pull
Processing changed file ._cfg0000_crontab
Regular copying ('._cfg0000_crontab',) to pull/rdiff-backup.tmp.0
Writing file object to pull/rdiff-backup.tmp.0
Copying attributes from ('._cfg0000_crontab',) to pull/rdiff-backup.tmp.0
Setting time of pull/rdiff-backup.tmp.0 to 1073368087
Renaming pull/rdiff-backup.tmp.0 to pull/._cfg0000_crontab
Processing changed file ._cfg0000_make.conf
Regular copying ('._cfg0000_make.conf',) to pull/rdiff-backup.tmp.1
Writing file object to pull/rdiff-backup.tmp.1
Copying attributes from ('._cfg0000_make.conf',) to pull/rdiff-backup.tmp.1
Setting time of pull/rdiff-backup.tmp.1 to 1067037317
Renaming pull/rdiff-backup.tmp.1 to pull/._cfg0000_make.conf
Processing changed file ._cfg0000_make.globals
Regular copying ('._cfg0000_make.globals',) to pull/rdiff-backup.tmp.2
Writing file object to pull/rdiff-backup.tmp.2
Copying attributes from ('._cfg0000_make.globals',) to
pull/rdiff-backup.tmp.2
Setting time of pull/rdiff-backup.tmp.2 to 1067037317
Renaming pull/rdiff-backup.tmp.2 to pull/._cfg0000_make.globals
Processing changed file ._cfg0000_sensors.conf
Regular copying ('._cfg0000_sensors.conf',) to pull/rdiff-backup.tmp.3
Writing file object to pull/rdiff-backup.tmp.3
...
***a whole bunch of similar messages***
...
Copying attributes from ('init.d', 'modules') to
pull/init.d/rdiff-backup.tmp.90
Setting time of pull/init.d/rdiff-backup.tmp.90 to 1065248891
Renaming pull/init.d/rdiff-backup.tmp.90 to pull/init.d/modules
Processing changed file init.d/net.eth0
Regular copying ('init.d', 'net.eth0') to pull/init.d/rdiff-backup.tmp.91
Writing file object to pull/init.d/rdiff-backup.tmp.91
Sending back exception (('log.d', 'conf'), ('log.d', 'conf', 'logfiles', 
'up2date.conf')) of type exceptions.AssertionError:
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 329, in answer_request
    result = apply(eval(request.function_string), argument_list)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 475, in readfromid
    if length is None: return cls.vfiles[id].read()
  File "/usr/lib/python2.3/site-packages/rdiff_backup/iterfile.py", line
285, in read
    if not self.addtobuffer(): break
  File "/usr/lib/python2.3/site-packages/rdiff_backup/iterfile.py", line
308, in addtobuffer
    try: currentobj = self.iter.next()
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
236, in get_diffs_from_collated
    yield cls.get_diff(mir_rorp, target_rorp)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
245, in get_diff
    mir_rorp.setfile(cls.rf_cache.get_fp(expanded_index))
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
324, in get_fp
    rf = self.get_rf(index)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
318, in get_rf
    if (index[:-1] == rf.index[:-1] or not
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
343, in add_rfs
    if Globals.process_uid != 0: self.perm_changer(temp_rf.mirror_rp)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
659, in __call__
    assert index > old_index, (index, old_index)

Traceback (most recent call last):
  File "/usr/bin/rdiff-backup", line 23, in ?
    rdiff_backup.Main.Main(sys.argv[1:])
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line
250, in Main
    take_action(rps)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line
224, in take_action
    elif action == "restore-as-of": RestoreAsOf(rps[0], rps[1])
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line
395, in RestoreAsOf
    restore_common(rpin, target, time)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line
407, in restore_common
    restore.Restore(mirror, inc_rpath, target, time)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
50, in Restore
    TargetS.patch(target, diff_iter)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
270, in patch
    ITR(diff.index, diff)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rorpiter.py", line
279, in __call__
    last_branch.fast_process(*args)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
586, in fast_process
    self.patch_to_temp(rp, diff_rorp, tf)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/restore.py", line
594, in patch_to_temp
    rpath.copy(diff_rorp, new)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rpath.py", line
96, in copy
    if rpin.isreg(): copy_reg_file(rpin, rpout, compress)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rpath.py", line
118, in copy_reg_file
    rpout.write_from_fileobj(rpin.open("rb"), compress = compress)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rpath.py", line
823, in write_from_fileobj
    copyfileobj(fp, outfp)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rpath.py", line
58, in copyfileobj
    inbuf = inputfp.read(blocksize)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/rpath.py", line
948, in read
    def read(self, length = -1): return self.file.read(length)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/iterfile.py", line
117, in read
    if not self.addtobuffer(): break
  File "/usr/lib/python2.3/site-packages/rdiff_backup/iterfile.py", line
132, in addtobuffer
    type, data = self.iwf._get()
  File "/usr/lib/python2.3/site-packages/rdiff_backup/iterfile.py", line
401, in _get
    if not self.buf: self.buf += self.file.read()
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 508, in read
    return self.connection.VirtualFile.readfromid(self.id, length)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 440, in __call__
    return apply(self.connection.reval, (self.name,) + args)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 362, in reval
    if isinstance(result, Exception): raise result
AssertionError: (('log.d', 'conf'), ('log.d', 'conf', 'logfiles',
'up2date.conf'))
address@hidden:~/temptest]$ Traceback (most recent call last):
  File "/usr/bin/rdiff-backup", line 23, in ?
    rdiff_backup.Main.Main(sys.argv[1:])
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line
250, in Main
    take_action(rps)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/Main.py", line
220, in take_action
    connection.PipeConnection(sys.stdin, sys.stdout).Server()
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 347, in Server
    self.get_response(-1)
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 309, in get_response
    try: req_num, object = self._get()
  File "/usr/lib/python2.3/site-packages/rdiff_backup/connection.py",
line 225, in _get
    raise ConnectionReadError("Truncated header string (problem "
rdiff_backup.connection.ConnectionReadError: Truncated header string
(problem probably originated remotely)

address@hidden:~/temptest]$

Ok, so it looks like it's b0rking on log.d/conf/logfiles/up2date.conf. 
It's not executing the "Copying attributes from" stuff or the two 
remaining ("Setting time of" and "Renaming") commands on this file, I think.

The command I used to back up this stuff was:
rdiff-backup -v6 /etc address@hidden::/usr/local/storage/dan/backup/lycaeum/etc

Here's some pretty good evidence that the backup is good:
address@hidden:~/temptest]$ rdiff-backup -l
address@hidden::/usr/local/storage/dan/backup/lycaeum/etc
Found 2 increments:
    increments.2004-01-30T09:36:09-07:00.dir   Fri Jan 30 09:36:09 2004
    increments.2004-02-01T04:30:03-07:00.dir   Sun Feb  1 04:30:03 2004
Current mirror: Sun Feb  1 11:42:31 2004

Here's looking at it a different way:
address@hidden:/home/dan/storage/backup/lycaeum]$ rdiff-backup
--list-increment-sizes etc/
        Time                       Size        Cumulative size
-----------------------------------------------------------------------------
Sun Feb  1 11:42:31 2004          841 KB            841 KB   (current
mirror)
Sun Feb  1 04:30:03 2004         1.50 KB            842 KB
Fri Jan 30 09:36:09 2004         1.15 KB            843 KB

And a local-to-local restore works on the remote server:
address@hidden:/home/dan/storage/backup/lycaeum]$ rdiff-backup -r now -v4
etc/ test
Starting restore of etc to test as it was as of Sun Feb  1 12:19:04 2004.
Restore ended

So there you have it.  I can reproduce these errors every time, and it 
never succeeds.  Am I using the wrong commands or something?  I don't 
think I am, but it's possible I've missed something in the docs.

Sorry for the length of this, but I wanted to provide the list with as 
much searchable material as possible and get everything I could think of 
all in one post.  :-)