[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 16:17:56 +0200 |
User-agent: |
Mozilla/5.0 (Windows NT 5.1; rv:15.0) Gecko/20120824 Thunderbird/15.0 |
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
..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/04
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/04
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/04
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/04
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/04
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/04
- Re: [Duplicity-talk] Out of space error while restoring a file, Laurynas Biveinis, 2012/09/07
- Re: [Duplicity-talk] Out of space error while restoring a file, edgar . soldin, 2012/09/07
- 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, 2012/09/11
- Re: [Duplicity-talk] Out of space error while restoring a file,
edgar . soldin <=
- 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/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