[Duplicity-talk] Restore fails: duplicity-full.* files 0 bytes

[Mogliii]

Hi,

I posted a similar message to gmane more than 4 hours ago... so sorry if
it gets posted twice:

I have a vserver with ubuntu 8.04 and duplicity 0.6.08. I am using a
nightly cron job to do a duplicity backup onto a ftp server running in
my home (dynamic ip, dyndns name resolution, public key encryption).
Every 1st a full backup is done. After 6 months old backups get deleted.

First off: The server is running, so I am NOT dependent on this restore.
But with all the trouble amazon has in Ireland I thought I try if I
COULD restore a backup.


%%%%%%

I have all the duplicity files locally. Restore to 1st of August fails.
The restore command I use is:
$ sudo duplicity -v9 -t 2011-08-02 --file-to-restore / file://. restore/

I get the following error:
@@@@@@@@
[clip]
Forgetting temporary file /tmp/duplicity-756SMd-tempdir/mktemp-2uJUW8-298
Processed volume 68 of 80
Registering (mktemp) temporary file
/tmp/duplicity-756SMd-tempdir/mktemp-E0BFfa-299
Invalid data - SHA1 hash mismatch:
Calculated hash: da39a3ee5e6b4b0d3255bfef95601890afd80709
Manifest hash: 957348ebe196b962b8941f7bc7f44c26ade77115

Removing still remembered temporary file
/tmp/duplicity-756SMd-tempdir/mktemp-E0BFfa-299
[clip]
@@@@@@@

I had a look into the directory and found that vol69 has a size of 0 bytes.




So I checked the logs I make on the server and found these two passages:

@@@@@@@
[clip]
Mon Aug 1 03:30:02 CEST 2011
starting backup
NcFTP version is 3.2.1
Reading globbing filelist duplicity.exclude
Local and Remote metadata are synchronized, no sync needed.
Last full backup date: Fri Jul  1 03:30:09 2011
Remote write timed out.
Could not read reply from control connection -- timed out.
ncftpput 16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg:
data transfer timed out.
Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #1)
Could not read reply from control connection -- timed out.
ncftpput 16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg:
timed out while waiting for server response.
Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #2)
Could not read reply from control connection -- timed out.
ncftpput 16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg:
timed out while waiting for server response.
Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #3)
Could not read reply from control connection -- timed out.
ncftpput 16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg:
timed out while waiting for server response.
Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #4)
Could not read reply from control connection -- timed out.
ncftpput 16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg:
timed out while waiting for server response.
Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #5)
Giving up trying to execute 'ncftpput -f
/tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F -t 30 -o
useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' after 5
attempts
BackendException: Error running 'ncftpput -f
/tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F -t 30 -o
useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg''
NcFTP version is 3.2.1
Local and Remote metadata are synchronized, no sync needed.
Last full backup date: Mon Aug  1 03:30:05 2011
No old backup sets found, nothing deleted.
######### backup finished
Mon Aug 1 05:49:52 CEST 2011
Tue Aug 2 03:30:03 CEST 2011
starting backup
NcFTP version is 3.2.1
Reading globbing filelist duplicity.exclude
Local and Remote metadata are synchronized, no sync needed.
Last full backup left a partial set, restarting.
Last full backup date: Mon Aug  1 03:30:05 2011
Restarting after volume 69, file
var/www/opengoo16b_bak/tmp/fengoffice_1.7.zip, block 66
--------------[ Backup Statistics ]--------------
StartTime 1312248625.69 (Tue Aug  2 03:30:25 2011)
EndTime 1312249986.50 (Tue Aug  2 03:53:06 2011)
ElapsedTime 1360.81 (22 minutes 40.81 seconds)
SourceFiles 95581
SourceFileSize 3115011946 (2.90 GB)
NewFiles 95581
NewFileSize 3115011946 (2.90 GB)
DeletedFiles 0
ChangedFiles 0
ChangedFileSize 0 (0 bytes)
ChangedDeltaSize 0 (0 bytes)
DeltaEntries 95581
RawDeltaSize 3070142209 (2.86 GB)
TotalDestinationSizeChange 285135647 (272 MB)
Errors 0
-------------------------------------------------

NcFTP version is 3.2.1
Local and Remote metadata are synchronized, no sync needed.
Last full backup date: Mon Aug  1 03:30:05 2011
No old backup sets found, nothing deleted.
######### backup finished
Tue Aug 2 04:01:24 CEST 2011
[clip]
@@@@@@@


@@@@@@@
[clip]
NOTICE 1
. Last full backup date: Fri Jul  1 03:30:09 2011

NOTICE 1
. No old backup sets found, nothing deleted.

NOTICE 1
. NcFTP version is 3.2.1

NOTICE 1
. Reading globbing filelist duplicity.exclude

NOTICE 1
. Local and Remote metadata are synchronized, no sync needed.

NOTICE 1
. Last full backup date: Fri Jul  1 03:30:09 2011

WARNING 1
. Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #1)

WARNING 1
. Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #2)

WARNING 1
. Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #3)

WARNING 1
. Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #4)

WARNING 1
. Running 'ncftpput -f /tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F
-t 30 -o useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' failed
(attempt #5)

WARNING 1
. Giving up trying to execute 'ncftpput -f
/tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F -t 30 -o
useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg'' after 5
attempts

ERROR 23 BackendException
. BackendException: Error running 'ncftpput -f
/tmp/duplicity-OXk1uU-tempdir/mkstemp-Cp3QDw-1 -F -t 30 -o
useCLNT=0,useHELP_SITE=0  -P '59999' -m -V -C
'/tmp/duplicity-OXk1uU-tempdir/mktemp-MqlQUI-71'
'16G/****/duplicity-full.20110801T013005Z.vol69.difftar.gpg''

NOTICE 1
. NcFTP version is 3.2.1

NOTICE 1
. Local and Remote metadata are synchronized, no sync needed.

NOTICE 1
. Last full backup date: Mon Aug  1 03:30:05 2011

NOTICE 1
. No old backup sets found, nothing deleted.

NOTICE 1
. NcFTP version is 3.2.1

NOTICE 1
. Reading globbing filelist duplicity.exclude

NOTICE 1
. Local and Remote metadata are synchronized, no sync needed.

NOTICE 1
. Last full backup left a partial set, restarting.

NOTICE 1
. Last full backup date: Mon Aug  1 03:30:05 2011

NOTICE 1
. Restarting after volume 69, file
var/www/opengoo16b_bak/tmp/fengoffice_1.7.zip, block 66

NOTICE 1
. NcFTP version is 3.2.1

NOTICE 1
. Local and Remote metadata are synchronized, no sync needed.

NOTICE 1
. Last full backup date: Mon Aug  1 03:30:05 2011

NOTICE 1
. No old backup sets found, nothing deleted.

NOTICE 1
. NcFTP version is 3.2.1
[clip]
@@@@@@@


So I understand there was a network problem to write file 69 to the ftp
server. And when duplicity ran again on the 2nd August, it noticed that
the last backup failed and continues. But restore fails.

Is this a (know) bug? Did I do something wrong?
I can hardly rely on 100% uptime of the ftp server.

I also noticed that for the July full backup there are two empty
duplicity-full.* files with similar entries in the logs.