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

[Laurynas Biveinis]

>>>>>>>>>>>>>>>>>>>>>>>> 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.
>>>>>>>
>>>> TL;DR: it worked but there are some gotchas.
>>>>
>>>> Full story: I downloaded all of my backups from S3 to local storage. I
>>>> replaced the previous fix with "tmpspacefix" Launchpad MP patch. I run
>>>> the restore and it completed. Interestingly it completed at around 750
>>>> volumes processed out of 3400. Also the last 100 volumes took about 24
>>>> hours to complete.
>>>
>>> interesting. could you check which files took that long? do you still have 
>>> the output? could you run a full restore with -v9 and post the output 
>>> (private strings obfuscated)?
>>
>> Attached.
>
> will look at it later.

Thanks in advance.

>> So, "twice the size of the restored file + one volume?" But originally
>> it failed with 80GB free for a 30GB file, so it's even more than that.
>
> right, we would have to disect filesystem usage during restoring to find out 
> what is going on here. actually the v9 dump tells you when temp files are 
> created and deleted (though not their size) so you can work through that if 
> you want.
>
> alternatively you have to observe what happens in the tmp folder during 
> restore ;)

Here's the open file snapshot around volume 704 (out of ~750):
http://pastebin.com/pGFH6Wju

Note that "Sandėlys" has been replaced with "Elements", that's another
volume (so that locally-downloaded backup sets would fit)

Thanks again,
-- 
Laurynas