Local cache deleted after full S3 backup when IAM sub-keys used

[Kenneth Loafman]

After performing a full encrypted backup to S3, subsequent duplicity operations cause the local cache for that backup to be deleted, preventing further manipulation or verification of the backup.

Using duplicity 0.6.08b from Debian squeeze (testing) with python-boto 1.2a-1 and python 2.5.2.

1. Background

I create a full backup using the following command (and AWS credentials exported as env variables):

    duplicity incr \
        --asynchronous-upload \
        --s3-european-buckets \
        --s3-use-new-style \
        --full-if-older-than=3M \
        --volsize=50 \
        --encrypt-key=MYKEYHERE \
        --sign-key=MYKEYHERE \
        --tempdir=/var/tmp \
        --include="/backup/a/path/with spaces/in" \
        --exclude=/** \
        / "s3+http://my-bucket-name"

The command completes successfully with the following output:

Local and Remote metadata are synchronized, no sync needed.
Last full backup date: none
No old backup sets found, nothing deleted.
Local and Remote metadata are synchronized, no sync needed.
Last full backup date: none
Last full backup is too old, forcing full backup
--------------[ Backup Statistics ]--------------
StartTime 1270996918.40 (Sun Apr 11 15:41:58 2010)
EndTime 1270996920.95 (Sun Apr 11 15:42:00 2010)
ElapsedTime 2.55 (2.55 seconds)
SourceFiles 30
SourceFileSize 2181326 (2.08 MB)
NewFiles 30
NewFileSize 2181326 (2.08 MB)
DeletedFiles 0
ChangedFiles 0
ChangedFileSize 0 (0 bytes)
ChangedDeltaSize 0 (0 bytes)
DeltaEntries 30
RawDeltaSize 2152654 (2.05 MB)
TotalDestinationSizeChange 1850097 (1.76 MB)
Errors 0
-------------------------------------------------

Expected files are available in the destination S3 bucket.

sigtar and manifest files are created in the ~/.cache/duplicity/[hash]/ directory.

The manifest only appears to include only 1 file out of 30, though the local manifest does match the remote (encrypted) manifest exactly.

Similarly the local and remote sigtar files match once gunzip'ed and decrypted respectively.

2. Problem

I then run a verify on my newly-created backup using the following command (again with AWS credentials exported first):

    duplicity verify \
        --encrypt-key=MYKEYHERE \
        --sign-key=MYKEYHERE \
        --tempdir=/var/tmp \
        "s3+http://my-bucket-name" /

I then get this output from duplicity:

Synchronizing remote metadata to local cache...
Deleting local /root/.cache/duplicity/96e3afbc9cfaced5608c3540469d2d09/duplicity-full-signatures.20100411T144157Z.sigtar.gz (not authoritative at backend).
Deleting local /root/.cache/duplicity/96e3afbc9cfaced5608c3540469d2d09/duplicity-full.20100411T144157Z.manifest (not authoritative at backend).
Last full backup date: none
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1251, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1244, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1200, in main
    verify(col_stats)
  File "/usr/bin/duplicity", line 653, in verify
    collated = diffdir.collate2iters(restore_get_patched_rop_iter(col_stats),
  File "/usr/bin/duplicity", line 560, in restore_get_patched_rop_iter
    backup_chain = col_stats.get_backup_chain_at_time(time)
  File "/usr/lib/python2.5/site-packages/duplicity/collections.py", line 934, in get_backup_chain_at_time
    raise CollectionsError("No backup chains found")
CollectionsError: No backup chains found

ERROR:duplicity:Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1251, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1244, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1200, in main
    verify(col_stats)
  File "/usr/bin/duplicity", line 653, in verify
    collated = diffdir.collate2iters(restore_get_patched_rop_iter(col_stats),
  File "/usr/bin/duplicity", line 560, in restore_get_patched_rop_iter
    backup_chain = col_stats.get_backup_chain_at_time(time)
  File "/usr/lib/python2.5/site-packages/duplicity/collections.py", line 934, in get_backup_chain_at_time
    raise CollectionsError("No backup chains found")
CollectionsError: No backup chains found

My local cache is deleted at the beginning of the process and duplicity is then unable to verify the backup.

Repopulating the cache manually (decrypting and gzip'ing the manifest and sigtar as appropriate) and then rerunning the verify operation deletes the cache again.

Carrying out the same steps (full backup then verify) using a local file:// backend rather than S3 works okay.

Any thoughts on where I might be going wrong?

Cheers,

Jock

[Kenneth Loafman (kenneth-loafman)]

See also: https://answers.launchpad.net/duplicity/+question/107074

[Artur Ergashev (4-artur)]

I have an issue with similar circumstances which may be the same bug. Using an IAM sub-key on a backup that is approximately 1GB in size, a backup is done hourly and a full backup is done daily.

Yesterday the backup stopped working. When looking at the log I noticed roughly 800 instances of:

NOTICE 1
. Deleting local /opt/cache/mysql/duplicity-inc.20120704T004130Z.to.20120704T014124Z.manifest (not authoritative at backend).

Subsequent runs required a decryption key (which is NOT present on my backup machine), I was able to resolve the problem by pulling the deleted cache files from S3, decrypting them on a secure machine and putting them back on the backup machine. This seemed to resolve the immediate problem, I will continue monitoring for the cache getting cleared.