[Duplicity-talk] assertion fails on any operation (assert len(chain_list) == 2)

[Andrew Pimlott]

I've gotten my backup into a state where any operation results in where
anything I try (including cleanup) results in this assertion firing, in
duplicity/collections.py, line 913 (version 0.6.09 in Debian).

This followed a succession of failed backups over the past two tries.
(These failures were due to problems with Cloud Files.)  In all cases,
the backup command was:

duplicity --archive-dir=/var/cache/duplicity --name <NAME> --full-if-older-than 
4W --exclude-other-filesystems --exclude-globbing-filelist 
/root/backup/exclude.duplicity --volsize 250 / cf+http://<BUCKET>

day 1:
Reading globbing filelist /root/backup/exclude.duplicity
Local and Remote metadata are synchronized, no sync needed.
Last full backup date: Thu Sep 23 10:00:10 2010
Last full backup is too old, forcing full backup
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
1): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
2): sslerror: The write operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
3): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
4): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
5): sslerror: The read operation timed out
Giving up uploading 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' after 5 
attempts
BackendException: Error uploading 
'duplicity-full.20101022T100002Z.vol5.difftar.gpg'

day 2:
Reading globbing filelist /root/backup/exclude.duplicity
Local and Remote metadata are synchronized, no sync needed.
Last full backup left a partial set, restarting.
Last full backup date: Fri Oct 22 10:00:02 2010
RESTART: Volumes 5 to 5 failed to upload before termination.
        Restarting backup at volume 5.
Restarting after volume 4, file 
home/andrew/stable_api/data/datapooling/1908/tmx.zip, block 56
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
1): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
2): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol5.difftar.gpg' failed (attempt 
3): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol8.difftar.gpg' failed (attempt 
1): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol15.difftar.gpg' failed (attempt 
1): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol36.difftar.gpg' failed (attempt 
1): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol56.difftar.gpg' failed (attempt 
1): sslerror: The read operation timed out
Upload of 'duplicity-full.20101022T100002Z.vol59.difftar.gpg' failed (attempt 
1): sslerror: The read operation timed out
Upload of 'duplicity-full-signatures.20101022T100002Z.sigtar.gpg' failed 
(attempt 1): sslerror: The read operation timed out
Upload of 'duplicity-full-signatures.20101022T100002Z.sigtar.gpg' failed 
(attempt 2): sslerror: The read operation timed out
Upload of 'duplicity-full-signatures.20101022T100002Z.sigtar.gpg' failed 
(attempt 3): sslerror: The read operation timed out
Upload of 'duplicity-full-signatures.20101022T100002Z.sigtar.gpg' failed 
(attempt 4): sslerror: The read operation timed out
Upload of 'duplicity-full-signatures.20101022T100002Z.sigtar.gpg' failed 
(attempt 5): sslerror: The read operation timed out
Giving up uploading 'duplicity-full-signatures.20101022T100002Z.sigtar.gpg' 
after 5 attempts
BackendException: Error uploading 
'duplicity-full-signatures.20101022T100002Z.sigtar.gpg'

day 3:
Reading globbing filelist /root/backup/exclude.duplicity
Local and Remote metadata are synchronized, no sync needed.
Traceback (most recent call last):
 File "/usr/bin/duplicity", line 1251, in <module>
   with_tempdir(main)
 File "/usr/bin/duplicity", line 1244, in with_tempdir
   fn()
 File "/usr/bin/duplicity", line 1149, in main
   globals.archive_dir).set_values()
 File "/usr/lib/python2.5/site-packages/duplicity/collections.py", line 687, in 
set_values
   backup_chains)
 File "/usr/lib/python2.5/site-packages/duplicity/collections.py", line 700, in 
set_matched_chain_pair
   sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
 File "/usr/lib/python2.5/site-packages/duplicity/collections.py", line 913, in 
get_sorted_chains
   assert len(chain_list) == 2
AssertionError

I debugged just far enough into duplicity to see that when the assertion
fires, there are three elements in chain_list:

local: [duplicity-full-signatures.20101022T100002Z.sigtar.part]
local: [duplicity-full-signatures.20101022T100002Z.sigtar.gpg]
remote: [duplicity-full-signatures.20101022T100002Z.sigtar.gpg]

If I look into my local cache, I see both files:

duplicity-full-signatures.20101022T100002Z.sigtar.gpg
duplicity-full-signatures.20101022T100002Z.sigtar.part

It seems the problem is that duplicity didn't properly handle a failure
during failure recovery (on day 2).  Can someone explain exactly what
happened?  What can I do here?  Should I delete one of the local files?
(which one?)

Andrew