Duplicity

duplicity does not end or print summary

Asked by M Yudkowsky

I've run duplicity and created an approximately 2 TB backup, unencrypted. I ran this backup in verbose (8) mode, and I've watched as each time has been added.

The very last file under my root directory is shown as added, the line "AsyncScheduler: task completed successfully" and the line
"Processed volume XXX" prints, but the application has not terminated and has not printed out the final summary.

Looking at the backup data, e.g., duplicity-full-signatures.20160818T005511Z.sigtar.gz, I see that the file has not changed in the past 3 hours.

Now, this was a rather long haul in the sense that it took 2 days to complete; I ran this at ionice -c 3 in order to leave my machine usable in the meantime.

"ps" shows this duplicity still running at nearly 100% of one CPU. However, there's been no level 8 debug printout in 3 hours.

So:

a) Is this normal for duplicity?
b) If this is normal, how long should I expect to wait to see the final printout and exit from duplicity?
c) If this is _not_ normal, what are good recovery steps?

In the spirit of full disclosure, I used:

ionice -c 3 \
 duplicity \
  --no-encryption \
  -v8 \
  --exclude=/tmp --exclude=/backup --exclude=/proc \
  --exclude=/run --exclude=/dev --exclude=/sys \
  --exclude-device-files \
  --exclude=/media --exclude=/pc \
  --exclude=/backup/duplicity-data \
  --exclude=/cdrom --exclude=/mnt \
  --archive-dir=/backup/duplicity-data \
  --name=foo \
  / file:///backup

(I don't know if it's good practice or not but I put the archive-dir onto the same drive I'm using to back up. )

Question information

Language:
English Edit question
Status:
Solved
For:
Duplicity Edit question
Assignee:
No assignee Edit question
Solved by:
edso
Solved:
Last query:
Last reply:
Revision history for this message
M Yudkowsky (myudkowsky) said : 		#1

After about another hour or so of nothing happening, the printout displayed -- showing an end time four hours previous to the actual time.

On the one hand I'm happy that the program ran to completion, but I still consider this a bug of some nature.

Revision history for this message
Best edso (ed.so) said : 		#2

On 24.08.2016 02:32, M Yudkowsky wrote:
> Question #360622 on Duplicity changed:
> https://answers.launchpad.net/duplicity/+question/360622
>
> M Yudkowsky gave more information on the question:
> After about another hour or so of nothing happening, the printout
> displayed -- showing an end time four hours previous to the actual time.
>
> On the one hand I'm happy that the program ran to completion, but I
> still consider this a bug of some nature.
>

what's the size of the manifest/signature file in the target? they're probably quite huge for 2TB of data. it's probably the creation of those what's taking so long after the backup itself is kind of finished already.

can you try the latest release 0.7.10 and see if you can replicate the behaviour?

..ede/duply.net

Revision history for this message
M Yudkowsky (myudkowsky) said : 		#3

edso, thanks for your response.

1) I'm currently using duplicity 0.7.07.1. I will see if I can get 0.7.10 up and running.

2) The manifest/signature file is quite large; 11 GB to cover the 2.5 million files backed up:

-rw------- 1 root root 226M Aug 23 14:26 duplicity-full.20160818T005511Z.manifest
-rw------- 1 root root 11G Aug 23 14:26 duplicity-full-signatures.20160818T005511Z.sigtar.gz

However, note the timestamp on the files. The last write was at 14:26, but the program did not print a summary and exit until about 3 hours later. I'd theorized that the system was performing some final action on the file, and watched the timestamps, but nothing happened.

Perhaps some sanity check was in progress, one that read but did not write to these files? That came to mind, but -v8 did not print any such information.

Revision history for this message
M Yudkowsky (myudkowsky) said : 		#4

There will be a break of several days before I can get 0.7.10 up and running.

I ran an incremental backup. This started at approximately 18:00. This ran unattended overnight. The final information printout said:
StartTime 1472308401.92 (Sat Aug 27 09:33:21 2016)
EndTime 1472311275.63 (Sat Aug 27 10:21:15 2016)
ElapsedTime 2873.71 (47 minutes 53.71 seconds)
SourceFiles 2542209
SourceFileSize 1619702666108 (1.47 TB)
NewFiles 31230
NewFileSize 4206962937 (3.92 GB)
DeletedFiles 13842
ChangedFiles 3069
ChangedFileSize 3895294703 (3.63 GB)
ChangedDeltaSize 0 (0 bytes)
DeltaEntries 48141
RawDeltaSize 5043334722 (4.70 GB)
TotalDestinationSizeChange 4402852745 (4.10 GB)
Errors 0

That is, despite starting to run at 18:00, the backup claims to have run starting at 09:00 the next day, 15 hours later. For a substantial amount of time, over an hour until I had to leave this to run unattended, the only notation I saw was "deleting /tmp/<xxxx>."

 Again, I'll try 0.7.10 sometime soon.

Revision history for this message
M Yudkowsky (myudkowsky) said : 		#5

Duplicity version 0.7.10 seems to work correctly: an incremental backup of 2 TB or so took only 45 minutes, the reported time at the end was consistent with the actual elapsed time, and there was no long delay between the start of backup and the actual backup:

--------------[ Backup Statistics ]--------------
StartTime 1472614338.31 (Tue Aug 30 22:32:18 2016)
EndTime 1472617196.93 (Tue Aug 30 23:19:56 2016)
ElapsedTime 2858.62 (47 minutes 38.62 seconds)
SourceFiles 2545113
SourceFileSize 1621527065311 (1.47 TB)
NewFiles 8624
NewFileSize 1969806872 (1.83 GB)
DeletedFiles 5495
ChangedFiles 1581
ChangedFileSize 2000088202 (1.86 GB)
ChangedDeltaSize 0 (0 bytes)
DeltaEntries 15700
RawDeltaSize 2285541841 (2.13 GB)
TotalDestinationSizeChange 2106922313 (1.96 GB)
Errors 0
-------------------------------------------------

whereas "time" measured:

real 48m55.791s
user 29m15.624s
sys 1m50.220s

edso, thanks again for your help. I'm marking this as solved.

Revision history for this message
M Yudkowsky (myudkowsky) said : 		#6

Thanks edso, that solved my question.

Revision history for this message
edso (ed.so) said : 		#7

pleasure mate! please keep an eye on the next full, just in case there is still something fishy only when doing fulls.

..ede/duply.net