Re: [Duplicity-talk] Out of space error while restoring a file

[edgar . soldin]

On 04.09.2012 10:00, Laurynas Biveinis wrote:
> Hi -
> 
>>>>>>>>> I'm trying to restore a ~30GB file from backups. The free space on the
>>>>>>>>> drive is about 80GB. Yet on restore I get the error below. What would
>>>>>>>>> be causing this and how much free space do I actually need to restore?
>>>>>>>>>
>>>>>>>>> $ duplicity -t2D --file-to-restore "path/to/file"
>>>>>>>>> --s3-european-buckets --s3-use-new-style s3+http://foo $HOME/file
>>>>>>>>> Local and Remote metadata are synchronized, no sync needed.
>>>>>>>>> Warning, found the following orphaned backup file:
>>>>>>>>> [duplicity-inc.20120319T102409Z.to.20120320T010946Z.manifest.part]
>>>>>>>>> Last full backup date: Thu Aug 16 00:00:27 2012
>>>>>>>>> Traceback (most recent call last):
>>>>>>>>>   File "/usr/bin/duplicity", line 1403, in <module>
>>>>>>>>>     with_tempdir(main)
>>>>>>>>>   File "/usr/bin/duplicity", line 1396, in with_tempdir
>>>>>>>>>     fn()
>>>>>>>>>   File "/usr/bin/duplicity", line 1330, in main
>>>>>>>>>     restore(col_stats)
>>>>>>>>>   File "/usr/bin/duplicity", line 623, in restore
>>>>>>>>>     restore_get_patched_rop_iter(col_stats)):
>>>>>>>>>   File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
>>>>>>>>> 522, in Write_ROPaths
>>>>>>>>>     for ropath in rop_iter:
>>>>>>>>>   File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
>>>>>>>>> 495, in integrate_patch_iters
>>>>>>>>>     final_ropath = patch_seq2ropath( normalize_ps( patch_seq ) )
>>>>>>>>>   File "/usr/lib/python2.7/dist-packages/duplicity/patchdir.py", line
>>>>>>>>> 475, in patch_seq2ropath
>>>>>>>>>     misc.copyfileobj( current_file, tempfp )
>>>>>>>>>   File "/usr/lib/python2.7/dist-packages/duplicity/misc.py", line 170,
>>>>>>>>> in copyfileobj
>>>>>>>>>     outfp.write(buf)
>>>>>>>>> IOError: [Errno 28] No space left on device
>>>>>>>>>
>>>>>>>>> The backup chain looks as follows
>>>>>>>>>
>>>>>>>>> Chain start time: Thu Aug 16 00:00:27 2012
>>>>>>>>> Chain end time: Thu Aug 30 00:00:23 2012
>>>>>>>>> Number of contained backup sets: 12
>>>>>>>>> Total number of contained volumes: 3477
>>>>>>>>>  Type of backup set:                            Time:      Num 
>>>>>>>>> volumes:
>>>>>>>>>                 Full         Thu Aug 16 00:00:27 2012              
>>>>>>>>> 2916
>>>>>>>>>          Incremental         Sun Aug 19 00:00:25 2012                
>>>>>>>>> 96
>>>>>>>>>          Incremental         Mon Aug 20 00:00:28 2012                
>>>>>>>>> 33
>>>>>>>>>          Incremental         Tue Aug 21 00:00:30 2012                
>>>>>>>>> 37
>>>>>>>>>          Incremental         Wed Aug 22 00:00:25 2012                
>>>>>>>>> 58
>>>>>>>>>          Incremental         Thu Aug 23 00:00:30 2012                
>>>>>>>>> 62
>>>>>>>>>          Incremental         Fri Aug 24 00:00:31 2012                
>>>>>>>>> 32
>>>>>>>>>          Incremental         Sat Aug 25 00:00:26 2012                
>>>>>>>>> 81
>>>>>>>>>          Incremental         Sun Aug 26 00:00:28 2012                
>>>>>>>>> 75
>>>>>>>>>          Incremental         Mon Aug 27 00:00:21 2012                 
>>>>>>>>> 8
>>>>>>>>>          Incremental         Tue Aug 28 00:00:18 2012                
>>>>>>>>> 21
>>>>>>>>>          Incremental         Thu Aug 30 00:00:23 2012                
>>>>>>>>> 58
>>>>>>>>>
>>>>>>>>> Duplicity is 0.6.18.
>>>>>>>>>
>>>>>>>>> Thanks in advance,
>>>>>>>>>
>>>>>>>>
>>>>>>>> you need 30GB (size of file to restore) plus the size of one volume in 
>>>>>>>> wherever TMP points to.
>>>>>>>
>>>>>>> Thanks. But I have only one partition, TMP is unset (if I understand
>>>>>>> correctly, then it defaults to /tmp), the volume size is default, so
>>>>>>> I'd need 30GB + 25MB, and I have 80GB free, but apparently that's not
>>>>>>> enough?
>>>>>>>
>>>>>>
>>>>>> should be... runthe restore with maximum verbosity '-v9' and post the 
>>>>>> complete output to pastebin (obfuscate private info in it) and send the 
>>>>>> link. maybe i'll see something.
>>>>>
>>>>> I'm attaching the compressed log. It's 2.5MB uncompressed, that's too
>>>>> big for pastebin. Please let me know if I should it send it in some
>>>>> other way.
>>>>>
>>>>>> you might want to monitor the disk usage during the restore. my guess 
>>>>>> would be that the final copy of 30GB fails. maybe duplicity keeps 
>>>>>> downloaded volumes in temp until finished?
>>>>>
>>>>> I got the "low disk space, 200MB remaining" warning on the volume
>>>>> which had 80GB free initially. Looking at the log file, I guess it's
>>>>> the initial downloading that fails. But why does it have to download
>>>>> so much?
>>>>>
>>>>> I will attach a volume with some 200GB free, point TMP to it, and
>>>>> restart the restore now.
>>>>
>>>> I have retried with TMP pointing to a volume with 244GB and the
>>>> restore sill fails, although slightly differently. I have attached the
>>>> compressed log.
>>>>
>>>
>>> can you verify that during the course of the restore
>>>  /media/Sandelys/tmp/duplicity-*-tempdir/
>>> fills up the containing file system?
>>>
>>> this is suggested by the debug output. trying to pinpoint your issue here.
>>>
>>>
>>
>> unlikely but possible.. could you check that
>>
>> - you have enough inodes free (df -i) also during the course of the restore
>> - the file systems are sane by fsck'ing them as a precaution action
> 
> Thanks for your help and suggestions.
> 
> The big volume is formatted with NTFS. It was probably never mounted
> in its native environment, so I fired a Windows VM to check it. And
> indeed there were a few errors, involving the restore process. The
> "lost+found" contained some downloaded volumes after the check:
> 
> $ ls found.000/dir0000.chk/
> duplicity-inc.20110830T210003Z.to.20110831T210003Z.vol4.difftar.gpg
> duplicity-inc.20110830T210003Z.to.20110831T210003Z.vol7.difftar.gpg
> duplicity-inc.20110830T210003Z.to.20110831T210003Z.vol5.difftar.gpg
> duplicity-new-signatures.20110830T210003Z.to.20110831T210003Z.sigtar.gpg
> duplicity-inc.20110830T210003Z.to.20110831T210003Z.vol6.difftar.gpg
> 
> After fixing the volume I repeated the restore, monitoring the free
> space and inodes by a script that does df -h df -i every 15 seconds.
> 
> The restore failed in the same way as before, the log is attached
> again. What's interesting is that according to the df the free space
> did not change at all: http://pastebin.com/PhanxQUX (it contains two
> partitions, originally it had only $TMP, I couldn't believe its
> result, so I added $HOME (same as /) too and retried).
> 

recheck your outputs, see below. around 09:16:58 /home/laurynas/.Private 
overflows. my guess is that duplicity TMP is located there. use the other 
partition as 80GB is obviously not enough.

..ede/duply.net

An Rgs  4 06:49:14 EEST 2012
Filesystem      Size  Used Avail Use% Mounted on
/dev/sdb1       932G  688G  244G  74% /media/Sande.lys
Filesystem        Inodes IUsed     IFree IUse% Mounted on
/dev/sdb1      255977324 81331 255895993    1% /media/Sande.lys
Filesystem               Size  Used Avail Use% Mounted on
/home/laurynas/.Private  272G  179G   80G  70% /home/laurynas
Filesystem                Inodes   IUsed    IFree IUse% Mounted on
/home/laurynas/.Private 17801216 1817647 15983569   11% /home/laurynas

An Rgs  4 09:16:58 EEST 2012
Filesystem      Size  Used Avail Use% Mounted on
/dev/sdb1       932G  688G  244G  74% /media/Sande.lys
Filesystem        Inodes IUsed     IFree IUse% Mounted on
/dev/sdb1      255721060 81373 255639687    1% /media/Sande.lys
Filesystem               Size  Used Avail Use% Mounted on
/home/laurynas/.Private  272G  258G  119M 100% /home/laurynas
Filesystem                Inodes   IUsed    IFree IUse% Mounted on
/home/laurynas/.Private 17801216 1817134 15984082   11% /home/laurynas

An Rgs  4 09:20:13 EEST 2012
Filesystem      Size  Used Avail Use% Mounted on
/dev/sdb1       932G  688G  244G  74% /media/Sande.lys
Filesystem        Inodes IUsed     IFree IUse% Mounted on
/dev/sdb1      255977016 81332 255895684    1% /media/Sande.lys
Filesystem               Size  Used Avail Use% Mounted on
/home/laurynas/.Private  272G  179G   80G  70% /home/laurynas
Filesystem                Inodes   IUsed    IFree IUse% Mounted on
/home/laurynas/.Private 17801216 1817217 15983999   11% /home/laurynas