AssertionError in manifest.py: assert filecount == len(self.files_changed)

Bug #1538333 reported by Grishnackh
46
This bug affects 7 people
Affects Status Importance Assigned to Milestone
Duplicity
Fix Released
High
Unassigned
duplicity (Ubuntu)
Fix Released
High
Unassigned
Zesty
Fix Released
High
Unassigned

Bug Description

Duplicity was almost finishing a full backup to a FTP server. When I restarted the backup, the following error occured:

root@MyMachine:~# duply MyProfile backup
Start duply v1.11, time is 2016-01-26 23:38:21.
Using profile '/root/.duply/MyProfile'.
Using installed duplicity version 0.7.06, python 2.7.3, gpg 1.4.12 (Home: ~/.gnupg), awk 'mawk 1.3.3 Nov 1996, Copyright (C) Michael D. Brennan', grep 'grep (GNU grep) 2.12', bash 'GNU bash, Version 4.2.37(1)-release (i486-pc-linux-gnu)'.
Autoset found secret key of first GPG_KEY entry 'XXXXXXXX' for signing.
Checking TEMP_DIR '/tmp' is a folder and writable (OK)
Test - Encrypt to 'XXXXXXXX' & Sign with 'XXXXXXXX' (OK)
Test - Decrypt (OK)
Test - Compare (OK)
Cleanup - Delete '/tmp/duply.16938.1453847902_*'(OK)

--- Start running command PRE at 23:38:24.349 ---
Skipping n/a script '/root/.duply/MyProfile/pre'.
--- Finished state OK at 23:38:24.400 - Runtime 00:00:00.051 ---

--- Start running command BKP at 23:38:24.447 ---
LFTP version is 4.3.6
Reading globbing filelist /root/.duply/MyProfile/exclude
Local and Remote metadata are synchronized, no sync needed.
Traceback (most recent call last):
  File "/usr/local/bin/duplicity", line 1532, in <module>
    with_tempdir(main)
  File "/usr/local/bin/duplicity", line 1526, in with_tempdir
    fn()
  File "/usr/local/bin/duplicity", line 1380, in main
    do_backup(action)
  File "/usr/local/bin/duplicity", line 1405, in do_backup
    globals.archive_dir).set_values()
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 710, in set_values
    self.get_backup_chains(partials + backend_filename_list)
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 835, in get_backup_chains
    add_to_sets(f)
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 829, in add_to_sets
    if new_set.add_filename(filename):
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 101, in add_filename
    self.set_manifest(filename)
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 149, in set_manifest
    self.set_files_changed()
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 128, in set_files_changed
    mf = self.get_manifest()
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 250, in get_manifest
    return self.get_local_manifest()
  File "/usr/local/lib/python2.7/dist-packages/duplicity/collections.py", line 225, in get_local_manifest
    return manifest.Manifest().from_string(manifest_buffer)
  File "/usr/local/lib/python2.7/dist-packages/duplicity/manifest.py", line 207, in from_string
    assert filecount == len(self.files_changed)
AssertionError

23:38:36.860 Task 'BKP' failed with exit code '30'.
--- Finished state FAILED 'code 30' at 23:38:36.860 - Runtime 00:00:12.412 ---

--- Start running command POST at 23:38:36.930 ---
Skipping n/a script '/root/.duply/MyProfile/post'.
--- Finished state OK at 23:38:36.983 - Runtime 00:00:00.052 ---

Probably the version of python got updated in the meantime, but I'm not sure about this.

Similar tickets, eventually this bug report is a duplicate of those:
- https://bugs.launchpad.net/duplicity/+bug/1485579
- https://bugzilla.redhat.com/show_bug.cgi?id=1288702

Changed in duplicity:
importance: Undecided → Medium
milestone: none → 0.7.07
status: New → Fix Committed
Changed in duplicity:
status: Fix Committed → Fix Released
Vej (vej)
Changed in duplicity (Ubuntu):
status: New → Triaged
importance: Undecided → High
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package duplicity - 0.7.06-2ubuntu3

---------------
duplicity (0.7.06-2ubuntu3) zesty; urgency=medium

  * d/p/backport-fix-tags-in-locked-folders.patch:
    - Fix OSError looking for tag in locked folders with exclude-if-present
      (LP: #1620085)
  * d/p/backport-crash-on-restore.patch:
    - Guard a chown call to avoid a stacktrace (LP: #1642813)
  * d/p/backport-ignore-excluded-locked-files.patch:
    - Ignore excluded locked files rather than giving noisy errors
      (LP: #1089131)
  * d/p/backport-downgrade-error.patch:
    - Make locked file messages be warnings not errors, again. This avoids
      confusing deja-dup. (LP: #1605939)
  * d/p/backport-flush-after-write.patch:
    - Flush after writing a temp file, to keep disk in sync (LP: #1538333)
  * d/p/backport-gpg2.patch:
    - Improve support for gpg2 (fixing FTBFS in process)

 -- Michael Terry <email address hidden> Tue, 07 Mar 2017 18:48:01 -0500

Changed in duplicity (Ubuntu Zesty):
status: Triaged → Fix Released
Revision history for this message
Michael Terry (mterry) wrote :

The fix for this got reverted in duplicity (due to bug 1570293). Should this be re-opened?

Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

Reopening

Changed in duplicity:
assignee: nobody → Michael Terry (mterry)
milestone: 0.7.07 → 0.7.13
status: Fix Released → In Progress
Michael Terry (mterry)
Changed in duplicity (Ubuntu):
status: Fix Released → New
Michael Terry (mterry)
Changed in duplicity:
assignee: Michael Terry (mterry) → nobody
Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

This bug was fixed in 0.7.07.1. I cannot reproduce.

Changed in duplicity:
status: In Progress → Won't Fix
status: Won't Fix → New
milestone: 0.7.13 → none
Revision history for this message
Stefano Rago (stefano-rago) wrote :

I am still experiencing this issue with duplicity 0.7.12 on Ubuntu 15.04.

A previous backup terminated abnormally with this message:

"""
Giving up after 5 attempts. MemoryError:
"""

Any subsequent attempt to backup returns the AssertionError above.

Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Changed in duplicity (Ubuntu):
status: New → Confirmed
Changed in duplicity:
importance: Medium → High
Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

I have been unable to reproduce this in testing. If you encounter this error, please provide the following:

1) full command line
2) full unencrypted manifest file (attached as a file)
3) detailed (ls -l style) listing of the remote system (attached as a file)
4) as much of the logging as possible, especially the first 200 lines and last 200 lines at -v9 level (attached as a file)

NOTE: Comment #5 references a memory error. This is a different bug that we're working on.

Changed in duplicity:
milestone: none → 0.7.14
status: New → Incomplete
Revision history for this message
Tomek Korek (cytadela8) wrote :

I encountered this error today. Here is the data requested.

1) duplicity cleanup -v9 --force 'sftp://__MY_SERVER__/__MY_FOLDER__' 2&>1 > logfile1
2) 'duplicity-inc.20170609T192036Z.to.20170620T202313Z.manifest.part' the file causing problems
3) 'filelist' got with command echo "ls -la ." | sftp -q "__MY_SERVER__:/__MY_FOLDER__'" > filelist
4) 'logfile1' result of 1)

I can only add one attachment so I zipped everything.
I get the same exception also when I try to recover an folder.

Changed in duplicity:
assignee: nobody → Kenneth Loafman (kenneth-loafman)
status: Incomplete → In Progress
Revision history for this message
Kenneth Loafman (kenneth-loafman) wrote :

* Fixed bug #1538333 Assertion error in manifest.py: assert filecount == ...
  - Made sure to never pass .part files as true manifest files
  - Changed assert to log.Error to warn about truncated/corrupt filelist
  - Added unit test to make sure detection works
  - Note: while this condition is serious, it will not affect the basic backup and restore
    functions. Interactive options like --list-files-changed and --file-changed will not
    work correctly for this backup set, so it is advised to run a full backup as soon as
    possible after this error occurs.

Changed in duplicity:
assignee: Kenneth Loafman (kenneth-loafman) → nobody
status: In Progress → Fix Committed
Changed in duplicity:
status: Fix Committed → Fix Released
Revision history for this message
Niklas Sombert (ytvwld) wrote :

I've just experienced this bug on Zesty with duplicity 0.7.06-2ubuntu3.

I was doing a full backup when the underlying filesystem disappeared (partly my fault).
I remounted it and trying to resume the backup, but duplicity won't start with
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 829, in add_to_sets
    if new_set.add_filename(filename):
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 101, in add_filename
    self.set_manifest(filename)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 149, in set_manifest
    self.set_files_changed()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 128, in set_files_changed
    mf = self.get_manifest()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 250, in get_manifest
    return self.get_local_manifest()
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 225, in get_local_manifest
    return manifest.Manifest().from_string(manifest_buffer)
  File "/usr/lib/python2.7/dist-packages/duplicity/manifest.py", line 207, in from_string
    assert filecount == len(self.files_changed)
AssertionError

This bug is marked as fixed but I haven't seen an update for Zesty. Did I miss something?

Revision history for this message
darthvader (sarmbruster) wrote :

I was able to recover from this situation by doing a `rm -rf ~/.config/duplicity/duply_<jobname>`

Changed in duplicity (Ubuntu):
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.