Crash when restoring data KeyError

Yikes. This looks like it's crashing inside duplicity, the command line backup tool that does the heavy lifting behind the scenes.

Ken, raccoonone's using duplicity 0.5.18-0ubuntu1. I haven't seen this stack trace before.

It looks like there may be an issue with the Manifest. The error says
that volume 15 is not in the list, but it should be.

raccoonone, please attach the manifest (decrypted) to this bug report,
also, I need more info from the log. Please run with -v9 and attach the
first 200 lines and the last 200 lines (roughly), plus the full command
line, so I can get some context into what's going on.

Michael Terry wrote:
> Ken, raccoonone's using duplicity 0.5.18-0ubuntu1. I haven't seen this
> stack trace before.
>

raccoonone, you can get the log from Deja Dup by running the following:

 DEJA_DUP_DEBUG=1 deja-dup > /tmp/deja-dup.log
 cat /tmp/deja-dup.log | head -n 200 > /tmp/deja-dup.head
 cat /tmp/deja-dup.log | tail -n 200 > /tmp/deja-dup.tail

And attaching deja-dup.head and deja-dup.tail.

For the manifests, you should look in ~/.cache/deja-dup/ and find files with the word 'manifest' near the end of their filenames.

Here you go. Let me know if there are any other logs that you need.

I was wrong, it looks like a volume (# 15) is missing. Could you verify that there is indeed a "duplicity-full.*-vol15.difftar.gpg" in your collection.

Hmm, there's no vol15. Did something go wrong with the backup, and can I recover the rest of my files somehow?

It may be possible to remove volume 15 from the manifest and go on from there. You'll need to save a copy of the manifest, edit the file in place, and remove the lines:

Volume 15:
    StartingPath home/christopher/.mozilla/firefox/lm8fky5t.default/XPC.mfasl
    EndingPath home/christopher/Code/OpenCV-2.0.0/3rdparty/.libs/lib_flann.a
    Hash SHA1 c64fb927c6db2fce623e2f37a60ea491f93b631f

Be careful to use an editor like gedit or other text editor. Don't use a document editor.

This may still blow up due to the fact that both the StaringPath and EndingPath are files that are split across volumes. If this works, those files should be considered as trash since they would be incomplete.

k. Any idea what caused this in the first place?

Not really. As far as I know, this is the first time.

raccoonone wrote:
> k. Any idea what caused this in the first place?
>

I restored my computer, reinstalled Deja Dup, reran the backup and tested that it works (which it does now). So I don't know what went wrong before, but perhaps at the end of the backup it should verify that the backup actually worked?

I cannot reproduce this one at all. I'm closing as "Won't Fix" since LP does not have the option "Can't Fix".

As to checking afterwards, that's what the verify command is intended to do.

Closing out deja-dup side of this bug until/if it resurfaces.

I can consistently reproduce something apparently similar with one of my backups. Interestingly it happens after "processed volume 51 of 51", but to judge by the filenames it was a long way from done restoring, and there are a total of 76 increments in the full backup.

Writing bzr-explorer/.bzr/repository/pack-names of type reg
Writing bzr-explorer/.bzr/repository/packs of type dir
Making directory /home/mbp/tmp/trial-restore/bzr-explorer/.bzr/repository/packs
Writing bzr-explorer/.bzr/repository/packs/3a9b176eabd8dfe6b0283df2f776eb15.pack of type reg
Deleting /tmp/duplicity-R7p10d-tempdir/mktemp-tYge6x-52
Processed volume 51 of 51
Traceback (most recent call last):
  File "/home/mbp/work/duplicity/duplicity-bin", line 1245, in <module>
    with_tempdir(main)
  File "/home/mbp/work/duplicity/duplicity-bin", line 1238, in with_tempdir
    fn()
  File "/home/mbp/work/duplicity/duplicity-bin", line 1192, in main
    restore(col_stats)
  File "/home/mbp/work/duplicity/duplicity-bin", line 539, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 522, in Write_ROPaths
    ITR( ropath.index, ropath )
  File "/home/mbp/work/duplicity/duplicity/lazy.py", line 335, in __call__
    last_branch.fast_process, args)
  File "/home/mbp/work/duplicity/duplicity/robust.py", line 37, in check_common_error
    return function(*args)
  File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 575, in fast_process
    ropath.copy( self.base_path.new_index( index ) )
  File "/home/mbp/work/duplicity/duplicity/path.py", line 416, in copy
    other.writefileobj(self.open("rb"))
  File "/home/mbp/work/duplicity/duplicity/path.py", line 591, in writefileobj
    buf = fin.read(_copy_blocksize)
  File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 200, in read
    if not self.addtobuffer():
  File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 225, in addtobuffer
    self.tarinfo_list[0] = self.tar_iter.next()
  File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 332, in next
    self.set_tarfile()
  File "/home/mbp/work/duplicity/duplicity/patchdir.py", line 321, in set_tarfile
    self.current_fp = self.fileobj_iter.next()
  File "/home/mbp/work/duplicity/duplicity-bin", line 575, in get_fileobj_iter
    backup_set.volume_name_dict[vol_num],
KeyError: 52

The backup contents are private but I'm happy to send you edited data if that helps.

Hi,

I am also experiencing the same error. I did a full backup (encryped) and wanted to check a restore today. I chose a different directory just to see if the restored files would match the last incremental backup that happened today.

/home/jorg is the home dir that is backed up, Downloads, temp, Trash and Podcasts are not backed up, and I backed up to /home/jorg/backup-test

The backup destination is FTP, I used a gnome bookmark to backup the files to (which is basically the folder "Backup" on the FTP server).

The stack trace I get is;

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 1204, in main
    restore(col_stats)
  File "/usr/bin/duplicity", line 539, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 522, in Write_ROPaths
    ITR( ropath.index, ropath )
  File "/usr/lib/python2.6/dist-packages/duplicity/lazy.py", line 335, in __call__
    last_branch.fast_process, args)
  File "/usr/lib/python2.6/dist-packages/duplicity/robust.py", line 37, in check_common_error
    return function(*args)
  File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 575, in fast_process
    ropath.copy( self.base_path.new_index( index ) )
  File "/usr/lib/python2.6/dist-packages/duplicity/path.py", line 416, in copy
    other.writefileobj(self.open("rb"))
  File "/usr/lib/python2.6/dist-packages/duplicity/path.py", line 591, in writefileobj
    buf = fin.read(_copy_blocksize)
  File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 200, in read
    if not self.addtobuffer():
  File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 225, in addtobuffer
    self.tarinfo_list[0] = self.tar_iter.next()
  File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 332, in next
    self.set_tarfile()
  File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 321, in set_tarfile
    self.current_fp = self.fileobj_iter.next()
  File "/usr/bin/duplicity", line 575, in get_fileobj_iter
    backup_set.volume_name_dict[vol_num],
KeyError: 3

What is a Gnome Bookmark and how do you back up to it? Did you use a file:// URL as the destination, or ftp:// as the destination. Please be aware that file:// has no retry semantics since it is targeted to the local filesystem. It's possible that whatever is underneath a Gnome Bookmark may be failing silently and not letting duplicity know.

Hi,

When I use the normal FTP protocol and I enter a path it must first
change to before starting the backup, it refuses to change to that path.
So I decided to use a Gnome bookmark which seems to be a saved session
state of the current FTP login path and username. That works well with
sendig data, but restoring always fails hence this bug.

So the real bug was that the FTP path CWD wasn't executed and I tried
gnome bookmarks.

With regards,
- Jorgen

On 12/26/2010 05:27 PM, Kenneth Loafman wrote:
> What is a Gnome Bookmark and how do you back up to it? Did you use a
> file:// URL as the destination, or ftp:// as the destination. Please be
> aware that file:// has no retry semantics since it is targeted to the
> local filesystem. It's possible that whatever is underneath a Gnome
> Bookmark may be failing silently and not letting duplicity know.
>
>
> ** Changed in: duplicity
> Status: Confirmed => In Progress
>

Ken, when Jorgen talks about GNOME bookmarks, he's talking about using Deja Dup and selecting a backup from a dropdown populated with GNOME bookmarks.

I've been thinking about this bug, and I'm confused. It seems relatively common, but I can't figure out how duplicity would leave gaps in the backup. The reporter here had vol15 missing. The reporter from dup bug 804484 had vol1 through vol5 missing!

When resuming, duplicity will use what's actually on the backend to determine what volume to resume at. So I can't see how it would make a gap that way. These reporters don't seem to be using concurrency or anything.

Ken, have you had any ideas here?

I can imagine how one might be missing if it was the last one being sent and
it never made it before a forced shutdown. But we handle that case.

The other possible issue is concurrency, but that's not likely. I can see
how one volume might go missing, but not 5.

...Ken

On Fri, Jul 8, 2011 at 10:49 PM, Michael Terry
<email address hidden>wrote:

> Ken, when Jorgen talks about GNOME bookmarks, he's talking about using
> Deja Dup and selecting a backup from a dropdown populated with GNOME
> bookmarks.
>
> I've been thinking about this bug, and I'm confused. It seems
> relatively common, but I can't figure out how duplicity would leave gaps
> in the backup. The reporter here had vol15 missing. The reporter from
> dup bug 804484 had vol1 through vol5 missing!
>
> When resuming, duplicity will use what's actually on the backend to
> determine what volume to resume at. So I can't see how it would make a
> gap that way. These reporters don't seem to be using concurrency or
> anything.
>
> Ken, have you had any ideas here?
>
> --
> You received this bug notification because you are a bug assignee.
> https://bugs.launchpad.net/bugs/498933
>
> Title:
> Crash when restoring data KeyError
>
> Status in Déjà Dup Backup Tool:
> Invalid
> Status in Duplicity - Bandwidth Efficient Encrypted Backup:
> In Progress
> Status in “deja-dup” package in Ubuntu:
> Invalid
>
> Bug description:
> Binary package hint: deja-dup
>
> 1) Ubuntu 9.10
> 2) Deja Dup 10.2-0ubuntu1.1
> 3) I expected my backup to be restored
> 4) Deja Dup crashed instead.
>
> I just tried to restore the backup I made, and it crashes repeatedly
> when trying to restore.
>
> I have it setup to backup my home directory, and tried restoring to
> both the original location as well as a completely different folder.
> Both lead to the same error message.
>
>
> Traceback (most recent call last):
> File "/usr/bin/duplicity", line 825, in <module>
> with_tempdir(main)
> File "/usr/bin/duplicity", line 818, in with_tempdir
> fn()
> File "/usr/bin/duplicity", line 775, in main
> restore(col_stats)
> File "/usr/bin/duplicity", line 436, in restore
> restore_get_patched_rop_iter(col_stats)):
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 521,
> in Write_ROPaths
> ITR(ropath.index, ropath)
> File "/usr/lib/python2.6/dist-packages/duplicity/lazy.py", line 336, in
> __call__
> last_branch.fast_process, args)
> File "/usr/lib/python2.6/dist-packages/duplicity/robust.py", line 38, in
> check_common_error
> return function(*args)
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 574,
> in fast_process
> ropath.copy(self.base_path.new_index(index))
> File "/usr/lib/python2.6/dist-packages/duplicity/path.py", line 412, in
> copy
> other.writefileobj(self.open("rb"))
> File "/usr/lib/python2.6/dist-packages/duplicity/path.py", line 574, in
> writefileobj
> buf = fin.read(_copy_blocksize)
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line 199,
> in read
> if not self.addtobuffer():
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdi...

If it's any help, the place where my backup was located is a debian machine
running samba, and I mounted it using cifs. I tried restoring older backups
but with the same error. It also didn't work when i tried to restore using
command-line duplicity, for obvious reasons. The laptop i backed up from was
made by HP and was 3-4 years old.
This probably won't help, but who knows.
Den 9 jul 2011 18:05 skrev "Kenneth Loafman" <email address hidden>:

This has happened with both Deja Dup (this bug) and base duplicity (bug 751178). And it's happened with the gio backend (multiple protocols) and the ftp backend (bug 751178 again). So I doubt it's something Deja Dup is doing or some bug with a specific backend silently not writing its files.

There are a couple side issues we might want to fix as well:
 * Treat chains with gaps as 'incomplete' and ignore them
 * Make this error message nicer (though we likely wouldn't ever hit it if we did the above)

I know it's unlikely, but if anyone has a backup set that is exhibiting this problem and can be shared with me, please let me know.

I'm also experiencing this bug. I'm backing up to RackSpace via DéjàDup.

I don't know if this helps any, but I have DéjàDup configured to backup daily and keep backups for "at least a month." Because my backup set is large and my machine isn't always online, full backups take considerably more than a week to complete, meaning that once a full backup completes, it's only a few days until DéjàDup decides to do another full backup. Additionally, when restoring, I only have two restore points available: 2011-07-01 and 2011-07-14 (today's date is 2011-08-11, and backups should be happening daily).

Finally, the backup that ran today aborted with an error. However, unfortunately I didn't note the error, since I wasn't in bug-reporting mode.

I don't know whether any of this info is helpful in diagnosing this problem.

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 1209, in main
    restore(col_stats)
  File "/usr/bin/duplicity", line 539, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 521, in Write_ROPaths
    for ropath in rop_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 493, in integrate_patch_iters
    for patch_seq in collated:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 378, in yield_tuples
    setrorps( overflow, elems )
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 367, in setrorps
    elems[i] = iter_list[i].next()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 99, in filter_path_iter
    for path in path_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 112, in difftar2path_iter
    tarinfo_list = [tar_iter.next()]
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 328, in next
    self.set_tarfile()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 322, in set_tarfile
    self.current_fp = self.fileobj_iter.next()
  File "/usr/bin/duplicity", line 575, in get_fileobj_iter
    backup_set.volume_name_dict[vol_num],
KeyError: 5393

Trying to reproduce this bug, but no luck. Could all of you that have it verify what version of duplicity is causing the problem? Does the problem occur with the latest version of duplicity?

Version information for this bug is hard to come by, since the useful bit is the version that was actually used for the backup. But in bug 804484, the user implies that they backed up in Ubuntu 10.10 before moving to (and trying to restore on) Ubuntu 11.04.

So that would mean duplicity 0.6.10 is the most recent version for which we have evidence that it can trigger this bug.

I've only started using Deja-dup (and thus Duplicity) since I've been running Ubuntu 11.04. I'm currently running duplicity-0.6.13, and have only used an older version if such a version was once in the official Natty repositories.

Thanks, Scott.

Another interesting data point is that this bug's original reporter was using duplicity 0.5.18, right before checkpoint/restart support was added. So this likely isn't a bug with that feature.

Just a note, in 0.6.16, there will be some code to detect when this happens as it happens, so hopefully there won't be any surprises at resume time. We're still not sure of the root cause.

Ubuntu 10.04 LTS server
Duplicity 0.6.16 from PPA
--no-encryption to ssh storage server

backup runs fine.
Verify action (need to give --no-encryption as well) fails with KeyError: 1 every time for every backup set (there are about 20), some with multiple volumes, some with only a single volume. Full + increment or just full doesn't seem to make a difference.

Same error but it looks like maybe a different cause? Traceback attached.

This is a regression from 0.6.15->0.6.16. I installed from source 0.6.15 and it works fine.

D. Grady, your problem might be the same as mine, which is reported in Bug #881727. It might be an issue separate from the one in this bug.

My problem is definitely what you reported, megari, based on your much fuller information provided. Not sure if it's the same bug or not.

Closing deja-dup task, as this has been reported with just duplicity alone.

Can anyone reproduce this with the current version, 0.6.17??

[Expired for Duplicity because there has been no activity for 60 days.]

I just had this bug on Ubuntu 17.10, duplicity 0.7.12

```
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1546, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1540, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1391, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1468, in do_backup
    restore(col_stats)
  File "/usr/bin/duplicity", line 731, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 560, in Write_ROPaths
    for ropath in rop_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 523, in integrate_patch_iters
    for patch_seq in collated:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 389, in yield_tuples
    setrorps(overflow, elems)
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 378, in setrorps
    elems[i] = iter_list[i].next()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 121, in difftar2path_iter
    tarinfo_list = [tar_iter.next()]
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 339, in next
    self.set_tarfile()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 333, in set_tarfile
    self.current_fp = self.fileobj_iter.next()
  File "/usr/bin/duplicity", line 767, in get_fileobj_iter
    backup_set.volume_name_dict[vol_num],
KeyError: 1

```

It may or may not be related, but before seeing this bug, I had run restore in a loop on different times, asynchronously, that is to say I used:

for x in `seq 10 15`
duplicity --time {$x}D ... &

Note the ampersand, I forked them to a background process.
THEN on top of that I hit CTRL-C to force a cancel. This may have corrupted a cache.

This seems to have helped me (clearing the cache):

mv ~/.cache/duplicity ~/.cache/duplicity.old

[Expired for Duplicity because there has been no activity for 60 days.]

Setting back to confirmed because Kenneths question from comment #36 is implicitly answered in comment #38.

Please upgrade to the 0.7.15 version of duplicity. This will assure that any bugs fixed since the 0.7.12 release are available and may fix your issue.

There are three options:

* Release tarball Install - https://launchpad.net/duplicity/+download
* Daily duplicity builds - https://launchpad.net/~duplicity-team/+archive/ubuntu/daily
* Stable duplicity builds - https://launchpad.net/~duplicity-team/+archive/ubuntu/ppa

NOTE: UNinstall duplicity first if it was installed via the distribution repository. For Ubuntu, that would be "sudo apt-get purge duplicity".

I am seeing this too. It happened first time after I started backups from scratch after several weeks. It keeps occurring every day now.

Traceback (innermost last):
  File "/usr/bin/duplicity", line 1555, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1541, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1393, in main
    do_backup(action)
  File "/usr/bin/duplicity", line 1472, in do_backup
    restore(col_stats)
  File "/usr/bin/duplicity", line 728, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 558, in Write_ROPaths
    for ropath in rop_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 521, in integrate_patch_iters
    for patch_seq in collated:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 389, in yield_tuples
    setrorps(overflow, elems)
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 378, in setrorps
    elems[i] = iter_list[i].next()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 107, in filter_path_iter
    for path in path_iter:
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 121, in difftar2path_iter
    tarinfo_list = [tar_iter.next()]
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 339, in next
    self.set_tarfile()
  File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 333, in set_tarfile
    self.current_fp = self.fileobj_iter.next()
  File "/usr/bin/duplicity", line 764, in get_fileobj_iter
    backup_set.volume_name_dict[vol_num],
 KeyError: 43

This is with duplicity 0.7.17+bzr1353 and deja-dup 36.3 on Ubuntu 17.10.

This is a tail of log:

DUPLICITY: DEBUG 1
DUPLICITY: . Found manifest volume 7529

DUPLICITY: DEBUG 1
DUPLICITY: . Found manifest volume 7530

DUPLICITY: DEBUG 1
DUPLICITY: . Found manifest volume 7531

DUPLICITY: INFO 1
DUPLICITY: . Found 7531 volumes in manifest

DUPLICITY: DEBUG 1
DUPLICITY: . Releasing lockfile /home/user1/.cache/deja-dup/85893b547e8951c12699b18a9f26d2da/lockfile

DUPLICITY: DEBUG 1
DUPLICITY: . Removing still remembered temporary file /tmp/duplicity-LM6LdM-tempdir/mkstemp-slQNlf-1

DUPLICITY: DEBUG 1
DUPLICITY: . Releasing lockfile /home/user1/.cache/deja-dup/85893b547e8951c12699b18a9f26d2da/lockfile

DUPLICITY: ERROR 30 KeyError
DUPLICITY: . Traceback (innermost last):
DUPLICITY: . File "/usr/bin/duplicity", line 1555, in <module>
DUPLICITY: . with_tempdir(main)
DUPLICITY: . File "/usr/bin/duplicity", line 1541, in with_tempdir
DUPLICITY: . fn()
DUPLICITY: . File "/usr/bin/duplicity", line 1393, in main
DUPLICITY: . do_backup(action)
DUPLICITY: . File "/usr/bin/duplicity", line 1472, in do_backup
DUPLICITY: . restore(col_stats)
DUPLICITY: . File "/usr/bin/duplicity", line 728, in restore
DUPLICITY: . restore_get_patched_rop_iter(col_stats)):
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 558, in Write_ROPaths
DUPLICITY: . for ropath in rop_iter:
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 521, in integrate_patch_iters
DUPLICITY: . for patch_seq in collated:
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 389, in yield_tuples
DUPLICITY: . setrorps(overflow, elems)
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 378, in setrorps
DUPLICITY: . elems[i] = iter_list[i].next()
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 107, in filter_path_iter
DUPLICITY: . for path in path_iter:
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 121, in difftar2path_iter
DUPLICITY: . tarinfo_list = [tar_iter.next()]
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 339, in next
DUPLICITY: . self.set_tarfile()
DUPLICITY: . File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line 333, in set_tarfile
DUPLICITY: . self.current_fp = self.fileobj_iter.next()
DUPLICITY: . File "/usr/bin/duplicity", line 764, in get_fileobj_iter
DUPLICITY: . backup_set.volume_name_dict[vol_num],
DUPLICITY: . KeyError: 43
DUPLICITY: .

DUPLICITY: DEBUG 1
DUPLICITY: . Releasing lockfile /home/user1/.cache/deja-dup/85893b547e8951c12699b18a9f26d2da/lockfile

Log head.

Log head.

Please zip and post the entire log file if possible. If not possible, please do do the following:

$ grep -C 10 "vol43\." YourLogFile

and attach the results.

Here is the result of `grep -C 10 "vol43\." deja-dup.log`. It is compressed because it is otherwise 5 MiB.

OK, this is an old bug. The file list coming back from the remote is
truncated, however, I can clearly see vol43 in the list for
the 20171228T132324Z backup. Very confusing.

Would you look on the remote manually and compare the number of files? I'm
sure it is higher.

On Sun, Apr 1, 2018 at 10:41 AM, Václav Haisman <email address hidden> wrote:

> Here is the result of `grep -C 10 "vol43\." deja-dup.log`. It is
> compressed because it is otherwise 5 MiB.
>
> ** Attachment added: "result of `grep -C 10 "vol43\." deja-dup.log`"
> https://bugs.launchpad.net/ubuntu/+source/deja-dup/+bug/
> 498933/+attachment/5098011/+files/vol43.txt.xz
>
> --
> You received this bug notification because you are subscribed to
> Duplicity.
> https://bugs.launchpad.net/bugs/498933
>
> Title:
> Crash when restoring data KeyError
>
> Status in Déjà Dup:
> Invalid
> Status in Duplicity:
> Confirmed
> Status in deja-dup package in Ubuntu:
> Invalid
>
> Bug description:
> Binary package hint: deja-dup
>
> 1) Ubuntu 9.10
> 2) Deja Dup 10.2-0ubuntu1.1
> 3) I expected my backup to be restored
> 4) Deja Dup crashed instead.
>
> I just tried to restore the backup I made, and it crashes repeatedly
> when trying to restore.
>
> I have it setup to backup my home directory, and tried restoring to
> both the original location as well as a completely different folder.
> Both lead to the same error message.
>
>
> Traceback (most recent call last):
> File "/usr/bin/duplicity", line 825, in <module>
> with_tempdir(main)
> File "/usr/bin/duplicity", line 818, in with_tempdir
> fn()
> File "/usr/bin/duplicity", line 775, in main
> restore(col_stats)
> File "/usr/bin/duplicity", line 436, in restore
> restore_get_patched_rop_iter(col_stats)):
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line
> 521, in Write_ROPaths
> ITR(ropath.index, ropath)
> File "/usr/lib/python2.6/dist-packages/duplicity/lazy.py", line 336,
> in __call__
> last_branch.fast_process, args)
> File "/usr/lib/python2.6/dist-packages/duplicity/robust.py", line 38,
> in check_common_error
> return function(*args)
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line
> 574, in fast_process
> ropath.copy(self.base_path.new_index(index))
> File "/usr/lib/python2.6/dist-packages/duplicity/path.py", line 412,
> in copy
> other.writefileobj(self.open("rb"))
> File "/usr/lib/python2.6/dist-packages/duplicity/path.py", line 574,
> in writefileobj
> buf = fin.read(_copy_blocksize)
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line
> 199, in read
> if not self.addtobuffer():
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line
> 224, in addtobuffer
> self.tarinfo_list[0] = self.tar_iter.next()
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line
> 331, in next
> self.set_tarfile()
> File "/usr/lib/python2.6/dist-packages/duplicity/patchdir.py", line
> 320, in set_tarfile
> self.current_fp = self.fileobj_iter.next()
> File "/usr/bin/duplicity", line 472, in get_fileobj...

> The file list coming back from the remote is truncated [...]

You are absolutely right. I have WD My Cloud Mirror Gen 2 device and I used FTP to store the backups there. It turns out the Pro-FTPd that it uses only returns 10000 lines for directory listing command and my backups have grown beyond that point. I have ended up switching to CIFS mount to work around this.

This could alleviated if Deja-dup/Duplicity was using larger files for storage. Also, diagnosing this directory listing truncation instead of outright exception stack trace would be nice.