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

[edgar . soldin]

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