AssertionError after interruption/restart of backup

[On-The-Fly]

when starting a backup with Ubuntu 11.10 it starts to initialize but then fails with the following error message:

"Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1359, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1342, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1222, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 684, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 807, in get_backup_chains
    map(add_to_sets, filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 797, in add_to_sets
    if set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 94, in add_filename
    (self.volume_name_dict, filename)
AssertionError: ({1: u'duplicity-full.20111018T090402Z.vol1.difftar.gpg', 10: u'duplicity-full.20111018T090402Z.vol10.difftar.gpg', 11: u'duplicity-full.20111018T090402Z.vol11.difftar.gpg', 12: u'duplicity-full.20111018T090402Z.vol12.difftar.gpg', 13: u'duplicity-full.20111018T090402Z.vol13.difftar.gpg', 14: u'duplicity-full.20111018T090402Z.vol14.difftar.gpg', 15: u'duplicity-full.20111018T090402Z.vol15.difftar.gpg', 16: u'duplicity-full.20111018T090402Z.vol16.difftar.gpg', 17: u'duplicity-full.20111018T090402Z.vol17.difftar.gpg', 18: u'duplicity-full.20111018T090402Z.vol18.difftar.gpg', 19: u'duplicity-full.20111018T090402Z.vol19.difftar.gpg', 20: u'duplicity-full.20111018T090402Z.vol20.difftar.gpg', 21: u'duplicity-full.20111018T090402Z.vol21.difftar.gpg', 22: u'duplicity-full.20111018T090402Z.vol22.difftar.gpg', 23: u'duplicity-full.20111018T090402Z.vol23.difftar.gpg', 24: u'duplicity-full.20111018T090402Z.vol24.difftar.gpg', 25: u'duplicity-full.20111018T090402Z.vol25.difftar.gpg'}, u'duplicity-full.20111018T090402Z.vol25.difftar.gz')"

I'm trying to make a backup to my Ubuntu One online storage with my backup being encrypted.
Before this error occured, I was making my initial backup when the program returned an error code 302 ("Got status code 302") and aborted when it was close to being finished.

I'm using
deja-dup 20.0-0ubuntu3
duplicity 0.6.15-0ubuntu2

For more information, please see the attachment containing two logs.

[Michael Terry (mterry)]

For some reason, you have two volume 25's: duplicity-full.20111018T090402Z.vol25.difftar.gz and duplicity-full.20111018T090402Z.vol25.difftar.gpg.

Delete the difftar.gz one and try again. Does that work?

[On-The-Fly (onthefly)]

Looking into it via the web interface on one.ubuntu.com I don't see two 25 volumes but rather that all volumes until 24 are GPG and all volumes after that (25-31) are GZ. Should I delete all GZ ones and hope that it'll continue creating GPGs?

[Michael Terry (mterry)]

Yikes. Wipe all of them and start fresh. Deleting only a few of the volumes will cause problems when you want to restore. I'm looking into how this could have happened.

[On-The-Fly (onthefly)]

I will try this now. As my internet connection is very slow this is a pretty frustrating bug. I'm going to report when I am finished or encountering the next error.

A few other things that don't belong to this bug: you should consider implementing include and exclude of files and not just folders. Think of a user wanting to backup his /etc/fstab i.e..
Also, when pressing the 'backup now' (or whatever this string is in English) button in the settings, the settings should just disappear and only the newly opened window with déjà dup backing up should be visible.
And last but not least I have a question: as mentioned before my internet connection isn't very fast (and disk space is always rare). Therefore I want to know if déjà dup is making incremental updates like Areca Backup does (which is a very handy tool by the way).

[On-The-Fly (onthefly)]

the backup seems to have ended properly by now

[Michael Terry (mterry)]

Hello! I've figured out why this is happening, I think. Is the following scenario likely?

1) You started your first ever backup
2) You chose to encrypt it with a password
3) Your backup got interrupted
4) You later backed up again, resuming the backup
5) You were prompted for your encryption password again, but mistyped it (and DD accepted it without question)
6) Later, you got this error

I can reproduce the bug with those steps.

As for your other questions, more advanced include/exclude support is bug 374274. And yes, Deja Dup is making incremental updates. But every now and then (ever few months by default), it will make a fresh full backup.

[On-The-Fly (onthefly)]

The scenario fits pretty well except for point 5. At least I would say that I did not mistype it, because I normally double-check it. But as I cannot be 100% sure; I'll just say that you described my scenario perfectly (which would explain why out of a sudden DD created another archive type while continuing).
Thank you very much for this reply. You might mark this bug now as solved or wait for this until you made sure that DD prompts for retyping the password if it was wrong.

[Michael Terry (mterry)]

Hmm... With further testing, I'm now realizing that if you mistype your password, DD will accept it and just back up with a different password. But if you enter spaces as your password, it will switch to unencrypted backups as you have.

It sounds even less likely that you entered spaces as your password. So I think the behavior I describe about passwords is a separate (but also bad) bug. I'm suspecting there is another way to end up with a switch unencrypted backups that I haven't discovered yet.

[On-The-Fly (onthefly)]

if I recall it correctly, I interrupted the backup twice (or maybe even three times). When I wanted to continue the backup later on, I was asked for a password, entered it and it continued (and I am pretty sure that I did not mistype it). Then I suspended it again and when I continued for the second time, I was not asked for a password but it simply continued with the backup until the error 302 came up.
My password weren't spaces or even included them.

Additionally, I think that some files changed during backup. I don't know if that is a problem for déjà-dup though.

[Louis Bouchard (louis)]

I can confirm that I'm seeing a similar issue, but this was caused by voluntarily interrupting the backup by using the "continue later" button.

Here is the python backtrace :

Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1359, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1342, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1222, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 684, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 807, in get_backup_chains
    map(add_to_sets, filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 797, in add_to_sets
    if set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 94, in add_filename
    (self.volume_name_dict, filename)
AssertionError: ({10: u'duplicity-full.20111020T125029Z.vol10.difftar.gpg', 11: u'duplicity-full.20111020T125029Z.vol11.difftar.gpg', 12: u'duplicity-full.20111020T125029Z.vol12.difftar.gpg', 13: u'duplicity-full.20111020T125029Z.vol13.difftar.gpg'}, u'duplicity-full.20111020T125029Z.vol13.difftar.gz')

This is easily reproducible using local file system storage by following those steps :
1) Define the storage as a directory on a local disk
2) Start the backup and provide a password for encryption
3) use 'watch ls /the/backup/directory' to see the backup files appearing. They should end in .gpg
4) Interrupt the backup using "continue later" button
5) Restart the backup
6) Wait for new files to be created in the directory. They will now end in .gz
7) Interrupt the backup again like in #4
8) Restart the backup a third time, it will fail with the backtrace cited above.

It looks like, when interrupted and then restarted, deja-dup restarts _without_ encryption, which explains why the .gz file appears. When looking at the .gz file using a simple 'tar tvzf *.gz', it is indeed not encrypted and completly readable.

hth

[Michael Terry (mterry)]

Louis, love it! I haven't been able to reproduce yet, so someone that can is incredibly helpful.

I still can't reproduce with your sequence. I'd like to ask a few questions, to see if I can get to the same point that you're at.

1) Do you click 'Remember password' or not?
2) Do you interrupt the backup after a particular number of volumes exist?
3) Is there anything special about your settings? Can you share the output of "gsettings list-recursively org.gnome.DejaDup"?

[Louis Bouchard (louis)]

Hello,
Le 21/10/2011 17:42, Michael Terry a écrit :
> Louis, love it! I haven't been able to reproduce yet, so someone that
> can is incredibly helpful.
>
> I still can't reproduce with your sequence. I'd like to ask a few
> questions, to see if I can get to the same point that you're at.
>

Well, in order to rule out some customization that might have caused
this, I revered to the default backup scheme and ran the test again.

> 1) Do you click 'Remember password' or not?
No I didn't

> 2) Do you interrupt the backup after a particular number of volumes exist?
In the two test I did (one again a few minutes ago), I let it create 3
volumes.

> 3) Is there anything special about your settings? Can you share the output of "gsettings list-recursively org.gnome.DejaDup"?
>
Here it is :
> org.gnome.DejaDup backend 'file'
> org.gnome.DejaDup delete-after 0
> org.gnome.DejaDup exclude-list ['/home/caribou/.local/share/Trash', '/home/caribou/Téléchargements']
> org.gnome.DejaDup include-list ['/home/caribou']
> org.gnome.DejaDup last-backup '2011-10-24T12:33:09.052766Z'
> org.gnome.DejaDup last-restore ''
> org.gnome.DejaDup last-run '2011-10-24T12:33:09.052766Z'
> org.gnome.DejaDup periodic true
> org.gnome.DejaDup periodic-period 7
> org.gnome.DejaDup prompt-check '2011-10-17T12:31:15.057955Z'
> org.gnome.DejaDup root-prompt true
> org.gnome.DejaDup welcomed true
> org.gnome.DejaDup.File icon '. GThemedIcon drive-harddisk-usb drive-harddisk drive'
> org.gnome.DejaDup.File name 'Disque dur 500 GB: workdisk'
> org.gnome.DejaDup.File path ''
> org.gnome.DejaDup.File relpath b'backup/deja-test'
> org.gnome.DejaDup.File short-name 'workdisk'
> org.gnome.DejaDup.File type 'volume'
> org.gnome.DejaDup.File uuid '46163E7331613F19'
> org.gnome.DejaDup.Rackspace container 'marvin'
> org.gnome.DejaDup.Rackspace username ''
> org.gnome.DejaDup.S3 bucket ''
> org.gnome.DejaDup.S3 folder 'marvin'
> org.gnome.DejaDup.S3 id ''
> org.gnome.DejaDup.U1 folder '/deja-dup/marvin'

The following is a capture of the 'ps aux' output that shows the
duplicity options being used when executed the first time :

> caribou 3127 0.0 0.1 159960 4048 ? Sl 08:52 0:00 /usr/lib/deja-dup/deja-dup/deja-dup-monitor
> caribou 7190 0.8 0.9 682172 37056 ? Sl 14:23 0:03 gnome-control-center deja-dup
> caribou 7793 34.7 0.4 404364 17620 ? RNl 14:29 0:05 deja-dup --backup
> caribou 7806 102 0.4 107632 15952 ? RNs 14:30 0:06 /usr/bin/python /usr/bin/duplicity full --exclude=/media/workdisk/backup/deja-test --exclude=/home/caribou/Téléchargements --exclude=/home/caribou/.local/share/Trash --exclude=/home/caribou/.xsession-errors --exclude=/home/caribou/.thumbnails --exclude=/home/caribou/.gvfs --exclude=/home/caribou/.adobe/Flash_Player/AssetCache --exclude=/home/caribou/.cache/deja-dup --exclude=/home/caribou/.cache --include=/home/caribou --exclude=/sys --exclude=/proc --exclude=/tmp --exclude=** --gio --volsize=50 / file:///media/workdisk/backup/deja-test --verbosity=9 --gpg-options=--no-use-agent --archive-dir=/home/caribou/.cache/deja-dup --log-fd=17

Now this is the capture of the 'ps aux' output when deja-dup is used the
sec...

[On-The-Fly (onthefly)]

> I can confirm that I'm seeing a similar issue, but this was caused by voluntarily interrupting the backup by using the "continue later" button.

I might have not been too clear about this but all my interrupts occured on a complete voluntary basis as well.

[Michael Terry (mterry)]

I still can't reproduce. :( To be clear, what happens with me is that in Run #2, I *do* get prompted for my encryption password and Deja Dup *does* keep making .gpg files. Thus I never actually hit the error/traceback in Run #3.

Louis and I will both be at UDS, so we can debug what's going on there, once I have my hands on a reproducable machine.

[Michael Terry (mterry)]

OK, I got in touch with Louis.

Reproduction steps:

1) Make sure your LANGUAGE is de, es, fr, id, it, pt_BR, or sl and you have the appropriate language packs installed.
2) Follow the reproduction steps are in comment #11.

Why this bug happens:

In duplicity 0.6.15, a new feature was added to report to frontends (like deja-dup) whether the backup was encrypted. This was used in deja-dup to detect encryption on the fly and thus streamline the UI by dropping a preference checkbox.

To support older versions of duplicity, deja-dup added some detection code that relied on parsing a string intended for the user. Which is not normally a wise thing to do. But in 0.6.14 and before, that string was not marked for translation, so I felt it was safe to parse the string.

Then, it was discovered that a bug existed in 0.6.15's detection feature, and I reverted to the string parsing method of detection for that version. But in the mean time, that string had been marked for translation for 0.6.15's release.

So for those languages that translate that string, deja-dup does not notice the encryption and will continue an encrypted backup as unencrypted, creating this bug.

The fix:

Implement a slightly different string parsing that does not depend on the translation for 0.6.15. I am working on a patch for 22 and will backport that to 20 once it is approved.

[Launchpad Janitor (janitor)]

This bug was fixed in the package deja-dup - 21.1-0ubuntu2

---------------
deja-dup (21.1-0ubuntu2) precise; urgency=low

  * debian/patches/fix_encryption_switch.patch:
    - Backport patch from trunk to fix a bad bug that breaks backups after
      an interruption for some locales. LP: #877631
 -- Michael Terry <email address hidden> Thu, 03 Nov 2011 17:33:20 -0400

[Michael Terry (mterry)]

I've uploaded the fix from trunk/precise to oneiric-proposed and subscribed ubuntu-sru. This is a good SRU candidate because for some common locales, backup does not work after being interrupted.

For reproduction steps and background, see comment #16.

This fix prevents this sequence of events from happening in the future, but it does not try to automatically delete any data on your backend that may be cause the error now. So if you've hit this in the past, you may want to manually delete the old backup chain.

[Martin Pitt (pitti)]

Hello On-The-Fly, or anyone else affected,

Accepted deja-dup into oneiric-proposed, the package will build now and be available in a few hours. Please test and give feedback here. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Thank you in advance!

[Bernd Dietzel (1-launchpad-net-theregrunner-com)]

i am using deja-dup 20.1-0ubuntu0.2 (oneiric-proposed) to fix the problem , but the bug is śtill there

i am using ubuntu 11.10 32 bit with german Language (de)
i had used a password for encryption ( letters a-z , 0-9, and special char "-" )
i choose to keep the password
i choose to keep the backup one month ( maybe i changed to this while backup was running )
i interrupted backup
i tried to resume next day

------------ Error Message --------------
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1359, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1342, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1222, in main
    globals.archive_dir).set_values()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 684, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 807, in get_backup_chains
    map(add_to_sets, filename_list)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 797, in add_to_sets
    if set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 94, in add_filename
    (self.volume_name_dict, filename)
AssertionError: ({1: u'duplicity-full.20111107T184703Z.vol1.difftar.gpg', 10: u'duplicity-full.20111107T184703Z.vol10.difftar.gpg', 11: u'duplicity-full.20111107T184703Z.vol11.difftar.gpg', 12: u'duplicity-full.20111107T184703Z.vol12.difftar.gpg', 13: u'duplicity-full.20111107T184703Z.vol13.difftar.gpg', 14: u'duplicity-full.20111107T184703Z.vol14.difftar.gpg', 15: u'duplicity-full.20111107T184703Z.vol15.difftar.gpg', 16: u'duplicity-full.20111107T184703Z.vol16.difftar.gpg', 17: u'duplicity-full.20111107T184703Z.vol17.difftar.gpg', 18: u'duplicity-full.20111107T184703Z.vol18.difftar.gpg', 19: u'duplicity-full.20111107T184703Z.vol19.difftar.gpg', 20: u'duplicity-full.20111107T184703Z.vol20.difftar.gpg', 21: u'duplicity-full.20111107T184703Z.vol21.difftar.gpg', 22: u'duplicity-full.20111107T184703Z.vol22.difftar.gpg', 23: u'duplicity-full.20111107T184703Z.vol23.difftar.gpg'}, u'duplicity-full.20111107T184703Z.vol23.difftar.gz')

[Louis Bouchard (louis)]

Well, I have just tested on my system with this version and it now works correctly when localized in french.

It does not re-prompt for a password and continue the backup as expected.

...Louis

[Launchpad Janitor (janitor)]

This bug was fixed in the package deja-dup - 20.1-0ubuntu0.2

---------------
deja-dup (20.1-0ubuntu0.2) oneiric-proposed; urgency=low

  * debian/patches/fix_encryption_switch.patch:
    - Backport patch from 20.x trunk to fix a bad bug that breaks backups
      after an interruption for some locales. LP: #877631
 -- Michael Terry <email address hidden> Fri, 04 Nov 2011 12:34:06 -0400