Fails "silently" trying to restore an Amazon S3 backup without clock in sync

[Rodrigo Campos]

Hi!

I just find out that trying to restore a backup from Amazon S3 in a PC that doesn't have the clock in sync, fails. The error it is not very descriptive of the situation. The error is the following:

(ommited the S3 bucket)

$ duplicity restore --s3-use-new-style -v9 --num-retries 5 's3+http://<my-bucket>/<path>' retore
Using archive dir: /home/rata/.cache/duplicity/ca450b9de1f3f3afff546aee88a75d8c
Using backup name: ca450b9de1f3f3afff546aee88a75d8c
Import of duplicity.backends.ftpbackend Succeeded
Import of duplicity.backends.tahoebackend Succeeded
Import of duplicity.backends.imapbackend Succeeded
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.webdavbackend Succeeded
Import of duplicity.backends.u1backend Succeeded
Import of duplicity.backends.sshbackend Succeeded
Import of duplicity.backends.cloudfilesbackend Succeeded
Import of duplicity.backends.hsibackend Succeeded
Import of duplicity.backends.botobackend Succeeded
Import of duplicity.backends.giobackend Succeeded
Import of duplicity.backends.ftpsbackend Succeeded
Import of duplicity.backends.localbackend Succeeded
Import of duplicity.backends.gdocsbackend Succeeded
Main action: restore
================================================================================
duplicity 0.6.18 (February 29, 2012)
Args: /usr/bin/duplicity restore --s3-use-new-style -v9 --num-retries 5 s3+http://<my-bucket>/<path> retore
Linux lindsay 3.2.0-2-amd64 #1 SMP Sun Apr 15 16:47:38 UTC 2012 x86_64
/usr/bin/python 2.7.2+ (default, Nov 30 2011, 19:22:03)
[GCC 4.6.2]
================================================================================
Using temporary directory /tmp/duplicity-1gR6jJ-tempdir
Registering (mkstemp) temporary file /tmp/duplicity-1gR6jJ-tempdir/mkstemp-nElTiF-1
Temp has 75120640 available, backup will use approx 34078720.
Local and Remote metadata are synchronized, no sync needed.
0 files exist on backend
0 files exist in cache
Extracting backup chains from list of files: []
Last full backup date: none
Collection Status
-----------------
Connecting with backend: BotoBackend
Archive dir: /home/rata/.cache/duplicity/ca450b9de1f3f3afff546aee88a75d8c

Found 0 secondary backup chains.
No backup chains with active signatures found
No orphaned or incomplete backup sets found.
PASSPHRASE variable not set, asking user.
GnuPG passphrase:
Removing still remembered temporary file /tmp/duplicity-1gR6jJ-tempdir/mkstemp-nElTiF-1
Traceback (most recent call last):
  File "/usr/bin/duplicity", line 1404, in <module>
    with_tempdir(main)
  File "/usr/bin/duplicity", line 1397, in with_tempdir
    fn()
  File "/usr/bin/duplicity", line 1331, in main
    restore(col_stats)
  File "/usr/bin/duplicity", line 625, in restore
    restore_get_patched_rop_iter(col_stats)):
  File "/usr/bin/duplicity", line 647, in restore_get_patched_rop_iter
    backup_chain = col_stats.get_backup_chain_at_time(time)
  File "/usr/lib/python2.7/dist-packages/duplicity/collections.py", line 947, in get_backup_chain_at_time
    raise CollectionsError("No backup chains found")
CollectionsError: No backup chains found

When running collection-status, it also shows a not very clear error:

$ duplicity collection-status --s3-use-new-style -v9 --num-retries 5 's3+http://<my-bucket>/<path>'
Using archive dir: /home/rata/.cache/duplicity/ca450b9de1f3f3afff546aee88a75d8c
Using backup name: ca450b9de1f3f3afff546aee88a75d8c
Import of duplicity.backends.ftpbackend Succeeded
Import of duplicity.backends.tahoebackend Succeeded
Import of duplicity.backends.imapbackend Succeeded
Import of duplicity.backends.rsyncbackend Succeeded
Import of duplicity.backends.webdavbackend Succeeded
Import of duplicity.backends.u1backend Succeeded
Import of duplicity.backends.sshbackend Succeeded
Import of duplicity.backends.cloudfilesbackend Succeeded
Import of duplicity.backends.hsibackend Succeeded
Import of duplicity.backends.botobackend Succeeded
Import of duplicity.backends.giobackend Succeeded
Import of duplicity.backends.ftpsbackend Succeeded
Import of duplicity.backends.localbackend Succeeded
Import of duplicity.backends.gdocsbackend Succeeded
Main action: collection-status
================================================================================
duplicity 0.6.18 (February 29, 2012)
Args: /usr/bin/duplicity collection-status --s3-use-new-style -v9 --num-retries 5 s3+http://<my-bucket>/<path>
Linux lindsay 3.2.0-2-amd64 #1 SMP Sun Apr 15 16:47:38 UTC 2012 x86_64
/usr/bin/python 2.7.2+ (default, Nov 30 2011, 19:22:03)
[GCC 4.6.2]
================================================================================
Local and Remote metadata are synchronized, no sync needed.
0 files exist on backend
0 files exist in cache
Extracting backup chains from list of files: []
Last full backup date: none
Collection Status
-----------------
Connecting with backend: BotoBackend
Archive dir: /home/rata/.cache/duplicity/ca450b9de1f3f3afff546aee88a75d8c

Found 0 secondary backup chains.
No backup chains with active signatures found
No orphaned or incomplete backup sets found.
Collection Status
-----------------
Connecting with backend: BotoBackend
Archive dir: /home/rata/.cache/duplicity/ca450b9de1f3f3afff546aee88a75d8c

Found 0 secondary backup chains.
No backup chains with active signatures found
No orphaned or incomplete backup sets found.
Using temporary directory /tmp/duplicity-zHyz8c-tempdir

It really took me a while to realize what was happening here. I realized when trying to use this PC (with clock not in sync) to backup a new file and test a basic backup on Amazon S3 of an unimportant file that it trow this error (with verbose):

$ duplicity --s3-use-new-style -v9 --num-retries 5 bkp-dir/ 's3+http://<my-bucket>/test1'

(quoted the relevant part only, the output its really big. I can attach it if you need it)

AsyncScheduler: running task synchronously (asynchronicity disabled)
Failed to create bucket (attempt #1) '<my-bucket>' failed (reason: S3ResponseError: S3ResponseError: 403 Forbidden
<?xml version="1.0" encoding="UTF-8"?>
<Error><Code>RequestTimeTooSkewed</Code><Message>The difference between the request time and the current time is too large.</Message><MaxAllowedSkewMilliseconds>900000</MaxAllowedSkewMilliseconds><RequestId>BA793C6067E73366</RequestId><HostId>GXaz1ADuulZqpYxrS23487mnGxtfzr2Q0vsKje8LKJlCnWnQJuZcfyp95yZR2Vq2</HostId><RequestTime>Wed, 23 May 2012 16:13:56 GMT</RequestTime><ServerTime>2012-05-23T19:13:29Z</ServerTime></Error>)

Also, I can consistently reproduce this: if my clock is not in sync, then this error is shown, if I put it in sync, it works okay.
Btw, to change the clock I used: "date -s <some not in sync date>; hwclock -s". And to get back in sync: "ntpdate-debian" (that is a debian specific command, but ubuntu I think it has it and running ntpdate with appropriate parameters will do the trick too)

It would be really nice if the error shown when trying to restore a backup is nicer and properly tells whats is wrong. It really took me a while to understand the cause =) Perhaps even showing this very same (not nice, but clear) error that is shown when you try to create a backup. But really the trace and "No backup chains found" doesn't say anything to me :S

Please let me know if you need more information or I can help you to test some patch

Thanks a lot,
Rodrigo

[Rodrigo Campos (rodrigocc)]

Ping ?

[Rodrigo Campos (rodrigocc)]

Will a patch documenting this somewhere be accepted ?

[Kenneth Loafman (kenneth-loafman)]

Yes, of course. As long as it does not break things.

Why not just keep the clock in sync?

...Ken

On Mon, Jun 11, 2012 at 10:38 AM, Rodrigo Campos <email address hidden>wrote:

> Will a patch documenting this somewhere be accepted ?
>
> --
> You received this bug notification because you are subscribed to
> Duplicity.
> https://bugs.launchpad.net/bugs/1003615
>
> Title:
> Fails "silently" trying to restore an Amazon S3 backup without clock
> in sync
>
> Status in Duplicity - Bandwidth Efficient Encrypted Backup:
> New
>
> Bug description:
> Hi!
>
> I just find out that trying to restore a backup from Amazon S3 in a PC
> that doesn't have the clock in sync, fails. The error it is not very
> descriptive of the situation. The error is the following:
>
> (ommited the S3 bucket)
>
>
> $ duplicity restore --s3-use-new-style -v9 --num-retries 5 's3+http://<my-bucket>/<path>'
> retore
> Using archive dir:
> /home/rata/.cache/duplicity/ca450b9de1f3f3afff546aee88a75d8c
> Using backup name: ca450b9de1f3f3afff546aee88a75d8c
> Import of duplicity.backends.ftpbackend Succeeded
> Import of duplicity.backends.tahoebackend Succeeded
> Import of duplicity.backends.imapbackend Succeeded
> Import of duplicity.backends.rsyncbackend Succeeded
> Import of duplicity.backends.webdavbackend Succeeded
> Import of duplicity.backends.u1backend Succeeded
> Import of duplicity.backends.sshbackend Succeeded
> Import of duplicity.backends.cloudfilesbackend Succeeded
> Import of duplicity.backends.hsibackend Succeeded
> Import of duplicity.backends.botobackend Succeeded
> Import of duplicity.backends.giobackend Succeeded
> Import of duplicity.backends.ftpsbackend Succeeded
> Import of duplicity.backends.localbackend Succeeded
> Import of duplicity.backends.gdocsbackend Succeeded
> Main action: restore
>
> ================================================================================
> duplicity 0.6.18 (February 29, 2012)
> Args: /usr/bin/duplicity restore --s3-use-new-style -v9 --num-retries 5
> s3+http://<my-bucket>/<path> retore
> Linux lindsay 3.2.0-2-amd64 #1 SMP Sun Apr 15 16:47:38 UTC 2012 x86_64
> /usr/bin/python 2.7.2+ (default, Nov 30 2011, 19:22:03)
> [GCC 4.6.2]
>
> ================================================================================
> Using temporary directory /tmp/duplicity-1gR6jJ-tempdir
> Registering (mkstemp) temporary file
> /tmp/duplicity-1gR6jJ-tempdir/mkstemp-nElTiF-1
> Temp has 75120640 available, backup will use approx 34078720.
> Local and Remote metadata are synchronized, no sync needed.
> 0 files exist on backend
> 0 files exist in cache
> Extracting backup chains from list of files: []
> Last full backup date: none
> Collection Status
> -----------------
> Connecting with backend: BotoBackend
> Archive dir: /home/rata/.cache/duplicity/ca450b9de1f3f3afff546aee88a75d8c
>
> Found 0 secondary backup chains.
> No backup chains with active signatures found
> No orphaned or incomplete backup sets found.
> PASSPHRASE variable not set, asking user.
> GnuPG passphrase:
> Removing still remembered temporary file
> /tmp/duplicity-1gR6jJ-tempdir/mkstemp-nElTiF-1
> Traceback (most recent call l...

[Rodrigo Campos (rodrigocc)]

On Mon, Jun 11, 2012 at 03:48:32PM -0000, Kenneth Loafman wrote:
> Yes, of course. As long as it does not break things.

I mean at least on the manpage

>
> Why not just keep the clock in sync?

It was not on purpose. It was a recently installed machine and the installer
didn't put the clock in sync. I spent lot of time till I realize about it, and
I think perhaps giving a proper error o documenting it could save others some
time =)

Now I realize the clock wasn't in sync on the machine, I keep it in sync and all
works okay =)

Thanks a lot,
Rodrigo

[david rufino (david-rufino)]

Better error propagation from the backend would be much appreciated!

Thanks,
David