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

[Laurynas Biveinis]

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.

Thanks,
-- 
Laurynas

restore-10.log.bz2
Description: BZip2 compressed data