[Top][All Lists]
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Re: [Duplicity-talk] Out of space error while restoring a file
From: |
edgar . soldin |
Subject: |
Re: [Duplicity-talk] Out of space error while restoring a file |
Date: |
Tue, 11 Sep 2012 19:22:35 +0200 |
User-agent: |
Mozilla/5.0 (Windows NT 5.1; rv:15.0) Gecko/20120907 Thunderbird/15.0.1 |
On 11.09.2012 19:06, Laurynas Biveinis wrote:
> 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
> :)
>
well.. with duplicity you can always copy the repository to a local location
and restore from there ;) .. ede/duply.net
- Re: [Duplicity-talk] Out of space error while restoring a file, (continued)
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/17
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/17
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/17
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/17
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/21
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/26
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/26
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/29
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/30
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/11
- Re: [Duplicity-talk] Out of space error while restoring a file,
edgar . soldin <=