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

[edgar . soldin]

On 17.09.2012 09:01, Laurynas Biveinis wrote:
> Hi!
> 
> 2012/9/11  <address@hidden>:
>> On 11.09.2012 15:25, address@hidden wrote:
>>> On 11.09.2012 07:22, Laurynas Biveinis wrote:
>>>> 2012/9/7  <address@hidden>:
>>>>> On 07.09.2012 07:42, Laurynas Biveinis wrote:
>>>>>> 2012/9/4 Laurynas Biveinis <address@hidden>:
>>>>>>> 2012/9/4  <address@hidden>:
>>>>>>>> On 04.09.2012 20:04, Laurynas Biveinis wrote:
>>>>>>>>>> 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?
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> try setting all 3 env vars..
>>>>>>>> http://duplicity.nongnu.org/duplicity.1.html#sect7
>>>>>>>> maybe it's a bug deep down, not respecting TMPDIR only
>>>>>>>
>>>>>>> export TEMP=/media/Sandėlys/tmp
>>>>>>> export TMP=/media/Sandėlys/tmp
>>>>>>> export TMPDIR=/media/Sandėlys/tmp
>>>>>>>
>>>>>>> Does not seem to help:
>>>>>>>
>>>>>>> duplicity 32278 laurynas   44u   REG     8,1 282394624 15467022
>>>>>>> /tmp/tmpf7oQNmc (deleted)
>>>>>>>
>>>>>>>> still i wonder what's up with /media/Sandėlys versus /media/Sande.lys 
>>>>>>>> .. can you explain?
>>>>>>>
>>>>>>> I am not sure what you mean by "Sande.lys"?.. It's "/media/Sandėlys".
>>>>>>> I have a diacritic letter in the path, seems to work OK. I did check
>>>>>>> /media while the restore was running that there were no "Sandelys" (no
>>>>>>> diacritic) or "Sande.lys" or anything else similar there being
>>>>>>> created.
>>>>>>>
>>>>>>> Thanks again,
>>>>>>> --
>>>>>>> Laurynas
>>>>>>
>>>>>> Ping? Thanks.
>>>>>>
>>>>>
>>>>> maybe an issue with the special character in the path? .. try mounting it 
>>>>> on a plain path.
>>>>>
>>>>> '/media/Sandėlys versus /media/Sande.lys' meant that in the df output you 
>>>>> sent earlier a mount point called '/media/Sande.lys' was listed. why was 
>>>>> that?
>>>>
>>>> I am unable to find it. I see it in your message quoting from the
>>>> pastebin df output. But the pastebin http://pastebin.com/PhanxQUX does
>>>> not contain it.
>>>>
>>>>> ok, i think i found it.. please manually patch 'duplicity/patchdir.py' 
>>>>> around line 473
>>>>> http://bazaar.launchpad.net/~duplicity-team/duplicity/0.6-series/view/head:/duplicity/patchdir.py#L473
>>>>>
>>>>> from
>>>>>
>>>>>  # librsync needs true file
>>>>>  tempfp = os.tmpfile()
>>>>>  misc.copyfileobj( current_file, tempfp )
>>>>>
>>>>> to
>>>>>
>>>>>  # librsync needs true file
>>>>>  from duplicity import tempdir
>>>>>  tempfp_fd = tempdir.default().mkstemp()[0]
>>>>>  tempfp = os.fdopen(tempfp_fd,'w+b')
>>>>>  misc.copyfileobj( current_file, tempfp )
>>>>>
>>>>> i guess the os.tmpfile() is the culprit here and places everything in 
>>>>> /tmp.
>>>>
>>>> Patched and restarted. It still failed, the log is attached. I did not
>>>> catch any file in /tmp being opened with strace, but perhaps I looked
>>>> too early. Now I will get a full strace and peek around again.
>>>>
>>>
>>> but it get's much further now... please read my comment to the pending patch
>>> https://code.launchpad.net/~ed.so/duplicity/duplicity.tmpspacefix/+merge/123622
>>>
>>> 26    + """ TODO: the following is suboptimal and should be reworked
>>> 27    + librsync insists on a real file object, which we create manually
>>> 28    + by using the duplicity.tempdir to tell us where. unfortunately
>>> 29    + these files can't have an autodelete handler attached, so they
>>> 30    + are deleted only after the whole restore process is finished,
>>> 31    + meaning the space needed for a restore is 1 volume plus all files
>>> 32    + which need to be patched. in the worst case this means space for
>>> 33    + the whole restore is needed in the TMP fs additionally to the
>>> 34    + space
>>>
>>> the former os.tmpfile() obviously automatically deletes the file once there 
>>> are no file descriptors held anymore.
>>> http://docs.python.org/library/os.html#os.tmpfile
>>> unfortunately it creates the files always in the /tmp .
>>>
>>> aahhh. just found the following in the windows port branch. sounds 
>>> reasonable to me.
>>> http://bazaar.launchpad.net/~kevinoid/duplicity/windows-port/revision/702
>>>
>>> please try and come back with results. ..ede/duply.net
>>>
>>
>> just updated the proposed patch and checked if it works. seems so. look here
>> https://code.launchpad.net/~ed.so/duplicity/duplicity.tmpspacefix/+merge/123622
> 
> Is this fix functionally equivalent to a fix I have tried before? I.e.
> the one that does import right in the code.

in a way. like before but without the mentioned gotcha above. temp file is now 
deleted as soon as the processing is finished.

> TL;DR: it worked but there are some gotchas.
> 
> Full story: I downloaded all of my backups from S3 to local storage. I
> replaced the previous fix with "tmpspacefix" Launchpad MP patch. I run
> the restore and it completed. Interestingly it completed at around 750
> volumes processed out of 3400. Also the last 100 volumes took about 24
> hours to complete.

interesting. could you check which files took that long? do you still have the 
output? could you run a full restore with -v9 and post the output (private 
strings obfuscated)?

> 
> All in all, I got my files back (yay! Thanks! :), but some questions remain:
> 1) Is the free space estimate algorithm wrong? I.e. the one that says
> "you need the size of the restored file + one volume".

no algorithm there. it just describes what happens. duplicity restores the 
oldest version of the file and then starts to patch it via librsync. might be 
that the patching doubles the space needed but afaik should happen directly on 
the temp file.

> 2) There must be something quadratic or worse in the restore
> algorithm. Out of 750 volumes, first 500 complete in perhaps 30
> minutes, next 100 in one hour, last 100 in 24 hours.

can you check that the system resources do not get used up (cpu,memory) so that 
the system starts swapping? there are known issues sometimes that gpg processes 
are not ended properly so that the memory fills up.
this is mostly an issue with debian/ubuntu if duplicity was installed from 
distros repository. they package a wrong GnuPGInterface which does not cleanly 
collect and kill gpg instances.

if the system really swaps please try to install from tarball, like explained 
here under TIP
http://duply.net/?title=Duply-documentation

and file a complaint with the maintainer of the package that you used.

..ede/duply.net