AssertionError: assert len(chain_list) == 2

[Damon Lynch]

Bug present in both duplicity 0.6.11 on Ubuntu Maverick 10.10 (from PPA), and the standard shipping Maverick duplicity, which was used to create the backup.

Python 2.6.6. Target file system is a godaddy Linux virtual server.

Unfortunately I don't have the error output of the actual full backup created by the standard Maverick version of duplicity. It appeared to backup all files, and then fail at the very end (sadly, after 2 days continual operation and 32 GB of data).

When running duplicity --encrypt-key 29435027 --sign-key 29435027 --ssh-options="-oIdentityFile=/home/damon/.ssh/godaddy" --name documents -v9 /shared2/photos ssh://<email address hidden>:22/html/damonbackup/photos

I get this crash:

Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1257, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1250, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1155, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 687, in set_values
    backup_chains)
  File "/usr/lib/python2.6/dist-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.6/dist-packages/duplicity/collections.py", line 913, in get_sorted_chains
    assert len(chain_list) == 2
AssertionError

[Stephen N. DeWitt, OFM (sdewittofm)]

I get the same output when attempting to restore from a backup using Deja-Dup 16.1.1. Restore fails with an unknown error followed by the above.

[Laszlo Pandy (laszlok)]

I got this same traceback through Deja Dup when trying to resume an SSH backup. I had run Deja Dup twice before (so the first resume was successful). Now my backup was almost complete, and I had to stop it. Upon resuming, and I'm tried multiple times now, I get this error.

[Michael Terry (mterry)]

Duplicate bug 616482 has a complete deja-dup.log too.

[Michael Terry (mterry)]

I've looked into this a bit. Using the dataset from bug 616482 (https://launchpadlibrarian.net/53503951/deja-dup-log.txt), because it has the full file list on the backend, I was able to see that Duplicity created two signature chains from the remote end which were pretty similar:

['duplicity-full-signatures.20100811T104726Z.sigtar.part']
['duplicity-full-signatures.20100811T104726Z.sigtar.gz']

These both have the same end_time. Add in the same signature from the local cache and you have three chains with the same end_time, which would trigger the assert.

Ken, I'm tempted to code a patch that ignores partial signatures. Is that a reasonable thing? I'm not very clear on when partial files are usable and when they aren't.

[Sean Sosik-Hamor (sciri)]

mterry, add one more to the list. Basically the same as benste's report in LP Bug #616482.

sciri@rico:~/Shredder$ apt-cache policy duplicity deja-dup
deja-dup:
  Installed: 18.1.1-0ubuntu1
  Candidate: 18.1.1-0ubuntu1
  Version table:
 *** 18.1.1-0ubuntu1 0
        500 http://archive.ubuntu.com/ubuntu/ natty/universe amd64 Packages
        100 /var/lib/dpkg/status
duplicity:
  Installed: 0.6.13-0ubuntu1
  Candidate: 0.6.13-0ubuntu1
  Version table:
 *** 0.6.13-0ubuntu1 0
        500 http://archive.ubuntu.com/ubuntu/ natty/universe amd64 Packages
        100 /var/lib/dpkg/status

Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1262, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1255, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1237, in main
    incremental_backup(sig_chain)
  File "/usr/bin/duplicity", line 479, in incremental_backup
    bytes_written = dummy_backup(tarblock_iter)
  File "/usr/bin/duplicity", line 161, in dummy_backup
    while tarblock_iter.next():
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 505, in next
    result = self.process(self.input_iter.next(), size)
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 187, in get_delta_iter
    for new_path, sig_path in collated:
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 275, in collate2iters
    relem2 = riter2.next()
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 344, in combine_path_iters
    refresh_triple_list(triple_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 330, in refresh_triple_list
    new_triple = get_triple(old_triple[1])
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 316, in get_triple
    path = path_iter_list[iter_index].next()
  File "/usr/lib/python2.7/dist-packages/duplicity/diffdir.py", line 229, in sigtar2path_iter
    for tarinfo in tf:
  File "/usr/lib/python2.7/dist-packages/duplicity/tarfile.py", line 1211, in next
    tarinfo = self.tarfile.next()
  File "/usr/lib/python2.7/dist-packages/duplicity/tarfile.py", line 566, in next
    if tarinfo.issparse():
AttributeError: 'NoneType' object has no attribute 'issparse'

[Michael Terry (mterry)]

Sean, that's a very different traceback from the others in this bug. Do you think it's connected to the assert "len(chain_list)" error?

I've got a branch for the 'issparse' issue (https://code.launchpad.net/~mterry/duplicity/guard-tarinfo/+merge/65688) but there isn't a bug for it. Please file a new bug if you want a gathering-place for discussion of it.

[Michael Terry (mterry)]

OK, I think I figured this out. Bear with me.

Duplicity keeps writing to a local partial (.part) signature file. Then when backup is done, it copies it to the remote destination using a different filename. Then it copies to its final local destination using a third filename (.gz instead of .part). Finally, it deletes the local partial.

But duplicity can be interrupted at any point during that. So when the next run happens, there are 7 possible states for a signature file, depending on when we got interrupted:

1) Incomplete local partial
2) Complete local partial
3) Complete local partial, incomplete remote
4) Complete local partial, complete remote
5) Complete local partial, complete remote, incomplete local final
5) Complete local partial, complete remote, complete local final
6) Complete remote, complete local final

But these can be collapsed a bit, because duplicity doesn't bother telling the difference between complete or not files:

1) local partial
2) local partial and remote
3) local partial, remote, and local final
4) remote and local final

Situations #2 and #3 result in this bug. #2 because next run, duplicity will sync metadata, pull down the remote into the local final slot, and we'll have three signature files. #3 because we just have three signature files already.

Attached you'll find a test script to reproduce the problem.

The fix is to be a bit smarter when sync'ing metadata. I will shortly file a merge request with a patch.

[Jonathan Heard (jon-launchpad-jeh)]

Unfortunately I am on 0.6.19 (0.6.19-0ubuntu0ppa18~lucid1 to be exact) which contains the fix for this bug but I am still hitting what looks to be the same problem :-(
This is proving to be a nuisance because neither full, nor partial backups will complete once this happens until I manually do a cleanup and it usually fails again extremely soon.

I'm backing up to a European Amazon S3 bucket using the dt-s3-backup.sh script. Any help in resolving this would be greatly appreciated.... OR can anyone give me an example of how to dump out the chain_list that is failing the assertion so I can see that actual problem trigger?

Here's the stack trace I keep seeing:
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1391, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1384, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1264, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 707, in set_values
    backup_chains)
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 720, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 933, in get_sorted_chains
    assert len(chain_list) == 2
AssertionError

Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1391, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1384, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1264, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 707, in set_values
    backup_chains)
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 720, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/usr/lib/python2.6/dist-packages/duplicity/collections.py", line 933, in get_sorted_chains
    assert len(chain_list) == 2
AssertionError

[Duarte Rocha (duarte-rocha)]

I'm getting the same problem:

If I delete the backup folder or change the backup destination folder it works for a few days then comes this error...

I have the same configuration on a Fedora system, also the same duplicity version and has been working without fail for some months now....

NAME="Ubuntu"
VERSION="13.04, Raring Ringtail"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 13.04"
VERSION_ID="13.04"

~ $ duplicity -V
duplicity 0.6.21

Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1411, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1404, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1286, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 704, in set_values
    backup_chains)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 717, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 930, in get_sorted_chains
    assert len(chain_list) == 2
AssertionError

[Luca Gardi (luca-xr)]

Same here:

Linux serverposta 3.8.0-19-generic #30-Ubuntu SMP Wed May 1 16:35:23 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

duplicity 0.6.21

[..]
File duplicity-new-signatures.20140218T091432Z.to.20140221T040003Z.sigtar.gz is not part of a known set; creating new set
Ignoring file (rejected by backup set) 'duplicity-new-signatures.20140218T091432Z.to.20140221T040003Z.sigtar.gz'
File duplicity-new-signatures.20140221T040003Z.to.20140222T040003Z.sigtar.gz is not part of a known set; creating new set
Ignoring file (rejected by backup set) 'duplicity-new-signatures.20140221T040003Z.to.20140222T040003Z.sigtar.gz'
Found backup chain [Tue Feb 18 10:14:32 2014]-[Tue Feb 18 10:14:32 2014]
Added incremental Backupset (start_time: Tue Feb 18 10:14:32 2014 / end_time: Fri Feb 21 05:00:03 2014)
Added set Fri Feb 21 05:00:03 2014 to pre-existing chain [Tue Feb 18 10:14:32 2014]-[Fri Feb 21 05:00:03 2014]
Found backup chain [Sat Feb 22 05:00:03 2014]-[Sat Feb 22 05:00:03 2014]
Added incremental Backupset (start_time: Fri Feb 21 05:00:03 2014 / end_time: Sat Feb 22 05:00:03 2014)
Added set Sat Feb 22 05:00:03 2014 to pre-existing chain [Tue Feb 18 10:14:32 2014]-[Sat Feb 22 05:00:03 2014]
Removing still remembered temporary file /tmp/duplicity-Msdp6Q-tempdir/mkstemp-IwlMGa-2
Removing still remembered temporary file /tmp/duplicity-Msdp6Q-tempdir/mkstemp-ACFYb8-1
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1411, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1404, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1286, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 704, in set_values
    backup_chains)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 717, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 930, in get_sorted_chains
    assert len(chain_list) == 2
AssertionError

[Artur Bodera (abodera)]

Here's 0.7.04 with the same issue!!!

Copying duplicity-full-signatures.20150920T135054Z.sigtar.gpg.1 to local cache.
Deleting /var/folders/sn/lw4b5p6s6793ghngffqsy8cc0000gn/T/duplicity-MJR9My-tempdir/mktemp-7K3KaR-2
Deleting /var/folders/sn/lw4b5p6s6793ghngffqsy8cc0000gn/T/duplicity-MJR9My-tempdir/mktemp-EAoKyg-3
Copying duplicity-full-signatures.20150920T135054Z.sigtar.gpg.2 to local cache.
Deleting /var/folders/sn/lw4b5p6s6793ghngffqsy8cc0000gn/T/duplicity-MJR9My-tempdir/mktemp-8hl7lL-4
Deleting /var/folders/sn/lw4b5p6s6793ghngffqsy8cc0000gn/T/duplicity-MJR9My-tempdir/mktemp-kJsdDT-5
Traceback (most recent call last):
  File "/usr/local/Cellar/duplicity/0.7.04_1/libexec/bin/duplicity", line 1528, in <module>
    with_tempdir(main)
  File "/usr/local/Cellar/duplicity/0.7.04_1/libexec/bin/duplicity", line 1522, in with_tempdir
    fn()
  File "/usr/local/Cellar/duplicity/0.7.04_1/libexec/bin/duplicity", line 1376, in main
    do_backup(action)
  File "/usr/local/Cellar/duplicity/0.7.04_1/libexec/bin/duplicity", line 1401, in do_backup
    globals.archive_dir).set_values()
  File "/usr/local/Cellar/duplicity/0.7.04_1/libexec/lib/python2.7/site-packages/duplicity/collections.py", line 721, in set_values
    backup_chains)
  File "/usr/local/Cellar/duplicity/0.7.04_1/libexec/lib/python2.7/site-packages/duplicity/collections.py", line 734, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/usr/local/Cellar/duplicity/0.7.04_1/libexec/lib/python2.7/site-packages/duplicity/collections.py", line 951, in get_sorted_chains
    assert len(chain_list) == 2
AssertionError

[Tenzing (mat-5)]

This bug, or a very similar one, is still present in duplicity 0.7.17 (current stable):

Local and Remote metadata are synchronized, no sync needed.
ionice: ignoring given class data for idle class
Traceback (innermost last):
  File "/opt/duplicity-0.7.17/bin/duplicity", line 1555, in <module>
    with_tempdir(main)
  File "/opt/duplicity-0.7.17/bin/duplicity", line 1541, in with_tempdir
    fn()
  File "/opt/duplicity-0.7.17/bin/duplicity", line 1393, in main
    do_backup(action)
  File "/opt/duplicity-0.7.17/bin/duplicity", line 1419, in do_backup
    action).set_values()
  File "/opt/duplicity-0.7.17/local/lib/python2.7/site-packages/duplicity/collections.py", line 722, in set_values
    backup_chains)
  File "/opt/duplicity-0.7.17/local/lib/python2.7/site-packages/duplicity/collections.py", line 735, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/opt/duplicity-0.7.17/local/lib/python2.7/site-packages/duplicity/collections.py", line 955, in get_sorted_chains
    assert len(chain_list) == 2
AssertionError

This happens on very large/long backups that take close to a week to run, shorter backups seem to be doing fine. Running pristine duplicity-0.7.17 built from sources. Python 2.7.9 on a Debian jessie. The target is cf+hubic.

Should I file a new bug?

[Tenzing (mat-5)]

The bug is still present in duplicity 0.7.18.2. When doing a full backup that gets repetitively interrupted with HTTP 422 errors (cf+hubic target), duplicity stops with this message:

Traceback (innermost last):
  File "/opt/duplicity-0.7.18.2/bin/duplicity", line 1560, in <module>
    with_tempdir(main)
  File "/opt/duplicity-0.7.18.2/bin/duplicity", line 1546, in with_tempdir
    fn()
  File "/opt/duplicity-0.7.18.2/bin/duplicity", line 1398, in main
    do_backup(action)
  File "/opt/duplicity-0.7.18.2/bin/duplicity", line 1424, in do_backup
    action).set_values()
  File "/opt/duplicity-0.7.18.2/local/lib/python2.7/site-packages/duplicity/collections.py", line 722, in set_values
    backup_chains)
  File "/opt/duplicity-0.7.18.2/local/lib/python2.7/site-packages/duplicity/collections.py", line 735, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/opt/duplicity-0.7.18.2/local/lib/python2.7/site-packages/duplicity/collections.py", line 955, in get_sorted_chains
    assert len(chain_list) == 2
 AssertionError

I attached a (very large) verbose log running duplicity cleanup afterwards, which shows the very same error. I haven't found what to do to recover the backup at this point, except delete everything and start again from scratch, crossing fingers.

[Tenzing (mat-5)]

As a workaround when this bug happens, deleting the (remote) files mentioned in the log as "Ignored" seems to work:

File duplicity-full-signatures.20181020T154202Z.sigtar.gpg is not part of a known set; creating new set
Ignoring file (rejected by backup set) 'duplicity-full-signatures.20181020T154202Z.sigtar.gpg'
File duplicity-full-signatures.20190119T143326Z.sigtar.gpg is not part of a known set; creating new set
Ignoring file (rejected by backup set) 'duplicity-full-signatures.20190119T143326Z.sigtar.gpg'
File duplicity-full-signatures.20190119T143326Z.sigtar.gpg.1 is not part of a known set; creating new set
Ignoring file (rejected by backup set) 'duplicity-full-signatures.20190119T143326Z.sigtar.gpg.1'
File duplicity-full-signatures.20190119T143326Z.sigtar.gpg.2 is not part of a known set; creating new set
Ignoring file (rejected by backup set) 'duplicity-full-signatures.20190119T143326Z.sigtar.gpg.2'

[Matthijs Kooijman (matthijskooijman)]

I also ran into this same assert with 0.8.17 just now.

In my case, the remote disk is full, which seems to have aborted a backup run and caused a local .part file to linger around and trigger the assertion. The assert now triggers on at least the collection-status and cleanup commands (so cleanup cannot be used to fix it).

Here's the backtrace:

Traceback (innermost last):
  File "/usr/bin/duplicity", line 122, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 108, in with_tempdir
    fn()
  File "/usr/lib/python3/dist-packages/duplicity/dup_main.py", line 1535, in main
    do_backup(action)
  File "/usr/lib/python3/dist-packages/duplicity/dup_main.py", line 1555, in do_backup
    col_stats = dup_collections.CollectionsStatus(config.backend,
  File "/usr/lib/python3/dist-packages/duplicity/dup_collections.py", line 752, in set_values
    self.set_matched_chain_pair(local_sig_chains + remote_sig_chains,
  File "/usr/lib/python3/dist-packages/duplicity/dup_collections.py", line 766, in set_matched_chain_pair
    sig_chains = sig_chains and self.get_sorted_chains(sig_chains)
  File "/usr/lib/python3/dist-packages/duplicity/dup_collections.py", line 984, in get_sorted_chains
    assert len(chain_list) == 2
 AssertionError

I added a `print(list(map(str, chain_list)))` to figure out what was wrong (and also fixed SignatureChain.__str__), which shows the problematic chain list is:

["local: [b'duplicity-full-signatures.20220903T000045Z.sigtar.gpg']", "local: [b'duplicity-full-signatures.20220903T000045Z.sigtar.part']", "remote: [b'duplicity-full-signatures.20220903T000045Z.sigtar.gpg']"]

So indeed, an extra partial local signature.

I fixed this by (accidentally) removing the assert from the code and running cleanup, which deleted the local complete and partial signature saying:

Deleting local /data/backup/cache/duplicity/data-mail/duplicity-full-signatures.20220903T000045Z.sigtar.gpg (not authoritative at backend).

I think that the message might not be entirely correct (since it seems there *is* a remote version), but it does seem to have fixed my setup. I guess just deleting the .part file (and maybe also the full version to be sure) would have also helped.