Undescriptive duplicity/collection-status error when the backup directory contains two volumes with different file names and same volume number in the same backup set

Hello David,

can you provide us with the following informations please:

The file /tmp/deja-dup.gsettings after running the following line (you may want to scrub the file of any incriminating file names or details):
    gsettings list-recursively org.gnome.DejaDup > /tmp/deja-dup.gsettings

The file /tmp/deja-dup.log after running the appropriate line below and replicating the problem (you may want to scrub the log of any incriminating file names or details):

 * If you're having problems backing up:
    DEJA_DUP_DEBUG=1 deja-dup --backup | tail -n 1000 > /tmp/deja-dup.log

After that you can set the "Status" back to "New".

Thanking you in anticipation

Vej

Hello Vej
my /Tmp contains no file with deja-dup.settings

What I have not done is uninstall, purge & reinstall.

Did you executed the two commands before? If so did they failed somehow?

Sorry
Didn't recognize the commands as such.
Tmp contents:
org.gnome.DejaDup last-restore ''
org.gnome.DejaDup periodic true
org.gnome.DejaDup full-backup-period 90
org.gnome.DejaDup backend 'file'
org.gnome.DejaDup last-run ''
org.gnome.DejaDup nag-check ''
org.gnome.DejaDup prompt-check '2017-01-01T20:59:40.740292Z'
org.gnome.DejaDup root-prompt true
org.gnome.DejaDup include-list ['$HOME']
org.gnome.DejaDup exclude-list ['$TRASH', '$DOWNLOAD']
org.gnome.DejaDup last-backup ''
org.gnome.DejaDup periodic-period 7
org.gnome.DejaDup delete-after 182
org.gnome.DejaDup.S3 id ''
org.gnome.DejaDup.S3 bucket ''
org.gnome.DejaDup.S3 folder 'david-Lenovo-H535'
org.gnome.DejaDup.OpenStack authurl ''
org.gnome.DejaDup.OpenStack tenant ''
org.gnome.DejaDup.OpenStack username ''
org.gnome.DejaDup.OpenStack container 'david-Lenovo-H535'
org.gnome.DejaDup.GCS id ''
org.gnome.DejaDup.GCS bucket ''
org.gnome.DejaDup.GCS folder 'david-Lenovo-H535'
org.gnome.DejaDup.GDrive email ''
org.gnome.DejaDup.GDrive folder '/deja-dup/david-Lenovo-H535'
org.gnome.DejaDup.Rackspace username ''
org.gnome.DejaDup.Rackspace container 'david-Lenovo-H535'
org.gnome.DejaDup.File path 'file:///home/david/Dropbox/Backups'
org.gnome.DejaDup.File short-name ''
org.gnome.DejaDup.File uuid ''
org.gnome.DejaDup.File icon ''
org.gnome.DejaDup.File relpath @ay []
org.gnome.DejaDup.File name ''
org.gnome.DejaDup.File type 'normal'

Attempt to start again
Failed with an unknown error.
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1532, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1526, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1380, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1405, in do_backup
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 710, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 835, in get_backup_chains
    add_to_sets(f)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 823, in add_to_sets
    if set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 105, in add_filename
    (self.volume_name_dict, filename)
AssertionError: ({1: 'duplicity-full.20161129T015237Z.vol1.difftar'}, 'duplicity-full.20161129T015237Z.vol1.difftar.gz')

Could not find setting "status" to change

Hello David.

Thanks for the settings. Now we are still missing the /tmp/deja-dup.log with the output from the second command (that one, which did the run in debug mode).

Best Regards

Vej

found and attached
Also I got
DEJA_DUP_DEBUG=1 deja-dup --backup | tail -n 1000 > /tmp/deja-dup.log
Unsupported use of '='. To run 'deja-dup' with a modified environment, please use 'env DEJA_DUP_DEBUG=1 deja-dup…'
david@david-Lenovo-H535 ~>

It's because you're using the fish shell instead of the more common bash shell. If I understand correctly, the fish translation of Vej's command is:

  env DEJA_DUP_DEBUG=1 deja-dup --backup | tail -n 1000 > /tmp/deja-dup.log

or:

  set -x DEJA_DUP_DEBUG 1
  deja-dup --backup | tail -n 1000 > /tmp/deja-dup.log

Nathanael
Tried the commands you gave in fish
and also the ones intended for bash in bash.
some created the log but 3 times out of four the log was blank/empty
Attached is the one that did leave a log.
Notably every time start of backup produced "Backup failed"

sTraceback (most recent call last):
  File "/usr/bin/duplicity", line 1532, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1526, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1380, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1405, in do_backup
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 710, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 835, in get_backup_chains
    add_to_sets(f)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 823, in add_to_sets
    if set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 105, in add_filename
    (self.volume_name_dict, filename)
AssertionError: ({1: 'duplicity-full.20161129T015237Z.vol1.difftar'}, 'duplicity-full.20161129T015237Z.vol1.difftar.gz')
 Lastly I have not found the place to set "status"to "new" using the GUI version.(Thus far I've only been using GUI.
Thanks
David

The "status" Vej refers to is the bug status, on this web page, to switch from "incomplete" to "new".

Thanks for the log. Can you please show the content of your cache directory?

  ls -lR ~/.cache/deja-dup

You apparently performed a full backup on 2016-11-29 at 01:52 UTC, did everything work fine during this backup? Was it successful ?

When did you run first into this problem - on the first incremental backup ?

Also, from the content of your log-file, I've got the impression that there isn't a single well-formed backup chain in your backup directory. Can you check with:

  ls -l /home/david/Dropbox/Backups

Nathanael

using Fish

ls -lR ~/.cache/deja-dup
/home/david/.cache/deja-dup:
total 4
drwxrwxr-x 2 david david 4096 Jan 14 12:50 f00ff76508010e2a830dd26b1d39db42/

/home/david/.cache/deja-dup/f00ff76508010e2a830dd26b1d39db42:
total 8
-rw-rw-r-- 1 david david 165 Jan 14 12:50 duplicity-full.20161129T015237Z.manifest
-rw-rw-r-- 1 david david 143 Jan 14 12:50 duplicity-full-signatures.20161129T015237Z.sigtar.gz

again using Fish
 ls -l /home/david/Dropbox/Backups
total 358108
-rw-rw-r-- 1 david david 165 Nov 28 17:52 duplicity-full.20161129T015237Z.manifest
-rw-rw-r-- 1 david david 1024 Dec 22 16:08 duplicity-full.20161129T015237Z.vol1.difftar
-rw-rw-r-- 1 david david 120 Nov 28 17:52 duplicity-full.20161129T015237Z.vol1.difftar.gz
-rw-rw-r-- 1 david david 10240 Dec 22 16:05 duplicity-full-signatures.20161129T015237Z.sigtar
-rw-rw-r-- 1 david david 143 Nov 28 17:52 duplicity-full-signatures.20161129T015237Z.sigtar.gz
-rw-rw-r-- 1 david david 52366483 Dec 1 16:39 duplicity-inc.20161129T015237Z.to.20161202T003153Z.vol15.difftar.gz
-rw-rw-r-- 1 david david 52368153 Dec 1 16:40 duplicity-inc.20161129T015237Z.to.20161202T003153Z.vol16.difftar.gz
-rw-rw-r-- 1 david david 52371036 Dec 1 16:42 duplicity-inc.20161129T015237Z.to.20161202T003153Z.vol23.difftar.gz
-rw-rw-r-- 1 david david 52390301 Dec 1 16:33 duplicity-inc.20161129T015237Z.to.20161202T003153Z.vol2.difftar.gz
-rw-rw-r-- 1 david david 52368335 Dec 1 16:47 duplicity-inc.20161129T015237Z.to.20161202T003153Z.vol41.difftar.gz
-rw-rw-r-- 1 david david 52375173 Dec 1 16:49 duplicity-inc.20161129T015237Z.to.20161202T003153Z.vol49.difftar.gz
-rw-rw-r-- 1 david david 52375354 Dec 1 16:36 duplicity-inc.20161129T015237Z.to.20161202T003153Z.vol7.difftar.gz

You apparently performed a full backup on 2016-11-29 at 01:52 UTC, did everything work fine during this backup? Was it successful ?
Don't think so

When did you run first into this problem - on the first incremental backup ?
As far as I'm aware it has never succeeded.
Always got the message "Backup Failed" as it did just now when I ran it.
I've had this problem for a long time all through the time that I ran Ubuntu 14.04 and it's just since I installed 16.04 that I have tried to chase it down.
Thanks for your persistance
David

Thanks for the information. First of all, as reported by the log file you sent and the listing of your backup directory, there is an uncompressed backup volume in your volume directory, and an uncompressed file of files signatures, created or last modified on Dec 22:

  duplicity-full.20161129T015237Z.vol1.difftar
  duplicity-full-signatures.20161129T015237Z.sigtar

along with their older compressed versions, created on Nov 28:

  duplicity-full.20161129T015237Z.vol1.difftar.gz
  duplicity-full-signatures.20161129T015237Z.sigtar.gz

As far as I know there shouldn't be any such uncompressed files in the backup location. Did you uncompress them yourself perhaps? In any case, they're confusing duplicity (the command-line backup tool Déjà-Dup is a graphical front-end to), if I understand the log file and error message correctly:

  DUPLICITY: INFO 1
  DUPLICITY: . Args: /usr/bin/duplicity collection-status [...]

  [...]

  DUPLICITY: DEBUG 1
  DUPLICITY: . 12 files exist on backend

  DUPLICITY: DEBUG 1
  DUPLICITY: . Extracting backup chains from list of files:
   [u'duplicity-full.20161129T015237Z.vol1.difftar',
    u'duplicity-full.20161129T015237Z.manifest',
    u'duplicity-full.20161129T015237Z.vol1.difftar.gz',
    u'duplicity-full-signatures.20161129T015237Z.sigtar.gz',
    u'duplicity-full-signatures.20161129T015237Z.sigtar',
    [...]

  DUPLICITY: DEBUG 1
  DUPLICITY: . File duplicity-full.20161129T015237Z.vol1.difftar is not part of a
    known set; creating new set

  DUPLICITY: DEBUG 1
  DUPLICITY: . File duplicity-full.20161129T015237Z.manifest is part of known set

  DUPLICITY: ERROR 30 AssertionError
  [...]
  DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/collections.py",
    line 105, in add_filename(self.volume_name_dict, filename)
  DUPLICITY: . AssertionError:
    ({1: 'duplicity-full.20161129T015237Z.vol1.difftar'},
    'duplicity-full.20161129T015237Z.vol1.difftar.gz')

From my understanding of the duplicity source code in the incriminated file, this is what happens when happens Déjà-Dup launches the collection-status action to have duplicity find out which backup chains are in the backup repository: Déjà-Dup passes the list of files in this directory to duplicity, which takes the uncompressed duplicity-full.20161129T015237Z.vol1.difftar for the start of a backup set, then tries to add the compressed duplicity-full.20161129T015237Z.vol1.difftar.gz to this set, and fails because the volume number of this file has already been added to the set. Otherwise there would be two backup volumes with the same volume number in the backup set, and duplicity can't guess which one to take into account.

To fix this bug from happening in the future, we could perhaps restrict the file list that is passed from Déjà-Dup to duplicity collection-status? Perhaps to *.{diff,sig}tar.{gz,gpg} and *.manifest files only, or something like that?

Or perhaps it could be fixed in duplicity, by having duplicity prefer a particular filename when there are two volumes with the same number in the same backup set? But then which one and on what grounds?

Vej, your take on that?

In the meantime, David, I believe it's safe for you to delete t...

>> You apparently performed a full backup on 2016-11-29 at 01:52 UTC,
>> did everything work fine during this backup? Was it successful ?
> Don't think so

Don't think so either, because your full backup on that date is only one volume long and that volume is 120 bytes long:

  ls -l /home/david/Dropbox/Backups
  [...]
  ... 120 Nov 28 17:52 duplicity-full.20161129T015237Z.vol1.difftar.gz
  [...]

FYI duplicity makes backups into sets of normally 25 MB volumes.

And then there's your first incremental backup on Dec 1 which doesn't look good since there are only volumes 2, 7, 15, 16, 23, 41, 49 of that backup set in your backup repository. Where are all the other ones? Did Dropbox eat them? And the normally-accompanying signatures and manifest files are nowhere to be found either.

I don't know if Déjà-Dup can recover from this situation and finish the partial incremental backup set but I wouldn't even lose time trying to be honest. I've always found the easiest way to recover from a severely failed backup is to delete the failed part (everything in your case) and start again. For good measure you can also delete the backup's cache directory:

  rm -r /home/david/Dropbox/Backups
  rm -r /home/david/.cache/deja-dup/f00ff76508010e2a830dd26b1d39db42

When you try again, you may want to test backing up a small subset of your documents instead of your whole user directory. That way you'll know quickly if it works or fails again. If it works, you can delete this test backup and start again with the whole thing.

Regarding comment #15:

> To fix this bug from happening in the future, we could perhaps restrict the file list that is passed from Déjà-Dup to duplicity collection-status?
>Perhaps to *.{diff,sig}tar.{gz,gpg} and *.manifest files only, or something like that?

This sounds good to me!

I consider this to be Triaged, even if this bug has not been replicated by someone else. The reason for this problem is found and a way to solve it within Dèjá Dup is given.

I will forward to upstream as well.

>> To fix this bug from happening in the future, we could perhaps
>> restrict the file list that is passed from Déjà-Dup to duplicity
>> collection-status? Perhaps to *.{diff,sig}tar.{gz,gpg} and
>> *.manifest files only, or something like that?

> This sounds good to me!

On further investigation, unfortunately, I realize it is not a file list that Déjà-Dup passes to duplicity collection-status, but the path/URL of the backup repository, e.g.:

  duplicity collection-status [options] file://home/luke/deja-dup

This is what duplicity expects for this action, according to the man page. So it might be trickier than I thought to have duplicity not examine certain files, and perhaps this bug would be better solved on duplicity's side than on Déjà-Dup's side.

Worst case, if the bug can't be fixed and the situation requires a human to examine the contents of the backup repository to take adequate action, then duplicity should return a more descriptive message than the current terse assertion error.

I have also replicated the bug, on Ubuntu 14.04 deja-dup 30.0 duplicity 0.6.23 (haven't got a more recent version yet but David has), as a newly-created user with the default Déjà-Dup settings:

1. Perform the first full backup and check that the backup, the file signatures, and the manifest file have been successfully created:

$ ls -l ~/deja-dup
-rw------- 1 luke luke 171 Jan 16 00:51 duplicity-full.20170115T235149Z.manifest
-rw------- 1 luke luke 48989 Jan 16 00:51 duplicity-full.20170115T235149Z.vol1.difftar.gz
-rw------- 1 luke luke 9965 Jan 16 00:51 duplicity-full-signatures.20170115T235149Z.sigtar.gz

2. Uncompress the backup volume:

$ gunzip --to-stdout duplicity-full.20170115T235149Z.vol1.difftar.gz > duplicity-full.20170115T235149Z.vol1.difftar

$ ls -l ~/deja-dup
-rw------- 1 luke luke 171 Jan 16 00:51 duplicity-full.20170115T235149Z.manifest
-rw-rw-r-- 1 luke luke 480256 Jan 16 00:57 duplicity-full.20170115T235149Z.vol1.difftar
-rw------- 1 luke luke 48989 Jan 16 00:51 duplicity-full.20170115T235149Z.vol1.difftar.gz
-rw------- 1 luke luke 9965 Jan 16 00:51 duplicity-full-signatures.20170115T235149Z.sigtar.gz

3. Start the first incremental backup and witness the assertion error in duplicity that David reported:

$ deja-dup --backup
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1494, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1488, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1337, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1370, in do_backup
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 697, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 819, in get_backup_chains
    map(add_to_sets, filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 809, in add_to_sets
    if set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 100, in add_filename
    (self.volume_name_dict, filename)
AssertionError: ({1: 'duplicity-full.20170115T235149Z.vol1.difftar'}, 'duplicity-full.20170115T235149Z.vol1.difftar.gz')

$ DEJA_DUP_DEBUG=1 deja-dup --backup > deja-dup.log1
# see attached file for details

4. Interestingly, duplicity already has checks to avoid considering files whose names don't look like they could be part of a backup set, as proven by the success and log file of the following incremental backup:

$ ls -l ~/deja-dup
-rw-rw-r-- 1 luke luke 0 Jan 16 01:08 assignment.odt
-rw-rw-r-- 1 luke luke 0 Jan 16 01:08 creative-writing-syllabus.pdf
-rw-rw-r-- 1 luke luke 0 Jan 16 01:08 duplicity-commandline-memo.txt
-rw-rw-r-- 1 luke luke 0 Jan 16 01:08 duplicity-full-1995-movie.mkv.vol1.rar
-rw------- 1 luke luke 171 Jan 16 00:51 duplicity-full.20170115T235149Z.manifest
-rw------- 1 luke luke 48989 Jan 16 00:51 duplicity-full.20170115T235149Z.vol1.difftar.gz
-rw------- 1 luke luke 9965 Jan 16 00:51 duplicity-full-signatures.20170115T235149Z.sigtar.gz

$ DEJA_DUP_DEBUG=1 deja-dup --backup > deja-dup.l...

Status changed to 'Confirmed' because the bug affects multiple users.

Resetting to "Confirmed", because it turned out, that more triaging is needed.

@Nathanael: Thanks for replicating the bug.

I did some searching for related bugs in duplicity and found bug #1471818, which states, that these files are sometimes even deleted. So we need to go into the code of both software packages now to find the part, which needs improvement.

If you do (or did?) so, it would be helpful, if you could state filename and line number of your findings.

I will come back to this bug later this week

The file and function I examined are those mentioned in the traceback reported by David for Ubuntu 16.04, deja-dup 34.2-0ubuntu1.1, duplicity 0.7.06-2ubuntu2:

  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py",
  line 105, in add_filename
    (self.volume_name_dict, filename)
  AssertionError: ({1: 'duplicity-full.20161129T015237Z.vol1.difftar'},
    'duplicity-full.20161129T015237Z.vol1.difftar.gz')

For Ubuntu 14.04, deja-dup 30.0-0ubuntu4.1, duplicity 0.6.23-1ubuntu4.1:

  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py",
  line 100, in add_filename
    (self.volume_name_dict, filename)
  AssertionError: ({1: 'duplicity-full.20170115T235149Z.vol1.difftar'},
    'duplicity-full.20170115T235149Z.vol1.difftar.gz')

Function add_filename(self, filename) parses the examined filename (in this case "duplicity-full.$timestring.vol1.difftar.gz") and decides if it should be added to the examined backup set (self, an instance of the BackupSet class, consisting for now of just one backup volume, "duplicity-full.$timestring.vol1.difftar").

The function returns True if it adds the examined filename to the current backup set, False if it rejects it, for instance it rejects files whose parse results don't include "full" or "inc", and files whose parse results indicate a different timestring than the timestring of the current backup set.

The assertion that fails is "not self.volume_name_dict.has_key(pr.volume_number)", meaning that the volume number found in the parse results (in our case 1) is already in the backup set (stored as a volumenumber/filename dictionnary: {1: duplicity-full.$timestring.vol1.difftar}).

A quick way to avoid that bug would be to turn the assertion into an "if volume-number already in backup-set, reject filename" (i.e. return False), which means that when encountering two or more of:

  duplicity-$type.$timestring.vol$n.difftar
  duplicity-$type.$timestring.vol$n.difftar.gz
  duplicity-$type.$timestring.vol$n.difftar.gpg

duplicity would accept into the backup set the first filename it processes, and reject the others.

A probably better way would be to also compare compression flags when grouping the files into sets, in addition to backup type (full/inc) and times. That way an uncompressed file couldn't be added to a backup set made up of compressed files, and vice versa. In the simplest case, this would require:

  adding the attribute self.compressed to the class BackupSet

  adding self.compressed = bool(pr.compressed) to the method
  BackupSet.set_info, that initializes the attributes of the
  class instances

  adding something like
    if bool(pr.compressed) != bool(self.compressed):
        return False
  to BackupSet.add_filename after it tests for backup type
  and backup times

But then it gets complicated by the fact that a backup set can be partially encrypted, if I understand correctly the rest of the add_filename function ("if bool(pr.encrypted) != bool(self.encrypted)..."). So perhaps the function should also accommodate backup sets which are partially compressed? Also, assuming the add_filename is changed to group files into sets of homogeneous compression/encryption status, then...

Vej and Nathanael
Update :
I deleted all the contents of dropbox backup file
restarted and it functioned without apparent error.
I did not, as you suggested, choose only a small file for backup, so ended up vol 399.
Running again today after startup no apparent errors.
Thank you for you time and persistence.
 This may save my skin someday.

I'm glad we could help!

All the best
Naël

Added this bug to duplicity, since it is probably better suited for resolution there than in Déjà-Dup.

Also updated the description.

This can also happen if, for some unlikely reason (like a corrupted NTFS partition), the file system lists the same file twice. See Question #670964

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

 status confirmed
 importance medium
 done
-----BEGIN PGP SIGNATURE-----

iQEzBAEBCAAdFiEExwf+p6/3mDvUSsaGH1G0ZBEHM/EFAmBmFc0ACgkQH1G0ZBEH
M/GUCwgAoXIyBDb6kUITjvrIJVhKO8CXv/94R1PxitsoYebTWK1D8TUkOWFmy+mS
2NFM/IsMk5XbIrMgPvaJCyp/CuGzehzIV6hBaQVyhOg9VcuAKSNJ4bSNeABmXqrM
dh7GoiuY7ECn6gybCUznONyDvMJXbhR6/hqZgfOqDZGeNHNMtFpa+72qgcdpnuQh
+ymv+CO9ZyVMqv2Zuh53U53AuBpB9O3NWKhTbYTB3uS8C546jvAzfUEApuSFVYS8
yerauyOPF+BoX6Kcvv2zT52exvrVjTFD6Nmrr3W1SItGP8ayg0lVgdgez3UDaZ/0
W0Euv6sOx6i5LUFmPkgVoJ9pfw6VbQ==
=HUg5
-----END PGP SIGNATURE-----