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

[Laurynas Biveinis]

> On 04.09.2012 16:03, Laurynas Biveinis wrote:
>> 2012/9/4  <address@hidden>:
>>> 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.
>>
>> Thanks. Something does not add up here. The restore script does
>> export TMPDIR=/media/Sandėlys/tmp
>>
>> and the output of duplicity has
>>
>> Using temporary directory /media/Sandėlys/tmp/duplicity-qD6e4q-tempdir
>> Registering (mkstemp) temporary file
>> /media/Sandėlys/tmp/duplicity-qD6e4q-tempdir/mkstemp-HzlUlf-1
>> Temp has 261955923968 available, backup will use approx 34078720.
>>
>> Could it be that TMPDIR is ignored somewhere?
>>

> find out which data on /home/laurynas fills it up. you are right the output 
> above suggests it uses the big partition (/media/Sande.lys) but obviously the 
> other one fills up.

So I might have found something useful: I started duplicity with
strace. Then I did lsof while it's in progress and got one open handle
outside the /media/Sandėlys:

duplicity 31759 laurynas   44u   REG     8,1 529465344 15467022
/tmp/tmpfxLhqjk (deleted)

It is deleted and ever-growing. I looked for it in strace:

31759 stat("/tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=45056, ...}) = 0
31759 open("/tmp/tmpfxLhqjk", O_RDWR|O_CREAT|O_EXCL, 0600) = 44
31759 unlink("/tmp/tmpfxLhqjk")         = 0
31759 fcntl(44, F_GETFL)                = 0x8002 (flags O_RDWR|O_LARGEFILE)
31759 fstat(44, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0

First write contents suggests that this is going to be the final file:

31759 write(44, "<<< Oracle VM VirtualBox Disk Im"..., 65536 <unfinished ...>

Any idea or pointers?

Thanks,
-- 
Laurynas