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

[Laurynas Biveinis]

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.

-- 
Laurynas