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

[Laurynas Biveinis]

2012/9/11  <address@hidden>:
> 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...

It got much further, but I also freed up some 15GBs of space on the
root partition.

> https://code.launchpad.net/~ed.so/duplicity/duplicity.tmpspacefix/+merge/123622
...
> http://bazaar.launchpad.net/~kevinoid/duplicity/windows-port/revision/702

> please try and come back with results. ..ede/duply.net

My strace()'ed run that had the 1st fix just stopped after ~8h running
due to unrelated reasons. lsof showed two big (tens of GBs) temp
files, there were no files on /tmp. One thing I did notice before the
stop (around 650th volume out of 3400) is that each subsequent volume
was being processed slower and slower while strace was showing
intensive reads and writes. It's as if some volume processing
algorithm is significantly worse than linear. If that's the case, then
I'm I'm concerned how much time all 3400 volumes will take...

I will now apply
https://code.launchpad.net/~ed.so/duplicity/duplicity.tmpspacefix/+merge/123622
and get back with results.

As you can probably tell, I'm really keen to get that file back from
the backup :) I am also slightly concerned with S3 bill for this month
:)

Thanks again,
-- 
Laurynas