Re: [Duplicity-talk] Duplicity - Resource Unavailable Errors

[Kenneth Loafman]

Better yet would be a Python implementation of the gpg library.  I
looked at one a year or more ago.  Maybe its grown up now.

...Ken

address@hidden wrote:
> smells like the gpg interface should be rewritten not to use pipes but
> files instead. Processes would die then timely on the end of gpg's actions.
> 
> .. ede
> duply.net
> 
> On 13.11.2009 18:56, Colin Ryan wrote:
>> Bump..
>>
>> Anyone have any ideas on the below...it's odd that this happens only on
>> restore. I make the backup itself from the same environment(s).
>>
>> C
>>
>> Colin Ryan wrote:
>>> Ken,
>>>
>>> No problem, your a busy man ;-).
>>>
>>> Summary/Update
>>> ----------
>>>
>>> Well I tried this on the source system and I get something different
>>> but the same in a way.
>>> It appears that I'm running into the following type of issue:
>>>
>>> http://www.google.ca/url?sa=t&source=web&ct=res&cd=1&ved=0CAcQFjAA&url=http%3A%2F%2Fbugs.debian.org%2Fcgi-bin%2Fbugreport.cgi%3Fbug%3D531786&ei=qDL7Ssj7AcfZnAfxoMmDDQ&usg=AFQjCNFeZMg6JCzACjbX3nmxpkXvFPxkKQ&sig2=_sCXzLVFuZkEvVmEcdFWHw
>>>
>>>
>>>
>>> or
>>>
>>> http://www.google.ca/url?sa=t&source=web&ct=res&cd=5&ved=0CBMQFjAE&url=http%3A%2F%2Fwww.mail-archive.com%2Fduplicity-tracker%40nongnu.org%2Fmsg00632.html&ei=qDL7Ssj7AcfZnAfxoMmDDQ&usg=AFQjCNEwImqEAQLUmA7ab5S44D1MlHpnZw&sig2=LNsQa64sQk-4GObh8B0sQA
>>>
>>>
>>>
>>> i.e. see below when it's running the restore it's hanging at 39 gpg
>>> sub-processes.
>>>
>>> My environment is:
>>>
>>> *Linux rdrive 2.6.22-univ-423 #1 PREEMPT Wed Jul 2 13:04:26 EDT 2008
>>> i686 GNU/Linux
>>>
>>> Custom Kernel on Stripped down version of Debian Lenny
>>>
>>> * rdrive:/# gpg --version
>>> gpg (GnuPG) 1.4.6
>>> Copyright (C) 2006 Free Software Foundation, Inc.
>>> This program comes with ABSOLUTELY NO WARRANTY.
>>> This is free software, and you are welcome to redistribute it
>>> under certain conditions. See the file COPYING for details.
>>>
>>> Home: ~/.gnupg
>>> Supported algorithms:
>>> Pubkey: RSA, RSA-E, RSA-S, ELG-E, DSA
>>> Cipher: 3DES, CAST5, BLOWFISH, AES, AES192, AES256, TWOFISH
>>> Hash: MD5, SHA1, RIPEMD160, SHA256, SHA384, SHA512, SHA224
>>> Compression: Uncompressed, ZIP, ZLIB, BZIP2
>>>
>>> * rdrive:/# duplicity --version
>>> duplicity 0.6.05
>>>
>>> (Hand compiled to a distribution tar then unpacked onto this system)
>>>
>>> Full Details Below:
>>> -------------------
>>>
>>> The following command:
>>>
>>> /usr/bin/duplicity restore -v9 --encrypt-key=xxxxxx --sign-key=xxxxxxx
>>> --gpg-options=--default-key=xxxxxx
>>> --archive-dir=/opt/aa/service/nas/restores
>>> --tempdir=/opt/aa/service/nas/restores s3+http://<amazone
>>> url>/office-demo.accessanywhere.net /opt/aa/service/nas/restores/office
>>>
>>> Run fine without errors as it's the same UID/GID etc. But eventually
>>> it now barfs out with a
>>>
>>> <code>
>>> tores/duplicity-sQKaRZ-tempdir/mktemp-kgeAuN-75
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-3Pq-mM-26
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-3Pq-mM-26
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-T0z4xe-67
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-T0z4xe-67
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-t8culd-72
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-t8culd-72
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-eBy5OU-87
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-eBy5OU-87
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp--H-_I3-29
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp--H-_I3-29
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-NSeApT-82
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-NSeApT-82
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-_m-wf1-91
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-_m-wf1-91
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-r1Z3CO-83
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-r1Z3CO-83
>>> Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-RLNUrL-68
>>> DEBUG:duplicity:Removing still remembered temporary file
>>> /opt/aa/service/nas/restores/duplicity-sQKaRZ-tempdir/mktemp-RLNUrL-68
>>> Traceback (most recent call last):
>>> File "/usr/bin/duplicity", line 1241, in ?
>>> with_tempdir(main)
>>> File "/usr/bin/duplicity", line 1234, in with_tempdir
>>> fn()
>>> File "/usr/bin/duplicity", line 1188, in main
>>> restore(col_stats)
>>> File "/usr/bin/duplicity", line 542, in restore
>>> restore_get_patched_rop_iter(col_stats)):
>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>> 519, in Write_ROPaths
>>> for ropath in rop_iter:
>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>> 492, in integrate_patch_iters
>>> final_ropath = patch_seq2ropath(normalize_ps(patch_seq))
>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>> 472, in patch_seq2ropath
>>> misc.copyfileobj(current_file, tempfp)
>>> File "/usr/lib/python2.4/site-packages/duplicity/misc.py", line 170,
>>> in copyfileobj
>>> outfp.write(buf)
>>> IOError: [Errno 28] No space left on device
>>>
>>> ERROR:duplicity:Traceback (most recent call last):
>>> File "/usr/bin/duplicity", line 1241, in ?
>>> with_tempdir(main)
>>> File "/usr/bin/duplicity", line 1234, in with_tempdir
>>> fn()
>>> File "/usr/bin/duplicity", line 1188, in main
>>> restore(col_stats)
>>> File "/usr/bin/duplicity", line 542, in restore
>>> restore_get_patched_rop_iter(col_stats)):
>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>> 519, in Write_ROPaths
>>> for ropath in rop_iter:
>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>> 492, in integrate_patch_iters
>>> final_ropath = patch_seq2ropath(normalize_ps(patch_seq))
>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>> 472, in patch_seq2ropath
>>> misc.copyfileobj(current_file, tempfp)
>>> File "/usr/lib/python2.4/site-packages/duplicity/misc.py", line 170,
>>> in copyfileobj
>>> outfp.write(buf)
>>> IOError: [Errno 28] No space left on device
>>> </code>
>>>
>>> This despite that the /opt/aa/service/nas path is a 400MB volume, that
>>> is totally empty.
>>>
>>> More interestingly is that at the time of this error (duplicity just
>>> hangs it doesn't crash) the
>>> Virtual Mem. footprint is 310Mb with 12MB resident.
>>>
>>> And all the GPG processes look like:
>>>
>>> nas 2302 2250 0 16:39 pts/1 00:00:00 gpg --status-fd 33
>>> --passphrase-fd 37 --logger-fd 7 --batch --no-tty --default-key xxxxx
>>> --no-secmem-warning --default-key=xxxxx --decrypt
>>> nas 2308 2250 0 16:39 pts/1 00:00:00 gpg --status-fd 39
>>> --passphrase-fd 43 --logger-fd 34 --batch --no-tty --default-key
>>> xxxxxx --no-secmem-warning --default-key=xxxxx --decrypt
>>> nas 2312 2250 0 16:39 pts/1 00:00:00 gpg --status-fd 44
>>> --passphrase-fd 48 --logger-fd 40 --batch --no-tty --default-key xxxxx
>>> --no-secmem-warning --default-key=xxxxx --decrypt
>>> nas 2314 2250 0 16:39 pts/1 00:00:00 gpg --status-fd 48
>>> --passphrase-fd 52 --logger-fd 45 --batch --no-tty --default-key
>>> xxxxxx --no-secmem-warning --default-key=xxxxx --decrypt
>>>
>>>
>>>
>>> Colin Ryan
>>>
>>>
>>> Kenneth Loafman wrote:
>>>> Sorry for the slow response. This seems to be a ulimit issue, but
>>>> that's not normal for only 45 incrementals. Please run 'ulimit -n' and
>>>> post the response here. Try increasing the ulimit with 'ulimit -n 4096'
>>>> or higher and retry. That could help.
>>>>
>>>> I'm not sure what's happening, but its possible that the permission
>>>> failures are somehow eating up file slots. During the run you could try
>>>> 'lsof -p <duplicity's pid>' just to see if any of those files are open.
>>>>
>>>> ...Thanks,
>>>> ...Ken
>>>>
>>>> Colin Ryan wrote:
>>>>
>>>>> Update:
>>>>>
>>>>> Tried this same test again and it is not always that this failure
>>>>> leaves
>>>>> the rest of the system unable to fork other processes such as "ls" or
>>>>> "top" etc etc. sometimes yes, sometimes no...in any even duplicity
>>>>> does
>>>>> continue to grow in excess of 200Mb put I do have physical RAM
>>>>> reported
>>>>> as free when this occurs.
>>>>>
>>>>> Any thoughts?
>>>>>
>>>>> Colin Ryan wrote:
>>>>>> I should know the answer to this but can't seem to confirm. Clearly
>>>>>> such errors are generally flimit/ulimit issues or RAM.
>>>>>>
>>>>>> But I'm testing restore a not huge ( ~ 8 GB archive that is only 1
>>>>>> full and 45 days of incremental's) and get the following from the
>>>>>> following command line.
>>>>>>
>>>>>> /duplicity restore -v9 --encrypt-key=xxxxxxx --sign-key=xxxxxx
>>>>>> --gpg-options='--default-key=xxxxxxx'
>>>>>> --archive-dir="/opt/aa/service/nas/restores"
>>>>>> --tempdir="/opt/aa/service/nas/restores" --ignore-errors
>>>>>> s3+http://URL/<backup set name> "/opt/aa/service/nas/restores/office"
>>>>>>
>>>>>> I'm using the -ignore-errors as I'm unpacking as a non-root user
>>>>>> other
>>>>>> than the one that did the backups so it was throwing "no permission"
>>>>>> errors on what I expect was the chmod/chown stages ( I say this
>>>>>> because the files themselves were extracted)...Anyhow...
>>>>>>
>>>>>> Version is 6.0.5 hand rolled in Debian Lenny.
>>>>>>
>>>>>> When it ceases the system is unable to fork any other processes until
>>>>>> I kill duplicity.
>>>>>>
>>>>>> A already running top in another terminal shows that duplicity at
>>>>>> this
>>>>>> point is ~ 200 MB virtual and 11 MB resident but that I have ~ 200M
>>>>>> RAM free (this is a fairly small footprint system).
>>>>>>
>>>>>> I believe it's out of memory for forking but is it normal.
>>>>>>
>>>>>> <code>
>>>>>> BEGNj3-tempdir/mktemp-QYdP4e-85
>>>>>> DEBUG:duplicity:Removing still remembered temporary file
>>>>>> /opt/aa/service/nas/restores/duplicity-BEGNj3-tempdir/mktemp-QYdP4e-85
>>>>>>
>>>>>> Removing still remembered temporary file
>>>>>> /opt/aa/service/nas/restores/duplicity-BEGNj3-tempdir/mktemp-aDi69N-61
>>>>>>
>>>>>> DEBUG:duplicity:Removing still remembered temporary file
>>>>>> /opt/aa/service/nas/restores/duplicity-BEGNj3-tempdir/mktemp-aDi69N-61
>>>>>>
>>>>>> Removing still remembered temporary file
>>>>>> /opt/aa/service/nas/restores/duplicity-BEGNj3-tempdir/mktemp-2YCFpS-81
>>>>>>
>>>>>> DEBUG:duplicity:Removing still remembered temporary file
>>>>>> /opt/aa/service/nas/restores/duplicity-BEGNj3-tempdir/mktemp-2YCFpS-81
>>>>>>
>>>>>> Removing still remembered temporary file
>>>>>> /opt/aa/service/nas/restores/duplicity-BEGNj3-tempdir/mktemp-CXX67i-73
>>>>>>
>>>>>> DEBUG:duplicity:Removing still remembered temporary file
>>>>>> /opt/aa/service/nas/restores/duplicity-BEGNj3-tempdir/mktemp-CXX67i-73
>>>>>>
>>>>>> Traceback (most recent call last):
>>>>>> File "/usr/bin/duplicity", line 1241, in ?
>>>>>> with_tempdir(main)
>>>>>> File "/usr/bin/duplicity", line 1234, in with_tempdir
>>>>>> fn()
>>>>>> File "/usr/bin/duplicity", line 1188, in main
>>>>>> restore(col_stats)
>>>>>> File "/usr/bin/duplicity", line 542, in restore
>>>>>> restore_get_patched_rop_iter(col_stats)):
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 519, in Write_ROPaths
>>>>>> for ropath in rop_iter:
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 491, in integrate_patch_iters
>>>>>> for patch_seq in collated:
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 376, in yield_tuples
>>>>>> setrorps(overflow, elems)
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 365, in setrorps
>>>>>> elems[i] = iter_list[i].next()
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 110, in difftar2path_iter
>>>>>> tarinfo_list = [tar_iter.next()]
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 326, in next
>>>>>> self.set_tarfile()
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 320, in set_tarfile
>>>>>> self.current_fp = self.fileobj_iter.next()
>>>>>> File "/usr/bin/duplicity", line 579, in get_fileobj_iter
>>>>>> manifest.volume_info_dict[vol_num])
>>>>>> File "/usr/bin/duplicity", line 603, in restore_get_enc_fileobj
>>>>>> fileobj = tdp.filtered_open_with_delete("rb")
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/dup_temp.py", line
>>>>>> 114, in filtered_open_with_delete
>>>>>> fh = FileobjHooked(path.DupPath.filtered_open(self, mode))
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/path.py", line 724,
>>>>>> in filtered_open
>>>>>> return gpg.GPGFile(False, self, gpg_profile)
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/gpg.py", line 135,
>>>>>> in __init__
>>>>>> attach_fhs={'stdin': encrypt_path.open("rb"),
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/GnuPGInterface.py",
>>>>>> line 365, in run
>>>>>> create_fhs, attach_fhs)
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/GnuPGInterface.py",
>>>>>> line 407, in _attach_fork_exec
>>>>>> process.pid = os.fork()
>>>>>> OSError: [Errno 11] Resource temporarily unavailable
>>>>>>
>>>>>> ERROR:duplicity:Traceback (most recent call last):
>>>>>> File "/usr/bin/duplicity", line 1241, in ?
>>>>>> with_tempdir(main)
>>>>>> File "/usr/bin/duplicity", line 1234, in with_tempdir
>>>>>> fn()
>>>>>> File "/usr/bin/duplicity", line 1188, in main
>>>>>> restore(col_stats)
>>>>>> File "/usr/bin/duplicity", line 542, in restore
>>>>>> restore_get_patched_rop_iter(col_stats)):
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 519, in Write_ROPaths
>>>>>> for ropath in rop_iter:
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 491, in integrate_patch_iters
>>>>>> for patch_seq in collated:
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 376, in yield_tuples
>>>>>> setrorps(overflow, elems)
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 365, in setrorps
>>>>>> elems[i] = iter_list[i].next()
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 110, in difftar2path_iter
>>>>>> tarinfo_list = [tar_iter.next()]
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 326, in next
>>>>>> self.set_tarfile()
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/patchdir.py", line
>>>>>> 320, in set_tarfile
>>>>>> self.current_fp = self.fileobj_iter.next()
>>>>>> File "/usr/bin/duplicity", line 579, in get_fileobj_iter
>>>>>> manifest.volume_info_dict[vol_num])
>>>>>> File "/usr/bin/duplicity", line 603, in restore_get_enc_fileobj
>>>>>> fileobj = tdp.filtered_open_with_delete("rb")
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/dup_temp.py", line
>>>>>> 114, in filtered_open_with_delete
>>>>>> fh = FileobjHooked(path.DupPath.filtered_open(self, mode))
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/path.py", line 724,
>>>>>> in filtered_open
>>>>>> return gpg.GPGFile(False, self, gpg_profile)
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/gpg.py", line 135,
>>>>>> in __init__
>>>>>> attach_fhs={'stdin': encrypt_path.open("rb"),
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/GnuPGInterface.py",
>>>>>> line 365, in run
>>>>>> create_fhs, attach_fhs)
>>>>>> File "/usr/lib/python2.4/site-packages/duplicity/GnuPGInterface.py",
>>>>>> line 407, in _attach_fork_exec
>>>>>> process.pid = os.fork()
>>>>>> OSError: [Errno 11] Resource temporarily unavailable
>>>>>>
>>>>>> Error in atexit._run_exitfuncs:
>>>>>> Traceback (most recent call last):
>>>>>> File "atexit.py", line 24, in _run_exitfuncs
>>>>>> func(*targs, **kargs)
>>>>>> File "threading.py", line 634, in __exitfunc
>>>>>> t.join()
>>>>>> File "threading.py", line 540, in join
>>>>>> self.__block.wait()
>>>>>> File "threading.py", line 203, in wait
>>>>>> waiter.acquire()
>>>>>> </code>
>>>>>>
>>>>>> Cheers and Thanks
>>>>>>
>>>>>> Colin
>>>>>>
>>>>>>
>>>>>> _______________________________________________
>>>>>> Duplicity-talk mailing list
>>>>>> address@hidden
>>>>>> http://lists.nongnu.org/mailman/listinfo/duplicity-talk
>>>>>
>>>>> _______________________________________________
>>>>> Duplicity-talk mailing list
>>>>> address@hidden
>>>>> http://lists.nongnu.org/mailman/listinfo/duplicity-talk
>>>>>
>>>>
>>>>
>>>> ------------------------------------------------------------------------
>>>>
>>>>
>>>> _______________________________________________
>>>> Duplicity-talk mailing list
>>>> address@hidden
>>>> http://lists.nongnu.org/mailman/listinfo/duplicity-talk
>>>
>>>
>>>
>>> _______________________________________________
>>> Duplicity-talk mailing list
>>> address@hidden
>>> http://lists.nongnu.org/mailman/listinfo/duplicity-talk
>>
>>
>>
>> _______________________________________________
>> Duplicity-talk mailing list
>> address@hidden
>> http://lists.nongnu.org/mailman/listinfo/duplicity-talk
> 
> 
> _______________________________________________
> Duplicity-talk mailing list
> address@hidden
> http://lists.nongnu.org/mailman/listinfo/duplicity-talk
>

signature.asc
Description: OpenPGP digital signature